Start fails with "Cannot request when znp has not been initialized yet" / "Port is not open" / "SRSP - SYS - osalNvRead after 6000ms"

[dmak]

Bug Report

Out of the sudden start of Zigbee2mqtt failed with message "Port is not open". I have decided to reboot Debian to have clean logs (check here).

In issue 1566 one suggests to remove problematic Tradfri devices from database.db. I've decided to implement it in more radical way and removed data/database.db completely. Now start of Zigbee2mqtt results error "SRSP - SYS - osalNvRead after 6000ms" (here is the log). Unfortunately Zigbee2mqtt cannot recover stick after such an error and I have to unplug the stick and plug it back before doing further experiments – perhaps that could be improved.

I have report: true feature enabled. I disabled it as advised here, but without any effect.

Finally I've decided to roll back to configuration backup from previous week. Zigbee2mqtt starts fine with it, but it does not work properly (I see no updates from devices in the log and they don't react on commands):

zigbee2mqtt:warn 12/12/2019, 12:29:53 AM Failed to configure unknown (0x000d6ffffea204c4) ('Error: SRSP - ZDO - bindReq after 6000ms') (attempt #1)
zigbee2mqtt:warn 12/12/2019, 12:29:53 AM This can be ignored if the device is working properly
zigbee2mqtt:error 12/12/2019, 12:29:57 AM Failed to bind for reporting for '0xd0cf5efffed314ac' - genOnOff - 1 - (Error: Timed out after 10000 ms)
zigbee2mqtt:error 12/12/2019, 12:29:59 AM Failed to bind for reporting for '0x000b57fffed6f264' - genOnOff - 1 - (Error: SRSP - ZDO - bindReq after 6000ms)
zigbee2mqtt:error 12/12/2019, 12:30:35 AM Failed to bind for reporting for '0xd0cf5efffed314ac' - genLevelCtrl - 1 - (Error: SRSP - ZDO - bindReq after 6000ms)
zigbee2mqtt:warn 12/12/2019, 12:30:39 AM Failed to configure unknown (0x000b57fffe2a8d31) ('Error: Timed out after 10000 ms') (attempt #1)
zigbee2mqtt:warn 12/12/2019, 12:30:39 AM This can be ignored if the device is working properly
zigbee2mqtt:error 12/12/2019, 12:30:41 AM Failed to bind for reporting for '0x000b57fffed6f264' - genLevelCtrl - 1 - (Error: SRSP - ZDO - bindReq after 6000ms)
zigbee2mqtt:warn 12/12/2019, 12:31:29 AM Failed to configure unknown (0xd0cf5efffe12d47a) ('Error: Timed out after 10000 ms') (attempt #1)
zigbee2mqtt:warn 12/12/2019, 12:31:29 AM This can be ignored if the device is working properly
zigbee2mqtt:info 12/12/2019, 12:34:59 AM Zigbee publish to device '0x000b57fffed6f264', genOnOff - off - {} - {"manufSpec":0,"disDefaultRsp":0} - 1
zigbee2mqtt:error 12/12/2019, 12:35:05 AM Zigbee publish to device '0x000b57fffed6f264', genOnOff - off - {} - {"manufSpec":0,"disDefaultRsp":0} - null failed with error Error: SRSP - AF - dataRequest after 6000ms
zigbee2mqtt:info 12/12/2019, 12:35:05 AM MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"zigbee_publish_error","message":"Error: SRSP - AF - dataRequest after 6000ms","meta":{"entity":{"ID":"0x000b57fffed6f264","type":"device:

Then I have downgraded to zigbee2mqtt version 1.5.1 ac3b924, that didn't help.

I don't know how to recover. Thanks for any hint in advance.

Debug Info

zigbee2mqtt version: 1.6.0 e26ad2a
CC2531 firmware version: 20190608

[Koenkk]

Probably you firmware crashed, I would recommend switching to the latest zigbee2mqtt (1.7.1) and use the source routing firmware which improves stability: https://github.com/Koenkk/Z-Stack-firmware/tree/master/coordinator/Z-Stack_Home_1.2/bin/source_routing

[dmak]

I have re-flashed the stick with CC2531_SOURCE_ROUTING_20190619 and updated Z2M to v1.8.0 da4d26a. In two words: it helped, but not all IKEA devices have re-joined the network (Xiaomi nevertheless have jumped in quickly). In particular two IKEA bulbs are timing-out:

12/17/2019, 9:59:47 AM - error: Failed to bind for reporting for '0x000b57fffed6f264' - genLevelCtrl - 1 - (Error: Timed out after 10000 ms)
12/17/2019, 9:59:48 AM - error: Failed to bind for reporting for '0xd0cf5efffed314ac' - genLevelCtrl - 1 - (Error: Timed out after 10000 ms)
12/17/2019, 9:59:58 AM - warn: Failed network lqi scan for device: '0x000b57fffed6f264' with error: 'Error: Timed out after 10000 ms'
12/17/2019, 9:59:58 AM - warn: Failed network lqi scan for device: '0xd0cf5efffed314ac' with error: 'Error: Timed out after 10000 ms'

They have worked as routers and without them other devices are not reachable. One of the bulbs is in group with motion sensor and reacts right on motion (lights up on event, and switches off after given timeout). Another lamp is in group with dimmer (ICTC-G-1), and unfortunately does not react on dimmer anymore and re-binding it with that dimmer didn't help (I will keep trying to resurrect it).

Another observation: Above mentioned dimmer (ICTC-G-1) has joined the network and generated a lot of logs for Z2M v1.8.0:

info  2019-12-17 09:09:14: MQTT publish: topic 'zigbee2mqtt/0x000b57fffe2a8d31', payload '{"battery":74,"linkquality":21,"brightness":252,"rate":70,"level":0,"action":""}'
info  2019-12-17 09:09:15: MQTT publish: topic 'zigbee2mqtt/0x000b57fffe2a8d31', payload '{"battery":74,"linkquality":21,"brightness":252,"rate":70,"level":0,"action":"rotate_right"}'
info  2019-12-17 09:09:15: MQTT publish: topic 'zigbee2mqtt/0x000b57fffe2a8d31', payload '{"battery":74,"linkquality":21,"brightness":252,"rate":70,"level":0,"action":""}'
info  2019-12-17 09:09:15: MQTT publish: topic 'zigbee2mqtt/0x000b57fffe2a8d31', payload '{"battery":74,"linkquality":21,"brightness":252,"rate":70,"level":0,"action":"rotate_right"}'

These logs result 10M of disk space per hour and caused log rotation. I had to roll back Z2M to v1.6.0 which does not cause such extensive logging.

[Koenkk]

@dmak can you try the following recommendation? https://www.zigbee2mqtt.io/devices/E1744.html#recommendation

[dmak]

Thanks, I will try it.