Auto-restore occasionally does not work (from USB?)

[t-m-w]

I tried to restore a D2D-only app (SafeNotes 2.1.0) from a v2 backup on a flash drive. It failed as shown in the error below, while OpenTasks restored fine. However, trying later, it worked. ("Later" was after switching to internal storage, where I also had backups, and trying to restore from there - success - then switching back to USB and trying again - another success somehow this time.)

Logcat snippet

I probably should have had verbose logging on when I took this.

10-03 15:12:49.987  1000  1750  1934 V BackupManagerService: [UserID:0] restoreAtInstall pkg=com.trisven.safenotes token=2 restoreSet=19253c392e2
10-03 15:12:49.987  1000  1750  1934 V BackupManagerService: [UserID:0] Acquired wakelock:*backup*-0-3250
10-03 15:12:49.988  1000  1750  3250 D BackupManagerService: MSG_RUN_RESTORE observer=null
10-03 15:12:49.988  1000  1750  3250 D BackupManagerService: Starting restore.
10-03 15:12:49.991  1000  1750  3250 W BackupManagerService: backup manager monitor is null unable to send event
10-03 15:12:50.001 10162  3984  3984 I BackupStateManager: appBackupRunning: true, filesBackupRunning: false, appBackupWorker: SUCCEEDED, pruneBackupWorker: SUCCEEDED
10-03 15:12:50.001 10162  3984  3984 D ConfigurableBackupTransportService: Service created.
10-03 15:12:50.005 10162  3984  3984 D ConfigurableBackupTransportService: Transport bound.
10-03 15:12:50.007  1000  1750  1750 I TransportConnection: ConfigurableBackupTransportService#14: Notifying [PerformUnifiedRestoreTask.startRestore()] transport = BackupTransportClient
10-03 15:12:50.011 10162  3984 10321 I RestoreCoordinator: Start restore 1727982179042 with [@pm@]
10-03 15:12:50.011 10162  3984 10321 E RestoreCoordinator: No cached backups, loading all and look for 1727982179042
10-03 15:12:50.011 10162  3984 10321 I RestoreCoordinator: getAvailableBackups
10-03 15:12:50.012 10162  3984 10321 D o.c.s.c.b.s.SafBackend: [binder:3984_10      ] list(null, [Snapshot, Metadata])
10-03 15:12:51.460  root     0     0 E msm_dwc3_perf_vote_work: in_perf_mode:1, interrupts in last sample:1692
10-03 15:12:51.714  1000  1750  2245 D ActivityManager: freezing 18703 org.surrel.facebooknotifications
10-03 15:12:51.869  1000  1750  3291 E TaskPersister: File error accessing recents directory (directory doesn't exist?).
10-03 15:12:51.902  1000  1750  2245 D ActivityManager: freezing 18664 android.process.media
10-03 15:12:53.593  root     0     0 E msm_dwc3_perf_vote_work: in_perf_mode:1, interrupts in last sample:1662
10-03 15:12:54.256  1000  1750  3250 E BackupManagerService: Transport error -1000; no restore possible
10-03 15:12:54.259 10162  3984 10321 D RestoreCoordinator: finishRestore
10-03 15:12:54.262  1000  1750  3250 I BackupManagerService: Restore complete.
10-03 15:12:54.272 10162  3984  3984 I BackupStateManager: appBackupRunning: false, filesBackupRunning: false, appBackupWorker: SUCCEEDED, pruneBackupWorker: SUCCEEDED
10-03 15:12:54.274 10162  3984  3984 D ConfigurableBackupTransportService: Service destroyed.

[t-m-w]

(Self-assigned because I think I will need to gather more info.)

[grote]

As there's no more info in between those lines, my theory is that loading all snapshots took too long and we ran into the timeout. The system doesn't want to block install for a long time, so it probably gave up after a couple of seconds.

10-03 15:12:50.011 10162  3984 10321 E RestoreCoordinator: No cached backups, loading all and look for 1727982179042
10-03 15:12:54.256  1000  1750  3250 E BackupManagerService: Transport error -1000; no restore possible

Running https://github.com/seedvault-app/seedvault/blob/android15/logcat-verbose.sh before trying this again may produce more logs and thus clarity.

[t-m-w]

Running https://github.com/seedvault-app/seedvault/blob/android15/logcat-verbose.sh before trying this again may produce more logs and thus clarity.

Yup, will do if/when I can ever reproduce this again.