Unreachable lumi.ctrl_neutral2

I've got a lumi.ctrl_neutral2 switch (end device) which cannot be reached from deCONZ, even though it's active on the network. The switch seems stuck in a loop, where it requests the attributes of the Time cluster from the coordinator, but doesn't receive any answer. After a couple of times, it gives up, leaves and rejoins the network, connecting to a different parent. deCONZ insists that the node is known by 0 neighbours. Sending a command to the switch results in error 0xA7 - no clue what that means?

Below the deCONZ log (filtered on the switch's MAC address) and the Wireshark dump (filtered on the switch's NWK address):

Aug 27 18:58:06 pi2 deCONZ[4989]: 18:58:05:183 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 231, rssi: -62
Aug 27 18:58:06 pi2 deCONZ[4989]: 18:58:05:527 add task 378160 type 21 to 0x00158D000239145E cluster 0x0004 req.id 129
Aug 27 18:58:06 pi2 deCONZ[4989]: 18:58:05:528 APS-DATA.request id: 129, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0004, ep: 0x03 queue: 0 len: 4
Aug 27 18:58:24 pi2 deCONZ[4989]: 18:58:22:082 Node 0x00158D000239145E is known by 0 neighbors, last seen 16 s
Aug 27 18:59:08 pi2 deCONZ[4989]: 18:59:04:626 Node 0x00158D000239145E is known by 0 neighbors, last seen 59 s
Aug 27 18:59:08 pi2 deCONZ[4989]: 18:59:07:186 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 223, rssi: -63
Aug 27 18:59:49 pi2 deCONZ[4989]: 18:59:48:571 Node 0x00158D000239145E is known by 0 neighbors, last seen 41 s
Aug 27 19:00:14 pi2 deCONZ[4989]: 19:00:09:301 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 223, rssi: -63
Aug 27 19:00:39 pi2 deCONZ[4989]: 19:00:36:883 Node 0x00158D000239145E is known by 0 neighbors, last seen 27 s
Aug 27 19:00:39 pi2 deCONZ[4989]: 19:00:38:974 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0000, cluster: 0x0013, lqi: 191, rssi: -67
Aug 27 19:00:39 pi2 deCONZ[4989]: 19:00:38:975 DeviceAnnce of LightNode: 0x00158d000239145e Permit Join: 0
Aug 27 19:00:39 pi2 deCONZ[4989]: 19:00:38:975 DeviceAnnce of SensorNode: 0x00158D000239145E [1]
Aug 27 19:00:39 pi2 deCONZ[4989]: 19:00:38:975 DeviceAnnce of SensorNode: 0x00158D000239145E [1]
Aug 27 19:00:39 pi2 deCONZ[4989]: 19:00:38:975 device announce 0x00158D000239145E (0x7F15) mac capabilities 0x84
Aug 27 19:00:39 pi2 deCONZ[4989]: 19:00:38:975 set fast probe address to 0x00158D000239145E (0x7F15)
Aug 27 19:00:46 pi2 deCONZ[4989]: 19:00:45:276 add task 378937 type 21 to 0x00158D000239145E cluster 0x0004 req.id 129
Aug 27 19:00:46 pi2 deCONZ[4989]: 19:00:45:276 APS-DATA.request id: 129, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0004, ep: 0x02 queue: 2 len: 4
Aug 27 19:00:46 pi2 deCONZ[4989]: 19:00:46:181 add task 378941 type 21 to 0x00158D000239145E cluster 0x0004 req.id 133
Aug 27 19:00:46 pi2 deCONZ[4989]: 19:00:46:181 APS-DATA.request id: 133, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0004, ep: 0x03 queue: 2 len: 4
Aug 27 19:01:13 pi2 deCONZ[4989]: 19:01:11:215 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 207, rssi: -65
Aug 27 19:01:25 pi2 deCONZ[4989]: 19:01:23:419 Node 0x00158D000239145E is known by 0 neighbors, last seen 12 s
Aug 27 19:02:09 pi2 deCONZ[4989]: 19:02:07:354 Node 0x00158D000239145E is known by 0 neighbors, last seen 56 s
Aug 27 19:02:16 pi2 deCONZ[4989]: 19:02:13:228 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 199, rssi: -66
Aug 27 19:02:24 pi2 deCONZ[4989]: 19:02:24:107 add task 379420 type 14 to 0x00158D000239145E cluster 0x0006 req.id 121
Aug 27 19:02:25 pi2 deCONZ[4989]: 19:02:24:109 APS-DATA.request id: 121, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0006, ep: 0x02 queue: 2 len: 3
Aug 27 19:02:30 pi2 deCONZ[4989]: 19:02:29:052 0x00158D000239145E error APSDE-DATA.confirm: 0xA7 on task
Aug 27 19:02:51 pi2 deCONZ[4989]: 19:02:51:154 Node 0x00158D000239145E is known by 0 neighbors, last seen 37 s
Aug 27 19:03:17 pi2 deCONZ[4989]: 19:03:15:254 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 191, rssi: -67
Aug 27 19:03:41 pi2 deCONZ[4989]: 19:03:37:882 Node 0x00158D000239145E is known by 0 neighbors, last seen 22 s
Aug 27 19:04:20 pi2 deCONZ[4989]: 19:04:17:282 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 255, rssi: -53
Aug 27 19:04:28 pi2 deCONZ[4989]: 19:04:24:650 Node 0x00158D000239145E is known by 0 neighbors, last seen 7 s
Aug 27 19:04:40 pi2 deCONZ[4989]: 19:04:39:276 add task 380084 type 21 to 0x00158D000239145E cluster 0x0004 req.id 214
Aug 27 19:04:40 pi2 deCONZ[4989]: 19:04:39:277 APS-DATA.request id: 214, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0004, ep: 0x02 queue: 1 len: 4
Aug 27 19:05:14 pi2 deCONZ[4989]: 19:05:08:650 Node 0x00158D000239145E is known by 0 neighbors, last seen 51 s
Aug 27 19:05:54 pi2 deCONZ[4989]: 19:05:52:315 Node 0x00158D000239145E is known by 0 neighbors, last seen 95 s
Aug 27 19:06:03 pi2 deCONZ[4989]: 19:06:01:408 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0000, cluster: 0x0013, lqi: 191, rssi: -67
Aug 27 19:06:03 pi2 deCONZ[4989]: 19:06:01:409 DeviceAnnce of LightNode: 0x00158d000239145e Permit Join: 0
Aug 27 19:06:03 pi2 deCONZ[4989]: 19:06:01:409 DeviceAnnce of SensorNode: 0x00158D000239145E [1]
Aug 27 19:06:03 pi2 deCONZ[4989]: 19:06:01:409 DeviceAnnce of SensorNode: 0x00158D000239145E [1]
Aug 27 19:06:03 pi2 deCONZ[4989]: 19:06:01:410 device announce 0x00158D000239145E (0x7F15) mac capabilities 0x84
Aug 27 19:06:03 pi2 deCONZ[4989]: 19:06:01:410 set fast probe address to 0x00158D000239145E (0x7F15)
Aug 27 19:06:03 pi2 deCONZ[4989]: 19:06:03:277 read attributes of 0x00158D000239145E cluster: 0x0000: [ 19:06:03:277 0x4000 19:06:03:277 ]
Aug 27 19:06:03 pi2 deCONZ[4989]: 19:06:03:277 add task 380490 type 19 to 0x00158D000239145E cluster 0x0000 req.id 113
Aug 27 19:06:03 pi2 deCONZ[4989]: 19:06:03:277 add task 380491 type 21 to 0x00158D000239145E cluster 0x0004 req.id 114
Aug 27 19:06:03 pi2 deCONZ[4989]: 19:06:03:277 APS-DATA.request id: 113, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0000, ep: 0x02 queue: 0 len: 5
Aug 27 19:06:03 pi2 deCONZ[4989]: 19:06:03:327 delay sending request 114 dt 0 ms to 0x00158D000239145E, cluster 0x0004
Aug 27 19:06:03 pi2 deCONZ[4989]: 19:06:03:327 delay sending request 114 cluster 0x0004 to 0x00158d000239145e
Aug 27 19:06:06 pi2 deCONZ[4989]: 19:06:03:403 APS-DATA.request id: 114, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0004, ep: 0x02 queue: 1 len: 4
Aug 27 19:06:06 pi2 deCONZ[4989]: 19:06:04:027 read attributes of 0x00158D000239145E cluster: 0x0000: [ 19:06:04:027 0x4000 19:06:04:027 ]
Aug 27 19:06:06 pi2 deCONZ[4989]: 19:06:04:027 add task 380495 type 19 to 0x00158D000239145E cluster 0x0000 req.id 118
Aug 27 19:06:06 pi2 deCONZ[4989]: 19:06:04:027 add task 380496 type 21 to 0x00158D000239145E cluster 0x0004 req.id 119
Aug 27 19:06:06 pi2 deCONZ[4989]: 19:06:04:027 APS-DATA.request id: 118, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0000, ep: 0x03 queue: 0 len: 5
Aug 27 19:06:06 pi2 deCONZ[4989]: 19:06:04:029 delay sending request 119 dt 0 ms to 0x00158D000239145E, cluster 0x0004
Aug 27 19:06:06 pi2 deCONZ[4989]: 19:06:04:029 delay sending request 119 cluster 0x0004 to 0x00158d000239145e
Aug 27 19:06:06 pi2 deCONZ[4989]: 19:06:04:126 delay sending request 119 dt 0 ms to 0x00158D000239145E, cluster 0x0004
Aug 27 19:06:06 pi2 deCONZ[4989]: 19:06:04:126 delay sending request 119 cluster 0x0004 to 0x00158d000239145e
Aug 27 19:06:06 pi2 deCONZ[4989]: 19:06:04:161 APS-DATA.request id: 119, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0004, ep: 0x03 queue: 1 len: 4

wireshark.pcapng.zip

And somehow that jinxed it. While posting the previous message, the switch spontaneously became reachable. Unfortunately, I just turned off the sniffer.

Aug 27 19:06:22 pi2 deCONZ[4989]: 19:06:21:273 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 255, rssi: -58
Aug 27 19:06:38 pi2 deCONZ[4989]: 19:06:35:738 Node 0x00158D000239145E is known by 0 neighbors, last seen 14 s
Aug 27 19:07:22 pi2 deCONZ[4989]: 19:07:21:683 Node 0x00158D000239145E is known by 0 neighbors, last seen 60 s
Aug 27 19:07:42 pi2 deCONZ[4989]: 19:07:40:661 add task 380975 type 21 to 0x00158D000239145E cluster 0x0004 req.id 111
Aug 27 19:07:42 pi2 deCONZ[4989]: 19:07:40:661 APS-DATA.request id: 111, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0004, ep: 0x02 queue: 0 len: 4
Aug 27 19:08:12 pi2 deCONZ[4989]: 19:08:08:034 Node 0x00158D000239145E is known by 0 neighbors, last seen 106 s
Aug 27 19:08:29 pi2 deCONZ[4989]: 19:08:25:568 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 255, rssi: -52
Aug 27 19:08:52 pi2 deCONZ[4989]: 19:08:52:434 Node 0x00158D000239145E is known by 0 neighbors, last seen 26 s
Aug 27 19:09:36 pi2 deCONZ[4989]: 19:09:27:603 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 159, rssi: -71
Aug 27 19:09:36 pi2 deCONZ[4989]: 19:09:35:579 Node 0x00158D000239145E is known by 0 neighbors, last seen 7 s
Aug 27 19:10:21 pi2 deCONZ[4989]: 19:10:20:235 Node 0x00158D000239145E is known by 0 neighbors, last seen 52 s
Aug 27 19:10:35 pi2 deCONZ[4989]: 19:10:29:394 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 159, rssi: -71
Aug 27 19:11:10 pi2 deCONZ[4989]: 19:11:06:100 Node 0x00158D000239145E is known by 0 neighbors, last seen 36 s
Aug 27 19:11:25 pi2 deCONZ[4989]: 19:11:24:960 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0000, cluster: 0x0013, lqi: 167, rssi: -70
Aug 27 19:11:25 pi2 deCONZ[4989]: 19:11:24:960 DeviceAnnce of LightNode: 0x00158d000239145e Permit Join: 0
Aug 27 19:11:25 pi2 deCONZ[4989]: 19:11:24:960 DeviceAnnce of SensorNode: 0x00158D000239145E [1]
Aug 27 19:11:25 pi2 deCONZ[4989]: 19:11:24:961 DeviceAnnce of SensorNode: 0x00158D000239145E [1]
Aug 27 19:11:25 pi2 deCONZ[4989]: 19:11:24:961 device announce 0x00158D000239145E (0x7F15) mac capabilities 0x84
Aug 27 19:11:25 pi2 deCONZ[4989]: 19:11:24:961 set fast probe address to 0x00158D000239145E (0x7F15)
Aug 27 19:11:26 pi2 deCONZ[4989]: 19:11:25:278 read attributes of 0x00158D000239145E cluster: 0x0000: [ 19:11:25:278 0x4000 19:11:25:278 ]
Aug 27 19:11:26 pi2 deCONZ[4989]: 19:11:25:278 add task 382048 type 19 to 0x00158D000239145E cluster 0x0000 req.id 57
Aug 27 19:11:26 pi2 deCONZ[4989]: 19:11:25:278 add task 382049 type 21 to 0x00158D000239145E cluster 0x0004 req.id 58
Aug 27 19:11:26 pi2 deCONZ[4989]: 19:11:25:278 APS-DATA.request id: 57, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0000, ep: 0x02 queue: 4 len: 5
Aug 27 19:11:26 pi2 deCONZ[4989]: 19:11:25:326 delay sending request 58 dt 0 ms to 0x00158D000239145E, cluster 0x0004
Aug 27 19:11:26 pi2 deCONZ[4989]: 19:11:25:326 delay sending request 58 cluster 0x0004 to 0x00158d000239145e
Aug 27 19:11:26 pi2 deCONZ[4989]: 19:11:25:353 APS-DATA.request id: 58, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0004, ep: 0x02 queue: 5 len: 4
Aug 27 19:11:26 pi2 deCONZ[4989]: 19:11:26:028 read attributes of 0x00158D000239145E cluster: 0x0000: [ 19:11:26:028 0x4000 19:11:26:028 ]
Aug 27 19:11:26 pi2 deCONZ[4989]: 19:11:26:028 add task 382053 type 19 to 0x00158D000239145E cluster 0x0000 req.id 62
Aug 27 19:11:26 pi2 deCONZ[4989]: 19:11:26:028 add task 382054 type 21 to 0x00158D000239145E cluster 0x0004 req.id 63
Aug 27 19:11:26 pi2 deCONZ[4989]: 19:11:26:029 APS-DATA.request id: 62, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0000, ep: 0x03 queue: 3 len: 5
Aug 27 19:11:26 pi2 deCONZ[4989]: 19:11:26:031 delay sending request 63 dt 0 ms to 0x00158D000239145E, cluster 0x0004
Aug 27 19:11:26 pi2 deCONZ[4989]: 19:11:26:031 delay sending request 63 cluster 0x0004 to 0x00158d000239145e
Aug 27 19:11:30 pi2 deCONZ[4989]: 19:11:26:098 APS-DATA.request id: 63, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0004, ep: 0x03 queue: 4 len: 4
Aug 27 19:11:30 pi2 deCONZ[4989]: 19:11:27:221 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0004, lqi: 159, rssi: -71
Aug 27 19:11:30 pi2 deCONZ[4989]: 19:11:27:221 verified group capacity: 8 and group count: 0 of LightNode 0x00158d000239145e
Aug 27 19:11:30 pi2 deCONZ[4989]: 19:11:29:284 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0004, lqi: 159, rssi: -71
Aug 27 19:11:30 pi2 deCONZ[4989]: 19:11:29:284 verified group capacity: 8 and group count: 0 of LightNode 0x00158d000239145e
Aug 27 19:11:33 pi2 deCONZ[4989]: 19:11:31:359 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 159, rssi: -71
Aug 27 19:11:55 pi2 deCONZ[4989]: 19:11:50:682 Node 0x00158D000239145E is known by 0 neighbors, last seen 19 s
Aug 27 19:12:35 pi2 deCONZ[4989]: 19:12:33:377 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 159, rssi: -71
Aug 27 19:12:35 pi2 deCONZ[4989]: 19:12:33:378 APS-DATA.request id: 122, addr: 0x00158D000239145E profile: 0x0104, cluster: 0x0000, ep: 0x01 queue: 2 len: 5 (send, fast lane)
Aug 27 19:12:35 pi2 deCONZ[4989]: 19:12:33:436 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0000, lqi: 159, rssi: -71
Aug 27 19:12:35 pi2 deCONZ[4989]: 19:12:33:437 Node data 0x00158d000239145e profileId: 0x0104, clusterId: 0x0000
Aug 27 19:12:35 pi2 deCONZ[4989]: 19:12:33:438 Update Sensor 0x00158D000239145E Basic Cluster
Aug 27 19:12:35 pi2 deCONZ[4989]: 19:12:34:415 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0000, lqi: 159, rssi: -71
Aug 27 19:12:35 pi2 deCONZ[4989]: 19:12:34:416 Node data 0x00158d000239145e profileId: 0x0104, clusterId: 0x0000
Aug 27 19:12:35 pi2 deCONZ[4989]: 19:12:34:416 Update Sensor 0x00158D000239145E Basic Cluster
Aug 27 19:12:35 pi2 deCONZ[4989]: 19:12:35:099 Node 0x00158D000239145E is known by 0 neighbors, last seen 0 s
Aug 27 19:12:35 pi2 deCONZ[4989]: 19:12:35:455 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0000, lqi: 159, rssi: -71
Aug 27 19:12:35 pi2 deCONZ[4989]: 19:12:35:455 Node data 0x00158d000239145e profileId: 0x0104, clusterId: 0x0000
Aug 27 19:12:35 pi2 deCONZ[4989]: 19:12:35:455 Update Sensor 0x00158D000239145E Basic Cluster
Aug 27 19:12:35 pi2 deCONZ[4989]: 19:12:35:456 Update Sensor 0x00158D000239145E Basic Cluster
Aug 27 19:12:40 pi2 deCONZ[4989]: 19:12:36:489 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0000, lqi: 159, rssi: -71
Aug 27 19:12:40 pi2 deCONZ[4989]: 19:12:36:490 Node data 0x00158d000239145e profileId: 0x0104, clusterId: 0x0000
Aug 27 19:12:40 pi2 deCONZ[4989]: 19:12:36:490 Update Sensor 0x00158D000239145E Basic Cluster
Aug 27 19:12:40 pi2 deCONZ[4989]: 19:12:37:508 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 159, rssi: -71
Aug 27 19:12:40 pi2 deCONZ[4989]: 19:12:37:640 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 159, rssi: -71
Aug 27 19:12:40 pi2 deCONZ[4989]: 19:12:37:640 ZCL attribute report 0x00158D000239145E for cluster 0x0006, ep 0x02
Aug 27 19:12:40 pi2 deCONZ[4989]: 19:12:37:641 Node data 0x00158d000239145e profileId: 0x0104, clusterId: 0x0006
Aug 27 19:12:40 pi2 deCONZ[4989]: 19:12:37:641 update ZCL value 0x0006/0x0000 for 0x00158D000239145E after 70658 s
Aug 27 19:12:40 pi2 deCONZ[4989]: 19:12:37:641 update ZCL value 0x0006/0x0000 for 0x00158D000239145E after 0 s
Aug 27 19:12:47 pi2 deCONZ[4989]: 19:12:44:436 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 159, rssi: -71
Aug 27 19:12:47 pi2 deCONZ[4989]: 19:12:44:560 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 159, rssi: -71
Aug 27 19:12:47 pi2 deCONZ[4989]: 19:12:44:560 ZCL attribute report 0x00158D000239145E for cluster 0x0006, ep 0x02
Aug 27 19:12:47 pi2 deCONZ[4989]: 19:12:44:561 Node data 0x00158d000239145e profileId: 0x0104, clusterId: 0x0006
Aug 27 19:12:47 pi2 deCONZ[4989]: 19:12:44:561 update ZCL value 0x0006/0x0000 for 0x00158D000239145E after 6 s
Aug 27 19:12:47 pi2 deCONZ[4989]: 19:12:44:561 0x00158D000239145E onOff 1 --> 0
Aug 27 19:12:47 pi2 deCONZ[4989]: 19:12:44:561 update ZCL value 0x0006/0x0000 for 0x00158D000239145E after 6 s
Aug 27 19:13:19 pi2 deCONZ[4989]: 19:13:18:674 Node 0x00158D000239145E is known by 0 neighbors, last seen 34 s
Aug 27 19:13:36 pi2 deCONZ[4989]: 19:13:34:204 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 159, rssi: -71
Aug 27 19:14:06 pi2 deCONZ[4989]: 19:14:03:851 Node 0x00158D000239145E is known by 0 neighbors, last seen 29 s
Aug 27 19:14:06 pi2 deCONZ[4989]: 19:14:06:527 add task 382862 type 21 to 0x00158D000239145E cluster 0x0004 req.id 135
Aug 27 19:14:11 pi2 deCONZ[4989]: 19:14:06:527 APS-DATA.request id: 135, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0004, ep: 0x02 queue: 0 len: 4
Aug 27 19:14:11 pi2 deCONZ[4989]: 19:14:07:077 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0004, lqi: 159, rssi: -71
Aug 27 19:14:11 pi2 deCONZ[4989]: 19:14:07:077 verified group capacity: 8 and group count: 0 of LightNode 0x00158d000239145e
Aug 27 19:14:36 pi2 deCONZ[4989]: 19:14:36:015 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 159, rssi: -71
Aug 27 19:14:56 pi2 deCONZ[4989]: 19:14:51:546 Node 0x00158D000239145E is known by 0 neighbors, last seen 15 s
Aug 27 19:15:38 pi2 deCONZ[4989]: 19:15:34:522 Node 0x00158D000239145E is known by 0 neighbors, last seen 58 s
Aug 27 19:15:38 pi2 deCONZ[4989]: 19:15:38:034 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 159, rssi: -71
Aug 27 19:16:23 pi2 deCONZ[4989]: 19:16:18:834 Node 0x00158D000239145E is known by 0 neighbors, last seen 40 s
Aug 27 19:16:46 pi2 deCONZ[4989]: 19:16:40:076 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 159, rssi: -71
Aug 27 19:16:56 pi2 deCONZ[4989]: 19:16:54:674 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0000, lqi: 151, rssi: -72
Aug 27 19:16:56 pi2 deCONZ[4989]: 19:16:54:674 ZCL attribute report 0x00158D000239145E for cluster 0x0000, ep 0x01
Aug 27 19:16:56 pi2 deCONZ[4989]: 19:16:54:674 0x00158D000239145E extract Xiaomi special
Aug 27 19:16:56 pi2 deCONZ[4989]: 19:16:54:675 Node data 0x00158d000239145e profileId: 0x0104, clusterId: 0x0000
Aug 27 19:16:56 pi2 deCONZ[4989]: 19:16:54:675 Update Sensor 0x00158D000239145E Basic Cluster
Aug 27 19:17:03 pi2 deCONZ[4989]: 19:17:01:907 Node 0x00158D000239145E is known by 0 neighbors, last seen 7 s
Aug 27 19:17:26 pi2 deCONZ[4989]: 19:17:25:526 add task 383828 type 21 to 0x00158D000239145E cluster 0x0004 req.id 170
Aug 27 19:17:26 pi2 deCONZ[4989]: 19:17:25:526 APS-DATA.request id: 170, addrmode: 0x03, addr: 0x00158d000239145e, profile: 0x0104, cluster: 0x0004, ep: 0x02 queue: 0 len: 4
Aug 27 19:17:26 pi2 deCONZ[4989]: 19:17:26:604 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0004, lqi: 151, rssi: -72
Aug 27 19:17:29 pi2 deCONZ[4989]: 19:17:26:604 verified group capacity: 8 and group count: 0 of LightNode 0x00158d000239145e
Aug 27 19:17:46 pi2 deCONZ[4989]: 19:17:42:116 APS-DATA.indication srcAddr: 0x00158d000239145e, dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 151, rssi: -72
Aug 27 19:17:48 pi2 deCONZ[4989]: 19:17:46:810 Node 0x00158D000239145E is known by 0 neighbors, last seen 4 s

But after a while, it leaves and rejoins the network again, and becomes unreachable again?!

Double-checked my other lumi.ctrl_neutral2: it also sends the Read attributes command for the Time cluster to the coordinator, and it also leaves/re-joins, finding a new parent, but deCONZ reports that it's know by 1 neighbour.

Today, my light nodes began turning red, starting, as always, with the Hue Blooms and (old model) Hue LED strips. This still happens once every other month or so. As usual, simply power cycling the red nodes doesn't help; only a full power cycle of my entire network remedied the situation. Both lumi.ctrl_neutral2 switches are now again fully operational. They're still asking the coordinator for the time, and they're still leaving and re-joining the network, but remain reachable.

@manup, I suspect there might still be something wrong with the routing in firmware 261f0500 that's causing the unresponsive nodes, but I have no clue how to even start analysing this. I never saw these unrecoverable red nodes, until the firmware was changed to handle IKEA meshing. I now have 89 nodes in my production network (1 coordinator, 47 routers). I haven't seen this issue on my test network.

They might use the a non responsive time cluster as indication to rejoin the network, same as Philips end-devices do when they don't receive zcl default response for their reports. A solution might be to just implement the time server on our side (or at least the responses which they expect).

In the last days I was quite busy to implement full nodes restore right after deCONZ starts, this is nearly finished and works quite well in my test networks (34, 80 and 105 nodes), hope to get the next release out this week.

Also I found a serious bug in the firmware (all versions) which will be fixed in 26220500, it caused the ZDO/ZDP module of the firmware to be blocked until next restart. As for the IKEA/OSRAM meshing I'm tempted to disable the many-to-one route record feature, it seems to cause more harm than good. All the other optimizations within deCONZ of the past releases should already provide a stable network, so it should be safe to disable it and just rely on good'ol mesh routing.

Both lumi.ctrl_neutral2 switches are now again fully operational.

That didn't last too long. Now seeing this error again:

Aug 30 09:31:51 pi2 deCONZ[6429]: 09:31:48:856 0x00158D000239145E error APSDE-DATA.confirm: 0xA7 on task

@manup, what's error 0xA7 in English? Would that be indicative of the ZDO/ZDP module of the firmware being blocked?

0xA7 is no APS ACK received. Since the switch often rejoins it might get a new NWK address and thus this might be the reason for the 0xA7.

Thanks. I’ll see if I can cook up something in the REST API plugin to answer the time request.

The NWK address doesn’t seem to change, but the switch rejoins to a different parent.

Interesting, I guess since the route changes it will need a few attempts until the gateway can reach the switch again. 0xA7 and somethings followed by 0xD0 (No Route), then route discovery restarts.

Keeping the switch happy via time cluster should be a good solution to prevent that.

Hacked together a very basic Time server, only responding to the Read Attributes command for the Time attribute (0x0000). As far as I can tell from WireShark, it works correctly, responding with a Read Attributes Response containing the current time (see frames below).

One of my switches seems to like it: although it keeps spamming the coordinator for the current time, it no longer leaves and re-joins the network. I'm in a brilliant catch 22 situation for the second switch: it seems the Read Attributes Response doesn't reach the switch (neither do other commands), so it continues to leave/re-join. I'll try another power cycle of the RaspBee.

Here's the request from the switch:

Frame 25777: 124 bytes on wire (992 bits), 124 bytes captured (992 bits) on interface 0
Ethernet II, Src: Raspberr_3b:e8:df (b8:27:eb:3b:e8:df), Dst: Apple_ca:3b:53 (a4:5e:60:ca:3b:53)
Internet Protocol Version 4, Src: 192.168.76.81, Dst: 192.168.76.41
User Datagram Protocol, Src Port: 53808, Dst Port: 17754
ZigBee Encapsulation Protocol, Channel: 25, Length: 50
IEEE 802.15.4 Data, Dst: 0x0000, Src: 0xa72e
ZigBee Network Layer Data, Dst: 0x0000, Src: 0xdc9f
    Frame Control Field: 0x0248, Frame Type: Data, Discover Route: Enable, Security Data
    Destination: 0x0000
    Source: 0xdc9f
    Radius: 29
    Sequence Number: 112
    [Extended Source: Jennic_00:02:4b:d5:7e (00:15:8d:00:02:4b:d5:7e)]
    [Origin: 643]
    ZigBee Security Header
ZigBee Application Support Layer Data, Dst Endpt: 1, Src Endpt: 1
    Frame Control Field: Data (0x00)
    Destination Endpoint: 1
    Cluster: Time (0x000a)
    Profile: Home Automation (0x0104)
    Source Endpoint: 1
    Counter: 66
ZigBee Cluster Library Frame, Command: Read Attributes, Seq: 216
    Frame Control Field: Profile-wide (0x10)
        .... ..00 = Frame Type: Profile-wide (0x0)
        .... .0.. = Manufacturer Specific: False
        .... 0... = Direction: Server
        ...1 .... = Disable Default Response: True
    Sequence Number: 216
    Command: Read Attributes (0x00)
    Attribute: Time (0x0000)

And here's my response:

Frame 25779: 130 bytes on wire (1040 bits), 130 bytes captured (1040 bits) on interface 0
Ethernet II, Src: Raspberr_3b:e8:df (b8:27:eb:3b:e8:df), Dst: Apple_ca:3b:53 (a4:5e:60:ca:3b:53)
Internet Protocol Version 4, Src: 192.168.76.81, Dst: 192.168.76.41
User Datagram Protocol, Src Port: 53808, Dst Port: 17754
ZigBee Encapsulation Protocol, Channel: 25, Length: 56
IEEE 802.15.4 Data, Dst: 0x3ddd, Src: 0x0000
ZigBee Network Layer Data, Dst: 0xdc9f, Src: 0x0000
    Frame Control Field: 0x0248, Frame Type: Data, Discover Route: Enable, Security Data
    Destination: 0xdc9f
    Source: 0x0000
    Radius: 10
    Sequence Number: 9
    [Extended Source: Dresden-_ff:ff:01:02:56 (00:21:2e:ff:ff:01:02:56)]
    [Origin: 74]
    ZigBee Security Header
ZigBee Application Support Layer Data, Dst Endpt: 1, Src Endpt: 1
    Frame Control Field: Data (0x00)
    Destination Endpoint: 1
    Cluster: Time (0x000a)
    Profile: Home Automation (0x0104)
    Source Endpoint: 1
    Counter: 174
ZigBee Cluster Library Frame, Command: Read Attributes Response, Seq: 216
    Frame Control Field: Profile-wide (0x18)
        .... ..00 = Frame Type: Profile-wide (0x0)
        .... .0.. = Manufacturer Specific: False
        .... 1... = Direction: Client
        ...1 .... = Disable Default Response: True
    Sequence Number: 216
    Command: Read Attributes Response (0x01)
    Status Record, UTC
        Attribute: Time (0x0000)
        Status: Success (0x00)
        Data Type: UTC Time (0xe2)
        UTC: Aug 30, 2018 22:21:58.000000000 CEST

Looks like WireShark courteously translates the UTC value to local time.

Power cycling the RaspBee, or rather doing a reset thru GCFFlasher_internal -r, brought back (the connection to) the second switch. My log shows no rejoin requests overnight, both switches are still responsive, and happily getting the time from the coordinator, approximately every 62 seconds. Finger crossed, but it looks like this is working...

@manup, could you please review and merge my PR?

Cool thanks, looks very good to me, the PR is merged and available in 2.05.37. You may try the 0x26220500 firmware included in the release, will bring hopefully more stable routing.

Now running v2.05.37 and 0x26220500 in test and production. Some observations:

Indeed, after restart, the GUI immediately shows all 89 nodes, and starts drawing the connection lines;
All /lights resources are available immediately - I think I can remove the lightlist workaround from homebridge-hue;
state.reachable is true immediately after startup for all the /lights resources - I'd expect this to be false until deCONZ has actually communicated with the light.
Same for config.reachable for /sensors resources (these used to available immediately after startup, but only became reachable as they were discovered);
The GUI lost the fields in the Node info panel after the first start, but these were re-populeted after next restarts. However, the name of my RaspBee is lost on each restart (both in the GUI node as well as in the Node info panel). Also the name of the XBee-s is lost;
The positions of the XBee nodes is lost on the first start, but saved at next restarts.
Firmware wouldn't update from the old web app, even though GUI showed the firmware update bar and I unplugged all USB devices (ConBee and XBee-s). No issue updating through GCFFlasher_internal.

After restart, deCONZ has a funny state for the lumi.ctrl_neutral2 switches. deCONZ reports them as unavailable, until I manually read the OnOff cluster attributes from the GUI. This was also the case in v2.05.35:

$ ph get /lights/423
{
  "etag": "3afa8b361233e55d9a07887e8f6ae0ac",
  "hascolor": false,
  "manufacturername": "LUMI",
  "modelid": "lumi.ctrl_neutral2",
  "name": "Living Room Fan 2",
  "state": {
    "alert": "none",
    "on": false,
    "reachable": true
  },
  "swversion": "11-11-2016",
  "type": "Smart plug",
  "uniqueid": "00:15:8d:00:02:4b:d5:7e-02"
}
$ ph put /lights/423/state '{"on": true}'
ph put: error: 3 resource, /lights/423, not available

I think this is due to the switch reporting Receiver On When Idle as false, even though it's mains powered. untitled However, the Basic cluster reports it's on DC power: untitled 2 I can't wait for deCONZ to read the Power descriptor again.

The lumi.ctrl_neutral2 switches don't seem to react to group commands (nor to a /groups/0 broadcast), even though they seem to support Groups cluster commands on both outlet endpoints.

Sep 02 18:23:04 pi2 deCONZ[312]: 18:22:59:258 add task 4777 type 21 to 0x00158D00024BD57E cluster 0x0004 req.id 125
Sep 02 18:23:04 pi2 deCONZ[312]: 18:22:59:258 APS-DATA.request id: 125, addrmode: 0x03, addr: 0x00158d00024bd57e, profile: 0x0104, cluster: 0x0004, ep: 0x01 -> 0x02 queue: 2 len: 4 tx.options 0x00
Sep 02 18:23:04 pi2 deCONZ[312]: 18:22:59:995 APS-DATA.indication srcAddr: 0x00158d00024bd57e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0004, lqi: 215, rssi: -64
Sep 02 18:23:04 pi2 deCONZ[312]: 18:22:59:995 verified group capacity: 7 and group count: 1 of LightNode 0x00158d00024bd57e
Sep 02 18:23:04 pi2 deCONZ[312]: 18:22:59:995 0x00158d00024bd57e found group 0x0003
...
Sep 02 18:28:04 pi2 deCONZ[312]: 18:28:02:505 add task 6263 type 21 to 0x00158D00024BD57E cluster 0x0004 req.id 159
Sep 02 18:28:04 pi2 deCONZ[312]: 18:28:02:552 APS-DATA.request id: 159, addrmode: 0x03, addr: 0x00158d00024bd57e, profile: 0x0104, cluster: 0x0004, ep: 0x01 -> 0x03 queue: 2 len: 4 tx.options 0x00
Sep 02 18:28:04 pi2 deCONZ[312]: 18:28:03:701 APS-DATA.indication srcAddr: 0x00158d00024bd57e, dstAddrMode: 2, profile: 0x0104, cluster: 0x0004, lqi: 231, rssi: -62
Sep 02 18:28:04 pi2 deCONZ[312]: 18:28:03:701 verified group capacity: 8 and group count: 0 of LightNode 0x00158d00024bd57e

BTW, is it possible to add the source endpoint to the APS-DATA.indication messages (I assume from the deCONZ core program)?

Thanks for the review, most of the issues should hopefully be fixed soon.

state.reachable is true immediately after startup for all the /lights resources - I'd expect this to be false until deCONZ has actually communicated with the light.

Either this or the last known state is restored, so after a deCONZ restart everything goes back to normal quickly. Currently this information is not in the database, it's already planned but didn't make it into this release :)

The GUI lost the fields in the Node info panel after the first start, but these were re-populeted after next restarts. However, the name of my RaspBee is lost on each restart (both in the GUI node as well as in the Node info panel). Also the name of the XBee-s is lost;

Confirmed, should be fixed in the next release. The XBees gui position did fall through since they don't have references in the zll.db. I'll add an exception.

The names of XBee and ConBee is stored in user-descriptor which is not yet stored in the zll.db.

Behind the scenes a cleanup of the session.default file happened, cached devices which have no references in zll.db were removed.

Firmware wouldn't update from the old web app, even though GUI showed the firmware update bar and I unplugged all USB devices (ConBee and XBee-s). No issue updating through GCFFlasher_internal.

Hmm, bad this should not happen I'll do more testing on various machines.

BTW, is it possible to add the source endpoint to the APS-DATA.indication messages (I assume from the deCONZ core program)?

Sure, I'll add it to the debug prints.

Either this or the last known state is restored

Why not initialise to false on db load and set it to true when traffic is received from the node? I think the logic to check for unreachable nodes on message receipt is already there?

Looks like they're working (now on v2.05.38 and firmware 0x26230500), except for https://github.com/dresden-elektronik/deconz-rest-plugin/issues/757#issuecomment-417943550:

After restart, deCONZ has a funny state for the lumi.ctrl_neutral2 switches. deCONZ reports them as unavailable, until I manually read the OnOff cluster attributes from the GUI. This was also the case in v2.05.35

@manup, what's your take on this?

Closing this issue to concentrate the discussion on the former issue https://github.com/dresden-elektronik/deconz-rest-plugin/issues/798

dresden-elektronik / deconz-rest-plugin

Unreachable lumi.ctrl_neutral2 #757