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

chris · August 8, 2020, 5:01pm

Please explan what that means. I don’t see anything in the logs so it’s hard to correlate these sort of statements and understand what you are actually seeing.

This is also pretty confusing, because a few minutes ago you said

So somewhere in the past 10 minutes, between that statement that I should remember that the stick is unreachable, and this statement that it is lost “again” I guess it was working?

Debug is fine - as per the documentation.

Fine - but that’s not really a description of a problem - I can’t look for random “bad things” - I need some direction, and at the moment things here are extremely confusing.

Please can I ask you to take a step back and try and consolidate the issues you’re seeing. Please ensure that the logging is properly enabled - if you’re 100% sure it is then I’m not sure where to go from here as I’m not seeing any communications with the dongle.

chris · August 8, 2020, 5:02pm

And?

Stoatwblr · August 8, 2020, 5:05pm

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

And?

and the results are what I was pasting

chris · August 8, 2020, 5:06pm

But is that the only logging you’ve enabled? The binding docs asks for different logging that this doesn’t it?

If you don’t enable all the logging, as per the binding docs, then I won’t see the communications with the dongle.

Stoatwblr · August 8, 2020, 5:08pm

Apart from the dongle losing its settings, ANY attempt to adjust it in paperui or habmin whilst it’s online results in OH disconnecting from the serial port (verified with lsof)

The only thing I appear to be able to do inside paperui is enable/disable - which at least reestablishes a connection with the serial port (agan, verified with lsof)

Stoatwblr · August 8, 2020, 5:09pm

If you’re going to be cryptic and say “use the binding docs” then I’m having to rely on a google search to find what I think is appropriate

I’m not a mind reader. If you explicitly want a particular setting then SAY SO

I can see in further google search that you have repeatedly told people to put things in debug mode in other tickets then made exactly the same gripe when they’ve followed the same instructions I’ve found without actually offering to tell them what they should be doing. It’s less than helpful to be reduced to playing guessing games when people are trying to get you the information you need

chris · August 8, 2020, 5:17pm

Sorry - I didn’t realise it was a cryptic statement. If you didn’t know where to find the documentation, then you could have asked, but as it’s at the top of the forum I assumed people knew where the docs where.

https://www.openhab.org/addons/bindings/zigbee/

Well, if you’d just typed in openhab zigbee binding docs, then you would have also found it in the first search result.

I guess you’ve not read the docs. Please take a few minutes to do so, clearly consolidate the issue you’re having, then come back and let’s see what we can do to help.

No - but when I ask you to check the binding docs, you didn’t say you didn’t know what I meant. You kept saying that you had configured as per the docs. If you aren’t able to find the documentation, then you are also able to articulate that I hope?

chris · August 8, 2020, 5:19pm

My apologies. I referred you to the binding documentation - I assumed that was a reasonable thing to do and I didn’t think that was a guessing game. Sometimes you also need to make a little effort yourself.

Stoatwblr · August 8, 2020, 5:20pm

You’re making assumptions about what people will search for that don’t match reality. You’re also assuming that people will scroll to the top of the forum instead of switching to a search engine to quickly find what it is you actually want.

The most common google search is

openhab putting binding into debug mode
or
openhab putting zigbee binding into debug mode

Neither of which end up pointing to the items you’ve just referenced.

chris · August 8, 2020, 5:22pm

No - I asked you to read the binding documentation.

Sorry, but this is well off topic now so let’s just drop this. Hopefully you’ve now found the documentation - please have a read as there is some useful stuff that people have spent a lot of time writing.

Stoatwblr · August 8, 2020, 5:29pm

I guess you’ve not read the docs

I guess you’re making the classic error of a someone intimately connected to a project assuming that everyone else intimately knows the software in question. It’s something that I keep on running into in my day job working in the UK space industry where everything is highly compartmentalised and these kind of assumptions tend to lead to things like smearing probes across other planets (Beagle, “Splatterelli”, etc)

I HAVE read the docs. Several times. For anyone just venturing into OH they’re not overly helpful as they reference things which simply don’t exist in the UIs and assume people are already familiar with all the nuances of the software - the reference to “Karaf commands” sent me off on a wild goose chase for a week - if what it actually means is “using ‘openhab-cli console’” then that should be mentioned, etc.

one thing that stands out IMMEDIATELY in the section on debugging is telling people to “log:set info com.zsmartsystems.zigbee.dongle.ember.internal.ash”

That’s not exactly going to be useful for anyone not using an ember

chris · August 8, 2020, 5:46pm

I was trying to keep things simple - if everyone uses this configuration it will work fine. This is simply disabling some logging - if you don’t have an ember, then disabling something that didn’t exist doesn’t hurt.

Again - this is off topic.

Bruce_Osborne · August 8, 2020, 5:49pm

Developers who write the documentation about their software have every right to assume you read them.

This forum is to assist you so you can learn. We are not a HelpDesk providing complete solutions.

Stoatwblr · August 8, 2020, 6:06pm

After setting per https://www.openhab.org/addons/bindings/zigbee/

“When things don’t appear to be working” section (complete with the ember debug command)

Disabling in paperui:

==> /var/log/openhab2/events.log <==
2020-08-08 18:35:05.426 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from ONLINE to UNINITIALIZED

==> /var/log/openhab2/openhab.log <==
2020-08-08 18:35:05.431 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager shutdown: networkState=SHUTDOWN
2020-08-08 18:35:05.432 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - Data store: Deferred Write Time set to 0ms
2020-08-08 18:35:05.432 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - Data store: Max Deferred Write Time set to 0ms
2020-08-08 18:35:05.432 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00124B001CD48A18: Data store: Save rejected as executor is already shut down.
2020-08-08 18:35:05.432 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - Network discovery task: shutdown
2020-08-08 18:35:05.432 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: stopped
2020-08-08 18:35:05.432 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Shutdown
2020-08-08 18:35:05.433 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - Data store: Shutdown
2020-08-08 18:35:10.432 [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 18:35:10.436 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)

Reenabling:

2020-08-08 18:36:52.704 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:cdb14d26' changed from UNINITIALIZED (DISABLED) to INITIALIZING

==> /var/log/openhab2/openhab.log <==
2020-08-08 18:36:52.709 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_cc2531:cdb14d26].
2020-08-08 18:36:52.709 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel 15
2020-08-08 18:36:52.709 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - PANID 6754
2020-08-08 18:36:52.709 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EPANID 00124B001CD48A18
2020-08-08 18:36:52.709 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key 9CA1248BDB42B6C8D2F85438CD511185
2020-08-08 18:36:52.709 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key 5A6967426565416C6C69616E63653039
2020-08-08 18:36:52.709 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_initialise found, initializeNetwork=false
2020-08-08 18:36:52.710 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key String 9CA1248BDB42B6C8D2F85438CD511185
2020-08-08 18:36:52.710 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network key final array 9CA1248BDB42B6C8D2F85438CD511185
2020-08-08 18:36:52.710 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key String 5A6967426565416C6C69616E63653039
2020-08-08 18:36:52.710 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link key final array 5A6967426565416C6C69616E63653039
2020-08-08 18:36:52.710 [DEBUG] [.zigbee.cc2531.handler.CC2531Handler] - Initializing ZigBee CC2531 serial bridge handler.
2020-08-08 18:36:52.711 [DEBUG] [.zigbee.cc2531.handler.CC2531Handler] - ZigBee CC2531 Coordinator opening Port:'/dev/ttyUSB.CC2531-01' PAN:1a62, EPAN:00124B001CD48A18, Channel:15
2020-08-08 18:36:52.711 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start

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

==> /var/log/openhab2/openhab.log <==
2020-08-08 18:36:53.711 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
2020-08-08 18:36:53.712 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
2020-08-08 18:36:53.713 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Default: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=50, maxRetries=2]
2020-08-08 18:36:53.713 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=3, interTransactionDelay=1200, maxRetries=0]
2020-08-08 18:36:53.713 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Multicast: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=3, interTransactionDelay=1200, maxRetries=0]
2020-08-08 18:36:53.714 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager initialize: networkState=UNINITIALISED
2020-08-08 18:36:53.714 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to INITIALISING
2020-08-08 18:36:53.714 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
2020-08-08 18:36:53.719 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00124B001CD48A18: ZigBee reading network state complete.
2020-08-08 18:36:53.719 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00124B001CD48A18: Data store: Node was restored.
2020-08-08 18:36:53.720 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00124B001CD48A18: Updating node NWK=0000
2020-08-08 18:36:53.720 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - CC2531 transport initialize
2020-08-08 18:36:53.720 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyUSB.CC2531-01] at 115200 baud, flow control FLOWCONTROL_OUT_RTSCTS.
2020-08-08 18:36:53.786 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Serial port [/dev/ttyUSB.CC2531-01] is initialized.
2020-08-08 18:36:53.786 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  SYS_RESET (Packet: subsystem=null, length=1, apiId=41 00, data=FE 01 41 00 01 41, checksum=41, error=false)
2020-08-08 18:36:56.419 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- SYS_RESET_RESPONSE (FE 06 41 80 00 02 02 02 07 02 C0)
2020-08-08 18:36:56.420 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=6, apiId=41 80, data=FE 06 41 80 00 02 02 02 07 02 C0, checksum=C0, error=false
2020-08-08 18:36:56.420 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  SYS_VERSION (Packet: subsystem=null, length=0, apiId=21 02, data=FE 00 21 02 23, checksum=23, error=false)
2020-08-08 18:36:56.439 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  SYS_VERSION_RESPONSE (FE 0E 61 02 02 02 02 07 02 D9 14 34 01 02 00 00 00 00 90)
2020-08-08 18:36:56.440 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - CC2531 version is Software=2.7 Product=2 Hardware=2 Transport=2
2020-08-08 18:36:56.440 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 01 20, checksum=20, error=false)
2020-08-08 18:36:56.459 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 01 18 8A D4 1C 00 4B 12 00 6B)
2020-08-08 18:36:56.460 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Mesh Update Period 300
2020-08-08 18:36:56.460 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0500
2020-08-08 18:36:56.460 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher starting for endpoint 1 with profile ID 0104 (ZIGBEE_HOME_AUTOMATION)
2020-08-08 18:36:56.461 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0500
2020-08-08 18:36:56.461 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0019
2020-08-08 18:36:56.461 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0019
2020-08-08 18:36:56.464 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0001
2020-08-08 18:36:56.464 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0001
2020-08-08 18:36:56.465 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0006
2020-08-08 18:36:56.465 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0006
2020-08-08 18:36:56.465 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0008
2020-08-08 18:36:56.465 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0008
2020-08-08 18:36:56.465 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 000F
2020-08-08 18:36:56.466 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 000F
2020-08-08 18:36:56.466 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0101
2020-08-08 18:36:56.466 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0101
2020-08-08 18:36:56.466 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0102
2020-08-08 18:36:56.466 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0102
2020-08-08 18:36:56.467 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0201
2020-08-08 18:36:56.467 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0201
2020-08-08 18:36:56.467 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0202
2020-08-08 18:36:56.467 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0202
2020-08-08 18:36:56.467 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0300
2020-08-08 18:36:56.468 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0300
2020-08-08 18:36:56.468 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0400
2020-08-08 18:36:56.468 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0400
2020-08-08 18:36:56.468 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0402
2020-08-08 18:36:56.468 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0402
2020-08-08 18:36:56.469 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0403
2020-08-08 18:36:56.469 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0403
2020-08-08 18:36:56.469 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0405
2020-08-08 18:36:56.469 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0405
2020-08-08 18:36:56.469 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0406
2020-08-08 18:36:56.469 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0406
2020-08-08 18:36:56.470 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0500
2020-08-08 18:36:56.470 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0500
2020-08-08 18:36:56.470 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0502
2020-08-08 18:36:56.470 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0502
2020-08-08 18:36:56.470 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0B04
2020-08-08 18:36:56.470 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0B04
2020-08-08 18:36:56.472 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0005
2020-08-08 18:36:56.472 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0005
2020-08-08 18:36:56.472 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0006
2020-08-08 18:36:56.472 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0006
2020-08-08 18:36:56.472 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0008
2020-08-08 18:36:56.472 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0008
2020-08-08 18:36:56.473 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0402
2020-08-08 18:36:56.473 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0402
2020-08-08 18:36:56.473 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0000
2020-08-08 18:36:56.473 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0000
 2020-08-08 18:36:56.473 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0019
 2020-08-08 18:36:56.474 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0019
2020-08-08 18:36:56.474 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0000
2020-08-08 18:36:56.474 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0000
2020-08-08 18:36:56.474 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 05 24, checksum=24, error=false)
2020-08-08 18:36:56.480 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 05 00 8A D4 1C 00 4B 12 00 77)
2020-08-08 18:36:56.480 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 06 27, checksum=27, error=false)
2020-08-08 18:36:56.500 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 06 FE FF D4 1C 00 4B 12 00 FF)
2020-08-08 18:36:56.500 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 07 26, checksum=26, error=false)
2020-08-08 18:36:56.520 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 07 8B C3 C8 D1 34 F4 8D C3 B1)
2020-08-08 18:36:56.520 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee Initialise: Previous device configuration was: channel=CHANNEL_00, PanID=65534, EPanId=C38DF434D1C8C38B
2020-08-08 18:36:56.521 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager startup: reinitialize=false, networkState=INITIALISING
2020-08-08 18:36:56.521 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - CC2531 transport startup
2020-08-08 18:36:56.521 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Creating network as Coordinator
2020-08-08 18:36:56.521 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZDO_MSG_CB_REGISTER (Packet: subsystem=null, length=2, apiId=25 3E, data=FE 02 25 3E FF FF 19, checksum=19, error=false)
2020-08-08 18:36:56.540 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZDO_MSG_CB_REGISTER_SRSP (FE 01 65 3E 00 5A)
2020-08-08 18:36:56.541 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZB_WRITE_CONFIGURATION (Packet: subsystem=null, length=3, apiId=26 05, data=FE 03 26 05 8F 01 01 AF, checksum=AF, error=false)
2020-08-08 18:36:56.560 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZB_WRITE_CONFIGURATION_RSP (FE 01 66 05 00 62)
2020-08-08 18:36:56.561 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZDO_STARTUP_FROM_APP (Packet: subsystem=null, length=2, apiId=25 40, data=FE 02 25 40 00 00 67, checksum=67, error=false)
2020-08-08 18:36:58.449 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZDO_STARTUP_FROM_APP_SRSP (FE 01 65 40 00 24)
2020-08-08 18:36:58.450 [INFO ] [.cc2531.network.ZigBeeNetworkManager] - Initialized ZigBee network with existing network state.
2020-08-08 18:36:58.469 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZDO_STATE_CHANGE_IND (FE 01 45 C0 09 8D)
 2020-08-08 18:36:58.470 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: ZDO_STATE_CHANGE_IND{State=DEV_COORD_STARTED}
2020-08-08 18:36:58.470 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45c0
2020-08-08 18:36:58.470 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Started as ZigBee Coordinator
2020-08-08 18:36:58.470 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 4F 80 0D 00 04 C5)
2020-08-08 18:36:58.470 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=3, apiId=4F 80, data=FE 03 4F 80 0D 00 04 C5, checksum=C5, error=false
2020-08-08 18:36:58.470 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x4f80
2020-08-08 18:36:58.500 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_REGISTER (Packet: subsystem=null, length=11, apiId=24 00, data=FE 0B 24 00 01 04 01 00 00 00 00 00 01 00 05 2F, checksum=2F, error=false)
2020-08-08 18:36:58.506 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_REGISTER_SRSP (FE 01 64 00 00 65)
2020-08-08 18:36:58.506 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Registered endpoint 1 with profile: 260
2020-08-08 18:36:58.506 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to ONLINE
2020-08-08 18:36:58.507 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 05 24, checksum=24, error=false)
2020-08-08 18:36:58.507 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state ONLINE: Process running. 1 Nodes in network.
2020-08-08 18:36:58.507 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00124B001CD48A18: Adding local node to network, NWK=0000
2020-08-08 18:36:58.507 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00124B001CD48A18: Updating node NWK=0000
2020-08-08 18:36:58.507 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00124B001CD48A18: Node 0000 update
2020-08-08 18:36:58.507 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00124B001CD48A18: Node 0000 is not updated
2020-08-08 18:36:58.508 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to FFFC/0 for 0 seconds.
2020-08-08 18:36:58.508 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=--, permitDuration=0, tcSignificance=true]]
 2020-08-08 18:36:58.508 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFC/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=00, permitDuration=0, tcSignificance=true]]
2020-08-08 18:36:58.508 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
 2020-08-08 18:36:58.509 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=00, permitDuration=0, tcSignificance=true]
2020-08-08 18:36:58.509 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFC/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=80, rssi=--, lqi=--, payload=00 00 01]
2020-08-08 18:36:58.510 [DEBUG] [transaction.ZigBeeTransactionManager] - 00124B001CD48A18: Creating new Transaction Queue
 2020-08-08 18:36:58.510 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B001CD48A18: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=50, maxRetries=2]
2020-08-08 18:36:58.510 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B001CD48A18: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B001CD48A18 queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=--, permitDuration=0, tcSignificance=true]]
 2020-08-08 18:36:58.511 [DEBUG] [transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=00124B001CD48A18 queueTime=1, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=01, permitDuration=0, tcSignificance=true]]
 2020-08-08 18:36:58.511 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
 2020-08-08 18:36:58.511 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=01, permitDuration=0, tcSignificance=true]
 2020-08-08 18:36:58.511 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=81, rssi=--, lqi=--, payload=01 00 01]
 2020-08-08 18:36:58.512 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Startup
 2020-08-08 18:36:58.512 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - Network discovery task: starting
 2020-08-08 18:36:58.513 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for 0000 scheduling node discovery
 2020-08-08 18:36:58.513 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for 0000 starting node discovery
 2020-08-08 18:36:58.513 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state ONLINE: Notifying node 00124B001CD48A18 [0000]
2020-08-08 18:36:58.514 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B001CD48A18: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B001CD48A18 queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=--, nwkAddrOfInterest=0000, requestType=1, startIndex=0]]
2020-08-08 18:36:58.516 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00124B001CD48A18: Data store: Deferring write for 250ms.
2020-08-08 18:36:58.516 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - 00124B001CD48A18: DISCOVERY Extension: Adding discoverer for node
2020-08-08 18:36:58.515 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B001CD48A18: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=50, maxRetries=2]
2020-08-08 18:36:58.516 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=ONLINE
2020-08-08 18:36:58.516 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: created discoverer
2020-08-08 18:36:58.521 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: start discovery
2020-08-08 18:36:58.522 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: starting new tasks []
2020-08-08 18:36:58.522 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: has no new tasks to perform
2020-08-08 18:36:58.524 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update
2020-08-08 18:36:58.524 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - 00124B001CD48A18: DISCOVERY Extension: Starting mesh update
2020-08-08 18:36:58.524 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: Update mesh
2020-08-08 18:36:58.525 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: starting new tasks [NWK_ADDRESS, NEIGHBORS, ROUTES]
2020-08-08 18:36:58.525 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: scheduled [NWK_ADDRESS, NEIGHBORS, ROUTES]
2020-08-08 18:36:58.526 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 05 0B 00 00 00 00 00 00 00 67)
2020-08-08 18:36:58.526 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 FC FF 00 00 36 00 80 30 1F 03 00 00 01 B0, checksum=B0, error=false)
2020-08-08 18:36:58.547 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2020-08-08 18:36:58.547 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 07 26, checksum=26, error=false)
2020-08-08 18:36:58.547 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=00 state=TX_ACK
2020-08-08 18:36:58.547 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=00, state=TX_ACK, outstanding=2
2020-08-08 18:36:58.547 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=39, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=00, permitDuration=0, tcSignificance=true]]
2020-08-08 18:36:58.548 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2020-08-08 18:36:58.548 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete COMPLETE 0
2020-08-08 18:36:58.548 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 00 -> TX_ACK == COMPLETE
2020-08-08 18:36:58.561 [DEBUG] [transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=00124B001CD48A18 queueTime=47, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]]
2020-08-08 18:36:58.561 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2020-08-08 18:36:58.561 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]
2020-08-08 18:36:58.562 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0001, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=82, rssi=--, lqi=--, payload=02 00 00 01 00]
2020-08-08 18:36:58.567 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 07 18 8A D4 1C 00 4B 12 00 6D)
2020-08-08 18:36:58.567 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee initialise done. channel=CHANNEL_11, PanId=65534  EPanId=00124B001CD48A18
2020-08-08 18:36:58.567 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 00 00 00 00 36 00 81 30 1F 03 01 00 01 B3, checksum=B3, error=false)

Stoatwblr · August 8, 2020, 6:07pm

continued:

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

==> /var/log/openhab2/openhab.log <==
2020-08-08 18:36:58.587 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2020-08-08 18:36:58.587 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 45 B6 00 00 00 F0)
2020-08-08 18:36:58.587 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=01 state=TX_ACK
2020-08-08 18:36:58.587 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=3, apiId=45 B6, data=FE 03 45 B6 00 00 00 F0, checksum=F0, error=false
2020-08-08 18:36:58.587 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=01, state=TX_ACK, outstanding=2
2020-08-08 18:36:58.587 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45b6
2020-08-08 18:36:58.587 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 00 00 00 00 01 00 82 30 1F 05 02 00 00 01 00 80, checksum=80, error=false)
2020-08-08 18:36:58.588 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B001CD48A18 queueTime=78, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=01, permitDuration=0, tcSignificance=true]]
2020-08-08 18:36:58.588 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0A 45 FF 00 00 00 36 80 00 01 00 00 00 07)
2020-08-08 18:36:58.588 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2020-08-08 18:36:58.588 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=10, apiId=45 FF, data=FE 0A 45 FF 00 00 00 36 80 00 01 00 00 00 07, checksum=07, error=false
2020-08-08 18:36:58.588 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B001CD48A18: transactionComplete COMPLETE 1
2020-08-08 18:36:58.589 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8036, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=00 00]
2020-08-08 18:36:58.589 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 01 -> TX_ACK == COMPLETE
2020-08-08 18:36:58.589 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=00, status=SUCCESS]
2020-08-08 18:36:58.589 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=00, status=SUCCESS]
2020-08-08 18:36:58.590 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=00, status=SUCCESS] ZigBeeTransaction [ieeeAddress=00124B001CD48A18 queueTime=76, state=DISPATCHED, sendCnt=1, command=IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]]
2020-08-08 18:36:58.607 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2020-08-08 18:36:58.607 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0D 45 81 00 18 8A D4 1C 00 4B 12 00 00 00 F0 00 3A)
2020-08-08 18:36:58.607 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=02 state=TX_ACK
2020-08-08 18:36:58.608 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=13, apiId=45 81, data=FE 0D 45 81 00 18 8A D4 1C 00 4B 12 00 00 00 F0 00 3A, checksum=3A, error=false
2020-08-08 18:36:58.608 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=02, state=TX_ACK, outstanding=1
2020-08-08 18:36:58.608 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8001, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=00 00 18 8A D4 1C 00 4B 12 00 00 00 00 F0]
2020-08-08 18:36:58.608 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 02 -> TX_ACK == TRANSMITTED
2020-08-08 18:36:58.608 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=00, status=SUCCESS, ieeeAddrRemoteDev=00124B001CD48A18, nwkAddrRemoteDev=0000, startIndex=240, nwkAddrAssocDevList=[]]
2020-08-08 18:36:58.608 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=00, status=SUCCESS, ieeeAddrRemoteDev=00124B001CD48A18, nwkAddrRemoteDev=0000, startIndex=240, nwkAddrAssocDevList=[]]
2020-08-08 18:36:58.609 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=00, status=SUCCESS, ieeeAddrRemoteDev=00124B001CD48A18, nwkAddrRemoteDev=0000, startIndex=240, nwkAddrAssocDevList=[]] ZigBeeTransaction [ieeeAddress=00124B001CD48A18 queueTime=95, state=TRANSMITTED, sendCnt=1, command=IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]]
2020-08-08 18:36:58.609 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction response received - waiting TX_ACK: ZigBeeTransaction [ieeeAddress=00124B001CD48A18 queueTime=95, state=RESPONDED, sendCnt=1, command=IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]]
2020-08-08 18:36:58.627 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 15 45 FF 00 00 00 01 80 00 02 00 00 00 18 8A D4 1C 00 4B 12 00 00 00 00 2F)
2020-08-08 18:36:58.628 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=21, apiId=45 FF, data=FE 15 45 FF 00 00 00 01 80 00 02 00 00 00 18 8A D4 1C 00 4B 12 00 00 00 00 2F, checksum=2F, error=false
2020-08-08 18:36:58.628 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8001, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=00 00 18 8A D4 1C 00 4B 12 00 00 00 00]
2020-08-08 18:36:58.628 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=00, status=SUCCESS, ieeeAddrRemoteDev=00124B001CD48A18, nwkAddrRemoteDev=0000, startIndex=null, nwkAddrAssocDevList=[]]
2020-08-08 18:36:58.628 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=00, status=SUCCESS, ieeeAddrRemoteDev=00124B001CD48A18, nwkAddrRemoteDev=0000, startIndex=null, nwkAddrAssocDevList=[]]
2020-08-08 18:36:58.628 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=00, status=SUCCESS, ieeeAddrRemoteDev=00124B001CD48A18, nwkAddrRemoteDev=0000, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [ieeeAddress=00124B001CD48A18 queueTime=114, state=RESPONDED, sendCnt=1, command=IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]]
2020-08-08 18:36:58.629 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B001CD48A18 queueTime=115, state=COMPLETE, sendCnt=1, command=IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]]
2020-08-08 18:36:58.629 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for 0000 IeeeAddressRequest returned IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=00, status=SUCCESS, ieeeAddrRemoteDev=00124B001CD48A18, nwkAddrRemoteDev=0000, startIndex=null, nwkAddrAssocDevList=[]]
2020-08-08 18:36:58.629 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2020-08-08 18:36:58.629 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B001CD48A18: transactionComplete COMPLETE 0
2020-08-08 18:36:58.629 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for 0000 ending node discovery. Success=true.
2020-08-08 18:36:58.654 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 4F 80 08 02 00 C6)
2020-08-08 18:36:58.654 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=3, apiId=4F 80, data=FE 03 4F 80 08 02 00 C6, checksum=C6, error=false
2020-08-08 18:36:58.654 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x4f80
2020-08-08 18:36:58.766 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00124B001CD48A18: Data store: Writing node.
2020-08-08 18:36:58.771 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00124B001CD48A18: ZigBee saving network state complete.
2020-08-08 18:37:00.408 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: running NWK_ADDRESS
2020-08-08 18:37:00.408 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=--, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:00.409 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFF/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=03, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:00.409 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2020-08-08 18:37:00.409 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=03, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]
2020-08-08 18:37:00.409 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFF/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=83, rssi=--, lqi=--, payload=03 18 8A D4 1C 00 4B 12 00 00 00]
2020-08-08 18:37:00.410 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FF FF 00 00 00 00 83 30 1F 0B 03 18 8A D4 1C 00 4B 12 00 00 00 97, checksum=97, error=false)
2020-08-08 18:37:00.424 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2020-08-08 18:37:00.424 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=03 state=TX_ACK
2020-08-08 18:37:00.424 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=03, state=TX_ACK, outstanding=1
2020-08-08 18:37:00.425 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 03 -> TX_ACK == TRANSMITTED
2020-08-08 18:37:08.425 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=8017, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=03, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
 2020-08-08 18:37:08.425 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2020-08-08 18:37:08.426 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete FAILED 0
2020-08-08 18:37:08.426 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded retries 1
2020-08-08 18:37:08.426 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [ieeeAddress=null queueTime=8018, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=03, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:08.426 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: NetworkAddressRequest returned null
2020-08-08 18:37:08.426 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: request NWK_ADDRESS failed. Retry 1, wait 2175ms before retry.
2020-08-08 18:37:10.602 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: running NWK_ADDRESS
2020-08-08 18:37:10.602 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=--, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:10.603 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFF/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=04, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:10.603 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2020-08-08 18:37:10.603 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=04, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]
2020-08-08 18:37:10.603 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFF/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=84, rssi=--, lqi=--, payload=04 18 8A D4 1C 00 4B 12 00 00 00]
2020-08-08 18:37:10.604 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FF FF 00 00 00 00 84 30 1F 0B 04 18 8A D4 1C 00 4B 12 00 00 00 97, checksum=97, error=false)
2020-08-08 18:37:10.617 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2020-08-08 18:37:10.618 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=04 state=TX_ACK
2020-08-08 18:37:10.618 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=04, state=TX_ACK, outstanding=1
2020-08-08 18:37:10.618 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 04 -> TX_ACK == TRANSMITTED
2020-08-08 18:37:18.618 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=8016, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=04, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:18.619 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2020-08-08 18:37:18.619 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete FAILED 0
2020-08-08 18:37:18.619 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded retries 1
2020-08-08 18:37:18.619 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [ieeeAddress=null queueTime=8017, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=04, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:18.619 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: NetworkAddressRequest returned null
2020-08-08 18:37:18.620 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: request NWK_ADDRESS failed. Retry 2, wait 4350ms before retry.
2020-08-08 18:37:22.970 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: running NWK_ADDRESS
2020-08-08 18:37:22.970 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=--, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:22.971 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFF/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=1, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=05, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:22.971 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2020-08-08 18:37:22.971 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=05, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]
2020-08-08 18:37:22.971 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFF/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=85, rssi=--, lqi=--, payload=05 18 8A D4 1C 00 4B 12 00 00 00] 
2020-08-08 18:37:22.972 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FF FF 00 00 00 00 85 30 1F 0B 05 18 8A D4 1C 00 4B 12 00 00 00 97, checksum=97, error=false)
2020-08-08 18:37:22.986 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2020-08-08 18:37:22.986 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=05 state=TX_ACK
2020-08-08 18:37:22.986 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=05, state=TX_ACK, outstanding=1
2020-08-08 18:37:22.987 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 05 -> TX_ACK == TRANSMITTED
2020-08-08 18:37:30.987 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=8017, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=05, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:30.987 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2020-08-08 18:37:30.987 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete FAILED 0
2020-08-08 18:37:30.987 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded retries 1
2020-08-08 18:37:30.987 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [ieeeAddress=null queueTime=8017, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=05, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:30.988 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: NetworkAddressRequest returned null
2020-08-08 18:37:30.988 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: request NWK_ADDRESS failed. Retry 3, wait 6525ms before retry.
2020-08-08 18:37:37.513 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: running NWK_ADDRESS
2020-08-08 18:37:37.514 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=--, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:37.514 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFF/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=06, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:37.514 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2020-08-08 18:37:37.514 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=06, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]
2020-08-08 18:37:37.514 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFF/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=86, rssi=--, lqi=--, payload=06 18 8A D4 1C 00 4B 12 00 00 00]
2020-08-08 18:37:37.515 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FF FF 00 00 00 00 86 30 1F 0B 06 18 8A D4 1C 00 4B 12 00 00 00 97, checksum=97, error=false)
2020-08-08 18:37:37.529 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2020-08-08 18:37:37.529 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=06 state=TX_ACK
2020-08-08 18:37:37.529 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=06, state=TX_ACK, outstanding=1
2020-08-08 18:37:37.529 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 06 -> TX_ACK == TRANSMITTED
2020-08-08 18:37:45.530 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=8016, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=06, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:45.530 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2020-08-08 18:37:45.530 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete FAILED 0
2020-08-08 18:37:45.530 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded retries 1
2020-08-08 18:37:45.530 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [ieeeAddress=null queueTime=8016, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=06, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:45.531 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: NetworkAddressRequest returned null
2020-08-08 18:37:45.531 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: request NWK_ADDRESS failed. Retry 4, wait 8700ms before retry.
2020-08-08 18:37:54.231 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00124B001CD48A18: Node SVC Discovery: running NWK_ADDRESS
2020-08-08 18:37:54.232 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=--, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:54.232 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFF/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=07, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]]
2020-08-08 18:37:54.232 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2020-08-08 18:37:54.233 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=07, ieeeAddr=00124B001CD48A18, requestType=0, startIndex=0]
2020-08-08 18:37:54.233 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFF/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=87, rssi=--, lqi=--, payload=07 18 8A D4 1C 00 4B 12 00 00 00]
2020-08-08 18:37:54.233 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FF FF 00 00 00 00 87 30 1F 0B 07 18 8A D4 1C 00 4B 12 00 00 00 97, checksum=97, error=false)
2020-08-08 18:37:54.247 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2020-08-08 18:37:54.248 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=07 state=TX_ACK
2020-08-08 18:37:54.248 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=07, state=TX_ACK, outstanding=1
2020-08-08 18:37:54.248 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 07 -> TX_ACK == TRANSMITTED

Stoatwblr · August 8, 2020, 6:15pm

You’re forgetting that people most likely to be encountering problems are newcomers to this and my point about the documentation seems to have completely whizzed past you.

I can think of an event I was involved in 30 years ago where a $6 million HF radio transmitter was nearly destroyed thanks to documentation on servicing which detailed everything needed in nice steps and ended after 21 pages with a 2 line footnote: “before you start any of this, you must do XYZ or you will ruin the sensors”

The american company in question did a roaring trade in selling replacement sensors and saw no need to adjust the documentation - until telcos stopped buying their equipment in favour of japanese ones which amongst other things were far better documented. 5 years later they were out of business.

Similarly because the developers of the Beagle spacecraft wouldn’t listen to what we were telling them about their airbags, we had a sweepstake running about the size of the eventual martian crater (yes, we knew even before launch it was going to end up splattered)

After 40 years dealing with this stuff the primary lesson is to NEVER assume someone encountering problems has fully read (or understood) the docs and to work on the premise they’re coming in cold. Anything else is a recipe for disaster - and more opensource projects than I like to think of have been killed due to documentation issues driving users away

Stoatwblr · August 8, 2020, 6:21pm

“Developers who write the documentation about their software have every right to assume you read them.”

Funnily enough, I WRITE documentation for my code, but the first thing I do before turning it loose is throw it at someone else who hasn’t written or been involved in the coding to make sure it’s understandable by newcomers.

Blaming people who have problems because of opaque documentation is a fast way of ensuring that your opensource project gets abandoned by users

rossko57 · August 8, 2020, 6:25pm

Can you clarify what the perceived problem is, as of the end of your log?

Stoatwblr · August 8, 2020, 6:32pm

What was working is no longer working.

Somehow what’s supposedly being set as Panid/Epanid/channel/etc is being wiped out and replaced with different (“Wrong”) values, resulting in loss of connectivity to all existing devices.

Not given extended debug logs (yet, that’s next on the to do list):

Attempting to change parameters in habmin or paperui results in complete loss of serial communication because OH2 disconnects from the serial port

Even if it’s left “as-is”

re-pairing devices to the dongle in the new state only work as long as OH2 isn’t restarted. Upon restart all pairing is lost and those devices have to be re-paired again, (they can’t just rejoin)

Stoatwblr · August 8, 2020, 6:40pm

Panid/Epanid/channel/etc is being wiped out and replaced with different (“Wrong”) values

The particularly serious issue is the changing of channel to zigbee 11 - this directly clashes with Wifi channel 1 operated by neighbours on either side

I live in a terrace house on a London street and there are upwards of 20 2GHz wifi networks currently visible - the ones on channel 1 are particularly “loud” because they’re less than 6 metres away (through boundary walls) and selection of Zigbee channels is crucial to ensuring reasonably interference-free operation

Having panids being rewritten is pretty nasty too - any alteration of these requires re-pairing the entire mesh.