I use hass.io on a RPi 3 and i really love it (thanks for all your work!).
I use AppDaemon for automations, escpecially for my lights (knx). But since Sunday evening, I saw AppDaemon is restarting every hour (to be correct: every 60-62 minutes). I searched for the reason many hours now, but I can’t solve it - so please help me.
I did not change anything that evening.
I tried to combine all relevant log info in a chronological order. These log entries occur approximately every hour.
[hassio] = system log from hass.io
[ha] = home assistant log from home-assistant.log
[ad] = AppDaemon log (logfile.log)
[hassio] 19-10-22 10:33:47 INFO (MainThread) [hassio.homeassistant] Updated Home Assistant API token
[ha] 2019-10-22 10:55:04 INFO (MainThread) [homeassistant.components.updater] Submitted analytics to Home Assistant servers. Information submitted includes {'version': '0.100.2', 'dev': False, 'hassio': True, 'virtualenv': False, 'python_version': '3.7.4', 'docker': True, 'arch': 'armv7l', 'timezone': 'Europe/Berlin', 'os_name': 'Linux', 'distribution': 'alpine', 'os_version': '3.10.2', 'huuid': 'acb123'}
[ha] 2019-10-22 10:55:04 INFO (MainThread) [homeassistant.components.updater] The latest available version of Home Assistant is 0.100.3
[ha] 2019-10-22 10:56:32 INFO (SyncWorker_2) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 10:56:32 INFO (SyncWorker_2) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/acb123%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&q=Papiertonne&timeMin=2019-10-22T10%3A56%3A32.175738%2B02%3A00&alt=json
[ha] 2019-10-22 10:56:32 INFO (SyncWorker_2) [oauth2client.transport] Refreshing due to a 401 (attempt 1/2)
[ha] 2019-10-22 10:56:32 INFO (SyncWorker_2) [oauth2client.client] Refreshing access_token
[ha] 2019-10-22 10:56:32 INFO (SyncWorker_11) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 10:56:32 INFO (SyncWorker_11) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/de.german%23holiday%40group.v.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T10%3A56%3A32.720343%2B02%3A00&alt=json
(some more google calendar requests)
[ha] 2019-10-22 10:56:37 INFO (SyncWorker_3) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/xyz123%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T10%3A56%3A37.632440%2B02%3A00&alt=json
[hassio] 19-10-22 10:57:11 INFO (MainThread) [hassio.api.proxy] Home Assistant WebSocket API connection is closed
[AD] 2019-10-22 10:57:31.042399 WARNING AppDaemon: HASS: Disconnected from Home Assistant, retrying in 5 seconds
[AD] 2019-10-22 10:57:36.071011 INFO AppDaemon: HASS: Connected to Home Assistant 0.100.2
[AD] 2019-10-22 10:57:36.290296 INFO AppDaemon: Processing restart for HASS
[hassio] 19-10-22 10:57:36 INFO (MainThread) [hassio.api.proxy] Home Assistant WebSocket API request initialize
[hassio] 19-10-22 10:57:36 INFO (MainThread) [hassio.api.proxy] WebSocket access from a0d7b954_appdaemon3
[hassio] 19-10-22 10:57:36 INFO (MainThread) [hassio.api.proxy] Home Assistant WebSocket API request running
[ha] 2019-10-22 10:57:45 INFO (SyncWorker_0) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 10:57:45 INFO (MainThread) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/acb456%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T08%3A57%3A45%2B00%3A00&timeMax=2019-11-22T08%3A57%3A45%2B00%3A00&alt=json
I think it’s related to somethin with tokens, but I don’t know how.
Thank you for your help
Little update: I updated to latest available Home Assistant, 100.3 - problem is the same.
I paste the log of the latest restart/disconnect, again in chonological order:
[hassio] 19-10-22 13:08:34 INFO (MainThread) [hassio.host.network] Update local network DNS information
[hassio] 19-10-22 13:08:34 INFO (MainThread) [hassio.utils.gdbus] Call org.freedesktop.DBus.Properties.GetAll on /org/freedesktop/NetworkManager/DnsManager
[ha] 2019-10-22 13:15:10 INFO (SyncWorker_1) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:15:10 INFO (MainThread) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/p123%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T11%3A15%3A10%2B00%3A00&timeMax=2019-10-22T11%3A29%3A10%2B00%3A00&alt=json
[ha] 2019-10-22 13:15:27 INFO (MainThread) [homeassistant.components.updater] Submitted analytics to Home Assistant servers. Information submitted includes {'version': '0.100.3', 'dev': False, 'hassio': True, 'virtualenv': False, 'python_version': '3.7.4', 'docker': True, 'arch': 'armv7l', 'timezone': 'Europe/Berlin', 'os_name': 'Linux', 'distribution': 'alpine', 'os_version': '3.10.2', 'huuid': '2123'}
[ha] 2019-10-22 13:15:27 INFO (MainThread) [homeassistant.components.updater] You are on the latest version (0.100.3) of Home Assistant
[hassio] 19-10-22 13:21:05 INFO (MainThread) [hassio.api.proxy] Home Assistant WebSocket API connection is closed
[ha] 2019-10-22 13:21:23 INFO (SyncWorker_17) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:21:23 INFO (SyncWorker_17) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/s123%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T13%3A21%3A23.180175%2B02%3A00&alt=json
[ha] 2019-10-22 13:21:23 INFO (SyncWorker_7) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:21:23 INFO (SyncWorker_7) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/j123%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&q=Restmuelltonne&timeMin=2019-10-22T13%3A21%3A23.503582%2B02%3A00&alt=json
[ha] 2019-10-22 13:21:23 INFO (SyncWorker_1) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:21:23 INFO (SyncWorker_1) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/r123%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T13%3A21%3A23.855761%2B02%3A00&alt=json
[ha] 2019-10-22 13:21:24 INFO (SyncWorker_10) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:21:24 INFO (SyncWorker_10) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/j123%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&q=Papiertonne&timeMin=2019-10-22T13%3A21%3A24.257773%2B02%3A00&alt=json
[ha] 2019-10-22 13:21:24 INFO (SyncWorker_8) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:21:24 INFO (SyncWorker_8) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/e123%40import.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T13%3A21%3A24.561767%2B02%3A00&alt=json
[ha] 2019-10-22 13:21:24 INFO (SyncWorker_2) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:21:24 INFO (SyncWorker_2) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/p123g%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T13%3A21%3A24.879774%2B02%3A00&alt=json
[ha] 2019-10-22 13:21:25 INFO (SyncWorker_15) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:21:25 INFO (SyncWorker_15) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/j123%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&q=Biotonne&timeMin=2019-10-22T13%3A21%3A25.265459%2B02%3A00&alt=json
[ha] 2019-10-22 13:21:25 INFO (SyncWorker_13) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:21:25 INFO (SyncWorker_13) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/h123%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T13%3A21%3A25.601305%2B02%3A00&alt=json
[ha] 2019-10-22 13:21:25 INFO (SyncWorker_5) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:21:25 INFO (SyncWorker_5) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/j123%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&q=RaWeg&timeMin=2019-10-22T13%3A21%3A25.897115%2B02%3A00&alt=json
[ha] 2019-10-22 13:21:26 INFO (SyncWorker_0) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:21:26 INFO (SyncWorker_0) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/abc.123%40gmail.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T13%3A21%3A26.209282%2B02%3A00&alt=json
[ha] 2019-10-22 13:21:26 INFO (SyncWorker_3) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:21:26 INFO (SyncWorker_3) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/de.german%23holiday%40group.v.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T13%3A21%3A26.535528%2B02%3A00&alt=json
[ha] 2019-10-22 13:21:26 INFO (SyncWorker_12) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:21:26 INFO (SyncWorker_12) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/l123%40import.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T13%3A21%3A26.818953%2B02%3A00&alt=json
[AD] 2019-10-22 13:21:26.846602 INFO counter_to_power_meter_waermepumpe: <class 'str'>
[AD] 2019-10-22 13:21:26.850358 INFO counter_to_power_meter_waermepumpe: Value 0 received from counter sensor.stromzahler_warmepumpe_rohdaten
[AD] 2019-10-22 13:21:27.322805 INFO counter_to_power_meter_waermepumpe: Looks like it is the first event since a restart. Power will be available next time
[ha] 2019-10-22 13:21:27 INFO (SyncWorker_12) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:21:27 INFO (SyncWorker_12) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/j123%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T13%3A21%3A27.219847%2B02%3A00&alt=json
[AD] 2019-10-22 13:21:45.883537 WARNING AppDaemon: HASS: Disconnected from Home Assistant, retrying in 5 seconds
[AD] 2019-10-22 13:21:49.089797 WARNING AppDaemon: Attempt to call Home Assistant while disconnected: <function Hass.call_service at 0x744acd20>
[hassio] 19-10-22 13:21:50 INFO (MainThread) [hassio.api.proxy] Home Assistant WebSocket API request initialize
[hassio] 19-10-22 13:21:50 INFO (MainThread) [hassio.api.proxy] WebSocket access from a0d7b954_appdaemon3
[hassio] 19-10-22 13:21:50 INFO (MainThread) [hassio.api.proxy] Home Assistant WebSocket API request running
[AD] 2019-10-22 13:21:50.913257 INFO AppDaemon: HASS: Connected to Home Assistant 0.100.3
[AD] 2019-10-22 13:21:51.129646 INFO AppDaemon: Processing restart for HASS
[ha] 2019-10-22 13:22:00 INFO (SyncWorker_19) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:22:00 INFO (MainThread) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/r123%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T11%3A22%3A00%2B00%3A00&timeMax=2019-11-22T11%3A22%3A00%2B00%3A00&alt=json
[ha] 2019-10-22 13:22:04 INFO (SyncWorker_16) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:22:04 INFO (MainThread) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/r123%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T11%3A22%3A04%2B00%3A00&timeMax=2019-11-22T11%3A22%3A04%2B00%3A00&alt=json
[ha] 2019-10-22 13:22:24 INFO (SyncWorker_15) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/calendar/v3/rest
[ha] 2019-10-22 13:22:24 INFO (SyncWorker_15) [googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/calendar/v3/calendars/s123g%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2019-10-22T13%3A22%3A24.258163%2B02%3A00&alt=json
[hassio] 19-10-22 13:28:33 INFO (MainThread) [hassio.updater] Fetch update data from https://version.home-assistant.io/stable.json
The lines with “counter_to_power_meter_waermepumpe” (which occur just before AD is disconnected) show, that HA read values from knx, the knx device did not send that value 0. I think that HA reads knx values only during start-up, but I’m not sure about that. Did HA restart just before that disconnect happened?
I enabled debug for xknx and checked the time before a disconnect happens. I see a lot of knx traffic, but no error.
Anyway, I will set sync_state to False for all my knx sensors and see what happens.
Thank you
please note that with sync_state = False your sensors won’t be read on HA restart as well. (Sensors will have undefined state until a Telegram on their GA is received.)
Sounds good, thank you
I set all my sensors to sync_state: False and I get AppDaemon Disconnects every 2 hours now. So 2 and 4 hours after HA restart. Not sure yet if the 2 hours interval will be permanent, as there were only 2 2-hour intervals up to now
No, it’s not permanent. Now it restartet after 1 hour.
Maybe it’s not a knx topic, but more related to CPU Load? I see peaks every hour:
I think that’s because knx still does some sync (e.g. lights, heating…) every hour and google calendar also checks updates at that time (it checks every 15 minutes, so also after 60 minutes). Maybe that leads somehow to a closing of WebSocket API?
Can I somehow debug that?
