Snapshots deleted out of order

sabeechen commented 3 years ago

Originally reported in the forums here: https://community.home-assistant.io/t/add-on-home-assistant-google-drive-backup/107928/511

Full text of the post is below: TL:DR - seems there is a conflict when the system initiates snapshots - caused the latest, manual, full snapshot to be purged.

Updating my system and took a full snapshot, then updated an Installed add-on (via supervisor) which triggered a partial snapshot of that component (I forgot to switch it off).

Then tried to take another full snapshot from your WebUI. This indicates it is a partial snapshot not a full snapshot though the logs seem to indicate a full snapshot (still in progress).

07-28 16:39:16 INFO [backup.ha.hasource] Requesting a new snapshot
07-28 16:39:16 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/snapshots/new/full
07-28 16:39:51 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/addons/self/info
07-28 16:39:51 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/info
07-28 16:39:51 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/core/info
07-28 16:39:51 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/supervisor/info

Once finished, it said ‘full’

However, the last full snapshot I triggered manually, seems to have been deleted! (this is the most worrying one!)

I did see it in the log file, but the log of that has gone as I have thousands of these messages

07-28 16:48:44 DEBUG [backup.worker.watcher] Backup directory modified event
07-28 16:48:44 DEBUG [backup.worker.watcher] Backup directory changed
07-28 16:48:44 DEBUG [backup.worker.watcher] Backup directory modified event
07-28 16:48:44 DEBUG [backup.worker.watcher] Backup directory changed
07-28 16:48:44 DEBUG [backup.worker.watcher] Backup directory modified event
07-28 16:48:44 DEBUG [backup.worker.watcher] Backup directory changed
07-28 16:48:44 DEBUG [backup.worker.watcher] Backup directory modified event
07-28 16:48:44 DEBUG [backup.worker.watcher] Backup directory changed
07-28 16:48:44 DEBUG [backup.worker.watcher] Backup directory modified event
07-28 16:48:44 DEBUG [backup.worker.watcher] Backup directory changed
07-28 16:48:44 DEBUG [backup.worker.watcher] Backup directory modified event
07-28 16:48:44 DEBUG [backup.worker.watcher] Backup directory changed

Great add-on though :slight_smile:

[edit] After uploading the new full snapshot, it deleted the partial snapshot!

07-28 16:56:28 DEBUG [backup.drive.drivesource] Uploading Full HASnapshot 2021-07-28 16:39:16 100.00%
07-28 16:56:28 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/xxxxxxxxxxxxxxxxxxxxxx/?fields=id%2Cname%2CappProperties%2Csize%2Ctrashed%2CmimeType%2CmodifiedTime%2Ccapabilities%2Cparents%2CdriveId&supportsAllDrives=true
07-28 16:56:29 INFO [backup.drive.drivesource] Deleting 'addon_7ad98f9c_zigbee2mqtt_1.15.0' From Google Drive
07-28 16:56:29 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/xxxxxxxxxxxxxxxxxxxxxxx/?supportsAllDrives=true
07-28 16:56:30 INFO [backup.worker.watcher] Backup directory changed
07-28 16:56:30 DEBUG [backup.model.syncer] Sync requested by Backup Directory Watcher
07-28 16:56:30 INFO [backup.model.coordinator] Syncing Snapshots
07-28 16:56:30 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/snapshots

sabeechen commented 3 years ago

This indicates it is a partial snapshot not a full snapshot though the logs seem to indicate a full snapshot (still in progress).

I've made separate issue for this, it looks unrelated to the delete-out-of-order issue you're seeing and I'll have it fixed int he next release.

However, the last full snapshot I triggered manually, seems to have been deleted! (this is the most worrying one!)

Which snapshot is this? It looks like your most recent full snapshot before running into this issue was "Full HASnapshot 2021-07-27 00:35:00" which is still there in your screenshots before and after the upload.

Some other things that will help me figure this out:

Its strange in your second screenshot that the snapshot HA created automatically for you "addon_7ad98f9c_zigbee2mqtt_1.15.0" is only in Google Drive and not in Home Assistant. Did the addon delete that snapshot from Home Assistant or did you do it?
Could I have you go to "Actions" -> "Report a Bug" and copy the output from it here? That will help me figure out if your settings could have caused this.

borpin commented 3 years ago

However, the last full snapshot I triggered manually, seems to have been deleted! (this is the most worrying one!)

Which snapshot is this?

It isn't there anymore! I had named it something like pre-update so it was obvious. I did see an entry in the log that it had been deleted, but the logs seem to cover a very small window of time. I am reasonably sure that it deleted it after the add-on backup was created.

Those snapshots you see are the automated ones. You can also see the partial snapshot has been deleted.

Its strange in your second screenshot that the snapshot HA created automatically for you "addon_7ad98f9c_zigbee2mqtt_1.15.0" is only in Google Drive and not in Home Assistant. Did the addon delete that snapshot from Home Assistant or did you do it?

Yes exactly. The snapshot was created by HA when I updated the add-on but when GoogleDrive synced (after creating a new snapshot from your UI), it deleted it.

Description:

If you have anything else that could help explain what happened, click "Markdown" above and write it here.

Addon version: 0.104.3 Home Assistant Version: 2021.7.4 Supervisor Version: 2021.06.8 Supervisor Channel: stable Hassos Version: 6.1 Docker Version: 20.10.6 Architecture: aarch64 Machine: odroid-n2 Date: 2021-07-28T20:52:55.151864+00:00 Timezone: Europe/London Failure Time: Never Last Good Sync: 2021-07-28T20:42:07.377485+00:00

Exception:

 No error could be identified automatically.

Snapshots:

 {
    "HomeAssistant": {
        "snapshots": 8,
        "retained": 0,
        "deletable": 8,
        "name": "HomeAssistant",
        "title": "Home Assistant",
        "latest": "2021-07-28T15:39:16Z",
        "max": 10,
        "enabled": true,
        "icon": "home-assistant",
        "ignored": 0,
        "size": "4.3 GB",
        "ignored_size": "0.0 B",
        "free_space": "91.0 GB"
    },
    "GoogleDrive": {
        "snapshots": 3,
        "retained": 0,
        "deletable": 3,
        "name": "GoogleDrive",
        "title": "Google Drive",
        "latest": "2021-07-28T15:39:16Z",
        "max": 3,
        "enabled": true,
        "icon": "google-drive",
        "ignored": 0,
        "size": "1.7 GB",
        "ignored_size": "0.0 B",
        "free_space": "8.5 GB"
    }
}

Config:

 {
    "Setting.MAX_SNAPSHOTS_IN_HASSIO": 10,
    "Setting.MAX_SNAPSHOTS_IN_GOOGLE_DRIVE": 3,
    "Setting.DAYS_BETWEEN_SNAPSHOTS": 1.0,
    "Setting.SNAPSHOT_NAME": "REDACTED",
    "Setting.SNAPSHOT_TIME_OF_DAY": "00:35",
    "Setting.GENERATIONAL_DAYS": 7,
    "Setting.GENERATIONAL_WEEKS": 2,
    "Setting.GENERATIONAL_DELETE_EARLY": true,
    "Setting.SEND_ERROR_REPORTS": true
}

Addon Logs:

07-28 18:42:03 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/snapshots/6f903373/info
07-28 18:42:03 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/snapshots/d411f8c9/info
07-28 18:42:03 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/snapshots/20bfab79/info
07-28 18:42:03 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/snapshots/b0b68197/info
07-28 18:42:03 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/snapshots/48b9f5e0/info
07-28 18:42:03 DEBUG [backup.drive.driverequests] Requesting refreshed Google Drive credentials
07-28 18:42:03 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx/?fields=id%2Cname%2CappProperties%2Csize%2Ctrashed%2CmimeType%2CmodifiedTime%2Ccapabilities%2Cparents%2CdriveId&supportsAllDrives=true
07-28 18:42:03 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/about?fields=storageQuota
07-28 18:42:04 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/?q=%27xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx%27+in+parents&fields=nextPageToken%2Cfiles%28id%2Cname%2CappProperties%2Csize%2Ctrashed%2CmimeType%2CmodifiedTime%2Ccapabilities%2Cparents%2CdriveId%29&pageSize=100&supportsAllDrives=true&includeItemsFromAllDrives=true&corpora=allDrives
07-28 19:42:05 DEBUG [backup.model.syncer] Sync requested by Coordinator
07-28 19:42:05 INFO [backup.model.coordinator] Syncing Snapshots
07-28 19:42:05 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/snapshots
07-28 19:42:05 DEBUG [backup.drive.driverequests] Requesting refreshed Google Drive credentials
07-28 19:42:05 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx/?fields=id%2Cname%2CappProperties%2Csize%2Ctrashed%2CmimeType%2CmodifiedTime%2Ccapabilities%2Cparents%2CdriveId&supportsAllDrives=true
07-28 19:42:05 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/about?fields=storageQuota
07-28 19:42:05 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/?q=%27xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx%27+in+parents&fields=nextPageToken%2Cfiles%28id%2Cname%2CappProperties%2Csize%2Ctrashed%2CmimeType%2CmodifiedTime%2Ccapabilities%2Cparents%2CdriveId%29&pageSize=100&supportsAllDrives=true&includeItemsFromAllDrives=true&corpora=allDrives
07-28 20:42:06 DEBUG [backup.model.syncer] Sync requested by Coordinator
07-28 20:42:06 INFO [backup.model.coordinator] Syncing Snapshots
07-28 20:42:06 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/snapshots
07-28 20:42:06 DEBUG [backup.drive.driverequests] Requesting refreshed Google Drive credentials
07-28 20:42:06 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx/?fields=id%2Cname%2CappProperties%2Csize%2Ctrashed%2CmimeType%2CmodifiedTime%2Ccapabilities%2Cparents%2CdriveId&supportsAllDrives=true
07-28 20:42:06 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/about?fields=storageQuota
07-28 20:42:06 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/?q=%27xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx%27+in+parents&fields=nextPageToken%2Cfiles%28id%2Cname%2CappProperties%2Csize%2Ctrashed%2CmimeType%2CmodifiedTime%2Ccapabilities%2Cparents%2CdriveId%29&pageSize=100&supportsAllDrives=true&includeItemsFromAllDrives=true&corpora=allDrives
07-28 21:42:07 DEBUG [backup.model.syncer] Sync requested by Coordinator
07-28 21:42:07 INFO [backup.model.coordinator] Syncing Snapshots
07-28 21:42:07 DEBUG [backup.ha.harequests] Making Hassio request: http://hassio/snapshots
07-28 21:42:07 DEBUG [backup.drive.driverequests] Requesting refreshed Google Drive credentials
07-28 21:42:07 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx/?fields=id%2Cname%2CappProperties%2Csize%2Ctrashed%2CmimeType%2CmodifiedTime%2Ccapabilities%2Cparents%2CdriveId&supportsAllDrives=true
07-28 21:42:07 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/about?fields=storageQuota
07-28 21:42:07 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/?q=%27xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx%27+in+parents&fields=nextPageToken%2Cfiles%28id%2Cname%2CappProperties%2Csize%2Ctrashed%2CmimeType%2CmodifiedTime%2Ccapabilities%2Cparents%2CdriveId%29&pageSize=100&supportsAllDrives=true&includeItemsFromAllDrives=true&corpora=allDrives

I have deleted the supervisor and HA logs as there was nothing relating to the add-on there (I have fairly verbose logging running).

sabeechen commented 3 years ago

Ah, the problem is generational snapshots. I should have noticed that from the screenshots. It might come as a surprise that its actually working as designed, though obviously not as expected.

Generational snapshots will keep at most 1 snapshot per day, and the one it keeps is the latest regardless of whats in it. So I think the order of events are:

You made a full snapshot.
HA made a newer partial snapshot.
The addon thinks that partial snapshot is the correct one for that "day" so it deletes the older, full snapshot.
You manually created another full snapshot named "Full HASnapshot 2021-07-28 16:39:16"
The addons thinks that must be the newest snapshot for the day and deletes the partial snapshot.

There is something you can do to avoid this in the future. In the settings enable either:

Ignore other snapshots, which will make it ignore any snapshot the addon didn't make.
Ignore upgrade snapshots, which will make the addon ignore any snapshot it didn't make only if it contains a single folder or addon.

Additionally, when creating a snapshot manually you can select "Keep indefinitely in Home Assistant/Google Drive" which will cause it to be ignored from the deletion schedule. The addon will never delete it automatically.

It might seem silly that the addon picked the more recent partial snapshot to delete over the older full one. In general I agree, but my hands are kind of tied in terms of what to do. The addon has to promote one of the snapshots to be represented for the day. It could instead:

Choose the oldest snapshot, but then any snapshot you create after the automatic one for the day would get deleted immediately.
Stop and throw an error if there are two snapshots for the same day, but then the user would have to intervene before the normal backup schedule could continue.
Do something much more complicated and confusing to try to figure out which snapshot the user would "want" to keep for a day. I suspect this would confuse people more than the existing behavior.

Choosing the latest snapshot may not always be the thing thats wanted, but it at least will produce reliable behavior.

Those automatically created snapshots kind of mess things up for this addon. I wish there were a way to make them default-off. If I'm being honest, I kind of regret implementing generational snapshots too. You aren't the first person who found it confusing and it has been difficult to keep its logic sane as the addon has grown in functionality.

I'm open to suggestions if you think there is some way to improve this experience.

borpin commented 3 years ago

Ah, the problem is generational snapshots. I should have noticed that from the screenshots. It might come as a surprise that its actually working as designed, though obviously not as expected.

Ok that makes sense.

I'm open to suggestions if you think there is some way to improve this experience.

I was not aware of the difference between generational and other types of snapshots. Perhaps you could add a category in the UI so there is a clear differentiation between the two types (generational/non-generational) - perhaps listing them in 2 groups.

I'd also suggest that someone using the add-on would not expect a manually created snapshot to be deleted by a schedule (by default). I now understand what the options in the 'Create Snapshot' mean now but perhaps the phrasing & info could be expanded.

Perhaps "If you rotate daily snapshots, this snapshot will be today's latest snapshot by default."
GD Option text "Upload to Google Drive, exclude from automatic deletion schedule and keep"
HA option text "Exclude from automatic deletion schedule and keep in HA"

Could you add an option to keep for x days when creating a snapshot?

Could a setting summary be included under the statistics?

borpin commented 3 years ago

Do something much more complicated and confusing to try to figure out which snapshot the user would "want" to keep for a day. I suspect this would confuse people more than the existing behavior.

Thinking about this again, I think the answer might be to provide a distinction between the automatic/generational backups and other backups (which is effectively what the two options do of course). I suspect those options may have been added after I set it up :)

sabeechen / hassio-google-drive-backup