Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

logging: undefined namespace when logging string with format specifiers eg %d #22935

Closed
ghoz opened this issue Jun 4, 2024 · 2 comments
Closed

logging: undefined namespace when logging string with format specifiers eg %d #22935

ghoz opened this issue Jun 4, 2024 · 2 comments
Labels
problem Something isn't working

Comments

@ghoz
Copy link
Contributor

ghoz commented Jun 4, 2024

What happened?

Looking at the debug logs , sumbled upon an oddity with the new namespace logging ouputting an undefined:

z2m 1.37.1

[2024-06-04 07:45:04] debug:    z2m: Received MQTT message on 'homeassistant/sensor/xxxx_0xieeeAddr/coordinator_version/config' with data '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","device":{"hw_version":"zStack3x0 20230507","identifiers":["zigbee2mqtt_bridge_0xieeeAddr"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.37.1"},"enabled_by_default":false,"entity_category":"diagnostic","icon":"mdi:chip","name":"Coordinator version","object_id":"zigbee2mqtt_bridge_coordinator_version","origin":{"name":"Zigbee2MQTT","sw":"1.37.1","url":"https://www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/bridge/info","unique_id":"bridge_0xieeeAddr_coordinator_version_zigbee2mqtt","value_template":"{{ value_json.coordinator.meta.revision }}"}'
[2024-06-04 07:45:04] debug:    undefined: Received MQTT message on 'homeassistant/sensor/xxxx_0xieeeAddr/network_map/config' with data '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","device":{"hw_version":"zStack3x0 20230507","identifiers":["zigbee2mqtt_bridge_0xieeeAddr"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.37.1"},"enabled_by_default":false,"entity_category":"diagnostic","json_attributes_template":"{{ value_json.data.value | tojson }}","json_attributes_topic":"zigbee2mqtt/bridge/response/networkmap","name":"Network map","object_id":"zigbee2mqtt_bridge_network_map","origin":{"name":"Zigbee2MQTT","sw":"1.37.1","url":"https://www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/bridge/response/networkmap","unique_id":"bridge_0xieeeAddr_network_map_zigbee2mqtt","value_template":"{{ now().strftime('%Y-%m-%d %H:%M:%S') }}"}'
[2024-06-04 07:45:04] debug:    z2m: Received MQTT message on 'homeassistant/sensor/xxxx_0xieeeAddr/permit_join_timeout/config' with data '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","device":{"hw_version":"zStack3x0 20230507","identifiers":["zigbee2mqtt_bridge_0xieeeAddr"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.37.1"},"device_class":"duration","entity_category":"diagnostic","name":"Permit join timeout","object_id":"zigbee2mqtt_bridge_permit_join_timeout","origin":{"name":"Zigbee2MQTT","sw":"1.37.1","url":"https://www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/bridge/info","unique_id":"bridge_0xieeeAddr_permit_join_timeout_zigbee2mqtt","unit_of_measurement":"s","value_template":"{{ iif(value_json.permit_join_timeout is defined, value_json.permit_join_timeout, None) }}"}'

z2m 1.38.0

[2024-06-04 08:00:49] info:     z2m:mqtt: MQTT publish: topic 'homeassistant/sensor/xxxx_0xieeeAddr/coordinator_version/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","device":{"hw_version":"zStack3x0 20230507","identifiers":["zigbee2mqtt_bridge_0xieeeAddr"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.38.0"},"enabled_by_default":false,"entity_category":"diagnostic","icon":"mdi:chip","name":"Coordinator version","object_id":"zigbee2mqtt_bridge_coordinator_version","origin":{"name":"Zigbee2MQTT","sw":"1.38.0","url":"https://www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/bridge/info","unique_id":"bridge_0xieeeAddr_coordinator_version_zigbee2mqtt","value_template":"{{ value_json.coordinator.meta.revision }}"}'
[2024-06-04 08:00:49] info:     undefined: MQTT publish: topic 'homeassistant/sensor/xxxx_0xieeeAddr/network_map/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","device":{"hw_version":"zStack3x0 20230507","identifiers":["zigbee2mqtt_bridge_0xieeeAddr"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.38.0"},"enabled_by_default":false,"entity_category":"diagnostic","json_attributes_template":"{{ value_json.data.value | tojson }}","json_attributes_topic":"zigbee2mqtt/bridge/response/networkmap","name":"Network map","object_id":"zigbee2mqtt_bridge_network_map","origin":{"name":"Zigbee2MQTT","sw":"1.38.0","url":"https://www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/bridge/response/networkmap","unique_id":"bridge_0xieeeAddr_network_map_zigbee2mqtt","value_template":"{{ now().strftime('%Y-%m-%d %H:%M:%S') }}"}'
[2024-06-04 08:00:49] info:     z2m:mqtt: MQTT publish: topic 'homeassistant/sensor/xxxx_0xieeeAddr/permit_join_timeout/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","device":{"hw_version":"zStack3x0 20230507","identifiers":["zigbee2mqtt_bridge_0xieeeAddr"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.38.0"},"device_class":"duration","entity_category":"diagnostic","name":"Permit join timeout","object_id":"zigbee2mqtt_bridge_permit_join_timeout","origin":{"name":"Zigbee2MQTT","sw":"1.38.0","url":"https://www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/bridge/info","unique_id":"bridge_0xieeeAddr_permit_join_timeout_zigbee2mqtt","unit_of_measurement":"s","value_template":"{{ iif(value_json.permit_join_timeout is defined, value_json.permit_join_timeout, None) }}"}'

What did you expect to happen?

I expected that the namespace would be used

How to reproduce it (minimal and precise)

  1. Enable debug logs, at least for the z2m:mqtt namespace
  2. Restart z2m
  3. grep 'network_map' zigbee2mqtt.log
  4. ponder at life

Zigbee2MQTT version

1.38.0

Adapter firmware version

20230507

Adapter

Sonoff ZBDongle-P

Setup

container on pi3

Debug log

see above
@ghoz ghoz added the problem Something isn't working label Jun 4, 2024
@ghoz
Copy link
Contributor Author

ghoz commented Jun 4, 2024 •
edited
Loading

Doing some tests to figure this one out, we do indeed have a weird situation with specifier strings %d %s etc and it happens to be used in the date format of the network_map discovery

modified test.logger.js 
    it('Logs special chars', () => {
        logger.setLevel('debug');

        const logSpy = jest.spyOn(logger.winston, 'log');
        consoleWriteSpy.mockClear();
        let i = 1;

        logger.debug('default namespace');
        expect(logSpy).toHaveBeenLastCalledWith('debug', 'default namespace', {namespace: 'z2m'});
        expect(consoleWriteSpy).toHaveBeenCalledTimes(i++);
        logger.debug('specific namespace','z2m:mqtt');
        expect(logSpy).toHaveBeenLastCalledWith('debug', 'specific namespace', {namespace: 'z2m:mqtt'});
        expect(consoleWriteSpy).toHaveBeenCalledTimes(i++);
        let net_map='special chars {"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state}}"}],"availability_mode":"all","device":{"hw_version":"zStack3x0 20230507","identifiers":["zigbee2mqtt_bridge_0xieeeAddr"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.37.1"},"enabled_by_default":false,"entity_category":"diagnostic","json_attributes_template":"{{value_json.data.value | tojson }}","json_attributes_topic":"zigbee2mqtt/bridge/response/networkmap","name":"Networkmap","object_id":"zigbee2mqtt_bridge_network_map","origin":{"name":"Zigbee2MQTT","sw":"1.37.1","url":"https:/www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/bridge/responsenetworkmap","unique_id":"bridge_0xieeeAddr_network_map_zigbee2mqtt","value_template":"{{ now().strftime(\'%Y-%m-%d %H:%M:%S\') }}"}';
        logger.debug(net_map,'z2m:mqtt');
        expect(logSpy).toHaveBeenLastCalledWith('debug', net_map, {namespace: 'z2m:mqtt'});
        expect(consoleWriteSpy).toHaveBeenCalledTimes(i++);
        net_map='{"value_template":"{{ now().strftime(\'%Y-%m-%d %H:%M:%S\') }}"}';
        logger.debug(net_map,'z2m:mqtt');
        expect(logSpy).toHaveBeenLastCalledWith('debug', net_map, {namespace: 'z2m:mqtt'});
        expect(consoleWriteSpy).toHaveBeenCalledTimes(i++);
        net_map='%Y-%m-%d %H:%M:%S';
        logger.debug(net_map,'z2m:mqtt');
        expect(logSpy).toHaveBeenLastCalledWith('debug', net_map, {namespace: 'z2m:mqtt'});
        expect(consoleWriteSpy).toHaveBeenCalledTimes(i++);
        net_map='%Y';
        logger.debug(net_map,'z2m:mqtt');
        expect(logSpy).toHaveBeenLastCalledWith('debug', net_map, {namespace: 'z2m:mqtt'});
        expect(consoleWriteSpy).toHaveBeenCalledTimes(i++);

the test result is all green, but the actual logs are not :

test log output 
[2024-06-04 18:02:20] info:     z2m: Logging to console, file (filename: log.log)
[2024-06-04 18:02:20] debug:    z2m: default namespace
[2024-06-04 18:02:20] debug:    z2m:mqtt: specific namespace
[2024-06-04 18:02:20] debug:    undefined: special chars {"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","device":{"hw_version":"zStack3x0 20230507","identifiers":["zigbee2mqtt_bridge_0xieeeAddr"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.37.1"},"enabled_by_default":false,"entity_category":"diagnostic","json_attributes_template":"{{ value_json.data.value | tojson }}","json_attributes_topic":"zigbee2mqtt/bridge/response/networkmap","name":"Network map","object_id":"zigbee2mqtt_bridge_network_map","origin":{"name":"Zigbee2MQTT","sw":"1.37.1","url":"https://www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/bridge/response/networkmap","unique_id":"bridge_0xieeeAddr_network_map_zigbee2mqtt","value_template":"{{ now().strftime('%Y-%m-%d %H:%M:%S') }}"}
[2024-06-04 18:02:20] debug:    undefined: {"value_template":"{{ now().strftime('%Y-%m-%d %H:%M:%S') }}"}
[2024-06-04 18:02:20] debug:    undefined: %Y-%m-%d %H:%M:%S
[2024-06-04 18:02:20] debug:    z2m:mqtt: %Y
[2024-06-04 18:02:20] debug:    undefined: %Y-%m-%d
[2024-06-04 18:02:20] debug:    z2m:mqtt: %H:%M:%S
[2024-06-04 18:02:20] debug:    z2m:mqtt: %m
[2024-06-04 18:02:20] debug:    undefined: %d
[2024-06-04 18:02:20] debug:    undefined: %s

So the high level winston logger does see the right strings/parameters, but it seems that it then interprets the strings with format specifiers.
From my understanding of the winston documentation string interpolation should require the splat filter, and I don't see us using it anywhere ...

@Nerivec do you see where this could come from ? I'm at the limit of my capabilities to debug this further...

@Nerivec
Copy link
Collaborator

Nerivec commented Jun 4, 2024

That bug is in my TODO list already, but I haven't gotten to it yet.

Nerivec added a commit to ghoz/zigbee2mqtt that referenced this issue Jun 4, 2024
@Nerivec
Fix Koenkk#22935
827e18e
@Nerivec Nerivec mentioned this issue Jun 4, 2024
Merged
5 tasks
Koenkk pushed a commit that referenced this issue Jun 4, 2024
@ghoz @Nerivec
feat: Allow hierarchical filtering of logger namespaces (#22859)
881037c 
* POC: Allow hierarchical filtering of logger namespaces

matches the closes defined namespace log level:

advanced:
  log_namespaced_levels:
    'zh:zstack:unpi': info

would also apply to zh:zstack:unpi:write and zh:zstack:unpi:parse

To limit runtime penalty uses the namespacedLevels as a lazy cache

* Move namespace levels to separate cache

Avoid poluting the namespacedLevel in the config / UI
Add cache reset on config time log level change

* Actually use the cache

* Optimize/Cleanup

* Add some namespace hierarchy filter tests

* More coverage.

* Fix #22935

---------

Co-authored-by: Nerivec <62446222+Nerivec@users.noreply.github.com>
@Nerivec Nerivec closed this as completed Jun 4, 2024
ghoz added a commit to ghoz/zigbee2mqtt that referenced this issue Jun 14, 2024
@ghoz @Nerivec
feat: Allow hierarchical filtering of logger namespaces (Koenkk#22859)
23a6e33 
* POC: Allow hierarchical filtering of logger namespaces

matches the closes defined namespace log level:

advanced:
  log_namespaced_levels:
    'zh:zstack:unpi': info

would also apply to zh:zstack:unpi:write and zh:zstack:unpi:parse

To limit runtime penalty uses the namespacedLevels as a lazy cache

* Move namespace levels to separate cache

Avoid poluting the namespacedLevel in the config / UI
Add cache reset on config time log level change

* Actually use the cache

* Optimize/Cleanup

* Add some namespace hierarchy filter tests

* More coverage.

* Fix Koenkk#22935

---------

Co-authored-by: Nerivec <62446222+Nerivec@users.noreply.github.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
problem Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ghoz @Nerivec