Zwavejs2mqtt: [bug] Log nodes not filtering log

[macf0x]

Checklist:

• [X ] I am not using HomeAssistant. Or: a developer has told me to come here.
• [ X] I have checked the troubleshooting section and my problem is not described there.
• [ X] I have read the changelog problem was not mentioned there.

Build/Run method

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

zwavejs2mqtt version: 2.4.1
zwave-js version: 6.6.3

Describe the bug

Setting a node ID in the Log Nodes option has no effect on the debug or file log output. Entries from other nodes are displayed/logged.

To Reproduce

Steps to reproduce the behavior:

1. Go to Settings and expand Zwave
2. Click on 'Log Nodes'
3. Type in Node ID
4. Click save

Expected behavior

Log file and debug log still contains entries for other node ID's

[macf0x]

I should add restarting to docker container has no impact.

[robertsLando]

Log file and debug log still contains entries for other node ID's

That setting only affect nodejs logging not zwavejs2mqtt logging, does this happen also on zwavejs side?

[macf0x]

If you are referring to the actual log files (exported from the storage tab), no they continue to log all nodes. As far as I can see this log nodes option has no effect.

[robertsLando]

Show me the log files. cc @AlCalzone

[macf0x]

zwavejs_369.log

[macf0x]

That was with Log Nodes 24

[AlCalzone]

Please try with zwave-js 7.0.0 to make sure we're not hunting ghosts

[macf0x]

Happy to give that a go. This option hasn't worked in recent version, as I was seeking to use it to trim down log during debugging.

Just to be clear this option should filter the debug console/tab output, or only the log file?

[AlCalzone]

It should affect all logs

[macf0x]

Was there a specific fix in 7.0.0 for this? I had a search and couldn't see any reference.

As I'm running HA Core + Docker will need to wait for the next release to test.

[robertsLando]

3+ versions are with zwavejs 7

[AlCalzone]

https://github.com/zwave-js/node-zwave-js/blob/master/CHANGELOG.md#bugfixes
first bullet point

[macf0x]

Updated Latest release
zwavejs2mqtt: 3.0.1
zwave-js: 7.0.0

Debug is still ignoring LogNodes setting.

"zwave": {
"port": "/dev/serial/by-id/usb-0658_0200-if00",
"commandsTimeout": 30,
"networkKey": "xxxxxxxxxxxxx",
"logLevel": "debug",
"logToFile": true,
"serverEnabled": true,
"serverPort": 3000,
"logEnabled": true,
"nodeFilter": [
"24"
]
}

2021-03-30 22:10:37.892 INFO ZWAVE: Node 24: value updated: 113-0-Home Security-Sensor status 2 => 2
2021-03-30 22:10:39.257 INFO ZWAVE: Node 24: value updated: 48-0-Any false => true
2021-03-30 22:10:39.284 INFO ZWAVE: Node 24: value updated: 113-0-Home Security-Sensor status 2 => 2
2021-03-30 22:10:43.094 INFO ZWAVE: Node 24: value updated: 113-0-Home Security-unknown 254 => 254
2021-03-30 22:10:44.205 INFO ZWAVE: Node 24: value updated: 113-0-Home Security-unknown 254 => 254
2021-03-30 22:10:46.404 INFO ZWAVE: Node 24: value updated: 48-0-Any true => false
2021-03-30 22:10:46.411 INFO ZWAVE: Node 24: value updated: 113-0-Home Security-Sensor status 2 => 2
2021-03-30 22:10:47.784 INFO ZWAVE: Node 24: value updated: 48-0-Any false => true
2021-03-30 22:10:47.806 INFO ZWAVE: Node 24: value updated: 113-0-Home Security-Sensor status 2 => 2
2021-03-30 22:11:06.584 INFO ZWAVE: Node 4: value updated: 128-0-level 100 => 100
2021-03-30 22:11:06.586 INFO ZWAVE: Node 4: value updated: 128-0-isLow false => false
2021-03-30 22:11:06.792 INFO ZWAVE: Node 4: metadata updated: 49-0-Illuminance
2021-03-30 22:11:06.794 INFO ZWAVE: Node 4: value updated: 49-0-Illuminance 0 => 0
2021-03-30 22:11:08.047 INFO ZWAVE: Node 4: metadata updated: 49-0-Air temperature
2021-03-30 22:11:08.049 INFO ZWAVE: Node 4: value updated: 49-0-Air temperature 19.5 => 19.5
2021-03-30 22:11:08.289 INFO ZWAVE: Node 4: metadata updated: 49-0-Humidity
2021-03-30 22:11:08.291 INFO ZWAVE: Node 4: value updated: 49-0-Humidity 29 => 30
2021-03-30 22:11:13.497 INFO ZWAVE: Node 19: value updated: 50-0-value-66049 1060.955 => 1064.084
2021-03-30 22:11:13.573 INFO ZWAVE: Node 19: value updated: 50-0-value-65537 8770.826 => 8770.842
2021-03-30 22:11:13.679 INFO ZWAVE: Node 19: value updated: 50-1-value-66049 78.013 => 78.579
2021-03-30 22:11:13.775 INFO ZWAVE: Node 19: value updated: 50-2-value-66049 814.862 => 817.226
2021-03-30 22:11:13.862 INFO ZWAVE: Node 19: value updated: 50-3-value-66049 168.08 => 168.279

[robertsLando]

This logs are from zwavejs2mqtt and as I said that option only filters logs on zwavejs side so you should provide logs of it

[AlCalzone]

@robertsLando respecting that flag on the zwavejs2mqtt side wouldn't be that bad I think.

[robertsLando]

Yeah but that would require some changes on logger level as ATM I have no reference of the node instance when a log is created

[macf0x]

zwavejs2mqtt: 3.2.0
zwave-js: 7.1.1

Still same issue.

ZWJS logs don't respect the option either.
00:38:04.859 SERIAL « 0x01090004001603300300d4 (11 bytes) 00:38:04.859 CNTRLR [Node 022] [Binary Sensor] Any: metadata updated [Endpoint 0] 00:38:04.860 CNTRLR [Node 022] [~] [Binary Sensor] Any: true => false [Endpoint 0] 00:38:04.861 SERIAL » [ACK] (0x06) 00:38:40.148 SERIAL « 0x0114000400130e32022174000d98a3000000000000a1 (22 bytes) 00:38:40.148 CNTRLR [Node 019] [~] [Meter] value[66049]: 890.843 => 891.043 [Endpoint 0] 00:38:40.153 CNTRLR [Node 019] [~] [Meter] deltaTime[66049]: 0 => 0 [Endpoint 0] 00:38:40.154 SERIAL » [ACK] (0x06) 00:38:40.212 SERIAL « 0x0114000400130e3202216400849657003c00849649a5 (22 bytes) 00:38:40.212 CNTRLR [Node 019] [~] [Meter] value[65537]: 8689.225 => 8689.239 [Endpoint 0] 00:38:40.214 CNTRLR [Node 019] [~] [Meter] previousValue[65537]: 8689.211 => 8689.225 [Endpoint 0] 00:38:40.214 CNTRLR [Node 019] [~] [Meter] deltaTime[65537]: 60 => 60 [Endpoint 0] 00:38:40.217 SERIAL » [ACK] (0x06) 00:38:40.332 SERIAL « 0x01180004001312600d010032022174000114c600000000000038 (26 bytes) 00:38:40.332 CNTRLR [Node 019] [~] [Meter] value[66049]: 71.22 => 70.854 [Endpoint 1] 00:38:40.334 CNTRLR [Node 019] [~] [Meter] deltaTime[66049]: 0 => 0 [Endpoint 1] 00:38:40.337 SERIAL » [ACK] (0x06) 00:38:40.403 SERIAL « 0x01180004001312600d020032022174000a1733000000000000c6 (26 bytes) 00:38:40.404 CNTRLR [Node 019] [~] [Meter] value[66049]: 660.9 => 661.299 [Endpoint 2] 00:38:40.405 CNTRLR [Node 019] [~] [Meter] deltaTime[66049]: 0 => 0 [Endpoint 2] 00:38:40.406 SERIAL » [ACK] (0x06) 00:38:40.522 SERIAL « 0x01180004001312600d03003202217400026caa0000000000002d (26 bytes) 00:38:40.522 CNTRLR [Node 019] [~] [Meter] value[66049]: 158.723 => 158.89 [Endpoint 3] 00:38:40.524 CNTRLR [Node 019] [~] [Meter] deltaTime[66049]: 0 => 0 [Endpoint 3] 00:38:40.524 SERIAL » [ACK] (0x06) 00:38:40.634 SERIAL « 0x01180004001312600d010032022164000a995f003c000a995ec6 (26 bytes) 00:38:40.635 CNTRLR [Node 019] [~] [Meter] value[65537]: 694.622 => 694.623 [Endpoint 1] 00:38:40.640 CNTRLR [Node 019] [~] [Meter] previousValue[65537]: 694.621 => 694.622 [Endpoint 1] 00:38:40.641 CNTRLR [Node 019] [~] [Meter] deltaTime[65537]: 60 => 60 [Endpoint 1] 00:38:40.641 SERIAL » [ACK] (0x06) 00:38:40.727 SERIAL « 0x01180004001312600d020032022164004e43b3003c004e43a8df (26 bytes) 00:38:40.728 CNTRLR [Node 019] [~] [Meter] value[65537]: 5129.128 => 5129.139 [Endpoint 2] 00:38:40.729 CNTRLR [Node 019] [~] [Meter] previousValue[65537]: 5129.117 => 5129.128 [Endpoint 2] 00:38:40.730 CNTRLR [Node 019] [~] [Meter] deltaTime[65537]: 60 => 60 [Endpoint 2] 00:38:40.730 SERIAL » [ACK] (0x06) 00:38:40.816 SERIAL « 0x01180004001312600d030032022164002bb945003c002bb943c3 (26 bytes) 00:38:40.817 CNTRLR [Node 019] [~] [Meter] value[65537]: 2865.475 => 2865.477 [Endpoint 3] 00:38:40.818 CNTRLR [Node 019] [~] [Meter] previousValue[65537]: 2865.473 => 2865.475 [Endpoint 3] 00:38:40.821 CNTRLR [Node 019] [~] [Meter] deltaTime[65537]: 60 => 60 [Endpoint 3] 00:38:40.822 SERIAL » [ACK] (0x06) 00:38:50.540 SERIAL « 0x010900040016033003ff2b (11 bytes) 00:38:50.541 CNTRLR [Node 022] [Binary Sensor] Any: metadata updated [Endpoint 0] 00:38:50.546 CNTRLR [Node 022] [~] [Binary Sensor] Any: false => true [Endpoint 0] 00:38:50.546 SERIAL » [ACK] (0x06)

[AlCalzone]

Looks like this only affects the value events, let me check.