High CPU usage on Home Assistant v0.115.0b4

philhawthorne commented 4 years ago

The problem

After upgrading to beta, my Home Assistant instance becomes unstable when multiple actions are carried out, for example lights in a group dimming, or multiple motion sensors changing states.

When the CPU usage gets high, Home Assistant chokes itself, eventually causing integrations to be marked as offline, as Home Assistant is unable to communicate on the network.

Environment

Home Assistant Core release with the issue: 0.115.0b4
Last working Home Assistant Core release (if known): 0.114.x
Operating environment (OS/Container/Supervised/Core): Container
Integration causing this issue: Possibly Websockets or Templates?
Link to integration documentation on our website:

Problem-relevant `configuration.yaml`

Traceback/Error logs

Link to debug log: Google Drive

Additional information

I am running Home Assistant via Docker container. There are two tablets which are displaying a Lovelace view, which uses many Markdown cards.

When looking at the logs, my CPU spiked to over 100% usage on Home Assistant at 20:51.

You can see in the logs at time 20:51:23. Errors start appearing and my Deconz integration has a mass update with all entities being marked as unavailable. This is due to the server choking and unable to communicate with Deconz.

I have included the previous 5 minutes of data, incase there is something you can see that might pinpoint what is choking my system.

Please note that I applied this patch from @bdraco to see if this is a template loop being caused. However I could not see any logs from this patch being generated.

bdraco commented 4 years ago

@philhawthorne Is this still happening on 0.115.0b7? If so can you send a py-spy top, dump, and record?

philhawthorne commented 4 years ago

Hey @bdraco

Unfortunately so. It is a bit tricky to trace down, as it doesn't happen from the start of the boot, and seems to occur randomly when events start happening.

I had previously experienced this on some older hardware. I was able to pin point it down to using "Soft UI" from Nathan Li as my Lovelace. That relies heavily on markdown cards in Lovelace, which render Jinja templates. I run 2 tablets with Lovelace open around the house, plus my computer. So there are 2-3 devices always open with Lovelace.

On my older hardware once I removed the soft UI lovelace dashboard, the CPU usage stabalised. Once I moved to my new hardware, I was able to run the Soft UI (which currently has 180+ markdown cards) again without CPU spikes. This was working fine in 0.114.x. However with the new beta, including b7, I am now seeing the CPU spikes again.

Tonight while hass was bugging out at 100% CPU, I attached py-spy for your requests. Excuse the long text dumps.

py-spy dump

Process 6821: python3 -m homeassistant --config /config
Python v3.8.4 (/usr/local/bin/python3.8)

Thread 0x5643A51288B0 (active): "MainThread"
    feed_appdata (asyncio/sslproto.py:274)
    _process_write_backlog (asyncio/sslproto.py:675)
    _write_appdata (asyncio/sslproto.py:599)
    write (asyncio/sslproto.py:387)
    _write (aiohttp/http_writer.py:68)
    write_headers (aiohttp/http_writer.py:112)
    send (aiohttp/client_reqrep.py:629)
    _request (aiohttp/client.py:502)
    async_send_changereport_message (homeassistant/components/alexa/state_report.py:96)
    async_entity_state_listener (homeassistant/components/alexa/state_report.py:48)
    _run (asyncio/events.py:81)
    _run_once (asyncio/base_events.py:1859)
    run_forever (asyncio/base_events.py:570)
    run_until_complete (asyncio/base_events.py:603)
    run (asyncio/runners.py:43)
    run (homeassistant/runner.py:133)
    main (homeassistant/__main__.py:312)
    <module> (homeassistant/__main__.py:320)
    _run_code (runpy.py:87)
    _run_module_as_main (runpy.py:194)
Thread 0x7F06EDEB3B20 (active): "Thread-1"
    dequeue (logging/handlers.py:1427)
    _monitor (logging/handlers.py:1478)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06EDDAFB20 (active): "SyncWorker_0"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06ECDFFB20 (active): "SyncWorker_1"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06EC7FFB20 (active): "SyncWorker_2"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06EC1FFB20 (active): "SyncWorker_3"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06EBBFFB20 (active): "SyncWorker_4"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06EB5FFB20 (active): "SyncWorker_5"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E5943B20 (active): "SyncWorker_6"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E583FB20 (active): "SyncWorker_7"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E573BB20 (active): "SyncWorker_8"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E5637B20 (active): "SyncWorker_9"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E5533B20 (active): "SyncWorker_10"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E542FB20 (active): "Recorder"
    run (homeassistant/components/recorder/__init__.py:346)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E52ABB20 (active): "Thread-2"
    dequeue (logging/handlers.py:1427)
    _monitor (logging/handlers.py:1478)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E3F83B20 (active): "Thread-3"
    loop (paho/mqtt/client.py:1163)
    loop_forever (paho/mqtt/client.py:1782)
    _thread_main (paho/mqtt/client.py:3428)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E340BB20 (active): "zeroconf-Engine-251"
    run (zeroconf/__init__.py:1325)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E3307B20 (idle): "zeroconf-Reaper_252"
    wait (threading.py:306)
    run (zeroconf/__init__.py:1451)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E2D43B20 (idle): "influxdb"
    wait (threading.py:302)
    get (queue.py:170)
    get_events_json (homeassistant/components/influxdb/__init__.py:499)
    run (homeassistant/components/influxdb/__init__.py:549)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E2BFFB20 (active): "SyncWorker_11"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E287BB20 (active): "SyncWorker_12"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E2737B20 (active): "SyncWorker_13"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E2633B20 (active): "SyncWorker_14"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E252FB20 (active): "SyncWorker_15"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E242BB20 (active): "SyncWorker_16"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E2327B20 (active): "SyncWorker_17"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E20E3B20 (active): "SyncWorker_18"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E115FB20 (active): "SyncWorker_19"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E0B1BB20 (active): "SyncWorker_20"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06E0857B20 (active): "SyncWorker_21"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DF3D3B20 (active): "Thread-6"
    _discover_thread (pysonos/discovery.py:124)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DF083B20 (idle): "Thread-7"
    select (selectors.py:415)
    handle_request (socketserver.py:294)
    run (pysonos/events.py:149)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DEB6FB20 (idle): "Thread-12"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DE967B20 (idle): "Thread-14"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DE75FB20 (idle): "Thread-16"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DE65BB20 (idle): "Thread-17"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DE257B20 (idle): "Thread-25"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DE153B20 (idle): "Thread-26"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DE04FB20 (idle): "Thread-27"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DDF4BB20 (idle): "Thread-28"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DDE47B20 (idle): "Thread-33"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DDD43B20 (idle): "Thread-34"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DDC3FB20 (idle): "Thread-35"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DDB3BB20 (idle): "Thread-36"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DDA37B20 (idle): "Thread-37"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DD82FB20 (idle): "Thread-39"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DD72BB20 (idle): "Thread-40"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DD627B20 (idle): "Thread-41"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DCD23B20 (idle): "Thread-48"
    wait (threading.py:302)
    get (queue.py:170)
    _consume (limitlessled/bridge.py:188)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DCBDFB20 (idle): "Thread-49"
    wait (threading.py:302)
    get (queue.py:170)
    run (limitlessled/pipeline.py:32)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DCA5BB20 (active): "Thread-50"
    _keep_alive (limitlessled/bridge.py:292)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DC957B20 (idle): "Thread-51"
    wait (threading.py:302)
    get (queue.py:170)
    run (limitlessled/pipeline.py:32)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DC853B20 (idle): "Thread-52"
    wait (threading.py:302)
    get (queue.py:170)
    run (limitlessled/pipeline.py:32)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DC74FB20 (idle): "Thread-53"
    wait (threading.py:302)
    get (queue.py:170)
    run (limitlessled/pipeline.py:32)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DB06BB20 (active): "SyncWorker_22"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06D621BB20 (active): "SyncWorker_23"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06D6116B20 (active): "SyncWorker_24"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06D6011B20 (active): "SyncWorker_25"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06D5F0CB20 (active): "SyncWorker_26"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06D5E07B20 (idle): "zeroconf-ServiceBrowser__ipps._tcp.local.-_plugwise._tcp.local.-_spotify-connect._tcp.local.-_wled._tcp.local.-_daap._tcp.local.-_axis-video._tcp.local.-_nut._tcp.local.-_dkapi._tcp.local.-_printer._tcp.local.-_elg._tcp.local.-_bond._tcp.local.-_miio._udp.local.-_http._tcp.local.-_ssh._tcp.local.-_xbmc-jsonrpc-h._tcp.local.-_api._udp.local.-_esphomelib._tcp.local.-_hap._tcp.local.-_googlecast._tcp.local.-_viziocast._tcp.local.-_ipp._tcp.local.-_Volumio._tcp.local._351"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2407)
    run (zeroconf/__init__.py:1701)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DEE7FB20 (idle): "Thread-182"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DED7AB20 (idle): "Thread-183"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06DEC75B20 (idle): "Thread-184"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06CF1FFB20 (idle): "Thread-185"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06CEF3AB20 (active): "SyncWorker_27"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06CEE35B20 (active): "SyncWorker_28"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 0x7F06CED30B20 (active): "SyncWorker_29"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)

py-spy top

3000.00% 3000.00%   570.0s    570.0s   _worker (concurrent/futures/thread.py:78)
200.00% 200.00%   38.00s    38.00s   dequeue (logging/handlers.py:1427)
100.00% 100.00%   19.00s    19.00s   loop (paho/mqtt/client.py:1163)
100.00% 100.00%   19.00s    19.00s   run (homeassistant/components/recorder/__init__.py:346)
100.00% 100.00%   19.00s    19.00s   _discover_thread (pysonos/discovery.py:124)
100.00% 100.00%   19.00s    19.00s   _keep_alive (limitlessled/bridge.py:292)
100.00% 100.00%   19.00s    19.00s   run (zeroconf/__init__.py:1325)
 33.00%  33.00%    6.71s     6.71s   write (ssl.py:897)
 17.00%  17.00%    2.83s     2.83s   feed_appdata (asyncio/sslproto.py:274)
 13.00%  46.00%    2.27s     9.01s   feed_appdata (asyncio/sslproto.py:262)
  5.00%   5.00%    1.33s     1.33s   feed_appdata (asyncio/sslproto.py:279)
  5.00%   5.00%    1.28s     1.28s   feed_appdata (asyncio/sslproto.py:270)
  4.00%   4.00%    1.01s     1.01s   feed_appdata (asyncio/sslproto.py:263)
  8.00%   8.00%   0.890s    0.890s   feed_appdata (asyncio/sslproto.py:277)
  8.00%   8.00%   0.880s    0.880s   feed_appdata (asyncio/sslproto.py:267)
  2.00%   2.00%   0.530s    0.530s   feed_appdata (asyncio/sslproto.py:268)
  0.00%   0.00%   0.390s    0.390s   feed_appdata (asyncio/sslproto.py:259)
  1.00%   1.00%   0.380s    0.380s   feed_appdata (asyncio/sslproto.py:261)
  2.00%   2.00%   0.240s    0.240s   feed_appdata (asyncio/sslproto.py:272)
  2.00%   2.00%   0.190s    0.190s   feed_appdata (asyncio/sslproto.py:271)
  0.00%   0.00%   0.040s    0.040s   feed_appdata (asyncio/sslproto.py:260)
  0.00%   0.00%   0.030s    0.030s   write (ssl.py:891)
  0.00% 100.00%   0.000s    19.00s   async_entity_state_listener (homeassistant/components/alexa/state_report.py:48)
  0.00% 100.00%   0.000s    19.00s   _run_code (runpy.py:87)
  0.00% 100.00%   0.000s    19.00s   <module> (homeassistant/__main__.py:320)
  0.00% 100.00%   0.000s    19.00s   run (asyncio/runners.py:43)
  0.00% 100.00%   0.000s    19.00s   main (homeassistant/__main__.py:312)
  0.00% 100.00%   0.000s    19.00s   run (homeassistant/runner.py:133)
  0.00% 100.00%   0.000s    19.00s   _write_appdata (asyncio/sslproto.py:599)
  0.00% 100.00%   0.000s    19.00s   _run_once (asyncio/base_events.py:1859)
  0.00% 100.00%   0.000s    19.00s   _run (asyncio/events.py:81)
  0.00% 100.00%   0.000s    19.00s   loop_forever (paho/mqtt/client.py:1782)
  0.00% 3500.00%   0.000s

py-spy record (see attached) b7.svg.zip

Hopefully there's enough to go on here. I'll remove my Soft UI dashboard again and see how that goes (on beta 6 it seemed to improve, so I'll let it run for a few days to see if it makes a difference)

Cheers

bdraco commented 4 years ago

It seems like alexa is eating up a bit of cpu time sending state change events.

Do you have a significant number of state change events in the log if you turn on debug logging for homeassistant.core ?

philhawthorne commented 4 years ago

Hey @bdraco I haven't forgotten about this.

After your suggestion I noticed in the logs my washing machine and dishwasher were spamming update events, even when they were off. Seems like my TP Link smart plug and one of my z-wave smart plugs are spamming too much on the slightest power change.

I updated those to remove the template power sensors as I can expose their attributes in automations now without needing a template. That has made things slightly better. Although things are still a bit sluggish, and randomly I'll see 100% CPU spikes.

I've got my logs set to debug, so next time I see a 100% spike I'll take a look and see if there's something else spamming events, or something else might be causing the CPU spikes.

philhawthorne commented 4 years ago

Ok I've experienced this again and getting closer.

I walked into my hallway, which fired some events.

Motion sensor is attached to a bayesian sensor working out the probability of someone being inside
Motion sensor triggers the hallway lights to turn on, as they did their white temperature changes

2020-09-17 22:14:31 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.motion_hall_south, old_state=<state binary_sensor.motion_hall_south=off; battery_level=100, device_armed=False, last_tripped_time=2020-09-17T11:39:43+00:00, device_tripped=False, current_power_w=0.0, Vera Device Id=104, friendly_name=Hall South, device_class=motion @ 2020-09-17T21:39:43.857868+10:00>, new_state=<state binary_sensor.motion_hall_south=on; battery_level=100, device_armed=False, last_tripped_time=2020-09-17T12:14:31+00:00, device_tripped=True, current_power_w=0.0, Vera Device Id=104, friendly_name=Hall South, device_class=motion @ 2020-09-17T22:14:31.203885+10:00>>
2020-09-17 22:14:31 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.person_inside_house, old_state=<state binary_sensor.person_inside_house=on; observations=[{'entity_id': 'alarm_control_panel.ha_alarm', 'prob_given_true': 0.7, 'prob_given_false': 0.0, 'platform': 'state', 'to_state': 'disarmed', 'id': 4}, {'entity_id': 'media_player.tv_living_room', 'prob_given_true': 0.7, 'prob_given_false': 0.0, 'platform': 'state', 'to_state': 'on', 'id': 5}, {'entity_id': 'binary_sensor.study_desk', 'prob_given_true': 0.75, 'prob_given_false': 0.0, 'platform': 'state', 'to_state': 'on', 'id': 6}, {'entity_id': 'binary_sensor.motion_office', 'prob_given_true': 0.6, 'prob_given_false': 0.0, 'platform': 'state', 'to_state': 'on', 'id': 13}], occurred_observation_entities=['alarm_control_panel.ha_alarm', 'media_player.tv_living_room', 'binary_sensor.study_desk', 'binary_sensor.motion_office'], probability=1.0, probability_threshold=0.85, friendly_name=Person Inside House @ 2020-09-16T18:31:23.694042+10:00>, new_state=<state binary_sensor.person_inside_house=on; observations=[{'entity_id': 'alarm_control_panel.ha_alarm', 'prob_given_true': 0.7, 'prob_given_false': 0.0, 'platform': 'state', 'to_state': 'disarmed', 'id': 4}, {'entity_id': 'media_player.tv_living_room', 'prob_given_true': 0.7, 'prob_given_false': 0.0, 'platform': 'state', 'to_state': 'on', 'id': 5}, {'entity_id': 'binary_sensor.study_desk', 'prob_given_true': 0.75, 'prob_given_false': 0.0, 'platform': 'state', 'to_state': 'on', 'id': 6}, {'entity_id': 'binary_sensor.motion_hall_south', 'prob_given_true': 0.6, 'prob_given_false': 0.0, 'platform': 'state', 'to_state': 'on', 'id': 12}, {'entity_id': 'binary_sensor.motion_office', 'prob_given_true': 0.6, 'prob_given_false': 0.0, 'platform': 'state', 'to_state': 'on', 'id': 13}], occurred_observation_entities=['media_player.tv_living_room', 'binary_sensor.motion_hall_south', 'alarm_control_panel.ha_alarm', 'binary_sensor.motion_office', 'binary_sensor.study_desk'], probability=1.0, probability_threshold=0.85, friendly_name=Person Inside House @ 2020-09-16T18:31:23.694042+10:00>>
2020-09-17 22:14:31 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event automation_triggered[L]: name=Lights Hall On, entity_id=automation.lights_hall_on, source=state of binary_sensor.motion_hall_south>
2020-09-17 22:14:31 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.lights_hall_on, old_state=<state automation.lights_hall_on=on; last_triggered=2020-09-17T21:37:44.688959+10:00, mode=single, current=0, friendly_name=Lights Hall On @ 2020-09-17T21:37:57.695319+10:00>, new_state=<state automation.lights_hall_on=on; last_triggered=2020-09-17T22:14:31.974793+10:00, mode=single, current=1, friendly_name=Lights Hall On @ 2020-09-17T21:37:57.695319+10:00>>
2020-09-17 22:14:32 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=automation, service=turn_off, service_data=entity_id=automation.lights_hall_on, stop_actions=False>
2020-09-17 22:14:32 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.lights_hall_on, old_state=<state automation.lights_hall_on=on; last_triggered=2020-09-17T22:14:31.974793+10:00, mode=single, current=1, friendly_name=Lights Hall On @ 2020-09-17T21:37:57.695319+10:00>, new_state=<state automation.lights_hall_on=off; last_triggered=2020-09-17T22:14:31.974793+10:00, mode=single, current=1, friendly_name=Lights Hall On @ 2020-09-17T22:14:32.244341+10:00>>
2020-09-17 22:14:32 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=script, service=hall_all, service_data=color_temp=500, brightness_pct=35>
2020-09-17 22:14:32 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event script_started[L]: name=Hall All, entity_id=script.hall_all>
2020-09-17 22:14:32 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=script.hall_all, old_state=<state script.hall_all=off; last_triggered=2020-09-17T21:37:45.107648+10:00, mode=single, current=0, friendly_name=Hall All @ 2020-09-17T21:37:45.528133+10:00>, new_state=<state script.hall_all=on; last_triggered=2020-09-17T22:14:32.499928+10:00, mode=single, current=1, friendly_name=Hall All @ 2020-09-17T22:14:32.500043+10:00>>
2020-09-17 22:14:32 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.hall, brightness_pct=35, color_temp=500>
2020-09-17 22:14:32 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_north, old_state=<state light.hall_north=off; min_mireds=153, max_mireds=370, is_deconz_group=False, friendly_name=Hall North, supported_features=43, icon=mdi:track-light @ 2020-09-17T21:39:45.255173+10:00>, new_state=<state light.hall_north=on; min_mireds=153, max_mireds=370, brightness=89, color_temp=500, is_deconz_group=False, friendly_name=Hall North, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:32.773033+10:00>>
2020-09-17 22:14:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_south, old_state=<state light.hall_south=off; min_mireds=153, max_mireds=370, effect_list=['colorloop'], is_deconz_group=False, friendly_name=Hall South, supported_features=63, icon=mdi:track-light @ 2020-09-17T21:39:45.665043+10:00>, new_state=<state light.hall_south=on; min_mireds=153, max_mireds=370, effect_list=['colorloop'], brightness=89, color_temp=500, is_deconz_group=False, friendly_name=Hall South, supported_features=63, icon=mdi:track-light @ 2020-09-17T22:14:33.033204+10:00>>
2020-09-17 22:14:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_center, old_state=<state light.hall_center=off; min_mireds=153, max_mireds=370, is_deconz_group=False, friendly_name=Hall Center, supported_features=43, icon=mdi:track-light @ 2020-09-17T21:39:45.666157+10:00>, new_state=<state light.hall_center=on; min_mireds=153, max_mireds=370, brightness=89, color_temp=500, is_deconz_group=False, friendly_name=Hall Center, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:33.034347+10:00>>
2020-09-17 22:14:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall, old_state=<state light.hall=off; min_mireds=153, max_mireds=500, effect_list=['colorloop'], is_deconz_group=True, all_on=False, friendly_name=Hall, supported_features=47 @ 2020-09-17T21:39:45.666994+10:00>, new_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=89, color_temp=500, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>>
2020-09-17 22:14:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_north, old_state=<state light.hall_north=on; min_mireds=153, max_mireds=370, brightness=89, color_temp=500, is_deconz_group=False, friendly_name=Hall North, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:32.773033+10:00>, new_state=<state light.hall_north=on; min_mireds=153, max_mireds=370, brightness=1, color_temp=500, is_deconz_group=False, friendly_name=Hall North, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:32.773033+10:00>>
2020-09-17 22:14:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall, old_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=89, color_temp=500, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>, new_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=1, color_temp=500, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>>
2020-09-17 22:14:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_center, old_state=<state light.hall_center=on; min_mireds=153, max_mireds=370, brightness=89, color_temp=500, is_deconz_group=False, friendly_name=Hall Center, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:33.034347+10:00>, new_state=<state light.hall_center=on; min_mireds=153, max_mireds=370, brightness=89, color_temp=351, is_deconz_group=False, friendly_name=Hall Center, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:33.034347+10:00>>
2020-09-17 22:14:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall, old_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=1, color_temp=500, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>, new_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=89, color_temp=351, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>>
2020-09-17 22:14:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_center, old_state=<state light.hall_center=on; min_mireds=153, max_mireds=370, brightness=89, color_temp=351, is_deconz_group=False, friendly_name=Hall Center, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:33.034347+10:00>, new_state=<state light.hall_center=on; min_mireds=153, max_mireds=370, brightness=1, color_temp=351, is_deconz_group=False, friendly_name=Hall Center, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:33.034347+10:00>>
2020-09-17 22:14:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall, old_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=89, color_temp=351, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>, new_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=1, color_temp=351, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>>
2020-09-17 22:14:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.sidebar_active, old_state=<state sensor.sidebar_active=2 lamps is on; friendly_name=sidebar_active @ 2020-09-17T21:57:30.352047+10:00>, new_state=<state sensor.sidebar_active=3 lamps is on; friendly_name=sidebar_active @ 2020-09-17T22:14:33.574964+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event timer_out_of_sync[L]: seconds=1.5886788259958848>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=script.hall_all, old_state=<state script.hall_all=on; last_triggered=2020-09-17T22:14:32.499928+10:00, mode=single, current=1, friendly_name=Hall All @ 2020-09-17T22:14:32.500043+10:00>, new_state=<state script.hall_all=off; last_triggered=2020-09-17T22:14:32.499928+10:00, mode=single, current=0, friendly_name=Hall All @ 2020-09-17T22:14:35.590288+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_north, old_state=<state light.hall_north=on; min_mireds=153, max_mireds=370, brightness=1, color_temp=500, is_deconz_group=False, friendly_name=Hall North, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:32.773033+10:00>, new_state=<state light.hall_north=on; min_mireds=153, max_mireds=370, brightness=1, color_temp=351, is_deconz_group=False, friendly_name=Hall North, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:32.773033+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_south, old_state=<state light.hall_south=on; min_mireds=153, max_mireds=370, effect_list=['colorloop'], brightness=89, color_temp=500, is_deconz_group=False, friendly_name=Hall South, supported_features=63, icon=mdi:track-light @ 2020-09-17T22:14:33.033204+10:00>, new_state=<state light.hall_south=on; min_mireds=153, max_mireds=370, effect_list=['colorloop'], brightness=1, color_temp=500, is_deconz_group=False, friendly_name=Hall South, supported_features=63, icon=mdi:track-light @ 2020-09-17T22:14:33.033204+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall, old_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=1, color_temp=351, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>, new_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=1, color_temp=500, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_south, old_state=<state light.hall_south=on; min_mireds=153, max_mireds=370, effect_list=['colorloop'], brightness=1, color_temp=500, is_deconz_group=False, friendly_name=Hall South, supported_features=63, icon=mdi:track-light @ 2020-09-17T22:14:33.033204+10:00>, new_state=<state light.hall_south=on; min_mireds=153, max_mireds=370, effect_list=['colorloop'], brightness=1, color_temp=362, is_deconz_group=False, friendly_name=Hall South, supported_features=63, icon=mdi:track-light @ 2020-09-17T22:14:33.033204+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall, old_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=1, color_temp=500, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>, new_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=1, color_temp=362, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_center, old_state=<state light.hall_center=on; min_mireds=153, max_mireds=370, brightness=1, color_temp=351, is_deconz_group=False, friendly_name=Hall Center, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:33.034347+10:00>, new_state=<state light.hall_center=on; min_mireds=153, max_mireds=370, brightness=89, color_temp=351, is_deconz_group=False, friendly_name=Hall Center, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:33.034347+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall, old_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=1, color_temp=362, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>, new_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=89, color_temp=351, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_north, old_state=<state light.hall_north=on; min_mireds=153, max_mireds=370, brightness=1, color_temp=351, is_deconz_group=False, friendly_name=Hall North, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:32.773033+10:00>, new_state=<state light.hall_north=on; min_mireds=153, max_mireds=370, brightness=89, color_temp=351, is_deconz_group=False, friendly_name=Hall North, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:32.773033+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_center, old_state=<state light.hall_center=on; min_mireds=153, max_mireds=370, brightness=89, color_temp=351, is_deconz_group=False, friendly_name=Hall Center, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:33.034347+10:00>, new_state=<state light.hall_center=on; min_mireds=153, max_mireds=370, brightness=89, color_temp=370, is_deconz_group=False, friendly_name=Hall Center, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:33.034347+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall, old_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=89, color_temp=351, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>, new_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=89, color_temp=370, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_south, old_state=<state light.hall_south=on; min_mireds=153, max_mireds=370, effect_list=['colorloop'], brightness=1, color_temp=362, is_deconz_group=False, friendly_name=Hall South, supported_features=63, icon=mdi:track-light @ 2020-09-17T22:14:33.033204+10:00>, new_state=<state light.hall_south=on; min_mireds=153, max_mireds=370, effect_list=['colorloop'], brightness=89, color_temp=362, is_deconz_group=False, friendly_name=Hall South, supported_features=63, icon=mdi:track-light @ 2020-09-17T22:14:33.033204+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall, old_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=89, color_temp=370, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>, new_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=89, color_temp=362, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_north, old_state=<state light.hall_north=on; min_mireds=153, max_mireds=370, brightness=89, color_temp=351, is_deconz_group=False, friendly_name=Hall North, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:32.773033+10:00>, new_state=<state light.hall_north=on; min_mireds=153, max_mireds=370, brightness=89, color_temp=370, is_deconz_group=False, friendly_name=Hall North, supported_features=43, icon=mdi:track-light @ 2020-09-17T22:14:32.773033+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall, old_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=89, color_temp=362, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>, new_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=89, color_temp=370, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_south, old_state=<state light.hall_south=on; min_mireds=153, max_mireds=370, effect_list=['colorloop'], brightness=89, color_temp=362, is_deconz_group=False, friendly_name=Hall South, supported_features=63, icon=mdi:track-light @ 2020-09-17T22:14:33.033204+10:00>, new_state=<state light.hall_south=on; min_mireds=153, max_mireds=370, effect_list=['colorloop'], brightness=89, color_temp=370, is_deconz_group=False, friendly_name=Hall South, supported_features=63, icon=mdi:track-light @ 2020-09-17T22:14:33.033204+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall_south, old_state=<state light.hall_south=on; min_mireds=153, max_mireds=370, effect_list=['colorloop'], brightness=89, color_temp=370, is_deconz_group=False, friendly_name=Hall South, supported_features=63, icon=mdi:track-light @ 2020-09-17T22:14:33.033204+10:00>, new_state=<state light.hall_south=on; min_mireds=153, max_mireds=370, effect_list=['colorloop'], brightness=89, color_temp=351, is_deconz_group=False, friendly_name=Hall South, supported_features=63, icon=mdi:track-light @ 2020-09-17T22:14:33.033204+10:00>>
2020-09-17 22:14:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hall, old_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=89, color_temp=370, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>, new_state=<state light.hall=on; min_mireds=153, max_mireds=500, effect_list=['colorloop'], brightness=89, color_temp=351, is_deconz_group=True, all_on=True, friendly_name=Hall, supported_features=47 @ 2020-09-17T22:14:33.035246+10:00>>
2020-09-17 22:14:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=switch.washing_machine, old_state=<state switch.washing_machine=on; current_power_w=0.0, current_energy_kwh=9.749, Vera Device Id=94, friendly_name=Washing Machine Power Override, icon=mdi:washing-machine @ 2020-09-16T18:31:30.138269+10:00>, new_state=<state switch.washing_machine=on; current_power_w=0.545, current_energy_kwh=9.749, Vera Device Id=94, friendly_name=Washing Machine Power Override, icon=mdi:washing-machine @ 2020-09-16T18:31:30.138269+10:00>>
2020-09-17 22:14:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event timer_out_of_sync[L]: seconds=4.134853919036686>
2020-09-17 22:14:40 ERROR (MainThread) [homeassistant.components.roku] Error fetching roku data: Invalid response from API: Timeout occurred while connecting to device
2020-09-17 22:14:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=remote.living_room, old_state=<state remote.living_room=on; friendly_name=Living room, supported_features=0 @ 2020-09-17T22:03:18.030022+10:00>, new_state=<state remote.living_room=unavailable; friendly_name=Living room, supported_features=0 @ 2020-09-17T22:14:40.415434+10:00>>
2020-09-17 22:14:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=media_player.roku_bedroom, old_state=<state media_player.roku_bedroom=idle; source_list=['Home', 'ABC News Live', 'Disney Plus', 'Google Play Movies & TV', 'HBO', 'NBC News', 'Nature Relaxation', 'Netflix', 'Plex - Stream for Free', 'Prime Video', 'Roku Media Player', 'Roku Tips & Tricks', 'Spotify Music', 'The Roku Channel', 'Vimeo', 'YouTube', 'iHeartRadio'], app_name=Roku, source=Roku, friendly_name=Bedroom Roku, supported_features=151481, device_class=receiver @ 2020-09-17T22:03:18.030957+10:00>, new_state=<state media_player.roku_bedroom=unavailable; source_list=['Home', 'ABC News Live', 'Disney Plus', 'Google Play Movies & TV', 'HBO', 'NBC News', 'Nature Relaxation', 'Netflix', 'Plex - Stream for Free', 'Prime Video', 'Roku Media Player', 'Roku Tips & Tricks', 'Spotify Music', 'The Roku Channel', 'Vimeo', 'YouTube', 'iHeartRadio'], friendly_name=Bedroom Roku, supported_features=151481, device_class=receiver @ 2020-09-17T22:14:40.416154+10:00>>
2020-09-17 22:14:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=switch.dishwasher, old_state=<state switch.dishwasher=on; current_power_w=0.00, total_energy_kwh=6.065, voltage=251.1, current_a=0.02, today_energy_kwh=0.308, friendly_name=Dishwasher, icon=mdi:washing-machine @ 2020-09-16T18:31:24.859393+10:00>, new_state=<state switch.dishwasher=on; current_power_w=0.00, total_energy_kwh=6.065, voltage=250.9, current_a=0.02, today_energy_kwh=0.308, friendly_name=Dishwasher, icon=mdi:washing-machine @ 2020-09-16T18:31:24.859393+10:00>>

I found a template sensor which was looking at a few of my downlights, which I am guessing was being hit each time the lights updated. I've removed that one sensor.

In the logs above, as the script to turn the hall lights on is being triggered, and the lights are changing temperatures etc, Home Assistant chokes. When this happens, my Roku is marked as "unavailable" as Home Assistant can't get a connection out in time. There's also a "timer out of sync" error that occurs.

My assumption is that because the lights are changing temperature, anything watches the lights is getting hit.

This gets worse, as now that my Roku is marked as "unavailable", my alarm panel then moves into the armed_night state. This triggers my hue lights around the house to change Red. Once again causing a whole bunch of activity in my logs as the various bulbs change from their previous colours to red over 10-20 seconds. Home assistant then chokes again.

For the time being I am going to disable my templates that count how many lights are on in Lovelace and in my YAML. See if that makes a difference during the time when a few of my lights are transitioning.

Unfortunately I don't know why this is causing spikes like this in 0.115 and not 0.114 though.

bdraco commented 4 years ago

It looks like there is a feedback loop between the templates that didn't trigger in 0.114 because we missed some of the states in the template. Now that it can find them all, I suspect the loop can happen.

Can you post all the relevant yaml configuration for the bayes and template entities?

Also if you dump the template into the developer tools, it now shows you which states it is watching.

bdraco commented 4 years ago

@philhawthorne 0.116b1 could make a big difference if you are still having performance issues.

philhawthorne commented 4 years ago

Thanks @bdraco

Just upgraded to the beta. Having some unrelated issues so I'll have to roll back for now.

After reading some of your other github comments around CPU usage, I found a template in one of my Lovelace which was looking at all state changes, instead of just state changes for the light domain. After I changed that, things became a lot smoother. Not as smooth as 0.114, but much smoother.

So I'm hoping now with that template fixed, and 0.116b1 changes everything will be super smooth. Really appreciate your assistance.

home-assistant / core