search

sabeechen / hassio-google-drive-backup

Automatically create and sync Home Assistant backups into Google Drive
MIT License
3.15k stars 192 forks source link

Addon stopped to work some time after upgrading to homeassistant 0.114.2 #228

Closed slavik73 closed 4 years ago

slavik73 commented 4 years ago
Description:
If you have anything else that could help explain what happened, click "Markdown" above and write it here.

Addon version: 0.101.1 Home Assistant Version: 0.114.2 Supervisor Version: 234 Architecture: armv7 Date: 2020-08-19T11:45:34.645133+00:00 Timezone: Asia/Jerusalem Failure Time: 2020-08-19T11:34:29.653445+00:00 Last Good Sync: 2020-08-19T11:34:27.796873+00:00

Exception:

  addon/backup/util/asynchttpgetter.py:133 (read)
  /site-packages/aiohttp/streams.py:416 (readexactly)
aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed
Whose handling caused:
  addon/backup/model/coordinator.py:148 (_sync)
  addon/backup/model/model.py:162 (sync)
  addon/backup/drive/drivesource.py:148 (save)
  addon/backup/drive/driverequests.py:244 (create)
  addon/backup/util/asynchttpgetter.py:140 (read)
backup.exceptions.exceptions.SupervisorUnexpectedError

Snapshots:

 {
    "HomeAssistant": {
        "snapshots": 4,
        "retained": 0,
        "deletable": 4,
        "name": "HomeAssistant",
        "latest": "2020-08-17T22:02:43Z",
        "size": "8.3 GB"
    },
    "GoogleDrive": {
        "snapshots": 4,
        "retained": 0,
        "deletable": 4,
        "name": "GoogleDrive",
        "latest": "2020-08-14T22:45:20Z",
        "size": "8.2 GB"
    }
}
Config:
 {
    "Setting.SNAPSHOT_TIME_OF_DAY": "01:00",
    "Setting.SEND_ERROR_REPORTS": true
}
Addon Logs:
 08-19 12:34:25 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/upload/drive/v3/files/?uploadType=resumable&supportsAllDrives=true&upload_id=AAANsUnLrNaarq8eCqPONef-2WINAt0Rw9XkNqJPRRGUpDstY2M07hhzAAkPclY8BQMDZVqdO_ttcqO0Q5pq7USQt2-_djQP_w
08-19 12:34:25 DEBUG [backup.drive.driverequests] Resuming upload at byte 0 of 2244915200
08-19 12:34:25 ERROR [backup.model.coordinator] The supervisor gave an unexpected response
08-19 12:34:25 INFO [backup.model.coordinator] I'll try again in an hour
08-19 13:20:23 ERROR [backup.ha.haupdater] Trouble updating Home Assistant sensors.
08-19 13:20:23 ERROR [backup.ha.haupdater] 
  addon/backup/ha/haupdater.py:53 (update)
  addon/backup/ha/harequests.py:245 (updateSnapshotStaleSensor)
  addon/backup/ha/harequests.py:204 (_postHaData)
  /site-packages/aiohttp/client.py:1012 (__aenter__)
  [5 hidden frames]
  /site-packages/aiohttp/connector.py:943 (_wrap_create_connection)
aiohttp.client_exceptions.ClientConnectorError: Cannot connect to host hassio:80 ssl:default [Connect call failed ('172.30.32.2', 80)]

08-19 13:34:25 DEBUG [backup.model.syncer] Sync requested by Coordinator
08-19 13:34:25 INFO [backup.model.coordinator] Syncing Snapshots
08-19 13:34:25 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/snapshots
08-19 13:34:25 DEBUG [backup.drive.driverequests] Requesting refreshed Google Drive credentials
08-19 13:34:25 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/1WOg3Rv_JVmfeUC6wB3Q782aCWXpj_oza/?fields=id%2Cname%2CappProperties%2Csize%2Ctrashed%2CmimeType%2CmodifiedTime%2Ccapabilities%2Cparents&supportsAllDrives=true
08-19 13:34:26 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/?q=%271WOg3Rv_JVmfeUC6wB3Q782aCWXpj_oza%27+in+parents&fields=nextPageToken%2Cfiles%28id%2Cname%2CappProperties%2Csize%2Ctrashed%2CmimeType%2CmodifiedTime%2Ccapabilities%2Cparents%29&pageSize=100&supportsAllDrives=true&includeItemsFromAllDrives=true&corpora=allDrives
08-19 13:34:27 INFO [backup.drive.drivesource] Uploading 'Full Snapshot 2020-08-18 01:02:42' to Google Drive
08-19 13:34:27 DEBUG [backup.drive.driverequests] Attempting to resume a previosuly failed upload where we left off
08-19 13:34:27 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/upload/drive/v3/files/?uploadType=resumable&supportsAllDrives=true&upload_id=AAANsUnLrNaarq8eCqPONef-2WINAt0Rw9XkNqJPRRGUpDstY2M07hhzAAkPclY8BQMDZVqdO_ttcqO0Q5pq7USQt2-_djQP_w
08-19 13:34:27 DEBUG [backup.drive.driverequests] Resuming upload at byte 0 of 2244915200
08-19 13:34:27 ERROR [backup.model.coordinator] The supervisor gave an unexpected response
08-19 13:34:27 INFO [backup.model.coordinator] I'll try again in an hour
08-19 14:34:27 DEBUG [backup.model.syncer] Sync requested by Coordinator
08-19 14:34:27 INFO [backup.model.coordinator] Syncing Snapshots
08-19 14:34:27 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/snapshots
08-19 14:34:27 DEBUG [backup.drive.driverequests] Requesting refreshed Google Drive credentials
08-19 14:34:28 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/1WOg3Rv_JVmfeUC6wB3Q782aCWXpj_oza/?fields=id%2Cname%2CappProperties%2Csize%2Ctrashed%2CmimeType%2CmodifiedTime%2Ccapabilities%2Cparents&supportsAllDrives=true
08-19 14:34:28 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/?q=%271WOg3Rv_JVmfeUC6wB3Q782aCWXpj_oza%27+in+parents&fields=nextPageToken%2Cfiles%28id%2Cname%2CappProperties%2Csize%2Ctrashed%2CmimeType%2CmodifiedTime%2Ccapabilities%2Cparents%29&pageSize=100&supportsAllDrives=true&includeItemsFromAllDrives=true&corpora=allDrives
08-19 14:34:29 INFO [backup.drive.drivesource] Uploading 'Full Snapshot 2020-08-18 01:02:42' to Google Drive
08-19 14:34:29 DEBUG [backup.drive.driverequests] Attempting to resume a previosuly failed upload where we left off
08-19 14:34:29 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/upload/drive/v3/files/?uploadType=resumable&supportsAllDrives=true&upload_id=AAANsUnLrNaarq8eCqPONef-2WINAt0Rw9XkNqJPRRGUpDstY2M07hhzAAkPclY8BQMDZVqdO_ttcqO0Q5pq7USQt2-_djQP_w
08-19 14:34:29 DEBUG [backup.drive.driverequests] Resuming upload at byte 0 of 2244915200
08-19 14:34:29 ERROR [backup.model.coordinator] The supervisor gave an unexpected response
08-19 14:34:29 INFO [backup.model.coordinator] I'll try again in an hour
Supervisor Logs:
 20-08-19 10:21:09 INFO (MainThread) [supervisor.hassos] Rauc: A - marked slot kernel.0 as good
20-08-19 10:21:09 INFO (MainThread) [supervisor.addons] Phase 'AddonStartup.INITIALIZE' start 0 add-ons
20-08-19 10:21:09 INFO (MainThread) [supervisor.core] Supervisor reboot detected
20-08-19 10:21:09 INFO (MainThread) [supervisor.misc.tasks] All core tasks are scheduled
20-08-19 10:21:09 INFO (MainThread) [supervisor.misc.hwmon] Started Supervisor hardware monitor
20-08-19 10:21:09 INFO (MainThread) [supervisor.core] Supervisor is up and running
20-08-19 10:21:09 INFO (MainThread) [supervisor.host.info] Update local host information
20-08-19 10:21:09 INFO (MainThread) [supervisor.utils.gdbus] Call org.freedesktop.DBus.Properties.GetAll on /org/freedesktop/hostname1
20-08-19 10:21:09 INFO (MainThread) [supervisor.host.services] Update service information
20-08-19 10:21:09 INFO (MainThread) [supervisor.utils.gdbus] Call org.freedesktop.systemd1.Manager.ListUnits on /org/freedesktop/systemd1
20-08-19 10:21:09 INFO (MainThread) [supervisor.host.network] Update local network DNS information
20-08-19 10:21:09 INFO (MainThread) [supervisor.utils.gdbus] Call org.freedesktop.DBus.Properties.GetAll on /org/freedesktop/NetworkManager/DnsManager
20-08-19 10:21:09 INFO (MainThread) [supervisor.host.sound] Update PulseAudio information
Failed to load cookie file from cookie: No such file or directory
20-08-19 10:21:12 INFO (MainThread) [supervisor.homeassistant] Updated Home Assistant API token
20-08-19 10:21:12 INFO (MainThread) [supervisor.api.proxy] Home Assistant WebSocket API request initialize
20-08-19 10:21:12 INFO (MainThread) [supervisor.api.proxy] WebSocket access from a0d7b954_appdaemon
20-08-19 10:21:12 INFO (MainThread) [supervisor.api.proxy] Home Assistant WebSocket API request running
20-08-19 10:34:25 INFO (MainThread) [supervisor.api.security] /snapshots access from cebe7a76_hassio_google_drive_backup
20-08-19 10:34:27 INFO (MainThread) [supervisor.api.security] /snapshots/3bb6d6cd/download access from cebe7a76_hassio_google_drive_backup
20-08-19 10:34:27 INFO (MainThread) [supervisor.api.snapshots] Download snapshot 3bb6d6cd
20-08-19 10:51:15 INFO (MainThread) [supervisor.homeassistant] Updated Home Assistant API token
20-08-19 11:15:15 INFO (MainThread) [supervisor.auth] Auth request from core_mosquitto for mymqtt
20-08-19 11:15:16 INFO (MainThread) [supervisor.auth] Success login from mymqtt
20-08-19 11:21:18 INFO (MainThread) [supervisor.homeassistant] Updated Home Assistant API token
20-08-19 11:34:27 INFO (MainThread) [supervisor.api.security] /snapshots access from cebe7a76_hassio_google_drive_backup
20-08-19 11:34:29 INFO (MainThread) [supervisor.api.security] /snapshots/3bb6d6cd/download access from cebe7a76_hassio_google_drive_backup
20-08-19 11:34:29 INFO (MainThread) [supervisor.api.snapshots] Download snapshot 3bb6d6cd
20-08-19 11:45:34 INFO (MainThread) [supervisor.api.security] /supervisor/logs access from cebe7a76_hassio_google_drive_backup
Home Assistant Core Logs:
 2020-08-19 14:44:42 INFO (MainThread) [homeassistant.components.automation.pir_1_off] PIR_1 OFF: Running script
2020-08-19 14:44:42 INFO (MainThread) [homeassistant.components.automation.pir_1_off] PIR_1 OFF: Executing step call service
2020-08-19 14:44:47 ERROR (MainThread) [homeassistant.components.image_processing] Error on receive image from entity: Unable to get image
2020-08-19 14:44:49 INFO (MainThread) [homeassistant.components.automation.slavatoiletdoorclose] Executing SlavaToiletDoorClose
2020-08-19 14:44:49 INFO (MainThread) [homeassistant.components.automation.slavatoiletdoorclose] SlavaToiletDoorClose: Running script
2020-08-19 14:44:49 INFO (MainThread) [homeassistant.components.automation.slavatoiletdoorclose] SlavaToiletDoorClose: Executing step call service
2020-08-19 14:44:51 INFO (MainThread) [homeassistant.components.automation.slavatoilet_on] Executing SlavaToilet_OnDoor
2020-08-19 14:44:51 INFO (MainThread) [homeassistant.components.automation.slavatoilet_on] SlavaToilet_OnDoor: Running script
2020-08-19 14:44:51 INFO (MainThread) [homeassistant.components.automation.slavatoilet_on] SlavaToilet_OnDoor: Executing step call service
2020-08-19 14:44:52 INFO (MainThread) [homeassistant.components.automation.slavatoilet_on] SlavaToilet_OnDoor: Executing step call service
2020-08-19 14:44:54 INFO (MainThread) [homeassistant.components.automation.slavatoilet_offv] Executing SlavaToilet_OffV
2020-08-19 14:44:54 INFO (MainThread) [homeassistant.components.automation.slavatoilet_offv] SlavaToilet_OffV: Running script
2020-08-19 14:44:54 INFO (MainThread) [homeassistant.components.automation.slavatoilet_offv] SlavaToilet_OffV: Executing step call service
2020-08-19 14:44:55 INFO (MainThread) [homeassistant.components.automation.slavatoiletdoorclose] Executing SlavaToiletDoorClose
2020-08-19 14:44:55 INFO (MainThread) [homeassistant.components.automation.slavatoiletdoorclose] SlavaToiletDoorClose: Running script
2020-08-19 14:44:55 INFO (MainThread) [homeassistant.components.automation.slavatoiletdoorclose] SlavaToiletDoorClose: Executing step call service
2020-08-19 14:44:57 ERROR (MainThread) [homeassistant.components.image_processing] Error on receive image from entity: Unable to get image
2020-08-19 14:44:59 INFO (MainThread) [homeassistant.components.mqtt.binary_sensor] No matching payload found for entity: RBUTTON_1 with state topic: /myhome/rfbridge/tele/RESULT. Payload: '{"Time":"2020-08-19T12:44:59","RfReceived":{"Sync":12740,"Low":430,"High":1240,"Data":"064566","RfKey":"None"}}', template output: '064566', with value template 'Template("{{ value_json.RfReceived.Data }}")'
2020-08-19 14:44:59 INFO (MainThread) [homeassistant.components.automation.pir_1_camera] Executing PIR_1 Camera
2020-08-19 14:44:59 INFO (MainThread) [homeassistant.components.automation.pir_1_camera] PIR_1 Camera: Running script
2020-08-19 14:44:59 INFO (MainThread) [homeassistant.components.automation.pir_1_camera] PIR_1 Camera: Executing step call service
2020-08-19 14:45:04 INFO (MainThread) [homeassistant.components.esphome] Can't connect to ESPHome API for 192.168.5.83: Error connecting to ('192.168.5.83', 6053): [Errno 113] Connect call failed ('192.168.5.83', 6053)
2020-08-19 14:45:04 INFO (MainThread) [homeassistant.components.esphome] Trying to reconnect to 192.168.5.83 in 60 seconds
2020-08-19 14:45:07 ERROR (MainThread) [homeassistant.components.image_processing] Error on receive image from entity: Unable to get image
2020-08-19 14:45:09 INFO (MainThread) [homeassistant.components.automation.pir_1_off] Executing PIR_1 OFF
2020-08-19 14:45:09 INFO (MainThread) [homeassistant.components.automation.pir_1_off] PIR_1 OFF: Running script
2020-08-19 14:45:09 INFO (MainThread) [homeassistant.components.automation.pir_1_off] PIR_1 OFF: Executing step call service
2020-08-19 14:45:17 ERROR (MainThread) [homeassistant.components.image_processing] Error on receive image from entity: Unable to get image
2020-08-19 14:45:27 ERROR (MainThread) [homeassistant.components.image_processing] Error on receive image from entity: Unable to get image

Copy the info from the previous page here

sabeechen commented 4 years ago

Duplicate of #226 I've had a few other users report this issue already, and from your logs it looks like the same problem. I'll close this (as a duplicate) and post updates any updates in the other bug (#226).