2024-11-14 19:29:03.496 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration received.
2024-11-14 19:29:03.498 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_port as no change
2024-11-14 19:29:03.499 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_channel as no change
2024-11-14 19:29:03.500 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Processing zigbee_initialise -> true
2024-11-14 19:29:03.501 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_concentrator as no change
2024-11-14 19:29:03.502 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_trustcentremode as no change
2024-11-14 19:29:03.503 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_extendedpanid as no change
2024-11-14 19:29:03.504 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_baud as no change
2024-11-14 19:29:03.505 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_flowcontrol as no change
2024-11-14 19:29:03.506 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_panid as no change
2024-11-14 19:29:03.507 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_powermode as no change
2024-11-14 19:29:03.507 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_txpower as no change
2024-11-14 19:29:03.508 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_networksize as no change
2024-11-14 19:29:03.509 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_linkkey as no change
2024-11-14 19:29:03.510 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_childtimeout as no change
2024-11-14 19:29:03.511 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_networkkey as no change
2024-11-14 19:29:03.512 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - null: Ember configuration update: Ignored zigbee_meshupdateperiod as no change
2024-11-14 19:29:03.513 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration received (Coordinator).
2024-11-14 19:29:03.514 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: Configuration update: Processing zigbee_initialise -> true
The stick keeps in the state “Initializing”, nothing happens.
When i access the advanced option, the reinitialization switch remains in the same state. I would expect, that the switch has to change it´s state to “not activated”, but it´s still in the “activated” state.
Unfortunately this log is just too short to tell what’s happening - it doesn’t contain any of the lower level zigbee stuff and only shows the configuration that is sent to the binding (a whole 20 milliseconds ).
You should enable logging of com.zsmartsystems.zigbee at debug level - this will hopefully throw out a lot of debug and we can see what’s going on (hopefully).
There really must be more logging that this. The fact that this logging shows configuration updates means the handler is running, so there must have been log entries prior to this at least - ie during the startup?
So, i´ve done a reboot with DEBUG logging for com.zsmartsystems.zigbee.
You´ve mentioned, that a handler is running. During the shutdown process i´ve read this entry:
2024-11-18 17:25:13.213 [WARN ] [core.thing.internal.ThingManagerImpl] - Cannot unregister handler. No handler factory for thing 'zigbee:coordinator_ember:b0481bd394' found.
After the reboot, the log contains the following entries for ZigBee:
I don´t know… Additionally i´ve found at the events.log this entry:
> 2024-11-18 17:31:33.836 [INFO ] [penhab.event.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:coordinator_ember:b0481bd394 changed to UNKNOWN.
Does your complete openHAB system stop at this point? It seems strange that the log ends here. You say it “keeps initialising forever”, but I only see a single initialisation attempt, and then the log stops. It stops before the dongle initialisation is started, so it’s impossible for me to determine why it’s not initialising.
Sorry, but without more information - ie a log that shows the initialisation, it’s hard to say what’s going on.
Strange - then how do you know the dongle keeps initialising forever if the log stops? Also, looking at the log, ZWave also stops - so is that also not working? If the log you’ve provided is to be believed, then the dongle doesn’t keep initialising - it doesn’t even initialise once.
To me it seems there’s something else going on. The log shouldn’t stop like this - at least not unless OH has completely stopped working. These dongles work fine - I have 2 of them here that I use for development and others are using them. Again, if the dongle was faulty, we’d still see more information in the log - eg communication errors or something, but we see nothing at all…
I think the first thing to understand is what’s going on with the logging. Without this, it’s impossible to diagnose the zigbee problem.
I see the initialization state at the openhab GUI. When i use the switch to re-initializise, it remains in this position. I´ve tried this so much, saved it, changed the state, checked it again, changed the switch again and so on… But it remains in the state.
Openhab itself works fine. Z-Wave stick and all other devices works as expected.
You´ve to adviced me about the logging for com.zsmartsystems.zigbee. I´ve configured it as you suggested. But from my point of view, we´ve no entries for that. Maybe there´re other logging options available for that stick?
The logging is correct - there’s nothing more we an add. We see a few log entries in the log above from this (the ones with ZigBeeDongleEzsp and AshFrameHandler), so the logging is configured correctly to see the zigbee binding output…
But my point is from the log you’ve provided, there is (apparently) no logging from ANY binding, or any part of OH. From what you’ve said, after the ZWave initialises, there is no logging in the OH log.
Until we can see logging, it’s really hard to say what is happening. This doesn’t seem to be an issue with zigbee - at least I can’t think of anything that should be able to stop all logging if there’s an error in any binding. So, if all logging has stopped, then there is something else going on that needs to be solved first. Once we can see the logging, then we can work out what’s happening with zigbee.
I´ve tried some tasks to get more logs, but it doesn´t work. In the meantime, i´ve detected, that the stick changed their port to ttyUSB1
I´ve updated the configuration and now, the stick is marked as offline. Additionaly i´ve set a log directly at the console. That happens when i detach and attach the stick again:
openhab> log:tail com.zsmartsystems.zigbee
09:11:30.763 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH TX EZSP: EzspVersionRequest [networkId=0, desiredProtocolVersion=4]
09:11:33.609 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: Reconnect
09:11:33.616 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameRst []
09:11:36.822 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: Reconnect
09:11:36.825 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameRst []
09:11:40.032 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: Reconnect
09:11:40.037 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameRst []
09:11:40.834 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - Sending EZSP transaction timed out after 10 seconds
09:11:40.840 [DEBUG] [tsystems.zigbee.dongle.ember.EmberNcp] - No response from ezspVersion command
09:11:40.845 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Dongle: Version returned null. ASH/EZSP not initialised.
09:11:40.854 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to OFFLINE
09:11:41.029 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager shutdown: networkState=OFFLINE
09:11:41.033 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - Data store: Deferred Write Time set to 0ms
09:11:41.042 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - Data store: Deferred Write Time set less than Max Deferred Write Time
09:11:41.046 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - Data store: Max Deferred Write Time set to 0ms
09:11:41.054 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to SHUTDOWN
09:11:41.058 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - Data store: Shutdown
09:11:41.068 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Dongle: Shutdown
09:11:41.086 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - AshFrameHandler close.
09:11:41.106 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - Ember: Link State change to false, initialised=false, networkStateUp=false
09:11:41.143 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - Ember: Link State change to false ignored.
09:11:41.193 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - AshReceiveParserThread exited.
09:11:41.206 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - AshFrameHandler parser thread terminated.
09:11:41.221 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - AshFrameHandler InterruptedException processing EZSP frame
09:11:41.232 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - AshFrameHandler processor thread terminated.
09:11:41.238 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - AshFrameHandler close complete.
09:11:41.557 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Shutdown
09:11:41.563 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: Queue shutdown
09:11:41.571 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Multicast: Queue shutdown
09:11:41.690 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager shutdown: networkState=SHUTDOWN
09:11:41.716 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to OFFLINE
09:11:41.733 [DEBUG] [s.zigbee.internal.NotificationService] - NotificationService is shutdown. Not scheduling com.zsmartsystems.zigbee.ZigBeeNetworkManager$5
09:11:41.750 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - Data store: Deferred Write Time set to 0ms
09:11:41.758 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - Data store: Max Deferred Write Time set to 0ms
09:11:41.767 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to SHUTDOWN
09:11:41.775 [DEBUG] [s.zigbee.internal.NotificationService] - NotificationService is shutdown. Not scheduling com.zsmartsystems.zigbee.ZigBeeNetworkManager$5
09:11:41.789 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - Data store: Shutdown
09:11:41.800 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Dongle: Shutdown
09:11:41.840 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Shutdown
09:11:41.857 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: Queue shutdown
09:11:41.878 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Multicast: Queue shutdown
09:11:42.991 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Default: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
09:11:42.998 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=4000, maxRetries=0]
09:11:43.001 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Multicast: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=3, interTransactionDelay=1200, maxRetries=0]
09:11:43.006 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager initialize: networkState=UNINITIALISED
09:11:43.015 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to INITIALISING
09:11:43.040 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Dongle: Initialize with protocol ASH2.
09:11:43.176 [ERROR] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Dongle: Unable to open serial port
09:11:43.190 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to OFFLINE
And here is the result for dmesg | grep usb:
[1008804.643379] usb 3-2: USB disconnect, device number 3
[1008808.396917] usb 3-2: new full-speed USB device number 4 using ohci-pci
[1008808.603856] usb 3-2: New USB device found, idVendor=10c4, idProduct=ea60, bcdDevice= 1.00
[1008808.603885] usb 3-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[1008808.603896] usb 3-2: Product: Sonoff Zigbee 3.0 USB Dongle Plus V2
[1008808.603906] usb 3-2: Manufacturer: Itead
[1008808.603915] usb 3-2: SerialNumber: 7eb4fca5f912ef11809e6fb8bf9df066
[1008808.614097] usb 3-2: cp210x converter now attached to ttyUSB1
The logging completely stops, so I don’t see it being any different with any binding.
This dongle does work - I use them here (Sonoff have supplied me a couple for development) - the issue is to find out what’s wrong - why it doesn’t log, why it doesn’t (maybe) initialise, and why the serial port is incorrect…
).
