search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
72.82k stars 30.51k forks source link

Logger: Exception in attributes_message_received when handling msg #50905

Closed pejotigrek closed 3 years ago

pejotigrek commented 3 years ago

The problem

I was sent here after opening an issue in Valetudo repository with the hint that it has something related with logger.

Problem showed up after updating my vacuum to latest Valetudo - with the rewritten MQTT interface. I did all the steps mentioned on said repository to clean up the Home Assistant's sensors/configuration related to Valetudo/Vacuum.

Errors show up on every restart, and during normal work after a random amount of time. As for right now I didn't noticed any interruptions with vacuum automations/scripts and all works normal, the only thing that is wrong - is the log spammed with errors.

What is version of Home Assistant Core has the issue?

core-2021.5.5

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Supervised

Integration causing the issue

MQTT, Logger

Link to integration documentation on our website

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

------------------------- AFTER RESTART
2021-05-20 16:50:31 ERROR (MainThread) [homeassistant.util.logging] Exception in attributes_message_received when handling msg on 'valetudo/1_lvn_rosita_mqtt/ZoneCleaningCapability/presets': '{"1648d7a3-9156-44b3-8a15-080f84dcc2ee":{"__class":"ValetudoZonePreset","metaData":{},"name":"Kuchnia","zones":[{"__class":"ValetudoZone","metaData":{},"points":{"pA":{"x":2955,"y":2565},"pB":{"x":3300,"y":2565},"pC":{"x":3300,"y":2675},"pD":{"x":2955,"y":2675}},"iterations":1},{"__class":"ValetudoZone","metaData":{},"points":{"pA":{"x":2985,"y":2670},"pB":{"x":3150,"y":2670},"pC":{"x":3150,"y":2740},"pD":{"x":2985,"y":2740}},"iterations":1}],"id":"1648d7a3-9156-44b3-8a15-080f84dcc2ee"},"f5e505f1-a475-4026-a53c-7fc8ea633594":{"__class":"ValetudoZonePreset","metaData":{},"name":"Korytarz","zones":[{"__class":"ValetudoZone","metaData":{},"points":{"pA":{"x":3105,"y":2740},"pB":{"x":3360,"y":2740},"pC":{"x":3360,"y":2915},"pD":{"x":3105,"y":2915}},"iterations":1}],"id":"f5e505f1-a475-4026-a53c-7fc8ea633594"},"16a36953-0b03-4d3d-b1c7-710f6825ae83":{"__class":"ValetudoZonePreset","metaData":{},"name":"Taras","zones":[{"__class":"ValetudoZone","metaData":{},"points":{"pA":{"x":2485,"y":2950},"pB":{"x":2670,"y":2950},"pC":{"x":2670,"y":3100},"pD":{"x":2485,"y":3100}},"iterations":1}],"id":"16a36953-0b03-4d3d-b1c7-710f6825ae83"}}'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 32, in wrapper
    msg_callback(msg)
  File "/usr/src/homeassistant/homeassistant/components/mqtt/mixins.py", line 206, in attributes_message_received
    payload = attr_tpl.async_render_with_possible_json_value(payload)
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 552, in async_render_with_possible_json_value
    return _render_with_context(
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 1359, in _render_with_context
    return template.render(**kwargs)
  File "/usr/local/lib/python3.8/site-packages/jinja2/environment.py", line 1304, in render
    self.environment.handle_exception()
  File "/usr/local/lib/python3.8/site-packages/jinja2/environment.py", line 925, in handle_exception
    raise rewrite_traceback_stack(source=source)
  File "<template>", line 1, in top-level template code
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 1316, in to_json
    return json.dumps(value)
  File "/usr/local/lib/python3.8/json/__init__.py", line 231, in dumps
    return _default_encoder.encode(obj)
  File "/usr/local/lib/python3.8/json/encoder.py", line 199, in encode
    chunks = self.iterencode(o, _one_shot=True)
  File "/usr/local/lib/python3.8/json/encoder.py", line 257, in iterencode
    return _iterencode(o, 0)
  File "/usr/local/lib/python3.8/json/encoder.py", line 179, in default
    raise TypeError(f'Object of type {o.__class__.__name__} '
TypeError: Object of type LoggingUndefined is not JSON serializable
------------------------- AFTER RANDOM TIME
2021-05-20 16:51:53 ERROR (MainThread) [homeassistant.util.logging] Exception in attributes_message_received when handling msg on 'valetudo/1_lvn_rosita_mqtt/GoToLocationCapability/presets': '{"4b55c843-359b-4e1b-8ea7-fb231b0430cb":{"__class":"ValetudoGoToLocation","metaData":{},"name":"Kuchnia","coordinates":{"x":3198,"y":2628},"id":"4b55c843-359b-4e1b-8ea7-fb231b0430cb"}}'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 32, in wrapper
    msg_callback(msg)
  File "/usr/src/homeassistant/homeassistant/components/mqtt/mixins.py", line 206, in attributes_message_received
    payload = attr_tpl.async_render_with_possible_json_value(payload)
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 552, in async_render_with_possible_json_value
    return _render_with_context(
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 1359, in _render_with_context
    return template.render(**kwargs)
  File "/usr/local/lib/python3.8/site-packages/jinja2/environment.py", line 1304, in render
    self.environment.handle_exception()
  File "/usr/local/lib/python3.8/site-packages/jinja2/environment.py", line 925, in handle_exception
    raise rewrite_traceback_stack(source=source)
  File "<template>", line 1, in top-level template code
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 1316, in to_json
    return json.dumps(value)
  File "/usr/local/lib/python3.8/json/__init__.py", line 231, in dumps
    return _default_encoder.encode(obj)
  File "/usr/local/lib/python3.8/json/encoder.py", line 199, in encode
    chunks = self.iterencode(o, _one_shot=True)
  File "/usr/local/lib/python3.8/json/encoder.py", line 257, in iterencode
    return _iterencode(o, 0)
  File "/usr/local/lib/python3.8/json/encoder.py", line 179, in default
    raise TypeError(f'Object of type {o.__class__.__name__} '
TypeError: Object of type LoggingUndefined is not JSON serializable

Additional information

No response

probot-home-assistant[bot] commented 3 years ago

logger documentation logger source (message by IssueLinks)

probot-home-assistant[bot] commented 3 years ago

Hey there @home-assistant/core, mind taking a look at this issue as its been labeled with an integration (logger) you are listed as a codeowner for? Thanks! (message by CodeOwnersMention)

probot-home-assistant[bot] commented 3 years ago

mqtt documentation mqtt source (message by IssueLinks)

probot-home-assistant[bot] commented 3 years ago

Hey there @emontnemery, mind taking a look at this issue as its been labeled with an integration (mqtt) you are listed as a codeowner for? Thanks! (message by CodeOwnersMention)

emontnemery commented 3 years ago

Can you share the MQTT discovery message for the vacuum?

You can find it from frontend: Configuration->Devices->(the vacuum device)->MQTT info->MQTT discovery data

Hypfer commented 3 years ago 
{
    "state_topic": "valetudo/rockrobo/hass/rockrobo_sensor_ZoneCleaningCapability",
    "icon": "mdi:square-outline",
    "json_attributes_topic": "valetudo/rockrobo/ZoneCleaningCapability/presets",
    "json_attributes_template": "{{ value }}",
    "name": "Zone Presets",
    "unique_id": "rockrobo_sensor_ZoneCleaningCapability",
    "availability_topic": "valetudo/rockrobo/$state",
    "payload_available": "ready",
    "payload_not_available": "lost",
    "device": {
        "manufacturer": "Beijing Roborock Technology Co., Ltd.",
        "model": "S5",
        "name": "rockrobo",
        "identifiers": ["rockrobo"],
        "sw_version": "2021.04.0 (Valetudo)"
    }
}

The identifiers are of course different but it looks like this. Looking at it now, I'm not entirely sure about the json_attribute_template part. Might actually be a Valetudo issue

emontnemery commented 3 years ago

That configuration shouldn't give the error in the log. Can you please provide the exact configuration, either by checking in frontend or by enabling this log configuration and attaching here a log file starting with a restart of Home Assistant and until you get the error message in the log.

logger:
  default: info
  logs:
    homeassistant.core: debug
    homeassistant.components.mqtt: debug
pejotigrek commented 3 years ago

hi, sorry for slight delay - I'm at work right now and couldn't access everything at once, but there's another thing "in the meantime". after log was spammed with errors given in the opening post, I just turned off the MQTT for vacuum, until it is needed for solving the issue. now, wanting to give you the MQTT discovery data I turned it on again, restarted Home Assistant and.. clicking on "MQTT Info" gives nothing [other devices display a popup with all the info, so I'm guessing it's working fine, just there's someting strange with the vacuum]. it looks like the integration is unavailable somehow now..? I've checked the MQTT [with MQTT Explorer] and everything shows up and updates as usual:

image

besides that - a new opponent has showed up, there is a new error in the log:

2021-05-24 12:28:53 ERROR (MainThread) [homeassistant.components.websocket_api.messages] Unable to serialize to JSON. Bad data found at $.result.entities[1].subscriptions[1].messages[0].payload=b'\x89PNG\r\n\x1a\n\x00\x00\x00\rIHDR\x00\x00\x02\xd0\x00\x00\x01\xe0\x08\x02\x00\x00\x00\x03\xa7\xcd\xfb\x00\x00\x01\x84iCCPICC profile\x00\x00(\x91}\x91=H\xc3@\x1c\xc5_S\xa5"\x15A;\x888d\xa8NV\x8a\x8a8J\x15\x8b`\xa1\xb4\x15Zu0\xb9\xf4\x0b\x9a4$).\x8e\x82k\xc1\xc1\x8f\xc5\xaa\x83\x8b\xb3\xae\x0e\xae\x82 \xf8\x01\xe2\xe6\xe6\xa4\xe8"%\xfe/)\xb4\x88\xf1\xe0\xb8\x1f\xef\xee=\xee\xde\x01B\xa3\xc2T\xb3+\n\xa8\x9ae\xa4\xe211\x9b[\x15\x03\xaf\x10\xe0\xc7\x00\xa2\x98\x90\x98\xa9\'\xd2\x8b\x19x\x8e\xaf{\xf8\xf8z\x17\xe1Y\xde\xe7\xfe\x1c}J\xded\x80O$\x9ec\xbaa\x11o\x10\xcflZ:\xe7}\xe2\x10
(...)

and that's just a first part, the log goes for quite a long like this, and I can understand that it is PNG map from vacum base64 encoded probably? but don't know why it can't be read as usual.

anyway, I've changed my logger configuration to info and added options to logs: keyword - didn't saw the original error, but I've cut out some personal info [mostly gps tracking info from google maps, and some snapshots from frigate sent ans encoded PNGs] and rest of the log is attached.

log.txt

to be honest - I think I can live without having the MQTT interface between vacuum and HA, so I can easily turn it off and have cleaner log, but I'm guessing that it's not good if this - random for me - errors pop up ;)

wfroemgen commented 3 years ago

Hey there. I see similiar issues with a "nan" from a plugwise circle monitored with plugwise-beta.

Describe the bug HA is unresponisve when accessing History, or from time to time without noteable cause.

Evidence From Log:

2021-06-26 10:31:44 ERROR (MainThread) [homeassistant.components.websocket_api.messages] Unable to serialize to JSON. Bad data found at $.result[293](State: switch.relay_state_38b3f).attributes.current_power_w=nan(<class 'float'>

Expected behavior HA should not crash and should show the current Power for all devices

Home Assistant (please complete the following information):

Plugwise-Setup:

emontnemery commented 3 years ago

@wfroemgen Please report that on the plugwise custom component's bugtracker 👍

Hypfer commented 3 years ago

While trying to get a clean logfile with a completely new deployment of HA 2021.6.5 and 2021.6.6 , I wasn't able to reproduce this issue.

Can't 100% confirm that it's fixed yet, however I'd like to ask if you're aware of any changes in HA that might've fixed this issue since 2021.5 @emontnemery ?

emontnemery commented 3 years ago

Data received on the configured json_attributes_topic, after being processed by an optional json_attributes_template must be a dict, where all values must be JSON serializable.

The initial problem reported in this issue happens while rendering the json_attributes_template, so either the template is incorrect or the data received over MQTT is bad.

@pejotigrek mentioned there are also errors indicating that the template output is not JSON serializable, but the errors are not included in the log.

I'm not aware of any change in Home Assistant which will hide the error, it's probably gone due to changes or corrections in what you have connected to over MQTT (Valetudo?).

It's not possible to make progress in this issue since neither the discovery message nor a log showing MQTT data has been provided. Should we close the issue for now since it no longer happens?

pejotigrek commented 3 years ago

as for now I also can't reproduce that error, so it is possible that somehow some other update cleaned that up maybe? @emontnemery if you think that it's enough to close the issue - fell free to do it :) I'll be updating Valetudo to 2021.06.0 soon, and if something similar happens - I can write that here and reopen the issue if needed.

emontnemery commented 3 years ago

Please open a new issue if this happens again.

ruimarinho commented 3 years ago

Make sure you have the Homie Autodiscovery setting disabled. I'm not sure if this was or is a Valetudo bug or not, but two of my recent Valetudo installations had both enabled -- could just be a coincidence on my end or part of the migration procedure from 2021.0x to 2021.0[5-6].

You will need to enable Delete autodiscovery on shutdown and then disable and re-enable the MQTT setting to force a cleanup of the existing autodiscovery messages.