HUSBZB-1: ZigBee controller stuck at "Initializing"

mechalas · February 4, 2021, 2:40pm

Running OH 3.0.0 release build on Ubuntu Linux 20.04 with OpenJDK 11 runtime.

$ java --version
openjdk 11.0.9.1 2020-11-04
OpenJDK Runtime Environment (build 11.0.9.1+1-Ubuntu-0ubuntu1.20.04)
OpenJDK 64-Bit Server VM (build 11.0.9.1+1-Ubuntu-0ubuntu1.20.04, mixed mode, sharing)

I have the HUSBZB-1 USB adapter and the Z-Wave controller is working fine on ttyUSB0. The ZigBee adapter on ttyUSB1, however, is stuck in “Initializing”. My settings for the controller, based on documentation and forum comments are:

/dev/ttyUSB1
57600 baud
Software flow control (XOn/XOff)

OH Java options are:

-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB0,/dev/ttyUSB1 -Djava.library.path=/usr/lib/jni -cp /usr/share/java/RXTXcomm.jar

And here’s what I see in the logs:

2021-02-04 06:18:18.523 [WARN ] [core.thing.internal.ThingManagerImpl] - The model of zigbee:coordinator_ember:exxxxxxxxb is inconsistent [thing.getHandler().getThing() != thing]
2021-02-04 06:18:18.597 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_ember:exxxxxxxxb].
2021-02-04 06:18:18.597 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel 11
2021-02-04 06:18:18.597 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - PANID 3xxx4
2021-02-04 06:18:18.597 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EPANID Axxxxxxxxxxxxxx2
2021-02-04 06:18:18.597 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key 1xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxA
2021-02-04 06:18:18.597 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key 6xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx4
2021-02-04 06:18:18.597 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_initialise found, initializeNetwork=false
2021-02-04 06:18:18.598 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key String 1xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxA
2021-02-04 06:18:18.598 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network key final array 1xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxA
2021-02-04 06:18:18.598 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key String 6xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx4
2021-02-04 06:18:18.598 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link key final array 6xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx4
2021-02-04 06:18:18.598 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - Initializing ZigBee Ember serial bridge handler.
2021-02-04 06:18:18.598 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - ZigBee Ember Coordinator opening Port:'/dev/ttyUSB1' PAN:7xx0, EPAN:5xxxxxxxxxxxxxxE, Channel:11
2021-02-04 06:18:18.562 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:coordinator_ember:exxxxxxxxb' takes more than 5000ms.

And that is as far as it goes. Reboot, restart, remove and re-add…all have resulted in the same behavior. Status shows as “Inititalizing” in the UI and it never progresses beyond that.

I assume I am missing something really obvious, especially since the Z-Wave controller has been functioning flawlessly. Any ideas what that might be? I find this first warning line at least somewhat interesting, but am not sure what to make of it. And I am not sure if it came from a previous shutdown or the most recent startup:

2021-02-04 06:18:18.523 [WARN ] [core.thing.internal.ThingManagerImpl] - The model of zigbee:coordinator_ember:exxxxxxxxb is inconsistent [thing.getHandler().getThing() != thing]

Bruce_Osborne · February 4, 2021, 3:00pm

How have you defined the Thing? text file or UI?

mechalas · February 4, 2021, 3:21pm

How have you defined the Thing? text file or UI?

UI

Definition is:

UID: zigbee:coordinator_ember:exxxxxxxxb
label: Ember EM35x Coordinator
thingTypeUID: zigbee:coordinator_ember
configuration:
  zigbee_port: /dev/ttyUSB1
  zigbee_initialise: false
  zigbee_channel: 11
  zigbee_concentrator: null
  zigbee_trustcentremode: TC_JOIN_SECURE
  zigbee_extendedpanid: Axxxxxxxxxxxxxx2
  zigbee_flowcontrol: 2
  zigbee_baud: 57600
  zigbee_panid: 3xxx4
  zigbee_powermode: null
  zigbee_txpower: 0
  zigbee_networksize: null
  zigbee_linkkey: 6xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx4
  zigbee_childtimeout: 86400
  zigbee_networkkey: 1xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxA
  zigbee_meshupdateperiod: 86400

Bruce_Osborne · February 4, 2021, 3:39pm

I have successfully had that coordinator recognized on my test machine with OH 3.x but have not tested in a while.

Does the 3.0.1 release work any better?

I cannot recall whether I last tested on 3.0.0 Release or just a snapshot.

mechalas · February 4, 2021, 3:55pm

I will try 3.0.1 later this morning.

I did a restart (again) and this time I got ONLINE, and I thought maybe it had been fixed and that the solution was to post for help on the forums. But now it’s in the UNKNOWN state after attempting to do a scan for devices. The logs show:

2021-02-04 07:40:48.739 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:exxxxxxxxxb
2021-02-04 07:50:38.647 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=SHUTDOWN
2021-02-04 07:50:38.654 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 000xxxxxxxxxx275: ZigBee saving network state complete.
2021-02-04 07:50:38.735 [DEBUG] [nding.zigbee.serial.ZigBeeSerialPort] - Serial port '/dev/ttyUSB1' closed.
2021-02-04 07:50:38.739 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network [zigbee:coordinator_ember:exxxxxxxxxb] closed.
2021-02-04 07:50:38.740 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_ember:exxxxxxxxxb].
2021-02-04 07:50:38.741 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel 11

So it looks like it closed and reopened the serial port and is trying to reinitialize.

I hate serial ports. Just wanted to throw that out there.

Will let you know how 3.0.1 goes.

Bruce_Osborne · February 4, 2021, 3:59pm

OK I have the coordinator but no Zigbee devices.
I originally bought the stick for Z-Wave access but have moved my production to a different stick. I now use this one for testing.

I know the binding developer is very busy IRL so I try to help out where I can.

mechalas · February 4, 2021, 6:32pm

I upgraded to 3.0.1 and it’s looking more positive. The coordinator started with an ONLINE status, and it stayed ONLINE even after a scan for ZigBee devices. I don’t have any devices for pairing at the moment–wanted to make sure this controller would work before going on a spending spree–but this is a change from the previous behavior so I am encouraged.

chris · February 5, 2021, 8:22am

Please enable full debug logging so we can see what is happening. Check out the binding docs which explain how to do this.

mechalas · February 5, 2021, 12:27pm

It appears to be working now, but I won’t know for sure until I get my first ZigBee device.

That being said, is there a more verbose log setting than this?

org.openhab.binding.zigbee                         │ DEBUG

Bruce_Osborne · February 5, 2021, 12:29pm

TRACE is more verbose than DEBUG but the developer says that is usually not helpful.

mechalas · February 5, 2021, 12:34pm

OK. In the mean time, per the docs, I’ve added:

com.zsmartsystems.zigbee                           │ DEBUG
com.zsmartsystems.zigbee.dongle.ember.internal.ash │ INFO