Getting the same error every ~100ms on 2024.2.1 and cannot locate cause

jon1 · February 11, 2024, 2:32pm

Hi, yesterday I noticed the following error really hammer my system:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/automation/__init__.py", line 637, in async_trigger
    and not self._cond_func(variables)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/automation/__init__.py", line 1009, in if_action
    if check(hass, variables) is False:
       ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/condition.py", line 179, in wrapper
    result = condition(hass, variables)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/condition.py", line 787, in template_if
    return async_template(hass, value_template, variables)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/condition.py", line 767, in async_template
    info = value_template.async_render_to_info(variables, parse_result=False)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 686, in async_render_to_info
    assert self.hass and _render_info.get() is None
AssertionError

It seemed to occur several times per second although was not preceeded by anything identifiable to suggest its ultimate cause.

I had upgraded several HACS components yesterday (Atomic CAlendar Revive, MercedesME, Mushroom, SmarthThinq LGE) and upgraded my docker instance from 2024.1.6 to 2024.2.1 (run the docker container on a ubuntu VM).

I turned on “debug” logging which did not identify any additional trigger for the error. The error seemed to persist even in safe mode! At times, I thought it began anytime I played a video on Kodi. I disabled my kodi integration and there was no change. Ultimately, the association I thought I noticed with media playing on Kodi may not have held up as it also just seemed to start after home assistant had been open for several minutes.

When the error started, home assistant would become SUUPPPPER slow.

Since the error was present even in safe mode, I assume this means that HACS had nothing to do with it?

After spending way too long trying to figure this out, I just restored a backup from 2 days ago when I was on 2024.1.6 (and downgraded) and everything appears to be working again.

I have not seen this error mentioned elsewhere on reddit, here, or broadly on google. The one mentioned of something similar appeared to be from a calendar integration I think?

Anyway, would really appreciate any insight, if anyone has any, on what might have caused this and what I can do to prevent it. I understand that my details make it difficult to pin down the error, but any thoughts would be appreciated.

Thanks

tom_l · February 11, 2024, 9:56pm

This is correct. It looks like an automation template condition causing the issue.

mcv93 · February 11, 2024, 10:53pm

The same error happens to me too, in a short time I found over 2500000 AssertionErrors in the registry so I deactivated all the automations and then reactivated them one at a time until I found the one that was generating the problem.
In my case the offending line that generates the error is this:

{{ trigger.event.data.entity_id.startswith('media_player.') }}

Until now it had always worked, I don’t understand what has changed with version 2024.2.1

tom_l · February 11, 2024, 10:56pm

Interesting. I wonder if it is related to this issue of another media player going nuts:

github.com/home-assistant/core

Slimproto logs exception every 100ms

opened 03:40AM - 07 Feb 24 UTC

balloob

integration: slimproto

### The problem The slimproto integration is set up, and I see 2 exception ge…t logged every 1-2 minutes with 100ms inbetween them. I had a slimproto device in the past but it’s offline now. ``` 2024-02-06 19:17:06.885 ERROR (MainThread) [homeassistant] Error doing job: Unhandled exception in client_connected_cb Traceback (most recent call last): File "/usr/local/lib/python3.12/site-packages/aioslimproto/cli.py", line 409, in _handle_json_client result = await self._handle_cli_message(rpc_msg) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/aioslimproto/cli.py", line 578, in _handle_cli_message return await handler(player, msg.command_args) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/aioslimproto/cli.py", line 213, in handle_mixer await player.volume_set(int(arg)) ^^^^^^^^^^^^^^^^^ AttributeError: 'NoneType' object has no attribute 'volume_set' ``` ### What version of Home Assistant Core has the issue? core-2024.2.0b9 ### What was the last working version of Home Assistant Core? don't know ### What type of installation are you running? Home Assistant OS ### Integration causing the issue slimproto ### Link to integration documentation on our website https://www.home-assistant.io/integrations/slimproto ### Diagnostics information _No response_ ### Example YAML snippet _No response_ ### Anything in the logs that might be useful for us? _No response_ ### Additional information _No response_

You should definitely open a new issue.

mcv93 · February 11, 2024, 11:03pm

Ok, I’ll try tomorrow now it’s late at night for me; I had the CPU at 90% and the memory occupied at over 80%, I deleted the registers to clean up so I don’t have the details of the error.
Tomorrow I’ll turn the automation back on and see when it starts going crazy.

jon1 · February 11, 2024, 11:12pm

Turning all my automations off and then starting them one at a time seems so daunting. I have had messed up automatoins before, however, and a single automation may fail, but not sure why it would cause this string of errors.

I’ll look through the release notes and see if there is anything that sticks out.

tom_l · February 11, 2024, 11:18pm

Start by disabling the automations with template conditions, or media player conditions or triggers.

jon1 · February 11, 2024, 11:26pm

Ok I will, but don’t think I’ll have time for that tonight. That pretty much summarizes all of my automations lol.

I don’t know if this is related or not, but since I rolled back to 2024.1.6 in which an error pops up when I start playing something on kodi. It’s different, however, but still not sure if it might be related.

Logger: homeassistant
Source: components/media_player/significant_change.py:44
First occurred: 10:22:37 AM (21 occurrences)
Last logged: 6:07:45 PM

Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/google_assistant/report_state.py", line 115, in async_entity_state_listener
    if not checker.async_is_significant_change(new_state, extra_arg=entity_data):
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/significant_change.py", line 215, in async_is_significant_change
    result = check_significantly_changed(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/media_player/significant_change.py", line 44, in async_check_significant_change
    old_attrs_s = set(
                  ^^^^
TypeError: unhashable type: 'dict'

Again, this error seems to occur with watching something on Kodi so no idea what it would involve google assistant. I don’t think I have any convoluted automation or anything which would somehow combine the two.

I will add- I do make use of a HACS addon called media player template (GitHub - Sennevds/media_player.template: Template media_player for Home Assistant) and I have a universal media player entity. Since I noticed this issue start sometimes (i think?) with media, I also thought those two things especially could be the problem. I uninstalled the custom component and removed the entities of both and the problem still occurred.

Cadish · February 25, 2024, 6:19pm

I’m having the exact same issue, and cannot find what’s causing the issue. When disabling my HEOS integration, I don’t get the errors anymore…

thoughton · February 29, 2024, 1:59pm

I’ve just started to experience this as well. Updated to the latest HA a few days ago, and now Home Assistant will run normally for a few hours, then something happens, and after that it’s generating errors every 7-10ms forever. HA continues to work, but CPU is around 50% (up from 10%) and it’s a bit sluggish.

Once this happens the log file starts to grow at about 150GB a day

These are the errors:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/automation/__init__.py", line 637, in async_trigger
    and not self._cond_func(variables)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/automation/__init__.py", line 1009, in if_action
    if check(hass, variables) is False:
       ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/condition.py", line 179, in wrapper
    result = condition(hass, variables)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/condition.py", line 787, in template_if
    return async_template(hass, value_template, variables)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/condition.py", line 767, in async_template
    info = value_template.async_render_to_info(variables, parse_result=False)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 686, in async_render_to_info
    assert self.hass and _render_info.get() is None
AssertionError

Tom pointed out above the error shows the issue is a condition in a template, and based on the times it happens I think it might be coming from my calendar-based automations. They look like this:

- alias: 'Calendar lawnmower start time'
  trigger:
    - platform: calendar
      event: start
      entity_id: calendar.house_events
  condition:
    - condition: template
      value_template: "{{ 'Lawnmower start' in trigger.calendar_event.summary }}"

This is based on the example on the ‘Calendar Event Light Schedule’ example on docs page, so not really sure what I can do other than stop using calendar triggers.

jon1 · February 29, 2024, 3:02pm

Does it seem to happen only when:

value_template: “{{ ‘Lawnmower start’ in trigger.calendar_event.summary }}”

Is not found in the calendar _event?

jone9618 · February 29, 2024, 6:26pm

For what it is worth I am having the same problem. HA runs cleanly for a period of time after start up and then the the logs start filling with this message, with consequent impact on system performance. The period between start up can vary between a few minutes and 10+ hours. At the moment I am not able to correlate the commencement of the error with any particular event.

Grateful for any insight from finer minds.

jon1 · February 29, 2024, 6:51pm

I had the same issue. I had the hardest time finding the trigger for this error. It would occur at some point after startup- minutes to a day even- and then wouldn’t stop.

It turned out, in my case, to be a stupid mistake where I used state(‘entity’) instead of states('entity) in an automation condition. The mistyped condition must have been present for a while but its only with this more recent version of home assistant that I guess more of these template errors are being logged.

On the one hand, its good to see errors which may have previously gone unrecognized are now being presented, but on the other hand, perhaps there is a bug in that these error messages are creataing more a strain on system resources than the actual error?

jone9618 · March 2, 2024, 11:19am

Managed to sort this out too. I also had an automation with an erroneous template in the condition statement that caused this. Thanks to @jon1 for pointing me in the right direction.

phairplay · March 9, 2024, 11:04am

I had the same issue yesterday which created a 18gb log file
While it mentioned automation the issue was with a custom sensor template.

petro · March 18, 2024, 10:42am

The general consensus on this right now is: There’s a custom integration or a core integration without tests doing unsafe threading. Can everyone list all integrations being used?

thoughton · April 2, 2024, 4:35pm

Thanks Petro! My integrations list looks like this:

Summary

Alexa Media Player

Android Debug Bridge

Android TV Remote

Apple iCloud

Apple TV

Bluetooth

Bond

Denon AVR Network Receivers

Denon HEOS

Discord

Forecast.Solar

Fully Kiosk Browser

Generic Camera

Google Calendar

Google Cast

Google Translate text-to-speech

HACS

Home Assistant iOS

Home Assistant Supervisor

Home Connect Alt

HomeKit Bridge

HomeKit Device

iBeacon Tracker

Internet Printing Protocol (IPP)

Konnected.io

LocalTuya integration

Logitech Harmony Hub

Meross Cloud IoT

Mobile App

Moon

MQTT

Notifications for Android TV / Fire TV

OpenWeatherMap

Philips Hue

Ping (ICMP)

Plex Media Server

Pushover

QNAP

Radio Browser

Remote Home-Assistant

SmartThinQ LGE Sensors

Sony Bravia TV

Speedtest.net

Sun

System Monitor

Tapo: Cameras Control

Tasmota

Tautulli

Thread

TP-Link Smart Home

Trakt

UPnP/IGD

Uptime

Xbox

Xiaomi BLE

Xiaomi Gateway (Aqara)

Xiaomi Miio

Z-Wave

petro · April 2, 2024, 4:39pm

Which ones are custom?

thoughton · April 3, 2024, 10:26am

Actually it’s possible we might be able to set aside custom integrations for the moment. I’d have to go and look up each one to check if it’s custom or not. I installed these years ago, memories are a bit dim

I had disabled all my calendar automations when this happened back in February. This stopped the errors.

Last night I checked each calendar automation to make sure the trigger matches the calendar event summary (thanks @jon1), and reenabled them all, except for one old testing one that had no corresponding calendar entry.

This morning I have a 15GB log file, with millions of these:

2024-04-03 02:00:00.013 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/automation/__init__.py", line 637, in async_trigger
    and not self._cond_func(variables)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/automation/__init__.py", line 1009, in if_action
    if check(hass, variables) is False:
       ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/condition.py", line 179, in wrapper
    result = condition(hass, variables)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/condition.py", line 787, in template_if
    return async_template(hass, value_template, variables)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/condition.py", line 767, in async_template
    info = value_template.async_render_to_info(variables, parse_result=False)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 686, in async_render_to_info
    assert self.hass and _render_info.get() is None
AssertionError

petro · April 3, 2024, 11:40am

Yes, that’s the error. So which custom integration are you using that’s a calendar?

To be clear, this is a threading safety issue, so the error is coming from core but it’s caused by the entity you’re accessing. I.e. the integration that’s creating the entity.

It could be a calendar, it could also just be a condition on one of your calendar automations that’s looking at a custom integrations sensor or entity.