CC2531 USB stick running Zb 3.0 loses its settings (appears to be OH2 issue, not device issue)

Splitting off from Zigbee binding stopped working since 2.5 M4

OH2 2.5.7-stable

After updating a CC2531 stick from ZB 1.2HA to ZB 3.0 using the code at https://github.com/Koenkk/Z-Stack-firmware/tree/master/coordinator/

The coordinator worked fine for a few days (including several OH2 restarts and device repluggings), then lost all its settings and reverted to what appears to be factory defaults after an OH2 restart

Zigbee Channel, panid, extended panid and mesh update period are no longer controllable - Any attempts to edit them results in a reversion to defaults at OH2 restart

(apparently locked in Defaults:
“zigbee_channel”: 11,
“zigbee_panid”: 65534,
“zigbee_extendedpanid”: “00124B001CD48A18”,
“zigbee_meshupdateperiod”: 86400)

Zigbee_linkkey (which was at default anyway) and zigbee_networkkey are not interfered with

Setting them back to the configured values doesn’t result in pairing being re-established and restarting openhab has them revert back to the values above.

Attempting to pair ZB devices with the stick in this state results in pairing only lasting until OH restart

Even editing org.eclipse.smarthome.core.thing.Thing.json whilst OH2 is stopped is ineffective

The stick is still controllable with zigbee2mqtt, so this is pointing to some kind of OH2 problem

Once its in this state, attempts to alter the PANID are 100% failures whilst running, which I expect os why pairing is failing.

Ext panid will change (editing using paperui or habmin) but reverts at restart and none of these online changes actually seems to change any of the USB device parameters anyway - with or without a controller reset

As mentioned previously, please can you provide logs showing the issues you’re having. It will make it easier to understand what’s happening, and easier for us to help you with your problems.

You should not change the PANID after the network has been created - you will loose the ability to control devices.

what exactly do you need Chris? The existing logs aren’t showing much

This is what’s showing at restart

2020-08-08 16:42:16.688 [ERROR] [.cc2531.network.ZigBeeNetworkManager] - Failed to open the dongle.
    at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.initialiseZigBee(ZigBeeCoordinatorHandler.java:425) ~[?:?]
    at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.lambda$2(ZigBeeCoordinatorHandler.java:543) ~[?:?]
2020-08-08 16:42:16.701 [ERROR] [.cc2531.network.ZigBeeNetworkManager] - Failed to open the dongle.
    at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.initialiseZigBee(ZigBeeCoordinatorHandler.java:425) ~[?:?]
    at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.lambda$2(ZigBeeCoordinatorHandler.java:543) ~[?:?]
2020-08-08 16:42:16.707 [ERROR] [.cc2531.network.ZigBeeNetworkManager] - Failed to open the dongle.
    at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.initialiseZigBee(ZigBeeCoordinatorHandler.java:425) ~[?:?]
    at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.lambda$2(ZigBeeCoordinatorHandler.java:543) ~[?:?]
2020-08-08 16:42:16.712 [ERROR] [.cc2531.network.ZigBeeNetworkManager] - Failed to open the dongle.
    at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.initialiseZigBee(ZigBeeCoordinatorHandler.java:425) ~[?:?]
    at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.lambda$2(ZigBeeCoordinatorHandler.java:543) ~[?:?]

# ls -l /dev/ttyUSB.CC2531-01 
lrwxrwxrwx 1 root root 7 Aug  8 02:50 /dev/ttyUSB.CC2531-01 -> ttyACM0
# ls -l /dev/ttyACM0
crw-rw-rw- 1 openhab dialout 166, 0 Aug  8 16:46 /dev/ttyACM0

This is what’s logged when confic changes are attempted:

2020-08-08 16:42:42.906 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_cc2531:cdb14d26' has been updated.
2020-08-08 16:42:42.908 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from UNKNOWN to ONLINE
2020-08-08 16:50:23.780 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_cc2531:cdb14d26' has been updated.
2020-08-08 16:53:00.972 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_cc2531:cdb14d26' has been updated.

NB: Even though the stick is listed as online in Habmin/Paperui:

# lsof -n | grep ttyACM
lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/1000/gvfs
  Output information may be incomplete.

Take a look at the binding documentation - it describes how to put the logging into debug mode - at the moment the logs are useless without this.

I don’t understand what the issue is you’re trying to show here? By “even though the stick is listed as online in HABmin” I guess you mean it is actually offline? But the log also shows that it’s online so this looks consistent doesn’t it? It’s also useful to spell things out to me so that I can understand exactly what you think is wrong - remember - you’ve probably got more information than me, even if you don’t realise it…

I’ve no idea what this error is about - it’s not coming from openHAB - can you explain what you’re getting at with this please?

I don’t understand what the issue is you’re trying to show here? By “even though the stick is listed as online in HABmin” I guess you mean it is actually offline?

Yes

[lsof]

I’ve no idea what this error is about - it’s not coming from openHAB - can you explain what you’re getting at with this please?

“man lsof”- it’s a very useful (and extremely powerful) OS tool

“list open files”, piped through grep for ttyACM

if Openhab was working correctly the dongle process would be bound to /dev/ttyACM0 (and usually we see 50-60 subprocesses involved)

below, we can see what processes are using tty devices on the entire system

# lsof -n | grep /dev/tty
lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/1000/gvfs
  Output information may be incomplete.
systemd-l    4168                              root   20u      CHR                4,6        0t0         27 /dev/tty6
agetty      14717                              root    0u      CHR                4,1        0t0         22 /dev/tty1
agetty      14717                              root    1u      CHR                4,1        0t0         22 /dev/tty1
agetty      14717                              root    2u      CHR                4,1        0t0         22 /dev/tty1

Thanks - this is the sort of explanation I was after. I know and use linux, but I don’t know your system, so you are starting with a lot more information than I have. I had no idea that ttyACM was being used by this task, and you don’t even mention serial port issues in the description of this issue, so just providing such output with no explanation is pretty confusing.

If the serial port is not working, it will clearly be shown in the logs. Please take a look at providing this - otherwise we can discuss all sorts of things for a very long time, but it will largely just be guessing.

ok, after doing this and attempting to adjust the PANID away from 65534

2020-08-08 17:21:05.072 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration received (Coordinator).
2020-08-08 17:21:05.073 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_port as no change
2020-08-08 17:21:05.074 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_baud as no change
2020-08-08 17:21:05.074 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_initialise as no change
2020-08-08 17:21:05.074 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_channel as no change
2020-08-08 17:21:05.075 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_panid as no change
2020-08-08 17:21:05.075 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_znp_magicnumber as no change
2020-08-08 17:21:05.075 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_linkkey as no change
2020-08-08 17:21:05.075 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_extendedpanid as no change
2020-08-08 17:21:05.075 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_networkkey as no change
2020-08-08 17:21:05.076 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_meshupdateperiod as no change
2020-08-08 17:21:05.078 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_cc2531:cdb14d26' has been updated.

Altering other parameters works:

2020-08-08 17:21:20.792 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Processing zigbee_initialise -> false

except when it doesn’t:

 2020-08-08 17:21:44.848 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Processing zigbee_meshupdateperiod -> 300
2020-08-08 17:21:44.848 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Unhandled configuration parameter zigbee_meshupdateperiod >> 300.

It would be useful to get a long log, or one that shows the problems you’re having. I don’t see anything here that is abnormal and attributable to any sort of issue you’re trying to cover here.

disabling the dongle (in paperui)

2020-08-08 17:25:19.601 [WARN ] [core.thing.internal.ThingManagerImpl] - Disposing handler for thing 'zigbee:coordinator_cc2531:cdb14d26' takes more than 5000ms.
2020-08-08 17:25:19.609 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)

reenabling:

(I’m not terribly worried about the network keys and panid showing. They were randomly generated in the first place and I can regenerate them later)

2020-08-08 17:25:19.601 [WARN ] [core.thing.internal.ThingManagerImpl] - Disposing handler for thing 'zigbee:coordinator_cc2531:cdb14d26' takes more than 5000ms.
2020-08-08 17:25:19.609 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)
2020-08-08 17:26:07.170 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from UNINITIALIZED (DISABLED) to INITIALIZING
2020-08-08 17:26:07.174 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_cc2531:cdb14d26].
2020-08-08 17:26:07.174 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel 15
2020-08-08 17:26:07.174 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - PANID 6754
2020-08-08 17:26:07.174 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EPANID C38DF434D1C8C38B
2020-08-08 17:26:07.174 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key 9CA1248BDB42B6C8D2F85438CD511185
2020-08-08 17:26:07.174 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key 5A6967426565416C6C69616E63653039
2020-08-08 17:26:07.175 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_initialise found, initializeNetwork=false
2020-08-08 17:26:07.175 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key String 9CA1248BDB42B6C8D2F85438CD511185
2020-08-08 17:26:07.175 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network key final array 9CA1248BDB42B6C8D2F85438CD511185
2020-08-08 17:26:07.175 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key String 5A6967426565416C6C69616E63653039
2020-08-08 17:26:07.175 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link key final array 5A6967426565416C6C69616E63653039
2020-08-08 17:26:07.175 [DEBUG] [.zigbee.cc2531.handler.CC2531Handler] - Initializing ZigBee CC2531 serial bridge handler.
2020-08-08 17:26:07.176 [DEBUG] [.zigbee.cc2531.handler.CC2531Handler] - ZigBee CC2531 Coordinator opening Port:'/dev/ttyUSB.CC2531-01' PAN:1a62, EPAN:C38DF434D1C8C38B, Channel:15
2020-08-08 17:26:07.176 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
2020-08-08 17:26:07.176 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from INITIALIZING to UNKNOWN
2020-08-08 17:26:08.176 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
2020-08-08 17:26:08.177 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
2020-08-08 17:26:08.178 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
2020-08-08 17:26:08.188 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00124B001CD48A18: ZigBee reading network state complete.
2020-08-08 17:26:08.189 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyUSB.CC2531-01] at 115200 baud, flow control FLOWCONTROL_OUT_RTSCTS.
2020-08-08 17:26:08.256 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Serial port [/dev/ttyUSB.CC2531-01] is initialized.
2020-08-08 17:26:10.980 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Mesh Update Period 300
2020-08-08 17:26:11.040 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee Initialise: Previous device configuration was: channel=CHANNEL_00, PanID=65534, EPanId=C38DF434D1C8C38B
2020-08-08 17:26:11.801 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=ONLINE
2020-08-08 17:26:11.835 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee initialise done. channel=CHANNEL_11, PanId=65534  EPanId=00124B001CD48A18
2020-08-08 17:26:11.836 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_cc2531:cdb14d26' has been updated.
2020-08-08 17:26:11.837 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from UNKNOWN to ONLINE
2020-08-08 17:26:12.054 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00124B001CD48A18: ZigBee saving network state complete.


# lsof -n | grep /dev/tty
lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/1000/gvfs
  Output information may be incomplete.
systemd-l    4168                              root   20u      CHR                4,6        0t0         27 /dev/tty6
agetty      14717                              root    0u      CHR                4,1        0t0         22 /dev/tty1
agetty      14717                              root    1u      CHR                4,1        0t0         22 /dev/tty1
agetty      14717                              root    2u      CHR                4,1        0t0         22 /dev/tty1
java      1775091                           openhab   55u      CHR              166,0        0t0        357 /dev/ttyACM0
java      1775091 1775521 java              openhab   55u      CHR              166,0        0t0        357 /dev/ttyACM0
java      1775091 1775522 GC\x20Thr         openhab   55u      CHR              166,0        0t0        357 /dev/ttyACM0
java      1775091 1775523 G1\x20Mai         openhab   55u      CHR              166,0        0t0        357 /dev/ttyACM0
java      1775091 1775524 G1\x20Con         openhab   55u      CHR              166,0        0t0        357 /dev/ttyACM0
java      1775091 1775527 G1\x20Ref         openhab   55u      CHR              166,0        0t0        357 /dev/ttyACM0
java      1775091 1775529 G1\x20You         openhab   55u      CHR              166,0        0t0        357 /dev/ttyACM0
  [snip 60 more lines]

Going in with paperui and resetting the panid + epanid + channel to desired values and setting initialise on

2020-08-08 17:26:12.054 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00124B001CD48A18: ZigBee saving network state complete.
2020-08-08 17:33:29.288 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration received (Coordinator).
2020-08-08 17:33:29.288 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_port as no change
2020-08-08 17:33:29.289 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_baud as no change
2020-08-08 17:33:29.289 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Processing zigbee_initialise -> true
2020-08-08 17:33:29.289 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Processing zigbee_channel -> 15
2020-08-08 17:33:29.289 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_panid as no change
2020-08-08 17:33:29.289 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_znp_magicnumber as no change
2020-08-08 17:33:29.290 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_linkkey as no change
2020-08-08 17:33:29.290 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Processing zigbee_extendedpanid -> C38DF434D1C8C38B
2020-08-08 17:33:29.290 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_networkkey as no change
2020-08-08 17:33:29.290 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_meshupdateperiod as no change
2020-08-08 17:33:29.292 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=SHUTDOWN
2020-08-08 17:33:29.292 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_cc2531:cdb14d26' has been updated.
2020-08-08 17:33:29.295 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00124B001CD48A18: ZigBee saving network state complete.
2020-08-08 17:33:29.410 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Serial port '/dev/ttyUSB.CC2531-01' closed.

and at that point OH is no longer talking to the serial port.

You really have to wonder why it will not take a change to panid

At the moment I’m still trying to work out what the issue is to be honest. Is changing the pan ID the problem?

The logs are quite strange - are you sure you’ve fully enabled logging? I don’t see communications with the stick going on here, so maybe there’s a very fundamental issue with communications with the serial port.

setting these in habmin (remember the stick is actually unreachable at the moment even though it shows as online)

2020-08-08 17:38:20.279 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration received (Coordinator).
2020-08-08 17:38:20.281 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Processing zigbee_channel -> 15
2020-08-08 17:38:20.281 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Processing zigbee_panid -> 6754
2020-08-08 17:38:20.282 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Unhandled configuration parameter zigbee_panid >> 6754.
2020-08-08 17:38:20.284 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_cc2531:cdb14d26' has been updated.

Toggling disabled and then reenabled in paperui

Note that this time the panid sticks but the epanid and channel are killed

2020-08-08 17:38:57.423 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from ONLINE to UNINITIALIZED
2020-08-08 17:39:02.430 [WARN ] [core.thing.internal.ThingManagerImpl] - Disposing handler for thing 'zigbee:coordinator_cc2531:cdb14d26' takes more than 5000ms.
2020-08-08 17:39:02.434 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)
2020-08-08 17:39:07.109 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from UNINITIALIZED (DISABLED) to INITIALIZING
2020-08-08 17:39:07.114 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_cc2531:cdb14d26].
2020-08-08 17:39:07.114 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel 15
2020-08-08 17:39:07.114 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - PANID 6754
2020-08-08 17:39:07.114 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EPANID C38DF434D1C8C38B
2020-08-08 17:39:07.114 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key 9CA1248BDB42B6C8D2F85438CD511185
2020-08-08 17:39:07.115 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key 5A6967426565416C6C69616E63653039
2020-08-08 17:39:07.115 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_initialise found, initializeNetwork=true
2020-08-08 17:39:07.115 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key String 9CA1248BDB42B6C8D2F85438CD511185
2020-08-08 17:39:07.115 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network key final array 9CA1248BDB42B6C8D2F85438CD511185
2020-08-08 17:39:07.115 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key String 5A6967426565416C6C69616E63653039
2020-08-08 17:39:07.116 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising network
2020-08-08 17:39:07.117 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link key final array 5A6967426565416C6C69616E63653039
2020-08-08 17:39:07.117 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_cc2531:cdb14d26' has been updated.
2020-08-08 17:39:07.117 [DEBUG] [.zigbee.cc2531.handler.CC2531Handler] - Initializing ZigBee CC2531 serial bridge handler.
2020-08-08 17:39:07.117 [DEBUG] [.zigbee.cc2531.handler.CC2531Handler] - ZigBee CC2531 Coordinator opening Port:'/dev/ttyUSB.CC2531-01' PAN:1a62, EPAN:C38DF434D1C8C38B, Channel:15
2020-08-08 17:39:07.118 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
2020-08-08 17:39:07.118 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from INITIALIZING to UNKNOWN
2020-08-08 17:39:08.118 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
2020-08-08 17:39:08.119 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
2020-08-08 17:39:08.120 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
2020-08-08 17:39:08.133 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00124B001CD48A18: ZigBee reading network state complete.
2020-08-08 17:39:08.133 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyUSB.CC2531-01] at 115200 baud, flow control FLOWCONTROL_OUT_RTSCTS.
2020-08-08 17:39:08.200 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Serial port [/dev/ttyUSB.CC2531-01] is initialized.
2020-08-08 17:39:09.865 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Mesh Update Period 300
2020-08-08 17:39:09.925 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee Initialise: Previous device configuration was: channel=CHANNEL_00, PanID=65534, EPanId=C38DF434D1C8C38B
2020-08-08 17:39:09.926 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link key initialise 5A6967426565416C6C69616E63653039
2020-08-08 17:39:09.926 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network key initialise 9CA1248BDB42B6C8D2F85438CD511185
2020-08-08 17:39:14.844 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=ONLINE
2020-08-08 17:39:14.939 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee initialise done. channel=CHANNEL_11, PanId=6754  EPanId=00124B001CD48A18
2020-08-08 17:39:14.941 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_cc2531:cdb14d26' has been updated.
2020-08-08 17:39:14.941 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from UNKNOWN to ONLINE
2020-08-08 17:39:15.102 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00124B001CD48A18: ZigBee saving network state complete.

“The logs are quite strange - are you sure you’ve fully enabled logging? I don’t see communications with the stick going on here, so maybe there’s a very fundamental issue with communications with the serial port.”

That’s debug level, tail -F /var/log/openhab2/*log | grep -i zigbee (there are 30 other devices sending log updates - tasmota/mosquitto, network service, pings and other things and without the grep it’s swamped out)

in the cli:
openhab> log:set DEBUG org.openhab.binding.zigbee

if the comms aren’t tagged as zigbee then they’ll escape the grep

What do you mean by this? In the log I see the port is opening, although strangely there is no communications with the stick showing in the log.

I’m reasonably sure that you’ve not enabled debug logging fully, or your grep is killing off an awful log of data that I need to see. Please ensure logging is properly enabled and preferably do not filter logs if it’s really filtering everything out.

Well, class names can get truncated (as you can see) but I still think it’s unlikely that you’ve set the logging correctly as per the binding docs?

looking at the raw logfiles when attempting to reset epanid and channel in paperui

Note that the dongle is lost again.

==> /var/log/openhab2/openhab.log <==
2020-08-08 17:49:16.470 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration received (Coordinator).
2020-08-08 17:49:16.471 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_port as no change
2020-08-08 17:49:16.471 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_baud as no change
2020-08-08 17:49:16.471 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Processing zigbee_initialise -> true
2020-08-08 17:49:16.472 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Processing zigbee_channel -> 15
2020-08-08 17:49:16.472 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_panid as no change
2020-08-08 17:49:16.472 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_znp_magicnumber as no change
2020-08-08 17:49:16.472 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_linkkey as no change
2020-08-08 17:49:16.472 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Processing zigbee_extendedpanid -> C38DF434D1C8C38B
2020-08-08 17:49:16.473 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_networkkey as no change
2020-08-08 17:49:16.473 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Ignored zigbee_meshupdateperiod as no change

==> /var/log/openhab2/events.log <==
2020-08-08 17:49:16.479 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_cc2531:cdb14d26' has been updated.

==> /var/log/openhab2/openhab.log <==
2020-08-08 17:49:16.479 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=SHUTDOWN
2020-08-08 17:49:16.483 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00124B001CD48A18: ZigBee saving network state complete.
2020-08-08 17:49:16.525 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Serial port '/dev/ttyUSB.CC2531-01' closed.

do you want DEBUG or TRACE?

toggling disabled in paperui, raw logfile view

2020-08-08 17:52:12.848 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from ONLINE to UNINITIALIZED
 
==> /var/log/openhab2/openhab.log <==
2020-08-08 17:52:17.854 [WARN ] [core.thing.internal.ThingManagerImpl] - Disposing handler for thing 'zigbee:coordinator_cc2531:cdb14d26' takes more than 5000ms.

==> /var/log/openhab2/events.log <==
2020-08-08 17:52:17.857 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)

and back to enabled:

==> /var/log/openhab2/openhab.log <==
2020-08-08 17:53:59.741 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_cc2531:cdb14d26].
2020-08-08 17:53:59.741 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel 15
2020-08-08 17:53:59.741 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - PANID 6754
2020-08-08 17:53:59.741 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EPANID C38DF434D1C8C38B
2020-08-08 17:53:59.741 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key 9CA1248BDB42B6C8D2F85438CD511185
2020-08-08 17:53:59.742 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key 5A6967426565416C6C69616E63653039
2020-08-08 17:53:59.742 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_initialise found, initializeNetwork=true
2020-08-08 17:53:59.742 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key String 9CA1248BDB42B6C8D2F85438CD511185
2020-08-08 17:53:59.742 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network key final array 9CA1248BDB42B6C8D2F85438CD511185
2020-08-08 17:53:59.742 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key String 5A6967426565416C6C69616E63653039
2020-08-08 17:53:59.742 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising network
2020-08-08 17:53:59.744 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link key final array 5A6967426565416C6C69616E63653039
 
==> /var/log/openhab2/events.log <==
2020-08-08 17:53:59.744 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_cc2531:cdb14d26' has been updated.

==> /var/log/openhab2/openhab.log <==
2020-08-08 17:53:59.744 [DEBUG] [.zigbee.cc2531.handler.CC2531Handler] - Initializing ZigBee CC2531 serial bridge handler.
2020-08-08 17:53:59.744 [DEBUG] [.zigbee.cc2531.handler.CC2531Handler] - ZigBee CC2531 Coordinator opening Port:'/dev/ttyUSB.CC2531-01' PAN:1a62, EPAN:C38DF434D1C8C38B, Channel:15
2020-08-08 17:53:59.745 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start

==> /var/log/openhab2/events.log <==
2020-08-08 17:53:59.745 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from INITIALIZING to UNKNOWN

==> /var/log/openhab2/openhab.log <==
2020-08-08 17:54:00.745 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
2020-08-08 17:54:00.745 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
2020-08-08 17:54:00.746 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
2020-08-08 17:54:00.751 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00124B001CD48A18: ZigBee reading network state complete.
2020-08-08 17:54:00.751 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyUSB.CC2531-01] at 115200 baud, flow control FLOWCONTROL_OUT_RTSCTS.
2020-08-08 17:54:00.817 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Serial port [/dev/ttyUSB.CC2531-01] is initialized.
2020-08-08 17:54:03.609 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Mesh Update Period 300
2020-08-08 17:54:03.670 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee Initialise: Previous device configuration was: channel=CHANNEL_00, PanID=65534, EPanId=C38DF434D1C8C38B
2020-08-08 17:54:03.670 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link key initialise 5A6967426565416C6C69616E63653039
2020-08-08 17:54:03.670 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network key initialise 9CA1248BDB42B6C8D2F85438CD511185
2020-08-08 17:54:08.503 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=ONLINE
2020-08-08 17:54:08.597 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee initialise done. channel=CHANNEL_11, PanId=6754  EPanId=00124B001CD48A18

==> /var/log/openhab2/events.log <==
2020-08-08 17:54:08.598 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_cc2531:cdb14d26' has been updated.
2020-08-08 17:54:08.599 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from UNKNOWN to ONLINE

==> /var/log/openhab2/openhab.log <==
2020-08-08 17:54:08.755 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00124B001CD48A18: ZigBee saving network state complete.

Well, considering that if you change the channel, panid, epanid or netywork key it means you can no longer connect with your existing mesh… having this changed underneath you comes under “BAD THINGS HAPPENING”

openhab> log:set DEBUG org.openhab.binding.zigbee