search

zigpy / bellows

A Python 3 project to implement EZSP for EmberZNet devices
GNU General Public License v3.0
179 stars 86 forks source link

Resetting ControllerApplication. Cause: 'NcpResetCode.RESET_WATCHDOG' #461

Closed pipiche38 closed 1 year ago

pipiche38 commented 2 years ago

while everything works well, we have the following error. This is occuri,ng several time in a day. There are about 65 Devices. (28 routers). ( https://github.com/zigbeefordomoticz/Domoticz-Zigbee/issues/1200 )

2022-05-29 18:27:42,263 DEBUG   :Sending: b'70dc21a9602a15fc2d904b23aa5493099d4e270ed9cb772ef6cc6383cb7e'
2022-05-29 18:27:44,231 DEBUG   :Error code: RESET_WATCHDOG, Version: 2, frame: b'c20203d20a7e'
2022-05-29 18:27:44,234 ERROR   :NCP entered failed state. Requesting APP controller restart
2022-05-29 18:27:44,235 DEBUG   :Received _reset_controller_application frame with (<NcpResetCode.RESET_WATCHDOG: 3>,)
2022-05-29 18:27:44,237 DEBUG   :Closed serial connection

And then nothing happen !!!!

2022-05-29 18:27:32,194 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=3, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_NONE: 0>, groupId=0, sequence=74), 60, -85, 0xc501, 255, 255, b'\x18\x1d\n\x00\x00 \xfe']
2022-05-29 18:27:32,571 DEBUG   :Data frame: b'14d8b1a9112a15b658964d24ab1592499c079f61a6e59874efde6383fc7e1af3d1c8de6f8fffc3f179d669de957e'
2022-05-29 18:27:32,572 DEBUG   :Sending: b'82503a7e'
2022-05-29 18:27:32,573 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'000401020701014000000049b8ca4b2bffff1218000a000025543a0500000000042aac0400'
2022-05-29 18:27:32,577 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=73), 184, -54, 0x2b4b, 255, 255, b'\x18\x00\n\x00\x00%T:\x05\x00\x00\x00\x00\x04*\xac\x04\x00']
2022-05-29 18:27:33,624 DEBUG   :Data frame: b'24d8b1a9112a15b658954824ab1593499c619362c8979874f5de2283fc7e1619e1c9d64e7e'
2022-05-29 18:27:33,627 DEBUG   :Sending: b'83401b7e'
2022-05-29 18:27:33,630 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'00040101020101400100002fb4c92559ffff0818410a000029be0a04'
2022-05-29 18:27:33,635 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=47), 180, -55, 0x5925, 255, 255, b'\x18A\n\x00\x00)\xbe\n']
2022-05-29 18:27:34,188 DEBUG   :Data frame: b'34d8b1a9112a15b658964d24ab1592499c079f61a6e59874efde6383fc7e1af3d1c8de6f8fffc3f179d6695e787e'
2022-05-29 18:27:34,188 DEBUG   :Sending: b'8430fc7e'
2022-05-29 18:27:34,190 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'000401020701014000000049b8ca4b2bffff1218000a000025543a0500000000042aac0400'
2022-05-29 18:27:34,194 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=73), 184, -54, 0x2b4b, 255, 255, b'\x18\x00\n\x00\x00%T:\x05\x00\x00\x00\x00\x04*\xac\x04\x00']
2022-05-29 18:27:34,855 DEBUG   :Data frame: b'44d8b1a90d2a9c5e134f10db55726fcd2c8627d2107e'
2022-05-29 18:27:34,855 DEBUG   :Sending: b'8520dd7e'
2022-05-29 18:27:34,857 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'89ec4adb5afeff27fd84b0c800'
2022-05-29 18:27:34,858 DEBUG   :Received incomingRouteRecordHandler frame with [0xec89, 84:fd:27:ff:fe:5a:db:4a, 176, -56, []]
2022-05-29 18:27:34,858 DEBUG   :Processing route record request: (0xec89, 84:fd:27:ff:fe:5a:db:4a, 176, -56, [])
2022-05-29 18:27:34,910 DEBUG   :Data frame: b'54d8b1a9112a15b658964d24ab1592499c3d976364229874efde6383fc7e1a71facdde6f8fffc3f1d5d2698e5e8c7e'
2022-05-29 18:27:34,910 DEBUG   :Sending: b'8610be7e'
2022-05-29 18:27:34,912 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'000401020701014000000073b0c889ecffff1218000a000025d6110000000000042a00000002'
2022-05-29 18:27:34,914 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=115), 176, -56, 0xec89, 255, 255, b'\x18\x00\n\x00\x00%\xd6\x11\x00\x00\x00\x00\x00\x04*\x00\x00\x00']
2022-05-29 18:27:35,940 DEBUG   :Data frame: b'64d8b1a9112a15b65894b5caab5592499ccf8b6c82289874fb396289f87c3d41f87e'
2022-05-29 18:27:35,941 DEBUG   :Sending: b'87009f7e'
2022-05-29 18:27:35,942 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'00040100ffef010000000081acc76fe6ffff06ff0100040202'
2022-05-29 18:27:35,944 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=65280, sourceEndpoint=239, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_NONE: 0>, groupId=0, sequence=129), 172, -57, 0xe66f, 255, 255, b'\xff\x01\x00\x04\x02\x02']
2022-05-29 18:27:36,163 DEBUG   :Data frame: b'74d8b1a90d2af09b174e10db55726fcd208526d85d25247e'
2022-05-29 18:27:36,163 DEBUG   :Sending: b'8070787e'
2022-05-29 18:27:36,165 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'e5294eda5afeff27fd84bccb0173b0'
2022-05-29 18:27:36,166 DEBUG   :Received incomingRouteRecordHandler frame with [0x29e5, 84:fd:27:ff:fe:5a:da:4e, 188, -53, [0xb073]]
2022-05-29 18:27:36,166 DEBUG   :Processing route record request: (0x29e5, 84:fd:27:ff:fe:5a:da:4e, 188, -53, [0xb073])
2022-05-29 18:27:36,173 DEBUG   :Data frame: b'04d8b1a9112a15b658964d24ab1592499ce09b6008e79874efde6383fc7e1af2e3cdde6f8fffc3f1d5d2698820707e'
2022-05-29 18:27:36,173 DEBUG   :Sending: b'8160597e'
2022-05-29 18:27:36,175 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0004010207010140000000aebccbe529ffff1218000a00002555080000000000042a00000004'
2022-05-29 18:27:36,178 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=174), 188, -53, 0x29e5, 255, 255, b'\x18\x00\n\x00\x00%U\x08\x00\x00\x00\x00\x00\x04*\x00\x00\x00']
2022-05-29 18:27:36,206 DEBUG   :Send command readCounters: ()
2022-05-29 18:27:36,208 DEBUG   :Sending: b'41d921a9a52abb6a7e'
2022-05-29 18:27:36,230 DEBUG   :Data frame: b'15d9a1a9a52aa0b6359479277455d649854e2eabe4ce7e8adec66c89fa7e30a7c9cdcc6f87ffc7dbd5d2698c4623a9ec763ba5ea75824198682713b1e070381c0e07bbe5ca6598459a4d9e4f9ff7c3d9d46a35a2519048246c217e'
2022-05-29 18:27:36,231 DEBUG   :Sending: b'82503a7e'
2022-05-29 18:27:36,233 DEBUG   :Application frame 241 (readCounters) received: b'b5046c003302de004400190009000900190123000f0006000f002200120008000000000000000000000000000000000000002401000000000000000000000000120000000000000000000000000000000000'
2022-05-29 18:27:36,237 DEBUG   :Send command getValue: (<EzspValueId.VALUE_FREE_BUFFERS: 3>,)
2022-05-29 18:27:36,238 DEBUG   :Sending: b'52de21a9fe2a1687c07e'
2022-05-29 18:27:36,245 DEBUG   :Data frame: b'26dea1a9fe2a15b3abd1017e'
2022-05-29 18:27:36,245 DEBUG   :Sending: b'83401b7e'
2022-05-29 18:27:36,256 DEBUG   :Application frame 170 (getValue) received: b'0001f2'
2022-05-29 18:27:36,258 DEBUG   :Free buffers status EzspStatus.SUCCESS, value: 242
2022-05-29 18:27:36,258 DEBUG   :ezsp_counters: [MAC_RX_BROADCAST = 1205, MAC_TX_BROADCAST = 108, MAC_RX_UNICAST = 563, MAC_TX_UNICAST_SUCCESS = 222, MAC_TX_UNICAST_RETRY = 68, MAC_TX_UNICAST_FAILED = 25, APS_DATA_RX_BROADCAST = 9, APS_DATA_TX_BROADCAST = 9, APS_DATA_RX_UNICAST = 281, APS_DATA_TX_UNICAST_SUCCESS = 35, APS_DATA_TX_UNICAST_RETRY = 15, APS_DATA_TX_UNICAST_FAILED = 6, ROUTE_DISCOVERY_INITIATED = 15, NEIGHBOR_ADDED = 34, NEIGHBOR_REMOVED = 18, NEIGHBOR_STALE = 8, JOIN_INDICATION = 0, CHILD_REMOVED = 0, ASH_OVERFLOW_ERROR = 0, ASH_FRAMING_ERROR = 0, ASH_OVERRUN_ERROR = 0, NWK_FRAME_COUNTER_FAILURE = 0, APS_FRAME_COUNTER_FAILURE = 0, UTILITY = 0, APS_LINK_KEY_NOT_AUTHORIZED = 0, NWK_DECRYPTION_FAILURE = 292, APS_DECRYPTION_FAILURE = 0, ALLOCATE_PACKET_BUFFER_FAILURE = 0, RELAYED_UNICAST = 0, PHY_TO_MAC_QUEUE_LIMIT_REACHED = 0, PACKET_VALIDATE_LIBRARY_DROPPED_COUNT = 0, TYPE_NWK_RETRY_OVERFLOW = 0, PHY_CCA_FAIL_COUNT = 18, BROADCAST_TABLE_FULL = 0, PTA_LO_PRI_REQUESTED = 0, PTA_HI_PRI_REQUESTED = 0, PTA_LO_PRI_DENIED = 0, PTA_HI_PRI_DENIED = 0, PTA_LO_PRI_TX_ABORTED = 0, PTA_HI_PRI_TX_ABORTED = 0, ADDRESS_CONFLICT_SENT = 0, EZSP_FREE_BUFFERS = 242]
2022-05-29 18:27:36,418 DEBUG   :Data frame: b'36deb1a9112a15b65894b5caab5593499ced5b1000549874fb396289f87c3d87117e'
2022-05-29 18:27:36,419 DEBUG   :Sending: b'8430fc7e'
2022-05-29 18:27:36,419 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'00040100ffef0100010000a37cbbed9affff06ff0100040202'
2022-05-29 18:27:36,421 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=65280, sourceEndpoint=239, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=163), 124, -69, 0x9aed, 255, 255, b'\xff\x01\x00\x04\x02\x02']
2022-05-29 18:27:36,438 DEBUG   :Data frame: b'46deb1a9112a15b65894b5caab5593499ce15b10f91a9874fb396289f87c3da8277e'
2022-05-29 18:27:36,439 DEBUG   :Sending: b'8520dd7e'
2022-05-29 18:27:36,439 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'00040100ffef0100010000af7cbb14d4ffff06ff0100040202'
2022-05-29 18:27:36,441 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=65280, sourceEndpoint=239, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=175), 124, -69, 0xd414, 255, 255, b'\xff\x01\x00\x04\x02\x02']
2022-05-29 18:27:37,954 DEBUG   :Data frame: b'56deb1a90d2aa35865169adb5579f8755c8226dfc530f87e'
2022-05-29 18:27:37,954 DEBUG   :Sending: b'8610be7e'
2022-05-29 18:27:37,956 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'b6ea3c82d0feff2c6a3cc0cc017428'
2022-05-29 18:27:37,957 DEBUG   :Received incomingRouteRecordHandler frame with [0xeab6, 3c:6a:2c:ff:fe:d0:82:3c, 192, -52, [0x2874]]
2022-05-29 18:27:37,958 DEBUG   :Processing route record request: (0xeab6, 3c:6a:2c:ff:fe:d0:82:3c, 192, -52, [0x2874])
2022-05-29 18:27:38,014 DEBUG   :Data frame: b'66deb1a9112a15b658964d24ab5592499ce39b605b249874d6de6383fc7e1ad5fa83df6f8fffc3f129d6698f7701b6f57638e4cfcfc90f984c261090ca223a1c0e05a3e5ce04867e'
2022-05-29 18:27:38,015 DEBUG   :Sending: b'87009f7e'
2022-05-29 18:27:38,017 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0004010207010100000000adbccbb6eaffff2b18000a00002572114e01000000042afc04000331221f1900034125ba4b4e00000003212a5202000002180004'
2022-05-29 18:27:38,020 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_NONE: 0>, groupId=0, sequence=173), 188, -53, 0xeab6, 255, 255, b'\x18\x00\n\x00\x00%r\x11N\x01\x00\x00\x00\x04*\xfc\x04\x00\x031"\x1f\x19\x00\x03A%\xbaKN\x00\x00\x00\x03!*R\x02\x00\x00\x02\x18\x00']
2022-05-29 18:27:38,459 DEBUG   :Data frame: b'76deb1a90d2aa35865169adb5579f875208526dfc5fac37e'
2022-05-29 18:27:38,460 DEBUG   :Sending: b'8070787e'
2022-05-29 18:27:38,461 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'b6ea3c82d0feff2c6a3cbccb017428'
2022-05-29 18:27:38,463 DEBUG   :Received incomingRouteRecordHandler frame with [0xeab6, 3c:6a:2c:ff:fe:d0:82:3c, 188, -53, [0x2874]]
2022-05-29 18:27:38,464 DEBUG   :Processing route record request: (0xeab6, 3c:6a:2c:ff:fe:d0:82:3c, 188, -53, [0x2874])
2022-05-29 18:27:38,516 DEBUG   :Data frame: b'06deb1a9112a15b658964d24ab5592499ce09b605b249874ceda5f98fc743fe7ce203ca68fffc7dbf5f8638c462399ce5932a5ea44a0b59a4c265294ee660b1c0e07bbc4e0d48a459e0cbe499b2c0c7e'
2022-05-29 18:27:38,517 DEBUG   :Sending: b'8160597e'
2022-05-29 18:27:38,518 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0004010207010100000000aebccbb6eaffff331c3c11000a004025ede2c900000000202a0a00000030222f0900003122f402000041250e163300000000212ab100000441200604'
2022-05-29 18:27:38,522 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_NONE: 0>, groupId=0, sequence=174), 188, -53, 0xeab6, 255, 255, b'\x1c<\x11\x00\n\x00@%\xed\xe2\xc9\x00\x00\x00\x00 *\n\x00\x00\x000"/\t\x00\x001"\xf4\x02\x00\x00A%\x0e\x163\x00\x00\x00\x00!*\xb1\x00\x00\x04A \x06']
2022-05-29 18:27:39,432 DEBUG   :Data frame: b'16deb1a90d2aa35865169adb5579f8755c8226dfc52b8e7e'
2022-05-29 18:27:39,432 DEBUG   :Sending: b'82503a7e'
2022-05-29 18:27:39,434 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'b6ea3c82d0feff2c6a3cc0cc017428'
2022-05-29 18:27:39,435 DEBUG   :Received incomingRouteRecordHandler frame with [0xeab6, 3c:6a:2c:ff:fe:d0:82:3c, 192, -52, [0x2874]]
2022-05-29 18:27:39,435 DEBUG   :Processing route record request: (0xeab6, 3c:6a:2c:ff:fe:d0:82:3c, 192, -52, [0x2874])
2022-05-29 18:27:39,508 DEBUG   :Data frame: b'26deb1a9112a15b658964d24ab5592499ce1e7675b249874ceda5f98fc743ee7ce96d5438fffc7daf5f86f8c462299ce5932a5eb44a05e984c275294f0463a1c0e07bac4e0618a459f0cbe019b18b07e'
2022-05-29 18:27:39,509 DEBUG   :Sending: b'83401b7e'
2022-05-29 18:27:39,510 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0004010207010100000000afc0ccb6eaffff331c3c11000a0140255b0b2c00000001202a0600000130222f09000131221f000001412510360200000001212a0400000541204e04'
2022-05-29 18:27:39,514 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_NONE: 0>, groupId=0, sequence=175), 192, -52, 0xeab6, 255, 255, b'\x1c<\x11\x00\n\x01@%[\x0b,\x00\x00\x00\x01 *\x06\x00\x00\x010"/\t\x00\x011"\x1f\x00\x00\x01A%\x106\x02\x00\x00\x00\x01!*\x04\x00\x00\x05A N']
2022-05-29 18:27:39,710 DEBUG   :Data frame: b'36deb5a9902a1904b3c3f47e'
2022-05-29 18:27:39,710 DEBUG   :Sending: b'8430fc7e'
2022-05-29 18:27:39,712 DEBUG   :Data frame: b'46deb1a9d42abf04b33ebb7e'
2022-05-29 18:27:39,713 DEBUG   :Application frame 196 (changeSourceRouteHandler) received: b'0cb6ea'
2022-05-29 18:27:39,713 DEBUG   :Sending: b'8520dd7e'
2022-05-29 18:27:39,714 DEBUG   :Received changeSourceRouteHandler frame with [0xb60c, 0x00ea, <Bool.false: 0>]
2022-05-29 18:27:39,716 DEBUG   :Application frame 128 (incomingRouteErrorHandler) received: b'aab6ea'
2022-05-29 18:27:39,717 DEBUG   :Received incomingRouteErrorHandler frame with [<EmberStatus.MANY_TO_ONE_ROUTE_FAILURE: 170>, 0xeab6]
2022-05-29 18:27:39,717 DEBUG   :Processing route error: status=EmberStatus.MANY_TO_ONE_ROUTE_FAILURE, nwk=0xeab6
2022-05-29 18:27:39,983 DEBUG   :Data frame: b'56deb1a9112a15b658944f24ab1593499c4c9763fe169874f4cf5e89ec7e3fa7ebcdfdd67e'
2022-05-29 18:27:39,983 DEBUG   :Sending: b'8610be7e'
2022-05-29 18:27:39,985 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'000401000501014001000002b0c813d8ffff09093d00100000000000'
2022-05-29 18:27:39,988 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1280, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=2), 176, -56, 0xd813, 255, 255, b'\t=\x00\x10\x00\x00\x00\x00\x00']
2022-05-29 18:27:40,001 DEBUG   :Data frame: b'66deb1a90d2aa35865169adb5579f8755c8226dfc5b38e7e'
2022-05-29 18:27:40,002 DEBUG   :Sending: b'87009f7e'
2022-05-29 18:27:40,012 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'b6ea3c82d0feff2c6a3cc0cc017428'
2022-05-29 18:27:40,013 DEBUG   :Received incomingRouteRecordHandler frame with [0xeab6, 3c:6a:2c:ff:fe:d0:82:3c, 192, -52, [0x2874]]
2022-05-29 18:27:40,013 DEBUG   :Processing route record request: (0xeab6, 3c:6a:2c:ff:fe:d0:82:3c, 192, -52, [0x2874])
2022-05-29 18:27:40,016 DEBUG   :Data frame: b'76deb1a9902a17a181b2707e'
2022-05-29 18:27:40,017 DEBUG   :Sending: b'8070787e'
2022-05-29 18:27:40,018 DEBUG   :Application frame 196 (changeSourceRouteHandler) received: b'0213d8'
2022-05-29 18:27:40,019 DEBUG   :Received changeSourceRouteHandler frame with [0x1302, 0x00d8, <Bool.false: 0>]
2022-05-29 18:27:40,028 DEBUG   :Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0xD813, EmberApsFrame(profileId=260, clusterId=1280, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=61), 51, b'\x10=\x0b\x00\x00')
2022-05-29 18:27:40,036 DEBUG   :Sending: b'60df21a9602a15a181904b25af5493099d4e2796decb77b6f6c6631d6b7e'
2022-05-29 18:27:40,045 DEBUG   :Data frame: b'07dfa1a9602a1599edf27e'
2022-05-29 18:27:40,045 DEBUG   :Sending: b'8160597e'
2022-05-29 18:27:40,046 DEBUG   :Application frame 52 (sendUnicast) received: b'002b'
2022-05-29 18:27:40,058 DEBUG   :Data frame: b'17dfb1a9112a15b658964d24ab5592499cfe9b605b249874ceda5f98fc743de7cee7fd378fffc7d9f5f88488462199ce5832a5e844a04d8e4c2452947c8f201c0e07b9c4e0f98b459c0cbe109bb95d7e'
2022-05-29 18:27:40,059 DEBUG   :Sending: b'82503a7e'
2022-05-29 18:27:40,060 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0004010207010100000000b0bccbb6eaffff331c3c11000a0240252a235800000002202aed04000230222e09000231220c16000241259cff1800000002212a9c01000641205f04'
2022-05-29 18:27:40,063 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_NONE: 0>, groupId=0, sequence=176), 188, -53, 0xeab6, 255, 255, b'\x1c<\x11\x00\n\x02@%*#X\x00\x00\x00\x02 *\xed\x04\x00\x020".\t\x00\x021"\x0c\x16\x00\x02A%\x9c\xff\x18\x00\x00\x00\x02!*\x9c\x01\x00\x06A _']
2022-05-29 18:27:40,242 DEBUG   :Data frame: b'27dfb1a90d2a6602ed889bdb5579f875208527de147e'
2022-05-29 18:27:40,242 DEBUG   :Sending: b'83401b7e'
2022-05-29 18:27:40,243 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'73b0b41cd1feff2c6a3cbccb00'
2022-05-29 18:27:40,244 DEBUG   :Received incomingRouteRecordHandler frame with [0xb073, 3c:6a:2c:ff:fe:d1:1c:b4, 188, -53, []]
2022-05-29 18:27:40,244 DEBUG   :Processing route record request: (0xb073, 3c:6a:2c:ff:fe:d1:1c:b4, 188, -53, [])
2022-05-29 18:27:40,303 DEBUG   :Data frame: b'37dfb1a9112a15b658954824ab1593499c1d9b609e7e9874f5de7683fc7e163be2cf11f97e'
2022-05-29 18:27:40,303 DEBUG   :Sending: b'8430fc7e'
2022-05-29 18:27:40,304 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'000401010201014001000053bccb73b0ffff0818150a0000299c0902'
2022-05-29 18:27:40,306 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=83), 188, -53, 0xb073, 255, 255, b'\x18\x15\n\x00\x00)\x9c\t']
2022-05-29 18:27:40,432 DEBUG   :Data frame: b'47dfb1a96b2a15a181904b25af5493099c4e2780dece67d6107e'
2022-05-29 18:27:40,433 DEBUG   :Sending: b'8520dd7e'
2022-05-29 18:27:40,434 DEBUG   :Application frame 63 (messageSentHandler) received: b'0013d8040100050101400000002b330000'
2022-05-29 18:27:40,437 DEBUG   :Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 55315, EmberApsFrame(profileId=260, clusterId=1280, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=43), 51, <EmberStatus.SUCCESS: 0>, b'']
2022-05-29 18:27:41,225 DEBUG   :Data frame: b'57dfb1a9702aef205cd5a32baa1e80499c4d02f241b07e'
2022-05-29 18:27:41,231 DEBUG   :Sending: b'8610be7e'
2022-05-29 18:27:41,232 DEBUG   :Application frame 36 (trustCenterJoinHandler) received: b'fa920541e90e004b120000032559'
2022-05-29 18:27:41,233 DEBUG   :Received trustCenterJoinHandler frame with [0x92fa, 00:12:4b:00:0e:e9:41:05, <EmberDeviceUpdate.STANDARD_SECURITY_SECURED_REJOIN: 0>, <EmberJoinDecision.NO_ACTION: 3>, 0x5925]
2022-05-29 18:27:41,514 DEBUG   :Data frame: b'67dfb1a9112a15b658924a24ab5592499c61a717a3ba9874facec683fc7e2fa788897e'
2022-05-29 18:27:41,515 DEBUG   :Sending: b'87009f7e'
2022-05-29 18:27:41,570 DEBUG   :Data frame: b'77dfb1a9112a15b658944f24ab1593499c4c9763fe169874f4cf5e89ec7e3fa7ebcd4add7e'
2022-05-29 18:27:41,570 DEBUG   :Sending: b'8070787e'
2022-05-29 18:27:42,236 INFO    :Device 0x92fa (00:12:4b:00:0e:e9:41:05) joined the network
2022-05-29 18:27:42,238 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'00040106000101000000002f80bc4e74ffff0708a50a00001000'
2022-05-29 18:27:42,240 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_NONE: 0>, groupId=0, sequence=47), 128, -68, 0x744e, 255, 255, b'\x08\xa5\n\x00\x00\x10\x00']
2022-05-29 18:27:42,242 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'000401000501014001000002b0c813d8ffff09093d00100000000000'
2022-05-29 18:27:42,247 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1280, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=2), 176, -56, 0xd813, 255, 255, b'\t=\x00\x10\x00\x00\x00\x00\x00']
2022-05-29 18:27:42,255 DEBUG   :Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x744E, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=165), 52, b'\x10\xa5\x0b\n\x00')
2022-05-29 18:27:42,263 DEBUG   :Sending: b'70dc21a9602a15fc2d904b23aa5493099d4e270ed9cb772ef6cc6383cb7e'
2022-05-29 18:27:44,231 DEBUG   :Error code: RESET_WATCHDOG, Version: 2, frame: b'c20203d20a7e'
2022-05-29 18:27:44,234 ERROR   :NCP entered failed state. Requesting APP controller restart
2022-05-29 18:27:44,235 DEBUG   :Received _reset_controller_application frame with (<NcpResetCode.RESET_WATCHDOG: 3>,)
2022-05-29 18:27:44,237 DEBUG   :Closed serial connection
2022-05-29 18:27:44,237 DEBUG   :Resetting ControllerApplication. Cause: 'NcpResetCode.RESET_WATCHDOG'
2022-05-29 18:27:47,267 ERROR   :Task exception was never retrieved
future: <Task finished coro=<transport_request() done, defined at /home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py:535> exception=TimeoutError()>
Traceback (most recent call last):
  File "/usr/lib/python3.7/asyncio/tasks.py", line 223, in __step
    result = coro.send(None)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 555, in transport_request
    result, msg = await self.app.request( destination, Profile, Cluster, sEp, dEp, sequence, payload, expect_reply, use_ieee )
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 581, in request
    self.direct, device.nwk, aps_frame, message_tag, data
  File "/usr/lib/python3.7/asyncio/tasks.py", line 423, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
2022-05-29 20:09:07,512 INFO    : [       MainThread] UpdateGroup  - (  Lampes sejour) 1:100
2022-05-29 20:09:07,614 ERROR   : [       ZigpyCom_4] Error while receiving a Plugin command: >ApplicationController is not running<
2022-05-29 20:09:07,632 ERROR   : [       ZigpyCom_4] Issue in request {'cmd': 'RAW-COMMAND', 'datas': {'Function': 'raw_zcl_zcl_onoff', 'Profile': 260, 'Cluster': 6, 'TargetNwk': 1, 'TargetEp': 1, 'SrcEp': 1, 'Sqn': 0, 'payload': '110001', 'timestamp': 1653847747.5226061, 'AddressMode': 1}, 'NwkId': 1, 'TimeStamp': 1653847747.5232742, 'ACKIsDisable': False, 'Sqn': 0}, dumping stack: Traceback (most recent call last):
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 245, in worker_loop
    await dispatch_command(self, data)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 354, in dispatch_command
    await process_raw_command(self, data["datas"], AckIsDisable=data["ACKIsDisable"], Sqn=data["Sqn"])
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 407, in process_raw_command
    result, msg = await self.app.mrequest(destination, Profile, Cluster, sEp, sequence, payload)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 479, in mrequest
    raise ControllerError("ApplicationController is not running")
bellows.exception.ControllerError: ApplicationController is not running

2022-05-29 20:09:08,171 INFO    : [       MainThread] UpdateGroup  - (  Lampes sejour) 1:100
2022-05-29 20:09:08,358 ERROR   : [       ZigpyCom_4] Error while receiving a Plugin command: >ApplicationController is not running<
2022-05-29 20:09:08,406 ERROR   : [       ZigpyCom_4] Issue in request {'cmd': 'RAW-COMMAND', 'datas': {'Function': 'zcl_raw_level_move_to_level', 'Profile': 260, 'Cluster': 8, 'TargetNwk': 1, 'TargetEp': 1, 'SrcEp': 1, 'Sqn': 0, 'payload': '110000FF1000', 'timestamp': 1653847748.278268, 'AddressMode': 1}, 'NwkId': 1, 'TimeStamp': 1653847748.2785985, 'ACKIsDisable': False, 'Sqn': 0}, dumping stack: Traceback (most recent call last):
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 245, in worker_loop
    await dispatch_command(self, data)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 354, in dispatch_command
    await process_raw_command(self, data["datas"], AckIsDisable=data["ACKIsDisable"], Sqn=data["Sqn"])
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 407, in process_raw_command
    result, msg = await self.app.mrequest(destination, Profile, Cluster, sEp, sequence, payload)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 479, in mrequest
    raise ControllerError("ApplicationController is not running")
bellows.exception.ControllerError: ApplicationController is not running

2022-05-29 20:09:17,561 INFO    : [       MainThread] UpdateGroup  - (  Lampes sejour) 1:100
2022-05-29 20:09:17,665 ERROR   : [       ZigpyCom_4] Error while receiving a Plugin command: >ApplicationController is not running<
2022-05-29 20:09:17,709 ERROR   : [       ZigpyCom_4] Issue in request {'cmd': 'RAW-COMMAND', 'datas': {'Function': 'raw_zcl_zcl_onoff', 'Profile': 260, 'Cluster': 6, 'TargetNwk': 1, 'TargetEp': 1, 'SrcEp': 1, 'Sqn': 0, 'payload': '110001', 'timestamp': 1653847757.56448, 'AddressMode': 1}, 'NwkId': 1, 'TimeStamp': 1653847757.56464, 'ACKIsDisable': False, 'Sqn': 0}, dumping stack: Traceback (most recent call last):
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 245, in worker_loop
    await dispatch_command(self, data)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 354, in dispatch_command
    await process_raw_command(self, data["datas"], AckIsDisable=data["ACKIsDisable"], Sqn=data["Sqn"])
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 407, in process_raw_command
    result, msg = await self.app.mrequest(destination, Profile, Cluster, sEp, sequence, payload)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 479, in mrequest
    raise ControllerError("ApplicationController is not running")
bellows.exception.ControllerError: ApplicationController is not running

2022-05-29 20:09:20,019 INFO    : [       MainThread] UpdateGroup  - (  Lampes sejour) 1:100
2022-05-29 20:09:20,084 ERROR   : [       ZigpyCom_4] Error while receiving a Plugin command: >ApplicationController is not running<
2022-05-29 20:09:20,110 ERROR   : [       ZigpyCom_4] Issue in request {'cmd': 'RAW-COMMAND', 'datas': {'Function': 'zcl_raw_level_move_to_level', 'Profile': 260, 'Cluster': 8, 'TargetNwk': 1, 'TargetEp': 1, 'SrcEp': 1, 'Sqn': 0, 'payload': '110000FF1000', 'timestamp': 1653847760.0161397, 'AddressMode': 1}, 'NwkId': 1, 'TimeStamp': 1653847760.0163817, 'ACKIsDisable': False, 'Sqn': 0}, dumping stack: Traceback (most recent call last):
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 245, in worker_loop
    await dispatch_command(self, data)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 354, in dispatch_command
    await process_raw_command(self, data["datas"], AckIsDisable=data["ACKIsDisable"], Sqn=data["Sqn"])
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 407, in process_raw_command
    result, msg = await self.app.mrequest(destination, Profile, Cluster, sEp, sequence, payload)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 479, in mrequest
    raise ControllerError("ApplicationController is not running")
bellows.exception.ControllerError: ApplicationController is not running

2022-05-29 20:09:21,142 INFO    : [       MainThread] UpdateGroup  - (  Lampes sejour) 1:100
2022-05-29 20:09:27,468 ERROR   : [       ZigpyCom_4] Error while receiving a Plugin command: >ApplicationController is not running<
2022-05-29 20:09:27,505 ERROR   : [       ZigpyCom_4] Issue in request {'cmd': 'RAW-COMMAND', 'datas': {'Function': 'zcl_raw_level_move_to_level', 'Profile': 260, 'Cluster': 8, 'TargetNwk': 1, 'TargetEp': 1, 'SrcEp': 1, 'Sqn': 0, 'payload': '110000FF1000', 'timestamp': 1653847767.4179358, 'AddressMode': 1}, 'NwkId': 1, 'TimeStamp': 1653847767.418459, 'ACKIsDisable': False, 'Sqn': 0}, dumping stack: Traceback (most recent call last):
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 245, in worker_loop
    await dispatch_command(self, data)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 354, in dispatch_command
    await process_raw_command(self, data["datas"], AckIsDisable=data["ACKIsDisable"], Sqn=data["Sqn"])
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 407, in process_raw_command
    result, msg = await self.app.mrequest(destination, Profile, Cluster, sEp, sequence, payload)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 479, in mrequest
    raise ControllerError("ApplicationController is not running")
bellows.exception.ControllerError: ApplicationController is not running

2022-05-29 20:09:37,514 INFO    : [       MainThread] UpdateGroup  - (  Lampes sejour) 1:100
2022-05-29 20:10:22,686 INFO    : [       MainThread] zcl_group_onoff_off_noeffect 0002 01 01
2022-05-29 20:10:22,701 INFO    : [       MainThread] UpdateGroup  - (Lampes suite parents) 0:100
2022-05-29 20:10:22,739 ERROR   : [       ZigpyCom_4] Error while receiving a Plugin command: >ApplicationController is not running<
2022-05-29 20:10:22,765 ERROR   : [       ZigpyCom_4] Issue in request {'cmd': 'RAW-COMMAND', 'datas': {'Function': 'raw_zcl_zcl_onoff', 'Profile': 260, 'Cluster': 6, 'TargetNwk': 2, 'TargetEp': 1, 'SrcEp': 1, 'Sqn': 0, 'payload': '110000', 'timestamp': 1653847822.684379, 'AddressMode': 1}, 'NwkId': 2, 'TimeStamp': 1653847822.684722, 'ACKIsDisable': False, 'Sqn': 0}, dumping stack: Traceback (most recent call last):
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 245, in worker_loop
    await dispatch_command(self, data)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 354, in dispatch_command
    await process_raw_command(self, data["datas"], AckIsDisable=data["ACKIsDisable"], Sqn=data["Sqn"])
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 407, in process_raw_command
    result, msg = await self.app.mrequest(destination, Profile, Cluster, sEp, sequence, payload)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 479, in mrequest
    raise ControllerError("ApplicationController is not running")
bellows.exception.ControllerError: ApplicationController is not running

2022-05-29 20:10:27,495 INFO    : [       MainThread] UpdateGroup  - (  Lampes sejour) 1:100
2022-05-29 20:10:27,549 INFO    : [       MainThread] UpdateGroup  - (  Lampes sejour) 1:100
2022-05-29 20:10:27,582 ERROR   : [       ZigpyCom_4] Error while receiving a Plugin command: >ApplicationController is not running<
2022-05-29 20:10:27,604 ERROR   : [       ZigpyCom_4] Issue in request {'cmd': 'RAW-COMMAND', 'datas': {'Function': 'raw_zcl_zcl_onoff', 'Profile': 260, 'Cluster': 6, 'TargetNwk': 1, 'TargetEp': 1, 'SrcEp': 1, 'Sqn': 0, 'payload': '110001', 'timestamp': 1653847827.5098717, 'AddressMode': 1}, 'NwkId': 1, 'TimeStamp': 1653847827.5102925, 'ACKIsDisable': False, 'Sqn': 0}, dumping stack: Traceback (most recent call last):
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 245, in worker_loop
    await dispatch_command(self, data)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 354, in dispatch_command
    await process_raw_command(self, data["datas"], AckIsDisable=data["ACKIsDisable"], Sqn=data["Sqn"])
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 407, in process_raw_command
    result, msg = await self.app.mrequest(destination, Profile, Cluster, sEp, sequence, payload)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 479, in mrequest
    raise ControllerError("ApplicationController is not running")
bellows.exception.ControllerError: ApplicationController is not running

2022-05-29 20:10:27,625 ERROR   : [       ZigpyCom_4] Error while receiving a Plugin command: >ApplicationController is not running<
2022-05-29 20:10:27,647 ERROR   : [       ZigpyCom_4] Issue in request {'cmd': 'RAW-COMMAND', 'datas': {'Function': 'raw_zcl_zcl_onoff', 'Profile': 260, 'Cluster': 6, 'TargetNwk': 1, 'TargetEp': 1, 'SrcEp': 1, 'Sqn': 0, 'payload': '110001', 'timestamp': 1653847827.5751395, 'AddressMode': 1}, 'NwkId': 1, 'TimeStamp': 1653847827.5753965, 'ACKIsDisable': False, 'Sqn': 0}, dumping stack: Traceback (most recent call last):
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 245, in worker_loop
    await dispatch_command(self, data)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 354, in dispatch_command
    await process_raw_command(self, data["datas"], AckIsDisable=data["ACKIsDisable"], Sqn=data["Sqn"])
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 407, in process_raw_command
    result, msg = await self.app.mrequest(destination, Profile, Cluster, sEp, sequence, payload)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 479, in mrequest
    raise ControllerError("ApplicationController is not running")
bellows.exception.ControllerError: ApplicationController is not running

2022-05-29 20:10:32,102 INFO    : [       MainThread] UpdateGroup  - (  Lampes sejour) 1:100
2022-05-29 20:10:37,486 INFO    : [       MainThread] UpdateGroup  - (  Lampes sejour) 1:100
2022-05-29 20:10:37,518 ERROR   : [       ZigpyCom_4] Error while receiving a Plugin command: >ApplicationController is not running<
2022-05-29 20:10:37,542 ERROR   : [       ZigpyCom_4] Issue in request {'cmd': 'RAW-COMMAND', 'datas': {'Function': 'raw_zcl_zcl_onoff', 'Profile': 260, 'Cluster': 6, 'TargetNwk': 1, 'TargetEp': 1, 'SrcEp': 1, 'Sqn': 0, 'payload': '110001', 'timestamp': 1653847837.5124815, 'AddressMode': 1}, 'NwkId': 1, 'TimeStamp': 1653847837.5131602, 'ACKIsDisable': False, 'Sqn': 0}, dumping stack: Traceback (most recent call last):
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 245, in worker_loop
    await dispatch_command(self, data)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 354, in dispatch_command
    await process_raw_command(self, data["datas"], AckIsDisable=data["ACKIsDisable"], Sqn=data["Sqn"])
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 407, in process_raw_command
    result, msg = await self.app.mrequest(destination, Profile, Cluster, sEp, sequence, payload)
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 479, in mrequest
    raise ControllerError("ApplicationController is not running")
bellows.exception.ControllerError: ApplicationController is not running
pipiche38 commented 2 years ago

Is there anything expected to be done when receiving Exception ?

bellows.exception.ControllerError: ApplicationController is not running

puddly commented 2 years ago

There is a gap in the debug log of over an hour:

2022-05-29 18:27:44,237 DEBUG   :Resetting ControllerApplication. Cause: 'NcpResetCode.RESET_WATCHDOG'
...
2022-05-29 20:09:07,512 INFO    : [       MainThread] UpdateGroup  - (  Lampes sejour) 1:100

Please post the full log, bellows should be trying to reconnect.

pipiche38 commented 2 years ago

There is no more Log. the bellows just stop working and logging ! A restart of the plugin was tried and this doesn't help A full power Off/On make it working again

As mentioned more than 60 devices. A lot of incoming traffic ( several metering equipments )

puddly commented 2 years ago

What is in the debug log when you restart the plugin and it doesn't work?

pipiche38 commented 2 years ago

Here is what I have

pp.zip

here is the log level set

Debug Bellows/Ezsp

requests_logger = logging.getLogger("zigpy")
requests_logger.setLevel(logging.DEBUG)
requests_logger = logging.getLogger("bellows")
requests_logger.setLevel(logging.DEBUG)
requests_logger = logging.getLogger("AppEzsp")
requests_logger.setLevel(logging.DEBUG)
puddly commented 2 years ago

I'm not sure. When EZSP's _handle_reset_request is received, it will log:

Resetting ControllerApplication. Cause: 'NcpResetCode.RESET_WATCHDOG'

After that, the reset task is spawned, which closes the serial port and then will try to call startup. Have you modified startup? You should be seeing more logging as bellows tries to reconnect.

pipiche38 commented 2 years ago

we are still experiencing this issue , when it start, only a full restart of the Pi is fixing the issue (this is based on an Popp shield) . Anything you advice to look ?

It happens on ZCL , but also ZDP commands

pipiche38 commented 2 years ago

up+

pipiche38 commented 2 years ago

2022-07-09 15:34:00,013 DEBUG :get_device raise KeyError ieee: None nwk: fcbd !! 2022-07-09 15:34:40,577 ERROR :NCP entered failed state. Requesting APP controller restart 2022-07-09 15:34:40,579 ERROR :NCP entered failed state. Requesting APP controller restart 2022-07-09 15:34:40,580 ERROR :NCP entered failed state. Requesting APP controller restart 2022-07-09 15:34:40,580 ERROR :NCP entered failed state. Requesting APP controller restart 2022-07-09 15:34:45,500 ERROR :Task exception was never retrieved future: <Task finished coro=<transport_request() done, defined at /home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py:565> exception=TimeoutError()> Traceback (most recent call last): File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 585, in transport_request result, msg = await self.app.request( destination, Profile, Cluster, sEp, dEp, sequence, payload, expect_reply, use_ieee ) File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 777, in request await self._ezsp.setExtendedTimeout(device.ieee, True) File "/usr/lib/python3.7/asyncio/tasks.py", line 423, in wait_for raise futures.TimeoutError() concurrent.futures._base.TimeoutError 2022-07-09 15:34:51,248 ERROR :Task exception was never retrieved

pipiche38 commented 2 years ago

I have been able to get a Elelabs crash with debug information. See here after

2022-07-12 17:49:15,084 DEBUG :Error code: ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT, Version: 2, frame: b'c20251a8bd7e'

To give you some context:

pipiche38 commented 2 years ago

just to keep it open (before a bot close it)