Home Assistant crashing after clocks changed?

joshlbs · October 31, 2021, 2:47am

We’ve just moved out of daylight savings time (BST, UTC+1) back to our normal timezone (GMT, UTC). At 2am the clocks went back, so we effectively had 1am twice.

I’ve just been woken up at 2.15am to find the lights in the house turned on (many of our ZigBee and Tasmota bulbs are configured to do this if they lose connection) and all our esphome devices LEDS flashing. Home Assistant has crashed and is completely unreachable!

I’ve powercycled the raspberry pi and it’s all come back okay. We have some automations triggered with cron-style notation to run every “/10” minutes. Looking in the logbook I can see these time-triggered automations were running repeatedly (almost every second) around 1.15am.

I want to go back to sleep, but I’ll do more troubleshooting in the morning. Has anyone else seen similar?

tom_l · October 31, 2021, 3:14am

No, the daylight savings change here (UTC+10 → +11) went off without issue.

There were some people on Discord reporting issues: Discord

The solution was a forced shut-down and restart.

mobile.andrew.jones · October 31, 2021, 3:43am

Yup - same here - there is a bug on Github.
I’ve narrowed it down to automations that are triggered with a time pattern. From the MASSIVE 123mb log file I was left with…

github.com/home-assistant/core

High CPU usage since summer to winter time change

opened 01:13AM - 31 Oct 21 UTC

chneau

### The problem In UK 2021/10/31, at 01:59:59, time got back to 01:00:00 (sum…mer to winter, Daylight saving), since then (it's 01:08) home-assistant has a high CPU usage, using a core at 100%. ``` CONTAINER ID NAME CPU % MEM USAGE / LIMIT MEM % NET I/O BLOCK I/O PIDS 42985e0497d4 hass 104.53% 251.7MiB / 7.658GiB 3.21% 0B / 0B 103MB / 1.77MB 15 ``` Edit: memory usage seems to increase quickly: at 01:14:00 ``` CONTAINER ID NAME CPU % MEM USAGE / LIMIT MEM % NET I/O BLOCK I/O PIDS 42985e0497d4 hass 104.93% 703.1MiB / 7.658GiB 8.97% 0B / 0B 112MB / 1.98MB 16 ``` Edit2: Switching lights work fine but it does not appear on the state history of the light. ### What version of Home Assistant Core has the issue? core-2021.10.6 ``` REPOSITORY TAG IMAGE ID CREATED SIZE homeassistant/home-assistant stable e0a45773808a 12 days ago 1.14GB ``` I could not find the exact image id on docker hub, but here is the label section of `docker inspect` ``` "io.hass.arch": "amd64", "io.hass.base.arch": "amd64", "io.hass.base.image": "homeassistant/amd64-base:3.14", "io.hass.base.name": "python", "io.hass.base.version": "2021.09.1", "io.hass.type": "core", "io.hass.version": "2021.10.6", "org.opencontainers.image.authors": "The Home Assistant Authors", "org.opencontainers.image.created": "2021-10-18 06:34:53+00:00", "org.opencontainers.image.description": "Open-source home automation platform running on Python 3", "org.opencontainers.image.documentation": "https://www.home-assistant.io/docs/", "org.opencontainers.image.licenses": "Apache License 2.0", "org.opencontainers.image.source": "https://github.com/home-assistant/core", "org.opencontainers.image.title": "Home Assistant", "org.opencontainers.image.url": "https://www.home-assistant.io/", "org.opencontainers.image.version": "2021.10.6" ``` ### What was the last working version of Home Assistant Core? _No response_ ### What type of installation are you running? Home Assistant Container ### Integration causing the issue _No response_ ### Link to integration documentation on our website _No response_ ### Example YAML snippet _No response_ ### Anything in the logs that might be useful for us? Interesting `The recorder queue reached the maximum size of 30000` ```txt 2021-10-30T09:40:10.884156228Z 2021-10-30 10:40:10 WARNING (MainThread) [homeassistant.components.websocket_api.http.connection] [139778345277952] Disconnected: Did not receive auth message within 10 seconds 2021-10-30T09:40:22.323961416Z 2021-10-30 10:40:22 WARNING (MainThread) [homeassistant.components.webhook] Received message for unregistered webhook c9fa7b5955dcce6df0ec16e14a28b23623563b96373bc5a66c0413c418093008 from 192.168.1.117 2021-10-31T01:03:30.660640416Z 2021-10-31 01:03:30 ERROR (MainThread) [homeassistant.components.recorder] The recorder queue reached the maximum size of 30000; Events are no longer being recorded 2021-10-31T01:04:57.487128770Z [cont-finish.d] executing container finish scripts... 2021-10-31T01:04:57.489476430Z [cont-finish.d] done. ``` at `2021-10-31T01:03:30.660640416Z` I restarted the container to see if it could fix the issue, it did not. ``` ### Additional information Maybe after 02:00:00 it will stop? Everything is working properly: light switches, the mobile phone app is working properly, the website served by the container (server:8123) is working properly. Restarting the container or restarting the PC does not solve the high CPU usage

tom_l · October 31, 2021, 4:06am

That would be why I was unaffected then, I avoid that trigger. Usually there will be a much more efficient state trigger option.

mobile.andrew.jones · October 31, 2021, 4:17am

Well that and you seem to have jumped forward an hour, rather than repeating an hour. I certainly did not have any problems when we jumped forward an hour in March.

EDIT:

If you have a fancy template though that replicate being able to run an automation every X minutes, I’d be interested - because this is one of the automations that was affected:

alias: Camera Snapshots
description: ''
trigger:
  - platform: time_pattern
    minutes: /5
condition: []
action:
  - service: camera.snapshot
    target:
      entity_id: camera.livingroom_mainstream
    data:
      filename: /config/www/cameras/rtsp_livingroom_main.jpg
  - service: camera.snapshot
    target:
      entity_id: camera.bedroom_mainstream
    data:
      filename: /config/www/cameras/rtsp_bedroom_main.jpg
mode: single

tom_l · October 31, 2021, 4:26am

I only take a snapshot when movement is detected.

- id: d70f3e5f-8bcc-49bb-8aa4-3fc389f300e8
  alias: 'Drive Camera Motion'
  max_exceeded: 'silent'
  trigger:
    platform: state
    entity_id:
    - binary_sensor.pir_drive
    from: 'off'
    to: 'on'
  action:
  - service: camera.snapshot
    data:
      entity_id: camera.front
      filename: '/config/www/snapshots/drive1.jpg'
  - delay: 00:00:01
  - service: camera.snapshot
    data:
      entity_id: camera.front
      filename: '/config/www/snapshots/drive2.jpg'
  - delay: 00:00:01
  - service: camera.snapshot
    data:
      entity_id: camera.front
      filename: '/config/www/snapshots/drive3.jpg'
  - service: script.turn_on
    entity_id: script.drive_cam_telegram
  - service: notify.gmail
    data:
      title: 'Drive Movement'
      message: 'Drive movement detected'
      data:
        images:
          - /config/www/snapshots/drive1.jpg
          - /config/www/snapshots/drive2.jpg
          - /config/www/snapshots/drive3.jpg
  - delay:
      seconds: 5 # trigger every 5 seconds at most

evantaur · October 31, 2021, 4:35am

Yeah, everything with timepattern just fires constantly on all cylinders.

mobile.andrew.jones · October 31, 2021, 4:39am

That doesn’t help in this case - the problem is the cameras are using RTSP and when you load the lovelace view, you don’t get a picture on loading it, until the first time the picture card refreshes the feed (every 10 seconds or so). This workaround means there is a recent image at least when you look at the camera page. This workaround is required on multiple installations not just mine.

Here is another automation that ensure that the boiler state stays synchronised on several ESPHome thermostats, in case they have been rebooted or lost connection with WiFi temporarily.

alias: Sensor - Boiler Running
description: Update State of Thermostats
trigger:
  - entity_id: binary_sensor.boiler_working
    platform: state
  - hours: '*'
    minutes: /5
    platform: time_pattern
    seconds: '0'
condition: []
action:
  - data: {}
    target:
      entity_id:
        - switch.boiler_status_led
        - switch.boiler_status_led_2
        - switch.boiler_status_led_3
    service: >-
      switch.turn_{{ 'on' if is_state('binary_sensor.boiler_working','on') else
      'off' }}

Dujith · October 31, 2021, 4:59am

Same here. Crashed HA and i have an automation with time pattern.
And ofcourse it happend right when i was heating… so nice and warm house this morning

jammiejammie · October 31, 2021, 5:54am

My system crashed last night. Not figured out yet what it could be, but we have some time to fix this

tom_l · October 31, 2021, 6:09am

You are putting your CPU to that much use 24/7 just to refresh an image in case you might look at it?

Browser mod can refresh the image only when Lovelace is opened, (use the device sensor visibility attribute to trigger a script that captures your image).

The other one is easily converted to state based triggers too:

alias: Sensor - Boiler Running
description: Update State of Thermostats
trigger:
  - platform: state
    entity_id: binary_sensor.boiler_working
    to:
      - 'on'
      - 'off'
  - platform: homeassistant
    event: start
  - platform: state
    entity_id: 
      - switch.boiler_status_led
      - switch.boiler_status_led_2
      - switch.boiler_status_led_3
    from: 'unavailable'
condition: []
action:
  - data: {}
    target:
      entity_id:
        - switch.boiler_status_led
        - switch.boiler_status_led_2
        - switch.boiler_status_led_3
    service: >-
      switch.turn_{{ 'on' if is_state('binary_sensor.boiler_working','on') else
      'off' }}

This is getting off topic. Open another topic if you want help making your automations more efficient.

megabitus · October 31, 2021, 6:32am

Same issue for me, last night we’ve moved out of daylight savings time, and at 3AM, home assistant stooped receiving updates form sensors, and got stuck at the last value received. I’ve checked the logs in esphome, and they were still detecting the right values. Also none of my automations ran over night. After a restart of the virtual machine, everything started to work. I’m running core-2021.10.6 and Home Assistant OS 6.5

mirekmal · October 31, 2021, 6:59am

Same for me, my HA crashed exectly at 3AM and the first error message in the log is iindeed linked to time patter triggered automation. Interesting though, HA was working (or trying so) for another almost 7 minutes before finally stopping. In that time it generated almost 600 000 of various error messages in the log - 79MB of data

inf · October 31, 2021, 7:08am

For me, Home Assistant continued to run (data was still captured from sensors and sent to InfluxDB) but my graphs were “flat”. The relevant error was “The recorder queue reached the maximum size” - but I have no idea why the clocks changing would cause the recorder queue to build up.

My recorder database is the default SQLite one.

System Health
version: core-2021.10.2
installation_type: Home Assistant Core
dev: false
hassio: false
docker: false
user: homeassistant
virtualenv: true
python_version: 3.9.1
os_name: Linux
os_version: 5.10.17-v8+
arch: aarch64
timezone: Europe/London

logged_in: false
can_reach_cert_server: ok
can_reach_cloud_auth: ok
can_reach_cloud: ok

Masteroshi · October 31, 2021, 7:12am

FYI:
I have a notification each time HA reboots and I had like 6 notifications in a row at 3am.
(yes I have automations with the time pattern trigger)

hamoph · October 31, 2021, 7:15am

For me HA still running but no history after clocks went back an hour. With this error -

The recorder queue reached the maximum size of 30000; Events are no longer being recorded

Seems fixed by a restart.

koying · October 31, 2021, 7:51am

Yep, “backend” crashed for me as well.
Besides the “recorder” message, ZHA seemed to have lost it as well.

2021-10-31 02:02:26 WARNING (MainThread) [bellows.zigbee.application] Watchdog heartbeat timeout: 
2021-10-31 02:04:37 WARNING (MainThread) [bellows.zigbee.application] Watchdog heartbeat timeout: 
2021-10-31 02:05:47 ERROR (MainThread) [homeassistant.components.recorder] The recorder queue reached the maximum size of 30000; Events are no longer being recorded
2021-10-31 02:09:35 WARNING (MainThread) [bellows.zigbee.application] Watchdog heartbeat timeout: 
2021-10-31 02:20:58 WARNING (MainThread) [bellows.zigbee.application] Watchdog heartbeat timeout: 
2021-10-31 02:27:18 WARNING (MainThread) [bellows.zigbee.application] Watchdog heartbeat timeout: 
2021-10-31 02:29:17 WARNING (MainThread) [bellows.zigbee.application] Watchdog heartbeat timeout: 
2021-10-31 02:34:22 WARNING (MainThread) [bellows.zigbee.application] Watchdog heartbeat timeout: 
2021-10-31 02:37:58 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.plug_tuya_01_electrical_measurement is taking over 10 seconds
2021-10-31 02:38:00 WARNING (MainThread) [bellows.zigbee.application] Watchdog heartbeat timeout: 
2021-10-31 02:38:16 WARNING (MainThread) [bellows.zigbee.application] Watchdog heartbeat timeout: 
2021-10-31 02:38:31 WARNING (MainThread) [bellows.zigbee.application] Watchdog heartbeat timeout: 
2021-10-31 02:38:46 WARNING (MainThread) [bellows.zigbee.application] Watchdog heartbeat timeout: 
2021-10-31 02:39:01 WARNING (MainThread) [bellows.zigbee.application] Watchdog heartbeat timeout: 
2021-10-31 02:39:50 WARNING (bellows.thread_0) [bellows.uart] Reset future is None
2021-10-31 02:40:04 ERROR (bellows.thread_0) [bellows.uart] Lost serial connection: device reports readiness to read but returned no data (device disconnected or multiple access on port?)
2021-10-31 02:40:04 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2021-10-31 02:40:04 WARNING (bellows.thread_0) [bellows.uart] Reset future is None
2021-10-31 02:40:04 ERROR (bellows.thread_0) [bellows.uart] Lost serial connection: device reports readiness to read but returned no data (device disconnected or multiple access on port?)
2021-10-31 02:40:04 ERROR (bellows.thread_0) [bellows.uart] Lost serial connection: device reports readiness to read but returned no data (device disconnected or multiple access on port?)
2021-10-31 02:40:04 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2021-10-31 02:40:04 ERROR (MainThread) [bellows.ezsp] NCP entered failed state. Requesting APP controller restart
2021-10-31 02:47:22 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2021-10-31 02:47:22 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!

Might be worth some testing before our western Atlantic friends do their DST jump next week…

qpasatio · October 31, 2021, 7:52am

my system crahed too

Olie · October 31, 2021, 7:52am

I woke up to a crashed instance at exactly 2am too. Used the console to do a core restart which brought it back to life.

I thought something had happened as a motion sensor didn’t trigger lights when I walked past.

First time anything like this has happened.

baz123 · October 31, 2021, 7:57am

Yes it looks like Home Assistant crashed for me as well at 02:00 (UK DST applied).

Of course, logs don’t survive a rebbot so absolutely noidea why.

I do wish the system logs were saved and rotated…

[edit]
HA Blue
core-2021.10.6
supervisor-2021.10.6
Home Assistant OS 6.5