seedvault-app / seedvault

A backup application for the Android Open Source Project.
1.19k stars 73 forks source link

Backup fails to run #626

Closed jmbreuer closed 4 months ago

jmbreuer commented 4 months ago

I'm trying to run SeedVault as it comes built into LineageOS 20.0/20240114 for my SM-G930F. My backup target is on the (non-adopted) SD card.

Starting the backup just gives a "Backup failed to run" notification after some time. No progress indication whatsoever.

I've already completely removed and re-initialized the backup location, same thing.

This looks like the possibly relevant log snippet; I'm happy to provide more:

02-08 12:38:29.068  3505  3583 D ConfigurableBackupTransportService: Backup is enabled, request backup...
02-08 12:38:29.068  3505  3583 I BackupNotificationManager: 0/191 - 0% - 
02-08 12:38:29.074  3505  3505 D ConfigurableBackupTransportService: Service created.
02-08 12:38:29.076  3505  3505 D ConfigurableBackupTransportService: Transport bound.
02-08 12:38:29.077  3876  3876 I TransportConnection: ConfigurableBackupTransportService#1884: Notifying [BMS.getOperati
onTypeFromTransport] transport = BackupTransportClient
02-08 12:38:29.085  3505  3583 I ConfigurableBackupTransportService: Backup succeeded 
02-08 12:38:29.086  3876  5138 V BackupManagerService: [UserID:0] Acquired wakelock:*backup*-0-5138
02-08 12:38:29.086  3876  5138 D KeyValueBackupTask: Spinning thread key-value-backup-2
02-08 12:38:29.091  3876  5464 D PFTBT   : backupmanager pftbt token=153e3705
02-08 12:38:29.092  3876  5464 V KeyValueBackupTask: Beginning backup of 27 targets
02-08 12:38:29.093  3876  5464 I KeyValueBackupTask: Initializing transport and resetting backup state
02-08 12:38:29.113  3505  3553 I BackupCoordinator: Starting new RestoreSet with token 1707392309113...
02-08 12:38:35.565  3505  3553 I BackupCoordinator: Initialize Device!
02-08 12:40:43.359  3505  3553 D BackupCoordinator: Resetting backup metadata for token 1707392309113...

[...]

02-08 12:40:43.521  3505  3553 E JavaBinder: *** Uncaught remote exception!  (Exceptions are not yet supported across processes.)
02-08 12:40:43.521  3505  3553 E JavaBinder: java.security.UnrecoverableKeyException: Key algorithm unknown
02-08 12:40:43.521  3505  3553 E JavaBinder:    at android.security.keystore2.AndroidKeyStoreProvider.loadAndroidKeyStoreKeyFromKeystore(AndroidKeyStoreProvider.java:400)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at android.security.keystore2.AndroidKeyStoreProvider.loadAndroidKeyStoreKeyFromKeystore(AndroidKeyStoreProvider.java:352)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at android.security.keystore2.AndroidKeyStoreSpi.engineGetKey(AndroidKeyStoreSpi.java:110)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at java.security.KeyStoreSpi.engineGetEntry(KeyStoreSpi.java:511)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at java.security.KeyStore.getEntry(KeyStore.java:1581)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at com.stevesoltys.seedvault.crypto.KeyManagerImpl.getMainKey(KeyManager.kt:93)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at com.stevesoltys.seedvault.crypto.CryptoImpl$key$2.invoke(Crypto.kt:126)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at com.stevesoltys.seedvault.crypto.CryptoImpl$key$2.invoke(Crypto.kt:125)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at kotlin.SynchronizedLazyImpl.getValue(LazyJVM.kt:74)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at com.stevesoltys.seedvault.crypto.CryptoImpl.getKey(Crypto.kt:125)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at com.stevesoltys.seedvault.crypto.CryptoImpl.newEncryptingStream(Crypto.kt:157)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at com.stevesoltys.seedvault.metadata.MetadataWriterImpl.write(MetadataWriter.kt:23)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at com.stevesoltys.seedvault.metadata.MetadataManager.modifyMetadata(MetadataManager.kt:188)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at com.stevesoltys.seedvault.metadata.MetadataManager.onDeviceInitialization(MetadataManager.kt:65)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at com.stevesoltys.seedvault.transport.backup.BackupCoordinator.initializeDevice(BackupCoordinator.kt:128)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at com.stevesoltys.seedvault.transport.ConfigurableBackupTransport$initializeDevice$1.invokeSuspend(ConfigurableBackupTransport.kt:115)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:284)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source:1)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source:1)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at com.stevesoltys.seedvault.transport.ConfigurableBackupTransport.initializeDevice(ConfigurableBackupTransport.kt:114)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at android.app.backup.BackupTransport$TransportImpl.initializeDevice(BackupTransport.java:743)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at com.android.internal.backup.IBackupTransport$Stub.onTransact(IBackupTransport.java:638)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at android.os.Binder.execTransactInternal(Binder.java:1285)
02-08 12:40:43.521  3505  3553 E JavaBinder:    at android.os.Binder.execTransact(Binder.java:1244)
02-08 12:40:43.521  3505  3553 I oltys.seedvault: oneway function results for code 8 on binder at 0x77596c0fd0 will be dropped but finished with status UNKNOWN_TRANSACTION

[...]

02-08 12:43:25.939  3876  4007 I ActivityTaskManager: START u0 {cmp=com.android.settings/.backup.UserBackupSettingsActivity (has extras)} from uid 1000
02-08 12:43:25.991  2717  2717 D BackupSettings: NO dashboard tiles for BackupSettings
02-08 12:43:25.992  2717  2717 D BackupSettings: All preferences added, reporting fully drawn
02-08 12:43:26.011  2717  2717 D DashboardFragment: Preference key is null in Controller BackupSettingsPreferenceController
02-08 12:43:26.019  3876  4007 D CoreBackPreview: Window{36d2e55 u0 com.android.settings/com.android.settings.backup.UserBackupSettingsActivity}: Setting back callback OnBackInvokedCallbackInfo{mCallback=android.window.IOnBackInvokedCallback$Stub$Proxy@54d395b, mPriority=-1}
02-08 12:43:26.054  3876  3893 I ActivityTaskManager: Displayed com.android.settings/.backup.UserBackupSettingsActivity: +114ms
02-08 12:43:26.055  3876  3893 I ActivityTaskManager: Fully drawn com.android.settings/.backup.UserBackupSettingsActivity: +114ms
02-08 12:43:28.822  3876  4318 I ActivityTaskManager: START u0 {act=android.intent.action.VIEW dat=settings://com.android.settings.backup.transport/... cmp=com.android.settings/.backup.transport.TransportActivity} from uid 1000
02-08 12:43:28.893  3876  4007 D CoreBackPreview: Window{640cbca u0 com.android.settings/com.android.settings.backup.transport.TransportActivity}: Setting back callback OnBackInvokedCallbackInfo{mCallback=android.window.IOnBackInvokedCallback$Stub$Proxy@8db3058, mPriority=-1}
02-08 12:43:28.939  3876  3893 I ActivityTaskManager: Displayed com.android.settings/.backup.transport.TransportActivity: +116ms
02-08 12:43:28.939  3876  3893 I ActivityTaskManager: Fully drawn com.android.settings/.backup.transport.TransportActivity: +116ms
02-08 12:43:29.114  3876  5464 E KeyValueBackupTask: Transport error in initializeDevice()
02-08 12:43:29.134  3505  4375 I BackupCoordinator: Request incremental backup time. Returned 0
02-08 12:43:29.138  3876  5464 I KeyValueBackupTask: K/V backup pass finished
02-08 12:43:29.144  3505  4375 I NotificationBackupObserver: Backup finished 0/191. Status: -1000
02-08 12:43:29.144  3876  5464 V BackupManagerService: [UserID:0] Released wakelock:*backup*-0-5138
02-08 12:43:29.147  3505  3505 W BackupNotificationManager: Needed to clean up notification with ID 1
02-08 12:43:29.149  3505  3505 D ConfigurableBackupTransportService: Service destroyed.
jmbreuer commented 4 months ago

Since re-initializing the backup location and/or re-creating the backup encryption key thing does not change this, where/how/... would I clear/reset/recreate that key that it's complaining about? (I have root on the device, if that helps.)

grote commented 4 months ago

You could try to clear app data in system settings.

grote commented 4 months ago

As this seems to be related to #448, it would be interesting to know if you are on an official LineageOS build.

jmbreuer commented 4 months ago

As this seems to be related to #448, it would be interesting to know if you are on an official LineageOS build.

I'm on Ivan Meler's unofficial build, there is no official (non-ancient Android base version) one for my device any more. 🙁

jmbreuer commented 4 months ago

... I cleared the system data, which did allow me to completely re-initialize/reconfigure SeedVault backup from scratch.

"Initializing backup location..." takes quite some time, and ends in "An error occured while accessing the backup location."

In the log, it looks like that exact issue again:

02-20 11:03:23.815 28837 30463 I BackupCoordinator: Initialize Device!
02-20 11:03:24.258 28837 30463 D BackupCoordinator: Resetting backup metadata for token 1708423403599...
02-20 11:03:24.326 28837 30463 E JavaBinder: *** Uncaught remote exception!  (Exceptions are not yet supported across pr
ocesses.)
02-20 11:03:24.326 28837 30463 E JavaBinder: java.security.UnrecoverableKeyException: Key algorithm unknown
02-20 11:03:24.326 28837 30463 E JavaBinder:    at android.security.keystore2.AndroidKeyStoreProvider.loadAndroidKeyStor
eKeyFromKeystore(AndroidKeyStoreProvider.java:400)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at android.security.keystore2.AndroidKeyStoreProvider.loadAndroidKeyStor
eKeyFromKeystore(AndroidKeyStoreProvider.java:352)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at android.security.keystore2.AndroidKeyStoreSpi.engineGetKey(AndroidKey
StoreSpi.java:110)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at java.security.KeyStoreSpi.engineGetEntry(KeyStoreSpi.java:511)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at java.security.KeyStore.getEntry(KeyStore.java:1581)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at com.stevesoltys.seedvault.crypto.KeyManagerImpl.getMainKey(KeyManager.kt:93)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at com.stevesoltys.seedvault.crypto.CryptoImpl$key$2.invoke(Crypto.kt:126)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at com.stevesoltys.seedvault.crypto.CryptoImpl$key$2.invoke(Crypto.kt:125)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at kotlin.SynchronizedLazyImpl.getValue(LazyJVM.kt:74)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at com.stevesoltys.seedvault.crypto.CryptoImpl.getKey(Crypto.kt:125)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at com.stevesoltys.seedvault.crypto.CryptoImpl.newEncryptingStream(Crypto.kt:157)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at com.stevesoltys.seedvault.metadata.MetadataWriterImpl.write(MetadataWriter.kt:23)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at com.stevesoltys.seedvault.metadata.MetadataManager.modifyMetadata(MetadataManager.kt:188)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at com.stevesoltys.seedvault.metadata.MetadataManager.onDeviceInitialization(MetadataManager.kt:65)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at com.stevesoltys.seedvault.transport.backup.BackupCoordinator.initializeDevice(BackupCoordinator.kt:128)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at com.stevesoltys.seedvault.transport.ConfigurableBackupTransport$initializeDevice$1.invokeSuspend(ConfigurableBackupTransport.kt:115)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:284)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source:1)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source:1)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at com.stevesoltys.seedvault.transport.ConfigurableBackupTransport.initializeDevice(ConfigurableBackupTransport.kt:114)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at android.app.backup.BackupTransport$TransportImpl.initializeDevice(BackupTransport.java:743)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at com.android.internal.backup.IBackupTransport$Stub.onTransact(IBackupTransport.java:638)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at android.os.Binder.execTransactInternal(Binder.java:1285)
02-20 11:03:24.326 28837 30463 E JavaBinder:    at android.os.Binder.execTransact(Binder.java:1244)
02-20 11:03:24.326 28837 30463 I oltys.seedvault: oneway function results for code 8 on binder at 0x786875a600 will be dropped but finished with status UNKNOWN_TRANSACTION
jmbreuer commented 4 months ago

Duplicate of #448

jmbreuer commented 4 months ago

... How do I properly mark and close this as a duplicate?

https://docs.github.com/en/issues/tracking-your-work-with-issues/marking-issues-or-pull-requests-as-a-duplicate

doesn't seem to work.

grote commented 4 months ago

I also don't know, just closing it is fine.