[bug] upgrading from 3.4.0 to 4.0.3 results in excessive logging

[billimek]

Version

Build/Run method

• [x] Docker
• [ ] PKG
• [ ] Manually built (git clone - npm install - npm run build )

Zwave2Mqtt version: 4.0.3 Openzwave Version: 1.6.0

Describe the bug

After upgrading zwave2mqtt from 3.4.0 to 4.0.3 and toggling a device off-on (via MQTT) results in an endless logging cycle of the same message, resulting in a non-trivial logfile growth on the filesystem (approx 30KB/sec growth rate)

To Reproduce Steps to reproduce the behavior:

1. Install zwave2mqtt 4.0.3
2. Send MQTT message to toggle the power state of a zwave switch
3. Observe logs emitting from the zwave2mqtt container
4. Observe OZW_Log.txt filesize grwoth rate

Expected behavior

The logs should not repeatedly log the same thing indefinitley

Additional context Add any other context about the problem here.

Screenshot illustrating the OZW_Log.txt file growth rate with timestamps

Snippet from logfile of the data that gets written over and over:

2020-08-31T13:50:53.605Z z2m:Zwave zwave node 7: changed: 37-1-1:Target State:true -> true
2020-08-31 09:50:53.810 Info, Timer: delayed event
2020-08-31 09:50:53.810 Info, Node007, Sending Get to Refresh Value after Target Check
2020-08-31 09:50:53.810 Detail, Node007, Queuing (Send) SwitchBinaryCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x25, 0x02, 0x25, 0xfd, 0x1f
2020-08-31 09:50:53.811 Detail, Timer: waiting with timeout 38 ms
2020-08-31 09:50:53.811 Detail,
2020-08-31 09:50:53.813 Info, Node007, Sending (Send) message (Callback ID=0xfd, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x25, 0x02, 0x25, 0xfd, 0x1f
2020-08-31 09:50:53.813 Info, Node007, Encrypted Flag is 0
2020-08-31 09:50:53.820 Detail, Node007,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-08-31 09:50:53.820 Detail, Node007,   ZW_SEND_DATA delivered to Z-Wave stack
2020-08-31 09:50:53.837 Detail, Node007,   Received: 0x01, 0x07, 0x00, 0x13, 0xfd, 0x00, 0x00, 0x02, 0x14
2020-08-31 09:50:53.837 Detail, Node007,   ZW_SEND_DATA Request with callback ID 0xfd received (expected 0xfd)
2020-08-31 09:50:53.837 Info, Node007, Request RTT 24 Average Request RTT 23
2020-08-31 09:50:53.837 Detail, Node007,   Expected callbackId was received
2020-08-31 09:50:53.849 Detail, Node007,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x07, 0x03, 0x25, 0x03, 0x00, 0xd0
2020-08-31 09:50:53.849 Detail,
2020-08-31 09:50:53.849 Info, Node007, Response RTT 35 Average Response RTT 35
2020-08-31 09:50:53.849 Info, Node007, Received SwitchBinary report from node 7: level=Off
2020-08-31 09:50:53.849 Detail, Node007, Value Updated: old value=true, new value=false, type=bool
2020-08-31 09:50:53.849 Detail, Node007,        Target Value is Set to true
2020-08-31 09:50:53.849 Info, Timer: adding event in 250 ms
2020-08-31 09:50:53.849 Detail, Node007, Value Updated: old value=true, new value=true, type=bool
2020-08-31 09:50:53.849 Detail, Node007, Changes to this value are not verified
2020-08-31 09:50:53.850 Detail, Node007,   Expected reply and command class was received
2020-08-31 09:50:53.850 Detail, Node007,   Message transaction complete
2020-08-31 09:50:53.850 Detail,
2020-08-31 09:50:53.850 Detail, Node007, Removing current message
2020-08-31 09:50:53.851 Detail, Node007, Notification: ValueRefreshed CC: COMMAND_CLASS_SWITCH_BINARY Instance: 1 Index: 1
2020-08-31 09:50:53.851 Info, Timer: delayed event
2020-08-31 09:50:53.851 Info, Node007, Sending Get to Refresh Value after Target Check
2020-08-31 09:50:53.851 Detail, Node007, Queuing (Send) SwitchBinaryCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x25, 0x02, 0x25, 0xfe, 0x1c
2020-08-31 09:50:53.851 Detail, Timer: waiting with timeout 249 ms
2020-08-31 09:50:53.851 Detail,
2020-08-31 09:50:53.852 Info, Node007, Sending (Send) message (Callback ID=0xfe, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x25, 0x02, 0x25, 0xfe, 0x1c
2020-08-31 09:50:53.852 Info, Node007, Encrypted Flag is 0

• This seems similar perhaps to #692 but I don't have the same device as described above and this is certainly new behavior with an upgrade (in other words, I can get back to a working state by downgrading to 3.4.0)
• The logfile behavior is the same as #686 but the content of the messages are different

[robertsLando]

@billimek No changes in logs on my side except the bug that has been solved with custom devices. Maybe the new ozw version logs more? Anyway I suggest to disable ozw logging and keep it enabled only for debug purposes

[billimek]

@robertsLando that is indeed a clever way to solve this. Disabling logging solve this issue for me. Ok for me to close this issue?

[robertsLando]

@billimek Yes :)