seedvault
seedvault copied to clipboard
Published
20 hours ago •
seedvault-app
seedvault-app
MetadataManager.getMetadata() throws AssertionError after storage full
trafficstars
While investigating why SeedVault had not run a backup since 12-12-2020 on GrapheneOS where this is implemented as the OS backup solution I found that the backup page shows a black screen and not the seed vault settings.
Device: Pixel 3a XL GrapheneOS Build: RQ1A.210205.004.2021.02.19.15 With what I assume is the latest release of SeedVault.
ADB Logcat when navigating to GrapheneOS' backup screen (a full log taken here: Logcat_seedvault_error.log):
02-23 16:22:12.738 8292 8292 E AndroidRuntime: Process: com.stevesoltys.seedvault, PID: 8292
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:43)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getBackupToken(MetadataManager.kt:195)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.App.migrateTokenFromMetadataToSettingsManager(App.kt:102)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.App.access$migrateTokenFromMetadataToSettingsManager(App.kt:37)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:87)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:37)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.AppKt.permitDiskReads(App.kt:131)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.App.onCreate(App.kt:86)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:40)
02-23 16:22:12.779 1006 4808 I ActivityManager: Process com.stevesoltys.seedvault (pid 8292) has died: fg IMPF
02-23 16:22:12.780 1006 4808 W ActivityManager: Scheduling restart of crashed service com.stevesoltys.seedvault/.transport.ConfigurableBackupTransportService in 1024000ms for connection
02-23 16:22:53.439 1006 1513 E BackupManagerService: [UserID:0] Unable to get management intent from transport: Transport com.stevesoltys.seedvault.transport.ConfigurableBackupTransport not registered
02-23 16:23:38.515 1006 4931 E BackupManagerService: [UserID:0] Unable to get management intent from transport: Transport com.stevesoltys.seedvault.transport.ConfigurableBackupTransport not registered
A separate crash monitored here:
--------- beginning of crash
02-23 16:16:24.849 3857 3857 E AndroidRuntime: FATAL EXCEPTION: main
02-23 16:16:24.849 3857 3857 E AndroidRuntime: Process: com.stevesoltys.seedvault, PID: 3857
02-23 16:16:24.849 3857 3857 E AndroidRuntime: java.lang.AssertionError: Error reading metadata from cache
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:43)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getBackupToken(MetadataManager.kt:195)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.App.migrateTokenFromMetadataToSettingsManager(App.kt:102)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.App.access$migrateTokenFromMetadataToSettingsManager(App.kt:37)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:87)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:37)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.AppKt.permitDiskReads(App.kt:131)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.App.onCreate(App.kt:86)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1192)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6715)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at android.app.ActivityThread.access$1300(ActivityThread.java:237)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1913)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at android.os.Handler.dispatchMessage(Handler.java:106)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at android.os.Looper.loop(Looper.java:223)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at android.app.ActivityThread.main(ActivityThread.java:7660)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at java.lang.reflect.Method.invoke(Native Method)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.android.internal.os.ExecInit.main(ExecInit.java:48)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.android.internal.os.RuntimeInit.nativeFinishInit(Native Method)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.android.internal.os.RuntimeInit.main(RuntimeInit.java:399)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: Caused by: java.io.IOException
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:40)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: ... 19 more
02-23 16:16:24.850 3857 3857 E AndroidRuntime: Error reporting crash
02-23 16:16:24.850 3857 3857 E AndroidRuntime: java.lang.RuntimeException: Bad file descriptor
02-23 16:16:24.850 3857 3857 E AndroidRuntime: at android.os.BinderProxy.transactNative(Native Method)
02-23 16:16:24.850 3857 3857 E AndroidRuntime: at android.os.BinderProxy.transact(BinderProxy.java:550)
02-23 16:16:24.850 3857 3857 E AndroidRuntime: at android.app.IActivityManager$Stub$Proxy.handleApplicationCrash(IActivityManager.java:5208)
02-23 16:16:24.850 3857 3857 E AndroidRuntime: at com.android.internal.os.RuntimeInit$KillApplicationHandler.uncaughtException(RuntimeInit.java:158)
02-23 16:16:24.850 3857 3857 E AndroidRuntime: at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:1073)
02-23 16:16:24.850 3857 3857 E AndroidRuntime: at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:1068)
02-23 16:16:24.850 3857 3857 E AndroidRuntime: at java.lang.Thread.dispatchUncaughtException(Thread.java:2203)
02-23 16:16:24.900 1006 3749 I ActivityManager: Process com.stevesoltys.seedvault (pid 3857) has died: fg IMPF
02-23 16:16:24.901 1006 3749 W ActivityManager: Scheduling restart of crashed service com.stevesoltys.seedvault/.transport.ConfigurableBackupTransportService in 1000ms for connection
Thanks a lot for filing this issue! For some reason your device violates an assertion we made here:
This is essentially doing Context#openFileInput() which should not throw. But there could be an error when parsing the metadata.
Unfortunately, your log only contains indirect stack traces from the AndroidRuntime, but no logs from Seedvault itself. Could you please check if you find something else? It should have the tag MetadataManager. It could be though that this is a release build that doesn't do any logging.
@grote, I just tried running adp logcat | grep seedvault and found something that has MetadataManager:
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:43)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getBackupToken(MetadataManager.kt:195)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.App.migrateTokenFromMetadataToSettingsManager(App.kt:102)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.App.access$migrateTokenFromMetadataToSettingsManager(App.kt:37)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:87)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:37)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.AppKt.permitDiskReads(App.kt:131)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.App.onCreate(App.kt:86)
02-23 16:16:24.849 3857 3857 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:40)
02-23 16:16:27.409 4165 4165 E AndroidRuntime: Process: com.stevesoltys.seedvault, PID: 4165
02-23 16:16:27.409 4165 4165 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:43)
02-23 16:16:27.409 4165 4165 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getBackupToken(MetadataManager.kt:195)
02-23 16:16:27.409 4165 4165 E AndroidRuntime: at com.stevesoltys.seedvault.App.migrateTokenFromMetadataToSettingsManager(App.kt:102)
02-23 16:16:27.409 4165 4165 E AndroidRuntime: at com.stevesoltys.seedvault.App.access$migrateTokenFromMetadataToSettingsManager(App.kt:37)
02-23 16:16:27.409 4165 4165 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:87)
02-23 16:16:27.409 4165 4165 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:37)
02-23 16:16:27.409 4165 4165 E AndroidRuntime: at com.stevesoltys.seedvault.AppKt.permitDiskReads(App.kt:131)
02-23 16:16:27.409 4165 4165 E AndroidRuntime: at com.stevesoltys.seedvault.App.onCreate(App.kt:86)
02-23 16:16:27.409 4165 4165 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:40)
02-23 16:16:32.785 4543 4543 E AndroidRuntime: Process: com.stevesoltys.seedvault, PID: 4543
02-23 16:16:32.785 4543 4543 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:43)
02-23 16:16:32.785 4543 4543 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getBackupToken(MetadataManager.kt:195)
02-23 16:16:32.785 4543 4543 E AndroidRuntime: at com.stevesoltys.seedvault.App.migrateTokenFromMetadataToSettingsManager(App.kt:102)
02-23 16:16:32.785 4543 4543 E AndroidRuntime: at com.stevesoltys.seedvault.App.access$migrateTokenFromMetadataToSettingsManager(App.kt:37)
02-23 16:16:32.785 4543 4543 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:87)
02-23 16:16:32.785 4543 4543 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:37)
02-23 16:16:32.785 4543 4543 E AndroidRuntime: at com.stevesoltys.seedvault.AppKt.permitDiskReads(App.kt:131)
02-23 16:16:32.785 4543 4543 E AndroidRuntime: at com.stevesoltys.seedvault.App.onCreate(App.kt:86)
02-23 16:16:32.785 4543 4543 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:40)
02-23 16:16:49.881 5153 5153 E AndroidRuntime: Process: com.stevesoltys.seedvault, PID: 5153
02-23 16:16:49.881 5153 5153 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:43)
02-23 16:16:49.881 5153 5153 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getBackupToken(MetadataManager.kt:195)
02-23 16:16:49.881 5153 5153 E AndroidRuntime: at com.stevesoltys.seedvault.App.migrateTokenFromMetadataToSettingsManager(App.kt:102)
02-23 16:16:49.881 5153 5153 E AndroidRuntime: at com.stevesoltys.seedvault.App.access$migrateTokenFromMetadataToSettingsManager(App.kt:37)
02-23 16:16:49.881 5153 5153 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:87)
02-23 16:16:49.881 5153 5153 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:37)
02-23 16:16:49.881 5153 5153 E AndroidRuntime: at com.stevesoltys.seedvault.AppKt.permitDiskReads(App.kt:131)
02-23 16:16:49.881 5153 5153 E AndroidRuntime: at com.stevesoltys.seedvault.App.onCreate(App.kt:86)
02-23 16:16:49.881 5153 5153 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:40)
02-23 16:17:54.894 7038 7038 E AndroidRuntime: Process: com.stevesoltys.seedvault, PID: 7038
02-23 16:17:54.894 7038 7038 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:43)
02-23 16:17:54.894 7038 7038 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getBackupToken(MetadataManager.kt:195)
02-23 16:17:54.894 7038 7038 E AndroidRuntime: at com.stevesoltys.seedvault.App.migrateTokenFromMetadataToSettingsManager(App.kt:102)
02-23 16:17:54.894 7038 7038 E AndroidRuntime: at com.stevesoltys.seedvault.App.access$migrateTokenFromMetadataToSettingsManager(App.kt:37)
02-23 16:17:54.894 7038 7038 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:87)
02-23 16:17:54.894 7038 7038 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:37)
02-23 16:17:54.894 7038 7038 E AndroidRuntime: at com.stevesoltys.seedvault.AppKt.permitDiskReads(App.kt:131)
02-23 16:17:54.894 7038 7038 E AndroidRuntime: at com.stevesoltys.seedvault.App.onCreate(App.kt:86)
02-23 16:17:54.894 7038 7038 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:40)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: Process: com.stevesoltys.seedvault, PID: 8292
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:43)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getBackupToken(MetadataManager.kt:195)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.App.migrateTokenFromMetadataToSettingsManager(App.kt:102)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.App.access$migrateTokenFromMetadataToSettingsManager(App.kt:37)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:87)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:37)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.AppKt.permitDiskReads(App.kt:131)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.App.onCreate(App.kt:86)
02-23 16:22:12.738 8292 8292 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:40)
02-23 16:39:17.738 9775 9775 E AndroidRuntime: Process: com.stevesoltys.seedvault, PID: 9775
02-23 16:39:17.738 9775 9775 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:43)
02-23 16:39:17.738 9775 9775 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getBackupToken(MetadataManager.kt:195)
02-23 16:39:17.738 9775 9775 E AndroidRuntime: at com.stevesoltys.seedvault.App.migrateTokenFromMetadataToSettingsManager(App.kt:102)
02-23 16:39:17.738 9775 9775 E AndroidRuntime: at com.stevesoltys.seedvault.App.access$migrateTokenFromMetadataToSettingsManager(App.kt:37)
02-23 16:39:17.738 9775 9775 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:87)
02-23 16:39:17.738 9775 9775 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:37)
02-23 16:39:17.738 9775 9775 E AndroidRuntime: at com.stevesoltys.seedvault.AppKt.permitDiskReads(App.kt:131)
02-23 16:39:17.738 9775 9775 E AndroidRuntime: at com.stevesoltys.seedvault.App.onCreate(App.kt:86)
02-23 16:39:17.738 9775 9775 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:40)
02-23 17:47:34.861 13694 13694 E AndroidRuntime: Process: com.stevesoltys.seedvault, PID: 13694
02-23 17:47:34.861 13694 13694 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:43)
02-23 17:47:34.861 13694 13694 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getBackupToken(MetadataManager.kt:195)
02-23 17:47:34.861 13694 13694 E AndroidRuntime: at com.stevesoltys.seedvault.App.migrateTokenFromMetadataToSettingsManager(App.kt:102)
02-23 17:47:34.861 13694 13694 E AndroidRuntime: at com.stevesoltys.seedvault.App.access$migrateTokenFromMetadataToSettingsManager(App.kt:37)
02-23 17:47:34.861 13694 13694 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:87)
02-23 17:47:34.861 13694 13694 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:37)
02-23 17:47:34.861 13694 13694 E AndroidRuntime: at com.stevesoltys.seedvault.AppKt.permitDiskReads(App.kt:131)
02-23 17:47:34.861 13694 13694 E AndroidRuntime: at com.stevesoltys.seedvault.App.onCreate(App.kt:86)
02-23 17:47:34.861 13694 13694 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:40)
02-24 02:32:05.589 24087 24087 E AndroidRuntime: Process: com.stevesoltys.seedvault, PID: 24087
02-24 02:32:05.589 24087 24087 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:43)
02-24 02:32:05.589 24087 24087 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getBackupToken(MetadataManager.kt:195)
02-24 02:32:05.589 24087 24087 E AndroidRuntime: at com.stevesoltys.seedvault.App.migrateTokenFromMetadataToSettingsManager(App.kt:102)
02-24 02:32:05.589 24087 24087 E AndroidRuntime: at com.stevesoltys.seedvault.App.access$migrateTokenFromMetadataToSettingsManager(App.kt:37)
02-24 02:32:05.589 24087 24087 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:87)
02-24 02:32:05.589 24087 24087 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$2.invoke(App.kt:37)
02-24 02:32:05.589 24087 24087 E AndroidRuntime: at com.stevesoltys.seedvault.AppKt.permitDiskReads(App.kt:131)
02-24 02:32:05.589 24087 24087 E AndroidRuntime: at com.stevesoltys.seedvault.App.onCreate(App.kt:86)
02-24 02:32:05.589 24087 24087 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:40)```
Maybe that helps?
No, this is all coming from the tag AndroidRuntime.
Maybe
adb logcat -b all -v color --pid=`adb shell pidof -s com.stevesoltys.seedvault`
brings up something? (only works when seedvault is already running)
Running that shows really nothing in the logs: `➜ ~ adb logcat -s MetadataManager -b all -v color
--------- beginning of crash
--------- beginning of radio
--------- beginning of system
--------- beginning of events
--------- beginning of main`
Well, if there's no way to get more info here, a workaround to get this to work again is to clear all app data of Seedvault in system app settings. You will get a new recovery code and then should be able to run backups again.
@grote Clearing app settings and restarting my phone now allows me to do the new recovery code process. Not sure what happened but I guess at least I can continue with backups this way.
@grote Backup worked after clearing but again stopped after installing GrapheneOS' latest OTA and I assume after restarting the phone. GrapheneOS does not believe this is anything to do with the OS as they just minimally add SeedVault and do not modify it.
The issue must be with my device after installing an OS update and SeedVault starting up or something along those lines.
It was suggested that maybe a restart in general causes the issue on my device so I tried clearing app settings, recreating the recovery code, doing a backup, and then restarting the phone but this does not cause an issue.
On next GrapheneOS OTA I will try to log out when restarting.
when you can roughly pinpoint when the issue starts to happen, it would be great if you could capture logs from that moment, so we can figure out what's going on.
@grote I beleive I found out the case in which this issue occurs but I was not able to capture logs of it happeneing.
I think the app crashes and cannot recover when it tries to backup but runs out of space on system storage. I believe this is the issue because my phone ran out of space after a separate backup task and I noticed other apps complaining about not working properly. I checked SeedVault backup and again the app would not load.
Thanks for keeping an eye on this @BradNut! The app should never crash, but it might. Would be great to get a logcat for the crash.
But a task for us can be to artificially create an out-of-space situation and then do a backup. I imagine that the metadata can get corrupted, if it writes a few bytes, but can't write all it needs to.
Where did you set the storage location of your backups to?
I'm setting the storage location to the device itself. So I think it backs up to /storage/emulated/0/.SeedVaultAndroidBackup.
I can also try to create another out of space issue on purpose and then manually backup to try and reproduce the issue with logcat. I'll comment back on my attempt.
Still trying to get a log of this happening as I would need to purposefully fill up my phone's space and have not had time to do so. However, it is worth noting that when this issue occurs and you have to reset the whole backup I still see old backups persisting on the phone which never get cleaned up.
If somebody can try to almost fill their storage, then start capturing logs, then run a backup and then reproduce the issue with sharing logs afterwards, this would be helpful. It just happened to someone else: #351
I've run into this I think. On a Fairphone 2, running LineageOS 18.1-20230920-NIGHTLY-FP2. De-googled, so no play services. Magisk installed.
Got errors in a pop-up dialog on starting phone, along the lines of "Seedvault Backup keeps stopping"
Checked logcat for mentions of seed, found this:
2$ grep seed tmp 09-25 09:10:19.592 1997 3312 V BackupManagerService: [UserID:0] Starting with transport com.stevesoltys.seedvault.transport.ConfigurableBackupTransport 09-25 09:10:26.544 1997 2233 I ActivityManager: Start proc 6632:com.stevesoltys.seedvault/u0a88 for service {com.stevesoltys.seedvault/com.stevesoltys.seedvault.transport.ConfigurableBackupTransportService} 09-25 09:10:27.961 6632 6632 E AndroidRuntime: Process: com.stevesoltys.seedvault, PID: 6632 09-25 09:10:27.961 6632 6632 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:43) 09-25 09:10:27.961 6632 6632 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getBackupToken(MetadataManager.kt:195) 09-25 09:10:27.961 6632 6632 E AndroidRuntime: at com.stevesoltys.seedvault.App.migrateTokenFromMetadataToSettingsManager(App.kt:108) 09-25 09:10:27.961 6632 6632 E AndroidRuntime: at com.stevesoltys.seedvault.App.access$migrateTokenFromMetadataToSettingsManager(App.kt:39) 09-25 09:10:27.961 6632 6632 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$1.invoke(App.kt:75) 09-25 09:10:27.961 6632 6632 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$1.invoke(App.kt:39) 09-25 09:10:27.961 6632 6632 E AndroidRuntime: at com.stevesoltys.seedvault.AppKt.permitDiskReads(App.kt:136) 09-25 09:10:27.961 6632 6632 E AndroidRuntime: at com.stevesoltys.seedvault.App.onCreate(App.kt:74) 09-25 09:10:27.961 6632 6632 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:40) 09-25 09:10:28.031 1997 5683 I ActivityManager: Process com.stevesoltys.seedvault (pid 6632) has died: fg IMPF 09-25 09:10:28.032 1997 5683 W ActivityManager: Scheduling restart of crashed service com.stevesoltys.seedvault/.transport.ConfigurableBackupTransportService in 1000ms for connection 09-25 09:10:29.147 1997 2233 I ActivityManager: Start proc 7005:com.stevesoltys.seedvault/u0a88 for service {com.stevesoltys.seedvault/com.stevesoltys.seedvault.transport.ConfigurableBackupTransportService} 09-25 09:10:29.320 7005 7005 E AndroidRuntime: Process: com.stevesoltys.seedvault, PID: 7005 09-25 09:10:29.320 7005 7005 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:43) 09-25 09:10:29.320 7005 7005 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getBackupToken(MetadataManager.kt:195) 09-25 09:10:29.320 7005 7005 E AndroidRuntime: at com.stevesoltys.seedvault.App.migrateTokenFromMetadataToSettingsManager(App.kt:108) 09-25 09:10:29.320 7005 7005 E AndroidRuntime: at com.stevesoltys.seedvault.App.access$migrateTokenFromMetadataToSettingsManager(App.kt:39) 09-25 09:10:29.320 7005 7005 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$1.invoke(App.kt:75) 09-25 09:10:29.320 7005 7005 E AndroidRuntime: at com.stevesoltys.seedvault.App$onCreate$1.invoke(App.kt:39) 09-25 09:10:29.320 7005 7005 E AndroidRuntime: at com.stevesoltys.seedvault.AppKt.permitDiskReads(App.kt:136) 09-25 09:10:29.320 7005 7005 E AndroidRuntime: at com.stevesoltys.seedvault.App.onCreate(App.kt:74) 09-25 09:10:29.320 7005 7005 E AndroidRuntime: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:40) 09-25 09:11:30.125 1997 5637 I ActivityManager: Killing 7005:com.stevesoltys.seedvault/u0a88 (adj 0): crash 09-25 09:11:30.199 1997 5591 E BackupTransportManager: Couldn't connect to transport com.stevesoltys.seedvault/.transport.ConfigurableBackupTransportService for registration
Searched the web, found only this one issue, then subsequently the current issue searching for "getMetadata" in the seedvault open issues.
Tried the workaround above: clear seedvault's cache and data in the app's settings, then restart, and re-enable seedvault backups. (Set this to use the external SDCard, I'd used Nextcloud but it has seemed problematic in the past.) Got a new recovery key. Started a backup.
This completed successfully (although checking the status it seems like various apps have the "Backup quota exceeded" status, e.g. FDroid, Wallabag). Local contacts "Waiting to back up...". What's App: just a red exclamation mark.
Output from the logcat command suggested above, whilst backup running, got:
$ adb logcat -s MetadataManager -b all -v color
--------- beginning of kernel
--------- beginning of events
--------- beginning of system
--------- beginning of radio
--------- beginning of crash
--------- beginning of main
09-25 09:36:58.570 13020 13036 D MetadataManager: Cached metadata not found, creating...
Nothing more. Grepping logcat for seedv gets:
09-25 09:43:48.561 2002 2002 D NotificationService: 0|com.stevesoltys.seedvault|1|null|10088: granting content://settings/system/notification_sound
09-25 09:45:00.805 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 14455(2159KB) AllocSpace objects, 102(6936KB) LOS objects, 49% free, 6534KB/12MB, paused 102us total 131.332ms
09-25 09:45:09.678 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 11920(1798KB) AllocSpace objects, 88(5984KB) LOS objects, 49% free, 6770KB/13MB, paused 111us total 111.215ms
09-25 09:45:19.028 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 17577(2150KB) AllocSpace objects, 90(6120KB) LOS objects, 49% free, 7169KB/14MB, paused 123us total 131.763ms
09-25 09:45:26.222 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 38387(2651KB) AllocSpace objects, 120(6456KB) LOS objects, 49% free, 7118KB/13MB, paused 571us total 155.838ms
09-25 09:45:31.877 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 52215(3069KB) AllocSpace objects, 113(5412KB) LOS objects, 49% free, 7252KB/14MB, paused 78us total 158.841ms
09-25 09:45:32.637 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 21077(2315KB) AllocSpace objects, 98(6664KB) LOS objects, 49% free, 7104KB/13MB, paused 145us total 100.540ms
09-25 09:45:39.556 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 44895(2839KB) AllocSpace objects, 115(5936KB) LOS objects, 49% free, 7282KB/14MB, paused 83us total 177.791ms
09-25 09:45:42.232 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 13543(1991KB) AllocSpace objects, 94(6392KB) LOS objects, 49% free, 7324KB/14MB, paused 99us total 117.112ms
09-25 09:45:50.199 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 13900(2009KB) AllocSpace objects, 97(6596KB) LOS objects, 49% free, 6773KB/13MB, paused 76us total 112.534ms
09-25 09:45:51.830 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 13368(1951KB) AllocSpace objects, 93(6324KB) LOS objects, 49% free, 7063KB/13MB, paused 89us total 103.714ms
09-25 09:45:54.376 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 17339(1911KB) AllocSpace objects, 90(5552KB) LOS objects, 51% free, 5888KB/11MB, paused 76us total 129.533ms
09-25 09:46:10.076 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 64843(2841KB) AllocSpace objects, 93(3044KB) LOS objects, 49% free, 6591KB/12MB, paused 77us total 109.414ms
09-25 09:46:15.061 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 25268(2122KB) AllocSpace objects, 80(5440KB) LOS objects, 49% free, 6261KB/12MB, paused 92us total 103.194ms
09-25 09:46:16.904 13020 13032 I oltys.seedvaul: Background young concurrent copying GC freed 24460(1815KB) AllocSpace objects, 79(4236KB) LOS objects, 45% free, 6874KB/12MB, paused 97us total 110.240ms
09-25 09:46:23.620 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 51709(2828KB) AllocSpace objects, 95(4188KB) LOS objects, 49% free, 7362KB/14MB, paused 125us total 117.409ms
09-25 09:46:36.103 13020 13032 I oltys.seedvaul: Background young concurrent copying GC freed 62050(2889KB) AllocSpace objects, 49(2068KB) LOS objects, 40% free, 7273KB/11MB, paused 80us total 101.705ms
09-25 09:46:38.605 13020 13032 I oltys.seedvaul: Background concurrent copying GC freed 51758(2654KB) AllocSpace objects, 76(4192KB) LOS objects, 49% free, 6987KB/13MB, paused 151us total 119.159ms
Grepping logcat for Metadata finds nothing.
Storage space is not full:
$ adb shell df -h
Filesystem Size Used Avail Use% Mounted on
tmpfs 924M 1.1M 923M 1% /dev
tmpfs 924M 0 924M 0% /mnt
/dev/block/mmcblk0p13 1.9G 1.4G 580M 72% /
magisk 924M 2.8M 921M 1% /debug_ramdisk
tmpfs 924M 0 924M 0% /apex
/dev/block/mmcblk0p20 26G 21G 4.4G 83% /data
/dev/block/mmcblk0p15 630M 17M 606M 3% /cache
/dev/block/mmcblk0p14 4.9M 4.9M 0 100% /persist
/dev/block/mmcblk0p1 64M 56M 7.7M 88% /firmware
worker 924M 0 924M 0% /debug_ramdisk/.magisk/worker
/dev/fuse 26G 21G 4.4G 83% /storage/emulated
/dev/fuse 59G 7.8G 52G 14% /storage/E488-6A1F
Will wait and watch for a bit. Hoping to get backup-ups to Nextcloud working later.
I'm running into the same symptom, probably the same bug. @grote, here is a backtrace you were asking for above:
~$ adb logcat -s MetadataManager -b all -v color
--------- beginning of main
12-08 17:15:17.453 6971 6971 E MetadataManager: Error parsing cached metadata
12-08 17:15:17.453 6971 6971 E MetadataManager: java.lang.SecurityException: org.json.JSONException: End of input at character 0 of
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.stevesoltys.seedvault.metadata.MetadataReaderImpl.decode(MetadataReader.kt:158)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.stevesoltys.seedvault.metadata.MetadataReader$DefaultImpls.decode$default(MetadataReader.kt:31)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadataFromCache(MetadataManager.kt:250)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.stevesoltys.seedvault.metadata.MetadataManager.getMetadata(MetadataManager.kt:45)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.stevesoltys.seedvault.metadata.MetadataManager.getBackupToken(MetadataManager.kt:209)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.stevesoltys.seedvault.App.migrateTokenFromMetadataToSettingsManager(App.kt:109)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.stevesoltys.seedvault.App.access$migrateTokenFromMetadataToSettingsManager(App.kt:40)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.stevesoltys.seedvault.App$onCreate$1.invoke(App.kt:76)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.stevesoltys.seedvault.App$onCreate$1.invoke(App.kt:75)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.stevesoltys.seedvault.AppKt.permitDiskReads(App.kt:138)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.stevesoltys.seedvault.App.onCreate(App.kt:75)
12-08 17:15:17.453 6971 6971 E MetadataManager: at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1215)
12-08 17:15:17.453 6971 6971 E MetadataManager: at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6727)
12-08 17:15:17.453 6971 6971 E MetadataManager: at android.app.ActivityThread.access$1500(ActivityThread.java:248)
12-08 17:15:17.453 6971 6971 E MetadataManager: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2054)
12-08 17:15:17.453 6971 6971 E MetadataManager: at android.os.Handler.dispatchMessage(Handler.java:106)
12-08 17:15:17.453 6971 6971 E MetadataManager: at android.os.Looper.loopOnce(Looper.java:201)
12-08 17:15:17.453 6971 6971 E MetadataManager: at android.os.Looper.loop(Looper.java:288)
12-08 17:15:17.453 6971 6971 E MetadataManager: at android.app.ActivityThread.main(ActivityThread.java:7841)
12-08 17:15:17.453 6971 6971 E MetadataManager: at java.lang.reflect.Method.invoke(Native Method)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.android.internal.os.ExecInit.main(ExecInit.java:48)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.android.internal.os.RuntimeInit.nativeFinishInit(Native Method)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.android.internal.os.RuntimeInit.main(RuntimeInit.java:355)
12-08 17:15:17.453 6971 6971 E MetadataManager: Caused by: org.json.JSONException: End of input at character 0 of
12-08 17:15:17.453 6971 6971 E MetadataManager: at org.json.JSONTokener.syntaxError(JSONTokener.java:460)
12-08 17:15:17.453 6971 6971 E MetadataManager: at org.json.JSONTokener.nextValue(JSONTokener.java:101)
12-08 17:15:17.453 6971 6971 E MetadataManager: at org.json.JSONObject.<init>(JSONObject.java:168)
12-08 17:15:17.453 6971 6971 E MetadataManager: at org.json.JSONObject.<init>(JSONObject.java:185)
12-08 17:15:17.453 6971 6971 E MetadataManager: at com.stevesoltys.seedvault.metadata.MetadataReaderImpl.decode(MetadataReader.kt:89)
12-08 17:15:17.453 6971 6971 E MetadataManager: ... 23 more
So looks like the metadata.cache file exists but is 0 bytes. I've had available disk space go to 0 as well (usable from user, not sure about system apps). Can the metadata.cache be rebuilt from the backup files?
