Sporadic UnhandledPromiseRejection

[assensus]

What happened?

The add-on sporadically crashes after receiving an UnhandledPromiseRejection. Unfortunately, the problem cannot be reproduced systematically, but it occurs again and again.

What did you expect to happen?

The add-on should work reliably.
A guide that helps me to provide further information to solve the problem.

How to reproduce it (minimal and precise)

Unfortunately, the problem cannot be reproduced systematically.

Zigbee2MQTT version

1.36.0

Adapter firmware version

0x26520700

Adapter

RaspBee2

Setup

Add-On on Home Assistant OS on Raspberry PI4

Debug log

UnhandledPromiseRejection: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason "TIMEOUT".

[Koenkk]

To debug this I need the herdsman debug logging of the crash.

See this on how to enable the herdsman debug logging. Note that this is only logged to STDOUT and not to log files.

[assensus]

Sorry for the late reply.
The problem has now reappeared. Unfortunately, that's all the log output contained. Let me know if you want me to provide more information.
Thanks, Reiner

2024-03-08T11:53:23.768Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10101010
2024-03-08T11:53:23.768Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 1 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:23.772Z zigbee-herdsman:deconz:driver query aps data indication
2024-03-08T11:53:23.777Z zigbee-herdsman:deconz:driver DATA_INDICATION - sending read data request - SeqNr. 116
2024-03-08T11:53:23.796Z zigbee-herdsman:deconz:frameParser DATA_INDICATION RESPONSE - seqNr. 116 srcAddr: 0x484b destAddr: 0x0 profile id: 0x104 cluster id: 0xb04 lqi: 159
2024-03-08T11:53:23.797Z zigbee-herdsman:deconz:frameParser response payload: 8,62,10,5,5,33,235,0,8,5,33,0,0,11,5,41,0,0
2024-03-08T11:53:23.807Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":62,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":1285,"dataType":33,"attrData":235},{"attrId":1288,"dataType":33,"attrData":0},{"attrId":1291,"dataType":41,"attrData":0}],"Command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}},"address":18507,"endpoint":1,"linkquality":159,"groupID":null,"wasBroadcast":false,"destinationEndpoint":1}'
2024-03-08T11:53:23.812Z zigbee-herdsman:controller:endpoint DefaultResponse 0xa4c138a1fbb0ff2a/1 2820(10, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false})
2024-03-08T11:53:23.813Z zigbee-herdsman:deconz:adapter no response expected (62)
2024-03-08T11:53:23.813Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
Zigbee2MQTT:info 2024-03-08 12:53:23: MQTT publish: topic 'zigbee2mqtt/Waschmaschine', payload '{"child_lock":"LOCK","current":0,"energy":44.22,"indicator_mode":"off","linkquality":159,"power":0,"power_outage_memory":"on","state":"ON","update":{"installed_version":-1,"latest_version":-1,"state":null},"update_available":null,"voltage":235}'
2024-03-08T11:53:23.830Z zigbee-herdsman:deconz:driver DATA_REQUEST - destAddr: 0x484b EP:1 SeqNr. 117 request id: 107
2024-03-08T11:53:23.854Z zigbee-herdsman:deconz:frameParser DATA_REQUEST RESPONSE - request id: 107 status: 0
2024-03-08T11:53:23.854Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:23.856Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10100110
2024-03-08T11:53:23.856Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 1 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:23.856Z zigbee-herdsman:deconz:driver query aps data confirm
2024-03-08T11:53:23.862Z zigbee-herdsman:deconz:driver DATA_CONFIRM - sending data state request - SeqNr. 118
2024-03-08T11:53:23.872Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10100110
2024-03-08T11:53:23.872Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 1 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:23.877Z zigbee-herdsman:deconz:driver query aps data confirm
2024-03-08T11:53:23.882Z zigbee-herdsman:deconz:driver DATA_CONFIRM - sending data state request - SeqNr. 119
2024-03-08T11:53:23.884Z zigbee-herdsman:deconz:frameParser DATA_CONFIRM RESPONSE - destAddr: 0x484b request id: 107 confirm status: 0
2024-03-08T11:53:23.884Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 1 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:23.884Z zigbee-herdsman:deconz:adapter sendZclFrameToEndpoint - message send with transSeq Nr.: 62
2024-03-08T11:53:23.884Z zigbee-herdsman:deconz:adapter false, true, false, 10000
2024-03-08T11:53:23.884Z zigbee-herdsman:deconz:adapter resolve request (62)
2024-03-08T11:53:23.885Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10101110
2024-03-08T11:53:23.886Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 1 apsDataIndication: 1 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:23.888Z zigbee-herdsman:deconz:driver query aps data confirm
2024-03-08T11:53:23.892Z zigbee-herdsman:deconz:driver DATA_CONFIRM - sending data state request - SeqNr. 120
2024-03-08T11:53:23.893Z zigbee-herdsman:deconz:driver query aps data indication
2024-03-08T11:53:23.894Z zigbee-herdsman:deconz:frameParser DATA_CONFIRM RESPONSE - destAddr: 0xfffc request id: 106 confirm status: 0
2024-03-08T11:53:23.894Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 1 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:23.894Z zigbee-herdsman:deconz:adapter PERMIT_JOIN - 254 seconds
2024-03-08T11:53:23.895Z zigbee-herdsman:deconz:adapter zclFrame to all - zclFrame.payload:
2024-03-08T11:53:23.896Z zigbee-herdsman:deconz:adapter { options: 11, commisioningWindow: 254 }
2024-03-08T11:53:23.896Z zigbee-herdsman:deconz:adapter sendZclFrameToAll - message send
2024-03-08T11:53:23.896Z zigbee-herdsman:deconz:driver query aps data indication
2024-03-08T11:53:23.897Z zigbee-herdsman:deconz:driver DATA_INDICATION - sending read data request - SeqNr. 121
2024-03-08T11:53:23.898Z zigbee-herdsman:deconz:driver send write parameter request from queue. seqNr: 122 paramId: 33 param: 254
2024-03-08T11:53:23.899Z zigbee-herdsman:deconz:driver DATA_REQUEST - destAddr: 0xfffd EP:242 SeqNr. 123 request id: 108
2024-03-08T11:53:23.902Z zigbee-herdsman:deconz:driver DATA_INDICATION - sending read data request - SeqNr. 124
2024-03-08T11:53:23.914Z zigbee-herdsman:deconz:frameParser DATA_INDICATION RESPONSE - seqNr. 121 srcAddr: 0x484b destAddr: 0x0 profile id: 0x104 cluster id: 0x702 lqi: 159
2024-03-08T11:53:23.914Z zigbee-herdsman:deconz:frameParser response payload: 8,63,10,0,0,37,70,17,0,0,0,0
2024-03-08T11:53:23.926Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":63,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":0,"dataType":37,"attrData":[0,4422]}],"Command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}},"address":18507,"endpoint":1,"linkquality":159,"groupID":null,"wasBroadcast":false,"destinationEndpoint":1}'
2024-03-08T11:53:23.933Z zigbee-herdsman:controller:endpoint DefaultResponse 0xa4c138a1fbb0ff2a/1 1794(10, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false})
2024-03-08T11:53:23.934Z zigbee-herdsman:deconz:adapter no response expected (63)
2024-03-08T11:53:23.934Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
Zigbee2MQTT:info 2024-03-08 12:53:23: MQTT publish: topic 'zigbee2mqtt/Waschmaschine', payload '{"child_lock":"LOCK","current":0,"energy":44.22,"indicator_mode":"off","linkquality":159,"power":0,"power_outage_memory":"on","state":"ON","update":{"installed_version":-1,"latest_version":-1,"state":null},"update_available":null,"voltage":235}'
2024-03-08T11:53:23.946Z zigbee-herdsman:deconz:driver DATA_REQUEST - destAddr: 0x484b EP:1 SeqNr. 125 request id: 109
2024-03-08T11:53:23.947Z zigbee-herdsman:deconz:frameParser DATA_REQUEST RESPONSE - request id: 108 status: 0
2024-03-08T11:53:23.947Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:23.969Z zigbee-herdsman:deconz:frameParser DATA_REQUEST RESPONSE - request id: 109 status: 0
2024-03-08T11:53:23.969Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:23.970Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10100110
2024-03-08T11:53:23.971Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 1 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:23.972Z zigbee-herdsman:deconz:driver query aps data confirm
2024-03-08T11:53:23.977Z zigbee-herdsman:deconz:driver DATA_CONFIRM - sending data state request - SeqNr. 126
2024-03-08T11:53:23.988Z zigbee-herdsman:deconz:frameParser DATA_CONFIRM RESPONSE - destAddr: 0x484b request id: 109 confirm status: 0
2024-03-08T11:53:23.988Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:23.988Z zigbee-herdsman:deconz:adapter sendZclFrameToEndpoint - message send with transSeq Nr.: 63
2024-03-08T11:53:23.988Z zigbee-herdsman:deconz:adapter false, true, false, 10000
2024-03-08T11:53:23.988Z zigbee-herdsman:deconz:adapter resolve request (63)
2024-03-08T11:53:24.450Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10100110
2024-03-08T11:53:24.450Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 1 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:24.453Z zigbee-herdsman:deconz:driver query aps data confirm
2024-03-08T11:53:24.458Z zigbee-herdsman:deconz:driver DATA_CONFIRM - sending data state request - SeqNr. 127
2024-03-08T11:53:24.469Z zigbee-herdsman:deconz:frameParser DATA_CONFIRM RESPONSE - destAddr: 0xfffd request id: 108 confirm status: 0
2024-03-08T11:53:24.469Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:27.524Z zigbee-herdsman:controller:endpoint Read 0xa4c138a1fbb0ff2a/1 seMetering(["currentSummDelivered"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false})
2024-03-08T11:53:27.525Z zigbee-herdsman:deconz:driver DATA_REQUEST - destAddr: 0x484b EP:1 SeqNr. 128 request id: 110
2024-03-08T11:53:27.545Z zigbee-herdsman:deconz:frameParser DATA_REQUEST RESPONSE - request id: 110 status: 0
2024-03-08T11:53:27.546Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:27.547Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10100110
2024-03-08T11:53:27.547Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 1 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:27.550Z zigbee-herdsman:deconz:driver query aps data confirm
2024-03-08T11:53:27.555Z zigbee-herdsman:deconz:driver DATA_CONFIRM - sending data state request - SeqNr. 129
2024-03-08T11:53:27.570Z zigbee-herdsman:deconz:frameParser DEVICE_STATE changed: 10101110
2024-03-08T11:53:27.571Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 1 apsDataIndication: 1 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:27.571Z zigbee-herdsman:deconz:driver query aps data confirm
2024-03-08T11:53:27.576Z zigbee-herdsman:deconz:driver DATA_CONFIRM - sending data state request - SeqNr. 130
2024-03-08T11:53:27.576Z zigbee-herdsman:deconz:driver query aps data indication
2024-03-08T11:53:27.577Z zigbee-herdsman:deconz:frameParser DATA_CONFIRM RESPONSE - destAddr: 0x484b request id: 110 confirm status: 0
2024-03-08T11:53:27.577Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 1 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:27.577Z zigbee-herdsman:deconz:adapter sendZclFrameToEndpoint - message send with transSeq Nr.: 115
2024-03-08T11:53:27.577Z zigbee-herdsman:deconz:adapter true, true, false, 10000
2024-03-08T11:53:27.577Z zigbee-herdsman:deconz:adapter resolve request (115)
2024-03-08T11:53:27.578Z zigbee-herdsman:deconz:driver query aps data indication
2024-03-08T11:53:27.581Z zigbee-herdsman:deconz:driver DATA_INDICATION - sending read data request - SeqNr. 131
2024-03-08T11:53:27.586Z zigbee-herdsman:deconz:driver DATA_INDICATION - sending read data request - SeqNr. 132
2024-03-08T11:53:27.598Z zigbee-herdsman:deconz:frameParser DATA_INDICATION RESPONSE - seqNr. 131 srcAddr: 0x484b destAddr: 0x0 profile id: 0x104 cluster id: 0x702 lqi: 159
2024-03-08T11:53:27.598Z zigbee-herdsman:deconz:frameParser response payload: 24,115,1,0,0,0,37,70,17,0,0,0,0
2024-03-08T11:53:27.602Z zigbee-herdsman:deconz:adapter resolve data request with transSeq Nr.: 115
2024-03-08T11:53:27.608Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":115,"manufacturerCode":null,"commandIdentifier":1},"Payload":[{"attrId":0,"status":0,"dataType":37,"attrData":[0,4422]}],"Command":{"ID":1,"name":"readRsp","parameters":[{"name":"attrId","type":33},{"name":"status","type":32},{"name":"dataType","type":32,"conditions":[{"type":"statusEquals","value":0}]},{"name":"attrData","type":1000,"conditions":[{"type":"statusEquals","value":0}]}]}},"address":18507,"endpoint":1,"linkquality":159,"groupID":null,"wasBroadcast":false,"destinationEndpoint":1}'
2024-03-08T11:53:27.612Z zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 0 configChanged: 0 apsRequestFreeSlots: 1
2024-03-08T11:53:27.616Z zigbee-herdsman:deconz:adapter response received (115)
Zigbee2MQTT:info 2024-03-08 12:53:27: MQTT publish: topic 'zigbee2mqtt/Waschmaschine', payload '{"child_lock":"LOCK","current":0,"energy":44.22,"indicator_mode":"off","linkquality":159,"power":0,"power_outage_memory":"on","state":"ON","update":{"installed_version":-1,"latest_version":-1,"state":null},"update_available":null,"voltage":235}'
2024-03-08T11:53:33.903Z zigbee-herdsman:deconz:driver Timeout for request - CMD: 0xb seqNr: 122
UnhandledPromiseRejection: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason "TIMEOUT".

[Koenkk]

Do you have permit_join: true in your configuration.yaml? Or did you permit joining around the time of the crash? if yes, can you try removing it?

Note to self; add await here

[assensus]

There are two instances of "permit_join" in configuration.yaml, all of which are now set to "false". Previously both had value "true".

A small hint: I suspect that Silvercrest (Lidl) plugs are causing the crash. Because I believe that the error only occurs since I have used three of them. If the problem occurs again, I will remove it to verify my suspicion.

[assensus]

After setting the permit_join option to false, the problem no longer occurred. So, the ticket can be closed..
Many thanks for your support.

[Koenkk]

Great, also pushed a fix!

Changes will be available in the dev branch in a few hours from now.