zwave-js
Consistent timeouts trying to upgrade firmware on two identical devices
I've tried dozens of times to upgrade the firmware on these two Aeotec ZW111 nano dimmers. They've been a little weird lately already, which is why I was interested in a firmware upgrade. By weird, I mean they've gone "offline" in some way, not officially, but unable to control and require a hard power off (at the breaker box) in order to get them operable again. They're working fine now and I've tried hard power offs to resolve this issue. The controller is < 1m away from these devices.
Debug log of the last attempt (Node 28) attached. Snip of the last couple successful fragments up to the timeout pasted below.
It's a pretty consistent pattern, other than the amount of progress it makes varies from <1% to >15% before it says "timed out".
I've tried on 3.0.2 and 3.1.0. Hardware is Razberry 7 pro.
2024-01-13T21:08:10.528Z CNTRLR » [Node 028] Sending firmware fragment 28 / 6240 2024-01-13T21:08:10.532Z DRIVER all queues busy 2024-01-13T21:08:10.535Z SERIAL » 0x011000a90001001c02984025000000009337 (18 bytes) 2024-01-13T21:08:10.535Z DRIVER » [Node 028] [REQ] [SendDataBridge] │ source node id: 1 │ transmit options: 0x25 │ callback id: 147 └─[SecurityCCNonceGet] 2024-01-13T21:08:10.544Z SERIAL « [ACK] (0x06) 2024-01-13T21:08:10.545Z SERIAL « 0x010401a90152 (6 bytes) 2024-01-13T21:08:10.545Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:10.546Z DRIVER « [RES] [SendDataBridge] was sent: true 2024-01-13T21:08:10.555Z SERIAL « 0x011d00a99300000100d37f7f7f7f00000300000000030100007f7f7f7f7f74 (31 bytes) 2024-01-13T21:08:10.556Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:10.557Z DRIVER « [REQ] [SendDataBridge] callback id: 147 transmit status: OK, took 10 ms routing attempts: 1 protocol & route speed: Z-Wave, 100 kbit/s routing scheme: LWR ACK RSSI: -45 dBm ACK channel no.: 0 TX channel no.: 0 2024-01-13T21:08:10.564Z SERIAL « 0x011800a8000001001c0a9880ad61141f709c1f5000d3007f7ff7 (26 bytes) 2024-01-13T21:08:10.565Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:10.566Z DRIVER « [Node 028] [REQ] [BridgeApplicationCommand] │ RSSI: -45 dBm └─[SecurityCCNonceReport] nonce: 0xad61141f709c1f50 2024-01-13T21:08:10.569Z SERIAL » 0x013c00a90001001c2e988121f8559ad2ba2fa2f026fe628638f9ca335ef6c5057 (62 bytes) 1f6518e523f0f7c8b903f9a6047add51748bf06a8f3c025000000009444 2024-01-13T21:08:10.570Z DRIVER » [Node 028] [REQ] [SendDataBridge] │ source node id: 1 │ transmit options: 0x25 │ callback id: 148 └─[SecurityCCCommandEncapsulation] │ nonce id: 173 └─[FirmwareUpdateMetaDataCCReport] report #: 28 is last: false 2024-01-13T21:08:10.580Z SERIAL « [ACK] (0x06) 2024-01-13T21:08:10.581Z SERIAL « 0x010401a90152 (6 bytes) 2024-01-13T21:08:10.581Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:10.583Z DRIVER « [RES] [SendDataBridge] was sent: true 2024-01-13T21:08:10.612Z SERIAL « 0x011d00a99400000300d37f7f7f7f00000300000000030100007f7f7f7f7f71 (31 bytes) 2024-01-13T21:08:10.613Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:10.615Z DRIVER « [REQ] [SendDataBridge] callback id: 148 transmit status: OK, took 30 ms routing attempts: 1 protocol & route speed: Z-Wave, 100 kbit/s routing scheme: LWR ACK RSSI: -45 dBm ACK channel no.: 0 TX channel no.: 0 2024-01-13T21:08:10.617Z DRIVER all queues idle 2024-01-13T21:08:10.619Z SERIAL « 0x011800a8000001001c0a9880ad61141f709c1f5000d3007f7ff7 (26 bytes) 2024-01-13T21:08:10.621Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:10.623Z DRIVER « [Node 028] [REQ] [BridgeApplicationCommand] │ RSSI: -45 dBm └─[SecurityCCNonceReport] nonce: 0xad61141f709c1f50 2024-01-13T21:08:10.631Z SERIAL « 0x011000a8000001001c02984000d4007f7f54 (18 bytes) 2024-01-13T21:08:10.632Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:10.633Z DRIVER « [Node 028] [REQ] [BridgeApplicationCommand] │ RSSI: -44 dBm └─[SecurityCCNonceGet] 2024-01-13T21:08:10.636Z DRIVER all queues busy 2024-01-13T21:08:10.638Z SERIAL » 0x011800a90001001c0a9880e43d3779505002f9050000000095bd (26 bytes) 2024-01-13T21:08:10.639Z DRIVER » [Node 028] [REQ] [SendDataBridge] │ source node id: 1 │ transmit options: 0x05 │ callback id: 149 └─[SecurityCCNonceReport] nonce: 0xe43d3779505002f9 2024-01-13T21:08:10.642Z SERIAL « [ACK] (0x06) 2024-01-13T21:08:10.644Z SERIAL « 0x010401a90152 (6 bytes) 2024-01-13T21:08:10.645Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:10.646Z DRIVER « [RES] [SendDataBridge] was sent: true 2024-01-13T21:08:10.660Z SERIAL « 0x011000a8000001001c02984000d3007f7f53 (18 bytes) 2024-01-13T21:08:10.661Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:10.663Z DRIVER « [Node 028] [REQ] [BridgeApplicationCommand] │ RSSI: -45 dBm └─[SecurityCCNonceGet] 2024-01-13T21:08:10.665Z CNTRLR [Node 028] in the process of replying to a NonceGet, won't send another NonceR eport 2024-01-13T21:08:10.822Z SERIAL « 0x011d00a99500001101d77f7f7f7f00000420000000030400007f7f7f7f7f45 (31 bytes) 2024-01-13T21:08:10.823Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:10.825Z DRIVER « [REQ] [SendDataBridge] callback id: 149 transmit status: OK, took 170 ms repeater node IDs: 32 routing attempts: 4 protocol & route speed: Z-Wave, 100 kbit/s routing scheme: NLWR ACK RSSI: -41 dBm ACK RSSI on repeaters: N/A ACK channel no.: 0 TX channel no.: 0 2024-01-13T21:08:10.828Z DRIVER all queues idle 2024-01-13T21:08:10.887Z SERIAL « 0x012700a8000001001c199881d453cdbd904978e15480ddef099de4100742b8089 (41 bytes) c7b4b00d3007f7fd6 2024-01-13T21:08:10.890Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:10.893Z DRIVER « [Node 028] [REQ] [BridgeApplicationCommand] │ RSSI: -45 dBm └─[SecurityCCCommandEncapsulation] │ sequenced: false └─[FirmwareUpdateMetaDataCCGet] total # of reports: 1 report number: 29 2024-01-13T21:08:10.894Z CNTRLR » [Node 028] Sending firmware fragment 29 / 6240 2024-01-13T21:08:10.900Z DRIVER all queues busy 2024-01-13T21:08:10.903Z SERIAL » 0x013c00a90001001c2e9881d6f3de8b1df8573792e327dbe01e778d72898ba0d5e (62 bytes) 096e99b717265e2b7e02315e963ad32b422d1902d01ed25000000009668 2024-01-13T21:08:10.904Z DRIVER » [Node 028] [REQ] [SendDataBridge] │ source node id: 1 │ transmit options: 0x25 │ callback id: 150 └─[SecurityCCCommandEncapsulation] │ nonce id: 173 └─[FirmwareUpdateMetaDataCCReport] report #: 29 is last: false 2024-01-13T21:08:10.910Z SERIAL « [ACK] (0x06) 2024-01-13T21:08:10.915Z SERIAL « 0x010401a90152 (6 bytes) 2024-01-13T21:08:10.916Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:10.917Z DRIVER « [RES] [SendDataBridge] was sent: true 2024-01-13T21:08:12.632Z SERIAL « 0x011d00a9960000a801d87f7f7f7f01010520000000020a201c7f7f7f7f7fc2 (31 bytes) 2024-01-13T21:08:12.634Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:12.639Z DRIVER « [REQ] [SendDataBridge] callback id: 150 transmit status: OK, took 1680 ms repeater node IDs: 32 routing attempts: 10 protocol & route speed: Z-Wave, 40 kbit/s routing scheme: Auto Route ACK RSSI: -40 dBm ACK RSSI on repeaters: N/A ACK channel no.: 1 TX channel no.: 1 route failed here: 32 -> 28 2024-01-13T21:08:12.648Z DRIVER all queues idle 2024-01-13T21:08:26.786Z SERIAL « 0x011000a8000001001c02984000d8007f7f58 (18 bytes) 2024-01-13T21:08:26.790Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:26.795Z DRIVER « [Node 028] [REQ] [BridgeApplicationCommand] │ RSSI: -40 dBm └─[SecurityCCNonceGet] 2024-01-13T21:08:26.799Z DRIVER all queues busy 2024-01-13T21:08:26.802Z SERIAL » 0x011800a90001001c0a988063d763924e2018ec0500000000970c (26 bytes) 2024-01-13T21:08:26.803Z DRIVER » [Node 028] [REQ] [SendDataBridge] │ source node id: 1 │ transmit options: 0x05 │ callback id: 151 └─[SecurityCCNonceReport] nonce: 0x63d763924e2018ec 2024-01-13T21:08:26.806Z SERIAL « [ACK] (0x06) 2024-01-13T21:08:26.809Z SERIAL « 0x010401a90152 (6 bytes) 2024-01-13T21:08:26.810Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:26.812Z DRIVER « [RES] [SendDataBridge] was sent: true 2024-01-13T21:08:26.915Z SERIAL « 0x011d00a99700000a01d87f7f7f7f01010320000000020100007f7f7f7f7f50 (31 bytes) 2024-01-13T21:08:26.916Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:26.918Z DRIVER « [REQ] [SendDataBridge] callback id: 151 transmit status: OK, took 100 ms repeater node IDs: 32 routing attempts: 1 protocol & route speed: Z-Wave, 40 kbit/s routing scheme: LWR ACK RSSI: -40 dBm ACK RSSI on repeaters: N/A ACK channel no.: 1 TX channel no.: 1 2024-01-13T21:08:26.923Z DRIVER all queues idle 2024-01-13T21:08:27.007Z SERIAL « 0x012b00a8000001001c1d9881717d379578e412e664b8ebe8187baaa580f863595 (45 bytes) 6a7cfd8a0355a00d8007f7fa3 2024-01-13T21:08:27.011Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:27.016Z DRIVER « [Node 028] [REQ] [BridgeApplicationCommand] │ RSSI: -40 dBm └─[SecurityCCCommandEncapsulation] │ sequenced: false └─[ConfigurationCCReport] [INVALID] 2024-01-13T21:08:27.017Z CNTRLR « [Node 028] TODO: no handler for application command 2024-01-13T21:08:31.925Z DRIVER all queues busy 2024-01-13T21:08:31.932Z SERIAL » 0x0103003bc7 (5 bytes) 2024-01-13T21:08:31.933Z DRIVER » [REQ] [GetBackgroundRSSI] 2024-01-13T21:08:31.936Z SERIAL « [ACK] (0x06) 2024-01-13T21:08:31.937Z SERIAL « 0x0107013b9d9a9a7f20 (9 bytes) 2024-01-13T21:08:31.939Z SERIAL » [ACK] (0x06) 2024-01-13T21:08:31.941Z DRIVER « [RES] [GetBackgroundRSSI] channel 0: -99 dBm channel 1: -102 dBm channel 2: -102 dBm 2024-01-13T21:08:31.944Z DRIVER all queues idle 2024-01-13T21:09:01.926Z DRIVER all queues busy 2024-01-13T21:09:01.930Z SERIAL » 0x0103003bc7 (5 bytes) 2024-01-13T21:09:01.931Z DRIVER » [REQ] [GetBackgroundRSSI] 2024-01-13T21:09:01.934Z SERIAL « [ACK] (0x06) 2024-01-13T21:09:01.936Z SERIAL « 0x0107013b9e9a9a7f23 (9 bytes) 2024-01-13T21:09:01.937Z SERIAL » [ACK] (0x06) 2024-01-13T21:09:01.940Z DRIVER « [RES] [GetBackgroundRSSI] channel 0: -98 dBm channel 1: -102 dBm channel 2: -102 dBm 2024-01-13T21:09:01.944Z DRIVER all queues idle 2024-01-13T21:09:31.926Z DRIVER all queues busy 2024-01-13T21:09:31.931Z SERIAL » 0x0103003bc7 (5 bytes) 2024-01-13T21:09:31.933Z DRIVER » [REQ] [GetBackgroundRSSI] 2024-01-13T21:09:31.936Z SERIAL « [ACK] (0x06) 2024-01-13T21:09:31.938Z SERIAL « 0x0107013b9c98987f21 (9 bytes) 2024-01-13T21:09:31.940Z SERIAL » [ACK] (0x06) 2024-01-13T21:09:31.943Z DRIVER « [RES] [GetBackgroundRSSI] channel 0: -100 dBm channel 1: -104 dBm channel 2: -104 dBm 2024-01-13T21:09:31.947Z DRIVER all queues idle 2024-01-13T21:10:01.927Z DRIVER all queues busy 2024-01-13T21:10:01.936Z SERIAL » 0x0103003bc7 (5 bytes) 2024-01-13T21:10:01.937Z DRIVER » [REQ] [GetBackgroundRSSI] 2024-01-13T21:10:01.940Z SERIAL « [ACK] (0x06) 2024-01-13T21:10:01.941Z SERIAL « 0x0107013b9c99997f21 (9 bytes) 2024-01-13T21:10:01.944Z SERIAL » [ACK] (0x06) 2024-01-13T21:10:01.948Z DRIVER « [RES] [GetBackgroundRSSI] channel 0: -100 dBm channel 1: -103 dBm channel 2: -103 dBm 2024-01-13T21:10:01.953Z DRIVER all queues idle 2024-01-13T21:10:12.647Z CNTRLR [Node 028] Firmware update timed out 2024-01-13T21:10:12.649Z CNTRLR « [Node 028] Firmware update (part 1 / 1) failed with status Error_Timeout
