I just got a GoControl USB stick (https://www.amazon.com/GoControl-CECOMINOD016164-HUSBZB-1-USB-Hub/dp/B01GJ826F8) that I’m trying to get set up with OpenHAB. I’m attempting to add the device as a Zigbee coordinator Thing (will do Z-Wave after - I just have Sengled Zigbee bulbs to test with right now), and in both the Paper and HABmin UIs when I try to add it using the Zigbee binding > Ember coordinator, the serial port for this device does not appear in the dropdown. The only entry in the dropdown is /dev/ttyArduinoUno, which is a udev symlink for a MySensors serial gateway that has been functioning just fine for a few months.
I am running Ubuntu 14.04 amd64 and OpenHAB 2.4. I have made sure that the openhab user is in the tty and dialout groups and the openhab process is running under the openhab user. I used lsusb and dmesg to get the vendor/product IDs and serial for the device and set up /etc/udev/rules.d/99-usb-serial.rules
to set up a /dev/ttyZigbee symlink that points to /dev/ttyUSB0, which is owned by root:dialout and has read/write permissions for both self and group. I modified /etc/default/openhab2
to include EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyZigbee:/dev/ttyUSB0"
. I heard about some serial port issues with different JREs, and even though this seemed to mainly be for 64-bit ARM I tried installing and switching to the recommended Zulu Java 8 JRE just to be sure. I’ve restarted OpenHAB and my computer multiple times.
I’ve also tried adding the Thing by editing /etc/openhab2/things/default.things
to include Thing zigbee:coordinator_ember:45bc1f9a "ZigBee Coordinator" @ "Apartment" [ zigbee_port="/dev/ttyZigbee", zigbee_baud="57600", zigbee_flowcontrol=2 ]
, and when I save and the Things reload (or I restart OpenHAB), I get the following in my logs (with debug logs enabled for Zigbee):
==> /var/log/openhab2/events.log <==
2019-01-04 22:54:33.263 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_ember:45bc1f9a' changed from OFFLINE (COMMUNICATION_ERROR) to UNINITIALIZED
==> /var/log/openhab2/openhab.log <==
2019-01-04 22:54:33.271 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.
2019-01-04 22:54:33.280 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.
2019-01-04 22:54:33.282 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.dispose()' on 'org.openhab.binding.zigbee.ember.handler.EmberHandler@4f4d40e6': null
java.lang.NullPointerException: null
at com.zsmartsystems.zigbee.app.discovery.ZigBeeDiscoveryExtension.extensionShutdown(ZigBeeDiscoveryExtension.java:96) ~[?:?]
at com.zsmartsystems.zigbee.ZigBeeNetworkManager.shutdown(ZigBeeNetworkManager.java:529) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.dispose(ZigBeeCoordinatorHandler.java:303) ~[?:?]
at org.openhab.binding.zigbee.ember.handler.EmberHandler.dispose(EmberHandler.java:128) ~[?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [102:org.eclipse.smarthome.core:0.10.0.oh240]
at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [102:org.eclipse.smarthome.core:0.10.0.oh240]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
2019-01-04 22:54:33.286 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while disposing handler of thing 'zigbee:coordinator_ember:45bc1f9a': null
java.lang.NullPointerException: null
at com.zsmartsystems.zigbee.app.discovery.ZigBeeDiscoveryExtension.extensionShutdown(ZigBeeDiscoveryExtension.java:96) ~[?:?]
at com.zsmartsystems.zigbee.ZigBeeNetworkManager.shutdown(ZigBeeNetworkManager.java:529) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.dispose(ZigBeeCoordinatorHandler.java:303) ~[?:?]
at org.openhab.binding.zigbee.ember.handler.EmberHandler.dispose(EmberHandler.java:128) ~[?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [102:org.eclipse.smarthome.core:0.10.0.oh240]
at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [102:org.eclipse.smarthome.core:0.10.0.oh240]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
2019-01-04 22:54:33.294 [DEBUG] [org.openhab.binding.zigbee.ember ] - ServiceEvent UNREGISTERING - {org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler}={service.id=317, service.bundleid=217, service.scope=singleton} - org.openhab.binding.zigbee.ember
2019-01-04 22:54:33.295 [DEBUG] [org.openhab.binding.zigbee.ember ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=318, service.bundleid=217, service.scope=singleton} - org.openhab.binding.zigbee.ember
==> /var/log/openhab2/events.log <==
2019-01-04 22:54:33.299 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_ember:45bc1f9a' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
==> /var/log/openhab2/openhab.log <==
2019-01-04 22:54:33.328 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.things'
2019-01-04 22:54:33.334 [DEBUG] [org.openhab.binding.zigbee.ember ] - ServiceEvent REGISTERED - {org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler}={service.id=393, service.bundleid=217, service.scope=singleton} - org.openhab.binding.zigbee.ember
2019-01-04 22:54:33.336 [DEBUG] [org.openhab.binding.zigbee.ember ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=394, service.bundleid=217, service.scope=singleton} - org.openhab.binding.zigbee.ember
2019-01-04 22:54:33.338 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - Initializing ZigBee Ember serial bridge handler.
2019-01-04 22:54:33.339 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_ember:45bc1f9a].
==> /var/log/openhab2/events.log <==
2019-01-04 22:54:33.339 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_ember:45bc1f9a' changed from UNINITIALIZED to INITIALIZING
==> /var/log/openhab2/openhab.log <==
2019-01-04 22:54:33.340 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel 0
2019-01-04 22:54:33.340 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - PANID 0
2019-01-04 22:54:33.340 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EPANID 0000000000000000
2019-01-04 22:54:33.341 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2019-01-04 22:54:33.341 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key 5A 69 67 42 65 65 41 6C 6C 69 61 6E 63 65 30 39
2019-01-04 22:54:33.342 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_initialise found, initializeNetwork=false
2019-01-04 22:54:33.342 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ExtendedPanId or PanId not set: initializeNetwork=true
2019-01-04 22:54:33.342 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key String 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2019-01-04 22:54:33.342 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network key initialised 276F2A2DD6C5BE7BB7C34ECDE852B8E7
2019-01-04 22:54:33.343 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network key final array 276F2A2DD6C5BE7BB7C34ECDE852B8E7
2019-01-04 22:54:33.343 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key String 5A 69 67 42 65 65 41 6C 6C 69 61 6E 63 65 30 39
2019-01-04 22:54:33.343 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising network
2019-01-04 22:54:33.343 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel set to 11.
2019-01-04 22:54:33.345 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Created random ZigBee PAN ID [C160].
==> /var/log/openhab2/events.log <==
2019-01-04 22:54:33.345 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_ember:45bc1f9a' has been updated.
==> /var/log/openhab2/openhab.log <==
2019-01-04 22:54:33.345 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Created random ZigBee extended PAN ID [EF82F3566B7D67BB].
2019-01-04 22:54:33.346 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link key final array 5A6967426565416C6C69616E63653039
==> /var/log/openhab2/events.log <==
2019-01-04 22:54:33.347 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_ember:45bc1f9a' has been updated.
==> /var/log/openhab2/openhab.log <==
2019-01-04 22:54:33.347 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - ZigBee Ember Coordinator opening Port:'/dev/ttyZigbee' PAN:c160, EPAN:EF82F3566B7D67BB, Channel:11
==> /var/log/openhab2/events.log <==
2019-01-04 22:54:33.347 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_ember:45bc1f9a' has been updated.
==> /var/log/openhab2/openhab.log <==
2019-01-04 22:54:33.347 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
==> /var/log/openhab2/events.log <==
2019-01-04 22:54:33.348 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_ember:45bc1f9a' has been updated.
2019-01-04 22:54:33.348 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_ember:45bc1f9a' changed from INITIALIZING to UNKNOWN
2019-01-04 22:54:33.351 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:coordinator_ember:45bc1f9a changed to UNKNOWN.
==> /var/log/openhab2/openhab.log <==
2019-01-04 22:54:34.349 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
2019-01-04 22:54:34.349 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
2019-01-04 22:54:34.351 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Loading ZigBee network state: Start.
2019-01-04 22:54:34.357 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Loading ZigBee network state: Done.
2019-01-04 22:54:34.362 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyZigbee] at 57600 baud, flow control FLOWCONTROL_OUT_XONOFF.
2019-01-04 22:54:34.363 [ERROR] [ding.zigbee.handler.ZigBeeSerialPort] - Serial Error: Port /dev/ttyZigbee does not exist.
2019-01-04 22:54:34.363 [ERROR] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unable to open Ember serial port
2019-01-04 22:54:34.369 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=OFFLINE
==> /var/log/openhab2/events.log <==
2019-01-04 22:54:34.375 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_ember:45bc1f9a' changed from UNKNOWN to OFFLINE: Failed to open communications port
==> /var/log/openhab2/openhab.log <==
2019-01-04 22:54:34.378 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=UNINITIALISED
2019-01-04 22:54:34.379 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'default.things'
==> /var/log/openhab2/events.log <==
2019-01-04 22:54:34.383 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_ember:45bc1f9a' changed from OFFLINE: Failed to open communications port to OFFLINE (COMMUNICATION_ERROR)
==> /var/log/openhab2/openhab.log <==
2019-01-04 22:54:34.386 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.
2019-01-04 22:54:34.386 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.
2019-01-04 22:54:34.387 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.thingUpdated()' on 'org.openhab.binding.zigbee.ember.handler.EmberHandler@13b8590b': null
java.lang.NullPointerException: null
at com.zsmartsystems.zigbee.app.discovery.ZigBeeDiscoveryExtension.extensionShutdown(ZigBeeDiscoveryExtension.java:96) ~[?:?]
at com.zsmartsystems.zigbee.ZigBeeNetworkManager.shutdown(ZigBeeNetworkManager.java:529) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.dispose(ZigBeeCoordinatorHandler.java:303) ~[?:?]
at org.openhab.binding.zigbee.ember.handler.EmberHandler.dispose(EmberHandler.java:128) ~[?:?]
at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.thingUpdated(BaseThingHandler.java:206) ~[?:?]
at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.thingUpdated(ZigBeeCoordinatorHandler.java:315) ~[?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [102:org.eclipse.smarthome.core:0.10.0.oh240]
at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [102:org.eclipse.smarthome.core:0.10.0.oh240]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
==> /var/log/openhab2/events.log <==
2019-01-04 22:54:34.394 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_ember:45bc1f9a' has been updated.
What might be going wrong? One debugging step I’m interested in is how the dropdown options for the serial ports are generated. I was reading that rxtx will look for /dev/ttyS*
on Linux, and that the Java command line option gnu.io.rxtx.SerialPorts
I’ve supplied would override that, but neither of those seem to be true in my case.
Thank you,
Matt