Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

No response on commands - error APSDE-DATA.confirm: 0xA7 #2245

Closed
MikaelHoogen opened this issue Dec 26, 2019 · 17 comments
Closed

No response on commands - error APSDE-DATA.confirm: 0xA7 #2245

MikaelHoogen opened this issue Dec 26, 2019 · 17 comments
Labels

Comments

@MikaelHoogen
Copy link

MikaelHoogen commented Dec 26, 2019

Update 1:
Yesterday I notised that TRADFRI bulb E27 WS opal 1000lm seems to be the cause. When light nodes are routed through a TRADFRI bulb E27 WS opal 1000lm the problems occur. I have powered of my two TRADFRI bulb E27 WS opal 1000lm and after that things are working.

I have two networks with exactly the same behavour. The common ground are TRADFRI bulb E27 WS opal 1000lm.

The problem seems to be related to TRADFRI bulb E27 WS opal 1000lm. Can I get any feedback and can I provide any information to help out a solution?


I'm having some serious bugs in my setup:
Hassio deConz - lastest version
Conbee connected to USB extension cable - latest firmware

Some light nodes in my network stop responding on commands to them. The manufacturer doesn't seem to matter. It's affecting my IKEA, Philips and Osram nodes. One very intressesting fact is that if I send a group command to the node it responds perfectly. I cannot get a grip on the problem. An (for me) strange example :
If I send i read Attributes command the node is blinking blue as if it responds, but nothing happens. Even if I unplug the power (!?) the node is blinking blue if I send the read attributes command.
ScreenClip

To me it seems like there is some kind of bug. Here are I screenshot of the node when it's unplugged (still acting as it is there):
ScreenClip  2

@ebaauw
Copy link
Collaborator

ebaauw commented Dec 26, 2019

One very intressesting fact is that if I send a group command to the node it responds perfectly.

The gateway has lost the route to the node, so it cannot send unicast commands (generated by light commands). The node is still on the network, and responds normally to broadcasts (generated by group commands). Note that routes are asymmetric. Typically, reports from the node will reach the gateway normally as well.

Not sure why the gateway loses the route. It seems worse with multi-manufacturer networks - different manufacturers use different route discovery methods. What RaspBee/ConBee firmware are you on? What deCONZ version are you on?

The usual workaround is to power-cycle the node; the Device Announcement message that the device sends on boot seems to reset the route discovery.

If I send i read Attributes command the node is blinking blue as if it responds

The node blinks blue when sending or receiving traffic. It blinks red on a timeout or error sending traffic. Typically behaviour querying a powered-down device is blue blinking when sending the command, followed by red blinking, a while later.

@MikaelHoogen
Copy link
Author

One very intressesting fact is that if I send a group command to the node it responds perfectly.

The gateway has lost the route to the node, so it cannot send unicast commands (generated by light commands). The node is still on the network, and responds normally to broadcasts (generated by group commands). Note that routes are asymmetric. Typically, reports from the node will reach the gateway normally as well.

Not sure why the gateway loses the route. It seems worse with multi-manufacturer networks - different manufacturers use different route discovery methods. What RaspBee/ConBee firmware are you on? What deCONZ version are you on?
ScreenClip  3

The usual workaround is to power-cycle the node; the Device Announcement message that the device sends on boot seems to reset the route discovery.

If I power-cycle the node It seems to get the Device Announcement. But the problem is still there.

If I send i read Attributes command the node is blinking blue as if it responds

The node blinks blue when sending or receiving traffic. It blinks red on a timeout or error sending traffic. Typically behaviour querying a powered-down device is blue blinking when sending the command, followed by red blinking, a while later.

I see. But it doesn't blink red. Just blue. It's acting like it's there even when it's unplugged. Waited for 5 minutes now, no red blink. Can I see the traffic in some kind of log?

@ebaauw
Copy link
Collaborator

ebaauw commented Dec 26, 2019

Can I see the traffic in some kind of log?

Yes. Start deCONZ with --dbg-info=2 --dbg-aps=2 --dbg-zcl=1 --dbg-zdp=1 --dbg-http=1 --dbg-error=1. That probably more way logging than you care for, so you need to experiment a bit with the parameters to see what level you want.

deCONZ just writes to standard output and/or standard error. To which file this is redirected depends on how you start deCONZ. I'm sorry, I don't know Hassio.

@MikaelHoogen
Copy link
Author

15:58:28:153 add task 5745 type 19 to 0x00158D00017D4431 cluster 0x0006 req.id 236
15:58:28:153 Poll APS request 236 to 0x00158D00017D4431 cluster: 0x0006
15:58:28:246 APS-DATA.request id: 236, addrmode: 0x03, addr: 0x00158d00017d4431, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x01 queue: 4 len: 5 tx.options 0x00
15:58:28:338 Poll APS confirm 236 status: 0x00
15:58:28:338 Erase task req-id: 236, type: 19 zcl seqno: 211 send time 0, profileId: 0x0104, clusterId: 0x0006
15:58:28:339 APS-DATA.confirm id: 236, status: 0x00 SUCCESS
15:58:28:339 APS-DATA.confirm request id: 236 -> erase from queue
15:58:28:370 APS-DATA.indication srcAddr: 0x0cb7, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 151, rssi: -72
15:58:28:370 asdu: 18d3010000001001
15:58:28:371 APS-DATA.request id: 236 erase from queue
15:58:28:371 Node data 0x00158d00017d4431 profileId: 0x0104, clusterId: 0x0006
15:58:28:372 update ZCL value 0x0006/0x0000 for 0x00158D00017D4431 after 76 s
15:58:28:546 read attributes of 0x00158D00017D4431 cluster: 0x0008: [ 15:58:28:547 0x0000 15:58:28:547 ]
15:58:28:547 add task 5749 type 19 to 0x00158D00017D4431 cluster 0x0008 req.id 243
15:58:28:548 Poll APS request 243 to 0x00158D00017D4431 cluster: 0x0008
15:58:28:548 APS-DATA.request id: 243, addrmode: 0x03, addr: 0x00158d00017d4431, profile: 0x0104, cluster: 0x0008, ep: 0x01 -> 0x01 queue: 4 len: 5 tx.options 0x00
15:58:28:641 Poll APS confirm 243 status: 0x00
15:58:28:642 Erase task req-id: 243, type: 19 zcl seqno: 212 send time 0, profileId: 0x0104, clusterId: 0x0008
15:58:28:642 APS-DATA.confirm id: 243, status: 0x00 SUCCESS
15:58:28:642 APS-DATA.confirm request id: 243 -> erase from queue
15:58:28:644 read attributes of 0x00158D00017D4431 cluster: 0x0300: [ 15:58:28:644 0x0007 15:58:28:644 0x0008 15:58:28:646 ]
15:58:28:646 add task 5750 type 19 to 0x00158D00017D4431 cluster 0x0300 req.id 244
15:58:28:646 Poll APS request 244 to 0x00158D00017D4431 cluster: 0x0300
15:58:28:647 APS-DATA.request id: 244, addrmode: 0x03, addr: 0x00158d00017d4431, profile: 0x0104, cluster: 0x0300, ep: 0x01 -> 0x01 queue: 5 len: 7 tx.options 0x00
15:58:28:674 APS-DATA.indication srcAddr: 0x0cb7, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0008, lqi: 159, rssi: -71
15:58:28:674 asdu: 18d40100000020fe
15:58:28:674 APS-DATA.request id: 243 erase from queue
15:58:28:675 Node data 0x00158d00017d4431 profileId: 0x0104, clusterId: 0x0008
15:58:28:675 update ZCL value 0x0008/0x0000 for 0x00158D00017D4431 after 76 s
15:58:28:738 Poll APS confirm 244 status: 0x00
15:58:28:739 Erase task req-id: 244, type: 19 zcl seqno: 213 send time 0, profileId: 0x0104, clusterId: 0x0300
15:58:28:739 APS-DATA.confirm id: 244, status: 0x00 SUCCESS
15:58:28:739 APS-DATA.confirm request id: 244 -> erase from queue
15:58:28:777 aps request id: 244 finished, erase from queue
15:58:28:785 APS-DATA.indication srcAddr: 0x0cb7, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0300, lqi: 151, rssi: -72
15:58:28:785 asdu: 18d5010700002132010800003002
15:58:28:786 Node data 0x00158d00017d4431 profileId: 0x0104, clusterId: 0x0300
15:58:28:786 update ZCL value 0x0300/0x0007 for 0x00158D00017D4431 after 76 s
15:58:28:786 update ZCL value 0x0300/0x0008 for 0x00158D00017D4431 after 76 s
15:58:29:045 Daylight now: sunsetEnd, status: 200, daylight: 0, dark: 1
15:58:29:338 APS-DATA.request id: 254, addrmode: 0x03, addr: 0x00158d00017d4431, profile: 0x0000, cluster: 0x0031, ep: 0x00 -> 0x00 queue: 4 len: 2 tx.options 0x00
15:58:29:371 poll node 00:0d:6f:ff:fe:48:4f:5c-01
15:58:29:371 Poll light node Hall spotlight 2
15:58:29:410 APS-DATA.confirm id: 254, status: 0x00 SUCCESS
15:58:29:411 APS-DATA.confirm request id: 254 -> confirmed, timeout 1577372309
15:58:29:424 read attributes of 0x000D6FFFFE484F5C cluster: 0x0006: [ 15:58:29:424 0x0000 15:58:29:424 ]
15:58:29:424 add task 5756 type 19 to 0x000D6FFFFE484F5C cluster 0x0006 req.id 255
15:58:29:425 Poll APS request 255 to 0x000D6FFFFE484F5C cluster: 0x0006
15:58:29:446 APS-DATA.request id: 255, addrmode: 0x03, addr: 0x000d6ffffe484f5c, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x01 queue: 5 len: 5 tx.options 0x00
15:58:29:474 APS-DATA.indication srcAddr: 0x0cb7, srcEp: 0x00 dstAddrMode: 2, profile: 0x0000, cluster: 0x8031, lqi: 151, rssi: -72
15:58:29:475 asdu: 95000500028aaf03ffff2e21000bc003feff6f0d00a9ca250201578aaf03ffff2e2100b1f70408018817005eb125020137
15:58:29:475 APS-DATA.indication request id: 254 -> finished
15:58:29:475 APS-DATA.request id: 254 erase from queue
172.30.32.2 - - [26/Dec/2019:15:58:29 +0100] "GET /api/FB501ECCB6/sensors/new HTTP/1.1" 200 34 "http://192.168.0.146:8123/api/hassio_ingress/VjK-2Fqh9Dp73vU1xOL__0jc9IX9P_Gln9yn7jqwjMg/pwa/devices-lights.html?_v=bb47cdbc19c257e3000fdb8475aa456830e6df94,11,4,15&gwid=00212EFFFF03AF8A" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.108 Safari/537.36 OPR/65.0.3467.78"
15:58:29:817 APS-DATA.request id: 3, addrmode: 0x03, addr: 0x00158d00017d4431, profile: 0x0000, cluster: 0x0031, ep: 0x00 -> 0x00 queue: 5 len: 2 tx.options 0x00
15:58:29:890 APS-DATA.confirm id: 3, status: 0x00 SUCCESS
15:58:29:890 APS-DATA.confirm request id: 3 -> confirmed, timeout 1577372309
15:58:29:955 APS-DATA.indication srcAddr: 0x0cb7, srcEp: 0x00 dstAddrMode: 2, profile: 0x0000, cluster: 0x8031, lqi: 151, rssi: -72
15:58:29:955 asdu: 96000502028aaf03ffff2e2100c9119c01008d15008f712502014b8aaf03ffff2e210075ad4203008d1500688b25020134
15:58:29:955 APS-DATA.indication request id: 3 -> finished
15:58:29:955 APS-DATA.request id: 3 erase from queue
15:58:29:987 APS-DATA.indication srcAddr: 0xcaa9, srcEp: 0x01 dstAddrMode: 1, profile: 0x0104, cluster: 0x0000, lqi: 207, rssi: -65
15:58:29:989 asdu: 08520a00404207322e302e303232
15:58:29:990 Node data 0x000d6ffffe03c00b profileId: 0x0104, clusterId: 0x0000
15:58:29:990 update ZCL value 0x0000/0x4000 for 0x000D6FFFFE03C00B after 691 s
15:58:29:990 ZCL attribute report 0x000D6FFFFE03C00B for cluster 0x0000, ep 0x01
15:58:29:990 payload: 00404207322e302e303232
15:58:29:990 APS-DATA.request id: 7, addrmode: 0x02, addr: 0xcaa9, profile: 0x0104, cluster: 0x0000, ep: 0x1D -> 0x01 queue: 5 len: 5 tx.options 0x00
15:58:30:082 APS-DATA.indication srcAddr: 0xcaa9, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0000, lqi: 255, rssi: -27
15:58:30:082 asdu: 08520a00404207322e302e303232
15:58:30:082 Node data 0x000d6ffffe03c00b profileId: 0x0104, clusterId: 0x0000
15:58:30:083 update ZCL value 0x0000/0x4000 for 0x000D6FFFFE03C00B after 0 s
15:58:30:083 ZCL attribute report 0x000D6FFFFE03C00B for cluster 0x0000, ep 0x01
15:58:30:083 payload: 00404207322e302e303232
15:58:30:083 APS-DATA.request id: 11, addrmode: 0x02, addr: 0xcaa9, profile: 0x0104, cluster: 0x0000, ep: 0x01 -> 0x01 queue: 6 len: 5 tx.options 0x00
15:58:30:098 APS-DATA.confirm id: 7, status: 0xA6 INVALID_PARAMETER
15:58:30:162 APS-DATA.confirm id: 11, status: 0x00 SUCCESS
15:58:30:162 APS-DATA.confirm request id: 11 -> erase from queue
15:58:30:218 aps request id: 11 finished, erase from queue
15:58:30:297 APS-DATA.request id: 14, addrmode: 0x03, addr: 0x00158d00017d4431, profile: 0x0000, cluster: 0x0031, ep: 0x00 -> 0x00 queue: 5 len: 2 tx.options 0x00
15:58:30:371 APS-DATA.confirm id: 14, status: 0x00 SUCCESS
15:58:30:371 APS-DATA.confirm request id: 14 -> confirmed, timeout 1577372310
15:58:30:435 APS-DATA.indication srcAddr: 0x0cb7, srcEp: 0x00 dstAddrMode: 2, profile: 0x0000, cluster: 0x8031, lqi: 143, rssi: -73
15:58:30:436 asdu: 98000504018aaf03ffff2e2100828f330401881700814825020138
15:58:30:436 APS-DATA.indication request id: 14 -> finished
15:58:30:436 APS-DATA.request id: 14 erase from queue
15:58:30:437 void deCONZ::zmNode::setFetched(deCONZ::RequestId, bool) fetched item: 8, node: 0x0CB7
15:58:31:064 APS-DATA.confirm id: 206, status: 0x00 SUCCESS
15:58:31:065 APS-DATA.confirm request id: 206 -> confirmed, timeout 1577372306
15:58:31:091 0x000D6FFFFE4507C2 error APSDE-DATA.confirm: 0xA7 on task

I get the error APSDE-DATA.confirm: 0xA7 on task all the time. I don't understand which telegram the failed ack belongs to.

@MikaelHoogen
Copy link
Author

16:24:21:646 APS-DATA.request id: 139, addrmode: 0x03, addr: 0x001788010496197e, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x0B queue: 3 len: 5 tx.options 0x00
16:24:22:066 aps request id: 98 prf: 0x0000 cl: 0x0005 timeout (confirmed: 1) to 0x7CB03EAA00B05A3F (0x1C16)
16:24:22:146 aps request id: 98 finished, erase from queue
16:24:27:026 aps request id: 156 prf: 0x0000 cl: 0x0000 timeout (confirmed: 1) to 0x000D6FFFFE484F5C (0xFFFD)
16:24:27:105 aps request id: 156 finished, erase from queue
16:24:29:716 0x001788010496197E error APSDE-DATA.confirm: 0xA7 on task
16:24:29:716 APS-DATA.confirm id: 139, status: 0xA7 NO_ACK
16:24:29:716 max transmit errors for node 0x001788010496197E, last seen by neighbors 117 s

A bit less cluttered.

@MikaelHoogen
Copy link
Author

16:35:19:540 APS-DATA.indication srcAddr: 0xaa76, srcEp: 0x01 dstAddrMode: 1, profile: 0x0104, cluster: 0x0000, lqi: 207, rssi: -65
16:35:19:541 ZCL attribute report 0x000D6FFFFE9CD6D1 for cluster 0x0000, ep 0x01
16:35:19:541 APS-DATA.request id: 68, addrmode: 0x02, addr: 0xaa76, profile: 0x0104, cluster: 0x0000, ep: 0x1D -> 0x01 queue: 1 len: 5 tx.options 0x00
16:35:19:572 APS-DATA.indication srcAddr: 0xaa76, srcEp: 0x01 dstAddrMode: 1, profile: 0x0104, cluster: 0x0000, lqi: 199, rssi: -66
16:35:19:573 ZCL attribute report 0x000D6FFFFE9CD6D1 for cluster 0x0000, ep 0x01
16:35:19:573 APS-DATA.request id: 72, addrmode: 0x02, addr: 0xaa76, profile: 0x0104, cluster: 0x0000, ep: 0x1D -> 0x01 queue: 2 len: 5 tx.options 0x00
16:35:19:604 APS-DATA.indication srcAddr: 0xaa76, srcEp: 0x01 dstAddrMode: 1, profile: 0x0104, cluster: 0x0000, lqi: 207, rssi: -65
16:35:19:605 ZCL attribute report 0x000D6FFFFE9CD6D1 for cluster 0x0000, ep 0x01
16:35:19:605 APS-DATA.request id: 75, addrmode: 0x02, addr: 0xaa76, profile: 0x0104, cluster: 0x0000, ep: 0x1D -> 0x01 queue: 3 len: 5 tx.options 0x00
16:35:19:716 APS-DATA.indication srcAddr: 0xaa76, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0000, lqi: 207, rssi: -65
16:35:19:717 ZCL attribute report 0x000D6FFFFE9CD6D1 for cluster 0x0000, ep 0x01
16:35:19:717 APS-DATA.request id: 78, addrmode: 0x02, addr: 0xaa76, profile: 0x0104, cluster: 0x0000, ep: 0x01 -> 0x01 queue: 4 len: 5 tx.options 0x00
16:35:19:732 APS-DATA.confirm id: 68, status: 0xA6 INVALID_PARAMETER
16:35:19:769 Mgmt_Lqi_req zdpSeq: 12 to 0x001788010496196F start index 10
16:35:19:770 APS-DATA.request id: 79, addrmode: 0x03, addr: 0x001788010496196f, profile: 0x0000, cluster: 0x0031, ep: 0x00 -> 0x00 queue: 4 len: 2 tx.options 0x00
16:35:19:845 APS-DATA.confirm id: 72, status: 0xA6 INVALID_PARAMETER
16:35:19:860 APS-DATA.confirm id: 75, status: 0xA6 INVALID_PARAMETER

0xA6 INVALID_PARAMETER
What does that mean?

@ebaauw
Copy link
Collaborator

ebaauw commented Dec 26, 2019

@MikaelHoogen
Copy link
Author

MikaelHoogen commented Dec 27, 2019

I have a theory

I have another network with the same behavour. The common ground is an IKEA bulb close to the gateway that other bulbs are routed trough. I have now powered off the IKEA bulb and things are starting to work again. There must be some kind of bug when routing trough this kind of bulb.

ScreenClip  4

@ebaauw
Copy link
Collaborator

ebaauw commented Dec 27, 2019

I’m afraid the details are lost on me, but different manufacturers seem to use different methods for route discovery. Notably, IKEA Trådfri works very differently from Hue and dresden elektronik. When the first Trådfri bulbs came out, they spend a lot of time and effort trying to handle them the right way, resulting in many different versions of the RaspBee/ConBee firmware and the deCONZ core program. There still seem to be some residual issues, especially on larger, networks (> ~22 routers from multiple manufacturers).

@MikaelHoogen
Copy link
Author

I’m afraid the details are lost on me, but different manufacturers seem to use different methods for route discovery. Notably, IKEA Trådfri works very differently from Hue and dresden elektronik. When the first Trådfri bulbs came out, they spend a lot of time and effort trying to handle them the right way, resulting in many different versions of the RaspBee/ConBee firmware and the deCONZ core program. There still seem to be some residual issues, especially on larger, networks (> ~22 routers from multiple manufacturers).

Yeah it seems like mixing manufactorers cause problems. But I have exactly the same issue on the smaller network. In my opinion it should be a warning when you buy a conbee about this. I don't like the fact that there is a problem and no solution is at hand. If i knew this before I bought all the bulbs it would have been a different story.

Skärmklipp tran

@MikaelHoogen
Copy link
Author

MikaelHoogen commented Dec 27, 2019

Okey. I had one more TRADFRI bulb E27 WS opal 1000lm in the big network. So the thing is that it caused problems even to another IKEA bulb (hall på byrå) when routed through the 1000lm (kök kösbord). When I unlugged the 1000lm and (hall på byrå) changed route it started to respond directly.

So my conclusion (for now) is that TRADFRI bulb E27 WS opal 1000lm is causing problems. Even to other IKEA bulbs.
Skärmklipp tra

@ginkel
Copy link

ginkel commented Dec 27, 2019

ScreenClip 4

The firmware on that bulb seems a little old (just from memory based on the versions my IKEA bulbs show). Have you tried updating it?

@MikaelHoogen
Copy link
Author

ScreenClip 4

The firmware on that bulb seems a little old (just from memory based on the versions my IKEA bulbs show). Have you tried updating it?

http://fw.ota.homesmart.ikea.net/feed/version_info.json

If i'm not misstaken 2.0.022 is the lastest for that bulb acording to the link?

@PeterRemnemark
Copy link

I've similar situation as you, have not nail down to if the issue is the same as you might point out that a bulb is the cause of "routing" problem or not. Today I got one "old timer bulb" to be not responding to any action, even after a power cycle...

#2256 (comment)

@MikaelHoogen
Copy link
Author

I've similar situation as you, have not nail down to if the issue is the same as you might point out that a bulb is the cause of "routing" problem or not. Today I got one "old timer bulb" to be not responding to any action, even after a power cycle...

#2256 (comment)

Do the node have a direct link to the gateway if you look at the mesh network in deconz?

@PeterRemnemark
Copy link

I've similar situation as you, have not nail down to if the issue is the same as you might point out that a bulb is the cause of "routing" problem or not. Today I got one "old timer bulb" to be not responding to any action, even after a power cycle...
#2256 (comment)

Do the node have a direct link to the gateway if you look at the mesh network in deconz?

I do not think so at that time. I see now after a reboot of Deconz that most bulbs that is active do have a direct link and a mesh to some other. It is too messy to really see if all have it or not, but when I dragged the "coordinator" it looked that all my routers had a link attached. I doubt that all has, since some of them are too far away from the coordinator to actual have a direct link.

@stale
Copy link

stale bot commented May 1, 2020

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.

@stale stale bot added the stale label May 1, 2020
@stale stale bot closed this as completed May 9, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

4 participants