Error finishing backup: IllegalStateException: No metadata for @pm@

[aereaux]

Hi, I'm using Seedvault on Grapheneos, and after switching to the davx5 backend the backup starts failing at the end. I think this is the relevant portion of the log:

12-15 19:02:32.755 13691 13957 D NotificationBackupObserver: Finalizing backup...
12-15 19:02:32.758 13691 13957 D MemoryLogger: 37 MiB free - 85 of 122 (max 256)
12-15 19:02:32.764 13691 13957 I c.s.s.r.AppBackupManager: [binder:13691_C      ] After backup finished. Success: true
12-15 19:02:32.767 13691 13957 I c.s.s.r.BlobCache: [binder:13691_C      ] Clearing cache...
12-15 19:02:32.768 13691 13957 I c.s.s.r.SnapshotCreator: [binder:13691_C      ] finalizeSnapshot()
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: [binder:13691_C      ] Error finishing backupjava.lang.IllegalStateException: No metadata for @pm@
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at com.stevesoltys.seedvault.repo.SnapshotCreator.finalizeSnapshot(SnapshotCreator.kt:191)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at com.stevesoltys.seedvault.repo.AppBackupManager.afterBackupFinished(AppBackupManager.kt:99)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at com.stevesoltys.seedvault.ui.notification.NotificationBackupObserver$backupFinished$snapshot$1.invokeSuspend(NotificationBackupObserver.kt:165)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:108)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:280)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source:1)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source:1)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at com.stevesoltys.seedvault.ui.notification.NotificationBackupObserver.backupFinished(NotificationBackupObserver.kt:162)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at android.app.backup.IBackupObserver$Stub.onTransact(IBackupObserver.java:148)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at android.os.Binder.execTransactInternal(Binder.java:1425)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: 	at android.os.Binder.execTransact(Binder.java:1359)
12-15 19:02:32.866 13691 13957 D MemoryLogger: 37 MiB free - 85 of 122 (max 256)

[grote]

Thanks for the report! Is there any chance you could mail me the full log to t at grobox dot de ? Otherwise, previous mentions of @pm@ with their context would be helpful.

[aereaux]

Thanks for the quick response! Is there anything I can do to trim down the logs to just the relevant parts?

[aereaux]

A bit of previous content that might be helpful:

12-15 18:59:30.612 19965 19965 D ConnectBot.BackupAgent: onCreate called
12-15 18:59:30.620  1480 17494 D BackupManagerService: [UserID:0] agentConnected pkg=org.sufficientlysecure.termbot agent=android.os.BinderProxy@1a948f1
12-15 18:59:30.620  1480 19657 I BackupManagerService: [UserID:0] got agent android.app.IBackupAgent$Stub$Proxy@4b3acd6
12-15 18:59:30.620  1480 19657 D KeyValueBackupTask: Invoking agent on org.sufficientlysecure.termbot
12-15 18:59:30.623 13691 13838 I BackupCoordinator: Get backup quota for org.sufficientlysecure.termbot. Is full backup: false.
12-15 18:59:30.623 13691 13838 I BackupCoordinator: Reported quota of 1073741824 bytes.
12-15 18:59:30.624 19965 19986 D BackupHelperDispatcher: handling existing helper 'hosts' android.app.backup.FileBackupHelper@9dc58dd
12-15 18:59:30.626 19965 19986 D BackupHelperDispatcher: handling existing helper 'prefs' android.app.backup.SharedPreferencesBackupHelper@dd35c52
12-15 18:59:30.628 13691 13838 D com.stevesoltys.seedvault.BackupMonitor: org.sufficientlysecure.termbot                                   cat: 2 id: 52
12-15 18:59:30.628 13691 13838 D com.stevesoltys.seedvault.BackupMonitor: org.sufficientlysecure.termbot                                   cat: 3 id: 7
12-15 18:59:30.628  1480 19657 V BackupManagerConstants: getBackupFinishedNotificationReceivers(...) returns 
12-15 18:59:30.628 13691 17233 I NotificationBackupObserver: Completed. Target: org.sufficientlysecure.termbot, status: 0
12-15 18:59:30.629 13691 13838 I c.s.s.t.b.BackupTransportMonitor: [binder:13691_5      ] sendNoDataChanged(org.sufficientlysecure.termbot)
12-15 18:59:30.629 13691 13838 E c.s.s.t.b.BackupTransportMonitor: [binder:13691_5      ] No latest snapshot!
12-15 18:59:30.629 13691 17233 I NotificationBackupObserver: Showing progress notification for org.isoron.uhabits 216/247
12-15 18:59:30.629 13691 17233 I NotificationBackupObserver: 216/247 - TermBot (org.sufficientlysecure.termbot)
12-15 18:59:30.630  1480 19657 V KVBT    : Skipping package which was backed up this time: @pm@
12-15 18:59:30.633 13691 13838 I KVBackup: No K/V backup data has changed for android
12-15 18:59:30.635 13691 13838 I KVBackup: Finish K/V Backup of android
12-15 18:59:30.654 13691 13838 D MemoryLogger: 37 MiB free - 85 of 122 (max 256)

12-15 18:59:23.204 13691 13921 I BackupRequester: Requesting backup for 247 of 247 packages...
12-15 18:59:23.206 13691 13921 I BackupRequester: [a bunch of packages]
12-15 18:59:23.211 13691 13691 I BackupStateManager: appBackupRunning: false, filesBackupRunning: false, appBackupWorker: ENQUEUED
12-15 18:59:23.217  1480  1647 E HintManagerService: ADPF IS GETTING RESUMED? UID: 10037 TAG: 2
12-15 18:59:23.217   762   762 W powerhal-libperfmgr: Sess(11785), cannot resume, already active
12-15 18:59:23.217 13691 13691 D ConfigurableBackupTransportService: Service destroyed.
12-15 18:59:23.220 13691 13691 I BackupStateManager: appBackupRunning: true, filesBackupRunning: false, appBackupWorker: ENQUEUED
12-15 18:59:23.220 13691 13691 D ConfigurableBackupTransportService: Service created.
12-15 18:59:23.224 13691 13691 D ConfigurableBackupTransportService: Transport bound.
12-15 18:59:23.226  1480  1480 I TransportConnection: ConfigurableBackupTransportService#24: Notifying [BMS.getBackupDestinationFromTransport] transport = BackupTransportClient
12-15 18:59:23.233 13691 13921 I BackupRequester: Backup request succeeded
12-15 18:59:23.233 13691 13921 I NotificationBackupObserver: Completed. Target: com.google.pixel.camera.services, status: -2001
12-15 18:59:23.233 13691 13921 I NotificationBackupObserver: Showing progress notification for com.google.euiccpixel.permissions 201/247
12-15 18:59:23.233 13691 13921 I NotificationBackupObserver: 201/247 - com.google.pixel.camera.services.PersistentApplication (com.google.pixel.camera.services)
12-15 18:59:23.234  1480  4492 V BackupManagerService: [UserID:0] Acquired wakelock:*backup*-0-4492
12-15 18:59:23.234 13691 13691 W Seedvault: onTrimMemory(20) 45 MiB free - 77 of 122 (max 256)
12-15 18:59:23.235 13691 13691 W Seedvault:   lastTrimLevel: 0
12-15 18:59:23.235 13691 13691 W Seedvault:   importance: 200
12-15 18:59:23.235  1480  4492 D KeyValueBackupTask: Spinning thread key-value-backup-21
12-15 18:59:23.236 13691 13921 I NotificationBackupObserver: Completed. Target: com.google.pixel.iwlan, status: -2001
12-15 18:59:23.236 13691 13921 I NotificationBackupObserver: Showing progress notification for com.google.pixel.camera.services 202/247
12-15 18:59:23.236 13691 13921 I NotificationBackupObserver: 202/247 - com.google.pixel.iwlan (com.google.pixel.iwlan)
12-15 18:59:23.238 13691 13921 I NotificationBackupObserver: Completed. Target: com.samsung.slsi.telephony.oem.oemrilhookservice, status: -2001
12-15 18:59:23.238 13691 13921 I NotificationBackupObserver: Showing progress notification for com.google.pixel.iwlan 203/247
12-15 18:59:23.239 13691 15500 D com.stevesoltys.seedvault.BackupMonitor: com.motorolasolutions.talkabout                                  cat: 3 id: 11
12-15 18:59:23.240 13691 17233 D com.stevesoltys.seedvault.BackupMonitor: com.seeclickfix.ma.android                                       cat: 3 id: 11
12-15 18:59:23.241  1480 19657 D PFTBT   : backupmanager pftbt token=311e64bf
12-15 18:59:23.241  1480 19657 V KeyValueBackupTask: Beginning backup of 7 targets
12-15 18:59:23.243  1480 19657 D KeyValueBackupTask: Starting key-value backup of @pm@
12-15 18:59:23.244 13691 13921 I NotificationBackupObserver: 203/247 - RadioConfigService (com.samsung.slsi.telephony.oem.oemrilhookservice)
12-15 18:59:23.247 13691 13921 I NotificationBackupObserver: Completed. Target: com.samsung.slsi.telephony.oemril, status: -2001
12-15 18:59:23.247 13691 13921 I NotificationBackupObserver: Showing progress notification for com.samsung.slsi.telephony.oem.oemrilhookservice 204/247
12-15 18:59:23.247 13691 13921 I NotificationBackupObserver: 204/247 - com.samsung.slsi.telephony.oemril.OemRilApp (com.samsung.slsi.telephony.oemril)
12-15 18:59:23.250 13691 13921 I NotificationBackupObserver: Completed. Target: com.shannon.imsservice, status: -2001
12-15 18:59:23.250 13691 13921 I NotificationBackupObserver: Showing progress notification for com.samsung.slsi.telephony.oemril 205/247
12-15 18:59:23.257  1480 19657 D KeyValueBackupTask: Invoking agent on @pm@
12-15 18:59:23.258 13691 13921 I NotificationBackupObserver: 205/247 - ImsService (com.shannon.imsservice)
12-15 18:59:23.260 13691 17233 I BackupCoordinator: Get backup quota for @pm@. Is full backup: false.
12-15 18:59:23.260 13691 17233 I BackupCoordinator: Reported quota of 1073741824 bytes.
12-15 18:59:23.261  1480  3009 E NotificationService: Package enqueue rate is 6.733768. Shedding 0|com.stevesoltys.seedvault|1|null|10037. package=com.stevesoltys.seedvault
12-15 18:59:23.262 13691 17233 I NotificationBackupObserver: Completed. Target: com.shannon.qualifiednetworksservice, status: -2001
12-15 18:59:23.262 13691 17233 I NotificationBackupObserver: Showing progress notification for com.shannon.imsservice 206/247
12-15 18:59:23.269 13691 17233 I NotificationBackupObserver: 206/247 - QualifiedNetworksService (com.shannon.qualifiednetworksservice)
12-15 18:59:23.271 13691 13921 D com.stevesoltys.seedvault.BackupMonitor: @pm@                                                             cat: 3 id: 7
12-15 18:59:23.271  1480 19657 D KeyValueBackupTask: Starting key-value backup of com.motivateco.gobike
12-15 18:59:23.272  1480 19657 V GrammaticalInflectionUtils: AttributionSource: android.content.AttributionSource@de880123 does not have READ_SYSTEM_GRAMMATICAL_GENDER permission.
12-15 18:59:23.272  1480 19657 D CompatChangeReporter: Compat change id reported: 151861875; UID 10231; state: ENABLED
12-15 18:59:23.273 13691 17233 I NotificationBackupObserver: Completed. Target: com.shannon.rcsservice, status: -2001
12-15 18:59:23.273 13691 17233 I NotificationBackupObserver: Showing progress notification for com.shannon.qualifiednetworksservice 207/247
12-15 18:59:23.274  1480 19657 D BackupManagerService: [UserID:0] awaiting agent for ApplicationInfo{9bc6082 com.motivateco.gobike}
12-15 18:59:23.275   931   931 W zygote64: Waiting for a thread to finish unregistering
12-15 18:59:23.277 13691 13921 I c.s.s.t.b.BackupTransportMonitor: [binder:13691_9      ] sendNoDataChanged(@pm@)
12-15 18:59:23.277 13691 13921 E c.s.s.t.b.BackupTransportMonitor: [binder:13691_9      ] No latest snapshot!
12-15 18:59:23.278  1480  3200 I ActivityManager: Process com.google.euiccpixel.permissions (pid 19628) has died: bkup TRNB
12-15 18:59:23.279  1480  1648 D DisplayManagerService: Drop pending events for gone uid 10099
12-15 18:59:23.282  1480  1667 I libprocessgroup: Removed cgroup /sys/fs/cgroup/uid_10099/pid_19628
12-15 18:59:23.288 13691 17233 I NotificationBackupObserver: 207/247 - RcsService (com.shannon.rcsservice)
12-15 18:59:23.291 13691 17233 I NotificationBackupObserver: Completed. Target: org.chromium.chrome, status: -2001
12-15 18:59:23.295 13691 17233 I NotificationBackupObserver: Showing progress notification for com.shannon.rcsservice 208/247
12-15 18:59:23.302   931   931 D Zygote  : Forked child process 19660
12-15 18:59:23.304   931   931 I Zygote  : Process 19628 exited due to signal 9 (Killed)
12-15 18:59:23.306  1480  1666 I ActivityManager: Start proc 19660:com.motivateco.gobike/u0a231 for backup {com.motivateco.gobike/com.lyft.android.accountsecurity.backup.LyftBackupAgent}
12-15 18:59:23.322 19660 19660 I tivateco.gobike: Using CollectorTypeCMC GC.
12-15 18:59:23.327 19660 19660 E tivateco.gobike: Not starting debugger since process cannot load the jdwp agent.
12-15 18:59:23.368 13691 17233 I NotificationBackupObserver: 208/247 - Vanadium (org.chromium.chrome)
12-15 18:59:23.371 13691 17233 I NotificationBackupObserver: Completed. Target: com.motorolasolutions.talkabout, status: -2001
12-15 18:59:23.371 13691 17233 I NotificationBackupObserver: Showing progress notification for org.chromium.chrome 209/247
12-15 18:59:23.372 13691 17233 I NotificationBackupObserver: 209/247 - Talkabout (com.motorolasolutions.talkabout)
12-15 18:59:23.375 13691 17233 I NotificationBackupObserver: Completed. Target: com.seeclickfix.ma.android, status: -2001
12-15 18:59:23.375 13691 17233 I NotificationBackupObserver: Showing progress notification for com.motorolasolutions.talkabout 210/247
12-15 18:59:23.375 13691 17233 I NotificationBackupObserver: 210/247 - SeeClickFix (com.seeclickfix.ma.android)
12-15 18:59:23.378 13691 17233 I NotificationBackupObserver: Completed. Target: @pm@, status: 0
12-15 18:59:23.378 13691 17233 I NotificationBackupObserver: Showing progress notification for com.seeclickfix.ma.android 210/247
12-15 18:59:23.378 13691 17233 I NotificationBackupObserver: 210/247 - System package manager (@pm@)

[grote]

Thanks, that's helpful already, filtering it to the relevant parts:

12-15 18:59:30.630  1480 19657 V KVBT    : Skipping package which was backed up this time: @pm@
12-15 18:59:23.243  1480 19657 D KeyValueBackupTask: Starting key-value backup of @pm@
12-15 18:59:23.257  1480 19657 D KeyValueBackupTask: Invoking agent on @pm@
12-15 18:59:23.260 13691 17233 I BackupCoordinator: Get backup quota for @pm@. Is full backup: false.
12-15 18:59:23.260 13691 17233 I BackupCoordinator: Reported quota of 1073741824 bytes.
12-15 18:59:23.271 13691 13921 D com.stevesoltys.seedvault.BackupMonitor: @pm@                                                             cat: 3 id: 7
12-15 18:59:23.277 13691 13921 I c.s.s.t.b.BackupTransportMonitor: [binder:13691_9      ] sendNoDataChanged(@pm@)
12-15 18:59:23.277 13691 13921 E c.s.s.t.b.BackupTransportMonitor: [binder:13691_9      ] No latest snapshot!
12-15 18:59:23.378 13691 17233 I NotificationBackupObserver: Completed. Target: @pm@, status: 0
12-15 18:59:23.378 13691 17233 I NotificationBackupObserver: 210/247 - System package manager (@pm@)
12-15 19:02:32.865 13691 13957 E c.s.s.r.AppBackupManager: [binder:13691_C      ] Error finishing backupjava.lang.IllegalStateException: No metadata for @pm@

So this means that (in the new location) Seedvault doesn't find a previous snapshot, but the system thinks that @pm@ backup data hasn't changed, so it doesn't give it to us.

When changing the backup location, we should have asked to re-initialize the backup, so the system shouldn't think no data has changed. We obviously need to fix this and thanks to your report we can.

However, in the meantime, you should be able to work around this issue by disabling app backup and then re-enabling it again. Please let me know if this fixes things.

[aereaux]

Great, yeah that seems to fix it!