Strange behavior after an NVM backup

[kpine]

I perfomed an NVM backup, and that much seemed to work,. Afterwards I noticed strange behavior though. One of my dimmer switches starts sending multiple broadcast multilevel CC reports after a refresh. The normal behavior is just a single reply.

Log after NVM backup:

2021-11-14T06:49:13.366Z SERIAL » 0x010f00a901020326012825000000001665                                (17 bytes)
2021-11-14T06:49:13.368Z DRIVER » [Node 002] [REQ] [SendDataBridge]
                                  │ source node id:   1
                                  │ transmit options: 0x25
                                  │ route:            0, 0, 0, 0
                                  │ callback id:      22
                                  └─[MultilevelSwitchCCSet]
                                      target value: 40
2021-11-14T06:49:13.375Z SERIAL « [ACK]                                                                   (0x06)
2021-11-14T06:49:13.377Z SERIAL « 0x010401a90152                                                       (6 bytes)
2021-11-14T06:49:13.379Z SERIAL » [ACK]                                                                   (0x06)
2021-11-14T06:49:13.380Z DRIVER « [RES] [SendDataBridge]
                                    was sent: true
2021-11-14T06:49:13.394Z SERIAL « 0x011d00a91600000100c07f7f7f7f01010300000000020100007f7f7f7f7fe3    (31 bytes)
2021-11-14T06:49:13.395Z SERIAL » [ACK]                                                                   (0x06)
2021-11-14T06:49:13.396Z DRIVER « [REQ] [SendDataBridge]
                                    callback id:     22
                                    transmit status: OK
2021-11-14T06:49:13.402Z CNTRLR   [Node 002] [~] [Multilevel Switch] currentValue: 25 => 40         [Endpoint 0]
2021-11-14T06:49:18.415Z SERIAL » 0x010e00a901020226022500000000174f                                  (16 bytes)
2021-11-14T06:49:18.416Z DRIVER » [Node 002] [REQ] [SendDataBridge]
                                  │ source node id:   1
                                  │ transmit options: 0x25
                                  │ route:            0, 0, 0, 0
                                  │ callback id:      23
                                  └─[MultilevelSwitchCCGet]
2021-11-14T06:49:18.423Z SERIAL « [ACK]                                                                   (0x06)
2021-11-14T06:49:18.426Z SERIAL « 0x010401a90152                                                       (6 bytes)
2021-11-14T06:49:18.428Z SERIAL » [ACK]                                                                   (0x06)
2021-11-14T06:49:18.429Z DRIVER « [RES] [SendDataBridge]
                                    was sent: true
2021-11-14T06:49:18.442Z SERIAL « 0x011d00a91700000100c07f7f7f7f01010300000000020100007f7f7f7f7fe2    (31 bytes)
2021-11-14T06:49:18.443Z SERIAL » [ACK]                                                                   (0x06)
2021-11-14T06:49:18.444Z DRIVER « [REQ] [SendDataBridge]
                                    callback id:     23
                                    transmit status: OK
2021-11-14T06:49:19.945Z SERIAL « 0x010c00a81401020326032800df9d                                      (14 bytes)
2021-11-14T06:49:19.949Z CNTRLR   [Node 002] [~] [Multilevel Switch] currentValue: 40 => 40         [Endpoint 0]
2021-11-14T06:49:19.956Z SERIAL » [ACK]                                                                   (0x06)
2021-11-14T06:49:19.960Z DRIVER « [Node 002] [REQ] [BridgeApplicationCommand]
                                  │ type:        broadcast
                                  │ target node: 255
                                  └─[MultilevelSwitchCCReport]
                                      current value: 40
2021-11-14T06:49:20.142Z SERIAL « 0x010c00a81401020326032800e4a6                                      (14 bytes)
2021-11-14T06:49:20.144Z CNTRLR   [Node 002] [~] [Multilevel Switch] currentValue: 40 => 40         [Endpoint 0]
2021-11-14T06:49:20.147Z SERIAL » [ACK]                                                                   (0x06)
2021-11-14T06:49:20.148Z DRIVER « [Node 002] [REQ] [BridgeApplicationCommand]
                                  │ type:        broadcast
                                  │ target node: 255
                                  └─[MultilevelSwitchCCReport]
                                      current value: 40
2021-11-14T06:49:20.243Z SERIAL « 0x010c00a81401020326032800d496                                      (14 bytes)
2021-11-14T06:49:20.244Z CNTRLR   [Node 002] [~] [Multilevel Switch] currentValue: 40 => 40         [Endpoint 0]
2021-11-14T06:49:20.247Z SERIAL » [ACK]                                                                   (0x06)
2021-11-14T06:49:20.249Z DRIVER « [Node 002] [REQ] [BridgeApplicationCommand]
                                  │ type:        broadcast
                                  │ target node: 255
                                  └─[MultilevelSwitchCCReport]
                                      current value: 40
2021-11-14T06:49:20.474Z SERIAL « 0x010c00a81401020326032800dd9f                                      (14 bytes)
2021-11-14T06:49:20.480Z CNTRLR   [Node 002] [~] [Multilevel Switch] currentValue: 40 => 40         [Endpoint 0]
2021-11-14T06:49:20.484Z SERIAL » [ACK]                                                                   (0x06)
2021-11-14T06:49:20.486Z DRIVER « [Node 002] [REQ] [BridgeApplicationCommand]
                                  │ type:        broadcast
                                  │ target node: 255
                                  └─[MultilevelSwitchCCReport]
                                      current value: 40

Logs of normal behavior:

2021-11-14T06:54:53.924Z SERIAL » 0x010f00a901020326011925000000001052                                (17 bytes)
2021-11-14T06:54:53.925Z DRIVER » [Node 002] [REQ] [SendDataBridge]
                                  │ source node id:   1
                                  │ transmit options: 0x25
                                  │ route:            0, 0, 0, 0
                                  │ callback id:      16
                                  └─[MultilevelSwitchCCSet]
                                      target value: 25
2021-11-14T06:54:53.933Z SERIAL « [ACK]                                                                   (0x06)
2021-11-14T06:54:53.934Z SERIAL « 0x010401a90152                                                       (6 bytes)
2021-11-14T06:54:53.936Z SERIAL » [ACK]                                                                   (0x06)
2021-11-14T06:54:53.937Z DRIVER « [RES] [SendDataBridge]
                                    was sent: true
2021-11-14T06:54:53.948Z SERIAL « 0x011d00a91000000100c07f7f7f7f00000300000000030100007f7f7f7f7fe4    (31 bytes)
2021-11-14T06:54:53.949Z SERIAL » [ACK]                                                                   (0x06)
2021-11-14T06:54:53.950Z DRIVER « [REQ] [SendDataBridge]
                                    callback id:     16
                                    transmit status: OK
2021-11-14T06:54:53.956Z CNTRLR   [Node 002] [~] [Multilevel Switch] currentValue: 50 => 25         [Endpoint 0]
2021-11-14T06:54:58.977Z SERIAL » 0x010e00a9010202260225000000001149                                  (16 bytes)
2021-11-14T06:54:58.978Z DRIVER » [Node 002] [REQ] [SendDataBridge]
                                  │ source node id:   1
                                  │ transmit options: 0x25
                                  │ route:            0, 0, 0, 0
                                  │ callback id:      17
                                  └─[MultilevelSwitchCCGet]
2021-11-14T06:54:58.985Z SERIAL « [ACK]                                                                   (0x06)
2021-11-14T06:54:58.987Z SERIAL « 0x010401a90152                                                       (6 bytes)
2021-11-14T06:54:58.989Z SERIAL » [ACK]                                                                   (0x06)
2021-11-14T06:54:58.990Z DRIVER « [RES] [SendDataBridge]
                                    was sent: true
2021-11-14T06:54:59.001Z SERIAL « 0x011d00a91100000100c17f7f7f7f00000300000000030100007f7f7f7f7fe4    (31 bytes)
2021-11-14T06:54:59.002Z SERIAL » [ACK]                                                                   (0x06)
2021-11-14T06:54:59.003Z DRIVER « [REQ] [SendDataBridge]
                                    callback id:     17
                                    transmit status: OK
2021-11-14T06:54:59.008Z SERIAL « 0x010c00a80001020326031900bfd8                                      (14 bytes)
2021-11-14T06:54:59.011Z CNTRLR   [Node 002] [~] [Multilevel Switch] currentValue: 25 => 25         [Endpoint 0]
2021-11-14T06:54:59.016Z SERIAL » [ACK]                                                                   (0x06)
2021-11-14T06:54:59.020Z DRIVER « [Node 002] [REQ] [BridgeApplicationCommand]
                                  └─[MultilevelSwitchCCReport]
                                      current value: 25

I noticed this with another binary switch as well. Repeated reports but not necessarily broadcast. However, it seemed to go back to normal on its own. Otherwise, a restart of z2m fixes the problem right away.

Another thing I noticed, in the z2m control panel all of the nodes' battery icons become "Unknown". It took a re-interview to get the power info back.

Not sure if this is some kind of bug? I could send the entire logs of you want. I wasn't sure if the NVM logging was a dump of the actual NVM, which I might not want to publish?

[AlCalzone]

Could it be that node 2 tried to reach the controller while the backup was going on? During the backup the radio is off, so the node wouldn't get a response or even an ACK. It might have considered its known route to be broken and gone into panic mode (broadcasting).

Another thing I noticed, in the z2m control panel all of the nodes' battery icons become "Unknown". It took a re-interview to get the power info back.

I'm not sure what would cause this. @robertsLando any idea?

[kpine]

Could it be that node 2 tried to reach the controller while the backup was going on? During the backup the radio is off, so the node wouldn't get a response or even an ACK. It might have considered its known route to be broken and gone into panic mode (broadcasting).

Unlikely that happened, but I don't know for certain. It is a reasonable explanation though. These switches usually never communicate with the controller on their own, and it was at night when no one was using them. I repeated it twice, so I think the chance of this node tried to communicate the controller during both of those times is pretty slim. I guess a next step might be to try a Zniffer and see what it observes? Does it make sense that a restart of z2m fixed it?

[AlCalzone]

A restart of z2m will ping the node, which means it will now have a working route to reach the controller.
Having Zniffer traces would be good

[kpine]

I finally got around to capturing the traffic. No obvious reason to me why things go bad. The only weird thing I see is that the controller seems to downgrade from 100K to 40K speeds. Can I send you the capture?

[AlCalzone]

Sure, just send it to the e-mail in my profile (or via Discord/Slack)

[robertsLando]

I'm not sure what would cause this. @robertsLando any idea?

I have a feeling it could be sometihng related to then changes introduced to support battery levels, BTW I need some logs in order to check what's going on