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.89k stars 30.96k forks source link

Constant "Timer got out of sync" errors #6253

Closed danodemano closed 7 years ago

danodemano commented 7 years ago

Home Assistant release (hass --version): 0.39.0

Python release (python3 --version): 3.4.2

Component/platform: Core

Description of problem: Constant ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting Errors in log file

Expected: No error

Problem-relevant configuration.yaml entries and steps to reproduce: N/A just happens

Traceback (if applicable): N/A

Additional info: Wasn't happening in 0.38.3. No real consistency to timing:

17-02-26 14:31:24 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-26 14:31:26 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-26 14:31:29 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-26 14:31:31 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-26 14:31:35 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-26 14:31:37 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-26 14:31:40 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-26 14:31:45 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-26 14:31:52 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-26 14:32:00 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-26 14:32:03 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-26 14:33:31 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-26 14:35:30 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
terrycarlin commented 7 years ago

I am seeing this also. It might be from the hdmi_cec component as I see some “flickering” on the panel.

On Feb 26, 2017, at 12:37 PM, danodemano notifications@github.com wrote:

Home Assistant release (hass --version): 0.39.0

Python release (python3 --version): 3.4.2

Component/platform: Core

Description of problem: Constant ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting Errors in log file

Expected: No error

Problem-relevant configuration.yaml entries and steps to reproduce: N/A just happens

Traceback (if applicable): N/A

Additional info: Wasn't happening in 0.38.4. No real consistency to timing:

17-02-26 14:31:24 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-26 14:31:26 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-26 14:31:29 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-26 14:31:31 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-26 14:31:35 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-26 14:31:37 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-26 14:31:40 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-26 14:31:45 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-26 14:31:52 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-26 14:32:00 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-26 14:32:03 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-26 14:33:31 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-26 14:35:30 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/6253, or mute the thread https://github.com/notifications/unsubscribe-auth/AA1W1LJLh5k8Zz3S1dwlO3ZaC0e83lliks5rgdR9gaJpZM4MMfVC.

danodemano commented 7 years ago

@terrycarlin I'm not using the hdmi_cec component so I don't think it's related.

nVINCEble commented 7 years ago

i'm having the same issue and not sure if related, but all my zwave automations take 30sec or so before they respond to off/on commands.

balloob commented 7 years ago

If the timer gets out of sync it means that some component is doing something bad in the event loop. Anyone experiencing this, please list the integrations that you use.

danodemano commented 7 years ago

Hi @balloob, when you say integrations are you talking about the external components? If so see below:

I think that covers it all. :)

EDIT: I should also note, in the event it's related, that the CPU usage of my HASS PI has been significantly higher since the upgrade this morning:

cpu1

cpu2

Also of note it was running my memory usage through the roof and after ~5 hours of running the system was super-sluggish and I was getting these in the logs:

17-02-26 17:10:23 ERROR (MainThread) [homeassistant.components.switch] Error while update entity from wake_on_lan in switch
Traceback (most recent call last):
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/homeassistant/helpers/entity_component.py", line 396, in _update_entity_states
    yield from update_coro
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/homeassistant/helpers/entity.py", line 212, in async_update_ha_state
    yield from self.hass.loop.run_in_executor(None, self.update)
  File "/usr/lib/python3.4/asyncio/futures.py", line 388, in __iter__
    yield self  # This tells Task to wait for completion.
  File "/usr/lib/python3.4/asyncio/tasks.py", line 286, in _wakeup
    value = future.result()
  File "/usr/lib/python3.4/asyncio/futures.py", line 277, in result
    raise self._exception
  File "/usr/lib/python3.4/concurrent/futures/thread.py", line 54, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/homeassistant/components/switch/wake_on_lan.py", line 94, in update
    status = sp.getstatusoutput(ping_cmd)[0]
  File "/usr/lib/python3.4/subprocess.py", line 717, in getstatusoutput
    data = check_output(cmd, shell=True, universal_newlines=True, stderr=STDOUT)
  File "/usr/lib/python3.4/subprocess.py", line 607, in check_output
    with Popen(*popenargs, stdout=PIPE, **kwargs) as process:
  File "/usr/lib/python3.4/subprocess.py", line 859, in __init__
    restore_signals, start_new_session)
  File "/usr/lib/python3.4/subprocess.py", line 1395, in _execute_child
    restore_signals, start_new_session, preexec_fn)
OSError: [Errno 12] Cannot allocate memory

EDIT 2: Looks like perhaps a memory leak

memory

Should I open up another issue for that? EDIT 3: Memory leak reported here: https://github.com/home-assistant/home-assistant/issues/6270

EDIT 4: Memory leak duplicate of: https://github.com/home-assistant/home-assistant/issues/6165 Disabling the "discovery" component SEEMS to have solved the memory/CPU usage. However still getting the out of sync errors in my log.

terrycarlin commented 7 years ago

Having the same problem with lots of Out of Sync messages in log file

Components I use:

zwave switches, outlets Google calendar Shell commands Wunderground Speedtest USPS Systemmonitor Sun Moon Google travel time ISS Generic cameras Device tracker Insteon switches and lights hdmi_cec apple_tv iTunes mad samsungtv nest twitch wadi

On Feb 26, 2017, at 5:48 PM, danodemano notifications@github.com wrote:

Hi @balloob https://github.com/balloob, when you say integrations are you talking about the external components? If so see below:

Hue (both controlling and emulating for Alexa) zwave (switches, outlets, thermostat, energy monitors) Google calendar IFTTT ffmpeg (I don't think I'm actually using this anymore) Shell commands (curl to IR blaster) Wink MyQ (added AFTER these error started but figured I would note it) Wunderground Bitcoin Speedtest Pihole USPS Systemmonitor Sun Moon Google travel time ISS Generic cameras (Ubiquiti using anonymous snapshot URL) Device tracker (ping X4) WOL switches Kodi Onkyo I think that covers it all. :)

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/6253#issuecomment-282603526, or mute the thread https://github.com/notifications/unsubscribe-auth/AA1W1Hl5zOXUQLmfwt88LBuyD3F8pNvLks5rgh1qgaJpZM4MMfVC.

balloob commented 7 years ago

I think that the out of sync timer is caused by the system performing poorly due to high memory usage.

jamieshaw commented 7 years ago

Same issues here but not seeing any memory issues – I'm running HASS with VirtualEnv on a Mac mini but not seeing any issues with memory usage. No major changes since upgrading yesterday morning. Attached screenshot is of past 7 day usage.

screen shot 2017-02-27 at 9 45 59 am

Component list: Philips Hue Nest MySensors WeMo IFTTT Dark Sky Sun Moon Google Calendar Automatic ISS Ping NMAP OwnTracks History Logger Recorder (MySQL) Apple TV Sonos Google Travel Time System Monitor SpeedTest Sonarr Transmission Plex (Media Player & Sensor) Roku Sony Bravia Command Line (Switch & Sensor) Pushover Slack Growl Email Bitcoin Yahoo! Finance Fixer HaveIBeenPwned Generic Alarm File Camera Microsoft Face OpenALPR Local WAQI REST Sensors MQTT API Streams

...I think that's everything.

philhawthorne commented 7 years ago

Also experiencing this.

Components I use

danodemano commented 7 years ago

@balloob - after disabling the "discovery" component as referenced in #6165 I'm no longer seeing the high memory/CPU usage. I am, however, still getting the out of sync errors:

image

image

image

17-02-27 05:49:36 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 05:53:36 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 05:55:36 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:01:36 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:05:36 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:19:37 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:21:36 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:21:38 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:33:36 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:35:36 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:39:36 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:39:39 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:41:37 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:45:38 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:47:37 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:49:38 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:53:37 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:53:39 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:55:36 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:57:36 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 06:59:38 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
yajrendrag commented 7 years ago

similar to above - also because of #6165 with discovery disabled and after upgrading to 0.39.1, i still had 1 timer out of sync error overnight - my log looked like @danodemano's with discovery enabled and on 0.39. memory use seemed stable/normal overnight.

components:

wmn79 commented 7 years ago

I am also seeing these entries in the log after updating to 39.1. I am suspecting Hue to be the cause since I also got errors on a rest sensor and the only rest sensors I have are polling the Hue bridge.

Components:

Log:

17-02-27 21:51:40 WARNING (Thread-5) [homeassistant.components.zwave] zwave not ready after 30 seconds, continuing anyway 
17-02-27 21:51:53 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 
17-02-27 21:51:58 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:02 
17-02-27 21:51:58 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 
17-02-27 21:52:07 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:02 
17-02-27 21:52:07 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-27 21:52:15 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 
17-02-27 21:52:19 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:02 
17-02-27 21:52:20 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-27 21:52:45 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 21:52:47 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:02 
17-02-27 21:57:14 WARNING (MainThread) [homeassistant.components.sensor] Updating rest sensor took longer than the scheduled update interval 0:00:02 
17-02-27 21:57:44 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting 17-02-27 21:57:46 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-02-27 21:58:14 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
plainslice commented 7 years ago

Also experiancing this:

zwave CEC Cover Bluetooth ecobee pocketcasts ifttt notify

jamieshaw commented 7 years ago

I'm also seeing Hue errors – "Update took longer than requested interval 00:00:30"

kirichkov commented 7 years ago

I'm also seeing these errors together with a lot higher CPU usage after start up. When I disable the zwave component the warnings disappear and hass drops its CPU usage to the usual levels 1-2% on RPi2. I'm using the Aeotec USB Z-stick gen5

Components:

I'm also seeing the following traceback:

Traceback (most recent call last):
  File "/home/hass/lib/python3.4/site-packages/homeassistant/helpers/entity_component.py", line 151, in _async_setup_platform
    entity_platform.add_entities, discovery_info
  File "/usr/lib/python3.4/asyncio/futures.py", line 388, in __iter__
    yield self  # This tells Task to wait for completion.
  File "/usr/lib/python3.4/asyncio/tasks.py", line 286, in _wakeup
    value = future.result()
  File "/usr/lib/python3.4/asyncio/futures.py", line 277, in result
    raise self._exception
  File "/usr/lib/python3.4/concurrent/futures/thread.py", line 54, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/home/hass/lib/python3.4/site-packages/homeassistant/components/sensor/zwave.py", line 43, in setup_platform
    add_devices([ZWaveMultilevelSensor(value)])
  File "/home/hass/lib/python3.4/site-packages/homeassistant/components/sensor/zwave.py", line 55, in __init__
    zwave.ZWaveDeviceEntity.__init__(self, value, DOMAIN)
  File "/home/hass/lib/python3.4/site-packages/homeassistant/components/zwave/__init__.py", line 681, in __init__
    self._update_attributes()
  File "/home/hass/lib/python3.4/site-packages/homeassistant/components/zwave/__init__.py", line 703, in _update_attributes
    self.battery_level = self._value.node.get_battery_level()
  File "/home/hass/lib/python3.4/site-packages/openzwave-0.3.1-py3.4.egg/openzwave/command.py", line 284, in get_battery_level
    for val in self.get_battery_levels():
  File "/home/hass/lib/python3.4/site-packages/openzwave-0.3.1-py3.4.egg/openzwave/command.py", line 306, in get_battery_levels
    type='Byte', readonly=True, writeonly=False)
  File "/home/hass/lib/python3.4/site-packages/openzwave-0.3.1-py3.4.egg/openzwave/node.py", line 438, in get_values
    for value in self.values:
RuntimeError: dictionary changed size during iteration

And a warning:

WARNING (Thread-1) [homeassistant.components.zwave] zwave not ready after 30 seconds, continuing anyway

Also shutting down doesn't take place in the span of 3 minutes so I have to shutdown hass manually using Ctrl+C. With zwave disabled it shuts down immediately.

Toonix commented 7 years ago

same with 0.39.1

ViperRNMC commented 7 years ago

Same issue here 0.39.1

kopfsick commented 7 years ago

Same issue. 0.39

danodemano commented 7 years ago

@kirichkov - I think you might be onto something there. I disabled the z-wave component and while my CPU/Memory didn't change (it was already "normal" after disabling discovery the other day) I'm no longer getting those errors in my logs. In fact the log is near perfectly clean except for the warning about the Alexa type for the emulated hue. I'm using the same z-stick but with a Pi 3. Anyone else able to confirm?

jamieshaw commented 7 years ago

I'm seeing the issue despite not using Z-wave.

yajrendrag commented 7 years ago

@danodemano @kirichkov - may be a function of platform too - i am not having any issues with zwave. On startup, however, i alway get the warning about zwave not being read after 30 seconds, which i assume is simply a transient startup issue (& have had this warning for a long time - not just since 0.38.4). but i'm not running on a pi either - i have an 8 core desktop machine.. the combination of 0.39.1 & turning off discovery seemed to be the key for me to most of this (this issue and the memory issues in #6165 ).

Toonix commented 7 years ago

Well HA crashed today first time...then I had a dead node..thx I got it fixed with exclude/include. Then I deleted DB files and sqlite db. I got some bad error about chromcast..but since i don't need it i removed it from the config...but my cpu now pretty high.

top - 18:38:17 up 22 min, 1 user, load average: 1.44, 1.43, 1.13 Tasks: 120 total, 1 running, 119 sleeping, 0 stopped, 0 zombie %Cpu(s): 4.9 us, 1.0 sy, 0.0 ni, 74.9 id, 19.2 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem: 947732 total, 268968 used, 678764 free, 51764 buffers KiB Swap: 102396 total, 0 used, 102396 free. 127104 cached Mem

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 957 hass 20 0 229852 57704 11484 S 21.2 6.1 5:34.00 hass 83 root 20 0 0 0 0 S 1.3 0.0 0:15.67 mmcqd/0 85 root 20 0 0 0 0 S 0.7 0.0 0:06.00 jbd2/mmcbl+ 7 root 20 0 0 0 0 S 0.3 0.0 0:02.34 rcu_sched 913 root 20 0 0 0 0 S 0.3 0.0 0:03.25 kworker/0:0 1131 root 20 0 0 0 0 S 0.3 0.0 0:00.23 kworker/3:0

and this is not startup. It's running since 22 Minutes now.

xlibbyx commented 7 years ago

I also have the error message, and every now again it's taking a long time for HA to load or for Alexa to perform a command.

pascalmtts commented 7 years ago

Also have this issues since 0.39. Plattforms: zwave Cec Apple TV Fritzbox Webos

jmvermeulen commented 7 years ago

Same here since 0.39.1 (skipped 0.39.0). Using Hue, Xiaomi and ChromeCast.

bieniu commented 7 years ago

Same here since 0.39. Components: Z-Wave, Xiaomi, AsusWrt, nmap, mqtt, OwnTracks, DenonAVR, Chromecast, Speedtest, SystemMonitor.

cdybdahl commented 7 years ago

Same issue, on .39.1, accompanied by hass crashing regularly. Lots of 17-03-01 07:44:38 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting

as well as various components with message like 17-03-01 07:46:53 WARNING (MainThread) [homeassistant.components.light] Updating hue light took longer than the scheduled update interval 0:00:30

Using sun, hue, zwave, plex, ecobee, emulated hue, updater, config, discovery, frontend, conversation, history, logbook, device tracker, tts, ffmpeg, light, ifttt.

craigjmidwinter commented 7 years ago

I'm seeing this and crashing on dev branch Using sun, hue, mqtt, kodi, insteonlocal, emulated hue, updater, config, discovery, frontend, conversation, tts, camera, device tracker

jamieshaw commented 7 years ago

I take back my previous thoughts on memory and it being without issue. I've noticed that restarting my Mac server doesn't yield any "Out of sync" errors initially.

After my most recent HASS restart, I was greeting with the following as one of the first lines in the log:

Traceback (most recent call last):
  File "/usr/local/opt/hass/lib/python3.5/site-packages/homeassistant/components/device_tracker/__init__.py", line 172, in async_setup_platform
    disc_info)
  File "/usr/local/Cellar/python3/3.5.2_3/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/futures.py", line 361, in __iter__
    yield self  # This tells Task to wait for completion.
  File "/usr/local/Cellar/python3/3.5.2_3/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/tasks.py", line 296, in _wakeup
    future.result()
  File "/usr/local/Cellar/python3/3.5.2_3/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/futures.py", line 274, in result
    raise self._exception
  File "/usr/local/Cellar/python3/3.5.2_3/Frameworks/Python.framework/Versions/3.5/lib/python3.5/concurrent/futures/thread.py", line 55, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/opt/hass/lib/python3.5/site-packages/homeassistant/components/device_tracker/owntracks.py", line 314, in setup_scanner
    mqtt.subscribe(hass, EVENT_TOPIC, owntracks_event_update, 1)
  File "/usr/local/opt/hass/lib/python3.5/site-packages/homeassistant/components/mqtt/__init__.py", line 217, in subscribe
    hass.loop
  File "/usr/local/Cellar/python3/3.5.2_3/Frameworks/Python.framework/Versions/3.5/lib/python3.5/concurrent/futures/_base.py", line 405, in result
    return self.__get_result()
  File "/usr/local/Cellar/python3/3.5.2_3/Frameworks/Python.framework/Versions/3.5/lib/python3.5/concurrent/futures/_base.py", line 357, in __get_result
    raise self._exception
  File "/usr/local/Cellar/python3/3.5.2_3/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/tasks.py", line 239, in _step
    result = coro.send(None)
  File "/usr/local/opt/hass/lib/python3.5/site-packages/homeassistant/components/mqtt/__init__.py", line 209, in async_subscribe
    yield from hass.data[DATA_MQTT].async_subscribe(topic, qos)
  File "/usr/local/opt/hass/lib/python3.5/site-packages/homeassistant/components/mqtt/__init__.py", line 492, in async_subscribe
    _raise_on_error(result)
  File "/usr/local/opt/hass/lib/python3.5/site-packages/homeassistant/components/mqtt/__init__.py", line 611, in _raise_on_error
    'Error talking to MQTT: {}'.format(mqtt.error_string(result)))
homeassistant.exceptions.HomeAssistantError: Error talking to MQTT: Out of memory.
EleanorRagone commented 7 years ago

Similar to others, I'm getting errors that I can't seem to pinpoint. Mine seem to stem from openzwave:

17-03-01 12:14:55 ERROR (Dummy-20) [openzwave] Error in manager callback
Traceback (most recent call last):
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/openzwave-0.3.2-py3.4.egg/openzwave/network.py", line 950, in zwcallback
    self._handle_value_changed(args)
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/openzwave-0.3.2-py3.4.egg/openzwave/network.py", line 1502, in _handle_value_changed
    'value' : self.nodes[args['nodeId']].values[args['valueId']['id']]})
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/PyDispatcher-2.0.5-py3.4.egg/pydispatch/dispatcher.py", line 338, in send
    **named
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/PyDispatcher-2.0.5-py3.4.egg/pydispatch/robustapply.py", line 55, in robustApply
    return receiver(*arguments, **named)
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/homeassistant/components/zwave/__init__.py", line 691, in network_value_changed
    self.value_changed(value)
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/homeassistant/components/zwave/__init__.py", line 697, in value_changed
    self.schedule_update_ha_state()
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/homeassistant/helpers/entity.py", line 288, in schedule_update_ha_state
    self.hass.add_job(self.async_update_ha_state(force_refresh))
AttributeError: 'NoneType' object has no attribute 'add_job'
17-03-01 12:14:55 ERROR (Dummy-20) [openzwave] Error in manager callback
Traceback (most recent call last):
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/openzwave-0.3.2-py3.4.egg/openzwave/network.py", line 950, in zwcallback
    self._handle_value_changed(args)
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/openzwave-0.3.2-py3.4.egg/openzwave/network.py", line 1502, in _handle_value_changed
    'value' : self.nodes[args['nodeId']].values[args['valueId']['id']]})
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/PyDispatcher-2.0.5-py3.4.egg/pydispatch/dispatcher.py", line 338, in send
    **named
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/PyDispatcher-2.0.5-py3.4.egg/pydispatch/robustapply.py", line 55, in robustApply
    return receiver(*arguments, **named)
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/homeassistant/components/zwave/__init__.py", line 691, in network_value_changed
    self.value_changed(value)
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/homeassistant/components/zwave/__init__.py", line 697, in value_changed
    self.schedule_update_ha_state()
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/homeassistant/helpers/entity.py", line 288, in schedule_update_ha_state
    self.hass.add_job(self.async_update_ha_state(force_refresh))
AttributeError: 'NoneType' object has no attribute 'add_job'
17-03-01 12:14:58 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-01 12:15:04 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-01 12:15:19 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
pascalmtts commented 7 years ago

I downgraded to 0.38.4. No problems anymore. I will wait for next release which is hopefully fixing the most stuff.

bieniu commented 7 years ago

I installed netdisco 0.9.1 and my "Timer got out of sync" errors were gone and CPU/memory usage returned to normal.

sudo su -s /bin/bash homeassistant
pip install netdisco==0.9.1 --upgrade --target ~/.homeassistant/deps
danodemano commented 7 years ago

@bieniu - that didn't resolve it for me. Upgraded both using your command and in the virtual enviroment but still getting the same errors:

17-03-01 14:02:51 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-01 14:02:58 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-01 14:03:02 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-01 14:03:05 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-01 14:04:00 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
pascalmtts commented 7 years ago

After updating to 0.39.2 the "Timer got out of sync" is gone. Still having Z-Wave errors. Edit: Timer got out of sync is not gone. Spotted some in the Logs... Downgraded to 0.38.4 again.

EleanorRagone commented 7 years ago

@pascalmattes Are you still getting the z-wave errors with 0.38.4? Or, I guess, were you ever getting errors like mine? https://github.com/home-assistant/home-assistant/issues/6253#issuecomment-283406119

pascalmtts commented 7 years ago

@pcragone No, with 0.38.4 there are no z-Wave errors. Starting with 0.39 i get errors.

EleanorRagone commented 7 years ago

@pascalmattes Hmmm Ok. Still trying to figure out what's giving me those errors.

Toonix commented 7 years ago

After deleting every database and log and even chromcast the message disapeared. But it still feels sluggly..and my cpu is all the time about 8-10%. Switching over the gui is still slow.

Update now to 0.39.2 let's see if cpu is going down now.

This are all Error I got after deleting Chromcast and deleting DB Files and Log.

17-03-01 18:56:57 ERROR (MainThread) [aiohttp.server] Error handling request
Traceback (most recent call last):
  File "/home/hass/.homeassistant/deps/aiohttp/web_server.py", line 62, in handle_request
    resp = yield from self._handler(request)
  File "/home/hass/.homeassistant/deps/aiohttp/web.py", line 270, in _handle
    resp = yield from handler(request)
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/homeassistant/components/http/ban.py", line 57, in ban_middleware_handler
    return (yield from handler(request))
  File "/usr/lib/python3.4/asyncio/coroutines.py", line 143, in coro
    res = yield from res
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/homeassistant/components/http/__init__.py", line 417, in handle
    result = yield from result
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/homeassistant/components/api.py", line 413, in get
    request, request.app['hass'].config.path(ERROR_LOG_FILENAME))
  File "/srv/hass/hass_venv/lib/python3.4/site-packages/homeassistant/components/http/__init__.py", line 368, in file
    response = yield from FILE_SENDER.send(request, Path(fil))
  File "/home/hass/.homeassistant/deps/aiohttp/file_sender.py", line 155, in send
    st = filepath.stat()
  File "/usr/lib/python3.4/pathlib.py", line 1048, in stat
    return self._accessor.stat(self)
  File "/usr/lib/python3.4/pathlib.py", line 323, in wrapped
    return strfunc(str(pathobj), *args)
FileNotFoundError: [Errno 2] No such file or directory: '/home/hass/.homeassistant/home-assistant.log'
balloob commented 7 years ago

High ram and CPU usage was caused by the discovery component, this has been resolved in 0.39.2. Z-Wave issue is not related to this issue so I am closing this.

danodemano commented 7 years ago

@balloob 0.39.2 doesn't resolve the "out of sync" errors. Already have another 6 just from the last minute:

17-03-02 08:15:09 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-02 08:15:12 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-02 08:15:17 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-02 08:15:22 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-02 08:15:30 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-02 08:15:37 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting

FWIW I still have discovery commented out after the high resource usage. So these errors are not related to that.

heathpitts commented 7 years ago

I still have them as well but not as many. Also having a new error. Not using discovery component 

17-03-01 23:25:16 ERROR (MainThread) [aiohttp.server] Error handling request
Traceback (most recent call last):
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/aiohttp/web_server.py", line 62, in handle_request
resp = yield from self._handler(request)
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/aiohttp/web.py", line 270, in _handle
resp = yield from handler(request)
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/homeassistant/components/http/ban.py", line 57, in ban_middleware_handler
return (yield from handler(request))
  File "/usr/lib/python3.4/asyncio/coroutines.py", line 143, in coro
res = yield from res
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/homeassistant/components/http/__init__.py", line 417, in handle
result = yield from result
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/homeassistant/components/config/__init__.py", line 110, in post
yield from hass.loop.run_in_executor(None, _write, path, current)
  File "/usr/lib/python3.4/asyncio/futures.py", line 388, in __iter__
yield self  # This tells Task to wait for completion.
  File "/usr/lib/python3.4/asyncio/tasks.py", line 286, in _wakeup
value = future.result()
  File "/usr/lib/python3.4/asyncio/futures.py", line 277, in result
raise self._exception
  File "/usr/lib/python3.4/concurrent/futures/thread.py", line 54, in run
result = self.fn(*self.args, **self.kwargs)
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/homeassistant/components/config/__init__.py", line 134, in _write
data = dump(data)
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/homeassistant/util/yaml.py", line 75, in dump
.replace(': null\n', ':\n')
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/yaml/__init__.py", line 216, in safe_dump
return dump_all([data], stream, Dumper=SafeDumper, **kwds)
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/yaml/__init__.py", line 188, in dump_all
dumper.represent(data)
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/yaml/representer.py", line 26, in represent
node = self.represent_data(data)
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/yaml/representer.py", line 47, in represent_data
node = self.yaml_representers[data_types[0]](self, data)
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/homeassistant/util/yaml.py", line 308, in <lambda>
represent_odict(dumper, u'tag:yaml.org,2002:map', value))
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/homeassistant/util/yaml.py", line 290, in represent_odict
node_value = dump.represent_data(item_value)
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/yaml/representer.py", line 47, in represent_data
node = self.yaml_representers[data_types[0]](self, data)
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/homeassistant/util/yaml.py", line 308, in <lambda>
represent_odict(dumper, u'tag:yaml.org,2002:map', value))
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/homeassistant/util/yaml.py", line 290, in represent_odict
node_value = dump.represent_data(item_value)
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/yaml/representer.py", line 57, in represent_data
node = self.yaml_representers[None](self, data)
  File "/srv/homeassistant/homeassistant_venv/lib/python3.4/site-packages/yaml/representer.py", line 229, in represent_undefined
raise RepresenterError("cannot represent an object: %s" % data)
yaml.representer.RepresenterError: cannot represent an object: ['group.downstairs_lights', 'climate.downstairs', 'group.downstairs_sensors', 'group.downstairs_devices']
17-03-01 23:27:32 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-01 23:31:13 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-01 23:31:30 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-02 05:32:57 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
jamieshaw commented 7 years ago

Still having issues over here too:

17-03-02 13:30:02 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-02 13:30:36 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal read error on socket transport
pvizeli commented 7 years ago

"Timer got out of sync. Resetting" mean that a component/platform make bad stuff and lock the eventloop. Try to disable one component by other and lock which component/platform will be the bad thing.

pascalmtts commented 7 years ago

Will try later with a clean install.

danodemano commented 7 years ago

@pvizeli - I know others mentioned not using z-wave and still seeing these but in my case it appears to be z-wave related. After commenting out the z-wave block it runs without error for 30+ minutes. As soon as I turn it back on I get errors <5 minutes after the service restarts. Here's my z-wave config block as a reference:

zwave:
  usb_path: /dev/ttyACM0
  polling_interval: 10000
  device_config_domain:
    light:
      polling_intensity: 1
      refresh_value: 2
      delay: 3
  device_config:
    climate.main_thermostat_heating_1_31_1:
      polling_intensity: 1
      refresh_value: 2
      delay: 3
    sensor.ac_energy_23_0:
      polling_intensity: 1
      refresh_value: 2
      delay: 3
    sensor.dryer_energy_24_0:
      polling_intensity: 1
      refresh_value: 2
      delay: 3
    sensor.furnace1_energy_25_0:
      polling_intensity: 1
      refresh_value: 2
      delay: 3
    sensor.furnace2_energy_26_0:
      polling_intensity: 1
      refresh_value: 2
      delay: 3
arsaboo commented 7 years ago

I am on 0.39.2 and also seeing the occasional timer sync errors:

17-03-01 22:34:48 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-02 11:28:22 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
Molodax commented 7 years ago

Same here on 0.39.2. Not so much components: ffmpeg camera/binary sensors, osram lights, yeelight, broadlink, vasttrafik, miflora, yr, dark sky, Samsung, template sensors, Kodi, tts, speedtest. No z-wave.

kirichkov commented 7 years ago

I'm still having these errors in the log even with 0.39.2, I also can't get hass to shutdown cleanly - I have to either kill it or interrupt it with Ctrl+C. If discovery is disabled none of those manifest.

It appears even with discovery disabled those issues are still present.

17-03-02 21:33:37 ERROR (MainThread) [homeassistant.components.sensor] Error while setting up platform zwave
Traceback (most recent call last):
  File "/home/hass/lib/python3.4/site-packages/homeassistant/helpers/entity_component.py", line 151, in _async_setup_platform
    entity_platform.add_entities, discovery_info
  File "/usr/lib/python3.4/asyncio/futures.py", line 388, in __iter__
    yield self  # This tells Task to wait for completion.
  File "/usr/lib/python3.4/asyncio/tasks.py", line 286, in _wakeup
    value = future.result()
  File "/usr/lib/python3.4/asyncio/futures.py", line 277, in result
    raise self._exception
  File "/usr/lib/python3.4/concurrent/futures/thread.py", line 54, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/home/hass/lib/python3.4/site-packages/homeassistant/components/sensor/zwave.py", line 43, in setup_platform
    add_devices([ZWaveMultilevelSensor(value)])
  File "/home/hass/lib/python3.4/site-packages/homeassistant/components/sensor/zwave.py", line 55, in __init__
    zwave.ZWaveDeviceEntity.__init__(self, value, DOMAIN)
  File "/home/hass/lib/python3.4/site-packages/homeassistant/components/zwave/__init__.py", line 681, in __init__
    self._update_attributes()
  File "/home/hass/lib/python3.4/site-packages/homeassistant/components/zwave/__init__.py", line 705, in _update_attributes
    if self._value.node.can_wake_up():
  File "/home/hass/lib/python3.4/site-packages/openzwave-0.3.1-py3.4.egg/openzwave/command.py", line 354, in can_wake_up
    res = self.get_values(class_id=0x84)
  File "/home/hass/lib/python3.4/site-packages/openzwave-0.3.1-py3.4.egg/openzwave/node.py", line 438, in get_values
    for value in self.values:
RuntimeError: dictionary changed size during iteration
17-03-02 21:34:00 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-02 21:34:06 WARNING (Thread-10) [homeassistant.components.zwave] zwave not ready after 30 seconds, continuing anyway
17-03-02 21:34:28 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-02 21:34:59 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-02 21:35:01 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting

When attempting to shut down from /dev-service

17-03-02 21:41:00 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-02 21:41:54 WARNING (MainThread) [aiohttp.websocket] websocket connection is closing.

^C^CTraceback (most recent call last):
  File "/home/hass/lib/python3.4/site-packages/homeassistant/core.py", line 148, in start
    self.loop.run_forever()
  File "/usr/lib/python3.4/asyncio/base_events.py", line 244, in run_forever
    self._run_once()
  File "/usr/lib/python3.4/asyncio/base_events.py", line 1049, in _run_once
    event_list = self._selector.select(timeout)
  File "/usr/lib/python3.4/selectors.py", line 424, in select
    fd_event_list = self._epoll.poll(timeout, max_ev)
KeyboardInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/hass/bin/hass", line 11, in <module>
    sys.exit(main())
  File "/home/hass/lib/python3.4/site-packages/homeassistant/__main__.py", line 381, in main
    exit_code = setup_and_run_hass(config_dir, args)
  File "/home/hass/lib/python3.4/site-packages/homeassistant/__main__.py", line 311, in setup_and_run_hass
    hass.start()
  File "/home/hass/lib/python3.4/site-packages/homeassistant/core.py", line 151, in start
    self.loop.run_forever()
  File "/usr/lib/python3.4/asyncio/base_events.py", line 244, in run_forever
    self._run_once()
  File "/usr/lib/python3.4/asyncio/base_events.py", line 1081, in _run_once
    handle._run()
  File "/usr/lib/python3.4/asyncio/events.py", line 120, in _run
    self._callback(*self._args)
  File "/usr/lib/python3.4/asyncio/tasks.py", line 291, in _wakeup
    self._step(value, None)
  File "/usr/lib/python3.4/asyncio/tasks.py", line 237, in _step
    result = next(coro)
  File "/home/hass/lib/python3.4/site-packages/homeassistant/core.py", line 290, in async_stop
    self.executor.shutdown()
  File "/usr/lib/python3.4/concurrent/futures/thread.py", line 131, in shutdown
    t.join()
  File "/usr/lib/python3.4/threading.py", line 1060, in join
    self._wait_for_tstate_lock()
  File "/usr/lib/python3.4/threading.py", line 1076, in _wait_for_tstate_lock
    elif lock.acquire(block, timeout):
KeyboardInterrupt
^CError in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "/usr/lib/python3.4/concurrent/futures/thread.py", line 38, in _python_exit
    t.join()
  File "/usr/lib/python3.4/threading.py", line 1060, in join
    self._wait_for_tstate_lock()
  File "/usr/lib/python3.4/threading.py", line 1076, in _wait_for_tstate_lock
    elif lock.acquire(block, timeout):
KeyboardInterrupt
--- Logging error ---
Traceback (most recent call last):
--- Logging error ---
Traceback (most recent call last):
--- Logging error ---
Traceback (most recent call last):
Exception ignored in: <bound method Task.__del__ of <Task finished coro=<async_stop() done, defined at /home/hass/lib/python3.4/site-packages/homeassistant/core.py:274> exception=KeyboardInterrupt()>>
Traceback (most recent call last):
  File "/usr/lib/python3.4/asyncio/futures.py", line 218, in __del__
  File "/usr/lib/python3.4/asyncio/base_events.py", line 969, in call_exception_handler
  File "/usr/lib/python3.4/logging/__init__.py", line 1303, in error
  File "/usr/lib/python3.4/logging/__init__.py", line 1409, in _log
  File "/usr/lib/python3.4/logging/__init__.py", line 1419, in handle
  File "/usr/lib/python3.4/logging/__init__.py", line 1481, in callHandlers
  File "/usr/lib/python3.4/logging/__init__.py", line 853, in handle
  File "/usr/lib/python3.4/logging/__init__.py", line 984, in emit
  File "/usr/lib/python3.4/logging/__init__.py", line 906, in handleError
  File "/usr/lib/python3.4/traceback.py", line 169, in print_exception
  File "/usr/lib/python3.4/traceback.py", line 153, in _format_exception_iter
  File "/usr/lib/python3.4/traceback.py", line 18, in _format_list_iter
  File "/usr/lib/python3.4/traceback.py", line 65, in _extract_tb_or_stack_iter
  File "/home/hass/lib/python3.4/linecache.py", line 15, in getline
  File "/home/hass/lib/python3.4/linecache.py", line 41, in getlines
  File "/home/hass/lib/python3.4/linecache.py", line 126, in updatecache
  File "/home/hass/lib/python3.4/tokenize.py", line 437, in open
AttributeError: 'module' object has no attribute 'open'
bieniu commented 7 years ago

In my system issue appears (not always) when automation with trigger time starts, for example:

- alias: "Lights Disco Mode Begin"
  trigger: 
    platform: time
    seconds: '/5'
  condition: 
    condition: state
    entity_id: input_boolean.disco_mode
    state: 'on'
  action:
    service: light.turn_on
    entity_id: light.gateway_light_f0b429cc6f0b
    data_template:
      brightness: 60
      rgb_color: ['{{ (range(0, 255)|random) }}','{{ (range(0, 255)|random) }}','{{ (range(0, 255)|random) }}']

and in log:

17-03-02 20:36:40 INFO (MainThread) [homeassistant.components.automation] Executing Lights Disco Mode Begin
17-03-02 20:36:43 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
17-03-02 20:36:45 INFO (MainThread) [homeassistant.components.automation] Executing Lights Disco Mode Begin
yajrendrag commented 7 years ago

i didn't think my issue was related to zwave, but perhaps it is - i only have 1 of these timer got out of sync errors in my log - and i believe it was same yesterday (had to reboot for other reason), but it was immediately after doing a zwave soft reset...