search

sabeechen / hassio-google-drive-backup

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

Backup stale problem #923

Closed S3basuchian closed 1 year ago

S3basuchian commented 1 year ago

Copy the info from the previous page here

Description:
My addon does not create backups anymore. It loads indefinitely and never finishes creating the backup.

Addon version: 0.111.1 Home Assistant Version: 2023.9.3 Supervisor Version: 2023.10.0 Supervisor Channel: stable Hassos Version: 10.5 Docker Version: 23.0.6 Architecture: aarch64 Machine: raspberrypi4-64 Date: 2023-10-15T14:26:05.300561+00:00 Timezone: Europe/Vienna Failure Time: Never Last Good Sync: 2023-10-15T14:15:44.086662+00:00 Next Sync: 2023-10-15T15:46:09.260187+00:00 Next Backup: 2023-10-18T13:18:04.599942+00:00 Next Cache Warm: 2260-05-04T12:35:25.409403+00:00 Time Offset: 0.0

Exception:
 No error could be identified automatically.

Backups:

 {
    "HomeAssistant": {
        "backups": 5,
        "retained": 0,
        "deletable": 5,
        "name": "HomeAssistant",
        "title": "Home Assistant",
        "latest": "2023-10-15T13:18:04Z",
        "max": 4,
        "enabled": true,
        "icon": "home-assistant",
        "ignored": 10,
        "detail": "",
        "size": "790.2 MB",
        "ignored_size": "225.2 MB",
        "free_space": "11.4 GB"
    },
    "GoogleDrive": {
        "backups": 4,
        "retained": 0,
        "deletable": 4,
        "name": "GoogleDrive",
        "title": "Google Drive",
        "latest": "2023-08-31T21:13:34Z",
        "max": 4,
        "enabled": true,
        "icon": "google-drive",
        "ignored": 0,
        "detail": "s3basuchian@gmail.com",
        "size": "790.2 MB",
        "ignored_size": "0.0 B",
        "free_space": "96.3 GB"
    }
}
Config:
 {
    "Setting.SPECIFY_BACKUP_FOLDER": true,
    "Setting.SEND_ERROR_REPORTS": true
}
Addon Logs:
 10-15 09:18:01 INFO [backup.model.coordinator] Syncing Backups
10-15 09:18:02 INFO [backup.ha.hasource] Requesting a new backup
10-15 10:02:55 WARNING [backup.ha.hasource] A backup was already in progress
10-15 10:02:55 DEBUG [backup.model.syncer] Sync requested by HomeAssistant
10-15 10:02:55 INFO [backup.model.coordinator] Syncing Backups
10-15 10:02:55 DEBUG [backup.drive.driverequests] Requesting refreshed Google Drive credentials
10-15 12:18:02 DEBUG [backup.model.syncer] Sync requested by HomeAssistant
10-15 12:18:02 INFO [backup.model.coordinator] Syncing Backups
10-15 12:18:02 DEBUG [backup.drive.driverequests] Requesting refreshed Google Drive credentials
10-15 12:18:04 INFO [backup.ha.hasource] Requesting a new backup
10-15 13:02:12 WARNING [backup.ha.hasource] A backup was already in progress
10-15 13:02:12 DEBUG [backup.model.syncer] Sync requested by HomeAssistant
10-15 13:02:12 INFO [backup.model.coordinator] Syncing Backups
10-15 15:18:04 DEBUG [backup.model.syncer] Sync requested by HomeAssistant
10-15 15:18:04 INFO [backup.model.coordinator] Syncing Backups
10-15 15:18:04 DEBUG [backup.drive.driverequests] Requesting refreshed Google Drive credentials
10-15 15:18:06 INFO [backup.ha.hasource] Requesting a new backup
10-15 16:02:56 WARNING [backup.ha.hasource] A backup was already in progress
10-15 16:02:57 DEBUG [backup.model.syncer] Sync requested by HomeAssistant
10-15 16:02:57 INFO [backup.model.coordinator] Syncing Backups
10-15 16:13:49 DEBUG [backup.model.syncer] Sync requested by UI Server
10-15 16:13:49 INFO [backup.model.coordinator] Syncing Backups
10-15 16:14:52 INFO [backup.drive.folderfinder] Saving backup folder: 1VARspcvdeyQQa53qMBlyeDc12yTLkBLB
10-15 16:14:52 INFO [backup.model.coordinator] Syncing Backups
10-15 16:15:01 INFO [backup.ha.hasource] A backup was already in progress
10-15 16:15:01 ERROR [backup.ui.uiserver] Error serving POST http://s3basuchian.duckdns.org/backup?custom_name=&retain_drive=false&retain_ha=false&note=
10-15 16:15:01 ERROR [backup.ui.uiserver] 
  addon/backup/ui/uiserver.py:791 (error_middleware)
  addon/backup/ui/uiserver.py:294 (backup)
  addon/backup/model/coordinator.py:253 (startBackup)
  addon/backup/model/coordinator.py:353 (_withSoftLock)
  addon/backup/model/coordinator.py:261 (_startBackup)
  addon/backup/ha/hasource.py:200 (create)
backup.exceptions.exceptions.BackupInProgress

10-15 16:15:44 INFO [backup.model.coordinator] Syncing Backups
10-15 16:25:24 INFO [backup.watcher] A backup directory file was modified, we'll check for new backups soon.
10-15 16:25:34 DEBUG [backup.watcher] Checking backup source for changes...
Supervisor Logs:
 23-10-15 16:18:12 INFO (MainThread) [supervisor.api.middleware.security] /addons access from cebe7a76_hassio_google_drive_backup
23-10-15 16:21:38 INFO (MainThread) [supervisor.host.info] Updating local host information
23-10-15 16:21:39 INFO (MainThread) [supervisor.host.services] Updating service information
23-10-15 16:21:39 INFO (MainThread) [supervisor.host.network] Updating local network information
23-10-15 16:21:39 INFO (MainThread) [supervisor.host.sound] Updating PulseAudio information
23-10-15 16:21:39 INFO (MainThread) [supervisor.host.manager] Host information reload completed
23-10-15 16:23:55 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/logs access from cebe7a76_hassio_google_drive_backup
23-10-15 16:23:56 INFO (MainThread) [supervisor.api.middleware.security] /core/logs access from cebe7a76_hassio_google_drive_backup
23-10-15 16:23:56 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/logs access from cebe7a76_hassio_google_drive_backup
23-10-15 16:23:56 INFO (MainThread) [supervisor.api.middleware.security] /core/logs access from cebe7a76_hassio_google_drive_backup
23-10-15 16:25:24 INFO (MainThread) [supervisor.backups.manager] Found 14 backup files
23-10-15 16:25:24 INFO (MainThread) [supervisor.backups.manager] Found 14 backup files
23-10-15 16:25:31 INFO (MainThread) [supervisor.backups.manager] Backup 5388822e starting stage addon_repositories
23-10-15 16:25:31 INFO (MainThread) [supervisor.backups.manager] Backup 5388822e starting stage docker_config
23-10-15 16:25:31 INFO (MainThread) [supervisor.backups.manager] Creating new full backup with slug 5388822e
23-10-15 16:25:31 INFO (MainThread) [supervisor.backups.manager] Backup 5388822e starting stage addons
23-10-15 16:25:31 INFO (MainThread) [supervisor.addons.addon] Building backup for add-on core_duckdns
23-10-15 16:25:31 INFO (MainThread) [supervisor.addons.addon] Finish backup for addon core_duckdns
23-10-15 16:25:31 INFO (MainThread) [supervisor.addons.addon] Building backup for add-on core_configurator
23-10-15 16:25:31 INFO (MainThread) [supervisor.addons.addon] Finish backup for addon core_configurator
23-10-15 16:25:31 INFO (MainThread) [supervisor.addons.addon] Building backup for add-on core_ssh
23-10-15 16:25:31 INFO (MainThread) [supervisor.addons.addon] Finish backup for addon core_ssh
23-10-15 16:25:31 INFO (MainThread) [supervisor.addons.addon] Building backup for add-on a0d7b954_plex
23-10-15 16:25:34 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/info access from cebe7a76_hassio_google_drive_backup
23-10-15 16:25:34 INFO (MainThread) [supervisor.api.middleware.security] /backups access from cebe7a76_hassio_google_drive_backup
23-10-15 16:26:03 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/logs access from cebe7a76_hassio_google_drive_backup
23-10-15 16:26:05 INFO (MainThread) [supervisor.api.middleware.security] /core/logs access from cebe7a76_hassio_google_drive_backup
23-10-15 16:26:05 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/logs access from cebe7a76_hassio_google_drive_backup
23-10-15 16:26:05 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/logs access from cebe7a76_hassio_google_drive_backup
Home Assistant Core Logs:
 2023-10-14 19:50:26.558 ERROR (MainThread) [homeassistant.components.homematicip_cloud.hap] HMIP access point has lost connection with the cloud
2023-10-14 23:00:00.291 ERROR (MainThread) [homeassistant.components.automation.night_heat] Night Heat: Error executing script. Error for call_service at pos 1: Error rendering data template: ValueError: Template error: float got invalid input 'None' when rendering template '{{ (state_attr('climate.allegra_zimmer', 'temperature')) | float }}' but no default was specified
2023-10-14 23:00:00.294 ERROR (MainThread) [homeassistant.components.automation.night_heat] Error while executing automation automation.night_heat: Error rendering data template: ValueError: Template error: float got invalid input 'None' when rendering template '{{ (state_attr('climate.allegra_zimmer', 'temperature')) | float }}' but no default was specified
2023-10-15 01:20:38.309 WARNING (Thread-57) [pychromecast.socket_client] [Android TV(192.168.86.35):8009] Heartbeat timeout, resetting connection
2023-10-15 01:21:08.331 ERROR (Thread-57) [pychromecast.socket_client] [Android TV(192.168.86.35):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.86.35', 8009)), retrying in 5.0s
2023-10-15 02:51:18.245 WARNING (Thread-4) [pychromecast.socket_client] [Schreibtisch Speaker(192.168.86.249):8009] Heartbeat timeout, resetting connection
2023-10-15 02:51:21.819 ERROR (Thread-4) [pychromecast.socket_client] [Schreibtisch Speaker([::ffff:c0a8:56f9]):8009] Failed to connect to service ServiceInfo(type='host', data=('[::ffff:c0a8:56f9]', 8009)), retrying in 5.0s
2023-10-15 03:11:37.862 ERROR (Thread-5) [pychromecast.socket_client] [Ganze Wohnung(192.168.86.42):32168] Error reading from socket.
2023-10-15 03:11:37.866 WARNING (Thread-5) [pychromecast.socket_client] [Ganze Wohnung(192.168.86.42):32168] Error communicating with socket, resetting connection
2023-10-15 03:11:37.867 ERROR (Thread-6) [pychromecast.socket_client] [Allegra Zimmer display(192.168.86.42):8009] Error reading from socket.
2023-10-15 03:11:37.877 WARNING (Thread-6) [pychromecast.socket_client] [Allegra Zimmer display(192.168.86.42):8009] Error communicating with socket, resetting connection
2023-10-15 03:11:41.078 ERROR (Thread-6) [pychromecast.socket_client] [Allegra Zimmer display([::ffff:c0a8:562a]):8009] Failed to connect to service ServiceInfo(type='host', data=('[::ffff:c0a8:562a]', 8009)), retrying in 5.0s
2023-10-15 03:52:07.991 WARNING (Thread-8) [pychromecast.socket_client] [Bad Mini(192.168.86.38):8009] Heartbeat timeout, resetting connection
2023-10-15 03:52:15.112 ERROR (Thread-8) [pychromecast.socket_client] [Bad Mini(192.168.86.38):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.86.38', 8009)), retrying in 5.0s
2023-10-15 04:20:20.940 ERROR (Thread-9) [pychromecast.socket_client] [Kommandozentrale(192.168.86.30):8009] Error reading from socket.
2023-10-15 04:20:20.941 WARNING (Thread-9) [pychromecast.socket_client] [Kommandozentrale(192.168.86.30):8009] Error communicating with socket, resetting connection
2023-10-15 04:20:20.971 ERROR (Thread-9) [pychromecast.socket_client] [Kommandozentrale(192.168.86.30):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.86.30', 8009)), retrying in 5.0s
2023-10-15 04:20:38.514 ERROR (Thread-14) [pychromecast.socket_client] [Schreibtisch Display(192.168.86.29):8009] Error reading from socket.
2023-10-15 04:20:38.517 WARNING (Thread-14) [pychromecast.socket_client] [Schreibtisch Display(192.168.86.29):8009] Error communicating with socket, resetting connection
2023-10-15 04:20:42.135 ERROR (Thread-14) [pychromecast.socket_client] [Schreibtisch Display([::ffff:c0a8:561d]):8009] Failed to connect to service ServiceInfo(type='host', data=('[::ffff:c0a8:561d]', 8009)), retrying in 5.0s
2023-10-15 04:26:24.692 WARNING (Thread-12) [pychromecast.socket_client] [Küche Mini(192.168.86.27):8009] Heartbeat timeout, resetting connection
2023-10-15 04:26:31.801 ERROR (Thread-12) [pychromecast.socket_client] [Küche Mini(192.168.86.27):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.86.27', 8009)), retrying in 5.0s
2023-10-15 05:04:54.167 ERROR (MainThread) [homematicip.aio.connection] No Pong received from server.
2023-10-15 05:04:54.232 ERROR (MainThread) [homeassistant.components.homematicip_cloud.hap] Error connecting to HomematicIP with HAP 3014F711A00003DF29A2E324. Retrying in 8 seconds
2023-10-15 12:17:22.656 ERROR (Thread-7) [pychromecast.socket_client] [Pixel Tablet(192.168.86.25):8009] Error reading from socket.
2023-10-15 12:17:22.658 WARNING (Thread-7) [pychromecast.socket_client] [Pixel Tablet(192.168.86.25):8009] Error communicating with socket, resetting connection
2023-10-15 12:17:22.669 ERROR (Thread-7) [pychromecast.socket_client] [Pixel Tablet(192.168.86.25):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.86.25', 8009)), retrying in 5.0s
2023-10-15 14:30:40.934 WARNING (Thread-57) [pychromecast.socket_client] [Android TV(192.168.86.35):8009] Heartbeat timeout, resetting connection
2023-10-15 14:31:10.972 ERROR (Thread-57) [pychromecast.socket_client] [Android TV(192.168.86.35):8009] Failed to connect to service ServiceInfo(type='mdns', data='BeyondTV-b4b9eed94ca1f8008cddd3bf958664c1._googlecast._tcp.local.'), retrying in 5.0s
sabeechen commented 1 year ago

The supervisor logs get cut off after the back request was denied, thats where the explanation for the problem will show up.

If you are using a network share, its likely that HA is having troubleaccessing your share. For Annoying reasons, this addon can't differentiate between "a backup is in progress" and "the network share is inaccessible".

To figure out what wrong, look at the section at the bottom here about getting the Supervisor Logs. You'll want to look at the logs right after you ask for a new backup, since the supervisor keeps a pretty short log history.

S3basuchian commented 1 year ago

Thanks! I was able to find the issue: It tried to include my media folder in the backup, which is on another disk (and uses way more storage than there is available on the disk with HAOS).