dresden-elektronik / deconz-rest-plugin

deCONZ REST-API plugin to control ZigBee devices
BSD 3-Clause "New" or "Revised" License
1.89k stars 498 forks source link

19.3 takes 30 seconds to send command to light, Conbee I #6588

Closed Ltek closed 1 year ago

Ltek commented 1 year ago

Describe the bug

30 second delay in any command getting to a light. Same problem I've had with all 19.x releases. I revert back to 18.2 and the same lights respond almost instantly All my routes are Green in the Deconz UI. I have 13 wall powered devices within close proximity (see screenshot attached)

also, maybe related... initial Deconz start-up route mapping/connections take about 10x longer in any 19.x version than in 18.2 -- where the lines are all drawn within 30-60 seconds, 19.x takes multiple minutes.

Steps to reproduce the behavior

send any on/off or color change command, from Phoscon Windows PC, JowiHue / Homeseer Windows PC, or Hue Essentials android app

Expected behavior

Near instant response

Screenshots

n/a

Environment

deCONZ Logs

attached debug log. I changed colors twice during the log capture

Additional context

Deconz19.3debug.txt Capture

Smanar commented 1 year ago

I had the same issue than you but has since been fixed for me, I m using the same firmware ATM. A test that have asked manup is read an attribute for exemple the manufacture name in the basic cluster. Select the attribute with double clic, and press the "read" button on next windows. When I had the issue, it can work in less than 1s or totaly fail in timeout (so make the try 5/ 6 times)

Ltek commented 1 year ago

I don't understand what that helps? No matter what command is sent, to any light, it takes 30 seconds. When I go back to 18.2, it's instant... Seems pretty clear that the bug is not fixed

Smanar commented 1 year ago

I don't understand what that helps?

In nothing ^^, was just a test, easy with a single direct request in zigbee using the GUI, than something "magic" that can come from the API. And check if you haven't logs like that

14:21:56:298 Delay APS request id: 107 to 0x40FF, profile: 0x0104 cluster: 0xEF00 node already has busy 3
14:21:56:706 Delay APS request id: 114 to 0x40FF, profile: 0x0104 cluster: 0xEF00 node already has busy 3
14:21:56:707 Delay APS request id: 118 to 0x40FF, profile: 0x0104 cluster: 0xEF00 node already has busy 3

Because I don't see something special in your logs, and I can't reproduce it using same hardware/firmware on Raspian.

ebaauw commented 1 year ago

Same problem I've had with all 19.x releases.

I seriously doubt that. In pre-1.19.3 versions, deCONZ would issue too many requests in too short a timeframe, causing the queues on the coordinator device to fill up beyond recovery, effectively disabling any outgoing traffic from the gateway, until the coordinator device has been reset (clearing the queues).

In v1.19.3, the outgoing messages are eventually sent, so the queues don't fill up beyond recovery. I am seeing an occasional delay reading attributes in the GUI as well, but not consistently. I do notice that polling other devices (as indicated by the blue dots on the nodes) stalls as well.

Trying to capture relevant logs (with INFO, INFO_L2, ERROR, ERROR_L2, APS, APS_L2, ZCL) while catching deCONZ redhanded:

Here, I read the Level Control cluster attributes from my Mueller light:

Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:582 ZCL read cluster: 0x0008, attribute: 0x0000
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:584 ZCL read cluster: 0x0008, attribute: 0x0001
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:585 ZCL read cluster: 0x0008, attribute: 0x000F
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:587 ZCL read cluster: 0x0008, attribute: 0x0010
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:588 ZCL cmd-req nwk: 0x5227, profile: 0x0104, cluster: 0x0008 cmd: 0x00
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:590 APS-DATA.request id: 16, addrmode: 0x02, addr: 0x5227, profile: 0x0104, cluster: 0x0008, ep: 0x01 -> 0x01 queue: 0 len: 11 tx.options 0x00
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:591     asdu (length: 11): 104000000001000f001000
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:627 ZCL read cluster: 0x0008, attribute: 0x0011
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:629 ZCL read cluster: 0x0008, attribute: 0x0012
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:629 ZCL read cluster: 0x0008, attribute: 0x0013
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:630 ZCL read cluster: 0x0008, attribute: 0x0014
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:631 ZCL cmd-req nwk: 0x5227, profile: 0x0104, cluster: 0x0008 cmd: 0x00
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:632 APS-DATA.request id: 17, addrmode: 0x02, addr: 0x5227, profile: 0x0104, cluster: 0x0008, ep: 0x01 -> 0x01 queue: 1 len: 11 tx.options 0x00
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:633     asdu (length: 11): 1041001100120013001400
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:634 APS-DATA.confirm id: 16, status: 0x00 SUCCESS
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:635 APS-DATA.confirm request id: 16 -> erase from queue
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:666 aps request id: 16 finished, erase from queue

This results in two Zigbee requests, 16 and 17. 16 gets confirmed (sent?) immediately, but 17 "hangs". Meanwhile, the API plugin is polling some devices, for which the requests also seem to "hang":

Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:742 rule event /config/localtime: 11:25:02.741 -> 11:25:03.742 (1001ms)
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:957 poll node 00:13:a2:00:41:83:1c:ae-e6
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:03:960 Poll light node XBee 2
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:04:110 Poll APS request to 0x0013A20041831CAE cluster: 0x0000 dropped, cluster doesn't exist
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:04:742 rule event /config/localtime: 11:25:03.742 -> 11:25:04.741 (999ms)
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:04:796 poll node 00:13:a2:00:41:83:1c:4d-e6
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:04:799 Poll light node XBee 1
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:04:941 Poll APS request to 0x0013A20041831C4D cluster: 0x0000 dropped, cluster doesn't exist
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:05:345 APS-DATA.request id: 22, addrmode: 0x03, addr: 0x001fee0000001963, profile: 0x0000, cluster: 0x0031, ep: 0x00 -> 0x00 queue: 1 len: 2 tx.options 0x00
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:05:348     asdu (length: 2): 4206
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:05:666 poll node 00:1f:ee:00:00:00:19:63-01
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:05:668 Poll light node ubisys
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:05:718 Poll APS request to 0x001FEE0000001963 cluster: 0x0006 dropped, values are fresh enough
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:05:743 rule event /config/localtime: 11:25:04.741 -> 11:25:05.741 (1000ms)
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:06:742 poll node 00:1f:ee:00:00:00:19:63-02-0006
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:06:743 Poll ZHASwitch sensor node ubisys
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:06:747 rule event /config/localtime: 11:25:05.741 -> 11:25:06.742 (1001ms)
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:07:631 poll node 00:1f:ee:00:00:00:19:63-04-0702
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:07:633 Poll ZHAConsumption sensor node ubisys
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:07:741 rule event /config/localtime: 11:25:06.742 -> 11:25:07.741 (999ms)
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:07:743 ZCL read attr 0x001788010B1CFF75, ep: 0x0B, cl: 0x0300, attr: 0x4001, mfcode: 0x0000, aps.id: 32, zcl.seq: 162
Dec 04 11:25:07 pi5 deCONZ[17656]: 11:25:07:745 APS-DATA.request id: 32, addrmode: 0x03, addr: 0x001788010b1cff75, profile: 0x0104, cluster: 0x0300, ep: 0x01 -> 0x0B queue: 2 len: 11 tx.options 0x00
Dec 04 11:25:08 pi5 deCONZ[17656]: 11:25:07:747     asdu (length: 11): 10a2000140024000400100
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:07:874 read attributes of 0x001FEE0000001963 cluster: 0x0702: [ 11:25:07:875 0x0000 11:25:07:877 0x0400 11:25:07:878 ]
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:07:879 add task 221007 type 19 to 0x001FEE0000001963 cluster 0x0702 req.id 33
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:07:880 Poll APS request 33 to 0x001FEE0000001963 cluster: 0x0702
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:07:941 APS-DATA.request id: 33, addrmode: 0x03, addr: 0x001fee0000001963, profile: 0x0104, cluster: 0x0702, ep: 0x01 -> 0x04 queue: 3 len: 7 tx.options 0x00
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:07:943     asdu (length: 7): 10a30000000004
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:08:743 rule event /config/localtime: 11:25:07.741 -> 11:25:08.742 (1001ms)
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:09:741 Daylight now: goldenHour1, status: 160, daylight: 1, dark: 0
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:09:743 rule event /config/localtime: 11:25:08.742 -> 11:25:09.742 (1000ms)

Now the response to the first request is received, over 7 seconds after the request has been sent:

Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:10:974 APS-DATA.indication srcAddr: 0x5227, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0008, lqi: 255, rssi: -31
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:10:975     asdu: 18400100000020800100002100000f00001801100086
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:10:976 ZCL got data for node=0x5227, cl=0x0008, at=0x0000, status=0x00, type=0x20
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:10:977 ZCL got data for node=0x5227, cl=0x0008, at=0x0001, status=0x00, type=0x21
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:10:977 ZCL got data for node=0x5227, cl=0x0008, at=0x000F, status=0x00, type=0x18
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:10:978 ZCL got unsupported status: 0x86 for mandatory attribute
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:10:979 ZCL got data for node=0x5227, cl=0x0008, at=0x0010, status=0x86, type=0x18
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:10:982 rule event /config/localtime: 11:25:09.742 -> 11:25:10.956 (1214ms)
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:10:996 APS-DATA.indication srcAddr: 0x08c9, srcEp: 0x0B dstAddrMode: 2, profile: 0x0104, cluster: 0xFC03, lqi: 255, rssi: -31
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:10:997     asdu: 1c0b10c50a020041080b0000390b7e396a
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:001 ZCL attribute report 0x001788010B1CFF75 for cluster: 0xFC03, ep: 0x0B, frame control: 0x1C, mfcode: 0x100B
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:002     payload: 020041080b0000390b7e396a
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:003 Websocket 127.0.0.1:43066 send message: {"attr":{"lastseen":"2022-12-04T10:25Z"},"e":"changed","id":"6","r":"lights","t":"event","uniqueid":"00:17:88:01:0b:1c:ff:75-0b"} (ret = -751799808)
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:004 Websocket 127.0.0.1:44468 send message: {"attr":{"lastseen":"2022-12-04T10:25Z"},"e":"changed","id":"6","r":"lights","t":"event","uniqueid":"00:17:88:01:0b:1c:ff:75-0b"} (ret = -751799808)
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:005 Websocket 127.0.0.1:43082 send message: {"attr":{"lastseen":"2022-12-04T10:25Z"},"e":"changed","id":"6","r":"lights","t":"event","uniqueid":"00:17:88:01:0b:1c:ff:75-0b"} (ret = -751799808)
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:008 Websocket 192.168.76.40:59106 send message: {"attr":{"lastseen":"2022-12-04T10:25Z"},"e":"changed","id":"6","r":"lights","t":"event","uniqueid":"00:17:88:01:0b:1c:ff:75-0b"} (ret = -751799808)
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:010 ZCL read cluster: 0x0008, attribute: 0x4000
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:012 ZCL cmd-req nwk: 0x5227, profile: 0x0104, cluster: 0x0008 cmd: 0x00
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:013 APS-DATA.request id: 36, addrmode: 0x02, addr: 0x5227, profile: 0x0104, cluster: 0x0008, ep: 0x01 -> 0x01 queue: 4 len: 5 tx.options 0x00
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:014     asdu (length: 5): 1043000040

I think this triggers the sending of request 17 and the other hanging requests:

Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:015 APS-DATA.confirm id: 17, status: 0x00 SUCCESS
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:016 APS-DATA.confirm request id: 17 -> erase from queue
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:019 APS-DATA.indication srcAddr: 0x5227, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0008, lqi: 255, rssi: -31
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:020     asdu: 18410111000020ff120086130086140086
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:021 APS-DATA.request id: 17 erase from queue
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:021 ZCL got data for node=0x5227, cl=0x0008, at=0x0011, status=0x00, type=0x20
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:022 ZCL got unsupported status: 0x86 for mandatory attribute
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:023 ZCL got data for node=0x5227, cl=0x0008, at=0x0012, status=0x86, type=0x20
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:023 ZCL got unsupported status: 0x86 for mandatory attribute
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:024 ZCL got data for node=0x5227, cl=0x0008, at=0x0013, status=0x86, type=0x20
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:024 ZCL got unsupported status: 0x86 for mandatory attribute
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:025 ZCL got data for node=0x5227, cl=0x0008, at=0x0014, status=0x86, type=0x20
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:047 APS-DATA.confirm id: 22, status: 0x00 SUCCESS
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:048 APS-DATA.confirm request id: 22 -> confirmed, timeout 0
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:139 Poll APS confirm 33 status: 0x00
Dec 04 11:25:11 pi5 deCONZ[17656]: 11:25:11:140 Erase task req-id: 33, type: 19 zcl seqno: 163 send time 3, profileId: 0x0104, clusterId: 0x0702
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:141 APS-DATA.confirm id: 33, status: 0x00 SUCCESS
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:141 APS-DATA.confirm request id: 33 -> erase from queue
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:149 APS-DATA.confirm id: 36, status: 0x00 SUCCESS
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:150 APS-DATA.confirm request id: 36 -> erase from queue
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:172 APS-DATA.indication srcAddr: 0xec47, srcEp: 0x00 dstAddrMode: 2, profile: 0x0000, cluster: 0x8031, lqi: 255, rssi: -46
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:173     asdu: 42000a0603a7d403ffff2e2100e6c041100188170077592502ffffa7d403ffff2e21004d1c834100a21300bfaa2502ffe0a7d403ffff2e2100e077620d01881700adb12502ffff
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:174 APS-DATA.indication request id: 22 -> finished
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:174 APS-DATA.request id: 22 erase from queue
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:175 APS-DATA.request id: 33 erase from queue
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:176 APS-DATA.request id: 36 erase from queue
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:177 APS-DATA.confirm id: 32, status: 0x00 SUCCESS
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:178 APS-DATA.confirm request id: 32 -> erase from queue
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:186 APS-DATA.indication srcAddr: 0xec47, srcEp: 0x04 dstAddrMode: 2, profile: 0x0104, cluster: 0x0702, lqi: 255, rssi: -46
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:187     asdu: 18a301000000250000000000000004002a000000
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:188 APS-DATA.request id: 32 erase from queue
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:188 ZCL got data for node=0xEC47, cl=0x0702, at=0x0000, status=0x00, type=0x25
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:189 ZCL got data for node=0xEC47, cl=0x0702, at=0x0400, status=0x00, type=0x2A
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:189 Node data 0x001fee0000001963 profileId: 0x0104, clusterId: 0x0702
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:190 0x001FEE0000001963: update ZCL value 0x04/0x0702/0x0000 after 0 s
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:191 0x001FEE0000001963: update ZCL value 0x04/0x0702/0x0400 after 0 s
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:192 Websocket 127.0.0.1:43066 send message: {"e":"changed","id":"24","r":"sensors","state":{"lastupdated":"2022-12-04T10:25:11.192"},"t":"event","uniqueid":"00:1f:ee:00:00:00:19:63-04-0702"} (ret = -751799808)
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:194 Websocket 127.0.0.1:44468 send message: {"e":"changed","id":"24","r":"sensors","state":{"lastupdated":"2022-12-04T10:25:11.192"},"t":"event","uniqueid":"00:1f:ee:00:00:00:19:63-04-0702"} (ret = -751799808)
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:195 Websocket 127.0.0.1:43082 send message: {"e":"changed","id":"24","r":"sensors","state":{"lastupdated":"2022-12-04T10:25:11.192"},"t":"event","uniqueid":"00:1f:ee:00:00:00:19:63-04-0702"} (ret = -751799808)
Dec 04 11:25:12 pi5 deCONZ[17656]: 11:25:11:196 Websocket 192.168.76.40:59106 send message: {"e":"changed","id":"24","r":"sensors","state":{"lastupdated":"2022-12-04T10:25:11.192"},"t":"event","uniqueid":"00:1f:ee:00:00:00:19:63-04-0702"} (ret = -751799808)

I think this log proves the delay, but I don't see any indication as to what's causing it.

I don't know why the API plugin insists on polling the XBees, which have no Basic cluster but I've had them in this (test) network for months if not years. Also a bit worried about the "ZCL got unsupported status: 0x86 for mandatory attribute"; need to double-check if this a wrong definition in general.xml or if the Mueller is in violation of the standard. Seeing the same on Hue lights, though.

LukasA83 commented 1 year ago

I am having a similar issue, see #6590 .

Switching back to 2.18.02 and the issue is gone.

Qonstrukt commented 1 year ago

Just as a general "me too". I'd like to inform I've been seeing these issues with every 2.19.x release as well. I haven't had the time to debug or respond unfortunately, but I just want to make sure it's known more people are having these issues. Going back to 2.18.02 fixes these issues completely.

I'm running Deconz in Docker on Raspbian on a RPi 4 with a Raspbee 2.

jeankone commented 1 year ago

Just as a general "me too". I'd like to inform I've been seeing these issues with every 2.19.x release as well. I haven't had the time to debug or respond unfortunately, but I just want to make sure it's known more people are having these issues.

Going back to 2.18.02 fixes these issues completely.

I'm running Deconz in Docker on Raspbian on a RPi 4 with a Raspbee 2.

The exact same for me as well

monpelaud commented 1 year ago

Hi, Have you progressed on this issue? Can we expect a fix for the next release?

Best regards

Kenny-BC commented 1 year ago

Same here. ive to restart my system every day. after this time comes the delay

Smanar commented 1 year ago

I think the issue on 2.19.x is a priority ATM, manup is back and is testing new versions with somes devs ATM. But IDK what they are correcting ATM.

Ltek commented 1 year ago

I think the issue on 2.19.x is a priority ATM, manup is back and is testing new versions with somes devs ATM. But IDK what they are correcting ATM.

thx for the update, very glad to hear... I'm still on 18.2 since anything newer is not usable for me

jonnycastaway commented 1 year ago

Same Problem here, with newest release there are ~30 second delays at irregular intervals. In this 30 seconds no sensors, bulbs or switches are usable. The Raspbian (i'm using the Raspbian Pi Image from Dresden Electronics) is usable and didn't hang. Also tested with a Virtual Machine on my x86 Proxmox, same behavior. Back on 2.18.2 all is running fine.

Using RaspberyPi 4, 4GB and Conbee2 Stick with newest Firmware and USB Extension Cable. Wired connection to Network and disabled Wifi and Bluetooth with dtoverlay. For Control i use ioBroker with Deconz Adapter and Node-Red on my Proxmox System, also wired Network connection. Network is completely 1GBit/s and fine, i checked this.

olemr commented 1 year ago

I have a 117 node system that none of the 1.19.x versions behave on, but 1.18.02 works fine. (amd64 ubuntu, Conbee I) On another site with a much smaller setup (20~30 nodes) 1.19.01 works just fine (RPi4, Raspbian 32bit, Conbee I)

jonnycastaway commented 1 year ago

I have 72 Nodes from various Vendors.

Smanar commented 1 year ago

For information, there is a new version, not official yet but available for tests https://github.com/dresden-elektronik/deconz-rest-plugin/releases/tag/v2.20.0-beta

Ltek commented 1 year ago

For information, there is a new version, not official yet but available for tests https://github.com/dresden-elektronik/deconz-rest-plugin/releases/tag/v2.20.0-beta Are the devs saying they tested exclusively for this and fixed the delay? They told us it was fixed a few times now... Nope, not at all. . No reason for us to waste time on it otherwise.

Mimiix commented 1 year ago

For information, there is a new version, not official yet but available for tests https://github.com/dresden-elektronik/deconz-rest-plugin/releases/tag/v2.20.0-beta

It's a beta release.

LukasA83 commented 1 year ago

I tried the new version for 3 days. While the logs look normal now, I am still experiencing a random delay, e.g. on Aqara door sensor reporting. How can I help to further nail down the issue?

Smanar commented 1 year ago

A delay on sensor report ? Can you explain pls ?

Aqara device make a report every hour or if you have a noticiable change.

LukasA83 commented 1 year ago

I have a door sensor for my garage door. With 2.18.02 it reports directly after any change, with 2.19.x and 2.20 I get random delays especially on the second change. Typically the "OPEN" is reported directly, but the "CLOSED" few minutes later might get reported like 30-60 minutes delayed with the newer versions.

In 2.19.x I have seen like 30s hangs in the logs, this is no longer the case with 2.20

Smanar commented 1 year ago

I have made tries on my side. Same result. But it s not something normal ?

It work one time, but after that it simply stop working, no APS request from zigbee side. Something strange the dot is blinking green, and not on other sensors, but I don't see what can be wrong ! as Xiaomi device don't support bind or report, all is native ....

LukasA83 commented 1 year ago

For me it worked "as expected" on 2.18.x and before, now it is not working as expected, so I would not call it normal.

My expectation would be, that when the state changes from open to close and the other way around, it is reflected in deconz very quick. That is, how it worked on 2.18.x and before. Or do I read your question wrong?

Smanar commented 1 year ago

I will try an older version to compare. But we completely miss some aps request, or the device don't make it.

Smanar commented 1 year ago

Someone else have a door sensor to make tests ^^ ?

I have ugly result even with version 2.18 beta. Can be a battery issue, it's an unused device, but the device simply stop making report, so no battery return too, not possible to be sure of the battery level.

jonnycastaway commented 1 year ago

Someone else have a door sensor to make tests ^^ ?

I have ugly result even with version 2.18 beta. Can be a battery issue, it's an unused device, but the device simply stop making report, so no battery return too, not possible to be sure of the battery level.

Yes, i have several Door/Window Sensors. Some Mijia, Some Aquara. If you can tell me what and where i've to do i can doing some test.

Smanar commented 1 year ago

just check if you have no problem with them ^^. I have one that skip 1 event / 5, and idk if it's from the device or the deconz version.

github-actions[bot] commented 1 year ago

As there has not been any response in 21 days, this issue has been automatically marked as stale. At OP: Please either close this issue or keep it active It will be closed in 7 days if no further activity occurs.

github-actions[bot] commented 1 year ago

As there has not been any response in 28 days, this issue will be closed. @ OP: If this issue is solved post what fixed it for you. If it is not solved, request to get this opened again.