ZigBee controller initialization loop problem

Running 3.1M2, I have an Elelabs (Ember chipset) ZigBee controller that fails to become online for no apparent reason, it worked before. It’s in a constant loop.

@chris any idea?

EDIT: I sort of solved it but I had to flash the controller to v6 firmware and back to v8.
SW or HW reset hadn’t helped.

After successfull start and some ZigBee messages (ignore the timestamps, I took parts from different loops)

2021-03-26 23:41:14.373 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager initialize: networkState=UNINITIALISED
2021-03-26 23:41:14.374 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to INITIALISING
2021-03-26 23:41:14.375 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
2021-03-26 23:41:14.396 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - CCCCCCFFFEA5F167: ZigBee reading network state complete.
2021-03-26 23:41:14.397 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - CCCCCCFFFEA5F167: Data store: Node was restored.
2021-03-26 23:41:14.398 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - CCCCCCFFFEA5F167: Updating node NWK=0000
2021-03-26 23:41:14.405 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Dongle: Initialize with protocol ASH2.
2021-03-26 23:41:14.406 [DEBUG] [nding.zigbee.serial.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyUSB0] at 115200 baud, flow control FLOWCONTROL_OUT_RTSCTS.
2021-03-26 23:41:14.444 [DEBUG] [nding.zigbee.serial.ZigBeeSerialPort] - Serial port [/dev/ttyUSB0] is initialized.

I see the following 3 secs later

021-03-26 23:49:46.164 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:49:46.164 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:49:46.165 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueRequest [networkId=0, configId=EZSP_CONFIG_APS_UNICAST_MESSAGE_COUNT, value=10]
2021-03-26 23:49:46.184 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:49:46.184 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:49:46.185 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueRequest [networkId=0, configId=EZSP_CONFIG_BROADCAST_TABLE_SIZE, value=15]
2021-03-26 23:49:46.204 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:49:46.205 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:49:46.205 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueRequest [networkId=0, configId=EZSP_CONFIG_BINDING_TABLE_SIZE, value=2]
2021-03-26 23:49:46.225 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:49:46.225 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:49:46.226 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueRequest [networkId=0, configId=EZSP_CONFIG_NEIGHBOR_TABLE_SIZE, value=16]
2021-03-26 23:49:46.245 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:49:46.245 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:49:46.246 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueRequest [networkId=0, configId=EZSP_CONFIG_FRAGMENT_WINDOW_SIZE, value=1]
2021-03-26 23:49:46.266 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:49:46.266 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:49:46.266 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueRequest [networkId=0, configId=EZSP_CONFIG_FRAGMENT_DELAY_MS, value=50]
2021-03-26 23:49:46.286 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:49:46.286 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:49:46.287 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueRequest [networkId=0, configId=EZSP_CONFIG_PACKET_BUFFER_COUNT, value=255]
2021-03-26 23:49:46.306 [DEBUG] [s.zigbee.dongle.ember.ezsp.EzspFrame] - Error creating instance of EzspFrame
java.lang.reflect.InvocationTargetException: null
        at jdk.internal.reflect.GeneratedConstructorAccessor296.newInstance(Unknown Source) ~[?:?]
        at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
        at java.lang.reflect.Constructor.newInstance(Constructor.java:490) ~[?:?]
        at com.zsmartsystems.zigbee.dongle.ember.ezsp.EzspFrame.createHandler(EzspFrame.java:475) [bundleFile:?]
        at com.zsmartsystems.zigbee.dongle.ember.internal.ash.AshFrameHandler$1.run(AshFrameHandler.java:219) [bundleFile:?]
Caused by: java.lang.ArrayIndexOutOfBoundsException: Index 6 out of bounds for length 6
        at com.zsmartsystems.zigbee.dongle.ember.internal.serializer.EzspDeserializer.deserializeUInt8(EzspDeserializer.java:85) ~[?:?]
        at com.zsmartsystems.zigbee.dongle.ember.ezsp.command.EzspVersionResponse.<init>(EzspVersionResponse.java:58) ~[?:?]
        ... 5 more
2021-03-26 23:49:56.288 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetConfigurationValueRequest [networkId=0, configId=EZSP_CONFIG_END_DEVICE_POLL_TIMEOUT, value=169]

then ~10 sec later finally

021-03-26 23:41:28.539 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0402
2021-03-26 23:41:28.539 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0402
2021-03-26 23:41:28.540 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0000
2021-03-26 23:41:28.541 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0000
2021-03-26 23:41:28.541 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0019
2021-03-26 23:41:28.542 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0019
2021-03-26 23:41:28.542 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0000
2021-03-26 23:41:28.543 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0000
2021-03-26 23:41:28.543 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee Initialise: Previous device configuration was: channel=CHANNEL_11, PanID=65535, EPanId=06F23402EA6DBA08
2021-03-26 23:41:28.544 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_trustcentremode=TC_JOIN_INSECURE
2021-03-26 23:41:28.551 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetConcentratorResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:41:28.551 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSetConcentratorResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:41:28.571 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetPolicyResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:41:28.571 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetPolicyResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:41:28.571 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager startup: reinitialize=false, networkState=INITIALISING
2021-03-26 23:41:28.572 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Dongle: Startup - reinitialize=false
2021-03-26 23:41:28.572 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Adding Endpoint: ProfileID=0104, DeviceID=0050
2021-03-26 23:41:28.573 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Adding Endpoint: Input Clusters   0000
2021-03-26 23:41:28.573 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Adding Endpoint: Output Clusters  0000
2021-03-26 23:41:28.591 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspAddEndpointResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:41:28.591 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspAddEndpointResponse [networkId=0, status=EZSP_SUCCESS]
2021-03-26 23:41:28.689 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspNetworkInitResponse [networkId=0, status=EMBER_NOT_JOINED]
2021-03-26 23:41:28.689 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspNetworkInitResponse [networkId=0, status=EMBER_NOT_JOINED]
2021-03-26 23:41:28.691 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP dongle initialize failed to join network
2021-03-26 23:41:28.691 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to OFFLINE
2021-03-26 23:41:28.693 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=OFFLINE
2021-03-26 23:41:28.694 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00025816C2: Coordinator status changed to OFFLINE.
2021-03-26 23:41:28.696 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00025816C2: Coordinator status changed to OFFLINE.
2021-03-26 23:41:28.696 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00025816C2: Coordinator is unknown or not online.
2021-03-26 23:41:28.696 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00025816C2: Coordinator is unknown or not online.

2021-03-26 23:41:33.697 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2021-03-26 23:41:33.698 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager shutdown: networkState=OFFLINE
2021-03-26 23:41:33.699 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - Data store: Deferred Write Time set to 0ms
2021-03-26 23:41:33.699 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - Data store: Deferred Write Time set less than Max Deferred Write Time
2021-03-26 23:41:33.700 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - Data store: Max Deferred Write Time set to 0ms
2021-03-26 23:41:33.702 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to SHUTDOWN
2021-03-26 23:41:33.704 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=SHUTDOWN

Here is the Zigbee log viewer while you wait for Chris to assist.