search

Koenkk / zigbee2mqtt

Zigbee 🐝 to MQTT bridge 🌉, get rid of your proprietary Zigbee bridges 🔨
https://www.zigbee2mqtt.io
GNU General Public License v3.0
12.35k stars 1.69k forks source link

Sonoff zbmini does not reconnect to the network after restoring power to the house or restarting the server. #22591

Closed Blink8745 closed 2 months ago

Blink8745 commented 6 months ago

What happened?

And since I installed the Sonoff zbmini I noticed that after restoring power to the house it doesn't reconnect automatically but I have to set zigbee2mqtt in pairing mode otherwise they remain offline. It also happened with ezsp.

What did you expect to happen?

I expected the Sonoff zbmini to reconnect automatically after turning on the power again.

How to reproduce it (minimal and precise)

Turn off the power to the house and turn it back on.

Zigbee2MQTT version

1.37.1

Adapter firmware version

7.4.2 [GA]

Adapter

sonoff zigbee dongle-e

Setup

addon on raspberry pi 4

Debug log

[2024-05-10 18:48:12] info: zh:ember: [NCP COUNTERS] 2588,516,2916,2788,54,60,10,9,2505,2481,0,0,65,7,0,2,0,0,0,0,0,1,0,0,0,0,0,0,66,0,2,0,59,0,0,0,0,0,0,0,0 [2024-05-10 18:48:12] info: zh:ember: [ASH COUNTERS] 64901,10354,2549,7804,0,0,0,0,188557,7858,7857,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0 [2024-05-10 18:55:13] info: z2m: Disconnecting from MQTT server [2024-05-10 18:55:13] info: z2m: Stopping zigbee-herdsman... [2024-05-10 18:55:13] info: zh:controller: Wrote coordinator backup to '/config/zigbee2mqtt/coordinator_backup.json' [2024-05-10 18:55:13] info: zh:ember:uart:ash: ASH COUNTERS since last clear: [2024-05-10 18:55:13] info: zh:ember:uart:ash: Total frames: RX=1161, TX=1507 [2024-05-10 18:55:13] info: zh:ember:uart:ash: Cancelled : RX=0, TX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: DATA frames : RX=1161, TX=373 [2024-05-10 18:55:13] info: zh:ember:uart:ash: DATA bytes : RX=26654, TX=9472 [2024-05-10 18:55:13] info: zh:ember:uart:ash: Retry frames: RX=0, TX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: ACK frames : RX=0, TX=1134 [2024-05-10 18:55:13] info: zh:ember:uart:ash: NAK frames : RX=0, TX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: nRdy frames : RX=0, TX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: CRC errors : RX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: Comm errors : RX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: Length < minimum: RX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: Length > maximum: RX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: Bad controls : RX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: Bad lengths : RX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: Bad ACK numbers : RX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: Out of buffers : RX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: Retry dupes : RX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: Out of sequence : RX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: ACK timeouts : RX=0 [2024-05-10 18:55:13] info: zh:ember:uart:ash: Port closed. Error? no [2024-05-10 18:55:13] info: zh:ember:uart:ash: ======== ASH stopped ======== [2024-05-10 18:55:13] info: zh:ember:ezsp: ======== EZSP stopped ======== [2024-05-10 18:55:13] info: zh:ember: ======== Ember Adapter Stopped ======== [2024-05-10 18:55:13] info: z2m: Stopped zigbee-herdsman [2024-05-10 18:55:13] info: z2m: Stopped Zigbee2MQTT [17:17:21] INFO: Preparing to start... [17:17:22] INFO: Socat not enabled [17:17:25] INFO: Starting Zigbee2MQTT... [2024-05-11 17:17:32] info: z2m: Logging to console, file (filename: log.log) [2024-05-11 17:17:32] info: z2m: Starting Zigbee2MQTT version 1.37.1 (commit #unknown) [2024-05-11 17:17:32] info: z2m: Starting zigbee-herdsman (0.46.6) [2024-05-11 17:17:33] info: zh:ember: ======== Ember Adapter Starting ======== [2024-05-11 17:17:33] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-05-11 17:17:33] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-05-11 17:17:33] info: zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control. [2024-05-11 17:17:33] info: zh:ember:uart:ash: Serial port opened [2024-05-11 17:17:33] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-05-11 17:17:34] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-05-11 17:17:34] info: zh:ember:uart:ash: ======== ASH started ======== [2024-05-11 17:17:34] info: zh:ember:ezsp: ======== EZSP started ======== [2024-05-11 17:17:34] info: zh:ember: [STACK STATUS] Network up. [2024-05-11 17:17:34] info: zh:ember: [INIT TC] NCP network matches config. [2024-05-11 17:17:34] info: zh:ember: [CONCENTRATOR] Started source route discovery. 1248ms until next broadcast. [2024-05-11 17:17:34] info: z2m: zigbee-herdsman started (resumed) [2024-05-11 17:17:34] info: z2m: Coordinator firmware version: '{"meta":{"build":0,"ezsp":13,"major":7,"minor":4,"patch":2,"revision":"7.4.2 [GA]","special":0,"type":170},"type":"EmberZNet"}' [2024-05-11 17:17:34] info: z2m: Currently 9 devices are joined: [2024-05-11 17:17:34] info: z2m: MISURATORE CONSUMI (0x187a3efffe304456): SPM01 - TuYa Smart energy monitor for 1P+N system (Router) [2024-05-11 17:17:34] info: z2m: 0x00124b0024c2e039 (0x00124b0024c2e039): ZBMINI - SONOFF Zigbee two way smart switch (Router) [2024-05-11 17:17:34] info: z2m: 0x00158d00087b6773 (0x00158d00087b6773): WXKG11LM - Aqara Wireless mini switch (EndDevice) [2024-05-11 17:17:34] info: z2m: 0xf4ce368476a4095c (0xf4ce368476a4095c): 14592.0 - Vimar 2-way switch IoT connected mechanism (Router) [2024-05-11 17:17:34] info: z2m: 0xf4ce36e9cff023d1 (0xf4ce36e9cff023d1): 03981 - Vimar IoT connected relay module (Router) [2024-05-11 17:17:34] info: z2m: 0x287681fffe4937a4 (0x287681fffe4937a4): E2213 - IKEA SOMRIG shortcut button (EndDevice) [2024-05-11 17:17:34] info: z2m: 0xb43522fffe114a85 (0xb43522fffe114a85): ZBMINI - SONOFF Zigbee two way smart switch (Router) [2024-05-11 17:17:34] info: z2m: 0x0017880106d22449 (0x0017880106d22449): 8718699673147 - Philips Hue white A60 bulb E27 bluetooth (Router) [2024-05-11 17:17:34] info: z2m: 0xe0798dfffec9bf0d (0xe0798dfffec9bf0d): ZBMINI - SONOFF Zigbee two way smart switch (Router) [2024-05-11 17:17:34] info: z2m: Zigbee: disabling joining new devices. [2024-05-11 17:17:35] info: z2m: Connecting to MQTT server at mqtt://core-mosquitto:1883 [2024-05-11 17:17:35] warning: zh:ember: [TRUST CENTER] Device 8464:0xe0798dfffec9bf0d was denied joining via 15068. [2024-05-11 17:17:35] warning: z2m: Device '0xe0798dfffec9bf0d' left the network [2024-05-11 17:17:35] warning: zh:ember: [TRUST CENTER] Device 51520:0xb43522fffe114a85 was denied joining via 36355. [2024-05-11 17:17:35] info: z2m: Connected to MQTT server [2024-05-11 17:17:35] info: z2m: Started frontend on port 8099 [2024-05-11 17:17:35] info: z2m: Zigbee2MQTT started! [2024-05-11 17:17:35] error: z2m: EventBus error 'HomeAssistant/publishEntityState': Cannot read properties of undefined (reading 'isDevice') [2024-05-11 17:18:01] error: z2m: Publish 'set' 'state' to '0xb43522fffe114a85' failed: 'Error: ZCL command 0xb43522fffe114a85/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":4})' [2024-05-11 17:18:07] info: z2m: Zigbee: allowing new devices to join. [2024-05-11 17:18:07] info: zh:ember: [STACK STATUS] Network opened. [2024-05-11 17:18:14] info: zh:controller: Interview for '0xe0798dfffec9bf0d' started [2024-05-11 17:18:14] info: z2m: Device '0xe0798dfffec9bf0d' joined [2024-05-11 17:18:14] info: z2m: Starting interview of '0xe0798dfffec9bf0d' [2024-05-11 17:18:15] error: z2m: Publish 'set' 'state' to '0xb43522fffe114a85' failed: 'Error: ZCL command 0xb43522fffe114a85/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":20})' [2024-05-11 17:18:29] error: z2m: Publish 'set' 'state' to '0x00124b0024c2e039' failed: 'Error: ZCL command 0x00124b0024c2e039/1 genOnOff.off({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed ({"target":15068,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":39},"zclSequence":12,"commandIdentifier":11} timed out after 10000ms)' [2024-05-11 17:18:30] info: zh:controller: Succesfully interviewed '0xe0798dfffec9bf0d' [2024-05-11 17:18:30] info: z2m: Successfully interviewed '0xe0798dfffec9bf0d', device has successfully been paired [2024-05-11 17:18:30] info: z2m: Device '0xe0798dfffec9bf0d' is supported, identified as: SONOFF Zigbee two way smart switch (ZBMINI) [2024-05-11 17:18:30] info: z2m: Configuring '0xe0798dfffec9bf0d' [2024-05-11 17:18:30] info: z2m: Successfully configured '0xe0798dfffec9bf0d' [2024-05-11 17:22:11] info: zh:ember:ezsp: Received network/route error ROUTE_ERROR_NON_TREE_LINK_FAILURE for "21625". [2024-05-11 17:22:11] info: zh:ember:ezsp: Received network/route error ROUTE_ERROR_NON_TREE_LINK_FAILURE for "21625". [2024-05-11 17:22:12] info: zh:ember:ezsp: Received network/route error ROUTE_ERROR_MANY_TO_ONE_ROUTE_FAILURE for "30170". [2024-05-11 17:22:21] info: zh:ember: [STACK STATUS] Network closed. [2024-05-11 17:22:38] info: zh:ember:ezsp: Received network/route error ROUTE_ERROR_NON_TREE_LINK_FAILURE for "29215". [2024-05-11 17:22:38] info: zh:ember:ezsp: Received network/route error ROUTE_ERROR_NON_TREE_LINK_FAILURE for "29215". [2024-05-11 17:22:38] info: zh:ember:ezsp: Received network/route error ROUTE_ERROR_NON_TREE_LINK_FAILURE for "29215". [2024-05-11 17:22:43] info: zh:ember:ezsp: Received network/route error ROUTE_ERROR_NON_TREE_LINK_FAILURE for "29215". [2024-05-11 17:22:43] info: zh:ember:ezsp: Received network/route error ROUTE_ERROR_NON_TREE_LINK_FAILURE for "29215". [2024-05-11 17:23:06] error: z2m: Publish 'set' 'state' to '0x00124b0024c2e039' failed: 'Error: ZCL command 0x00124b0024c2e039/1 genOnOff.off({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed ({"target":15068,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":79},"zclSequence":66,"commandIdentifier":11} timed out after 10000ms)' [2024-05-11 17:30:54] info: z2m: Zigbee: allowing new devices to join. [2024-05-11 17:30:54] info: z2m: Zigbee: allowing new devices to join. [2024-05-11 17:30:54] info: z2m: Zigbee: allowing new devices to join. [2024-05-11 17:30:54] info: zh:ember: [STACK STATUS] Network opened. [2024-05-11 17:31:24] info: z2m: Zigbee: disabling joining new devices. [2024-05-11 17:31:24] info: z2m: Zigbee: disabling joining new devices. [2024-05-11 17:31:24] info: zh:ember: [STACK STATUS] Network closed. [2024-05-11 17:34:14] info: zh:ember: [STACK STATUS] Network opened.

Nerivec commented 6 months ago

At first glance, the behavior appears inconsistent, one is being denied join, leaves the network and does a full rejoin, another is denied join too, but doesn't leave the network, and the third one, nothing, except it doesn't appear to be responding either.

[2024-05-11 17:17:35] warning: zh:ember: [TRUST CENTER] Device 8464:0xe0798dfffec9bf0d was denied joining via 15068.
[2024-05-11 17:17:35] warning: zh:ember: [TRUST CENTER] Device 51520:0xb43522fffe114a85 was denied joining via 36355.

Can you confirm which devices are 0x3adc (15068) and 0x8e03 (36355)? Can you also tell me the Firmware build date and Firmware version for each of your zbmini (that's in the device page in Z2M frontend)? When you say "turn the power off then on", do you mean a rapid switch (1-2sec)? They may not like that (like many other pieces of equipment). Turning the power off to every router would definitely create a pain point though, it would likely result in a "messy" start the first time after that; big shuffles of the mesh always takes time to stabilize...

I have several zbminis, never had this issue a while back when I had to cut the power several times (only a few zbminis affected, rest of the network was still on). They are known for having a particularly bad antenna though, so their range is crappy; if you have to rely on them for routing, you better have several to cover the area well to work around that issue.

Blink8745 commented 6 months ago

hi, the 2 devices are: 0x3adc sonoff zbmini while the is a Vimar 14942 switch. The sonoff versions are: 0x00124b0024c2e039- 20210320, 2.0.0 0xb43522fffe114a85, 20200927, not specified. 0xe0798dfffec9bf0d, 20200927, not specified.

Even if you turn them on and off quickly, they work perfectly.

Nerivec commented 6 months ago

All of mine are 20210320, 2.0.0. Seems there are at least two versions out there.

Did you see anything strange with the light on one of the devices that does this, right after the power comes back on?

Even if you turn them on and off quickly, they work perfectly.

I meant that for the power to the house, not turning the switch on/off.

Blink8745 commented 6 months ago

I haven't noticed anything strange... however I can turn off the power even for just 10 seconds... and then it gives me the problem that it doesn't reconnect automatically.

Nerivec commented 2 months ago

I assume this is now fixed with unknown device identification mechanism.