Initialization of CC2531 coordinator always fails

[openhab]

Initialization of CC2531 coordinator always fails

[cdjackson]

I see that the binding attempts to open the coordinator's serial port a second time after it has already opened it earlier in the bundle startup sequence.

I'm not especially familiar with the TI driver, but it sees the log you attached only shows the port being opened once doesn't it? Or is this not the full log?

[ScottKinSF]

That is not the full log, but it is the complete log from the time I stopped the zigbee bundle, restarted it and saw that coordinator init had failed.

I think you may have missed this line near the middle of the uploaded log:
2017-12-03 09:42:01.485 [DEBUG] [ndler.ZigBeeCoordinatorCC2531Handler] - ZigBee Coordinator ZNP opening Port:'/dev/ttyUSBzigbee' PAN:ffffdf34, Channel:11

[cdjackson]

I think you may have missed this line near the middle of the uploaded log:

No - I saw that, but it's not opening the serial port at that point. This just logs the settings - it opens the serial port later (ie at the end of your log).

Was it working previously and now it's stopped working?

[ScottKinSF]

This is the first time I have run OH2 since updating to OH2 2.2.0-SNAPSHOT build #1106. Prior to this, the ZigBee binding was working with the CC2531 dongle on OH2 2.2.0-SNAPSHOT build #1102.

FYI, I tried stopping the zigbee bundle, unplugging the CC2531 dongle, then plugging it back in before restarting the bundle -- same behavior.

[BTW: I appreciate your quick response, thank you!]

[cdjackson]

What hardware are you using? Is it a linux box? Are you sure all the serial permissions are set correct - that’s the most likely issue I think. At the moment, I don’t see any issue with the binding - the serial port can’t be opened, but I can’t do much to help with that I think...

[ScottKinSF]

I'm running OH2 2.2.0-SNAPSHOT on an RPi3 under an up-to-date install of openhabian. The zigbee binding has been working for more than 9 months with this exact configuration (other than OH2 software version.)

lrwxrwxrwx 1 root root 7 Dec 3 09:39 /dev/ttyUSBzigbee -> ttyACM4
crw-rw---- 1 root dialout 166, 4 Dec 3 09:39 /dev/ttyACM4

[cdjackson]

Well, I don't know that I can do anything really. There's nothing wrong that I can see - just the port won't open.

Sorry - if you can provide something that points to the binding, then I'm happy to take a look, but otherwise I don't see any issue. I also just checked here and it works fine (well, I only checked that the serial port opens) so there's no systematic issue with opening the serial port.

I suggest to close this.

[ScottKinSF]

After further investigation, it looks like the coordinator's serial port is opened OK when OH2 is (re)started, but nothing -- neither coordinator nor devices -- is shown as ONLINE. When the zigbee bundle is restarted, the coordinator initialization fails when it attempts to open the serial port, which I surmise must not have been closed when the bundle was stopped.

Restarting OH2 will result in the zigbee binding successfully opening the coordinator's serial port, but none of the zigbee deviices appear to be ONLINE.

zigbee-oh2-restarted.log
zigbee-device-status.log

[cdjackson]

Is this all that's in the log? It looks like it's working ok up to this point. Is this the version directly from cloudbees or are you compiling it yourself?

[ScottKinSF]

That is all that is in the log, nothing more appended to the zigbee log after waiting longer.

This version is directly from cloudbees.

[ScottKinSF]

I can try manually installing org.openhab.binding.zigbee-2.2.0-20171201.171549-78.jar, which I'm pretty confident was working before I updated OH2.

[cdjackson]

Let me take a look at something I added to the binding this morning - I didn’t think it was in the version on Cloudbees yet, but maybe it’s causing an issue.

[cdjackson]

Please try this version and see if it's any better.

[ScottKinSF]

That looks somewhat better, the coordinator is now indicated as ONLINE, but the devices are not.

zigbee:coordinator_cc2531:b0ec0a7d (Type=Bridge, Status=ONLINE, Label=CC2531EMK Coordinator, Bridge=null) zigbee:device:b0ec0a7d:000b57fffe2efe6a (Type=Thing, Status=OFFLINE: zigbee.status.offline_nodenotfound, Label=ZigbeeBulb1, Bridge=zigbee:coordinator_cc2531:b0ec0a7d) zigbee:device:b0ec0a7d:b0ce1814030107c6 (Type=Thing, Status=OFFLINE: zigbee.status.offline_nodenotfound, Label=SengLED CT Bulb2, Bridge=zigbee:coordinator_cc2531:b0ec0a7d) zigbee:device:b0ec0a7d:b0ce181403019f87 (Type=Thing, Status=OFFLINE: zigbee.status.offline_nodenotfound, Label=SengLED CT Bulb1, Bridge=zigbee:coordinator_cc2531:b0ec0a7d) zigbee:device:b0ec0a7d:b0ce18140306e556 (Type=Thing, Status=OFFLINE: zigbee.status.offline_nodenotfound, Label=SengLED Bulb1, Bridge=zigbee:coordinator_cc2531:b0ec0a7d)

zigbee-2.2.0.201712031907.log

Serial port is now closed when the bundle is stopped 👍
zigbee-2.2.0.201712031907-bundle-restart.log

[cdjackson]

I don’t think there’s much in the log, but please can you disable TRACE logging - it’s hard to see anything when the logging is so verbose.

[ScottKinSF]

I finally resorted to resetting all of my zigbee bulbs, then re-pairing them one by one. All of the SengLED bulbs are again paired and working. I cannot seem to get the one Tradfri bulb I'm using with the ZigBee binding reset or paired -- can't tell for sure whether it's a bulb reset or a pairing issue.

[ScottKinSF]

I was finally able to reset the Tradfri bulb and pair it. Unfortunately commands issued via its linked item do not affect the physical state of the bulb. However, I do see the commands logged in the zigbee binding log.

tradfri-bulb-commands.log

[cdjackson]

So this issue seems resolved then - the coordinator is working ok so let's close this. IF there are further problems (eg the bulb pairing) then if you think there's a bug please open another request (although I know people are using Tradfri bulbs, so I think it should pair ok).