Huge delays in the network

dethon · June 2, 2024, 11:44am

after a day of maintenance on my home server which also runs deconz as a container i have massive problems with delays in my zigbee network. The Conbee II is directly connected to the host.

In the logs I see different messages which I cannot evaluate.

e.g.

11:28:17:920 read attributes of 0x3C2EF5FFFExxxxxx cluster: 0x0006: [ 11:28:17:921 0x0000 11:28:17:921 ]
11:28:17:921 add task 4494 type 19 to 0x3C2EF5FFFExxxxxx cluster 0x0006 req.id 230
11:28:17:922 Poll APS request 230 to 0x3C2EF5FFFExxxxxx cluster: 0x0006
11:28:17:943 delay sending request 230 dt 3 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:18:003 node 0x00178801081DF717 leave wait state
11:28:18:044 delay sending request 230 dt 3 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:18:144 delay sending request 230 dt 3 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:18:243 delay sending request 230 dt 3 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:18:343 delay sending request 230 dt 3 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:18:443 delay sending request 230 dt 3 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:18:543 delay sending request 230 dt 4 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:18:643 delay sending request 230 dt 4 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:18:743 delay sending request 230 dt 4 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:18:843 delay sending request 230 dt 4 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:18:943 delay sending request 230 dt 4 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:19:043 delay sending request 230 dt 4 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:19:144 delay sending request 230 dt 4 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:19:243 delay sending request 230 dt 4 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:19:343 delay sending request 230 dt 4 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:19:443 delay sending request 230 dt 4 ms to 0x3C2EF5FFFExxxxxx, ep: 0x01 cluster: 0x0006 onAir: 1
11:28:19:543 Daylight now: solarNoon, status: 170, daylight: 1, dark: 0
11:28:19:544 APS-DATA.request id: 230, addrmode: 0x03, addr: 0x3C2EF5FFFExxxxxx, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x01 queue: 1 len: 5 tx.options 0x00
11:28:19:545 	asdu (length: 5): 1039000000
11:28:19:662 Poll APS confirm 230 status: 0xE1
11:28:19:663 	 drop item attr/modelid
11:28:19:664 	 drop item attr/swversion
11:28:19:665 	 drop item state/bri
11:28:19:665 	 drop item state/colormode
11:28:19:666 0x3C2EF5FFFExxxxxx error APSDE-DATA.confirm: 0xE1 on task
11:28:19:666 Erase task req-id: 230, type: 19 zcl seqno: 57 send time 0, profileId: 0x0104, clusterId: 0x0006

or

11:31:30:998 add task 5066 type 11 to 0x842E14FFFE1yyyyy cluster 0x0008 req.id 198
11:31:31:043 delay sending request 198 dt 0 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:31:143 delay sending request 198 dt 0 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:31:244 delay sending request 198 dt 0 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:31:343 delay sending request 198 dt 0 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:31:443 delay sending request 198 dt 0 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:31:545 delay sending request 198 dt 1 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:31:643 delay sending request 198 dt 1 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:31:743 delay sending request 198 dt 1 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:31:844 delay sending request 198 dt 1 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:31:943 delay sending request 198 dt 1 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:32:043 delay sending request 198 dt 1 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:32:143 delay sending request 198 dt 1 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:32:243 delay sending request 198 dt 1 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:32:343 delay sending request 198 dt 1 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:32:443 delay sending request 198 dt 1 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:32:544 delay sending request 198 dt 2 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:32:643 delay sending request 198 dt 2 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:32:743 delay sending request 198 dt 2 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:32:843 delay sending request 198 dt 2 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:32:943 delay sending request 198 dt 2 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:33:043 delay sending request 198 dt 2 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:33:143 delay sending request 198 dt 2 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:33:243 delay sending request 198 dt 2 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:33:343 delay sending request 198 dt 2 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:33:444 delay sending request 198 dt 2 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:33:543 delay sending request 198 dt 3 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:33:644 delay sending request 198 dt 3 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:33:743 delay sending request 198 dt 3 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:33:843 delay sending request 198 dt 3 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:33:943 delay sending request 198 dt 3 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:34:043 delay sending request 198 dt 3 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:34:143 delay sending request 198 dt 3 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:34:244 delay sending request 198 dt 3 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:34:343 delay sending request 198 dt 3 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:34:443 delay sending request 198 dt 3 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:34:544 delay sending request 198 dt 4 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:34:644 delay sending request 198 dt 4 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:34:743 delay sending request 198 dt 4 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:34:843 delay sending request 198 dt 4 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:34:943 delay sending request 198 dt 4 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:35:044 delay sending request 198 dt 4 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:35:143 delay sending request 198 dt 4 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:35:243 delay sending request 198 dt 4 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:35:343 delay sending request 198 dt 4 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:35:443 delay sending request 198 dt 4 ms to 0x842E14FFFE1yyyyy, ep: 0x01 cluster: 0x0008 onAir: 1
11:31:35:543 APS-DATA.request id: 198, addrmode: 0x03, addr: 0x842E14FFFE1yyyyy, profile: 0x0104, cluster: 0x0008, ep: 0x01 -> 0x01 queue: 5 len: 6 tx.options 0x04
11:31:41:208 Erase task req-id: 198, type: 11 zcl seqno: 108 send time 5, profileId: 0x0104, clusterId: 0x0008
11:31:41:208 APS-DATA.confirm id: 198, status: 0x00 SUCCESS
11:31:41:209 APS-DATA.confirm request id: 198 -> erase from queue
11:31:41:284 aps request id: 198 finished, erase from queue

11:51:18:673 APS-DATA.request id: 115, addrmode: 0x03, addr: 0x3C2EF5FFFEEFuuuu, profile: 0x0104, cluster: 0x0300, ep: 0x01 -> 0x01 queue: 2 len: 41 tx.options 0x04
11:51:18:675 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:18:675 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:18:693 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:18:744 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:18:794 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:18:844 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:18:895 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:18:943 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:18:993 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:044 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:095 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:144 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:193 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:244 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:293 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:345 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:393 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:443 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:493 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:546 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:595 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:644 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:693 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:744 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:744 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:745 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:793 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:845 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:895 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:944 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:19:993 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:044 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:093 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:143 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:193 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:244 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:294 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:345 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:393 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:444 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:493 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:544 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:593 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:646 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:695 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:745 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:794 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:844 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:845 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:845 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:893 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:944 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:20:993 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:21:044 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:21:093 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:21:144 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:21:193 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:21:243 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:21:293 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:21:344 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:21:393 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:21:444 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:21:493 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:21:544 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:21:553 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:21:562    asdu (length: 6): 115E006B0000
11:51:21:562 Delay APS request id: 115 to 0x967B, profile: 0x0104 cluster: 0x0300 node already has busy 2
11:51:22:687 APS-DATA.confirm id: 115, status: 0x00 SUCCESS
11:51:22:687 APS-DATA.confirm request id: 115 -> erase from queue
11:51:22:724 aps request id: 115 finished, erase from queue
11:52:59:115 APS-DATA.confirm id: 108, status: 0x00 SUCCESS

11:55:09:923 APS-DATA.request id: 115, addrmode: 0x03, addr: 0x70AC08FFFEC7xxxx, profile: 0x0000, cluster: 0x0031, ep: 0x00 -> 0x00 queue: 1 len: 2 tx.options 0x00
11:55:10:087 APS-DATA.confirm id: 115, status: 0xE1 
11:55:10:088 unhandled APS-DATA.confirm id: 115 status 0xE1

In some cases the request do not have an impact on e.g. the light - it seems the request times out?

I already switched the zigbee chanal - no effect …

In general, I have not changed anything in the setup. The server was temporarily started in a different part of the house - but is now back in the same place where everything was already working fine. No new software / hardware or new devices have been added to the network.

Does anyone have any ideas for me where I can look further or what I can do to fix the problem?

Mimiix · June 2, 2024, 12:49pm

Looks like you have interference issues

APSDE-DATA.confirm: 0xE1

I recommend scanning for wifi networks and check if there’s overlaps with zigbee channels. Note that these are not the same numbers, I recommend reading up on Google.

Also, if you are not using a extension cable: you should use one.

dethon · June 2, 2024, 1:55pm

Many thanks for the hints.

I have added an extension cable and and optimized the channel again with the WLAN. For now it looks much more better. I will do some tests now.

For all those who are looking for documentation, here is a helpful link: ZigBee and Wi-Fi Coexistence | MetaGeek.
on This page is also a good overview picture: https://support.metageek.com/hc/en-us/article_attachments/115017048148/ZigBee_Channels.pdf

@Mimiix: maybe you can help me with my question. I have changed the Zigbee Knaal via Phoscon. However, this does not seem to consider a restart or recreation of the container. Is there another way to set the channel?

And what is the reason for using the extension cable? Indifference to the host system?

Mimiix · June 2, 2024, 3:01pm

You should change channel in deconz.

Click leave network.
Click edit - network settings
Change the channel and save
Click join network.

That should do it. However, due to the interference it is maybe not possible to send the message to devices so they change channel too.

The extension cable is because of usb interference.

There is a bug in the Intel usb 3.0 interface which causes interference on the 2.4ghz band.

The cable helps to gain distance between the USB port and the Conbee.