search

sabeechen / hassio-google-drive-backup

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

HA VM turns off on automatic backups #996

Closed bendiger closed 5 months ago

bendiger commented 7 months ago
Description:
I have been experiencing issues with this add-on for a few months now and have only narrowed it down in the 
past few weeks. When backups run automatically, they seem to shut down my instance of Home Assistant. 
My system runs on ProxMox, so the VM turns off. I have tried different times for backups, and HA shuts 
down the second it runs. I can run manual backups fine so I know the files save. I have plenty of space on 
my HA, and I have tried both local copies and backups to my SMB share. 

When I turn off the add-on, HA does not crash. 

I have not been able to find any useful logs on my own, as when HA turns off, I lose any useful data.
I would be willing to provide more data if directed to where to find it. 

~Ben

Addon version: 0.112.1 Home Assistant Version: 2024.1.5 Supervisor Version: 2024.02.0 Supervisor Channel: stable Hassos Version: 11.5 Docker Version: 24.0.7 Architecture: amd64 Machine: qemux86-64 Date: 2024-02-22T14:08:35.667557+00:00 Timezone: America/Chicago Failure Time: Never Last Good Sync: 2024-02-22T13:23:28.853205+00:00 Next Sync: 2024-02-22T15:41:26.279196+00:00 Next Backup: 2024-02-23T10:00:00+00:00 Next Cache Warm: 2024-02-22T15:35:33.778823+00:00 Time Offset: 0.0

Exception:
 No error could be identified automatically.

Backups:

 {
    "HomeAssistant": {
        "backups": 2,
        "retained": 0,
        "deletable": 2,
        "name": "HomeAssistant",
        "title": "Home Assistant",
        "latest": "2024-02-22T13:20:33Z",
        "max": 4,
        "enabled": true,
        "icon": "home-assistant",
        "ignored": 61,
        "detail": "",
        "size": "4.7 GB",
        "ignored_size": "218.7 MB",
        "free_space": "89.6 GB"
    },
    "GoogleDrive": {
        "backups": 5,
        "retained": 0,
        "deletable": 5,
        "name": "GoogleDrive",
        "title": "Google Drive",
        "latest": "2024-02-22T13:20:33Z",
        "max": 5,
        "enabled": true,
        "icon": "google-drive",
        "ignored": 0,
        "detail": "REDACTED",
        "size": "12.4 GB",
        "ignored_size": "0.0 B",
        "free_space": "1.8 TB"
    }
}
Config:
 {
    "Setting.MAX_BACKUPS_IN_GOOGLE_DRIVE": 5,
    "Setting.DAYS_BETWEEN_BACKUPS": 1.0,
    "Setting.IGNORE_OTHER_BACKUPS": true,
    "Setting.IGNORE_UPGRADE_BACKUPS": false,
    "Setting.DELETE_BEFORE_NEW_BACKUP": true,
    "Setting.BACKUP_TIME_OF_DAY": "04:00",
    "Setting.BACKUP_STORAGE": "local-disk",
    "Setting.GENERATIONAL_DAYS": 7,
    "Setting.GENERATIONAL_WEEKS": 1,
    "Setting.BACKGROUND_COLOR": "#212121"
}
Addon Logs:
 02-22 07:25:12 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 94.60%
02-22 07:25:12 DEBUG [backup.drive.driverequests] Sending 10 MB to Google Drive
02-22 07:25:13 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 95.01%
02-22 07:25:13 DEBUG [backup.drive.driverequests] Sending 10 MB to Google Drive
02-22 07:25:13 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 95.43%
02-22 07:25:13 DEBUG [backup.drive.driverequests] Sending 10 MB to Google Drive
02-22 07:25:13 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 95.84%
02-22 07:25:13 DEBUG [backup.drive.driverequests] Sending 10 MB to Google Drive
02-22 07:25:14 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 96.25%
02-22 07:25:14 DEBUG [backup.drive.driverequests] Sending 10 MB to Google Drive
02-22 07:25:14 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 96.67%
02-22 07:25:14 DEBUG [backup.drive.driverequests] Sending 10 MB to Google Drive
02-22 07:25:15 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 97.08%
02-22 07:25:15 DEBUG [backup.drive.driverequests] Sending 10 MB to Google Drive
02-22 07:25:15 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 97.49%
02-22 07:25:15 DEBUG [backup.drive.driverequests] Sending 10 MB to Google Drive
02-22 07:25:16 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 97.91%
02-22 07:25:16 DEBUG [backup.drive.driverequests] Sending 10 MB to Google Drive
02-22 07:25:16 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 98.32%
02-22 07:25:16 DEBUG [backup.drive.driverequests] Sending 10 MB to Google Drive
02-22 07:25:17 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 98.73%
02-22 07:25:17 DEBUG [backup.drive.driverequests] Sending 10 MB to Google Drive
02-22 07:25:17 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 99.15%
02-22 07:25:17 DEBUG [backup.drive.driverequests] Sending 10 MB to Google Drive
02-22 07:25:17 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 99.56%
02-22 07:25:17 DEBUG [backup.drive.driverequests] Sending 10 MB to Google Drive
02-22 07:25:18 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 99.97%
02-22 07:25:18 DEBUG [backup.drive.driverequests] Sending 714 KB to Google Drive
02-22 07:25:20 DEBUG [backup.drive.drivesource] Uploading Full Backup 2024-02-22 07:20:33 100.00%
02-22 07:25:20 DEBUG [backup.watcher] Checking backup source for changes...
Supervisor Logs:
 24-02-22 07:23:28 INFO (SyncWorker_0) [supervisor.backups.backup] Backing up folder ssl
24-02-22 07:23:28 INFO (SyncWorker_0) [supervisor.backups.backup] Backup folder ssl done
24-02-22 07:23:28 INFO (SyncWorker_7) [supervisor.backups.backup] Backing up folder media
24-02-22 07:23:28 INFO (SyncWorker_7) [supervisor.backups.backup] Backup folder media done
24-02-22 07:23:28 INFO (MainThread) [supervisor.backups.manager] Backup aeb9140f starting stage finishing_file
24-02-22 07:23:28 INFO (MainThread) [supervisor.backups.manager] Creating full backup with slug aeb9140f completed
24-02-22 07:23:28 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/info access from cebe7a76_hassio_google_drive_backup
24-02-22 07:23:28 INFO (MainThread) [supervisor.api.middleware.security] /backups access from cebe7a76_hassio_google_drive_backup
24-02-22 07:23:28 INFO (MainThread) [supervisor.api.middleware.security] /backups/aeb9140f/info access from cebe7a76_hassio_google_drive_backup
24-02-22 07:23:30 INFO (MainThread) [supervisor.api.middleware.security] /backups/aeb9140f/download access from cebe7a76_hassio_google_drive_backup
24-02-22 07:23:30 INFO (MainThread) [supervisor.api.backups] Downloading backup aeb9140f
24-02-22 07:25:20 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/info access from cebe7a76_hassio_google_drive_backup
24-02-22 07:25:20 INFO (MainThread) [supervisor.api.middleware.security] /backups access from cebe7a76_hassio_google_drive_backup
24-02-22 07:29:01 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt'
24-02-22 07:29:01 WARNING (MainThread) [supervisor.auth] Unauthorized login for 'mqtt'
24-02-22 07:34:57 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt'
24-02-22 07:34:57 WARNING (MainThread) [supervisor.auth] Unauthorized login for 'mqtt'
24-02-22 07:39:37 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token
24-02-22 07:39:45 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt'
24-02-22 07:39:45 WARNING (MainThread) [supervisor.auth] Unauthorized login for 'mqtt'
24-02-22 07:45:55 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt'
24-02-22 07:45:55 WARNING (MainThread) [supervisor.auth] Unauthorized login for 'mqtt'
24-02-22 07:51:57 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt'
24-02-22 07:51:57 WARNING (MainThread) [supervisor.auth] Unauthorized login for 'mqtt'
24-02-22 07:58:16 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt'
24-02-22 07:58:17 WARNING (MainThread) [supervisor.auth] Unauthorized login for 'mqtt'
24-02-22 08:04:13 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt'
24-02-22 08:04:13 WARNING (MainThread) [supervisor.auth] Unauthorized login for 'mqtt'
24-02-22 08:08:35 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/logs access from cebe7a76_hassio_google_drive_backup
Home Assistant Core Logs:
 2024-02-22 08:08:10.709 WARNING (MainThread) [homeassistant.const] LENGTH_CENTIMETERS was used from google_fit, this is a deprecated constant which will be removed in HA Core 2025.1. Use UnitOfLength.CENTIMETERS instead, please report it to the author of the 'google_fit' custom integration
2024-02-22 08:08:10.715 WARNING (MainThread) [homeassistant.const] LENGTH_KILOMETERS was used from google_fit, this is a deprecated constant which will be removed in HA Core 2025.1. Use UnitOfLength.KILOMETERS instead, please report it to the author of the 'google_fit' custom integration
2024-02-22 08:08:10.718 WARNING (MainThread) [homeassistant.const] LENGTH_KILOMETERS was used from google_fit, this is a deprecated constant which will be removed in HA Core 2025.1. Use UnitOfLength.KILOMETERS instead, please report it to the author of the 'google_fit' custom integration
2024-02-22 08:08:10.723 WARNING (MainThread) [homeassistant.const] LENGTH_MILES was used from google_fit, this is a deprecated constant which will be removed in HA Core 2025.1. Use UnitOfLength.MILES instead, please report it to the author of the 'google_fit' custom integration
2024-02-22 08:08:10.726 WARNING (MainThread) [homeassistant.const] LENGTH_MILES was used from google_fit, this is a deprecated constant which will be removed in HA Core 2025.1. Use UnitOfLength.MILES instead, please report it to the author of the 'google_fit' custom integration
2024-02-22 08:08:14.398 WARNING (MainThread) [custom_components.localtuya.common] [eb5...sns] Disconnected - waiting for discovery broadcast
2024-02-22 08:08:19.401 WARNING (MainThread) [custom_components.localtuya.common] [eb5...sns] Disconnected - waiting for discovery broadcast
2024-02-22 08:08:24.410 WARNING (MainThread) [custom_components.localtuya.common] [eb5...sns] Disconnected - waiting for discovery broadcast
2024-02-22 08:08:28.412 ERROR (MainThread) [homeassistant.components.forecast_solar] Unexpected error fetching forecast_solar data: 'X-Ratelimit-Limit'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 300, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/forecast_solar/coordinator.py", line 67, in _async_update_data
    return await self.forecast.estimate()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/forecast_solar/__init__.py", line 156, in estimate
    data = await self._request(
           ^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/forecast_solar/__init__.py", line 128, in _request
    self.ratelimit = Ratelimit.from_response(response)
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/forecast_solar/models.py", line 211, in from_response
    limit = int(response.headers["X-Ratelimit-Limit"])
                ~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^
KeyError: 'X-Ratelimit-Limit'
2024-02-22 08:08:29.408 WARNING (MainThread) [custom_components.localtuya.common] [eb5...sns] Disconnected - waiting for discovery broadcast
2024-02-22 08:08:30.865 WARNING (MainThread) [amcrest.http] <Unconnected @ 10.0.1.176> Trying again due to error: ConnectError('All connection attempts failed')
2024-02-22 08:08:34.416 WARNING (MainThread) [custom_components.localtuya.common] [eb5...sns] Disconnected - waiting for discovery broadcast
sabeechen commented 6 months ago

I struggle to think of an easy way to debug this or what would cause it. The HA supervisor loses all of its logs on a reboot, but it also seems unlikely those logs are useful because even the supervisor runs inside docker. The host is where useful information would be, but HA doesn't make it easy to get in there. Would you be willing to get ssh access to the host to see if it has any logs that might provide a clue?

bendiger commented 5 months ago

Funny you say that. I think I was able to figure out the issue. I was running out of ram on the my Host machine, some how... Every time I would see the backup start there was a quick short jump in ram usage, and sometimes proxmox hates this. I wonder if something changed between proxmox 7 to 8. I didn't have issues with ram before upgrading. Super fun to hunt down, but giving the VM another gig of ram seems to have mitigated the issue. I become more and more convinced each day that virtualization of home assistant is a bad idea. If I run the same config on bare metal, I have no issues. 🙃

sabeechen commented 5 months ago

Yikes, I'm glad you were able to extrapolate the problem from the little memory spike, that would have been a real pain to track down without a clue. I expect HA to use more ram during backups, ha still does all the work to construct the backup and particularly while backing up the database it buffers sensor history to ram. If you notice its this add-on using more memory let me know because that's probably a bug, its just sitting idle while it waits for HA to finish the backup.