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
73.51k stars 30.71k forks source link

A lot of "is taking over 10 seconds" and "took longer than the scheduled update interval" errors in > 0.78 #16986

Closed anaxyd closed 6 years ago

anaxyd commented 6 years ago

Home Assistant release with the issue:

0.79

Last working Home Assistant release (if known): 0.68

Operating environment (Hass.io/Docker/Windows/etc.):

Hassbian on RPI3

Component/platform:

Description of problem: Getting a lot of timeout errors in log after upgrading from 0.68 to 0.78. It seems to be coming each minute or so in the error log. See a bit of the error log below.

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

Traceback (if applicable):

018-09-29 23:08:00 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:05
2018-09-29 23:08:06 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:05
2018-09-29 23:08:07 WARNING (MainThread) [homeassistant.components.sensor] Updating command_line sensor took longer than the scheduled update interval 0:00:30
2018-09-29 23:08:07 WARNING (MainThread) [homeassistant.components.sensor] Updating speedtest sensor took longer than the scheduled update interval 0:00:30
2018-09-29 23:08:08 WARNING (MainThread) [homeassistant.components.sensor] Updating systemmonitor sensor took longer than the scheduled update interval 0:00:30
2018-09-29 23:08:08 WARNING (MainThread) [homeassistant.components.media_player] Updating sonos media_player took longer than the scheduled update interval 0:00:10
2018-09-29 23:08:09 WARNING (MainThread) [homeassistant.components.sensor] Updating netatmo sensor took longer than the scheduled update interval 0:00:30
2018-09-29 23:08:12 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:05
2018-09-29 23:08:17 WARNING (MainThread) [homeassistant.components.sensor] Updating ios sensor took longer than the scheduled update interval 0:00:30
2018-09-29 23:08:18 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:05
2018-09-29 23:08:19 WARNING (MainThread) [homeassistant.components.media_player] Updating sonos media_player took longer than the scheduled update interval 0:00:10
2018-09-29 23:08:24 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:05
2018-09-29 23:08:30 WARNING (MainThread) [homeassistant.components.media_player] Updating sonos media_player took longer than the scheduled update interval 0:00:10
2018-09-29 23:08:30 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:05
2018-09-29 23:08:36 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:05
2018-09-29 23:08:38 WARNING (MainThread) [homeassistant.components.sensor] Updating command_line sensor took longer than the scheduled update interval 0:00:30
2018-09-29 23:08:38 WARNING (MainThread) [homeassistant.components.sensor] Updating speedtest sensor took longer than the scheduled update interval 0:00:30
2018-09-29 23:08:39 WARNING (MainThread) [homeassistant.components.sensor] Updating systemmonitor sensor took longer than the scheduled update interval 0:00:30
2018-09-29 23:08:40 WARNING (MainThread) [homeassistant.components.sensor] Updating netatmo sensor took longer than the scheduled update interval 0:00:30
2018-09-29 23:08:41 WARNING (MainThread) [homeassistant.components.media_player] Updating sonos media_player took longer than the scheduled update interval 0:00:10
2018-09-29 23:08:42 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:05
2018-09-29 23:08:48 WARNING (MainThread) [homeassistant.components.sensor] Updating ios sensor took longer than the scheduled update interval 0:00:30
2018-09-29 23:08:48 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:05
2018-09-29 23:08:52 WARNING (MainThread) [homeassistant.components.media_player] Updating sonos media_player took longer than the scheduled update interval 0:00:10
2018-09-29 23:08:54 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:05
2018-09-29 23:09:03 WARNING (MainThread) [homeassistant.components.media_player] Updating sonos media_player took longer than the scheduled update interval 0:00:10
2018-09-29 23:09:06 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:05
2018-09-29 23:09:06 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.XXX_iphone_battery_state is taking over 10 seconds
2018-09-29 23:09:06 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.speedtest_ping is taking over 10 seconds
2018-09-29 23:09:06 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.memory_use_percent is taking over 10 seconds
2018-09-29 23:09:06 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.netatmo_innesensor_pressure is taking over 10 seconds
2018-09-29 23:09:06 WARNING (MainThread) [homeassistant.helpers.entity] Update of media_player.stue is taking over 10 seconds

Additional information:

cgarwood commented 6 years ago

Anything else running on your Pi? What do your load averages look like in the console? uptime or top - and how's the memory utilization?

ghost commented 6 years ago

Same here. Because of this automations take forever to execute

follox commented 6 years ago

Same problem here:

Updating sonos media_player took longer than the scheduled update interval 0:00:10
10:17 AM helpers/entity_platform.py (WARNING)
Updating sonos media_player took longer than the scheduled update interval 0:00:10
10:17 AM helpers/entity_platform.py (WARNING)
Updating sonos media_player took longer than the scheduled update interval 0:00:10
10:17 AM helpers/entity_platform.py (WARNING)
Updating sonos media_player took longer than the scheduled update interval 0:00:10
10:16 AM helpers/entity_platform.py (WARNING)
Update of sensor.varmepumpe_oppe_temperature is taking over 10 seconds
9:39 AM util/async_.py (WARNING)
Updating sonos media_player took longer than the scheduled update interval 0:00:10
9:03 AM helpers/entity_platform.py (WARNING)
Updating sonos media_player took longer than the scheduled update interval 0:00:10
9:03 AM helpers/entity_platform.py (WARNING)
Updating sonos media_player took longer than the scheduled update interval 0:00:10
9:03 AM helpers/entity_platform.py (WARNING)
Update for sensor.sirene_kjkken_temperature fails
8:52 AM components/verisure.py (ERROR)
Updating verisure sensor took longer than the scheduled update interval 0:00:30
8:52 AM helpers/entity_platform.py (WARNING)
Updating verisure sensor took longer than the scheduled update interval 0:00:30
8:52 AM helpers/entity_platform.py (WARNING)
Updating verisure sensor took longer than the scheduled update interval 0:00:30
8:51 AM helpers/entity_platform.py (WARNING)
Updating verisure sensor took longer than the scheduled update interval 0:00:30
8:51 AM helpers/entity_platform.py (WARNING)
Updating verisure sensor took longer than the scheduled update interval 0:00:30
8:50 AM helpers/entity_platform.py (WARNING)
Updating verisure sensor took longer than the scheduled update interval 0:00:30
8:49 AM helpers/entity_platform.py (WARNING)
Updating verisure sensor took longer than the scheduled update interval 0:00:30
8:49 AM helpers/entity_platform.py (WARNING)
Updating verisure sensor took longer than the scheduled update interval 0:00:30
8:48 AM helpers/entity_platform.py (WARNING)
Update of sensor.sirene_kjkken_temperature is taking over 10 seconds
8:48 AM util/async_.py (WARNING)
Updating verisure sensor took longer than the scheduled update interval 0:00:30
8:48 AM helpers/entity_platform.py (WARNING)
Resumed, lost 38 events
8:48 AM components/influxdb.py (ERROR)
Error doing job: Future exception was never retrieved
8:48 AM custom_components/climate/verisure/session.py (ERROR)
Updating ring binary_sensor took longer than the scheduled update interval 0:00:10
8:48 AM helpers/entity_platform.py (WARNING)
Update for sensor.stue_2_etasje_temperature fails
8:48 AM components/verisure.py (ERROR)
Update for sensor.varmepumpe_nede_temperature fails
8:48 AM components/verisure.py (ERROR)
Update for sensor.varmepumpe_oppe_temperature fails
8:48 AM components/verisure.py (ERROR)
Updating ring binary_sensor took longer than the scheduled update interval 0:00:10
8:48 AM helpers/entity_platform.py (WARNING)
Updating sonos media_player took longer than the scheduled update interval 0:00:10
8:48 AM helpers/entity_platform.py (WARNING)
Update for sensor.stue_temperature fails
8:48 AM components/verisure.py (ERROR)
Update for sensor.vaskerom_temperature fails
8:48 AM components/verisure.py (ERROR)
Updating ring binary_sensor took longer than the scheduled update interval 0:00:10
8:48 AM helpers/entity_platform.py (WARNING)
Updating ring binary_sensor took longer than the scheduled update interval 0:00:10
8:47 AM helpers/entity_platform.py (WARNING)
Updating sonos media_player took longer than the scheduled update interval 0:00:10
8:47 AM helpers/entity_platform.py (WARNING)
Updating denonavr media_player took longer than the scheduled update interval 0:00:10
8:47 AM helpers/entity_platform.py (WARNING)
Update for sensor.varmepumpe_oppe_temperature fails
8:47 AM components/verisure.py (ERROR)
Updating ring binary_sensor took longer than the scheduled update interval 0:00:10
8:47 AM helpers/entity_platform.py (WARNING)
Update for sensor.nattpanel_soverom_temperature fails
8:47 AM components/verisure.py (ERROR)
Updating denonavr media_player took longer than the scheduled update interval 0:00:10
8:47 AM helpers/entity_platform.py (WARNING)
Update for sensor.stue_temperature fails
8:47 AM components/verisure.py (ERROR)
Updating ring binary_sensor took longer than the scheduled update interval 0:00:10
8:47 AM helpers/entity_platform.py (WARNING)
Updating sonos media_player took longer than the scheduled update interval 0:00:10
8:47 AM helpers/entity_platform.py (WARNING)
Updating verisure sensor took longer than the scheduled update interval 0:00:30
8:47 AM helpers/entity_platform.py (WARNING)
Update for sensor.vaskerom_humidity fails
8:47 AM components/verisure.py (ERROR)
Updating denonavr media_player took longer than the scheduled update interval 0:00:10
8:47 AM helpers/entity_platform.py (WARNING)
Error doing job: Future exception was never retrieved
8:47 AM custom_components/climate/verisure/session.py (ERROR)
Update of media_player.denon_avrx2300w is taking over 10 seconds
8:47 AM util/async_.py (WARNING)
Update for sensor.stue_2_etasje_humidity fails
8:47 AM components/verisure.py (ERROR)
Updating ring binary_sensor took longer than the scheduled update interval 0:00:10
8:47 AM helpers/entity_platform.py (WARNING)
Update for sensor.varmepumpe_nede_temperature fails
8:47 AM components/verisure.py (ERROR)
Update for sensor.vaskerom_temperature fails
8:47 AM components/verisure.py (ERROR)
Unable to reach bridge 192.168.1.238
8:47 AM components/light/hue.py (ERROR)

Also experiencing that lights controlled by Fibaro Wall plug is almost uncontrollable. When toggling on, it's toggle itself off again without turning the lamp on. Sometimes it works, but majority of the time after the upgrade it is only toggling back to off position again without turning the lamp on.

Naesstrom commented 6 years ago

I'm having the same problem to and the log is filled with "timer out of sync" messages!

top: mobaxterm screenshot

arsaboo commented 6 years ago

@Naesstrom Your load average is over 1, suggesting capacity issues. If those messages only appear on startup, they can be ignored.

anaxyd commented 6 years ago

Anything else running on your Pi? What do your load averages look like in the console? uptime or top - and how's the memory utilization?

This is my top:

image

ghost commented 6 years ago

Any luck figuring out the solution to this?

lbschenkel commented 6 years ago

I'm experiencing this issue as well. It happens with all sorts of sensors that poll the network, but usually starts with the ping ones first. I have enabled the DEBUG log globally and the ping sensors simply no longer run: no output from the ping executions is seen on the logs and watch -n1 ps w shows no evidence of the ping commands running (I can see both before this problem starts manifesting).

WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:05:00

Not sure if related, but at some point other sensors start sporadically failing with bad file descriptor. I have already made sure that ulimit -n is set to unlimited, system-wide.

ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/homeassistant/components/device_tracker/__init__.py", line 692, in async_device_tracker_scan
    found_devices = await scanner.async_scan_devices()
  File "/usr/local/lib/python3.6/concurrent/futures/thread.py", line 56, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.6/site-packages/homeassistant/components/device_tracker/nmap_tracker.py", line 81, in scan_devices
    self._update_info()
  File "/usr/local/lib/python3.6/site-packages/homeassistant/components/device_tracker/nmap_tracker.py", line 132, in _update_info
    arguments=options)
  File "/usr/local/lib/python3.6/site-packages/nmap/nmap.py", line 231, in scan
    stderr=subprocess.PIPE)
  File "/usr/local/lib/python3.6/subprocess.py", line 709, in __init__
    restore_signals, start_new_session)
  File "/usr/local/lib/python3.6/subprocess.py", line 1304, in _execute_child
    os.close(errpipe_read)
OSError: [Errno 9] Bad file descriptor

Edit: I forgot to mention that when this happens, I tested running the ping commands manually from inside the container (ping, nmap, etc.) and they all work successfully. However, the sensors no longer update and I see no evidence of HASS trying to run the commands (only the repeated took longer than messages).

It looks that once the first sensor starts misbehaving, threads start getting stuck and other parts start failing. At some point even the HTTP server stops responding (but no errors in the logs) and I have to restart the HASS container. Sometimes it takes many hours for this to start happening again, and sometimes mere minutes.

I'm also seeing the exact same messages reported on https://github.com/home-assistant/home-assistant/issues/16930. I noticed these problems after the upgrade to 0.80.0, but unfortunately my logs rolled over and I cannot confirm this with 100% certainty. I'm not sure if it could be a side effect of: https://github.com/home-assistant/home-assistant/pull/17056.

I'm running the hass.io container on my NAS, a quad-core Core i5 with 16GB RAM. The machine is lightly loaded (< 0.2 load) and has plenty of free RAM (> 50%). I have tried to generate a backtrace via gdb, but unfortunately Alpine's gdb from the HASS container does not have the necessary Python support compiled-in for me to get a Python-level backtrace of the HASS process. Please let me know how I can further help in diagnosing this issue.

lbschenkel commented 6 years ago

Follow-up: Now I noticed in two different occasions that zombie child processes showed up: in one it was ping and in another it was nmap. They're never reaped by HASS and the respective sensors no longer run new commands: they just keep logging took longer than the scheduled update interval.

I noticed there's a new 0.80.1 release that is addressing some async issues, I'll try upgrading to see if there's any change.

Edit: upgraded to 0.80.1, unfortunately the nmap issue I mentioned above persists. Will wait for some hours for the other issues to reproduce (or not).

Unfortunately, ping sensor started failing after some hours:

2018-10-15 22:35:57 ERROR (MainThread) [homeassistant.helpers.entity] Update for binary_sensor.redacted fails
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/homeassistant/helpers/entity.py", line 221, in async_update_ha_state
    await self.async_device_update()
  File "/usr/local/lib/python3.6/site-packages/homeassistant/helpers/entity.py", line 347, in async_device_update
    await self.async_update()
  File "/usr/local/lib/python3.6/site-packages/homeassistant/components/binary_sensor/ping.py", line 98, in async_update
    await self.ping.update()
  File "/usr/local/lib/python3.6/site-packages/homeassistant/components/binary_sensor/ping.py", line 158, in update
    self.data = await self.ping()
  File "/usr/local/lib/python3.6/site-packages/homeassistant/components/binary_sensor/ping.py", line 123, in ping
    stderr=subprocess.PIPE)
  File "/usr/local/lib/python3.6/asyncio/subprocess.py", line 210, in create_subprocess_shell
    stderr=stderr, **kwds)
  File "uvloop/loop.pyx", line 2591, in subprocess_shell
  File "uvloop/loop.pyx", line 2563, in __subprocess_run
  File "uvloop/handles/process.pyx", line 595, in uvloop.loop.UVProcessTransport.new
  File "uvloop/handles/process.pyx", line 130, in uvloop.loop.UVProcess._init
OSError: [Errno 9] Bad file descriptor
follox commented 6 years ago

I am getting a lot of errors I have no clue what means...

Errors.txt

trekker25 commented 5 years ago

Got this issue since about March this year and i suspect it's Sonos that is causing it.

The logs keeps filling up with "took longer" The openzwave log is increasing, but the UI or automations are not working anymore.

The Hass software should be more robust, or some kind of option to at least have the UI respond, and the light toggles and automations.

And maybe implement something to ignore not responding devices.

I must add that i have some stabillity issues with Sonos on it's on (music sometimes pausing), but a media_player device in Hass should never cause the complete Hass is unresponsive!

WisdomWolf commented 5 years ago

This issue appears to still be present on 0.84.6 because I see my logs full of these messages and the HTTP server only appears to remain accessible for a few hours before it just stops responding. Any word on the cause or fix for this issue?

trekker25 commented 5 years ago

I removed Discovery and all non critical items from HASS (Harmony telegram etc) and is more stable now.

Also installed monit on my server that will check the UI of HASs every minute and when fails three times does a restart of the docker image. Hope this increases the WAF.

Only now wanting a toggle in iOS or something with Siri to do a Hass reboot.

Scepticalist commented 5 years ago

Any updates for this issue? I got a lot of these errors today and eventually HASS fell over completely to the extnet I had to restart the Ubuntu server - a service restart from the UI simply took it all offline.

smashah commented 5 years ago

This is becoming a real problem for me also. 25 tuya lights around the house and these errors are crippling the hassio pi. Here's what comes up in the logs.

2019-02-18 13:53:45 ERROR (MainThread) [homeassistant.helpers.entity] Update for switch.08045547840d8e6004b8 fails
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/urllib3/connection.py", line 159, in _new_conn
    (self._dns_host, self.port), self.timeout, **extra_kw)
  File "/usr/local/lib/python3.6/site-packages/urllib3/util/connection.py", line 57, in create_connection
    for res in socket.getaddrinfo(host, port, family, socket.SOCK_STREAM):
  File "/usr/local/lib/python3.6/socket.py", line 745, in getaddrinfo
    for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -3] Try again
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/urllib3/connectionpool.py", line 600, in urlopen
    chunked=chunked)
  File "/usr/local/lib/python3.6/site-packages/urllib3/connectionpool.py", line 343, in _make_request
    self._validate_conn(conn)
  File "/usr/local/lib/python3.6/site-packages/urllib3/connectionpool.py", line 839, in _validate_conn
    conn.connect()
  File "/usr/local/lib/python3.6/site-packages/urllib3/connection.py", line 301, in connect
    conn = self._new_conn()
  File "/usr/local/lib/python3.6/site-packages/urllib3/connection.py", line 168, in _new_conn
    self, "Failed to establish a new connection: %s" % e)
urllib3.exceptions.NewConnectionError: : Failed to establish a new connection: [Errno -3] Try again
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/requests/adapters.py", line 449, in send
    timeout=timeout
  File "/usr/local/lib/python3.6/site-packages/urllib3/connectionpool.py", line 638, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/usr/local/lib/python3.6/site-packages/urllib3/util/retry.py", line 398, in increment
    raise MaxRetryError(_pool, url, error or ResponseError(cause))
urllib3.exceptions.MaxRetryError: HTTPSConnectionPool(host='px1.tuyaeu.com', port=443): Max retries exceeded with url: /homeassistant/skill (Caused by NewConnectionError(': Failed to establish a new connection: [Errno -3] Try again',))
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/homeassistant/helpers/entity.py", line 221, in async_update_ha_state
    await self.async_device_update()
  File "/usr/local/lib/python3.6/site-packages/homeassistant/helpers/entity.py", line 349, in async_device_update
    await self.hass.async_add_executor_job(self.update)
  File "/usr/local/lib/python3.6/concurrent/futures/thread.py", line 56, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.6/site-packages/homeassistant/components/tuya.py", line 156, in update
    self.tuya.update()
  File "/usr/local/lib/python3.6/site-packages/tuyapy/devices/base.py", line 43, in update
    self.obj_id, 'QueryDevice', namespace='query')
  File "/usr/local/lib/python3.6/site-packages/tuyapy/tuyaapi.py", line 134, in device_control
    response = self._request(action, namespace, devId, param)
  File "/usr/local/lib/python3.6/site-packages/tuyapy/tuyaapi.py", line 159, in _request
    json = data
  File "/usr/local/lib/python3.6/site-packages/requests/api.py", line 116, in post
    return request('post', url, data=data, json=json, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/requests/api.py", line 60, in request
    return session.request(method=method, url=url, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/requests/sessions.py", line 533, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/local/lib/python3.6/site-packages/requests/sessions.py", line 646, in send
    r = adapter.send(request, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/requests/adapters.py", line 516, in send
    raise ConnectionError(e, request=request)
requests.exceptions.ConnectionError: HTTPSConnectionPool(host='px1.tuyaeu.com', port=443): Max retries exceeded with url: /homeassistant/skill (Caused by NewConnectionError(': Failed to establish a new connection: [Errno -3] Try again',))
Scepticalist commented 5 years ago

You can improve this situation a lot by Sonos config. Make sure only one of your Sonos has a hardwired connection. If more than one is hardwired, it's best to turn off the wireless that Sonos player through the Android/iPhone app advanced room setting (don't turn it off on all the wired ones!)

ReneTode commented 5 years ago

i have had this problem off and on over the last year. still no clue whats causing it. i am on the latest HA (updated yesterday) system health info:


arch | x86_64
-- | --
dev | false
docker | false
hassio | false
os_name | Linux
python_version | 3.6.7
timezone | Europe/Berlin
version | 0.88.1
virtualenv | true

and a little of the log:

2019-02-28 13:02:00 WARNING (MainThread) [homeassistant.components.sensor] Updating systemmonitor sensor took longer than the scheduled update interval 0:00:30
2019-02-28 13:02:06 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.network_in is taking over 10 seconds
2019-02-28 13:02:06 WARNING (MainThread) [homeassistant.helpers.entity] Update of calendar.olindetodegmailcom is taking over 10 seconds
2019-02-28 13:02:08 WARNING (MainThread) [homeassistant.components.calendar] Updating google calendar took longer than the scheduled update interval 0:01:00
2019-02-28 13:02:10 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.season is taking over 10 seconds
2019-02-28 13:02:10 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.fritz_netmonitor is taking over 10 seconds
2019-02-28 13:02:35 WARNING (MainThread) [homeassistant.helpers.entity] Update of calendar.dossier_marjolijn is taking over 10 seconds
2019-02-28 13:03:01 WARNING (MainThread) [homeassistant.components.sensor] Updating systemmonitor sensor took longer than the scheduled update interval 0:00:30
2019-02-28 13:03:04 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.processor_use is taking over 10 seconds
2019-02-28 13:03:30 WARNING (MainThread) [homeassistant.helpers.entity] Update of calendar.dossier_pa is taking over 10 seconds
2019-02-28 13:03:59 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.memory_use is taking over 10 seconds
2019-02-28 13:03:59 WARNING (MainThread) [homeassistant.helpers.entity] Update of calendar.dossier_farah is taking over 10 seconds
2019-02-28 13:04:10 WARNING (MainThread) [homeassistant.components.calendar] Updating google calendar took longer than the scheduled update interval 0:01:00
2019-02-28 13:04:27 WARNING (MainThread) [homeassistant.helpers.entity] Update of calendar.arbeit is taking over 10 seconds
2019-02-28 13:04:27 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.last_boot is taking over 10 seconds
2019-02-28 13:04:56 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.memory_use is taking over 10 seconds
2019-02-28 13:05:05 WARNING (MainThread) [homeassistant.components.sensor] Updating systemmonitor sensor took longer than the scheduled update interval 0:00:30
2019-02-28 13:05:25 WARNING (MainThread) [homeassistant.helpers.entity] Update of calendar.dossier_rene is taking over 10 seconds
2019-02-28 13:05:55 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.network_in is taking over 10 seconds
2019-02-28 13:05:55 WARNING (MainThread) [homeassistant.helpers.entity] Update of calendar.wk_2018_rusland is taking over 10 seconds
2019-02-28 13:06:12 WARNING (MainThread) [homeassistant.components.calendar] Updating google calendar took longer than the scheduled update interval 0:01:00
2019-02-28 13:06:23 WARNING (MainThread) [homeassistant.helpers.entity] Update of calendar.dossier_marjolijn is taking over 10 seconds
2019-02-28 13:06:25 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.processor_use is taking over 10 seconds
2019-02-28 13:06:53 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.last_boot is taking over 10 seconds
2019-02-28 13:07:22 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.network_out is taking over 10 seconds
2019-02-28 13:07:23 WARNING (MainThread) [homeassistant.helpers.entity] Update of calendar.dossier_farah is taking over 10 seconds
2019-02-28 13:07:48 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.season is taking over 10 seconds
2019-02-28 13:07:48 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.fritz_netmonitor is taking over 10 seconds
2019-02-28 13:07:48 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.network_out is taking over 10 seconds
2019-02-28 13:07:54 WARNING (MainThread) [homeassistant.helpers.entity] Update of calendar.wk_2018_rusland is taking over 10 seconds
2019-02-28 13:08:09 WARNING (MainThread) [homeassistant.components.sensor] Updating systemmonitor sensor took longer than the scheduled update interval 0:00:30
2019-02-28 13:08:14 WARNING (MainThread) [homeassistant.components.calendar] Updating google calendar took longer than the scheduled update interval 0:01:00
2019-02-28 13:08:19 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.season is taking over 10 seconds
2019-02-28 13:08:19 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.fritz_netmonitor is taking over 10 seconds
2019-02-28 13:08:19 WARNING (MainThread) [homeassistant.helpers.entity] Update of calendar.dossier_marjolijn is taking over 10 seconds
2019-02-28 13:08:50 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.season is taking over 10 seconds
2019-02-28 13:08:50 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.fritz_netmonitor is taking over 10 seconds
2019-02-28 13:08:50 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.processor_use is taking over 10 seconds

no errors when it started. i also cant reproduce it, because when i restart HA it can take hours, days, or weeks before the trouble starts. (which makes debugging very hard)

edit: some system info: i got a beebox with 16 Gb mem. no mem problems or CPU problems (never over 16%) i got no sonos, or any mediaplayer in my setup

smashah commented 5 years ago

I don't use any sonos devices. I have many cast devices but the cast component in the configuration.yaml causes many issues (one being that it conflicts with discovery resulting in many errors and it doesn't pick up groups) so I commented it out. Fixed some issues.

I have HASSio on RPi3b+ and use juicessh sometimes which has a performance monitoring feature. When I see these errors the CPU is peaking 99-100%. Which results in all of these tasks taking longer than x seconds.

ReneTode commented 5 years ago

update from my side: this issue happens when something goes wrong with the network connection i have 2 HA instances running now, and it happened to both when i was adding an accespoint.

there are only 2 components that i got in both HA instances:

so the problem is in 1 of these components or in the HA core and its network related.

follox commented 5 years ago

This case is marked as closed, so I am not sure if anything will happen.

ReneTode commented 5 years ago

hmm, thanks, i didnt even notice that. i wasnt expecting anything from it anyway. maybe i need to open a new one. :(

dzungpv commented 5 years ago

I have this warning with SQL sensor too, PI 3 B+ Sandisk Ultra SD card, the database is MarialDB, Home Assistant 0.90.2. You guy should try to let DB store more than 30 days and try any SQL sensor to reproduce this

nullnullnul commented 4 years ago

Is this going to be solved? My logs are full with errors: 2020-01-18 02:26:37 WARNING (MainThread) [homeassistant.components.sensor] Updating opensky sensor took longer than the scheduled update interval 0:00:12 2020-01-18 02:27:39 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.opensky is taking over 10 seconds

mkanet commented 4 years ago

I am seeing the same exact issue. I have several REST sensors which update once every 10 seconds. These sensors access API endpoints that are all accessible within 1-6 seconds from anywhere on my LAN. It definitely doesn't take 10 seconds or more to reach these endpoints from a web browser. My setup runs okay for about 4-5 hours or so, then begins producing a ton of these timeout errors endlessly. Something causes the rest sensors to start cascading with a ton of errors. The only way I can fix it is to restart Home Assistant.

I am running Home Assistant in a VirtualBox VM on a Windows 10 host. The API endpoints are a Glances server on the same Windows 10 host.

I noticed that this issue is "Closed"; however, I don't see a solution for this issue. Has anyone figured out a way to resolve this issue? Or, at least a way to troubleshoot it?

2020-07-09 01:58:29 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 01:58:29 ERROR (SyncWorker_4) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 01:59:45 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:10
2020-07-09 02:00:04 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_pagefile is taking over 10 seconds
2020-07-09 02:00:04 ERROR (SyncWorker_3) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/memswap failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 02:01:12 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 02:01:12 ERROR (SyncWorker_1) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 02:01:23 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.gpu is taking over 10 seconds
2020-07-09 02:01:23 ERROR (SyncWorker_4) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/gpu failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 02:01:23 WARNING (SyncWorker_4) [homeassistant.components.rest.sensor] Empty reply found when expecting JSON data
2020-07-09 02:01:23 ERROR (MainThread) [homeassistant.components.template.sensor] Could not render template horizon_gpu_memory: UndefinedError: 'mappingproxy object' has no attribute 'mem'
2020-07-09 02:01:23 WARNING (MainThread) [homeassistant.components.alexa.capabilities] Invalid temp value  for sensor.horizon_gpu_temperature
2020-07-09 02:18:31 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_pagefile is taking over 10 seconds
2020-07-09 02:18:31 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 02:18:31 ERROR (SyncWorker_1) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 02:18:31 ERROR (SyncWorker_0) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/memswap failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 02:18:32 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:10
2020-07-09 05:28:20 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:10
2020-07-09 05:54:38 ERROR (SyncWorker_3) [homeassistant.components.openweathermap.weather] Exception when calling OWM web API to update data
2020-07-09 06:56:01 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:10
2020-07-09 08:18:21 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_uptime is taking over 10 seconds
2020-07-09 08:18:21 ERROR (SyncWorker_2) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/uptime failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:17:59 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:17:59 ERROR (SyncWorker_0) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:18:00 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:10
2020-07-09 09:18:16 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_uptime is taking over 10 seconds
2020-07-09 09:18:16 ERROR (SyncWorker_2) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/uptime failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:18:18 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_pagefile is taking over 10 seconds
2020-07-09 09:18:18 ERROR (SyncWorker_4) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/memswap failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:18:32 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:18:32 ERROR (SyncWorker_0) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:18:47 ERROR (bellows.thread_0) [bellows.uart] CRC error in frame b'00217aa1ad90fb7e' (b'90fb' != b'0537')
2020-07-09 09:18:54 ERROR (SyncWorker_0) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:18:54 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:18:54 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:10
2020-07-09 09:19:15 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:19:15 ERROR (SyncWorker_4) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:19:36 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:19:36 ERROR (SyncWorker_0) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:19:58 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:19:58 ERROR (SyncWorker_3) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:20:18 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_uptime is taking over 10 seconds
2020-07-09 09:20:18 ERROR (SyncWorker_2) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/uptime failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:20:31 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:20:31 ERROR (SyncWorker_1) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:20:44 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_pagefile is taking over 10 seconds
2020-07-09 09:20:44 ERROR (SyncWorker_1) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/memswap failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:21:04 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:21:04 ERROR (SyncWorker_1) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:21:19 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_uptime is taking over 10 seconds
2020-07-09 09:21:19 ERROR (SyncWorker_2) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/uptime failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:21:37 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:21:37 ERROR (SyncWorker_3) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:21:59 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:21:59 ERROR (SyncWorker_1) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:22:20 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_uptime is taking over 10 seconds
2020-07-09 09:22:20 ERROR (SyncWorker_0) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/uptime failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:22:32 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:10
2020-07-09 09:22:32 ERROR (SyncWorker_0) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:22:32 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:22:49 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_pagefile is taking over 10 seconds
2020-07-09 09:22:49 ERROR (SyncWorker_2) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/memswap failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:23:03 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:23:03 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:10
2020-07-09 09:23:03 ERROR (SyncWorker_4) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:23:21 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_uptime is taking over 10 seconds
2020-07-09 09:23:35 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:23:35 ERROR (SyncWorker_3) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:23:51 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_pagefile is taking over 10 seconds
2020-07-09 09:23:51 ERROR (SyncWorker_2) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/memswap failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:24:07 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:24:07 ERROR (SyncWorker_4) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:24:22 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_uptime is taking over 10 seconds
2020-07-09 09:24:22 ERROR (SyncWorker_1) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/uptime failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:24:40 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:24:40 ERROR (SyncWorker_3) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:24:54 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_pagefile is taking over 10 seconds
2020-07-09 09:24:54 ERROR (SyncWorker_4) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/memswap failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)
2020-07-09 09:25:13 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.horizon_ram is taking over 10 seconds
2020-07-09 09:25:13 ERROR (SyncWorker_4) [homeassistant.components.rest.sensor] Error fetching data: http://192.168.1.2:61208/api/3/mem failed with HTTPConnectionPool(host='192.168.1.2', port=61208): Read timed out. (read timeout=10)