Turning off "Backup my apps" prevents existing backup from being restored

[t-m-w]

When turning off "Backup my apps", the existing backup set becomes unusable for restore. Attempting to restore the set follows through the usual process of entering the recovery key, but then leads to this message: "No suitable backups found at given location" and the following in logcat:

11-16 19:07:19.056 10138 29491 29709 I RestoreCoordinator: Got available metadata for tokens: [1668641603722]
11-16 19:07:19.056 10138 29491 29709 D RestoreViewModel: Ignoring RestoreSet with no last backup time: 1668641603722.

I can replicate this both with USB backup/restore and Internal Storage backup/restore. It has happened when restoring to the main user and restoring to a work profile. It is reproducible whenever "Backup my apps" had been turned off.

Debugging

After turning off "Backup my apps", Seedvault disables the backup service. For some reason, this (or something else related to turning this off) leads to BackupManagerService re-initializing the transport, which reinitializes the device, causing BackupMetadata to be cleared. The time field for the existing backup set becomes zero, and the above error occurs. (See logcat snippet further down.)

The documentation for IBackupManager.setBackupEnabled() doesn't suggest to me that this should happen; in fact, to me, it suggests the opposite, by discussing how data-changed notifications will continue. Nevertheless, it does happen.

This appears to be intended behavior on the AOSP side, when disabling backup. See UserBackupManagerService.updateStateOnBackupEnabled().

To work around this, perhaps Seedvault could disregard initialization calls from AOSP when backup is disabled, or - more simply - take some measures to ensure that the backup set is not modified when "Backup my apps" is turned off, unless fully intended.

logcat when turning off "Backup my apps"

 1000  2201  2766 I BackupManagerService: [UserID:0] Backup enabled => false
 1000  2201  2766 D BackupManagerService: user:0 writeBackupEnableState enable:false
 1000  2201  2201 V BackupManagerService: Running a device init; 2 pending
 1000  2201  2201 V BackupManagerService: [UserID:0] initializeTransport(): [com.android.localtransport/.LocalTransport, com.stevesoltys.seedvault.transport.ConfigurableBackupTransport]
 1000  2201  2201 V BackupManagerService: [UserID:0] Acquired wakelock:*backup*-0-3227
 1000  2201  3227 I BackupManagerService: Initializing (wiping) backup transport storage: com.android.localtransport/.LocalTransport
 1000  2201  3227 I backup_start: com.android.localtransport.LocalTransport
 1000  2201  3227 I backup_transport_lifecycle: [com.android.localtransport/.LocalTransportService,1]
 1000  2201  2201 I backup_transport_connection: [com.android.localtransport/.LocalTransportService,1]
 1000  2201  2201 I TransportConnection: LocalTransportService#22: Notifying [PerformInitializeTask.run()] transport = BackupTransportClient
 1000  2201  3227 I BackupManagerService: Device init successful
 1000  2201  3227 I backup_initialize: 
 1000  2201  3227 V BackupManagerConstants: getKeyValueBackupIntervalMilliseconds(...) returns 14400000
 1000  2201  3227 V BackupManagerConstants: getKeyValueBackupFuzzMilliseconds(...) returns 600000
 1000  2201  3227 V BackupManagerConstants: getKeyValueBackupRequiredNetworkType(...) returns 1
 1000  2201  3227 V BackupManagerConstants: getKeyValueBackupRequireCharging(...) returns true
 1000  2201  3227 V KeyValueBackupJob: Scheduling k/v pass in 242 minutes
 1000  2201  3227 I backup_success: [0,40]
 1000  2201  3227 I BackupManagerService: Initializing (wiping) backup transport storage: com.stevesoltys.seedvault.transport.ConfigurableBackupTransport
 1000  2201  3227 I backup_start: com.stevesoltys.seedvault.transport.ConfigurableBackupTransport
10136 17267 17267 D ConfigurableBackupTransportService: Service created.
 1000  2201  3227 I backup_transport_lifecycle: [com.stevesoltys.seedvault/.transport.ConfigurableBackupTransportService,1]
10136 17267 17267 D ConfigurableBackupTransportService: Transport bound.
 1000  2201  2201 I backup_transport_connection: [com.stevesoltys.seedvault/.transport.ConfigurableBackupTransportService,1]
 1000  2201  2201 I TransportConnection: ConfigurableBackupTransportService#23: Notifying [PerformInitializeTask.run()] transport = BackupTransportClient
10136 17267 17358 I BackupCoordinator: Initialize Device!
[...]
10136 17267 17358 D BackupCoordinator: Resetting backup metadata for token 1669134547630...
10161  3212  3418 V MediaProvider: Inserted id:1000000021 less than next row id backup:1000001000.
10161  3212  6598 V MediaProvider: Inserted id:1000000021 less than next row id backup:1000001000.
 1000  2201  3227 I BackupManagerService: Device init successful
 1000  2201  3227 I backup_initialize: 
 1000  2201  3227 I backup_success: [0,3030]
 1000  2201  3227 I backup_transport_lifecycle: [com.android.localtransport/.LocalTransportService,0]
 1000  2201  3227 I backup_transport_connection: [com.android.localtransport/.LocalTransportService,0]
 1000  2201  3227 I backup_transport_lifecycle: [com.stevesoltys.seedvault/.transport.ConfigurableBackupTransportService,0]
 1000  2201  3227 I backup_transport_connection: [com.stevesoltys.seedvault/.transport.ConfigurableBackupTransportService,0]
 1000  2201  3227 V BackupManagerService: [UserID:0] Released wakelock:*backup*-0-3227
10136 17267 17267 D ConfigurableBackupTransportService: Service destroyed.

[t-m-w]

One alternative to ignoring the BackupManager as done in PR #477 could be to track backup enablement separately within Seedvault, keeping it enabled as far as the system is concerned, and postpone backups that are requested by the system indefinitely when backups are turned off, as has been contemplated for a time at which Seedvault implements its own scheduling (if this happens).

[grote]

BackupManagerService re-initializing the transport, which reinitializes the device, causing BackupMetadata to be cleared. The time field for the existing backup set becomes zero, and the above error occurs.

Why does the time field for the existing backup set becomes zero? And why does that change get uploaded to the server before starting a new backup set?

(Haven't had time to review the open PR yet, but want to understand the above first anyway.)

[t-m-w]

Turning off backup, to AOSP, "also constitutes an opt-out, so we wipe any data for this device from the backend" (UserBackupManagerService.java).

To do this, AOSP calls initializeDevice on the transport, which eventually makes it to Seedvault's MetadataManager.onDeviceInitialization, whose doc states, "Existing [BackupMetadata] will be cleared".

[grote]

AOSP calls initializeDevice on the transport

We've seen it do this in a lot of situations, so killing the existing backup is probably not a good idea. We could start a new restore set, but not kill the old one, I'd say.

[grote]

With #750 we don't touch old restore sets and init is a no-op.