Error doing job: Task was destroyed but it is pending! 0.66.0.b2

ebudalen commented 6 years ago

Home Assistant release with the issue:

0.66.0.b2

Last working Home Assistant release (if known): 0.65.6

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

HassIO

Component/platform:

homeassistant.core (SyncWorker)

Description of problem:

Got this error after upgrading to 0.66.0.b2 from 0.65.6:

ERROR (SyncWorker_0) [homeassistant.core] Error doing job: Task was destroyed but it is pending!

Additional information:

Also started using the beta channel, and upgraded Host System from 1.1 to 1.3 at the same time.

Is there anyway of debugging this problem?

bachya commented 6 years ago

Turn your log level to DEBUG and share what else it says.

ebudalen commented 6 years ago


2018-03-28 14:43:56 DEBUG (SyncWorker_5) [homeassistant.util.json] JSON file not found: /usr/lib/python3.6/site-packages/homeassistant/components/sensor/.translations/pi_hole.no.json
2018-03-28 14:43:56 DEBUG (Dummy-7) [libopenzwave] notif_callback : call callback context
2018-03-28 14:43:56 DEBUG (SyncWorker_5) [homeassistant.util.json] JSON file not found: /usr/lib/python3.6/site-packages/homeassistant/components/switch/.translations/command_line.no.json
2018-03-28 14:43:56 ERROR (SyncWorker_17) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-03-28 14:43:56 DEBUG (Dummy-7) [openzwave] zwcallback args=[{'notificationType': 'ValueAdded', 'homeId': 3987672467, 'nodeId': 2, 'valueId': {'homeId': 3987672467, 'nodeId': 2, 'commandClass': 'COMMAND_CLASS_ZWAVE_PLUS_INFO', 'instance': 1, 'index': 0, 'id': 72057594085605377, 'genre': 'System', 'type': 'Byte', 'value': 1, 'label': 'ZWave+ Version', 'units': '', 'readOnly': True}}]
2018-03-28 14:43:56 DEBUG (SyncWorker_5) [homeassistant.util.json] JSON file not found: /usr/lib/python3.6/site-packages/homeassistant/components/.translations/websocket_api.no.json
2018-03-28 14:43:56 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.zwave
2018-03-28 14:43:56 DEBUG (SyncWorker_1) [homeassistant.components.recorder.util] converting 269 rows to native objects took 0.592159s
2018-03-28 14:43:56 DEBUG (Dummy-7) [openzwave] Z-Wave Notification ValueAdded : {'notificationType': 'ValueAdded', 'homeId': 3987672467, 'nodeId': 2, 'valueId': {'homeId': 3987672467, 'nodeId': 2, 'commandClass': 'COMMAND_CLASS_ZWAVE_PLUS_INFO', 'instance': 1, 'index': 0, 'id': 72057594085605377, 'genre': 'System', 'type': 'Byte', 'value': 1, 'label': 'ZWave+ Version', 'units': '', 'readOnly': True}}
2018-03-28 14:43:56 DEBUG (Dummy-7) [openzwave] Create object value (valueId:72057594085605377)
2018-03-28 14:43:56 DEBUG (SyncWorker_5) [homeassistant.util.json] JSON file not found: /usr/lib/python3.6/site-packages/homeassistant/components/.translations/sun.no.json
2018-03-28 14:43:56 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1847278352: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'binary_sensor.brannvarsler_bad_sensor', 'old_state': None, 'new_state': <state binary_sensor.brannvarsler_bad_sensor=off; node_id=2, value_index=0, value_instance=1, value_id=72057594076463104, friendly_name=brannvarsler bad Sensor @ 2018-03-28T14:43:55.959202+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 28, 12, 43, 55, 959510, tzinfo=<UTC>)}}
2018-03-28 14:43:56 DEBUG (Dummy-7) [homeassistant.components.zwave.util] value.command_class 94 not in command_class [49]
2018-03-28 14:43:56 DEBUG (SyncWorker_5) [homeassistant.util.json] JSON file not found: /usr/lib/python3.6/site-packages/homeassistant/components/sensor/.translations/yr.no.json
2018-03-28 14:43:56 DEBUG (Dummy-7) [homeassistant.components.zwave.util] value.command_class 94 not in command_class [50]
2018-03-28 14:43:56 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522241036.190336, level=ERROR, message=Error doing job: Task was destroyed but it is pending!, exception=, source=core.py>

ebudalen commented 6 years ago

With english language (translation disabled):

ERROR (Recorder) [homeassistant.core] Error doing job: Task was destroyed but it is pending!

and zwave disabled:

2018-03-28 16:27:00 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522247220.6923175, level=WARNING, message=Could not render template Dørsensor, the state is unknown., exception=, source=components/sensor/template.py>
2018-03-28 16:27:00 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522247220.7002707, level=WARNING, message=Could not render icon template Dørsensor, the state is unknown., exception=, source=components/sensor/template.py>
2018-03-28 16:27:00 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=device_tracker.philipshue, old_state=<state device_tracker.philipshue=not_home; source_type=None, friendly_name=Philips-hue @ 2018-03-28T16:26:45.187980+02:00>, new_state=<state device_tracker.philipshue=home; source_type=router, latitude=60.4610387, longitude=5.3679731, gps_accuracy=0, friendly_name=Philips-hue @ 2018-03-28T16:27:00.834461+02:00>>
2018-03-28 16:27:00 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.ark_sensor, old_state=<state sensor.ark_sensor=6 days, 13 hours, 35 minutes; friendly_name=Ark Sensor, icon=mdi:playstation @ 2018-03-28T16:26:47.311150+02:00>, new_state=<state sensor.ark_sensor=6 days, 13 hours, 36 minutes; friendly_name=Ark Sensor, icon=mdi:playstation @ 2018-03-28T16:27:00.876260+02:00>>
2018-03-28 16:27:00 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.termostat_kjokken_humidity, old_state=<state sensor.termostat_kjokken_humidity=unknown; unit_of_measurement=%, friendly_name=Kjøkken Fuktighet, icon=mdi:water @ 2018-03-28T16:26:03.287420+02:00>, new_state=<state sensor.termostat_kjokken_humidity=20; Temperature=24.5, Humidity=20, Humidity status=normal, Humidity status numeric=2, Battery numeric=9, Rssi numeric=7, unit_of_measurement=%, friendly_name=Kjøkken Fuktighet, icon=mdi:water @ 2018-03-28T16:27:00.910971+02:00>>
2018-03-28 16:27:00 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.processor_use, old_state=<state sensor.processor_use=32; unit_of_measurement=%, friendly_name=Processor use, icon=mdi:memory @ 2018-03-28T16:26:23.817008+02:00>, new_state=<state sensor.processor_use=30; unit_of_measurement=%, friendly_name=Processor use, icon=mdi:memory @ 2018-03-28T16:27:00.956542+02:00>>
2018-03-28 16:27:00 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.group_kamera_2_av, old_state=<state automation.group_kamera_2_av=on; last_triggered=None, friendly_name=group kamera 2 av @ 2018-03-28T16:26:49.048616+02:00>, new_state=<state automation.group_kamera_2_av=on; last_triggered=2018-03-28T16:27:00.992083+02:00, friendly_name=group kamera 2 av @ 2018-03-28T16:26:49.048616+02:00>>
2018-03-28 16:27:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.device_tracker_philipshue_template, old_state=<state sensor.device_tracker_philipshue_template=Offline; friendly_name=Hue Bridge, icon=mdi:server-network @ 2018-03-28T16:26:47.878323+02:00>, new_state=<state sensor.device_tracker_philipshue_template=Online; friendly_name=Hue Bridge, icon=mdi:server-network @ 2018-03-28T16:27:01.022198+02:00>>
2018-03-28 16:27:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.group_kamera_3_av, old_state=<state automation.group_kamera_3_av=on; last_triggered=None, friendly_name=group kamera 3 av @ 2018-03-28T16:26:49.366631+02:00>, new_state=<state automation.group_kamera_3_av=on; last_triggered=2018-03-28T16:27:01.058865+02:00, friendly_name=group kamera 3 av @ 2018-03-28T16:26:49.366631+02:00>>
2018-03-28 16:27:01 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!

point-4ward commented 6 years ago

I'm getting this too - no idea how to recreate.

ebudalen commented 6 years ago

Since the other messages was during startup, I have logged for a couple of days now, and this is what I got (not at startup these messages). I can confirm that v0.65.6 does not have this problem. I have xxx on the ip and mac adresses for asuswrt, and *** for "highlighting" the errors.

2018-03-29 03:25:37 DEBUG (Thread-3) [homeassistant.components.rfxtrx] Receive RFXCOM event from (Device_id: a700 Class: RFXtrxDevice Sub: 9, Pkt_id: 0a52092ca70080ae320169)
2018-03-29 03:25:40 INFO (MainThread) [homeassistant.components.http.view] Serving /api/12345678901234567890/lights to 192.168.1.234 (auth: True)
2018-03-29 03:25:41 INFO (MainThread) [homeassistant.components.http.view] Serving /api/camera_proxy/camera.vrvarsel to 192.168.1.1 (auth: False)
2018-03-29 03:25:44 INFO (SyncWorker_9) [homeassistant.components.device_tracker.asuswrt] Checking Devices
2018-03-29 03:25:44 DEBUG (SyncWorker_9) [homeassistant.components.device_tracker.asuswrt] Could not parse row: $dev assoclist; done
2018-03-29 03:25:44 DEBUG (SyncWorker_9) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? **xxxxx**
2018-03-29 03:25:44 DEBUG (SyncWorker_9) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? **xxxxx**
2018-03-29 03:25:44 DEBUG (SyncWorker_9) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? **xxxx**
2018-03-29 03:25:44 DEBUG (SyncWorker_9) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? **xxxx**
2018-03-29 03:25:44 DEBUG (SyncWorker_9) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? **xxxx**
2018-03-29 03:25:44 DEBUG (SyncWorker_9) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? **xxxxx**
2018-03-29 03:25:44 DEBUG (SyncWorker_9) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? **xxxx**
2018-03-29 03:25:44 DEBUG (SyncWorker_9) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? **xxxx**
2018-03-29 03:25:44 DEBUG (SyncWorker_9) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? **xxxxx**
2018-03-29 03:25:44 DEBUG (SyncWorker_9) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? **xxxx**
2018-03-29 03:25:44 DEBUG (SyncWorker_9) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? **xxxx**
 *********2018-03-29 03:25:46 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-03-29 03:25:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522286746.1833675, level=ERROR, message=Error doing job: Task was destroyed but it is pending!, exception=, source=core.py>
2018-03-29 03:25:48 DEBUG (Thread-3) [homeassistant.components.rfxtrx] Receive RFXCOM event from (Device_id: 8700 Class: RFXtrxDevice Sub: 9, Pkt_id: 0a52092d870000dc140279)
2018-03-29 03:25:50 INFO (MainThread) [homeassistant.components.http.view] Serving /api/12345678901234567890/lights to 192.168.1.234 (auth: True)
2018-03-29 03:25:51 INFO (MainThread) [homeassistant.components.http.view] Serving /api/camera_proxy/camera.vrvarsel to 192.168.1.1 (auth: False)

2018-03-29 13:01:16 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1851594992: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.forbruk_dette_aaret_stue_template', 'old_state': <state sensor.forbruk_dette_aaret_stue_template=17.4; unit_of_measurement=KW, friendly_name=Forbruk Siste 6 mnd, icon=mdi:chart-line @ 2018-03-29T12:59:13.620915+02:00>, 'new_state': <state sensor.forbruk_dette_aaret_stue_template=17.5; unit_of_measurement=KW, friendly_name=Forbruk Siste 6 mnd, icon=mdi:chart-line @ 2018-03-29T13:01:16.662238+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 11, 1, 16, 662450, tzinfo=<UTC>)}}
2018-03-29 13:01:17 DEBUG (SyncWorker_9) [homeassistant.components.recorder.util] converting 1 rows to native objects took 0.031987s
2018-03-29 13:01:17 INFO (MainThread) [homeassistant.components.http.view] Serving /api/camera_proxy/camera.vrvarsel to 192.168.1.1 (auth: False)
2018-03-29 13:01:17 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1851594992: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.forbruk_dette_aaret_total_template', 'old_state': <state sensor.forbruk_dette_aaret_total_template=25.0; unit_of_measurement=KW, friendly_name=Forbruk Siste 6 mnd, icon=mdi:chart-line @ 2018-03-29T12:59:13.734323+02:00>, 'new_state': <state sensor.forbruk_dette_aaret_total_template=25.1; unit_of_measurement=KW, friendly_name=Forbruk Siste 6 mnd, icon=mdi:chart-line @ 2018-03-29T13:01:16.764776+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 11, 1, 16, 765129, tzinfo=<UTC>)}}
2018-03-29 13:01:17 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1851594992: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.pris_forbruk_dette_aaret_stue_template', 'old_state': <state sensor.pris_forbruk_dette_aaret_stue_template=16.6; unit_of_measurement=kr, friendly_name=Pris Forbruk Siste 6 mnd, icon=mdi:currency-usd @ 2018-03-29T12:59:13.830964+02:00>, 'new_state': <state sensor.pris_forbruk_dette_aaret_stue_template=16.7; unit_of_measurement=kr, friendly_name=Pris Forbruk Siste 6 mnd, icon=mdi:currency-usd @ 2018-03-29T13:01:16.876276+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 11, 1, 16, 876611, tzinfo=<UTC>)}}
2018-03-29 13:01:17 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.pris_forbruk_dette_aaret_total_template, old_state=<state sensor.pris_forbruk_dette_aaret_total_template=23.8; unit_of_measurement=kr, friendly_name=Pris Forbruk Siste 6 mnd, icon=mdi:currency-usd @ 2018-03-29T12:59:13.967877+02:00>, new_state=<state sensor.pris_forbruk_dette_aaret_total_template=23.9; unit_of_measurement=kr, friendly_name=Pris Forbruk Siste 6 mnd, icon=mdi:currency-usd @ 2018-03-29T13:01:17.128210+02:00>>
2018-03-29 13:01:17 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1851594992: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.pris_forbruk_dette_aaret_total_template', 'old_state': <state sensor.pris_forbruk_dette_aaret_total_template=23.8; unit_of_measurement=kr, friendly_name=Pris Forbruk Siste 6 mnd, icon=mdi:currency-usd @ 2018-03-29T12:59:13.967877+02:00>, 'new_state': <state sensor.pris_forbruk_dette_aaret_total_template=23.9; unit_of_measurement=kr, friendly_name=Pris Forbruk Siste 6 mnd, icon=mdi:currency-usd @ 2018-03-29T13:01:17.128210+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 11, 1, 17, 128444, tzinfo=<UTC>)}}
2018-03-29 13:01:17 DEBUG (SyncWorker_1) [homeassistant.components.recorder.util] converting 9 rows to native objects took 0.021269s
2018-03-29 13:01:17 DEBUG (SyncWorker_1) [homeassistant.components.history] getting 0 first datapoints took 0.018661s
2018-03-29 13:01:17 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.varmekabel_gang_tid_30, old_state=<state sensor.varmekabel_gang_tid_30=6.75; value=6h 45m, unit_of_measurement=h, friendly_name=varmekabel gang tid 30, icon=mdi:chart-line @ 2018-03-29T13:00:46.061914+02:00>, new_state=<state sensor.varmekabel_gang_tid_30=6.76; value=6h 45m, unit_of_measurement=h, friendly_name=varmekabel gang tid 30, icon=mdi:chart-line @ 2018-03-29T13:01:17.295895+02:00>>
2018-03-29 13:01:17 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.forbruk_denne_manaden_gang_template, old_state=<state sensor.forbruk_denne_manaden_gang_template=4.0; unit_of_measurement=KW, friendly_name=Forbruk Siste 30 dager, icon=mdi:chart-line @ 2018-03-29T12:50:58.022382+02:00>, new_state=<state sensor.forbruk_denne_manaden_gang_template=4.1; unit_of_measurement=KW, friendly_name=Forbruk Siste 30 dager, icon=mdi:chart-line @ 2018-03-29T13:01:17.332535+02:00>>
2018-03-29 13:01:17 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1851594992: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.varmekabel_gang_tid_30', 'old_state': <state sensor.varmekabel_gang_tid_30=6.75; value=6h 45m, unit_of_measurement=h, friendly_name=varmekabel gang tid 30, icon=mdi:chart-line @ 2018-03-29T13:00:46.061914+02:00>, 'new_state': <state sensor.varmekabel_gang_tid_30=6.76; value=6h 45m, unit_of_measurement=h, friendly_name=varmekabel gang tid 30, icon=mdi:chart-line @ 2018-03-29T13:01:17.295895+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 11, 1, 17, 296089, tzinfo=<UTC>)}}
2018-03-29 13:01:17 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.forbruk_denne_manaden_total_template, old_state=<state sensor.forbruk_denne_manaden_total_template=25.1; unit_of_measurement=KW, friendly_name=Forbruk Siste 30 dager, icon=mdi:chart-line @ 2018-03-29T13:01:16.224939+02:00>, new_state=<state sensor.forbruk_denne_manaden_total_template=25.2; unit_of_measurement=KW, friendly_name=Forbruk Siste 30 dager, icon=mdi:chart-line @ 2018-03-29T13:01:17.379079+02:00>>
2018-03-29 13:01:17 DEBUG (SyncWorker_13) [homeassistant.components.recorder.util] converting 9 rows to native objects took 0.056337s
2018-03-29 13:01:17 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.pris_forbruk_denne_manaden_gang_template, old_state=<state sensor.pris_forbruk_denne_manaden_gang_template=3.8; unit_of_measurement=kr, friendly_name=Pris Forbruk Siste 30 Dager, icon=mdi:currency-usd @ 2018-03-29T12:50:58.169126+02:00>, new_state=<state sensor.pris_forbruk_denne_manaden_gang_template=3.9; unit_of_measurement=kr, friendly_name=Pris Forbruk Siste 30 Dager, icon=mdi:currency-usd @ 2018-03-29T13:01:17.435911+02:00>>
2018-03-29 13:01:17 DEBUG (SyncWorker_13) [homeassistant.components.history] getting 0 first datapoints took 0.048744s
2018-03-29 13:01:17 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1851594992: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.forbruk_denne_manaden_gang_template', 'old_state': <state sensor.forbruk_denne_manaden_gang_template=4.0; unit_of_measurement=KW, friendly_name=Forbruk Siste 30 dager, icon=mdi:chart-line @ 2018-03-29T12:50:58.022382+02:00>, 'new_state': <state sensor.forbruk_denne_manaden_gang_template=4.1; unit_of_measurement=KW, friendly_name=Forbruk Siste 30 dager, icon=mdi:chart-line @ 2018-03-29T13:01:17.332535+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 11, 1, 17, 332730, tzinfo=<UTC>)}}
2018-03-29 13:01:17 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1851594992: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.forbruk_denne_manaden_total_template', 'old_state': <state sensor.forbruk_denne_manaden_total_template=25.1; unit_of_measurement=KW, friendly_name=Forbruk Siste 30 dager, icon=mdi:chart-line @ 2018-03-29T13:01:16.224939+02:00>, 'new_state': <state sensor.forbruk_denne_manaden_total_template=25.2; unit_of_measurement=KW, friendly_name=Forbruk Siste 30 dager, icon=mdi:chart-line @ 2018-03-29T13:01:17.379079+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 11, 1, 17, 379269, tzinfo=<UTC>)}}
2018-03-29 13:01:17 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1851594992: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.pris_forbruk_denne_manaden_gang_template', 'old_state': <state sensor.pris_forbruk_denne_manaden_gang_template=3.8; unit_of_measurement=kr, friendly_name=Pris Forbruk Siste 30 Dager, icon=mdi:currency-usd @ 2018-03-29T12:50:58.169126+02:00>, 'new_state': <state sensor.pris_forbruk_denne_manaden_gang_template=3.9; unit_of_measurement=kr, friendly_name=Pris Forbruk Siste 30 Dager, icon=mdi:currency-usd @ 2018-03-29T13:01:17.435911+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 11, 1, 17, 436251, tzinfo=<UTC>)}}
2018-03-29 13:01:17 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.pris_forbruk_denne_manaden_total_template, old_state=<state sensor.pris_forbruk_denne_manaden_total_template=23.9; unit_of_measurement=kr, friendly_name=Pris Forbruk Siste 30 Dager, icon=mdi:currency-usd @ 2018-03-29T13:01:16.367505+02:00>, new_state=<state sensor.pris_forbruk_denne_manaden_total_template=24.0; unit_of_measurement=kr, friendly_name=Pris Forbruk Siste 30 Dager, icon=mdi:currency-usd @ 2018-03-29T13:01:17.667712+02:00>>
2018-03-29 13:01:17 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.varmekabel_stue_tid_7, old_state=<state sensor.varmekabel_stue_tid_7=6.97; value=6h 58m, unit_of_measurement=h, friendly_name=varmekabel stue tid 7, icon=mdi:chart-line @ 2018-03-29T13:00:46.253606+02:00>, new_state=<state sensor.varmekabel_stue_tid_7=6.98; value=6h 58m, unit_of_measurement=h, friendly_name=varmekabel stue tid 7, icon=mdi:chart-line @ 2018-03-29T13:01:17.735801+02:00>>
2018-03-29 13:01:17 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.termostat_fryser_temperature, old_state=<state sensor.termostat_fryser_temperature=-17.0; Temperature=-17.0, Humidity=51, Humidity status=comfort, Humidity status numeric=1, Battery numeric=9, Rssi numeric=6, unit_of_measurement=°C, friendly_name=Fryser @ 2018-03-29T12:59:43.399004+02:00>, new_state=<state sensor.termostat_fryser_temperature=-16.9; Temperature=-16.9, Humidity=51, Humidity status=comfort, Humidity status numeric=1, Battery numeric=9, Rssi numeric=6, unit_of_measurement=°C, friendly_name=Fryser @ 2018-03-29T13:01:17.794288+02:00>>
2018-03-29 13:01:17 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1851594992: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.pris_forbruk_denne_manaden_total_template', 'old_state': <state sensor.pris_forbruk_denne_manaden_total_template=23.9; unit_of_measurement=kr, friendly_name=Pris Forbruk Siste 30 Dager, icon=mdi:currency-usd @ 2018-03-29T13:01:16.367505+02:00>, 'new_state': <state sensor.pris_forbruk_denne_manaden_total_template=24.0; unit_of_measurement=kr, friendly_name=Pris Forbruk Siste 30 Dager, icon=mdi:currency-usd @ 2018-03-29T13:01:17.667712+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 11, 1, 17, 668024, tzinfo=<UTC>)}}
2018-03-29 13:01:17 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1851594992: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.varmekabel_stue_tid_7', 'old_state': <state sensor.varmekabel_stue_tid_7=6.97; value=6h 58m, unit_of_measurement=h, friendly_name=varmekabel stue tid 7, icon=mdi:chart-line @ 2018-03-29T13:00:46.253606+02:00>, 'new_state': <state sensor.varmekabel_stue_tid_7=6.98; value=6h 58m, unit_of_measurement=h, friendly_name=varmekabel stue tid 7, icon=mdi:chart-line @ 2018-03-29T13:01:17.735801+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 11, 1, 17, 736054, tzinfo=<UTC>)}}
2018-03-29 13:01:17 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1851594992: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.termostat_fryser_temperature', 'old_state': <state sensor.termostat_fryser_temperature=-17.0; Temperature=-17.0, Humidity=51, Humidity status=comfort, Humidity status numeric=1, Battery numeric=9, Rssi numeric=6, unit_of_measurement=°C, friendly_name=Fryser @ 2018-03-29T12:59:43.399004+02:00>, 'new_state': <state sensor.termostat_fryser_temperature=-16.9; Temperature=-16.9, Humidity=51, Humidity status=comfort, Humidity status numeric=1, Battery numeric=9, Rssi numeric=6, unit_of_measurement=°C, friendly_name=Fryser @ 2018-03-29T13:01:17.794288+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 11, 1, 17, 794457, tzinfo=<UTC>)}}
2018-03-29 13:01:17 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.forbruk_denne_uken_stue_template, old_state=<state sensor.forbruk_denne_uken_stue_template=17.4; unit_of_measurement=KW, friendly_name=Forbruk Siste 7 dager, icon=mdi:chart-line @ 2018-03-29T12:59:12.805472+02:00>, new_state=<state sensor.forbruk_denne_uken_stue_template=17.5; unit_of_measurement=KW, friendly_name=Forbruk Siste 7 dager, icon=mdi:chart-line @ 2018-03-29T13:01:17.954957+02:00>>
2018-03-29 13:01:18 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fryser_template, old_state=<state sensor.fryser_template=-17.0; unit_of_measurement=°C, friendly_name=Fryser, icon=mdi:thermometer @ 2018-03-29T12:59:43.521200+02:00>, new_state=<state sensor.fryser_template=-16.9; unit_of_measurement=°C, friendly_name=Fryser, icon=mdi:thermometer @ 2018-03-29T13:01:18.008894+02:00>>
2018-03-29 13:01:18 DEBUG (SyncWorker_5) [homeassistant.components.recorder.util] converting 10 rows to native objects took 0.026178s
******2018-03-29 13:01:18 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-03-29 13:01:18 DEBUG (SyncWorker_5) [homeassistant.components.history] getting 0 first datapoints took 0.060520s
2018-03-29 13:01:18 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522321278.4075933, level=ERROR, message=Error doing job: Task was destroyed but it is pending!, exception=, source=core.py>

2018-03-29 16:13:02 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1847834096: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.time', 'old_state': <state sensor.time=16:12; friendly_name=Time, icon=mdi:clock @ 2018-03-29T16:12:01.943980+02:00>, 'new_state': <state sensor.time=16:13; friendly_name=Time, icon=mdi:clock @ 2018-03-29T16:13:01.942858+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 14, 13, 1, 943139, tzinfo=<UTC>)}}
2018-03-29 16:13:02 DEBUG (MainThread) [homeassistant.components.sensor.uptime] New value: 114.22194173333334
2018-03-29 16:13:02 INFO (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Checking Devices
2018-03-29 16:13:02 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.time_online, old_state=<state sensor.time_online=113.71; unit_of_measurement=minutes, friendly_name=Time Online, icon=mdi:clock @ 2018-03-29T16:12:31.967769+02:00>, new_state=<state sensor.time_online=114.22; unit_of_measurement=minutes, friendly_name=Time Online, icon=mdi:clock @ 2018-03-29T16:13:02.947866+02:00>>
2018-03-29 16:13:03 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: $dev assoclist; done
2018-03-29 16:13:03 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? (192.168.1.42) at xxxxx
2018-03-29 16:13:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.ha_uptime_templated, old_state=<state sensor.ha_uptime_templated=1 hour, 53 minutes; friendly_name=Time Online, icon=mdi:clock-start @ 2018-03-29T16:12:02.086146+02:00>, new_state=<state sensor.ha_uptime_templated=1 hour, 54 minutes; friendly_name=Time Online, icon=mdi:clock-start @ 2018-03-29T16:13:03.069665+02:00>>
2018-03-29 16:13:03 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-29 16:13:03 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 16:13:03 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-29 16:13:03 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-29 16:13:03 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1847834096: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.time_online', 'old_state': <state sensor.time_online=113.71; unit_of_measurement=minutes, friendly_name=Time Online, icon=mdi:clock @ 2018-03-29T16:12:31.967769+02:00>, 'new_state': <state sensor.time_online=114.22; unit_of_measurement=minutes, friendly_name=Time Online, icon=mdi:clock @ 2018-03-29T16:13:02.947866+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 14, 13, 2, 948336, tzinfo=<UTC>)}}
2018-03-29 16:13:03 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-29 16:13:03 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-29 16:13:03 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-29 16:13:03 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1847834096: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.ha_uptime_templated', 'old_state': <state sensor.ha_uptime_templated=1 hour, 53 minutes; friendly_name=Time Online, icon=mdi:clock-start @ 2018-03-29T16:12:02.086146+02:00>, 'new_state': <state sensor.ha_uptime_templated=1 hour, 54 minutes; friendly_name=Time Online, icon=mdi:clock-start @ 2018-03-29T16:13:03.069665+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 14, 13, 3, 69978, tzinfo=<UTC>)}}
2018-03-29 16:13:03 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-29 16:13:03 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 16:13:03 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
******2018-03-29 16:13:04 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-03-29 16:13:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522332784.956785, level=ERROR, message=Error doing job: Task was destroyed but it is pending!, exception=, source=core.py>
2018-03-29 16:13:05 INFO (SyncWorker_11) [homeassistant.components.sensor.command_line] Running command: date +%s

2018-03-29 16:13:30 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2018-03-30T04:27:10+00:00, next_dusk=2018-03-29T18:56:27+00:00, next_midnight=2018-03-29T23:43:00+00:00, next_noon=2018-03-30T11:43:07+00:00, next_rising=2018-03-30T05:10:21+00:00, next_setting=2018-03-29T18:13:24+00:00, elevation=26.63, azimuth=222.62, friendly_name=Sun @ 2018-03-29T14:18:49.610407+02:00>, new_state=<state sun.sun=above_horizon; next_dawn=2018-03-30T04:27:10+00:00, next_dusk=2018-03-29T18:56:27+00:00, next_midnight=2018-03-29T23:43:00+00:00, next_noon=2018-03-30T11:43:07+00:00, next_rising=2018-03-30T05:10:21+00:00, next_setting=2018-03-29T18:13:24+00:00, elevation=26.55, azimuth=222.88, friendly_name=Sun @ 2018-03-29T14:18:49.610407+02:00>>
2018-03-29 16:13:31 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1847834096: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sun.sun', 'old_state': <state sun.sun=above_horizon; next_dawn=2018-03-30T04:27:10+00:00, next_dusk=2018-03-29T18:56:27+00:00, next_midnight=2018-03-29T23:43:00+00:00, next_noon=2018-03-30T11:43:07+00:00, next_rising=2018-03-30T05:10:21+00:00, next_setting=2018-03-29T18:13:24+00:00, elevation=26.63, azimuth=222.62, friendly_name=Sun @ 2018-03-29T14:18:49.610407+02:00>, 'new_state': <state sun.sun=above_horizon; next_dawn=2018-03-30T04:27:10+00:00, next_dusk=2018-03-29T18:56:27+00:00, next_midnight=2018-03-29T23:43:00+00:00, next_noon=2018-03-30T11:43:07+00:00, next_rising=2018-03-30T05:10:21+00:00, next_setting=2018-03-29T18:13:24+00:00, elevation=26.55, azimuth=222.88, friendly_name=Sun @ 2018-03-29T14:18:49.610407+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 14, 13, 30, 941958, tzinfo=<UTC>)}}
2018-03-29 16:13:33 DEBUG (MainThread) [homeassistant.components.sensor.uptime] New value: 114.73856773333334
2018-03-29 16:13:33 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.time_online, old_state=<state sensor.time_online=114.22; unit_of_measurement=minutes, friendly_name=Time Online, icon=mdi:clock @ 2018-03-29T16:13:02.947866+02:00>, new_state=<state sensor.time_online=114.74; unit_of_measurement=minutes, friendly_name=Time Online, icon=mdi:clock @ 2018-03-29T16:13:33.944608+02:00>>
2018-03-29 16:13:34 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1847834096: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sensor.time_online', 'old_state': <state sensor.time_online=114.22; unit_of_measurement=minutes, friendly_name=Time Online, icon=mdi:clock @ 2018-03-29T16:13:02.947866+02:00>, 'new_state': <state sensor.time_online=114.74; unit_of_measurement=minutes, friendly_name=Time Online, icon=mdi:clock @ 2018-03-29T16:13:33.944608+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 14, 13, 33, 945208, tzinfo=<UTC>)}}
*****2018-03-29 16:13:34 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-03-29 16:13:35 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522332814.9922976, level=ERROR, message=Error doing job: Task was destroyed but it is pending!, exception=, source=core.py>
2018-03-29 16:13:35 INFO (SyncWorker_9) [homeassistant.components.sensor.command_line] Running command: date +%s

2018-03-29 22:50:23 INFO (MainThread) [homeassistant.components.http.view] Serving /api/12345678901234567890/lights to 192.168.1.234 (auth: True)
2018-03-29 22:50:28 INFO (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Checking Devices
2018-03-29 22:50:28 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: $dev assoclist; done
2018-03-29 22:50:28 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 22:50:28 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 22:50:28 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 22:50:28 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-29 22:50:28 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 22:50:28 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 22:50:28 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 22:50:28 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 22:50:28 DEBUG (Thread-3) [homeassistant.components.rfxtrx] Receive RFXCOM event from (Device_id: a700 Class: RFXtrxDevice Sub: 9, Pkt_id: 0a5209dca70080a5340169)
2018-03-29 22:50:28 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 22:50:28 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 22:50:28 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 22:50:28 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? (xxxx
2018-03-29 22:50:30 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=below_horizon; next_dawn=2018-03-30T04:27:10+00:00, next_dusk=2018-03-30T18:59:05+00:00, next_midnight=2018-03-29T23:43:00+00:00, next_noon=2018-03-30T11:43:07+00:00, next_rising=2018-03-30T05:10:21+00:00, next_setting=2018-03-30T18:15:53+00:00, elevation=-17.3, azimuth=314.16, friendly_name=Sun @ 2018-03-29T20:13:25.705586+02:00>, new_state=<state sun.sun=below_horizon; next_dawn=2018-03-30T04:27:10+00:00, next_dusk=2018-03-30T18:59:05+00:00, next_midnight=2018-03-29T23:43:00+00:00, next_noon=2018-03-30T11:43:07+00:00, next_rising=2018-03-30T05:10:21+00:00, next_setting=2018-03-30T18:15:53+00:00, elevation=-17.39, azimuth=314.4, friendly_name=Sun @ 2018-03-29T20:13:25.705586+02:00>>
2018-03-29 22:50:30 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1849030672: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sun.sun', 'old_state': <state sun.sun=below_horizon; next_dawn=2018-03-30T04:27:10+00:00, next_dusk=2018-03-30T18:59:05+00:00, next_midnight=2018-03-29T23:43:00+00:00, next_noon=2018-03-30T11:43:07+00:00, next_rising=2018-03-30T05:10:21+00:00, next_setting=2018-03-30T18:15:53+00:00, elevation=-17.3, azimuth=314.16, friendly_name=Sun @ 2018-03-29T20:13:25.705586+02:00>, 'new_state': <state sun.sun=below_horizon; next_dawn=2018-03-30T04:27:10+00:00, next_dusk=2018-03-30T18:59:05+00:00, next_midnight=2018-03-29T23:43:00+00:00, next_noon=2018-03-30T11:43:07+00:00, next_rising=2018-03-30T05:10:21+00:00, next_setting=2018-03-30T18:15:53+00:00, elevation=-17.39, azimuth=314.4, friendly_name=Sun @ 2018-03-29T20:13:25.705586+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 20, 50, 30, 691461, tzinfo=<UTC>)}}
2018-03-29 22:50:30 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1849042320: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sun.sun', 'old_state': <state sun.sun=below_horizon; next_dawn=2018-03-30T04:27:10+00:00, next_dusk=2018-03-30T18:59:05+00:00, next_midnight=2018-03-29T23:43:00+00:00, next_noon=2018-03-30T11:43:07+00:00, next_rising=2018-03-30T05:10:21+00:00, next_setting=2018-03-30T18:15:53+00:00, elevation=-17.3, azimuth=314.16, friendly_name=Sun @ 2018-03-29T20:13:25.705586+02:00>, 'new_state': <state sun.sun=below_horizon; next_dawn=2018-03-30T04:27:10+00:00, next_dusk=2018-03-30T18:59:05+00:00, next_midnight=2018-03-29T23:43:00+00:00, next_noon=2018-03-30T11:43:07+00:00, next_rising=2018-03-30T05:10:21+00:00, next_setting=2018-03-30T18:15:53+00:00, elevation=-17.39, azimuth=314.4, friendly_name=Sun @ 2018-03-29T20:13:25.705586+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 20, 50, 30, 691461, tzinfo=<UTC>)}}
******2018-03-29 22:50:31 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-03-29 22:50:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522356631.7487166, level=ERROR, message=Error doing job: Task was destroyed but it is pending!, exception=, source=core.py>

2018-03-29 23:54:09 INFO (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Checking Devices
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: $dev assoclist; done
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxxx
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 23:54:09 DEBUG (SyncWorker_11) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-29 23:54:10 INFO (SyncWorker_10) [homeassistant.components.sensor.command_line] Running command: cat /sys/class/thermal/thermal_zone0/temp
2018-03-29 23:54:13 DEBUG (Thread-3) [homeassistant.components.rfxtrx] Receive RFXCOM event from (Device_id: 8800 Class: RFXtrxDevice Sub: 7, Pkt_id: 085007ee8800800179)
****2018-03-29 23:54:13 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
****2018-03-29 23:54:13 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
*****2018-03-29 23:54:13 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!

2018-03-30 00:55:30 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=below_horizon; next_dawn=2018-03-30T04:27:10+00:00, next_dusk=2018-03-30T18:59:05+00:00, next_midnight=2018-03-29T23:43:00+00:00, next_noon=2018-03-30T11:43:07+00:00, next_rising=2018-03-30T05:10:21+00:00, next_setting=2018-03-30T18:15:53+00:00, elevation=-24.82, azimuth=346.69, friendly_name=Sun @ 2018-03-29T20:13:25.705586+02:00>, new_state=<state sun.sun=below_horizon; next_dawn=2018-03-30T04:27:10+00:00, next_dusk=2018-03-30T18:59:05+00:00, next_midnight=2018-03-29T23:43:00+00:00, next_noon=2018-03-30T11:43:07+00:00, next_rising=2018-03-30T05:10:21+00:00, next_setting=2018-03-30T18:15:53+00:00, elevation=-24.85, azimuth=346.96, friendly_name=Sun @ 2018-03-29T20:13:25.705586+02:00>>
2018-03-30 00:55:30 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1849030672: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'sun.sun', 'old_state': <state sun.sun=below_horizon; next_dawn=2018-03-30T04:27:10+00:00, next_dusk=2018-03-30T18:59:05+00:00, next_midnight=2018-03-29T23:43:00+00:00, next_noon=2018-03-30T11:43:07+00:00, next_rising=2018-03-30T05:10:21+00:00, next_setting=2018-03-30T18:15:53+00:00, elevation=-24.82, azimuth=346.69, friendly_name=Sun @ 2018-03-29T20:13:25.705586+02:00>, 'new_state': <state sun.sun=below_horizon; next_dawn=2018-03-30T04:27:10+00:00, next_dusk=2018-03-30T18:59:05+00:00, next_midnight=2018-03-29T23:43:00+00:00, next_noon=2018-03-30T11:43:07+00:00, next_rising=2018-03-30T05:10:21+00:00, next_setting=2018-03-30T18:15:53+00:00, elevation=-24.85, azimuth=346.96, friendly_name=Sun @ 2018-03-29T20:13:25.705586+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 29, 22, 55, 30, 691675, tzinfo=<UTC>)}}
2018-03-30 00:55:31 INFO (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Checking Devices
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: $dev assoclist; done
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ?xxxxx
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? (xxxxx
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? (xxxxx
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxxx
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxxx
2018-03-30 00:55:31 DEBUG (SyncWorker_15) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
****2018-03-30 00:55:32 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-03-30 00:55:32 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522364132.7471666, level=ERROR, message=Error doing job: Task was destroyed but it is pending!, exception=, source=core.py>

2018-03-30 04:54:36 DEBUG (Thread-3) [homeassistant.components.rfxtrx] Receive RFXCOM event from (Device_id: 8700 Class: RFXtrxDevice Sub: 9, Pkt_id: 0a52097b870000dd140279)
2018-03-30 04:54:39 INFO (MainThread) [homeassistant.components.http.view] Serving /api/12345678901234567890/lights to 192.168.1.234 (auth: True)
*****2018-03-30 04:54:39 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-03-30 04:54:39 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522378479.7155669, level=ERROR, message=Error doing job: Task was destroyed but it is pending!, exception=, source=core.py>
2018-03-30 04:54:39 INFO (SyncWorker_4) [homeassistant.components.sensor.command_line] Running command: date +%s
2018-03-30 04:54:39 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.termostat_kjokken_temperature, old_state=<state sensor.termostat_kjokken_temperature=20.8; Temperature=20.8, Humidity=20, Humidity status=normal, Humidity status numeric=2, Battery numeric=9, Rssi numeric=7, unit_of_measurement=°C, friendly_name=Kjøkken Temp @ 2018-03-30T04:53:38.276383+02:00>, new_state=<state sensor.termostat_kjokken_temperature=22.1; Temperature=22.1, Humidity=20, Humidity status=normal, Humidity status numeric=2, Battery numeric=9, Rssi numeric=7, unit_of_measurement=°C, friendly_name=Kjøkken Temp @ 2018-03-30T04:54:39.779679+02:00>>
2018-03-30 04:54:39 DEBUG (SyncWorker_3) [homeassistant.components.recorder.util] converting 12 rows to native objects took 0.079194s
2018-03-30 04:54:39 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.processor_use, old_state=<state sensor.processor_use=9; unit_of_measurement=%, friendly_name=Processor use, icon=mdi:memory @ 2018-03-30T04:54:08.753049+02:00>, new_state=<state sensor.processor_use=8; unit_of_measurement=%, friendly_name=Processor use, icon=mdi:memory @ 2018-03-30T04:54:39.910636+02:00>>
2018-03-30 04:54:39 DEBUG (SyncWorker_3) [homeassistant.components.history] getting 0 first datapoints took 0.048881s

2018-03-30 05:03:07 DEBUG (SyncWorker_8) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 05:03:10 INFO (MainThread) [homeassistant.components.http.view] Serving /api/ to 172.30.32.2 (auth: True)
*****2018-03-30 05:03:12 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-03-30 05:03:12 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522378992.7059236, level=ERROR, message=Error doing job: Task was destroyed but it is pending!, exception=, source=core.py>
2018-03-30 05:03:16 INFO (MainThread) [homeassistant.components.http.view] Serving /api/12345678901234567890/lights to 192.168.1.234 (auth: True)

2018-03-30 08:57:40 INFO (MainThread) [homeassistant.components.http.view] Serving /api/12345678901234567890/lights to 192.168.1.234 (auth: True)
2018-03-30 08:57:42 DEBUG (Thread-3) [homeassistant.components.rfxtrx] Receive RFXCOM event from (Device_id: a700 Class: RFXtrxDevice Sub: 9, Pkt_id: 0a520948a7008092340169)
2018-03-30 08:57:42 INFO (SyncWorker_1) [homeassistant.components.device_tracker.asuswrt] Checking Devices
2018-03-30 08:57:42 DEBUG (SyncWorker_1) [homeassistant.components.device_tracker.asuswrt] Could not parse row: $dev assoclist; done
2018-03-30 08:57:42 DEBUG (SyncWorker_1) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-30 08:57:42 DEBUG (SyncWorker_1) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 08:57:42 DEBUG (SyncWorker_1) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 08:57:42 DEBUG (SyncWorker_1) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 08:57:42 DEBUG (SyncWorker_1) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-30 08:57:42 DEBUG (SyncWorker_1) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 08:57:42 DEBUG (SyncWorker_1) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-30 08:57:42 DEBUG (SyncWorker_1) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 08:57:42 DEBUG (SyncWorker_1) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 08:57:42 DEBUG (SyncWorker_1) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 08:57:42 DEBUG (SyncWorker_1) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 08:57:42 DEBUG (SyncWorker_1) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxxx
*****2018-03-30 08:57:43 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-03-30 08:57:43 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522393063.7290483, level=ERROR, message=Error doing job: Task was destroyed but it is pending!, exception=, source=core.py>
2018-03-30 08:57:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.termostat_fryser_humidity, old_state=<state sensor.termostat_fryser_humidity=52; Temperature=-14.4, Humidity=52, Humidity status=comfort, Humidity status numeric=1, Battery numeric=9, Rssi numeric=6, unit_of_measurement=%, friendly_name=Fryser Fuktighet, icon=mdi:water @ 2018-03-30T08:46:55.762978+02:00>, new_state=<state sensor.termostat_fryser_humidity=52; Temperature=-14.6, Humidity=52, Humidity status=comfort, Humidity status numeric=1, Battery numeric=9, Rssi numeric=6, unit_of_measurement=%, friendly_name=Fryser Fuktighet, icon=mdi:water @ 2018-03-30T08:46:55.762978+02:00>>
2018-03-30 08:57:45 INFO (SyncWorker_7) [homeassistant.components.sensor.command_line] Running command: date +%s

2018-03-30 14:21:02 DEBUG (Thread-3) [homeassistant.components.rfxtrx] Receive RFXCOM event from (Device_id: d700 Class: RFXtrxDevice Sub: 9, Pkt_id: 0a520913d7000034410169)
2018-03-30 14:21:03 INFO (MainThread) [homeassistant.components.http.view] Serving /api/12345678901234567890/lights to 192.168.1.234 (auth: True)
2018-03-30 14:21:04 DEBUG (Thread-3) [homeassistant.components.rfxtrx] Receive RFXCOM event from (Device_id: f700 Class: RFXtrxDevice Sub: 9, Pkt_id: 0a520914f70000ea140279)
*****2018-03-30 14:21:04 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-03-30 14:21:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522412464.7311141, level=ERROR, message=Error doing job: Task was destroyed but it is pending!, exception=, source=core.py>
2018-03-30 14:21:05 INFO (SyncWorker_16) [homeassistant.components.device_tracker.asuswrt] Checking Devices

2018-03-30 15:44:43 INFO (MainThread) [homeassistant.components.http.view] Serving /api/12345678901234567890/lights to 192.168.1.234 (auth: True)
2018-03-30 15:44:51 INFO (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Checking Devices
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: $dev assoclist; done
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxx
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxxx
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxxx
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 15:44:51 DEBUG (SyncWorker_3) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 15:44:53 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.tv_backlight, old_state=<state light.tv_backlight=unavailable; friendly_name=TV Backlight, supported_features=63 @ 2018-03-30T15:44:35.753378+02:00>, new_state=<state light.tv_backlight=off; min_mireds=154, max_mireds=500, friendly_name=TV Backlight, supported_features=63 @ 2018-03-30T15:44:53.742151+02:00>>
*****2018-03-30 15:44:53 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-03-30 15:44:53 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522417493.7936544, level=ERROR, message=Error doing job: Task was destroyed but it is pending!, exception=, source=core.py>
2018-03-30 15:44:53 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1856499184: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'light.tv_backlight', 'old_state': <state light.tv_backlight=unavailable; friendly_name=TV Backlight, supported_features=63 @ 2018-03-30T15:44:35.753378+02:00>, 'new_state': <state light.tv_backlight=off; min_mireds=154, max_mireds=500, friendly_name=TV Backlight, supported_features=63 @ 2018-03-30T15:44:53.742151+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 30, 13, 44, 53, 742481, tzinfo=<UTC>)}}
2018-03-30 15:44:53 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1851142000: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'light.tv_backlight', 'old_state': <state light.tv_backlight=unavailable; friendly_name=TV Backlight, supported_features=63 @ 2018-03-30T15:44:35.753378+02:00>, 'new_state': <state light.tv_backlight=off; min_mireds=154, max_mireds=500, friendly_name=TV Backlight, supported_features=63 @ 2018-03-30T15:44:53.742151+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 30, 13, 44, 53, 742481, tzinfo=<UTC>)}}
2018-03-30 15:44:54 INFO (MainThread) [homeassistant.components.http.view] Serving /api/12345678901234567890/lights to 192.168.1.234 (auth: True)

2018-03-30 16:06:48 DEBUG (Thread-3) [homeassistant.components.rfxtrx] Receive RFXCOM event from (Device_id: e700 Class: RFXtrxDevice Sub: 9, Pkt_id: 0a520953e70000b3140279)
2018-03-30 16:06:48 DEBUG (Thread-3) [homeassistant.components.rfxtrx] Receive RFXCOM event from (Device_id: 9700 Class: RFXtrxDevice Sub: 9, Pkt_id: 0a520954970000ef140279)
*****2018-03-30 16:06:51 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-03-30 16:06:51 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522418811.7033234, level=ERROR, message=Error doing job: Task was destroyed but it is pending!, exception=, source=core.py>
2018-03-30 16:06:51 INFO (SyncWorker_0) [homeassistant.components.sensor.command_line] Running command: date +%s
2018-03-30 16:06:51 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.timestamp_now, old_state=<state sensor.timestamp_now=1522418780; friendly_name=timestamp_now @ 2018-03-30T16:06:20.970022+02:00>, new_state=<state sensor.timestamp_now=1522418811; friendly_name=timestamp_now @ 2018-03-30T16:06:51.850871+02:00>>
2018-03-30 16:06:51 DEBUG (Thread-3) [homeassistant.components.rfxtrx] Receive RFXCOM event from (Device_id: c700 Class: RFXtrxDevice Sub: 9, Pkt_id: 0a520955c70000a0250279)
2018-03-30 16:06:51 DEBUG (SyncWorker_10) [homeassistant.components.recorder.util] converting 14 rows to native objects took 0.136417s
2018-03-30 16:06:51 DEBUG (SyncWorker_10) [homeassistant.components.history] getting 0 first datapoints took 0.059554s
2018-03-30 16:06:52 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.ark_sensor_raw, old_state=<state sensor.ark_sensor_raw=738965; friendly_name=Ark Sensor Raw @ 2018-03-30T16:06:21.083256+02:00>, new_state=<state sensor.ark_sensor_raw=738996; friendly_name=Ark Sensor Raw @ 2018-03-30T16:06:52.087089+02:00>>

2018-03-30 16:07:13 DEBUG (SyncWorker_17) [homeassistant.components.device_tracker.asuswrt] Could not parse row: ? xxxxx
2018-03-30 16:07:19 DEBUG (Thread-3) [homeassistant.components.rfxtrx] Receive RFXCOM event from (Device_id: a700 Class: RFXtrxDevice Sub: 9, Pkt_id: 0a520958a70080a3310169)
2018-03-30 16:07:19 DEBUG (Dummy-7) [libopenzwave] notif_callback : new notification
2018-03-30 16:07:19 DEBUG (Dummy-7) [libopenzwave] notif_callback : Notification type : 2, nodeId : 11
2018-03-30 16:07:19 DEBUG (Dummy-7) [libopenzwave] addValueId : ValueID : 72057594227769362
2018-03-30 16:07:19 DEBUG (Dummy-7) [libopenzwave] addValueId : GetCommandClassId : 67, GetType : 2
2018-03-30 16:07:19 DEBUG (Dummy-7) [libopenzwave] addValueId : Notification : {'notificationType': 'ValueChanged', 'homeId': 3987672467, 'nodeId': 11, 'valueId': {'homeId': 3987672467, 'nodeId': 11, 'commandClass': 'COMMAND_CLASS_THERMOSTAT_SETPOINT', 'instance': 1, 'index': 1, 'id': 72057594227769362, 'genre': 'User', 'type': 'Decimal', 'value': 17.0, 'label': 'Heating', 'units': 'C', 'readOnly': False}}
2018-03-30 16:07:19 DEBUG (Dummy-7) [libopenzwave] notif_callback : call callback context
2018-03-30 16:07:19 DEBUG (Dummy-7) [openzwave] zwcallback args=[{'notificationType': 'ValueChanged', 'homeId': 3987672467, 'nodeId': 11, 'valueId': {'homeId': 3987672467, 'nodeId': 11, 'commandClass': 'COMMAND_CLASS_THERMOSTAT_SETPOINT', 'instance': 1, 'index': 1, 'id': 72057594227769362, 'genre': 'User', 'type': 'Decimal', 'value': 17.0, 'label': 'Heating', 'units': 'C', 'readOnly': False}}]
2018-03-30 16:07:19 DEBUG (Dummy-7) [openzwave] Z-Wave Notification ValueChanged : {'notificationType': 'ValueChanged', 'homeId': 3987672467, 'nodeId': 11, 'valueId': {'homeId': 3987672467, 'nodeId': 11, 'commandClass': 'COMMAND_CLASS_THERMOSTAT_SETPOINT', 'instance': 1, 'index': 1, 'id': 72057594227769362, 'genre': 'User', 'type': 'Decimal', 'value': 17.0, 'label': 'Heating', 'units': 'C', 'readOnly': False}}
2018-03-30 16:07:19 DEBUG (Dummy-7) [homeassistant.components.climate.zwave] self._operation_list=['Cool', 'Heat (Default)', 'Energy Heat', 'Off']
2018-03-30 16:07:19 DEBUG (Dummy-7) [homeassistant.components.climate.zwave] self._current_operation=Heat (Default)
2018-03-30 16:07:19 DEBUG (Dummy-7) [homeassistant.components.climate.zwave] self._fan_list=None
2018-03-30 16:07:19 DEBUG (Dummy-7) [homeassistant.components.climate.zwave] self._current_fan_mode=None
2018-03-30 16:07:19 DEBUG (Dummy-7) [libopenzwave] notif_callback : end
2018-03-30 16:07:19 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=zwave.termostat_stue, old_state=<state zwave.termostat_stue=ready; node_id=11, node_name=termostat stue, manufacturer_name=ThermoFloor AS, product_name=Heatit Thermostat TF 021, query_stage=Complete, is_awake=True, is_ready=True, is_failed=False, is_info_received=True, max_baud_rate=40000, is_zwave_plus=True, capabilities={'listening', 'beaming', 'routing'}, neighbors={1, 2, 3, 4, 5, 6, 7, 9, 12, 13}, sentCnt=129, sentFailed=0, retries=0, receivedCnt=1253, receivedDups=10, receivedUnsolicited=1188, sentTS=2018-03-30 16:00:00:857 , receivedTS=2018-03-30 16:05:08:823 , lastRequestRTT=27, averageRequestRTT=25, lastResponseRTT=42, averageResponseRTT=45, friendly_name=termostat stue @ 2018-03-29T18:50:30.450828+02:00>, new_state=<state zwave.termostat_stue=ready; node_id=11, node_name=termostat stue, manufacturer_name=ThermoFloor AS, product_name=Heatit Thermostat TF 021, query_stage=Complete, is_awake=True, is_ready=True, is_failed=False, is_info_received=True, max_baud_rate=40000, is_zwave_plus=True, capabilities={'listening', 'beaming', 'routing'}, neighbors={1, 2, 3, 4, 5, 6, 7, 9, 12, 13}, sentCnt=129, sentFailed=0, retries=0, receivedCnt=1255, receivedDups=10, receivedUnsolicited=1190, sentTS=2018-03-30 16:00:00:857 , receivedTS=2018-03-30 16:07:19:322 , lastRequestRTT=27, averageRequestRTT=25, lastResponseRTT=42, averageResponseRTT=45, friendly_name=termostat stue @ 2018-03-29T18:50:30.450828+02:00>>
2018-03-30 16:07:19 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1856499184: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'zwave.termostat_stue', 'old_state': <state zwave.termostat_stue=ready; node_id=11, node_name=termostat stue, manufacturer_name=ThermoFloor AS, product_name=Heatit Thermostat TF 021, query_stage=Complete, is_awake=True, is_ready=True, is_failed=False, is_info_received=True, max_baud_rate=40000, is_zwave_plus=True, capabilities={'listening', 'beaming', 'routing'}, neighbors={1, 2, 3, 4, 5, 6, 7, 9, 12, 13}, sentCnt=129, sentFailed=0, retries=0, receivedCnt=1253, receivedDups=10, receivedUnsolicited=1188, sentTS=2018-03-30 16:00:00:857 , receivedTS=2018-03-30 16:05:08:823 , lastRequestRTT=27, averageRequestRTT=25, lastResponseRTT=42, averageResponseRTT=45, friendly_name=termostat stue @ 2018-03-29T18:50:30.450828+02:00>, 'new_state': <state zwave.termostat_stue=ready; node_id=11, node_name=termostat stue, manufacturer_name=ThermoFloor AS, product_name=Heatit Thermostat TF 021, query_stage=Complete, is_awake=True, is_ready=True, is_failed=False, is_info_received=True, max_baud_rate=40000, is_zwave_plus=True, capabilities={'listening', 'beaming', 'routing'}, neighbors={1, 2, 3, 4, 5, 6, 7, 9, 12, 13}, sentCnt=129, sentFailed=0, retries=0, receivedCnt=1255, receivedDups=10, receivedUnsolicited=1190, sentTS=2018-03-30 16:00:00:857 , receivedTS=2018-03-30 16:07:19:322 , lastRequestRTT=27, averageRequestRTT=25, lastResponseRTT=42, averageResponseRTT=45, friendly_name=termostat stue @ 2018-03-29T18:50:30.450828+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 30, 14, 7, 19, 491891, tzinfo=<UTC>)}}
2018-03-30 16:07:19 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1851142000: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'zwave.termostat_stue', 'old_state': <state zwave.termostat_stue=ready; node_id=11, node_name=termostat stue, manufacturer_name=ThermoFloor AS, product_name=Heatit Thermostat TF 021, query_stage=Complete, is_awake=True, is_ready=True, is_failed=False, is_info_received=True, max_baud_rate=40000, is_zwave_plus=True, capabilities={'listening', 'beaming', 'routing'}, neighbors={1, 2, 3, 4, 5, 6, 7, 9, 12, 13}, sentCnt=129, sentFailed=0, retries=0, receivedCnt=1253, receivedDups=10, receivedUnsolicited=1188, sentTS=2018-03-30 16:00:00:857 , receivedTS=2018-03-30 16:05:08:823 , lastRequestRTT=27, averageRequestRTT=25, lastResponseRTT=42, averageResponseRTT=45, friendly_name=termostat stue @ 2018-03-29T18:50:30.450828+02:00>, 'new_state': <state zwave.termostat_stue=ready; node_id=11, node_name=termostat stue, manufacturer_name=ThermoFloor AS, product_name=Heatit Thermostat TF 021, query_stage=Complete, is_awake=True, is_ready=True, is_failed=False, is_info_received=True, max_baud_rate=40000, is_zwave_plus=True, capabilities={'listening', 'beaming', 'routing'}, neighbors={1, 2, 3, 4, 5, 6, 7, 9, 12, 13}, sentCnt=129, sentFailed=0, retries=0, receivedCnt=1255, receivedDups=10, receivedUnsolicited=1190, sentTS=2018-03-30 16:00:00:857 , receivedTS=2018-03-30 16:07:19:322 , lastRequestRTT=27, averageRequestRTT=25, lastResponseRTT=42, averageResponseRTT=45, friendly_name=termostat stue @ 2018-03-29T18:50:30.450828+02:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 30, 14, 7, 19, 491891, tzinfo=<UTC>)}}
*****2018-03-30 16:07:22 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-03-30 16:07:22 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1522418842.7048855, level=ERROR, message=Error doing job: Task was destroyed but it is pending!, exception=, source=core.py>
2018-03-30 16:07:22 INFO (SyncWorker_13) [homeassistant.components.sensor.command_line] Running command: date +%s
2018-03-30 16:07:22 DEBUG (SyncWorker_17) [homeassistant.components.recorder.util] converting 14 rows to native objects took 0.111816s
2018-03-30 16:07:22 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.timestamp_now, old_state=<state sensor.timestamp_now=1522418811; friendly_name=timestamp_now @ 2018-03-30T16:06:51.850871+02:00>, new_state=<state sensor.timestamp_now=1522418842; friendly_name=timestamp_now @ 2018-03-30T16:07:22.941611+02:00>>
2018-03-30 16:07:22 DEBUG (SyncWorker_17) [homeassistant.components.history] getting 0 first datapoints took 0.031121s
2018-03-30 16:07:23 INFO (MainThread) [homeassistant.components.http.view] Serving /api/12345678901234567890/lights to 192.168.1.234 (auth: True)

balloob commented 6 years ago

The logs are not going to help that much. Please list the platforms that you are using

nicx commented 6 years ago

expecting the same sinst beta/rc of 0.66. even in the final release this error is regularly seen. running HA on Synology docker. last version without this error was 0.65.5

dancwilliams commented 6 years ago

I am seeing this error as well after upgrading to the stable release. Looks like there is a thread going on the forum.

https://community.home-assistant.io/t/error-in-log-on-restart/48471/4

dancwilliams commented 6 years ago

I am running th following platforms:

Cloud MQTT ZWave Sonos Ecobee

Then just random switches, timers, etc.

I have a second HASS install running the latest code that is not seeing the error. It is only running ZWave & MQTT.

My entire config can be found at:

https://github.com/dancwilliams/homeassistant-config

If you need any other details to help out just let me know.

ebudalen commented 6 years ago

I am using the following platforms:

panel_custom for floorplan
zwave
google (tts)
mjpeg (camera)
generic (still image url)
message_bird
message_bird_custom (custom component for voice)
pushover
smtp (email notify)
asuswrt (devicetracker)
tradfri
harmony (remote)
ifttt
rfxtrx
hue
emulated_hue
cast
mqtt
history_graph
shell_command
input_number
input_select

Sensors:

pi_hole
command_line
rest
rfxtrx
mqtt
scrape
statistics
systemmonitor
speedtest
time_date
uptime
yr
history_stats
template

Lights:

rfxtrx

Switches:

template
command_line
rfxtrx

Does anyone know what`s necessary to this error to be excecuted?

sinker1345 commented 6 years ago

I am using the following platforms:

panel_custom for dominos panel_iframe for nodered zwave (hubzub-1 stick) google (tts, calender, drive time, google assistant integration) mjpeg (camera) unifi_direct ifttt mqtt mysql recorder input_select duckdns binary_sensor media player (plex and kodi) zigbee (hubzub1 no zigbee divices paired) bluetooth tracker owntracks roomba fail2ban Sensors:

mqtt systemmonitor time_date yr template weather underground mqtt xbox googlemaps (drive time)

pip list output (run as homeassistant user):

aiohttp (3.0.9) aiohttp-cors (0.7.0) asn1crypto (0.24.0) astral (1.6) async-timeout (2.0.1) attrs (17.4.0) bellows (0.5.1) certifi (2018.1.18) cffi (1.11.5) chardet (3.0.4) click (6.7) click-log (0.2.0) colorlog (3.1.2) crccheck (0.6) cryptography (2.1.4) distro (1.2.0) ecdsa (0.13) enum-compat (0.0.2) fuzzywuzzy (0.16.0) google-api-python-client (1.6.4) googlemaps (2.5.1) gTTS-token (1.1.1) home-assistant-frontend (20180330.0) homeassistant (0.66.0) httmock (1.2.6) http-ece (1.0.5) httplib2 (0.10.3) idna (2.6) idna-ssl (1.0.1) Jinja2 (2.10) jsonrpc-async (0.6) jsonrpc-base (1.0) jsonrpc-websocket (0.6) libnacl (1.6.1) MarkupSafe (1.0) multidict (4.1.0) mutagen (1.40.0) mysqlclient (1.3.12) netdisco (1.3) netifaces (0.10.6) oauth2client (4.0.0) paho-mqtt (1.3.1) pexpect (4.0.1) pip (9.0.3) pizzapi (0.0.3) pkg-resources (0.0.0) PlexAPI (3.0.6) protobuf (3.5.2) psutil (5.4.3) ptyprocess (0.5.2) pure-pcapy3 (1.0.1) py-vapid (1.3.0) pyasn1 (0.4.2) pyasn1-modules (0.2.1) PyBluez (0.22) PyChromecast (2.0.0) pycparser (2.18) pycrypto (2.6.1) pycryptodome (3.4.11) PyDispatcher (2.0.5) pyfttt (0.3) pyiss (1.0.1) PyJWT (1.6.0) pymssql (2.1.3) pyserial (3.4) pyserial-asyncio (0.4) python-nmap (0.6.1) python-openzwave (0.4.3) pytz (2018.3) pyunifi (2.13) pywebpush (1.6.0) PyYAML (3.12) requests (2.18.4) roombapy (1.3.1) rsa (3.4.2) setuptools (38.5.2) six (1.11.0) SQLAlchemy (1.2.5) tqdm (4.19.6) typing (3.6.4) ua-parser (0.7.3) uritemplate (3.0.0) urllib3 (1.22) user-agents (1.1.0) voluptuous (0.11.1) websocket-client (0.47.0) wheel (0.30.0) XBee (2.3.1) xbee-helper (0.0.7) xboxapi (0.1.1) xmltodict (0.11.0) yarl (1.1.1) zeroconf (0.20.0) zigpy (0.0.3) zigpy-xbee (0.0.2)

if you need me to upload my config to github please let me know. running Home-Assistant in a VENV on proxmox as a VM running it on ubuntu 17.10 with python 3.6.

link to configuration file backup: https://github.com/tdbellgit/homeassistantconfig

HA version 65.6 does not produce any errors in my log but .66 spams my log with the above errors.

ConorMatthews commented 6 years ago

Im having this issue too after upgrading to the stable version of 0.66.0 on hassio :-(

point-4ward commented 6 years ago

On a seriously quick and completely unscientific look at the components listed by the guys above, the common denominators for them and me are mqtt and Zwave.

dancwilliams commented 6 years ago

But, I have an install in my shop that is only running MQTT and zwave that is not seeing the error. It has been running clean since the update to 0.66.

point-4ward commented 6 years ago

^ that's the bit that made me say 'unscientific' - I'm going to have to sit down and go through my config, yours and everyone else's with a fine-tooth comb looking for duplicates I think :/

nicx commented 6 years ago

I dont use these two modules, so this could not be the reason ;)

point-4ward commented 6 years ago

^ argh, would the two of you please stop ruining my theories with facts 😆

balloob commented 6 years ago

Can you try running Home Assistant with the environtment variable PYTHONASYNCIODEBUG set to 1? Command line example:

PYTHONASYNCIODEBUG=1 hass

point-4ward commented 6 years ago

@balloob - sorry to be thick - where do we put this and I'll give it a go later?

balloob commented 6 years ago

Depends on how you run Home Assistant. If you run from the command line, do exactly like I put up there.

Otherwise, you can add a custom component like described here

point-4ward commented 6 years ago

^ adding now, and just goiing to upgrade to 0.66 stable whilst I'm at it - Will report back shortly.

point-4ward commented 6 years ago

OK - so I upgraded and I'm now on 0.66.1b0 , which I didn't even know was a thing 😆

Anywho...

2018-04-01 18:28:44 WARNING (MainThread) [asyncio] Executing <Task pending coro=<_async_setup_component() running at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/setup.py:142> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f01e2ed7738>()] created at /usr/local/lib/python3.6/asyncio/base_events.py:275> cb=[<TaskWakeupMethWrapper object at 0x7f01e307c5e8>(), _wait.<locals>._on_completion() at /usr/local/lib/python3.6/asyncio/tasks.py:380]> took 0.105 seconds
2018-04-01 18:28:44 WARNING (MainThread) [asyncio] Executing <Task pending coro=<_async_setup_component() running at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/setup.py:123> wait_for=<_GatheringFuture pending cb=[<TaskWakeupMethWrapper object at 0x7f01e2ceb2e8>()] created at /usr/local/lib/python3.6/asyncio/tasks.py:549> cb=[<TaskWakeupMethWrapper object at 0x7f01e307c0a8>(), _wait.<locals>._on_completion() at /usr/local/lib/python3.6/asyncio/tasks.py:380]> took 0.602 seconds
2018-04-01 18:28:45 WARNING (MainThread) [asyncio] Executing <Task pending coro=<_async_setup_component() running at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/setup.py:123> wait_for=<_GatheringFuture pending cb=[<TaskWakeupMethWrapper object at 0x7f01e2d152e8>()] created at /usr/local/lib/python3.6/asyncio/tasks.py:549> cb=[<TaskWakeupMethWrapper object at 0x7f01e308e138>(), _wait.<locals>._on_completion() at /usr/local/lib/python3.6/asyncio/tasks.py:380]> took 0.820 seconds
2018-04-01 18:28:46 WARNING (MainThread) [asyncio] Executing <Task finished coro=<ServiceRegistry.async_call() done, defined at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/core.py:908> result=None created at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/core.py:214> took 0.211 seconds
2018-04-01 18:28:51 WARNING (MainThread) [asyncio] Executing <Handle <TaskWakeupMethWrapper object at 0x7f01e2ceb2e8>(<_GatheringFu.../tasks.py:549>) created at /usr/local/lib/python3.6/asyncio/tasks.py:639> took 0.401 seconds
2018-04-01 18:28:53 WARNING (MainThread) [asyncio] Executing <Task finished coro=<EntityPlatform._async_add_entity() done, defined at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py:175> result=None created at /usr/local/lib/python3.6/asyncio/tasks.py:311> took 0.192 seconds
2018-04-01 18:29:59 WARNING (MainThread) [asyncio] Executing <Handle <TaskWakeupMethWrapper object at 0x7f01e16b4498>(<Future finis...events.py:275>) created at /usr/local/lib/python3.6/asyncio/futures.py:378> took 0.385 seconds
2018-04-01 18:30:00 WARNING (SyncWorker_3) [homeassistant.components.emulated_hue] When targeting Google Home, listening port has to be port 80
2018-04-01 18:30:02 WARNING (MainThread) [asyncio] Executing <Task finished coro=<async_setup_platform() done, defined at /usr/local/lib/python3.6/asyncio/coroutines.py:210> result=None created at /usr/local/lib/python3.6/asyncio/tasks.py:672> took 0.101 seconds
2018-04-01 18:30:03 WARNING (MainThread) [asyncio] Executing <Task finished coro=<async_setup_platform() done, defined at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/components/media_player/cast.py:187> result=None created at /usr/local/lib/python3.6/asyncio/tasks.py:672> took 0.633 seconds
2018-04-01 18:30:05 WARNING (MainThread) [asyncio] Executing <Handle <TaskWakeupMethWrapper object at 0x7f01d4fc2b28>(<Future finis...events.py:275>) created at /usr/local/lib/python3.6/asyncio/locks.py:207> took 0.105 seconds
2018-04-01 18:30:07 WARNING (MainThread) [asyncio] Executing <Task pending coro=<EntityPlatform.async_add_entities() running at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py:163> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f01c54e5d08>()] created at /usr/local/lib/python3.6/asyncio/base_events.py:275> created at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/core.py:214> took 0.562 seconds
2018-04-01 18:30:28 WARNING (MainThread) [asyncio] Executing <Task finished coro=<Entity.async_update_ha_state() done, defined at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/entity.py:186> result=None created at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/core.py:214> took 0.227 seconds
2018-04-01 18:30:35 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2018-04-01 18:30:38 WARNING (MainThread) [asyncio] Executing <Task finished coro=<EntityPlatform._async_add_entity() done, defined at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py:175> result=None created at /usr/local/lib/python3.6/asyncio/tasks.py:311> took 0.486 seconds
2018-04-01 18:30:39 WARNING (MainThread) [homeassistant.components.light] Updating hue light took longer than the scheduled update interval 0:00:05
2018-04-01 18:30:42 WARNING (MainThread) [asyncio] Executing <Handle <TaskWakeupMethWrapper object at 0x7f01e2f369a8>(<Future finis...events.py:275>) created at /usr/local/lib/python3.6/asyncio/futures.py:378> took 0.235 seconds
2018-04-01 18:30:44 WARNING (MainThread) [asyncio] Executing <TimerHandle when=159.651115051 _async_create_timer.<locals>.fire_time_event(159.65110005) at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/core.py:1107 created at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/core.py:1122> took 0.192 seconds
2018-04-01 18:30:45 WARNING (MainThread) [asyncio] Executing <Task pending coro=<EntityPlatform._update_entity_states() running at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py:322> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f01c538bf18>()] created at /usr/local/lib/python3.6/asyncio/base_events.py:275> created at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/core.py:218> took 0.391 seconds
2018-04-01 18:30:46 WARNING (MainThread) [asyncio] Executing <Handle <TaskWakeupMethWrapper object at 0x7f01e1327738>(<Future finis...events.py:275>) created at /usr/local/lib/python3.6/asyncio/futures.py:378> took 0.624 seconds
2018-04-01 18:30:46 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2018-04-01 18:31:01 WARNING (MainThread) [asyncio] Executing <Task finished coro=<Entity.async_update_ha_state() done, defined at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/helpers/entity.py:186> result=None created at /srv/homeassistant/lib/python3.6/site-packages/homeassistant/core.py:214> took 0.253 seconds
2018-04-01 18:32:22 WARNING (SyncWorker_8) [homeassistant.components.switch.tplink] Could not read state for Heater: Communication error
2018-04-01 18:33:26 WARNING (MainThread) [asyncio] Executing <Handle <TaskWakeupMethWrapper object at 0x7f01e1929108>(<Future finis...events.py:275>) created at /usr/local/lib/python3.6/asyncio/tasks.py:390> took 0.195 seconds
2018-04-01 18:34:53 ERROR (MainThread) [homeassistant.core] Error doing job: Error on transport creation for incoming connection
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/asyncio/selector_events.py", line 230, in _accept_connection2
    yield from waiter
ConnectionResetError
2018-04-01 18:35:56 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-04-01 18:35:56 WARNING (MainThread) [asyncio] Executing <Handle <TaskWakeupMethWrapper object at 0x7f01e1996c78>(<Future finis...events.py:275>) created at /usr/local/lib/python3.6/asyncio/tasks.py:390> took 0.200 seconds
111

Hope that makes some sens to you @balloob

ebudalen commented 6 years ago

This is what I got during startup:

2018-04-01 19:50:15 WARNING (MainThread) [asyncio] Executing <Task finished coro=<Group._async_state_changed_listener() done, defined at /usr/lib/python3.6/site-packages/homeassistant/components/group/__init__.py:576> result=None created at /usr/lib/python3.6/site-packages/homeassistant/core.py:218> took 0.308 seconds
2018-04-01 19:50:16 WARNING (MainThread) [asyncio] Executing <Task finished coro=<Entity.async_update_ha_state() done, defined at /usr/lib/python3.6/site-packages/homeassistant/helpers/entity.py:186> result=None created at /usr/lib/python3.6/site-packages/homeassistant/core.py:214> took 0.275 seconds
2018-04-01 19:50:16 WARNING (MainThread) [asyncio] Executing <Task finished coro=<AutomationEntity.async_trigger() done, defined at /usr/lib/python3.6/site-packages/homeassistant/components/automation/__init__.py:329> result=None created at /usr/lib/python3.6/site-packages/homeassistant/core.py:218> took 0.313 seconds
2018-04-01 19:50:16 WARNING (MainThread) [asyncio] Executing <Handle <TaskWakeupMethWrapper object at 0x6b153450> created at /usr/lib/python3.6/asyncio/futures.py:383> took 0.271 seconds
2018-04-01 19:50:16 WARNING (MainThread) [asyncio] Executing <Handle <TaskWakeupMethWrapper object at 0x6b60cbb0> created at /usr/lib/python3.6/asyncio/futures.py:383> took 0.271 seconds
2018-04-01 19:50:16 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2018-04-01 19:50:17 WARNING (MainThread) [asyncio] Executing <Task finished coro=<EntityPlatform._async_add_entity() done, defined at /usr/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py:175> result=None created at /usr/lib/python3.6/asyncio/tasks.py:311> took 0.316 seconds
2018-04-01 19:50:17 WARNING (MainThread) [homeassistant.components.light] Updating hue light took longer than the scheduled update interval 0:00:05
2018-04-01 19:50:17 WARNING (MainThread) [asyncio] Executing <Task finished coro=<Entity.async_update_ha_state() done, defined at /usr/lib/python3.6/site-packages/homeassistant/helpers/entity.py:186> result=None created at /usr/lib/python3.6/site-packages/homeassistant/core.py:218> took 0.297 seconds
2018-04-01 19:50:18 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-04-01 19:50:18 WARNING (MainThread) [asyncio] Executing <Task finished coro=<Entity.async_update_ha_state() done, defined at /usr/lib/python3.6/site-packages/homeassistant/helpers/entity.py:186> result=None created at /usr/lib/python3.6/site-packages/homeassistant/core.py:214> took 0.717 seconds
2018-04-01 19:50:18 ERROR (MainThread) [homeassistant.components.light.hue] Unable to reach bridge xxxxxx
2018-04-01 19:50:19 WARNING (MainThread) [asyncio] Executing <Task finished coro=<Entity.async_update_ha_state() done, defined at /usr/lib/python3.6/site-packages/homeassistant/helpers/entity.py:186> result=None created at /usr/lib/python3.6/site-packages/homeassistant/core.py:214> took 0.449 seconds

sinker1345 commented 6 years ago

figured I should post my output from you command as well, this was all logged on 66.1.

PYTHONASYNCIODEBUG=1 hass

2018-04-01 19:58:20 WARNING (MainThread) [asyncio] <asyncio.sslproto.SSLProtocol object at 0x7f302d3127f0>: SSL handshake failed
Traceback (most recent call last):
  File "/usr/lib/python3.6/asyncio/sslproto.py", line 583, in _on_handshake_complete
    raise handshake_exc
  File "/usr/lib/python3.6/asyncio/sslproto.py", line 201, in feed_ssldata
    self._sslobj.do_handshake()
  File "/usr/lib/python3.6/ssl.py", line 689, in do_handshake
    self._sslobj.do_handshake()
ssl.SSLError: [SSL: HTTP_REQUEST] http request (_ssl.c:777)
2018-04-01 19:58:20 WARNING (MainThread) [asyncio] <asyncio.sslproto.SSLProtocol object at 0x7f302d3127f0>: SSL error 1 (reason HTTP_REQUEST)
2018-04-01 19:58:20 ERROR (MainThread) [homeassistant.core] Error doing job: Error on transport creation for incoming connection
Traceback (most recent call last):
  File "/usr/lib/python3.6/asyncio/selector_events.py", line 230, in _accept_connection2
    yield from waiter
  File "/usr/lib/python3.6/asyncio/sslproto.py", line 503, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/usr/lib/python3.6/asyncio/sslproto.py", line 201, in feed_ssldata
    self._sslobj.do_handshake()
  File "/usr/lib/python3.6/ssl.py", line 689, in do_handshake
    self._sslobj.do_handshake()
ssl.SSLError: [SSL: HTTP_REQUEST] http request (_ssl.c:777)
2018-04-01 19:58:20 ERROR (MainThread) [homeassistant.core] Error doing job: Error on transport creation for incoming connection
Traceback (most recent call last):
  File "/usr/lib/python3.6/asyncio/selector_events.py", line 230, in _accept_connection2
    yield from waiter
  File "/usr/lib/python3.6/asyncio/selector_events.py", line 724, in _read_ready
    data = self._sock.recv(self.max_size)
ConnectionResetError: [Errno 104] Connection reset by peer
2018-04-01 19:58:20 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-04-01 19:58:20 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-04-01 19:58:21 WARNING (MainThread) [asyncio] <asyncio.sslproto.SSLProtocol object at 0x7f306c4c0978>: SSL handshake failed
Traceback (most recent call last):
  File "/usr/lib/python3.6/asyncio/sslproto.py", line 583, in _on_handshake_complete
    raise handshake_exc
  File "/usr/lib/python3.6/asyncio/sslproto.py", line 201, in feed_ssldata
    self._sslobj.do_handshake()
  File "/usr/lib/python3.6/ssl.py", line 689, in do_handshake
    self._sslobj.do_handshake()
ssl.SSLError: [SSL: HTTP_REQUEST] http request (_ssl.c:777)
2018-04-01 19:58:21 WARNING (MainThread) [asyncio] <asyncio.sslproto.SSLProtocol object at 0x7f306c4c0978>: SSL error 1 (reason HTTP_REQUEST)
2018-04-01 19:58:21 ERROR (MainThread) [homeassistant.core] Error doing job: Error on transport creation for incoming connection
Traceback (most recent call last):
  File "/usr/lib/python3.6/asyncio/selector_events.py", line 230, in _accept_connection2
    yield from waiter
  File "/usr/lib/python3.6/asyncio/sslproto.py", line 503, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/usr/lib/python3.6/asyncio/sslproto.py", line 201, in feed_ssldata
    self._sslobj.do_handshake()
  File "/usr/lib/python3.6/ssl.py", line 689, in do_handshake
    self._sslobj.do_handshake()
ssl.SSLError: [SSL: HTTP_REQUEST] http request (_ssl.c:777)
2018-04-01 19:58:21 ERROR (MainThread) [homeassistant.core] Error doing job: Error on transport creation for incoming connection
Traceback (most recent call last):
  File "/usr/lib/python3.6/asyncio/selector_events.py", line 230, in _accept_connection2
    yield from waiter
  File "/usr/lib/python3.6/asyncio/selector_events.py", line 724, in _read_ready
    data = self._sock.recv(self.max_size)
ConnectionResetError: [Errno 104] Connection reset by peer
2018-04-01 19:58:22 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-04-01 19:58:22 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-04-01 19:58:22 WARNING (MainThread) [asyncio] <asyncio.sslproto.SSLProtocol object at 0x7f302d324080>: SSL handshake failed
Traceback (most recent call last):
  File "/usr/lib/python3.6/asyncio/sslproto.py", line 583, in _on_handshake_complete
    raise handshake_exc
  File "/usr/lib/python3.6/asyncio/sslproto.py", line 201, in feed_ssldata
    self._sslobj.do_handshake()
  File "/usr/lib/python3.6/ssl.py", line 689, in do_handshake
    self._sslobj.do_handshake()
ssl.SSLError: [SSL: HTTP_REQUEST] http request (_ssl.c:777)
2018-04-01 19:58:22 WARNING (MainThread) [asyncio] <asyncio.sslproto.SSLProtocol object at 0x7f302d324080>: SSL error 1 (reason HTTP_REQUEST)
2018-04-01 19:58:22 ERROR (MainThread) [homeassistant.core] Error doing job: Error on transport creation for incoming connection
Traceback (most recent call last):
  File "/usr/lib/python3.6/asyncio/selector_events.py", line 230, in _accept_connection2
    yield from waiter
  File "/usr/lib/python3.6/asyncio/sslproto.py", line 503, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/usr/lib/python3.6/asyncio/sslproto.py", line 201, in feed_ssldata
    self._sslobj.do_handshake()
  File "/usr/lib/python3.6/ssl.py", line 689, in do_handshake
    self._sslobj.do_handshake()
ssl.SSLError: [SSL: HTTP_REQUEST] http request (_ssl.c:777)
2018-04-01 19:58:22 ERROR (MainThread) [homeassistant.core] Error doing job: Error on transport creation for incoming connection
Traceback (most recent call last):
  File "/usr/lib/python3.6/asyncio/selector_events.py", line 230, in _accept_connection2
    yield from waiter
  File "/usr/lib/python3.6/asyncio/selector_events.py", line 724, in _read_ready
    data = self._sock.recv(self.max_size)
ConnectionResetError: [Errno 104] Connection reset by peer
2018-04-01 19:58:23 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-04-01 19:58:23 ERROR (MainThread) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-04-01 19:58:23 WARNING (MainThread) [asyncio] <asyncio.sslproto.SSLProtocol object at 0x7f302d324358>: SSL handshake failed

lolouk44 commented 6 years ago

Getting this too. On don't have Zwave but have MQTT. HA running on Docker. Will try and get the extra logs

Gnaget2 commented 6 years ago

same problem on hassio 066.1

anthonym21 commented 6 years ago

I started receiving this error tonight in 066.1 after I added a self signed certificate to my http config (from openssl)

I commented out ssl_certificate and ssl_key from my config yaml, restarted, no more error.

cpgifford commented 6 years ago

Like @anthonym21 posted, It seems to be a SSL error. Comment out the ssl_certificate & ssl_key, and pull the power (or restart) and It should come back online. I'm Not sure what caused the issue but I know this fixed mine!

sinker1345 commented 6 years ago

Can you re-include ssl after the restart of the system?

gabrielemanchi commented 6 years ago

Same problem here also with 0.67. All worked fine until 0.65.6 (i'm now using this version because i need SSL for external access and google home integration).

sinker1345 commented 6 years ago

Issue persists with ssl enabled on v .67.0. issue does in fact dissapear when disabling ssl but returns when ssl is re-enabled.

balloob commented 6 years ago

Are people experiencing this only with self signed certs or also with certs from Let's Encrypt?

point-4ward commented 6 years ago

^ Mine is Lets Encrypt.

Still doesn't actually seem to be affecting anything - everything is working fine, just this appears randomly throughout the day.

dancwilliams commented 6 years ago

I am using let’s encrypt as well and I agree, my system seems to be operating without issue. The error just seems to fill the log.

sinker1345 commented 6 years ago

Same here using letsencrypt, I have tried upgrading and downgrading the aiohttp packages the asyncio packages and any other package I could on 67.0 (just tried the packages that were listed as upgraded on the 66.0 release notes) with my config and nothing seems to get rid of the error. I would be fine running it with the error assuming it didn't cause the log file to inflate so much. I am also running home assistant behind haproxy on the latest pf sense if that helps. I am attempting a clean install on another vm tomorrow with just ssl enabled and the letsenceypt certs added if that helps. I am also running home assistant in a python venv

arsaboo commented 6 years ago

Letsencrypt here as well!

sinker1345 commented 6 years ago

Ok, I did a clean install on an Ubuntu server 17.10.1 VM hosted in proxmox and homeassistant installed under a venv as per https://www.home-assistant.io/docs/installation/raspberry-pi/ and I recieve this error as soon as I enable ssl as expected. proxmox vm has 8GB ram 4 sockets (2 sockets, 2cores) and has a bluetooth and hubzb (zwave and zigbee) usb dongles attached although neither of those devices are setup in configuration .yaml.

before I setup ssl I was recieving the following error but some basic googling led me to believe that is because a device is trying to establish an ssl connection. Posting error below for completeness.

ERROR:aiohttp.server:Error handling request
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/web_protocol.py", line 231, in data_received
    messages, upgraded, tail = self._request_parser.feed_data(data)
  File "aiohttp/_http_parser.pyx", line 297, in aiohttp._http_parser.HttpParser.feed_data
aiohttp.http_exceptions.BadStatusLine: invalid HTTP method
INFO:homeassistant.core:Bus:Handling <Event system_log_event[L]: timestamp=1523771618.0024974, level=ERROR, message=Error handling request, exception=Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/web_protocol.py", line 231, in data_received
    messages, upgraded, tail = self._request_parser.feed_data(data)
  File "aiohttp/_http_parser.pyx", line 297, in aiohttp._http_parser.HttpParser.feed_data
aiohttp.http_exceptions.BadStatusLine: invalid HTTP method
, source=/srv/homeassistant/lib/python3.6/site-packages/aiohttp/web_protocol.py>

Martinvdm commented 6 years ago

Perhaps we have to investigate what PHP version is everyone using. PHP has had some issues with ssl.

sinker1345 commented 6 years ago

PHP 7.1.15-0ubuntu0.17.10.1 (cli) (built: Mar 14 2018 22:30:42) ( NTS ) Copyright (c) 1997-2018 The PHP Group Zend Engine v3.1.0, Copyright (c) 1998-2018 Zend Technologies with Zend OPcache v7.1.15-0ubuntu0.17.10.1, Copyright (c) 1999-2018, by Zend Technologies this is what I have on my production system, throws the error as soon as it is upgraded from .65.6

Martinvdm commented 6 years ago

Sorry Made a type. Meaning python version instead of PHP.

sinker1345 commented 6 years ago

also using Python 3.6.3 and pip 9.0.3 from /srv/homeassistant/lib/python3.6/site-packages (python 3.6)

nicx commented 6 years ago

Just deleted all in the deps directory of my docker config dorectory and did a restart because of a tradfri issue... the error seems gone for me. I dont use ssl by the way.

dancwilliams commented 6 years ago

I am running Hass.io.

Python 3.6.3

Flagun commented 6 years ago

I have the same issue and only that error is in the log. However it does not impact the HA.

point-4ward commented 6 years ago

3.6.4 in a venv here.

nlejeune commented 6 years ago

Hass.io 0.67 Python 3.6.3 Same error, the error is here when I'm trying to connect thrue my duckdns with ssl let's encrypt. Since I have the error I can't log into my Haas thrue duckdns.

In local network without auth, no errors and I can log in.

ebudalen commented 6 years ago

Same here, no error when disabling ssl_certificate, ssl_key and base_url.

tim-devel commented 6 years ago

Hi, I am having this issue but do not use SSL. The only link I have identified is that the error comes up everytime I switch tradfri bulbs on or off

point-4ward commented 6 years ago

^ that's ruined the theory then 🤣

I don't have tradifri, and there doesn't seem to be any pattern to when it occurs for me. I've tried logging in and out of the interface, switching things off and on through the interface or from outside homeassistant and I'm stumped for predictably recreating it.

sinker1345 commented 6 years ago

have you put HA behind ngix or a load balancer like haproxy? my instance is behind one and I get the error every time I start it up

home-assistant / core

Error doing job: Task was destroyed but it is pending! 0.66.0.b2 #13494