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.