Open Krzysztonek opened 2 months ago
Those fatal errors happen during the startup sequence but there is a retry mechanism in place to bypass them (due to hardware flow control issues, Silabs is aware). In short, it's a problem, but it's bypassed for now, and doesn't prevent Z2M from starting; it should not be related to your troubles here.
Seems devices are failing to ping though. Any chance you have a fuller debug
log file I can take a look at?
Did you try clearing the NVM3 on your adapter (backup/clear/restore)? Seems some configs are failing to set that really shouldn't, could be the adapter is having some troubles.
Did you try clearing the NVM3 on your adapter (backup/clear/restore)?
No, I'm not aware of any method clearing the NVM on my SkyConnect adapter. Would you please give me any hints? guidance? commands? procedures?
I rebooted my HA server several times. Unfortunately, it doesn't help/change/repair anything. Still the same set of error messages appears:
[00:47:00] INFO: Preparing to start...
[00:47:00] INFO: Socat not enabled
[00:47:00] INFO: Enabled Zigbee2MQTT watchdog with value 'default'
[00:47:01] INFO: Starting Zigbee2MQTT...
Starting Zigbee2MQTT with watchdog (60000,300000,900000,1800000,3600000).
[2024-07-10 00:47:04] warning: zh:ember: [EzspConfigId] Failed to SET "ADDRESS_TABLE_SIZE" TO "16" with status=ERROR_OUT_OF_MEMORY. Firmware value will be used instead.
[2024-07-10 00:47:05] warning: zh:ember: [EzspConfigId] Failed to SET "APS_UNICAST_MESSAGE_COUNT" TO "32" with status=ERROR_OUT_OF_MEMORY. Firmware value will be used instead.
[2024-07-10 00:47:05] warning: zh:ember: [EzspConfigId] Failed to SET "NEIGHBOR_TABLE_SIZE" TO "26" with status=ERROR_OUT_OF_MEMORY. Firmware value will be used instead.
[2024-07-10 00:47:05] warning: zh:ember: [EzspConfigId] Failed to SET "SOURCE_ROUTE_TABLE_SIZE" TO "200" with status=ERROR_INVALID_VALUE. Firmware value will be used instead.
[2024-07-10 00:47:05] warning: zh:ember: [EzspConfigId] Failed to SET "MULTICAST_TABLE_SIZE" TO "16" with status=ERROR_OUT_OF_MEMORY. Firmware value will be used instead.
[2024-07-10 00:47:40] warning: z2m: Failed to ping 'Energia AC Gab_Iga' (attempt 1/1, ZCL command 0xa4c138bcff9500c7/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":247}))
[2024-07-10 00:47:47] error: z2m: Publish 'set' 'state' to 'Gniazdo Iga' failed: 'Error: ZCL command 0x540f57fffe78b292/1 genOnOff.off({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":251})'
[2024-07-10 00:47:52] warning: z2m: Failed to ping 'Oświetlenie Łazienka Sufit' (attempt 1/1, ZCL command 0xa4c13802912ea5f0/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":252}))
[2024-07-10 00:47:58] warning: z2m: Failed to ping 'Gniazdo Salon Kominek' (attempt 1/1, ZCL command 0xa4c138726c8fed7f/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":2}))
[2024-07-10 00:48:05] error: z2m: Publish 'set' 'state' to 'Gniazdo Koc Krzyś' failed: 'Error: ZCL command 0xa4c138b489a67b2c/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":3})'
[2024-07-10 00:48:10] error: z2m: Publish 'set' 'state' to 'Gniazdo Koc Aga' failed: 'Error: ZCL command 0xa4c1386b6e9c24f1/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":4})'
[2024-07-10 00:48:15] warning: z2m: Failed to ping 'Roleta Gabinet Okno D' (attempt 1/1, ZCL command 0x2c1165fffeea778c/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":5}))
[2024-07-10 00:48:37] warning: z2m: Failed to ping 'Roleta Iga Okno D' (attempt 1/1, ZCL command 0x048727fffe557123/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":33}))
[2024-07-10 00:48:43] error: z2m: Publish 'set' 'state' to 'Zawór Gazowy' failed: 'Error: ZCL command 0xa4c138648462125a/1 genOnOff.off({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":36})'
[2024-07-10 00:49:00] warning: z2m: Failed to ping 'Oświetlenie Kuchnia' (attempt 1/1, ZCL command 0xa4c138247b91408c/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":63}))
[2024-07-10 00:49:07] warning: z2m: Failed to ping 'Oświetlenie Iga Sufit' (attempt 1/1, ZCL command 0xa4c138afaa2eefa0/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":66}))
[2024-07-10 00:49:14] warning: z2m: Failed to ping 'Oświetlenie Gabinet Sufit' (attempt 1/1, ZCL command 0xa4c13851a4420b95/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":68}))
[2024-07-10 00:49:21] warning: z2m: Failed to ping 'Oświetlenie Jadalnia' (attempt 1/1, ZCL command 0xa4c138e2b911d4a8/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":73}))
[2024-07-10 00:49:30] warning: z2m: Failed to ping 'Gniazdo Koc Aga' (attempt 1/1, ZCL command 0xa4c1386b6e9c24f1/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":89}))
[2024-07-10 00:49:38] error: z2m: Failed to read state of 'Oświetlenie Gabinet Sufit' after reconnect (ZCL command 0xa4c13851a4420b95/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":103}))
[2024-07-10 00:49:42] warning: z2m: Failed to ping 'Roleta Salon Okno PP' (attempt 1/1, ZCL command 0x048727fffe4eaafa/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":104}))
[2024-07-10 00:49:52] error: z2m: Failed to read state of 'Oświetlenie Iga Sufit' after reconnect (ZCL command 0xa4c138afaa2eefa0/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":110}))
[2024-07-10 00:49:53] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":6,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":150} messageTag=255]
[2024-07-10 00:49:57] warning: z2m: Failed to ping 'Roleta Salon Okno PL' (attempt 1/1, ZCL command 0xcc86ecfffeb010ff/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":114}))
[2024-07-10 00:50:07] warning: z2m: Failed to ping 'Roleta Salon Okno LP' (attempt 1/1, ZCL command 0xcc86ecfffea1f7ca/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":125}))
[2024-07-10 00:50:14] warning: z2m: Failed to ping 'Roleta Salon Okno LL' (attempt 1/1, ZCL command 0x3410f4fffee9ef9f/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":130}))
I'm even not able to get into UI:
The failed pings on startup are likely preventing the frontend from showing up in a timely manner. Current dev/edge has some improvements in that domain.
For the NVM3, you can try using the new ember-zli
: https://github.com/Nerivec/ember-zli (check the Wiki)
or universal-silabs-flasher
+ bellows
: procedure details
The overall process is the same in both: backup, clear the NVM3, restore.
Note: the backup/restore process is the same executed when you stop/start Z2M (when applicable).
You can DM me from zigbee2mqtt server on Discord if needed.
I tried to do backup of my skyconnect configuration following the linked procedure. When executing the following command:
➜ ~ bellows -d /dev/ttyUSB0 -b 115200 backup | tee bellow.backup.json
I got the following log:
Traceback (most recent call last):
File "/usr/bin/bellows", line 8, in <module>
sys.exit(main())
^^^^^^
File "/usr/lib/python3.12/site-packages/click/core.py", line 1157, in __call__
return self.main(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/lib/python3.12/site-packages/click/core.py", line 1078, in main
rv = self.invoke(ctx)
^^^^^^^^^^^^^^^^
File "/usr/lib/python3.12/site-packages/click/core.py", line 1688, in invoke
return _process_result(sub_ctx.command.invoke(sub_ctx))
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/lib/python3.12/site-packages/click/core.py", line 1434, in invoke
return ctx.invoke(self.callback, **ctx.params)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/lib/python3.12/site-packages/click/core.py", line 783, in invoke
return __callback(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/lib/python3.12/site-packages/click/decorators.py", line 33, in new_func
return f(get_current_context(), *args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/lib/python3.12/site-packages/bellows/cli/util.py", line 39, in inner
loop.run_until_complete(f(*args, **kwargs))
File "/usr/lib/python3.12/asyncio/base_events.py", line 687, in run_until_complete
return future.result()
^^^^^^^^^^^^^^^
File "/usr/lib/python3.12/site-packages/bellows/cli/backup.py", line 80, in backup
await _backup(ezsp)
File "/usr/lib/python3.12/site-packages/bellows/cli/backup.py", line 114, in _backup
(status, key) = await ezsp.getKey(key_type)
^^^^^^^^^^^
File "/usr/lib/python3.12/site-packages/bellows/ezsp/__init__.py", line 300, in __getattr__
return getattr(self._protocol, name)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/lib/python3.12/site-packages/bellows/ezsp/protocol.py", line 148, in __getattr__
raise AttributeError(f"{name} not found in COMMANDS")
AttributeError: getKey not found in COMMANDS
So, I've followed again this video to upgrade my SkyConnect dongle to 7.4.3.0 from this repo.
And I failed again:
[14:37:59] INFO: Preparing to start...
[14:37:59] INFO: Socat not enabled
[14:37:59] INFO: Enabled Zigbee2MQTT watchdog with value 'default'
[14:38:00] INFO: Starting Zigbee2MQTT...
Starting Zigbee2MQTT with watchdog (60000,300000,900000,1800000,3600000).
[2024-07-13 14:38:04] error: zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=RESET_WATCHDOG.
[2024-07-13 14:38:04] error: zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
[2024-07-13 14:38:04] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-07-13 14:38:06] warning: zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e]
[2024-07-13 14:38:06] error: zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE.
[2024-07-13 14:38:06] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR
[2024-07-13 14:38:06] error: zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR.
[2024-07-13 14:38:06] error: zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!!
[2024-07-13 14:38:06] error: zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR.
[2024-07-13 14:38:08] warning: zh:ember: [EzspConfigId] Failed to SET "APS_UNICAST_MESSAGE_COUNT" TO "32" with status=ERROR_OUT_OF_MEMORY. Firmware value will be used instead.
[2024-07-13 14:40:34] warning: zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e]
[2024-07-13 14:40:34] error: zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE.
[2024-07-13 14:40:34] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR
[2024-07-13 14:40:34] error: zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR.
[2024-07-13 14:40:34] error: zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!!
[2024-07-13 14:40:39] warning: zh:ember: [EzspConfigId] Failed to SET "APS_UNICAST_MESSAGE_COUNT" TO "32" with status=ERROR_OUT_OF_MEMORY. Firmware value will be used instead.
I'm stuck again, really don't understand what is going wrong in there.
Try this:
coordinator_backup.json
(in zigbee2mqtt data folder) has been updated/is recent (open with a text editor and check the date
in it)ember-zli
https://github.com/Nerivec/ember-zli/wiki#installationember-zli bootloader
command with the adapter plugged into the machineClear NVM3
menu https://github.com/Nerivec/ember-zli/wiki/Bootloader#clear-nvm3Update firmware
menu https://github.com/Nerivec/ember-zli/wiki/Bootloader#update-firmwarePre-defined
> Latest
Since you have a proper coordinator backup created by Z2M, it should detect that the adapter was reset, and reform the network using that backup. If all goes well, this should clear the NVM3 and restore your backup from Z2M. Note that step 2 is important, as the process described here relies on that backup file to be correct, if not you may end up having to re-pair all devices.
Yesterday I did the backup:
{
"metadata": {
"format": "zigpy/open-coordinator-backup",
"version": 1,
"source": "zigbee-herdsman@0.50.1",
"internal": {
"date": "2024-07-13T11:00:21.474Z",
"ezspVersion": 13
}
},
"stack_specific": {
"ezsp": {
"hashed_tclk": "7c257da8ae16c70d6ffececad90cfaf8"
}
},
...
I already updated my SkyConnect dongle firmware to EMBER. So, my first concern is, why is this dongle still visible as ezsp
, not as ember
.
Today I launched ember-zli bootloader
command and got the following:
[2024-07-14 11:05:21.861] info: cli: Data folder: C:\Users\Krzysztof\ember-zli.
? Adapter connection type Serial
? Adapter firmware baudrate 115200
? Serial port Silicon Labs Silicon Labs CP210x USB to UART Bridge (COM4)
USB\VID_10C4&PID_EA60\30C07EFC368DEC119AFC69E883C5466D (COM4)
? Flow control Software Flow Control (rtscts=false)
? Adapter model Home Assistant SkyConnect
[2024-07-14 11:05:21.499] info: gecko: Connecting to bootloader...
[2024-07-14 11:05:21.573] info: gecko: Serial port opened
[2024-07-14 11:05:21.585] info: gecko: Closing serial connection...
[2024-07-14 11:05:21.588] info: gecko: Port closed.
[2024-07-14 11:05:21.589] info: gecko: Unable to enter bootloader.
[2024-07-14 11:05:21.591] info: zh:ember:ezsp: ======== EZSP starting ========
[2024-07-14 11:05:21.592] info: zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-07-14 11:05:21.593] info: zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control.
[2024-07-14 11:05:21.604] info: zh:ember:uart:ash: Serial port opened
[2024-07-14 11:05:21.605] info: zh:ember:uart:ash: ======== ASH starting ========
[2024-07-14 11:05:21.134] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_RESET_FAIL | Adapter status: NO_ERROR
[2024-07-14 11:05:21.135] info: zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-07-14 11:05:21.138] info: zh:ember:uart:ash: ======== ASH starting ========
[2024-07-14 11:05:21.644] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_RESET_FAIL | Adapter status: NO_ERROR
[2024-07-14 11:05:21.645] info: zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-07-14 11:05:21.647] info: zh:ember:uart:ash: ======== ASH starting ========
[2024-07-14 11:05:21.166] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_RESET_FAIL | Adapter status: NO_ERROR
[2024-07-14 11:05:21.167] info: zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-07-14 11:05:21.170] info: zh:ember:uart:ash: ======== ASH starting ========
[2024-07-14 11:05:21.779] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_RESET_FAIL | Adapter status: NO_ERROR
[2024-07-14 11:05:21.780] info: zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-07-14 11:05:21.782] info: zh:ember:uart:ash: ======== ASH starting ========
[2024-07-14 11:05:21.290] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_RESET_FAIL | Adapter status: NO_ERROR
Error: Failed to start EZSP layer with status=33.
Still EZSP, not EMBER.. Is that OK?
Then I tried to run Clear NVM3
, getting this:
? Menu Clear NVM3
? Confirm NVM3 clearing? (Cannot be undone.) yes
[2024-07-14 11:34:42.456] error: gecko: Firmware upload aborted.
In the next step I executed:
? Menu Get info
[2024-07-14 11:34:42.492] info: gecko: Gecko Bootloader v2.01.01.
? Menu Update firmware
? Firmware Source Use pre-defined firmware (recommended or latest based on your adapter)
? Firmware version Latest (7.4.3.0)
[2024-07-14 11:34:42.985] info: gecko: Firmware file metadata: SDK version: 4.4.3, EZSP version: 7.4.3.0, baudrate: 115200, type: ncp-uart-hw
? Version: 7.4.3.0, Baudrate: 115200. Proceed with this firmware? yes
[2024-07-14 11:34:42.126] info: gecko: Firmware upload completed.
? Menu Clear NVM3
? Confirm NVM3 clearing? (Cannot be undone.) yes
[2024-07-14 11:34:42.455] error: gecko: Firmware upload aborted.
? Menu Exit bootloader
[2024-07-14 11:34:42.606] info: gecko: Closing serial connection...
[2024-07-14 11:34:42.608] info: gecko: Port closed.
At the end I connected my dongle back to HA server and started Z2M again with the following result:
[11:49:39] INFO: Preparing to start...
[11:49:39] INFO: Socat not enabled
[11:49:40] INFO: Starting Zigbee2MQTT...
Starting Zigbee2MQTT without watchdog.
[2024-07-14 11:49:55] error: z2m: Error while starting zigbee-herdsman
[2024-07-14 11:49:55] error: z2m: Failed to start zigbee
[2024-07-14 11:49:55] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-07-14 11:49:55] error: z2m: Exiting...
[2024-07-14 11:49:55] error: z2m: Error: Failed to start EZSP layer with status=HOST_FATAL_ERROR.
at EmberAdapter.initEzsp (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:889:19)
at EmberAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2722:24)
at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:129:29)
at Zigbee.start (/app/lib/zigbee.ts:63:27)
at Controller.start (/app/lib/controller.ts:139:27)
at start (/app/index.js:154:5)
[11:50:26] INFO: Preparing to start...
[11:50:26] INFO: Socat not enabled
[11:50:27] INFO: Starting Zigbee2MQTT...
Starting Zigbee2MQTT without watchdog.
[2024-07-14 11:50:42] error: z2m: Error while starting zigbee-herdsman
[2024-07-14 11:50:42] error: z2m: Failed to start zigbee
[2024-07-14 11:50:42] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-07-14 11:50:42] error: z2m: Exiting...
[2024-07-14 11:50:42] error: z2m: Error: Failed to start EZSP layer with status=HOST_FATAL_ERROR.
at EmberAdapter.initEzsp (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:889:19)
at EmberAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2722:24)
at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:129:29)
at Zigbee.start (/app/lib/zigbee.ts:63:27)
at Controller.start (/app/lib/controller.ts:139:27)
at start (/app/index.js:154:5)
Looks, I've not been succeeded :/
EZSP is the name of the "middle-man" in the EmberZNet stack (EmberZNet Serial Protocol = EZSP) so it's still there in some names, just the Z2M driver itself is named ember
, as opposed to the old driver, named ezsp
.
Your backup appears correct, and according to your logs, you are using the ember
driver properly.
Can you go into the data folder for ember-zli and retrieve the log file with the failed NVM3 clearing?
Also, can you enable debug
log for your next Z2M logs, so I can see where the error is exactly.
Here is my ember-zli data folder content: logs.zip
And this is my Z2M log folder content: z2m_log.zip
I'm not able to start Z2M at all, therefore I can't get into UI to enable debug
log for my next Z2M logs.
Alright, let's try another method:
ember-zli stack
command with the adapter plugged into the machineSame as before, make sure your coordinator_backup.json
from Z2M is proper so it will restore when you start it again.
PS: you can enable debug
in logs from the configuration.yaml
file directly.
advanced:
log_level: debug
I launched ember-zli stack
command with the SkyConnect dongle plugged into my PC USB port, getting this:
[2024-07-17 20:21:31.136] info: cli: Data folder: C:\Users\Krzysztof\ember-zli.
? Path: COM4, Baudrate: 115200, RTS/CTS: true. Use this config? yes
[2024-07-17 20:21:31.638] info: zh:ember:ezsp: ======== EZSP starting ========
[2024-07-17 20:21:31.639] info: zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-07-17 20:21:31.651] info: zh:ember:uart:ash: Serial port opened
[2024-07-17 20:21:31.655] info: zh:ember:uart:ash: ======== ASH starting ========
[2024-07-17 20:21:31.194] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_RESET_FAIL | Adapter status: NO_ERROR
[2024-07-17 20:21:31.195] info: zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-07-17 20:21:31.197] info: zh:ember:uart:ash: ======== ASH starting ========
[2024-07-17 20:21:31.731] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_RESET_FAIL | Adapter status: NO_ERROR
[2024-07-17 20:21:31.732] info: zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-07-17 20:21:31.738] info: zh:ember:uart:ash: ======== ASH starting ========
[2024-07-17 20:21:31.261] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_RESET_FAIL | Adapter status: NO_ERROR
[2024-07-17 20:21:31.262] info: zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-07-17 20:21:31.265] info: zh:ember:uart:ash: ======== ASH starting ========
[2024-07-17 20:21:31.802] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_RESET_FAIL | Adapter status: NO_ERROR
[2024-07-17 20:21:31.803] info: zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-07-17 20:21:31.806] info: zh:ember:uart:ash: ======== ASH starting ========
[2024-07-17 20:21:31.343] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_RESET_FAIL | Adapter status: NO_ERROR
Error: Failed to start EZSP layer with status=33.
Since some errors appeared, I launched the below set of commands: first ember-zli bootloader
and then ember-zli stack
:
As you can see, during first atempt the Clear NVM3
command failed with errors. During second atempt I was not able even to launch this command due to Error: Failed to start EZSP layer with status=33.
appearance, which finally stopped the whole process.
I don't understand what is wrong with this damn adapter. The only I can say, seems it's not damaged.
I would also bring your attention to one more point (please, see the below screen with Update Firmware Menu
):
From what I see, the recommended version of the firmware is 7.4.1.0 while I already updated the adapter to version 7.4.3.0. As per your advise I didn't downgrade it to recommended
, still keeping the latest
7.4.3.0.
Since you flashed latest before, make sure you use these settings: port: COM4, baudrate: 115200, rtscts: false
.
In the first screenshot, did you unplug the adapter before launching ember-zli stack
again? It's likely stuck in bootloader since you Force close
(instead of Exit bootloader
).
Unplug the adapter for a few seconds, then try using ember-zli stack
directly after re-plugging it.
I did exactly what you've suggested:
Launch ember-zli stack command with the adapter plugged into the machine Answer the prompt's questions Go to Reset NVM3 tokens menu https://github.com/Nerivec/ember-zli/wiki/Stack#reset-nvm3-tokens Confirm Exit Go back to Z2M, and start it again
This time Reset NVM3 tokens
was executed successfully! Indeed, when launching ember-zli stack
directly right after re-pluging the dongle, it works fine.
However, seems this method still doesn't bring any success, since the same errors appear again:
[08:26:04] INFO: Preparing to start...
[08:26:04] INFO: Socat not enabled
[08:26:05] INFO: Starting Zigbee2MQTT...
Starting Zigbee2MQTT without watchdog.
[2024-07-18 08:26:20] error: z2m: Error while starting zigbee-herdsman
[2024-07-18 08:26:20] error: z2m: Failed to start zigbee
[2024-07-18 08:26:20] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-07-18 08:26:20] error: z2m: Exiting...
[2024-07-18 08:26:20] error: z2m: Error: Failed to start EZSP layer with status=HOST_FATAL_ERROR.
at EmberAdapter.initEzsp (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:889:19)
at EmberAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2722:24)
at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:129:29)
at Zigbee.start (/app/lib/zigbee.ts:63:27)
at Controller.start (/app/lib/controller.ts:139:27)
at start (/app/index.js:154:5)
I also enabled debug
for Z2M, but it changed nothing in the logs. Seems I even didn't manage to reach Z2M, being stopped by the incorrect setup of my dongle.
I seem to remember you had some past troubles with your configuration.yaml
file being duplicated in different folders and the file you were editing wasn't the one actually used by Z2M. Can you double-check that it didn't happen again?
Yes, you're right, I had some troubles in the past. It was caused by having two different Z2M instances installed on the same machine with two different Zigbee dongles connected to this machine, to ballance the zigbee network traffic ( those days I was facing huge lags in my zigbee network)..
But this is the past, few months ago I installed a fresh HA system from scratch with one Z2M add-on. Since then it worked fine until this huge failure, which I'm facing now.
Currently no other Z2M folders exist on my machine, just one. Here is my full configuration.yaml
zip file uploaded directly from //192.168.1.20/config/zigbee2mqtt
folder:
configuration.yaml
, change rtscts: true
to rtscts: false
and log_level: warning
to log_level: debug
.
See if you can at least get the logs to show as debug.
Good thing is, you were able to use ember-zli stack
, so your adapter works fine (ember-zli uses the exact same code that Z2M uses), just need to figure out why your HA machine is not cooperating.
Note: August release will support concurrency, so you will probably want to remove adapter_concurrent: 1
too.
I managed to enable log_level: debug
and to change rtscts
from true
to false
in the configuration.yaml
file.
Here is my latest Z2M log.log
file.
log.log
However, I also noticed, that regardless rtscts
setting, zh controller starts with the following options:
...
debug: zh:controller: Starting with options
"serialPort":{"rtscts":true,"path":"/dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_30c07efc368dxxxxxxxxxxxxxxxxxxxx-if00-port0","adapter":"ember"}
...
It means that rtscts
value is always(?) set to true
, regardless its setting in configuration.yaml
....
Is it OK?
rtscts
being true (with the firmware you have requiring false) is likely what's preventing Z2M from starting since I don't see anything else that would be an issue now.
@Koenkk You know the structure of the HA add-on better than me. Could something be cached and make a mess of the settings in configuration.yaml
? Seems like something's not quite right here, it's not following what's in the file properly.
What a lovely Friday! I powered my HA server off for 2 hours, then powered on back. And my Z2M ...started working! Looks that even the zigbee network has been rebuilt successfully (I still need to re-pair some of the devices). Thanks to you, this huge milestone has been achieved! Here are my logs:
Currently only the UI is still not reachable. When clicking Open UI
button, I'm getting this:
Clicking RETRY
doesn't change anything, still the same message appears..
Do you know how to get into UI screen?
There are some improvements for the UI being slow to load on start for 1.39 in current dev branch/edge. If you want, you can try the Edge
version of the add-on. You have to make sure to shutdown the regular add-on, and disable auto-start and watchdog for it. Also make sure to remove the line adapter_concurrent: 1
from your configuration.yaml
. (You can switch back to regular, once August release is available.)
I am seeing a few repeating issues in your latest logs though:
[2024-07-19 12:41:06] error: z2m: MQTT error: client disconnecting
[2024-07-19 12:41:06] error: z2m: MQTT error: client disconnecting
[2024-07-19 12:41:06] error: z2m: MQTT error: client disconnecting
[2024-07-19 12:41:11] error: z2m: MQTT error: client disconnecting
This is happening right around the time the UI should become available.
You have to put rtscts
in the Z2M addon page configuration (under serial
), not the z2m configuration.yaml
itself.
Hello,
I seemed to have a related issue (?) with the logs spammed of
zh:ember:uart:ash: ======== ASH starting ========
error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_RESET_FAIL | Adapter status: NO_ERROR
info: zh:ember:uart:ash: ======== ASH Adapter reset ========
and then Z2M refusing to start.
Reflashing + doing the Reset NVM3 tokens [all defaults/unselected]
seemed to have done the trick. Thank you for that!
[not sure reflashing was needed but can't have hurt either]
What happened?
Some devices disappear or they are being disconnected from the network randomly for a long time. Then only part of them appears back again. One of the most problematic devices are the roller drivers AM43-0.45_40-ES-EB, which are out of the network since last update. After repairing they remain in the zigbee network for a while, then become randomly disconnected.
What did you expect to happen?
No response
How to reproduce it (minimal and precise)
No response
Zigbee2MQTT version
1.39.0-1
Adapter firmware version
7.4.2
Adapter
SkyConnect
Setup
x86
Debug log
And here is the most frequently repeatable list of errors:
Here is my config: