ioBroker / ioBroker.zigbee

Zigbee communcation with Hue, Xiaomi, Lighttify... via TI CC2xxx USB stick
MIT License
315 stars 190 forks source link

OTA update Firmware check crashes Zigbee-Adapter if one Zigbee device is lost/undefined & Solution #653

Closed bl4ckwhiteeagle closed 2 years ago

bl4ckwhiteeagle commented 4 years ago

Here i'm again, sorry for my long absense, i was very very busy at work and in my real life... Many thanks to all of you, who made iobroker and zigbee as it is now, especially to you Koen! Zigbee is now very stable with all of my devices!!!

Stay healty! Mathias


Issue/Solution:

Symptom: Scanning Devices OTA/FW-Update crash Zigbee Adapter if a Zigbee-Device is lost/undefined not in the List shepherd.db but listet in instance/objects List

Solution: (Force) Delete the lost device and reconnect it, OTA scanning works then again, I've updated 2 Osram Plugs with success Undefined devices shouldn't get scanned.. Maybe undefined/Lost devices could draw a red background instead of white, if the Signal indicator tells 0 or n/a

HW: CC2531 v20190315 Coordinator 1.2 41 Zigbee Devices 12 Lamps (4 Mueller Licht & 8 IKEA Tradfri) / 5 OSRAM Plugs / 6 Xiaomi Temperature Sensors / 2 Xiaomi Motion Sensors / 6 Xiaomi Magnet Sensors

Version: Latest iobroker/zigbee 1.1.1 etc.

Log: Terminated (NO_ERROR): Without reasonzigbee.0 terminatingzigbee Got OTA request {"fieldControl":0,"manufacturerCode":4364,"imageType":39,"fileVersion":16909330}'

Silly Debug: zigbee.0 2020-06-06 15:50:46.878 error (12628) TypeError: Cannot read property 'resolveEntity' of undefined at Ota.getDeviceForMessage (/opt/iobroker/node_modules/iobroker.zigbee/lib/ota.js:136:34) at Ota.checkOtaAvail (/opt/iobrok zigbee.0 2020-06-06 15:50:46.876 error (12628) unhandled promise rejection: Cannot read property 'resolveEntity' of undefined zigbee.0 2020-06-06 15:50:46.862 error Unhandled promise rejection. 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(). zigbee.0 2020-06-06 15:50:46.858 silly (12628) States system redis pmessage io.messagebox.system.adapter.zigbee.0/io.messagebox.system.adapter.zigbee.0:{"command":"checkOtaAvail","message":{"devId":"zigbee.0.12345..."},"from":"syst

stale[bot] commented 4 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

JimmyBondi commented 4 years ago

Same here. When a device is offline, OTA check crashes and then the adapter restarts.

kirovilya commented 4 years ago

try to install from github and check

JimmyBondi commented 4 years ago

I've installed the Github Version yesterday, but the adapter still crashes during OTA Check

`

host.iobroker 2020-08-10 11:37:13.470 info Restart adapter system.adapter.zigbee.0 because enabled
host.iobroker 2020-08-10 11:37:13.461 info instance system.adapter.zigbee.0 terminated with code 0 (NO_ERROR)
zigbee.0 2020-08-10 11:37:12.904 info (15551) Terminated (NO_ERROR): Without reason
zigbee.0 2020-08-10 11:37:12.900 info (15551) terminating

`

before the adapter restarts, I got some errors like this:

`

zigbee.0 2020-08-10 11:45:23.652 error at processTimers (internal/timers.js:492:7)
zigbee.0 2020-08-10 11:45:23.652 error at listOnTimeout (internal/timers.js:549:17)
zigbee.0 2020-08-10 11:45:23.652 error at Timeout._onTimeout (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35)
zigbee.0 2020-08-10 11:45:23.652 error (12811) Error: Timeout - 54317 - 1 - null - 25 - 1 after 30000ms
zigbee.0 2020-08-10 11:45:23.651 error (12811) unhandled promise rejection: Timeout - 54317 - 1 - null - 25 - 1 after 30000ms
Unhandled 2020-08-10 11:45:23.650 error promise rejection. 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().

 

`

kirovilya commented 4 years ago

run adapter in debug mode and show logs. I don't understand why this is happening

JimmyBondi commented 4 years ago

This is what I got:

debuglog.txt

kirovilya commented 4 years ago

I can not reproduce your error... get only correct handle exceptions image image

killakaktus commented 4 years ago

I've installed the Github Version yesterday, but the adapter still crashes during OTA Check

` host.iobroker 2020-08-10 11:37:13.470 info Restart adapter system.adapter.zigbee.0 because enabled host.iobroker 2020-08-10 11:37:13.461 info instance system.adapter.zigbee.0 terminated with code 0 (NO_ERROR) zigbee.0 2020-08-10 11:37:12.904 info (15551) Terminated (NO_ERROR): Without reason zigbee.0 2020-08-10 11:37:12.900 info (15551) terminating

`

before the adapter restarts, I got some errors like this:

` zigbee.0 2020-08-10 11:45:23.652 error at processTimers (internal/timers.js:492:7) zigbee.0 2020-08-10 11:45:23.652 error at listOnTimeout (internal/timers.js:549:17) zigbee.0 2020-08-10 11:45:23.652 error at Timeout._onTimeout (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35) zigbee.0 2020-08-10 11:45:23.652 error (12811) Error: Timeout - 54317 - 1 - null - 25 - 1 after 30000ms zigbee.0 2020-08-10 11:45:23.651 error (12811) unhandled promise rejection: Timeout - 54317 - 1 - null - 25 - 1 after 30000ms Unhandled 2020-08-10 11:45:23.650 error promise rejection. 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().

`

Any news to this? Have the same problem.

crckmc commented 4 years ago

The crash happens for me when I have a Hue dimmer (RWL-021) connected. After deleting all dimmers the update check works without crashing.


zigbee.0 | 2020-11-07 22:16:04.104 | info | (6770) Terminated (NO_ERROR): Without reason
zigbee.0 | 2020-11-07 22:16:04.102 | info | (6770) terminating
zigbee.0 | 2020-11-07 22:16:04.047 | error | (6770) Error: Timeout - 10969 - 2 - null - 25 - 1 after 30000ms at Timeout._onTimeout (/opt/iobroker/node_modules/iobroker.zigbee/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35) at
zigbee.0 | 2020-11-07 22:16:04.046 | error | (6770) unhandled promise rejection: Timeout - 10969 - 2 - null - 25 - 1 after 30000ms
zigbee.0 | 2020-11-07 22:16:04.045 | error | Unhandled promise rejection. 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().
zigbee.0 | 2020-11-07 22:16:04.044 | error | (6770) Error: Timeout - 42743 - 2 - null - 25 - 1 after 30000ms at Timeout._onTimeout (/opt/iobroker/node_modules/iobroker.zigbee/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35) at
zigbee.0 | 2020-11-07 22:16:04.038 | error | (6770) unhandled promise rejection: Timeout - 42743 - 2 - null - 25 - 1 after 30000ms
zigbee.0 | 2020-11-07 22:16:04.036 | error | Unhandled promise rejection. 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().
zigbee.0 | 2020-11-07 22:16:03.126 | info | (6770) Zigbee: disabling joining new devices.
zigbee.0 | 2020-11-07 22:16:03.119 | info | (6770) cleaned everything up...
zigbee.0 | 2020-11-07 22:16:03.116 | error | (6770) Error: Timeout - 41074 - 2 - null - 25 - 1 after 30000ms at Timeout._onTimeout (/opt/iobroker/node_modules/iobroker.zigbee/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35) at
zigbee.0 | 2020-11-07 22:16:03.113 | error | (6770) unhandled promise rejection: Timeout - 41074 - 2 - null - 25 - 1 after 30000ms
zigbee.0 | 2020-11-07 22:16:03.111 | error | Unhandled promise rejection. 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().
zigbee.0 | 2020-11-07 22:16:03.053 | error | (6770) Failed to check if update available for '0x0017880102f9e56a' (Device didn't respond to OTA request)

`
JimmyBondi commented 3 years ago

In the meantime, I changed the coordinator from CC2531 to CC2538, so I had to pair all devices again. Now I've no more OTA crashes.

sky-it commented 3 years ago

Node.js: v14.15.4 NPM: 6.14.10 js-controller: 3.2.13 Adapter: 1.4.2

Ikea GU10 LED1737R5, LED1739R5

Update available. After clicking update, the update is shown as finished. The adapter then crashes and restarts.

update update_click

2021-02-02 10:08:50.109 - debug: zigbee.0 (5188) sendTo "checkOtaAvail" to system.adapter.admin.0 from system.adapter.zigbee.0
2021-02-02 10:08:50.151 - debug: zigbee.0 (5188) getNewImage for '0xd0cf5efffed951ae', meta {"fileVersion":537040419,"url":"http://fw.ota.homesmart.ikea.net/global/GW1.0/01.13.019/bin/10038562-2.1-TRADFRI-sy5882-bulb-ws-2.0.029.ota.ota.signed"}
2021-02-02 10:08:50.298 - debug: zigbee.0 (5188) getNewImage for '0xd0cf5efffed951ae', image header {"otaUpgradeFileIdentifier":{"type":"Buffer","data":[30,241,238,11]},"otaHeaderVersion":256,"otaHeaderLength":56,"otaHeaderFieldControl":0,"manufacturerCode":4476,"imageType":16900,"fileVersion":537040419,"zigbeeStackVersion":2,"otaHeaderString":"GBL GBL_tradfri_sy5882_bulb_ws\u0000\u0000","totalImageSize":208242}
2021-02-02 10:08:50.298 - error: zigbee.0 (5188) Update of '0xd0cf5efffed951ae' failed (Image is truncated: not long enough to contain a valid tag)
2021-02-02 10:08:50.299 - debug: zigbee.0 (5188) sendTo "startOta" to system.adapter.admin.0 from system.adapter.zigbee.0
2021-02-02 10:08:52.666 - debug: zigbee.0 (5188) handleMessage. {"type":"commandQueryNextImageRequest","device":{"ID":20,"_type":"Router","_ieeeAddr":"0xd0cf5efffed951ae","_networkAddress":57088,"_manufacturerID":4476,"_endpoints":[{"ID":1,"profileID":260,"deviceID":268,"inputClusters":[0,3,4,5,6,8,768,4096,64636],"outputClusters":[5,25,32,4096],"deviceNetworkAddress":57088,"deviceIeeeAddress":"0xd0cf5efffed951ae","clusters":{"genBasic":{"attributes":{"modelId":"TRADFRI bulb GU10 WS 400lm","manufacturerName":"IKEA of Sweden","powerSource":1,"zclVersion":2,"appVersion":32,"stackVersion":98,"hwVersion":1,"dateCode":"20190308","swBuildId":"2.0.022"}},"genOnOff":{"attributes":{"onOff":0}}},"_binds":[],"_configuredReportings":[],"meta":{}},{"ID":242,"profileID":41440,"deviceID":97,"inputClusters":[33],"outputClusters":[33],"deviceNetworkAddress":57088,"deviceIeeeAddress":"0xd0cf5efffed951ae","clusters":{},"_binds":[],"_configuredReportings":[],"meta":{}}],"_manufacturerName":"IKEA of Sweden","_powerSource":"Mains (single phase)","_modelID":"TRADFRI bulb GU10 WS 400lm","_applicationVersion":32,"_stackVersion":98,"_zclVersion":2,"_hardwareVersion":1,"_dateCode":"20190308","_softwareBuildID":"2.0.022","_interviewCompleted":true,"_interviewing":false,"meta":{},"_lastSeen":1612256932666,"_linkquality":15},"endpoint":"[Circular]","data":{"fieldControl":1,"manufacturerCode":4476,"imageType":16900,"fileVersion":537011747},"linkquality":15,"groupID":0,"cluster":"genOta","meta":{"zclTransactionSequenceNumber":78,"manufacturerCode":null,"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":false,"reservedBits":0}}}
2021-02-02 10:08:52.666 - debug: zigbee.0 (5188) Received Zigbee message from '0xd0cf5efffed951ae', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"manufacturerCode":4476,"imageType":16900,"fileVersion":537011747}' from endpoint 1 with groupID 0
2021-02-02 10:08:52.667 - debug: zigbee.0 (5188) Type commandQueryNextImageRequest device {"type":"device","device":{"ID":20,"_type":"Router","_ieeeAddr":"0xd0cf5efffed951ae","_networkAddress":57088,"_manufacturerID":4476,"_endpoints":[{"ID":1,"profileID":260,"deviceID":268,"inputClusters":[0,3,4,5,6,8,768,4096,64636],"outputClusters":[5,25,32,4096],"deviceNetworkAddress":57088,"deviceIeeeAddress":"0xd0cf5efffed951ae","clusters":{"genBasic":{"attributes":{"modelId":"TRADFRI bulb GU10 WS 400lm","manufacturerName":"IKEA of Sweden","powerSource":1,"zclVersion":2,"appVersion":32,"stackVersion":98,"hwVersion":1,"dateCode":"20190308","swBuildId":"2.0.022"}},"genOnOff":{"attributes":{"onOff":0}}},"_binds":[],"_configuredReportings":[],"meta":{}},{"ID":242,"profileID":41440,"deviceID":97,"inputClusters":[33],"outputClusters":[33],"deviceNetworkAddress":57088,"deviceIeeeAddress":"0xd0cf5efffed951ae","clusters":{},"_binds":[],"_configuredReportings":[],"meta":{}}],"_manufacturerName":"IKEA of Sweden","_powerSource":"Mains (single phase)","_modelID":"TRADFRI bulb GU10 WS 400lm","_applicationVersion":32,"_stackVersion":98,"_zclVersion":2,"_hardwareVersion":1,"_dateCode":"20190308","_softwareBuildID":"2.0.022","_interviewCompleted":true,"_interviewing":false,"meta":{},"_lastSeen":1612256932666,"_linkquality":15},"mapped":{"exposes":[{"type":"light","features":[{"type":"binary","name":"state","property":"state","access":7,"value_on":"ON","value_off":"OFF","value_toggle":"TOGGLE","description":"On/off state of this light"},{"type":"numeric","name":"brightness","property":"brightness","access":7,"value_min":0,"value_max":254,"description":"Brightness of this light"},{"type":"numeric","name":"color_temp","property":"color_temp","access":7,"unit":"mired","value_min":150,"value_max":500,"description":"Color temperature of this light"}]},{"type":"enum","name":"effect","property":"effect","access":2,"values":["blink","breathe","okay","channel_change","finish_effect","stop_effect"],"description":"Triggers an effect on the light (e.g. make light blink for a few seconds)"},{"type":"numeric","name":"linkquality","property":"linkquality","access":1,"unit":"lqi","description":"Link quality (signal strength)","value_min":0,"value_max":255}],"fromZigbee":[{"cluster":"lightingColorCtrl","type":["attributeReport","readResponse"]},{"cluster":"genOnOff","type":["attributeReport","readResponse"]},{"cluster":"genLevelCtrl","type":["attributeReport","readResponse"]},{"cluster":"genBasic","type":["attributeReport","readResponse"]}],"toZigbee":[{"key":["state","brightness","brightness_percent"]},{"key":["color_temp","color_temp_percent"]},{"key":["transition"],"attr":[]},{"key":["rate"],"attr":[]},{"key":["effect","alert","flash"]},{"key":["brightness_move","brightness_move_onoff"]},{"key":["colortemp_move","color_temp_move"]},{"key":["brightness_step","brightness_step_onoff"]},{"key":["color_temp_step"]},{"key":["scene_store"]},{"key":["scene_recall"]},{"key":["scene_add"]},{"key":["scene_remove"]},"[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]"],"zigbeeModel":["TRADFRI bulb GU10 WS 400lm"],"model":"LED1537R6/LED1739R5","vendor":"IKEA","description":"TRADFRI LED bulb GU10 400 lumen, dimmable, white spectrum","ota":{}},"name":"0xd0cf5efffed951ae"} incoming event: {"type":"commandQueryNextImageRequest","device":{"ID":20,"_type":"Router","_ieeeAddr":"0xd0cf5efffed951ae","_networkAddress":57088,"_manufacturerID":4476,"_endpoints":[{"ID":1,"profileID":260,"deviceID":268,"inputClusters":[0,3,4,5,6,8,768,4096,64636],"outputClusters":[5,25,32,4096],"deviceNetworkAddress":57088,"deviceIeeeAddress":"0xd0cf5efffed951ae","clusters":{"genBasic":{"attributes":{"modelId":"TRADFRI bulb GU10 WS 400lm","manufacturerName":"IKEA of Sweden","powerSource":1,"zclVersion":2,"appVersion":32,"stackVersion":98,"hwVersion":1,"dateCode":"20190308","swBuildId":"2.0.022"}},"genOnOff":{"attributes":{"onOff":0}}},"_binds":[],"_configuredReportings":[],"meta":{}},{"ID":242,"profileID":41440,"deviceID":97,"inputClusters":[33],"outputClusters":[33],"deviceNetworkAddress":57088,"deviceIeeeAddress":"0xd0cf5efffed951ae","clusters":{},"_binds":[],"_configuredReportings":[],"meta":{}}],"_manufacturerName":"IKEA of Sweden","_powerSource":"Mains (single phase)","_modelID":"TRADFRI bulb GU10 WS 400lm","_applicationVersion":32,"_stackVersion":98,"_zclVersion":2,"_hardwareVersion":1,"_dateCode":"20190308","_softwareBuildID":"2.0.022","_interviewCompleted":true,"_interviewing":false,"meta":{},"_lastSeen":1612256932666,"_linkquality":15},"endpoint":"[Circular]","data":{"fieldControl":1,"manufacturerCode":4476,"imageType":16900,"fileVersion":537011747},"linkquality":15,"groupID":0,"cluster":"genOta","meta":{"zclTransactionSequenceNumber":78,"manufacturerCode":null,"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":false,"reservedBits":0}}}
2021-02-02 10:08:52.669 - debug: zigbee.0 (5188) No converter available for 'LED1537R6/LED1739R5' with cluster 'genOta' and type 'commandQueryNextImageRequest'

...

2021-02-02 10:08:55.666 - debug: zigbee.0 (5188) handleMessage. {"type":"commandQueryNextImageRequest","device":{"ID":20,"_type":"Router","_ieeeAddr":"0xd0cf5efffed951ae","_networkAddress":57088,"_manufacturerID":4476,"_endpoints":[{"ID":1,"profileID":260,"deviceID":268,"inputClusters":[0,3,4,5,6,8,768,4096,64636],"outputClusters":[5,25,32,4096],"deviceNetworkAddress":57088,"deviceIeeeAddress":"0xd0cf5efffed951ae","clusters":{"genBasic":{"attributes":{"modelId":"TRADFRI bulb GU10 WS 400lm","manufacturerName":"IKEA of Sweden","powerSource":1,"zclVersion":2,"appVersion":32,"stackVersion":98,"hwVersion":1,"dateCode":"20190308","swBuildId":"2.0.022"}},"genOnOff":{"attributes":{"onOff":0}}},"_binds":[],"_configuredReportings":[],"meta":{}},{"ID":242,"profileID":41440,"deviceID":97,"inputClusters":[33],"outputClusters":[33],"deviceNetworkAddress":57088,"deviceIeeeAddress":"0xd0cf5efffed951ae","clusters":{},"_binds":[],"_configuredReportings":[],"meta":{}}],"_manufacturerName":"IKEA of Sweden","_powerSource":"Mains (single phase)","_modelID":"TRADFRI bulb GU10 WS 400lm","_applicationVersion":32,"_stackVersion":98,"_zclVersion":2,"_hardwareVersion":1,"_dateCode":"20190308","_softwareBuildID":"2.0.022","_interviewCompleted":true,"_interviewing":false,"meta":{},"_lastSeen":1612256935666,"_linkquality":15},"endpoint":"[Circular]","data":{"fieldControl":1,"manufacturerCode":4476,"imageType":16900,"fileVersion":537011747},"linkquality":15,"groupID":0,"cluster":"genOta","meta":{"zclTransactionSequenceNumber":79,"manufacturerCode":null,"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":false,"reservedBits":0}}}
2021-02-02 10:08:55.667 - debug: zigbee.0 (5188) Received Zigbee message from '0xd0cf5efffed951ae', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"manufacturerCode":4476,"imageType":16900,"fileVersion":537011747}' from endpoint 1 with groupID 0
2021-02-02 10:08:55.667 - debug: zigbee.0 (5188) Type commandQueryNextImageRequest device {"type":"device","device":{"ID":20,"_type":"Router","_ieeeAddr":"0xd0cf5efffed951ae","_networkAddress":57088,"_manufacturerID":4476,"_endpoints":[{"ID":1,"profileID":260,"deviceID":268,"inputClusters":[0,3,4,5,6,8,768,4096,64636],"outputClusters":[5,25,32,4096],"deviceNetworkAddress":57088,"deviceIeeeAddress":"0xd0cf5efffed951ae","clusters":{"genBasic":{"attributes":{"modelId":"TRADFRI bulb GU10 WS 400lm","manufacturerName":"IKEA of Sweden","powerSource":1,"zclVersion":2,"appVersion":32,"stackVersion":98,"hwVersion":1,"dateCode":"20190308","swBuildId":"2.0.022"}},"genOnOff":{"attributes":{"onOff":0}}},"_binds":[],"_configuredReportings":[],"meta":{}},{"ID":242,"profileID":41440,"deviceID":97,"inputClusters":[33],"outputClusters":[33],"deviceNetworkAddress":57088,"deviceIeeeAddress":"0xd0cf5efffed951ae","clusters":{},"_binds":[],"_configuredReportings":[],"meta":{}}],"_manufacturerName":"IKEA of Sweden","_powerSource":"Mains (single phase)","_modelID":"TRADFRI bulb GU10 WS 400lm","_applicationVersion":32,"_stackVersion":98,"_zclVersion":2,"_hardwareVersion":1,"_dateCode":"20190308","_softwareBuildID":"2.0.022","_interviewCompleted":true,"_interviewing":false,"meta":{},"_lastSeen":1612256935666,"_linkquality":15},"mapped":{"exposes":[{"type":"light","features":[{"type":"binary","name":"state","property":"state","access":7,"value_on":"ON","value_off":"OFF","value_toggle":"TOGGLE","description":"On/off state of this light"},{"type":"numeric","name":"brightness","property":"brightness","access":7,"value_min":0,"value_max":254,"description":"Brightness of this light"},{"type":"numeric","name":"color_temp","property":"color_temp","access":7,"unit":"mired","value_min":150,"value_max":500,"description":"Color temperature of this light"}]},{"type":"enum","name":"effect","property":"effect","access":2,"values":["blink","breathe","okay","channel_change","finish_effect","stop_effect"],"description":"Triggers an effect on the light (e.g. make light blink for a few seconds)"},{"type":"numeric","name":"linkquality","property":"linkquality","access":1,"unit":"lqi","description":"Link quality (signal strength)","value_min":0,"value_max":255}],"fromZigbee":[{"cluster":"lightingColorCtrl","type":["attributeReport","readResponse"]},{"cluster":"genOnOff","type":["attributeReport","readResponse"]},{"cluster":"genLevelCtrl","type":["attributeReport","readResponse"]},{"cluster":"genBasic","type":["attributeReport","readResponse"]}],"toZigbee":[{"key":["state","brightness","brightness_percent"]},{"key":["color_temp","color_temp_percent"]},{"key":["transition"],"attr":[]},{"key":["rate"],"attr":[]},{"key":["effect","alert","flash"]},{"key":["brightness_move","brightness_move_onoff"]},{"key":["colortemp_move","color_temp_move"]},{"key":["brightness_step","brightness_step_onoff"]},{"key":["color_temp_step"]},{"key":["scene_store"]},{"key":["scene_recall"]},{"key":["scene_add"]},{"key":["scene_remove"]},"[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]","[Circular]"],"zigbeeModel":["TRADFRI bulb GU10 WS 400lm"],"model":"LED1537R6/LED1739R5","vendor":"IKEA","description":"TRADFRI LED bulb GU10 400 lumen, dimmable, white spectrum","ota":{}},"name":"0xd0cf5efffed951ae"} incoming event: {"type":"commandQueryNextImageRequest","device":{"ID":20,"_type":"Router","_ieeeAddr":"0xd0cf5efffed951ae","_networkAddress":57088,"_manufacturerID":4476,"_endpoints":[{"ID":1,"profileID":260,"deviceID":268,"inputClusters":[0,3,4,5,6,8,768,4096,64636],"outputClusters":[5,25,32,4096],"deviceNetworkAddress":57088,"deviceIeeeAddress":"0xd0cf5efffed951ae","clusters":{"genBasic":{"attributes":{"modelId":"TRADFRI bulb GU10 WS 400lm","manufacturerName":"IKEA of Sweden","powerSource":1,"zclVersion":2,"appVersion":32,"stackVersion":98,"hwVersion":1,"dateCode":"20190308","swBuildId":"2.0.022"}},"genOnOff":{"attributes":{"onOff":0}}},"_binds":[],"_configuredReportings":[],"meta":{}},{"ID":242,"profileID":41440,"deviceID":97,"inputClusters":[33],"outputClusters":[33],"deviceNetworkAddress":57088,"deviceIeeeAddress":"0xd0cf5efffed951ae","clusters":{},"_binds":[],"_configuredReportings":[],"meta":{}}],"_manufacturerName":"IKEA of Sweden","_powerSource":"Mains (single phase)","_modelID":"TRADFRI bulb GU10 WS 400lm","_applicationVersion":32,"_stackVersion":98,"_zclVersion":2,"_hardwareVersion":1,"_dateCode":"20190308","_softwareBuildID":"2.0.022","_interviewCompleted":true,"_interviewing":false,"meta":{},"_lastSeen":1612256935666,"_linkquality":15},"endpoint":"[Circular]","data":{"fieldControl":1,"manufacturerCode":4476,"imageType":16900,"fileVersion":537011747},"linkquality":15,"groupID":0,"cluster":"genOta","meta":{"zclTransactionSequenceNumber":79,"manufacturerCode":null,"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":false,"reservedBits":0}}}
2021-02-02 10:08:55.668 - debug: zigbee.0 (5188) No converter available for 'LED1537R6/LED1739R5' with cluster 'genOta' and type 'commandQueryNextImageRequest'

...

2021-02-02 10:09:14.562 - error: zigbee.0 (5188) Unhandled promise rejection. 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().
2021-02-02 10:09:14.562 - error: zigbee.0 (5188) unhandled promise rejection: Timeout - 1458 - 1 - null - 25 - 1 after 30000ms
2021-02-02 10:09:14.563 - error: zigbee.0 (5188) Error: Timeout - 1458 - 1 - null - 25 - 1 after 30000ms
at Timeout._onTimeout (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35)
at listOnTimeout (internal/timers.js:554:17)
at processTimers (internal/timers.js:497:7)
2021-02-02 10:09:14.563 - error: zigbee.0 (5188) Timeout - 1458 - 1 - null - 25 - 1 after 30000ms
2021-02-02 10:09:14.571 - info: zigbee.0 (5188) cleaned everything up...
2021-02-02 10:09:14.572 - info: zigbee.0 (5188) Zigbee: disabling joining new devices.

...

2021-02-02 10:09:14.590 - debug: zigbee.0 (5188) Publish available for 0xd0cf5efffed951ae = false
2021-02-02 10:09:14.590 - debug: zigbee.0 (5188) Publish LQ for 0xd0cf5efffed951ae = 0

...

2021-02-02 10:09:14.591 - error: zigbee.0 (5188) Unhandled promise rejection. 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().
2021-02-02 10:09:14.591 - error: zigbee.0 (5188) unhandled promise rejection: Timeout - 1004 - 2 - null - 25 - 1 after 30000ms
2021-02-02 10:09:14.591 - error: zigbee.0 (5188) Error: Timeout - 1004 - 2 - null - 25 - 1 after 30000ms
at Timeout._onTimeout (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35)
at listOnTimeout (internal/timers.js:554:17)
at processTimers (internal/timers.js:497:7)
2021-02-02 10:09:14.591 - error: zigbee.0 (5188) Timeout - 1004 - 2 - null - 25 - 1 after 30000ms
2021-02-02 10:09:14.591 - error: zigbee.0 (5188) Unhandled promise rejection. 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().
2021-02-02 10:09:14.592 - error: zigbee.0 (5188) unhandled promise rejection: Timeout - 45537 - 1 - null - 25 - 1 after 30000ms
2021-02-02 10:09:14.592 - error: zigbee.0 (5188) Error: Timeout - 45537 - 1 - null - 25 - 1 after 30000ms
at Timeout._onTimeout (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35)
at listOnTimeout (internal/timers.js:554:17)
at processTimers (internal/timers.js:497:7)
2021-02-02 10:09:14.592 - error: zigbee.0 (5188) Timeout - 45537 - 1 - null - 25 - 1 after 30000ms
2021-02-02 10:09:14.592 - info: zigbee.0 (5188) Failed to check if update available for '0x000b57fffee77018' (Device didn't respond to OTA request)
2021-02-02 10:09:14.592 - debug: zigbee.0 (5188) sendTo "checkOtaAvail" to system.adapter.admin.0 from system.adapter.zigbee.0
2021-02-02 10:09:14.593 - info: zigbee.0 (5188) Failed to check if update available for '0x90fd9ffffe192306' (Device didn't respond to OTA request)
2021-02-02 10:09:14.593 - debug: zigbee.0 (5188) sendTo "checkOtaAvail" to system.adapter.admin.0 from system.adapter.zigbee.0
2021-02-02 10:09:14.972 - info: zigbee.0 (5188) terminating
2021-02-02 10:09:14.972 - warn: zigbee.0 (5188) Terminated (UNCAUGHT_EXCEPTION): Without reason
2021-02-02 10:09:15.507 - error: host.ioBroker instance system.adapter.zigbee.0 terminated with code 6 (UNCAUGHT_EXCEPTION)
2021-02-02 10:09:15.509 - info: host.ioBroker Restart adapter system.adapter.zigbee.0 because enabled
asgothian commented 3 years ago

Please verify if this also occurs with the current 1.4.3 GitHub version. Changes were made to the error handling which might affect this. Please also post what kind of coordinator you are using

A.

sky-it commented 3 years ago

with 1.4.3 Coordinator: TI CC26X2R1 type:zStack3x0 version:2-1.2.7.1. revision:20201026

host.ioBroker | 2021-02-02 11:31:56.443 | error | instance system.adapter.zigbee.0 terminated with code 6 (UNCAUGHT_EXCEPTION)
-- | -- | -- | --
zigbee.0 | 2021-02-02 11:31:55.521 | error | (6956) Timeout - 45537 - 1 - null - 25 - 1 after 30000ms
zigbee.0 | 2021-02-02 11:31:55.521 | error | (6956) Error: Timeout - 45537 - 1 - null - 25 - 1 after 30000ms at Timeout._onTimeout (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35) at listOnTimeout (internal/timer
zigbee.0 | 2021-02-02 11:31:55.521 | error | (6956) unhandled promise rejection: Timeout - 45537 - 1 - null - 25 - 1 after 30000ms
zigbee.0 | 2021-02-02 11:31:55.521 | error | (6956) Unhandled promise rejection. 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().
zigbee.0 | 2021-02-02 11:31:55.521 | error | (6956) Timeout - 1004 - 2 - null - 25 - 1 after 30000ms
zigbee.0 | 2021-02-02 11:31:55.521 | error | (6956) Error: Timeout - 1004 - 2 - null - 25 - 1 after 30000ms at Timeout._onTimeout (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35) at listOnTimeout (internal/timers
zigbee.0 | 2021-02-02 11:31:55.521 | error | (6956) unhandled promise rejection: Timeout - 1004 - 2 - null - 25 - 1 after 30000ms
zigbee.0 | 2021-02-02 11:31:55.520 | error | (6956) Unhandled promise rejection. 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().
zigbee.0 | 2021-02-02 11:31:55.488 | error | (6956) Timeout - 1458 - 1 - null - 25 - 1 after 30000ms
zigbee.0 | 2021-02-02 11:31:55.488 | error | (6956) Error: Timeout - 1458 - 1 - null - 25 - 1 after 30000ms at Timeout._onTimeout (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35) at listOnTimeout (internal/timers
zigbee.0 | 2021-02-02 11:31:55.487 | error | (6956) unhandled promise rejection: Timeout - 1458 - 1 - null - 25 - 1 after 30000ms
zigbee.0 | 2021-02-02 11:31:55.487 | error | (6956) Unhandled promise rejection. 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().
zigbee.0 | 2021-02-02 11:31:31.031 | error | (6956) Update of '0xd0cf5efffed951ae' failed (Image is truncated: not long enough to contain a valid tag)
sky-it commented 3 years ago

I'm from version 1.4.3 back to 1.4.2. Firmware update fails The adapter does not crash anymore

zigbee.0 2021-02-03 21:26:54.087 error (1215) Update of '0xd0cf5efffed951ae' failed (Image is truncated: not long enough to contain a valid tag)

In zigbee2mqtt isues I read that since 12.2020 there is a bug with the IKEA OTAs, maybe it is still because of that.

sky-it commented 3 years ago

Node.js: v14.16.0 NPM: 6.14.16 js-controller: 3.2.16

Adapter 1.4.4 Coordinator: TI CC26X2R1 type: zStack3x0 version:2-1.2.7.1. revision:20210120 `

host.ioBroker 2021-03-17 10:00:56.578 info Restart adapter system.adapter.zigbee.0 because enabled
host.ioBroker 2021-03-17 10:00:56.577 error instance system.adapter.zigbee.0 terminated with code 6 (UNCAUGHT_EXCEPTION)
zigbee.0 2021-03-17 10:00:55.538 error (27655) Timeout - 59328 - 1 - null - 25 - 1 after 30000ms
zigbee.0 2021-03-17 10:00:55.538 error at processTimers (internal/timers.js:497:7)
zigbee.0 2021-03-17 10:00:55.538 error at listOnTimeout (internal/timers.js:554:17)
zigbee.0 2021-03-17 10:00:55.538 error at Timeout._onTimeout (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/waitress.js:46:35)
zigbee.0 2021-03-17 10:00:55.538 error (27655) Error: Timeout - 59328 - 1 - null - 25 - 1 after 30000ms
zigbee.0 2021-03-17 10:00:55.538 error (27655) unhandled promise rejection: Timeout - 59328 - 1 - null - 25 - 1 after 30000ms
zigbee.0 2021-03-17 10:00:55.538 error (27655) Unhandled promise rejection. 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().

`

Could it be the coordinator? #997

asgothian commented 3 years ago

I suspect that it is a missing try/catch on the zigbee-herdsman-converters level. I'll try to trace that down in the coming days. Would you be willing to log onto Discord sometime next week to run a few tests together ? I may have a patched version for you to install for that to see if it removes the error.

A.

sky-it commented 3 years ago

After a few crashes I was able to update three lamps. I don't have an account on Discord yet, but I'd be happy to take a look at it.

stale[bot] commented 3 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

mariusbach commented 3 years ago

I have the same issue using 1.6.0 and 1.6.2 from github (installed today). It seems that if you have devices which don't respond (like aqara or xiaomi sensors), the adapter crashes. Any "firmware available"-info is lost, so I cannot update firmwares.

Deleting all non-responding devices is no useful option, really :)

asgothian commented 3 years ago

Please provide:

mariusbach commented 3 years ago

Hi @asgothian, sure, here's more info and thanks for looking into the issue:

OS: Raspbian, up-to-date Coordinator: CC2652RB type:zStack3x0 version:2-1.2.7.1. revision:20210708 port:/dev/ttyUSB0 channel:11

iobroker.zigbee Version 1.6.2 in /opt/iobroker/node_modules/iobroker.zigbee, node: v12.22.6, js-controller: 3.3.18

And here the log at info-level when I start the firmware check (the non-responding devices are mostly temperature and door sensors from aqara or xiaomi, and 2 Osram smart plugs):

zigbee.0 | 2021-09-22 09:50:54.594 | warn | Failed to ping 0x84182600000d5767 Plug 01
zigbee.0 | 2021-09-22 09:50:53.528 | warn | Failed to ping 0x84182600000c899e Plug 01
zigbee.0 | 2021-09-22 09:50:53.497 | warn | Failed to ping 0x000b57fffee77cbb TRADFRI bulb E14 WS opal 400lm
zigbee.0 | 2021-09-22 09:50:29.451 | info | Zigbee started

[note: list of devices appears - all normal. Excluded for readability]

zigbee.0 | 2021-09-22 09:50:29.257 | info | Currently 55 devices are joined:
zigbee.0 | 2021-09-22 09:50:29.241 | info | --> transmitPower : normal
zigbee.0 | 2021-09-22 09:50:29.239 | info | Disable LED
zigbee.0 | 2021-09-22 09:50:29.225 | info | Coordinator firmware version: {"type":"zStack3x0","meta":{"transportrev":2,"product":1,"majorrel":2,"minorrel":7,"maintrel":1,"revision":20210708}}
zigbee.0 | 2021-09-22 09:50:26.510 | warn | Extended PAN ID is reversed (expected=62dda376de36edaf, actual=afed36de76a3dd62)
zigbee.0 | 2021-09-22 09:50:18.846 | info | Installed Version: ioBroker/ioBroker.zigbee
zigbee.0 | 2021-09-22 09:50:18.418 | info | Starting Zigbee npm ...
zigbee.0 | 2021-09-22 09:50:18.298 | info | starting. Version 1.6.2 in /opt/iobroker/node_modules/iobroker.zigbee, node: v12.22.6, js-controller: 3.3.18
zigbee.0 | 2021-09-22 09:50:18.284 | info | Plugin sentry Sentry Plugin disabled for this process because sending of statistic data is disabled for the system
zigbee.0 | 2021-09-22 09:49:44.729 | warn | Terminated (UNCAUGHT_EXCEPTION): Without reason
zigbee.0 | 2021-09-22 09:49:44.728 | info | terminating
zigbee.0 | 2021-09-22 09:49:44.411 | info | Failed to check if update available for '0x84fd27fffeaae4b3' (Device didn't respond to OTA request)
zigbee.0 | 2021-09-22 09:49:44.410 | info | Failed to check if update available for '0x804b50fffe8a9a81' (Device didn't respond to OTA request)
zigbee.0 | 2021-09-22 09:49:44.409 | info | Failed to check if update available for '0x5c0272fffe2b10cf' (Device didn't respond to OTA request)
zigbee.0 | 2021-09-22 09:49:44.408 | info | Failed to check if update available for '0x804b50fffe4849f3' (Device didn't respond to OTA request)
zigbee.0 | 2021-09-22 09:49:44.230 | info | Zigbee: disabling joining new devices.
zigbee.0 | 2021-09-22 09:49:44.226 | info | cleaned everything up...
zigbee.0 | 2021-09-22 09:49:44.220 | info | Failed to check if update available for '0x0017880103a54fad' (Device didn't respond to OTA request)
zigbee.0 | 2021-09-22 09:49:44.216 | error | Timeout - 28780 - 2 - null - 25 - 1 after 30000ms
zigbee.0 | 2021-09-22 09:49:44.215 | error | Error: Timeout - 28780 - 2 - null - 25 - 1 after 30000ms at Timeout._onTimeout (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/waitress.js:37:35) at listOnTimeout (internal/timers.js:554:17) at processTimers (internal/timers.js:497:7)
zigbee.0 | 2021-09-22 09:49:44.214 | error | unhandled promise rejection: Timeout - 28780 - 2 - null - 25 - 1 after 30000ms
zigbee.0 | 2021-09-22 09:49:44.213 | error | Unhandled promise rejection. 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().
zigbee.0 | 2021-09-22 09:49:44.202 | info | Failed to check if update available for '0x000b57fffedaa7fa' (Device didn't respond to OTA request)
zigbee.0 | 2021-09-22 09:49:44.199 | info | Failed to check if update available for '0x001788010672a616' (Device didn't respond to OTA request)
zigbee.0 | 2021-09-22 09:49:44.196 | info | Failed to check if update available for '0x0017880103a4ed72' (Device didn't respond to OTA request)
zigbee.0 | 2021-09-22 09:49:44.193 | info | Failed to check if update available for '0x0017880103e5d790' (Device didn't respond to OTA request)
zigbee.0 | 2021-09-22 09:49:44.181 | info | Failed to check if update available for '0x000b57fffed963dc' (Device didn't respond to OTA request)
zigbee.0 | 2021-09-22 09:49:41.768 | info | Failed to check if update available for '0x84182600000c899e' (Device didn't respond to OTA request)
zigbee.0 | 2021-09-22 09:49:37.297 | info | Failed to check if update available for '0x000b57fffee77cbb' (Device didn't respond to OTA request)
zigbee.0 | 2021-09-22 09:49:37.277 | info | Failed to check if update available for '0x84182600000d5767' (Device didn't respond to OTA request)

Let me know if you need a log at a deeper level!

asgothian commented 3 years ago

Can you run the Adapter in debug mode and recreate the error ? I can't see any reason for the system to go down from the code as is.

Actually, can you patch your ota.js file (somewhere around line 44) from

            switch (obj.command) {
                case 'checkOtaAvail':
                    this.checkOtaAvail(obj);
                    break;

to

            switch (obj.command) {
                case 'checkOtaAvail':
                    await this.checkOtaAvail(obj);
                    break;

before you run the test again ?

A.

mariusbach commented 3 years ago

to

            switch (obj.command) {
                case 'checkOtaAvail':
                    await this.checkOtaAvail(obj);
                    break;

Hi @asgothian, I did the mod, hit restart and the adapter won't start anymore:

host.iobroker | 2021-09-24 11:37:11.933 | error | instance system.adapter.zigbee.0 terminated with code 1 (JS_CONTROLLER_STOPPED)
host.iobroker | 2021-09-24 11:37:11.933 | error | Caught by controller[0]: at Object.Module._extensions..js (internal/modules/cjs/loader.js:1027:10)
host.iobroker | 2021-09-24 11:37:11.933 | error | Caught by controller[0]: at Module._compile (internal/modules/cjs/loader.js:999:30)
host.iobroker | 2021-09-24 11:37:11.932 | error | Caught by controller[0]: at Object.<anonymous> (/opt/iobroker/node_modules/iobroker.zigbee/main.js:26:19)
host.iobroker | 2021-09-24 11:37:11.932 | error | Caught by controller[0]: at require (internal/modules/cjs/helpers.js:74:18)
host.iobroker | 2021-09-24 11:37:11.931 | error | Caught by controller[0]: at Module.require (internal/modules/cjs/loader.js:887:19)
host.iobroker | 2021-09-24 11:37:11.931 | error | Caught by controller[0]: at Function.Module._load (internal/modules/cjs/loader.js:708:14)
host.iobroker | 2021-09-24 11:37:11.931 | error | Caught by controller[0]: at Module.load (internal/modules/cjs/loader.js:863:32)
host.iobroker | 2021-09-24 11:37:11.930 | error | Caught by controller[0]: at Object.Module._extensions..js (internal/modules/cjs/loader.js:1027:10)
host.iobroker | 2021-09-24 11:37:11.930 | error | Caught by controller[0]: at Module._compile (internal/modules/cjs/loader.js:963:27)
host.iobroker | 2021-09-24 11:37:11.929 | error | Caught by controller[0]: at wrapSafe (internal/modules/cjs/loader.js:915:16)
host.iobroker | 2021-09-24 11:37:11.929 | error | Caught by controller[0]: SyntaxError: await is only valid in async function
host.iobroker | 2021-09-24 11:37:11.928 | error | Caught by controller[0]: ^^^^^
host.iobroker | 2021-09-24 11:37:11.928 | error | Caught by controller[0]: await this.checkOtaAvail(obj);
host.iobroker | 2021-09-24 11:37:11.927 | error | Caught by controller[0]: /opt/iobroker/node_modules/iobroker.zigbee/lib/ota.js:45
host.iobroker | 2021-09-24 11:37:09.901 | info | instance system.adapter.zigbee.0 started with pid 14769
host.iobroker | 2021-09-24 11:36:39.875 | info | Restart adapter system.adapter.zigbee.0 because enabled
mariusbach commented 3 years ago

Here's a file at debug level before I tried the await-mod from above. I clicked on the firmware check button at 2021-09-24 11:10:59.864.

iobroker.current.log

mariusbach commented 3 years ago

Issue persists with 1.6.3.

JorinL commented 3 years ago

Persists with 1.6.4.

zigbee.0 | 2021-10-30 13:37:53.548 | info | starting. Version 1.6.4 in /opt/iobroker/node_modules/iobroker.zigbee, node: v12.22.7, js-controller: 3.3.18
-- | -- | -- | --
zigbee.0 | 2021-10-30 13:37:53.467 | info | Plugin sentry Sentry Plugin disabled for this process because sending of statistic data is disabled for the system
zigbee.0 | 2021-10-30 13:37:53.455 | debug | Plugin sentry Initialize Plugin (enabled=true)
host.ioslave | 2021-10-30 13:37:48.274 | info | instance system.adapter.zigbee.0 started with pid 11395
host.ioslave | 2021-10-30 13:37:18.187 | info | Restart adapter system.adapter.zigbee.0 because enabled
host.ioslave | 2021-10-30 13:37:18.185 | error | instance system.adapter.zigbee.0 terminated with code 6 (UNCAUGHT_EXCEPTION)
zigbee.0 | 2021-10-30 13:37:16.024 | warn | Terminated (UNCAUGHT_EXCEPTION): Without reason
zigbee.0 | 2021-10-30 13:37:16.024 | debug | Plugin sentry destroyed
zigbee.0 | 2021-10-30 13:37:16.022 | info | terminating
zigbee.0 | 2021-10-30 13:37:15.726 | debug | sendTo "checkOtaAvail" to system.adapter.admin.0 from system.adapter.zigbee.0
zigbee.0 | 2021-10-30 13:37:15.725 | info | Failed to check if update available for '0x90fd9ffffe649738' (Device didn't respond to OTA request)
zigbee.0 | 2021-10-30 13:37:15.723 | debug | sendTo "checkOtaAvail" to system.adapter.admin.0 from system.adapter.zigbee.0
zigbee.0 | 2021-10-30 13:37:15.723 | info | Failed to check if update available for '0x90fd9ffffe085778' (Device didn't respond to OTA request)
zigbee.0 | 2021-10-30 13:37:15.721 | debug | sendTo "checkOtaAvail" to system.adapter.admin.0 from system.adapter.zigbee.0
zigbee.0 | 2021-10-30 13:37:15.720 | info | Failed to check if update available for '0x90fd9ffffe0857ad' (Device didn't respond to OTA request)
zigbee.0 | 2021-10-30 13:37:15.719 | error | Timeout - 63398 - 1 - null - 25 - 1 after 30000ms
zigbee.0 | 2021-10-30 13:37:15.719 | error | Error: Timeout - 63398 - 1 - null - 25 - 1 after 30000ms at Timeout._onTimeout (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/waitress.js:37:35) at listOnTimeout (internal/timers.js:554:17) at processTimers (internal/timers.js:497:7)
zigbee.0 | 2021-10-30 13:37:15.718 | error | unhandled promise rejection: Timeout - 63398 - 1 - null - 25 - 1 after 30000ms
zigbee.0 | 2021-10-30 13:37:15.717 | error | Unhandled promise rejection. 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().
zigbee.0 | 2021-10-30 13:37:15.716 | error | Timeout - 44133 - 1 - null - 25 - 1 after 30000ms
zigbee.0 | 2021-10-30 13:37:15.715 | error | Error: Timeout - 44133 - 1 - null - 25 - 1 after 30000ms at Timeout._onTimeout (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/waitress.js:37:35) at listOnTimeout (internal/timers.js:554:17) at processTimers (internal/timers.js:497:7)
zigbee.0 | 2021-10-30 13:37:15.714 | error | unhandled promise rejection: Timeout - 44133 - 1 - null - 25 - 1 after 30000ms
zigbee.0 | 2021-10-30 13:37:15.714 | error | Unhandled promise rejection. 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().
zigbee.0 | 2021-10-30 13:37:15.712 | debug | sendTo "checkOtaAvail" to system.adapter.admin.0 from system.adapter.zigbee.0
zigbee.0 | 2021-10-30 13:37:15.711 | info | Failed to check if update available for '0x90fd9ffffe71a006' (Device didn't respond to OTA request)
zigbee.0 | 2021-10-30 13:37:15.710 | debug | sendTo "checkOtaAvail" to system.adapter.admin.0 from system.adapter.zigbee.0
zigbee.0 | 2021-10-30 13:37:15.709 | info | Failed to check if update available for '0xec1bbdfffeb51680' (Device didn't respond to OTA request)
zigbee.0 | 2021-10-30 13:37:15.708 | debug | sendTo "checkOtaAvail" to system.adapter.admin.0 from system.adapter.zigbee.0
zigbee.0 | 2021-10-30 13:37:15.706 | info | Failed to check if update available for '0xd0cf5efffe1d74a8' (Device didn't respond to OTA request)
mariusbach commented 2 years ago

I still have errors with 1.6.6.

error: zigbee.0 (12721) Unhandled promise rejection. 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().

error: zigbee.0 (12721) unhandled promise rejection: SREQ '--> ZDO - extRouteDisc - {"dstAddr":33484,"options":0,"radius":30}' failed with status '(0xc7: NWK_TABLE_FULL)' (expected '(0x00: SUCCESS)')

error: zigbee.0 (12721) Error: SREQ '--> ZDO - extRouteDisc - {"dstAddr":33484,"options":0,"radius":30}' failed with status '(0xc7: NWK_TABLE_FULL)' (expected '(0x00: SUCCESS)')
at Object.func (/opt/iobroker/node_modules/zigbee-herdsman/dist/adapter/z-stack/znp/znp.js:276:27)
at async Queue.executeNext (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/queue.js:19:32)

error: zigbee.0 (12721) SREQ '--> ZDO - extRouteDisc - {"dstAddr":33484,"options":0,"radius":30}' failed with status '(0xc7: NWK_TABLE_FULL)' (expected '(0x00: SUCCESS)')
JorinL commented 2 years ago

Dito - here also with 1.6.6.

`

zigbee.0 | 2021-11-17 23:02:23.755 | warn | Terminated (UNCAUGHT_EXCEPTION): Without reason -- | -- | -- | -- zigbee.0 | 2021-11-17 23:02:23.752 | info | terminating zigbee.0 | 2021-11-17 23:02:23.413 | info | Failed to check if update available for '0x90fd9ffffe0857ad' (Device didn't respond to OTA request) zigbee.0 | 2021-11-17 23:02:23.411 | info | Failed to check if update available for '0x90fd9ffffe085778' (Device didn't respond to OTA request) zigbee.0 | 2021-11-17 23:02:23.410 | info | Failed to check if update available for '0x90fd9ffffe649738' (Device didn't respond to OTA request) zigbee.0 | 2021-11-17 23:02:23.409 | info | Failed to check if update available for '0x90fd9ffffedbcb5e' (Device didn't respond to OTA request) zigbee.0 | 2021-11-17 23:02:23.407 | info | Failed to check if update available for '0x90fd9ffffe71a006' (Device didn't respond to OTA request) zigbee.0 | 2021-11-17 23:02:23.406 | info | Failed to check if update available for '0xec1bbdfffeb51680' (Device didn't respond to OTA request)

`

mariusbach commented 2 years ago

still present on 1.6.8

mariusbach commented 2 years ago
source time level message
host.iobroker 2021-12-06 14:37:31.246 error instance system.adapter.zigbee.0 terminated with code 6 (UNCAUGHT_EXCEPTION)
zigbee.0 2021-12-06 14:37:30.657 warn Terminated (UNCAUGHT_EXCEPTION): Without reason
zigbee.0 2021-12-06 14:37:30.655 info terminating
zigbee.0 2021-12-06 14:37:30.395 info Failed to check if update available for '0x804b50fffe02e708' (Device didn't respond to OTA request)
zigbee.0 2021-12-06 14:37:30.394 info Failed to check if update available for '0x804b50fffe4849f3' (Device didn't respond to OTA request)
zigbee.0 2021-12-06 14:37:30.393 info Failed to check if update available for '0x90fd9ffffe51eef2' (Device didn't respond to OTA request)
zigbee.0 2021-12-06 14:37:30.158 info Zigbee: disabling joining new devices.
zigbee.0 2021-12-06 14:37:30.154 info cleaned everything up...
zigbee.0 2021-12-06 14:37:30.151 info Failed to check if update available for '0x0017880103a54fad' (Device didn't respond to OTA request)
zigbee.0 2021-12-06 14:37:30.147 error Timeout - 28780 - 2 - null - 25 - 1 after 30000ms
zigbee.0 2021-12-06 14:37:30.146 error Error: Timeout - 28780 - 2 - null - 25 - 1 after 30000ms at Timeout._onTimeout (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/waitress.js:37:35) at listOnTimeout (internal/timers.js:557:17) at processTimers (internal/timers.js:500:7)
zigbee.0 2021-12-06 14:37:30.146 error unhandled promise rejection: Timeout - 28780 - 2 - null - 25 - 1 after 30000ms
zigbee.0 2021-12-06 14:37:30.145 error Unhandled promise rejection. 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().

before these messages, some devices find updates, some don't and some don't respond (as expected). after the above errors appear, the adapter restarts.

asgothian commented 2 years ago

Is this error reproducible, i.e. it happens every time you try to check for updates ? If so, are you willing to do a remote debugging session in order to track it down ?

A.

mariusbach commented 2 years ago

@asgothian yes it happens every time. We can do a remote session, no problem!

Vodochnik commented 2 years ago

Any update on this? I have 2 zigbee networks, in one of them I have the same issue, in another one I cannot reproduce this behavior. Tried to switch off some bulbs but OTA works. Very strange...

ScumbagSteve commented 2 years ago

I have the same issue using 1.6.0 and 1.6.2 from github (installed today). It seems that if you have devices which don't respond (like aqara or xiaomi sensors), the adapter crashes. Any "firmware available"-info is lost, so I cannot update firmwares.

I have the same problem and I support this assumption. It doesn't happen to me every time, I would say every 2nd time when I check for updates. I check for updates and when a device doesn't respond, the adapter crashes after a certain time. However not this message is triggering the bug:

Failed to check if update available for '0x84fd27fffeaae4b3' (Device didn't respond to OTA request)

I have plenty of these messages and it still doesn't crash. You get this message when a device is not connected to power, which is nothing unusal for some devices in a large network.

This message seems to be the problem:

Timeout - 28780 - 2 - null - 25 - 1 after 30000ms

I am on 1.6.6 with CC26X2R1 Revision 20210120

mariusbach commented 2 years ago

Persists in 1.6.12, same signature.

onkelalex commented 2 years ago

would like to add that I also have the problem with the zigbee network crashing.

I am on 1.6.12 with tube-zb-gw-cc2652p2-poe gateway.

I did some trial and error yesterday, and I figured out that I have 3 "E1525/E1745 - IKEA TRADFRI motion sensors" in my network that stuck everytime at "checking". After removing them from the Network, I was able to run through the firmware checking process without any problem.

Is there a possibility to check updates only for selected devices? Or is there a possibility to outline some devices on the hard way (via config file?)

raspilaurent commented 2 years ago

me too. Same here: checking the Ikea motion sensor for firmware-update, adapter is crashing. This error is reproducible. If more information is needed, let me know. Thanks.

fraggle-iw commented 2 years ago

Same here. I have plenty of E1525/E1745 - IKEA TRADFRI motion sensors. Zigbee 1.6.10, CC26X2R1 Coordinator firmware version: {"type":"zStack3x0","meta":{"transportrev":2,"product":1,"majorrel":2,"minorrel":7,"maintrel":1,"revision":99999999}} Xiaomi FIX

asgothian commented 2 years ago

Please test the current GitHub version (once PR #1343 is merged).. devices which are known to be unavailable shouldn't trigger a firmware update.

mariusbach commented 2 years ago

Same signature. Unavailable devices are skipped, true, but I think not responding devices might trigger the crash? I have some Aqara/Sonoff window sensors, which probably cannot upgrade their firmware and don't respond.

Unfortunately, upon restart of the adapter, all discovered firmware updates are gone. Perhaps a workaround is to save them to be persistent? Then you could crash and restart without issues, and afterwards trigger the update for e.g. Ikea devices.

asgothian commented 2 years ago

Can you try to isolate the devices by disabling the, one by one through the interface ? Also - what is the available status and lqi of these devices ?

raspilaurent commented 2 years ago

Same here. Is it possible, to check the firmware-update for a single device? Maybe with an update-button in the card? I can see, there are updates for the Ikea bulbs, but after an adapter-crash the update-button in the card to start the update are gone. A button in every device-card for a firmware-update-check of this one device would be great. Thank you for your work!

onkelalex commented 2 years ago

Same here on my system.

@asgothian will try to isolate the devices. Unfortunately my zigbee network needs much time to recreate the routes after the adapter crashes.

` host.iobroker 2022-01-23 11:51:36.799 error instance system.adapter.zigbee.0 terminated with code 6 (UNCAUGHT_EXCEPTION)
zigbee.0 2022-01-23 11:51:36.258 warn Terminated (UNCAUGHT_EXCEPTION): Without reason
zigbee.0 2022-01-23 11:51:36.258 info terminating
zigbee.0 2022-01-23 11:51:35.816 error Timeout - 46708 - 1 - null - 25 - 1 after 30000ms
zigbee.0 2022-01-23 11:51:35.816 error Error: Timeout - 46708 - 1 - null - 25 - 1 after 30000ms at Timeout._onTimeout (/opt/iobroker/node_modules/zigbee-herdsman/dist/utils/waitress.js:37:35) at listOnTimeout (internal/timers.js:557:17) at processTimers (internal/timers.js:500:7)

`

onkelalex commented 2 years ago

Update: After disabling IKEA Remote E1524/E1810 (TRADFRI remote control), IKEA Remote E1744 (SYMFONISK sound controller) and IKEA PIR E1525/E1745 (TRADFRI motion sensor) the OTA Check runs smoothly (also with disconnected devices and devices that are not responding to OTA request).

To crosscheck I enabled one of the disabled devices, waited until they got recognized in Network map with a lqi of >20 and a green state to one of the coordinator or router and ota check crashes again with the same error message.

mariusbach commented 2 years ago

@onkelalex Awesome, I tried the same and it works. I have disabled 3 IKEA E1524/E1810 remote controls. I did not have to disable the two IKEA E1743 on-off switches I also own, neither any other devices (hue motion sensors, lots of Ikea bulbs and a bunch of Sonoff SNZB-02 and -04s). Firmware upgrades in progress, finally :)

asgothian commented 2 years ago

That’s something for sure.

now another question - what coordinator are you using ? I have some ikea remotes to play with at home so I can try to see what the cause for the crash is, but I need to know what coordinators to test with

onkelalex commented 2 years ago

@asgothian
had to tried it with two different coordiators - First one is a tube-zb-gw-cc2652p2-poe (with z-stack 3.x.0 20210708, 20211217 and 20220103) - have several full disconnects with that coordinator so I was forced to switch to a self build version with a cc2538 (z-stack 3.0.x 20211222)

mariusbach commented 2 years ago

I've got the slae.sh stick, CC2652RB:

type:zStack3x0 version:2-1.2.7.1. revision:20211217

JorinL commented 2 years ago

I use a: CC2652P zStack3x0 version:2-1.2.7.1. revision:20210708 on channel: 22

I use: 10x E1524/E1810 (Tradfri remote) 2x E1744 (Symfosik remote) 3x E1525/E1745 2x LED1732G11 1x L1528 (Floalt 30x90) 1x L1529 (Floalt 60x60) 1x L1527 (Floalt 30x30) 1x AB3257001NJ (Osram plug) 2x E1743 (Tradfri remote/dimmer)

When I update FW - I "sometimes" have the crash also - most off the time I just push abutton ohn the unit I want to update - otherwise most of the battery driven onse don't react.

So it seems to be not problem with one of those devices - it seems to be handling on coordinator side - in my opinion :-)

JorinL commented 2 years ago

Jip - seems legit :-)

Did not longer have it - nice work thx!