Koenkk
(reopened) CRASH on interview
What happened?
I'm trying to interview a leak sensor. Every time I interview it, I get the following crash:
Error: Failure send findKeyTableEntry:{"type":"Buffer","data":[113,0,1,117,0,218,160,44,0,0,163,34,0,1]} at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:562:23 at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)
NOTE: this continues https://github.com/Koenkk/zigbee2mqtt/issues/17532 which was closed, despite 5 others reporting the same issue.
I included the ezsp debug logs.
What did you expect to happen?
The interview to succeed, without crashing zigbee2mqtt!
How to reproduce it (minimal and precise)
Remove device. Re-add device
CRASH!
Zigbee2MQTT version
1.32.2
Adapter firmware version
6.10.3.0 build 297
Adapter
ezsp (Sonoff Dongle-E)
Debug log
2023-09-02T01:37:25.243Z zigbee-herdsman:adapter:ezsp:debg processMessage: {"messageType":0,"apsFrame":{"profileId":260,"clusterId":2820,"sourceEndpoint":1,"destinationEndpoint":1,"options":64,"groupId":0,"sequence":56},"lqi":156,"rssi":-61,"sender":41270,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[24,14,10,11,5,41,242,2]}}
2023-09-02T01:37:26.965Z zigbee-herdsman:adapter:ezsp:debg Device join request received: 57602 0022a300002ca0da
2023-09-02T01:37:29.134Z zigbee-herdsman:adapter:ezsp:debg Requesting 'Node Descriptor' for '57602'
2023-09-02T01:37:29.153Z zigbee-herdsman:adapter:ezsp:debg processMessage: {"messageType":0,"apsFrame":{"profileId":260,"clusterId":2820,"sourceEndpoint":1,"destinationEndpoint":1,"options":64,"groupId":0,"sequence":221},"lqi":136,"rssi":-66,"sender":33556,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[24,43,10,11,5,41,116,2]}}
2023-09-02T01:37:29.157Z zigbee-herdsman:adapter:ezsp:debg processMessage: {"messageType":0,"apsFrame":{"profileId":260,"clusterId":2820,"sourceEndpoint":1,"destinationEndpoint":1,"options":64,"groupId":0,"sequence":206},"lqi":156,"rssi":-61,"sender":8320,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[24,15,10,11,5,41,2,0]}}
2023-09-02T01:37:29.195Z zigbee-herdsman:adapter:ezsp:debg processMessage: {"messageType":4,"apsFrame":{"profileId":0,"clusterId":6,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":74},"lqi":160,"rssi":-60,"sender":63352,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[99,253,255,4,1,1,25,0,0]}}
2023-09-02T01:37:29.607Z zigbee-herdsman:adapter:ezsp:debg processMessage: {"messageType":0,"apsFrame":{"profileId":260,"clusterId":1794,"sourceEndpoint":1,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":72},"lqi":156,"rssi":-61,"sender":10857,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[8,19,10,0,0,37,198,43,0,0,0,0]}}
2023-09-02T01:37:29.612Z zigbee-herdsman:adapter:ezsp:debg sendZclFrameToEndpointInternal 0xb0ce1814001d7a6a:10857/1 (0,0,1)
Error: Failure send findKeyTableEntry:{"type":"Buffer","data":[113,0,1,117,0,218,160,44,0,0,163,34,0,1]}
at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:562:23
at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)
FYI - When I turn the system logging up to Debug (not ezsp logging, zigbee2mqtt logging), then the interview succeeds. So it looks like some kind of race condition where we're looking for something before it exists, and the extra logging from debug logging gives it enough time (?).
However, I can't (and don't want to) keep debug logging up permanently, as right now, the timeout on ezsp is too low (it's 10s and should be 30s or so, and the data going to the log file causes enough of a delay in processing (essentially I/O clogging up the main worker thread) during the HA interview that it it will crash on startup - so my logging is set to warn.
I experienced all the behaviors dscribed by all writers here.
Zigbee2MQTT version 1.33.0
Adapter ezsp (Sonoff Dongle-E)
Hi, I have the same Zigbee2MQTT 1.33.0 Sonoff Dongle-E 6.10.3 version Thanks
Still having the same issue. Every other time the HA Addon crashed upon pairing a device, irrespective what kind of device I'm paring. Keeping the addon updated, now with 1.33.0
Hello, Trying to pair 0xa46dd4fffe09620f unsuccessfully (I have the same behavior on 4 similar devices)
Zigbee2MQTT:info 2023-09-27 10:55:53: Device '0xa46dd4fffe09620f' joined Zigbee2MQTT:info 2023-09-27 10:55:54: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0xa46dd4fffe09620f","ieee_address":"0xa46dd4fffe09620f"},"type":"device_joined"}' Zigbee2MQTT:info 2023-09-27 10:55:54: Starting interview of '0xa46dd4fffe09620f' Zigbee2MQTT:info 2023-09-27 10:55:55: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0xa46dd4fffe09620f","ieee_address":"0xa46dd4fffe09620f","status":"started"},"type":"device_interview"}' Zigbee2MQTT:warn 2023-09-27 10:55:55: Failed to ping '0x385b44fffe57f840' (attempt 1/1, Read 0x385b44fffe57f840/1 genBasic(["zclVersion"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 46483 - 1 - 233 - 0 - 1 after 10000ms)) Error: Failure send findKeyTableEntry:{"type":"Buffer","data":[128,0,1,117,0,15,98,9,254,255,212,109,164,1]} at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:562:23 at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)
@Speedy1496 Such errors tell me that the connection with the chip may be interrupted. findKeyTableEntry - this command should be executed whenever there is a connection to the chip. And then even the 10 second timeout ended. Now I’ll ask the standard tricky questions:
- stick on a usb extension cable?
- are there any USB3 devices near the stick?
- is there enough power (in pairing mode, consumption increases and with weak power supplies the stick may be lost in the system)?
I have 3 setups with ZBdongle-E. 2 of those are using Zigbee2mqtt on rpiB and on both I keep receiving findKeyTableEntry crash after a few devices are paired. I will do some experimenting with the power supply and extension cable. Should using a powered USB hub help resolving the potential power supply issue?
The third setup uses ZHA on a desktop computer and so far I haven't experienced any issues there.
@kirovilya Hi, The stick is on and extension cable as I found in the preconisation For USB 3 I will move the RP3 somewhere else. I'm not sure of what "near" mean. For the power supply I will try something like what oversc0re described by using a USB hub in between the RP3 and the dongle
I keep you in touch Thx
@kirovilya Indeed I moved the RB on the other side of the room and I put a longer USB extension and now it visibly work properly Thank you for your help
Sébastien
FYI - I've been saying for a while the ezsp timeout should increase to 30s (from 10s), which would match other adapters https://github.com/Koenkk/zigbee-herdsman/blob/5507880d332af8a36ffa1548ad44efc15b6f70a6/src/adapter/deconz/adapter/deconzAdapter.ts#L323 https://github.com/Koenkk/zigbee-herdsman/blob/5507880d332af8a36ffa1548ad44efc15b6f70a6/src/adapter/deconz/adapter/deconzAdapter.ts#L482
It would also help with the timeout on sending the autoconfig information (for home assistant) if debug logging is enabled when you have a high number of entities (eg. above 10k) (short version: since the whole things is single threaded, the massive amount of i/o due to logging can be enough to exceed the 10s timeout for ezsp). Though that should be fixed by making logging async in a different thread so no logging can never affect the main processing. But that's a different issue entirely.
good video about USB3 and Zigbee https://www.youtube.com/watch?v=tHqZhNcFEvA
@corporategoth Show me exactly where you want to increase the timeout for the ezsp adapter code? In the cases under analysis, packet transmission occurs between the host (z2m) and the stick, so there can be no talk of any timeout of 30 seconds. A large timeout is needed when the command goes to network devices. But I still don’t see that the problem is in the transmission over the network.
@kirovilya, my logs are very similar. " Zigbee2MQTT:debug 2023-09-30 11:31:18: Received Zigbee message from 'Porte Veranda D D', type 'commandStatusChangeNotification', cluster 'ssIasZone', data '{"extendedstatus":0,"zonestatus":1}' from endpoint 1 with groupID 0 Zigbee2MQTT:info 2023-09-30 11:31:18: MQTT publish: topic 'zigbee2mqtt/Porte Veranda D D', payload '{"battery":100,"battery_low":false,"contact":false,"device":{"applicationVersion":5,"dateCode":"20211103","friendlyName":"Porte Veranda D D","hardwareVersion":1,"ieeeAddr":"0x00124b002445229e","manufacturerID":0,"manufacturerName":"eWeLink","model":"SNZB-04","networkAddress":43573,"powerSource":"Battery","type":"EndDevice","zclVersion":1},"last_seen":"2023-09-30T10:31:18.636Z","linkquality":196,"tamper":false,"voltage":3000}' Error: Failure send findKeyTableEntry:{"type":"Buffer","data":[95,0,1,117,0,158,34,69,36,0,75,18,0,1]} at /var/www/html/plugins/z2m/resources/zigbee2mqtt/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:562:23 at Queue.executeNext (/var/www/html/plugins/z2m/resources/zigbee2mqtt/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32) "
Regarding your questions. I am using the same powered USB hub (2.0) that I used for the last 2 years with my Combee II and Deconz. Anyway, the real problem for me is the CRASH of Zigbee2mqtt that makes it unusable. I have more than 60 devices and, each time I want to add a new one (even a "simple" one like here with a Sonoff SNZB 04) the whole system crashed and it needs sometimes to be back to normal.
Thanks
@corporategoth Show me exactly where you want to increase the timeout for the ezsp adapter code? In the cases under analysis, packet transmission occurs between the host (z2m) and the stick, so there can be no talk of any timeout of 30 seconds. A large timeout is needed when the command goes to network devices. But I still don’t see that the problem is in the transmission over the network.
There are 4 places I can find that have 10s timeouts - though I think the waitFor (the last two) is more important: https://github.com/Koenkk/zigbee-herdsman/blob/5507880d332af8a36ffa1548ad44efc15b6f70a6/src/adapter/ezsp/driver/driver.ts#L494 https://github.com/Koenkk/zigbee-herdsman/blob/5507880d332af8a36ffa1548ad44efc15b6f70a6/src/adapter/ezsp/driver/driver.ts#L506 https://github.com/Koenkk/zigbee-herdsman/blob/5507880d332af8a36ffa1548ad44efc15b6f70a6/src/adapter/ezsp/driver/driver.ts#L655 https://github.com/Koenkk/zigbee-herdsman/blob/5507880d332af8a36ffa1548ad44efc15b6f70a6/src/adapter/ezsp/driver/ezsp.ts#L639
I don't know exactly what they are used for in each case.
What I WILL say is, I have almost 160 devices. I don't think I got crashes with a lesser number of devices. The timeout is also causing problems with the associated issue https://github.com/Koenkk/zigbee2mqtt/issues/19125 - with the short 10s timeout, logging becomes an issue with a large number of entities for HA.
As a side note, if I turn UP logging to debug (from warn where I keep it because of https://github.com/Koenkk/zigbee2mqtt/issues/19125), then the interview has a much higher chance of success. Which would then indicate it's not necessarily the timeout that causes the crash (because logging would cause it to take more time, not less).
Also, my USB stick is connected to a desktop computer, NOT a raspberry pi. And I have the antenna on an extension of about 6ft. So USB extension should not need to be a thing (as it would be with the RPI).
I'm experiencing what seems to be the same issue with Philips Hue bulbs and a wired Ethernet ezsp coordinator (tubeszb-efr32-MGM210-eth_usb) where the interview more often than not will cause a crash but will eventually succeed after a few attempts. The crash does not appear to occur at all when zigbee-herdsman debug logs are enabled. I also appear to have much newer coordinator firmware than some of the other reporters in this and the previous issue.
Zigbee2MQTT version 1.33.0 commit: 7ee207f
Coordinator type EZSP v12
Coordinator revision 7.3.1.0 build 176
Here is a log snippet without debug:
Oct 02 18:49:26 zigbee2mqtt[3967812]: Zigbee2MQTT:error 2023-10-02 18:49:26: Failed to interview '0x0017880104d097ba', device has not successfully been paired
Oct 02 18:49:26 zigbee2mqtt[3967812]: Zigbee2MQTT:info 2023-10-02 18:49:26: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x0017880104d097ba","ieee_address":"0x0017880104d097ba","status":"failed"},"type":"device_interview"}'
Oct 02 18:49:29 zigbee2mqtt[3967812]: Assertion failed: Command (setConfigurationValue) returned unexpected state: [object Object]
Oct 02 18:49:31 zigbee2mqtt[3967812]: Zigbee2MQTT:debug 2023-10-02 18:49:31: Received Zigbee message from 'Bedroom Light Switch', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"fileVersion":1107324829,"imageType":265,"manufacturerCode":4107}' from endpoint 2 with groupID 0
Oct 02 18:49:31 zigbee2mqtt[3967812]: Zigbee2MQTT:debug 2023-10-02 18:49:31: Device 'Bedroom Light Switch' requested OTA
Oct 02 18:49:39 zigbee2mqtt[3967812]: Assertion failed: Command (setConfigurationValue) returned unexpected state: [object Object]
Oct 02 18:49:41 zigbee2mqtt[3967812]: Zigbee2MQTT:debug 2023-10-02 18:49:41: Received Zigbee message from 'Bedroom Light Switch', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"fileVersion":1107324829,"imageType":265,"manufacturerCode":4107}' from endpoint 2 with groupID 0
Oct 02 18:49:41 zigbee2mqtt[3967812]: Zigbee2MQTT:debug 2023-10-02 18:49:41: Device 'Bedroom Light Switch' requested OTA
Oct 02 18:49:59 zigbee2mqtt[3967812]: Assertion failed: Command (setConfigurationValue) returned unexpected state: [object Object]
Oct 02 18:50:12 zigbee2mqtt[3967812]: Zigbee2MQTT:warn 2023-10-02 18:50:12: Failed to ping 'Bedroom Light' (attempt 1/2, Read 0x0017880104d09935/11 genBasic(["zclVersion"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (sendZclFrameToEndpointInternal error))
Oct 02 18:50:12 zigbee2mqtt[3967812]: Assertion failed: Command (setConfigurationValue) returned unexpected state: [object Object]
Oct 02 18:50:15 zigbee2mqtt[3967812]: Zigbee2MQTT:info 2023-10-02 18:50:15: Starting interview of '0x0017880104d097ba'
Oct 02 18:50:15 zigbee2mqtt[3967812]: Zigbee2MQTT:info 2023-10-02 18:50:15: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x0017880104d097ba","ieee_address":"0x0017880104d097ba","status":"started"},"type":"device_interview"}'
Oct 02 18:50:22 zigbee2mqtt[3967812]: Assertion failed: Command (setConfigurationValue) returned unexpected state: [object Object]
Oct 02 18:50:25 zigbee2mqtt[3967812]: Error: {"address":45493,"clusterId":32773,"sequence":4} after 10000ms
Oct 02 18:50:25 zigbee2mqtt[3967812]: at Timeout._onTimeout (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:64:35)
Oct 02 18:50:25 zigbee2mqtt[3967812]: at listOnTimeout (node:internal/timers:569:17)
Oct 02 18:50:25 zigbee2mqtt[3967812]: at processTimers (node:internal/timers:512:7)
I'm experiencing the same crash very reproducible on every new device. Currently I'm creating a new setup with only Philips hue components. The crashing startet after about 50 devices (mainly routers (light bulbs)) irregularly. After 60 devices, crash is stable after join and starting the interview. The Interview is then completed after restart of Z2M. I've attached the complete log with herdsman debug.
Zigbee2MQTT-Version 1.33.0-dev commit: [1190a342]
Coordinator-Typ EZSP v8
Coordinator-Version 6.10.3.0 build 297
zigbee2mqtt-log-interview-crash.txt
@c5n good log, thanks. I see that the connection is breaking, but I don’t understand the reasons yet. I will sort this out
I initially had this exact same issue (with the same logs) with a Raspberry Pi 2b.
MQTT installed as a Raspbian package, Z2M (v1.33.0) installed as a docker container. Sonoff Dongle-E (EZSP v8 6.10.3.0 build 297).
I could add one device (almost) without trouble but as soon as I added a second and third one, I would encounter the "Error: Failure send findKeyTableEntry" and the container would crash and reboot during the interview of the device. After a lot of tries, all 3 devices were finally paired successfully.
Until I found that my CPU was peaking at 100% during the interview process.
Booted up a VM with Debian and the same setup (MQTT as a debian package, Z2M as a docker container), presented Sonoff Dongle-E to VM and tested : I added 5 devices without any issue (and the devices interview was almost instant vs ~1 full minute on the Pi). I did not push the test more than that as the VM was only a temporary test, but the problem might be tied to CPU performance / load.
Hope this can help investigate the issue.
I have a funny observation from today: It may be completely irrelevant but perhaps someone else with the issue can try. As 3 of my sensors suddenly stopped working I tried re-pairing them today. I used the permit join button on the web interface and I received a crash immediately after pairing the first one. Then I changed permit_join to true in my configuration.yaml and after that I was able to pair all three sensors on the first try... Is it a coincidence?
It was a coincidence.... I am trying to pair the fourth sensor now... z2m has crashed 7 times in a row now :(
Any updates or other new thoughts on this matter? Currently I rarely manage to add any device without hassle. 9 of 10 pairing attempts will crash the addon. And after a crash there are always some devices that looses connection. This has been the case for quite some time now and I consider moving my whole zigbee network to another platform.
same here About to move my Zigbee network from Home Assistant Yellow (internal) to an external device (Raspberry Zero 2 W) with Sonoff ZB Dongle E. I was hoping for better connection (I can put the device more central in the house). Connection works much better, but after around 15 devices I get the same crash and error when I try to pair.
Same here. Sonoff ZBDongle-E and ~20 devices, mostly TRVs, some sensors, a couple of switches that (should) also act as routers. Z2M running in HA on Proxmox. Everything went well so far and has been running happily for a couple of weeks. Now when trying to pair a new device, Z2M crashes while interviewing. Absolutely nothing changed in the setup.
Here's the log output:
Error: Failure send findKeyTableEntry:{"type":"Buffer","data":[80,0,1,117,0,167,243,212,254,255,20,67,12,1]} at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:562:23 at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)
Here's the output of Settings --> About:
Zigbee2MQTT version 1.33.2
Coordinator type EZSP v8
Coordinator revision 6.10.3.0 build 297
Coordinator IEEE Address 0xdc8e95fffe257cdb
Frontend version 0.6.142
Zigbee-herdsman-converters version 15.106.0
Zigbee-herdsman version 0.21.0
I have the same problem:
Error: Failure send findKeyTableEntry:{"type":"Buffer","data":[10,0,1,117,0,179,220,255,8,0,141,21,0,1]} at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:562:23 at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)
Z2M version: 1.33.2-1 Using Sonoff USB stick : /dev/serial/by-id/usb-ITEAD_SONOFF_Zigbee_3.0_USB_Dongle_Plus_V2_20220816090806-if00
Was working OK for the past months...
Version de Zigbee2MQTT [1.33.2] commit: [unknown] Type de coordinateur EZSP v8 Révision du coordinateur 6.10.3.0 build 297 Adresse IEEE du Coordinateur 0xe0798dfffe77be02 Version de l'interface 0.6.142 Zigbee-herdsman-converters version 15.106.0 Zigbee-herdsman version 0.21.0
Welcome to the club. I am slowly loosing hope that this will be resolved eventually. I have three dongles in 3 different locations but the same issue. Can anyone suggest a good dongle alternative that can make this issue go away?
Exchanged my Sonoff ZB Dongle from Model E back to a model P yesterday. Was able to pair more than 30 devices without a problem. Think it is a problem with the „E“ Hatdware.