seedvault icon indicating copy to clipboard operation
seedvault copied to clipboard

Published 20 hours ago • verified publisher icon seedvault-app

Storage backup bugs

Open rugk opened this issue 3 years ago • 2 comments

What happened

I noticed that since some days my backup would not show as backed up completely, i.e. the day counter showed "last backup: 21 October", e.g. Also, I noticed that once a day the beat feature for storage backup starts and does sth., which I interpret as being successful.

Now, I thus triggered it manually and I see it seems to do some backup and even pruning then, but at the end it shows a failed notification: backup-failed

I retriggered it 2-3 times with the same result…

Notable things

  • The menu of Seedvault shows a red icon next to the app "Nextcloud" indicating that the Nexctcloud app could not be backed up. Maybe the Nextcloud data could not be backed up while Nextcloud was currently being used for uploading (other) backup data?
  • As it shows something about pruning, maybe actually pruning fails and not the backup?
    • If that is the case, and sth. was actually backed up, maybe the status display in the app is wrong though, because it still shows some apps waiting to be backed up, which are new and likely included in the backup now. So it seems if pruning fails, the status is not updated, even though the backup may have suceeded.

Some logcat snippets

I can provide the full logcat privately if needed.

Here are some interesting snippets I could find upon skimming it:

[10-29 13:46:38.740 18678:18709 W/UnsafeUtil]
platform method missing - proto runtime falling back to safer methods: java.lang.NoSuchMethodException: sun.misc.Unsafe.copyMemory [class java.lang.Object, long, class java.lang.Object, long, long]

[10-29 13:46:38.755 3287:3306 I/MediaProvider]
Using lower FS for /storage/emulated/0/Download/blokada

[10-29 13:46:38.763 18678:18709 E/SmallFileBackup]
Error backing up content://media/external/downloads/3551
java.io.IOException: read failed: EISDIR (Is a directory)
	at libcore.io.IoBridge.read(IoBridge.java:519)
	at java.io.FileInputStream.read(FileInputStream.java:320)
	at android.os.ParcelFileDescriptor$AutoCloseInputStream.read(ParcelFileDescriptor.java:1005)
	at java.io.FileInputStream.read(FileInputStream.java:289)
	at android.os.ParcelFileDescriptor$AutoCloseInputStream.read(ParcelFileDescriptor.java:996)
	at kotlin.io.ByteStreamsKt.copyTo(IOStreams.kt:106)
	at kotlin.io.ByteStreamsKt.copyTo$default(IOStreams.kt:103)
	at org.calyxos.backup.storage.backup.ChunkWriter.writeNewZipEntry(Unknown Source:20)
	at org.calyxos.backup.storage.backup.ZipChunker.addFile(Unknown Source:16)
	at org.calyxos.backup.storage.backup.SmallFileBackup.makeZipChunk(Unknown Source:28)
	at org.calyxos.backup.storage.backup.SmallFileBackup.backupFiles(Unknown Source:681)
	at org.calyxos.backup.storage.backup.Backup.backupFiles(Unknown Source:198)
	at org.calyxos.backup.storage.backup.Backup.runBackup(Unknown Source:444)
	at org.calyxos.backup.storage.backup.Backup$runBackup$1.invokeSuspend(Unknown Source:12)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.ResumeModeKt.resumeUninterceptedMode(ResumeMode.kt:45)
	at kotlinx.coroutines.TimeoutCoroutine.afterCompletionInternal(Timeout.kt:100)
	at kotlinx.coroutines.JobSupport.completeStateFinalization(JobSupport.kt:310)
	at kotlinx.coroutines.JobSupport.tryFinalizeFinishingState(JobSupport.kt:236)
	at kotlinx.coroutines.JobSupport.tryMakeCompletingSlowPath(JobSupport.kt:849)
	at kotlinx.coroutines.JobSupport.tryMakeCompleting(JobSupport.kt:811)
	at kotlinx.coroutines.JobSupport.makeCompletingOnce$kotlinx_coroutines_core(JobSupport.kt:787)
	at kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:111)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
	at kotlinx.coroutines.DispatchedTask.run(Dispatched.kt:241)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:594)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.access$runSafely(CoroutineScheduler.kt:60)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:740)
Caused by: android.system.ErrnoException: read failed: EISDIR (Is a directory)
	at libcore.io.Linux.readBytes(Native Method)
	at libcore.io.Linux.read(Linux.java:189)
	at libcore.io.ForwardingOs.read(ForwardingOs.java:176)
	at libcore.io.BlockGuardOs.read(BlockGuardOs.java:305)
	at libcore.io.ForwardingOs.read(ForwardingOs.java:176)
	at libcore.io.IoBridge.read(IoBridge.java:509)
	... 27 more

[10-29 13:46:38.766 3287:3306 I/MediaProvider]
Using lower FS for /storage/emulated/0/Download/blokada/requests.csv

[10-29 13:46:38.769 18678:18709 E/SmallFileBackup]
Error backing up content://media/external/downloads/3552
java.util.zip.ZipException: duplicate entry: 1
	at java.util.zip.ZipOutputStream.putNextEntry(ZipOutputStream.java:234)
	at org.calyxos.backup.storage.backup.ChunkWriter.writeNewZipEntry(Unknown Source:14)
	at org.calyxos.backup.storage.backup.ZipChunker.addFile(Unknown Source:16)
	at org.calyxos.backup.storage.backup.SmallFileBackup.makeZipChunk(Unknown Source:28)
	at org.calyxos.backup.storage.backup.SmallFileBackup.backupFiles(Unknown Source:681)
	at org.calyxos.backup.storage.backup.Backup.backupFiles(Unknown Source:198)
	at org.calyxos.backup.storage.backup.Backup.runBackup(Unknown Source:444)
	at org.calyxos.backup.storage.backup.Backup$runBackup$1.invokeSuspend(Unknown Source:12)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.ResumeModeKt.resumeUninterceptedMode(ResumeMode.kt:45)
	at kotlinx.coroutines.TimeoutCoroutine.afterCompletionInternal(Timeout.kt:100)
	at kotlinx.coroutines.JobSupport.completeStateFinalization(JobSupport.kt:310)
	at kotlinx.coroutines.JobSupport.tryFinalizeFinishingState(JobSupport.kt:236)
	at kotlinx.coroutines.JobSupport.tryMakeCompletingSlowPath(JobSupport.kt:849)
	at kotlinx.coroutines.JobSupport.tryMakeCompleting(JobSupport.kt:811)
	at kotlinx.coroutines.JobSupport.makeCompletingOnce$kotlinx_coroutines_core(JobSupport.kt:787)
	at kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:111)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
	at kotlinx.coroutines.DispatchedTask.run(Dispatched.kt:241)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:594)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.access$runSafely(CoroutineScheduler.kt:60)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:740)

[10-29 13:46:38.772 3287:3306 I/MediaProvider]
Using lower FS for /storage/emulated/0/Download/mDbn9b7Eby6wysq3JrNVWXbBh2VVyEe92W8RIOpeGhIqLLf31Dt8eH8pVYzFjMx5ki8vTvlaAfvIf69fER5P7Wx+mvRb7ASxwAAAAAA==.wav

[10-29 13:46:38.774 18678:18709 E/SmallFileBackup]
Error backing up content://media/external/downloads/4083
java.util.zip.ZipException: duplicate entry: 1
	at java.util.zip.ZipOutputStream.putNextEntry(ZipOutputStream.java:234)
	at org.calyxos.backup.storage.backup.ChunkWriter.writeNewZipEntry(Unknown Source:14)
	at org.calyxos.backup.storage.backup.ZipChunker.addFile(Unknown Source:16)
	at org.calyxos.backup.storage.backup.SmallFileBackup.makeZipChunk(Unknown Source:28)
	at org.calyxos.backup.storage.backup.SmallFileBackup.backupFiles(Unknown Source:681)
	at org.calyxos.backup.storage.backup.Backup.backupFiles(Unknown Source:198)
	at org.calyxos.backup.storage.backup.Backup.runBackup(Unknown Source:444)
	at org.calyxos.backup.storage.backup.Backup$runBackup$1.invokeSuspend(Unknown Source:12)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.ResumeModeKt.resumeUninterceptedMode(ResumeMode.kt:45)
	at kotlinx.coroutines.TimeoutCoroutine.afterCompletionInternal(Timeout.kt:100)
	at kotlinx.coroutines.JobSupport.completeStateFinalization(JobSupport.kt:310)
	at kotlinx.coroutines.JobSupport.tryFinalizeFinishingState(JobSupport.kt:236)
	at kotlinx.coroutines.JobSupport.tryMakeCompletingSlowPath(JobSupport.kt:849)
	at kotlinx.coroutines.JobSupport.tryMakeCompleting(JobSupport.kt:811)
	at kotlinx.coroutines.JobSupport.makeCompletingOnce$kotlinx_coroutines_core(JobSupport.kt:787)
	at kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:111)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
	at kotlinx.coroutines.DispatchedTask.run(Dispatched.kt:241)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:594)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.access$runSafely(CoroutineScheduler.kt:60)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:740)

[10-29 13:46:38.774 18678:18709 D/SmallFileBackup]
Zip Chunks: 1

[10-29 13:46:38.774 18678:18709 E/Time]
Backing up 4 small files took 42.0ms

[10-29 13:46:38.774 18678:18709 E/Time]
Backing up 0 files took 0s

[10-29 13:46:38.877 1199:1199 I/cnss-daemon]
nl80211 response handler invoked

[10-29 13:46:38.877 1199:1199 I/cnss-daemon]
nl80211_response_handler: cmd 103, vendorID 4980, subcmd 13  received

[10-29 13:46:38.877 948:2583 I/WifiHAL]
event received NL80211_CMD_VENDOR, vendor_id = 0x1374, subcmd = 0xd

[10-29 13:46:38.923 943:1049 D/VSC]
@ 147999.759: [WO] isFlat() nearest_rotation: 4, flat_angle: 65

[10-29 13:46:38.923 943:1049 D/VSC]
@ 147999.759: [WO] orientation angle 356, orientation 4

[10-29 13:46:38.923 943:1049 D/VSC]
@ 147999.759: [WO] Gyro angle integrated: 51.109706

[10-29 13:46:38.923 943:1049 D/VSC]
@ 147999.760: [WO] Rejected by settle_time and gyro finds no rotation 0

[10-29 13:46:38.958 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.stevesoltys.seedvault|1000|null|10104

[10-29 13:46:38.958 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.stevesoltys.seedvault|1000|null|10104

[10-29 13:46:38.969 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.stevesoltys.seedvault|1000|null|10104

[10-29 13:46:38.969 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.stevesoltys.seedvault|1000|null|10104

[10-29 13:46:38.980 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.stevesoltys.seedvault|1000|null|10104

[10-29 13:46:38.980 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.stevesoltys.seedvault|1000|null|10104

[10-29 13:46:38.991 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.stevesoltys.seedvault|1000|null|10104

[10-29 13:46:38.991 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.stevesoltys.seedvault|1000|null|10104

[10-29 13:46:39.002 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.stevesoltys.seedvault|1000|null|10104

[10-29 13:46:39.003 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.stevesoltys.seedvault|1000|null|10104

[10-29 13:46:39.181 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.kunzisoft.keepass.libre|593|null|10207

[10-29 13:46:39.181 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.kunzisoft.keepass.libre|593|null|10207

[10-29 13:46:40.165 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.kunzisoft.keepass.libre|593|null|10207

[10-29 13:46:40.166 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.kunzisoft.keepass.libre|593|null|10207

[10-29 13:46:40.887 948:2583 I/WifiHAL]
event received NL80211_CMD_VENDOR, vendor_id = 0x1374, subcmd = 0xd

[10-29 13:46:40.887 1199:1199 I/cnss-daemon]
nl80211 response handler invoked

[10-29 13:46:40.887 1199:1199 I/cnss-daemon]
nl80211_response_handler: cmd 103, vendorID 4980, subcmd 13  received

[10-29 13:46:40.924 943:1049 D/VSC]
@ 148001.760: [WO] isFlat() nearest_rotation: 0, flat_angle: 65

[10-29 13:46:40.924 943:1049 D/VSC]
@ 148001.761: [WO] orientation angle 2, orientation 0

[10-29 13:46:41.179 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.kunzisoft.keepass.libre|593|null|10207

[10-29 13:46:41.180 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.kunzisoft.keepass.libre|593|null|10207

[10-29 13:46:42.185 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.kunzisoft.keepass.libre|593|null|10207

[10-29 13:46:42.186 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.kunzisoft.keepass.libre|593|null|10207

(Y29tLm5leHRjbG91ZC5jbGllbnQ is base64 for com.nextcloud.client)

[10-29 13:46:54.283 18678:18713 E/Pruner]
Error pruning StoredSnapshot(userId=7d307f7cea69dd15.sv, timestamp=1634164425281)
java.io.IOException
	at org.calyxos.backup.storage.restore.RestoreKt.readVersion(Unknown Source:63)
	at org.calyxos.backup.storage.restore.RestoreKt.readVersion$default(Unknown Source:5)
	at org.calyxos.backup.storage.plugin.SnapshotRetriever.getSnapshot(Unknown Source:89)
	at org.calyxos.backup.storage.prune.Pruner.pruneSnapshot(Unknown Source:149)
	at org.calyxos.backup.storage.prune.Pruner.prune(Unknown Source:283)
	at org.calyxos.backup.storage.api.StorageBackup$pruneOldBackups$2.invokeSuspend(Unknown Source:65)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(Dispatched.kt:241)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:594)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.access$runSafely(CoroutineScheduler.kt:60)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:740)

[10-29 13:46:54.284 18678:18713 I/Pruner]
Pruning took 9.91s

[10-29 13:46:54.302 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.stevesoltys.seedvault|1001|null|10104

[10-29 13:46:54.302 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.stevesoltys.seedvault|1001|null|10104

[10-29 13:46:54.308 18678:18713 I/PackageService]
Got 312 packages:

[…]

[10-29 13:46:54.311 18678:18678 D/ConfigurableBackupTransportService]
Service created.

[10-29 13:46:54.311 18678:18678 D/ConfigurableBackupTransportService]
Transport bound.

[10-29 13:46:44.594 1443:1443 I/chatty]
uid=1000(system) Binder:1443_3 identical 3 lines

[10-29 13:46:44.595 1443:1443 D/NotificationService]
0|com.nextcloud.client|411|null|10190: granting content://settings/system/notification_sound

[10-29 13:46:54.312 1443:1443 I/TransportClient]
ConfigurableBackupTransportService#381: Notifying [AppBackupUtils.appIsRunningAndEligibleForBackupWithTransport] transport = IBackupTransport

[10-29 13:46:54.420 18678:18678 D/ConfigurableBackupTransportService]
Service destroyed.

[10-29 13:46:54.420 18678:18713 I/PackageService]
Filtering left 203 eligible packages:

[…]

[10-29 13:46:54.434 18678:18713 D/ConfigurableBackupTransportService]
Backup is enabled, request backup...

[10-29 13:46:54.435 18678:18713 I/BackupNotificationManager]
0/204 - 0% - 

[10-29 13:46:54.446 18678:18713 I/ConfigurableBackupTransportService]
Backup succeeded 

[10-29 13:46:54.447 18678:18678 D/BackupService]
onDestroy

[10-29 13:46:54.448 1443:3233 V/BackupManagerService]
[UserID:0] Acquired wakelock:*backup*-0-3233

[10-29 13:46:54.449 1443:3233 D/KeyValueBackupTask]
Spinning thread key-value-backup-8

[10-29 13:46:54.450 1443:18746 D/PFTBT]
backupmanager pftbt token=11dc35f

[10-29 13:46:54.455 1443:18746 V/KeyValueBackupTask]
Beginning backup of 14 targets

[10-29 13:46:54.457 18678:18678 D/ConfigurableBackupTransportService]
Service created.

[10-29 13:46:54.457 18678:18678 D/ConfigurableBackupTransportService]
Transport bound.

[10-29 13:46:54.458 1443:1443 I/TransportClient]
ConfigurableBackupTransportService#382: Notifying [KVBT.startTask()] transport = IBackupTransport

[10-29 13:46:54.461 1443:18746 D/KeyValueBackupTask]
Starting key-value backup of @pm@

[10-29 13:46:54.468 1443:18746 D/KeyValueBackupTask]
Invoking agent on @pm@

[10-29 13:46:54.471 18678:18695 I/BackupCoordinator]
Get backup quota for @pm@. Is full backup: false.

[10-29 13:46:54.471 18678:18695 I/BackupCoordinator]
Reported quota of 10485760 bytes.

[10-29 13:46:54.479 1443:18746 I/BackupRestoreController]
Getting widget state for user: 0

[10-29 13:46:54.480 18678:18695 I/KVBackup]
Performing incremental K/V backup for @pm@

[10-29 13:46:54.492 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.stevesoltys.seedvault|1001|null|10104

[10-29 13:46:54.493 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.stevesoltys.seedvault|1001|null|10104

[10-29 13:46:54.638 1443:1443 D/NotificationService]
0|com.stevesoltys.seedvault|1|null|10104: granting content://settings/system/notification_sound

[10-29 13:46:54.639 1443:1443 I/chatty]
uid=1000(system) Binder:1443_3 identical 3 lines

[10-29 13:46:54.639 1443:1443 D/NotificationService]
0|com.stevesoltys.seedvault|1|null|10104: granting content://settings/system/notification_sound

[10-29 13:46:54.646 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.stevesoltys.seedvault|1|null|10104

[10-29 13:46:54.646 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.stevesoltys.seedvault|1|null|10104

[10-29 13:46:54.756 14367:18725 I/chatty]
uid=10190(com.nextcloud.client) pool-6-thread-4 expire 42 lines

[10-29 13:46:54.758 18678:18695 D/DocumentsStorage]
Wait for children to get loaded...

[10-29 13:46:54.912 1199:1199 I/cnss-daemon]
nl80211 response handler invoked

[10-29 13:46:54.912 1199:1199 I/cnss-daemon]
nl80211_response_handler: cmd 103, vendorID 4980, subcmd 13  received

[10-29 13:46:54.912 948:2583 I/WifiHAL]
event received NL80211_CMD_VENDOR, vendor_id = 0x1374, subcmd = 0xd

[10-29 13:46:54.922 943:1049 D/VSC]
@ 148015.759: [WO] isFlat() nearest_rotation: 0, flat_angle: 65

[10-29 13:46:54.922 943:1049 D/VSC]
@ 148015.759: [WO] orientation angle 2, orientation 0

[10-29 13:46:55.231 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.kunzisoft.keepass.libre|593|null|10207

[10-29 13:46:55.231 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.kunzisoft.keepass.libre|593|null|10207

[some more lines later……]


[10-29 13:47:06.632 3287:18180 I/MediaProvider]
Deleted 1 items on external_primary due to com.nextcloud.client

[10-29 13:47:06.731 18678:18695 E/KVBackup]
Unable to update base64Key file for base64Key Y29tLm5leHRjbG91ZC5jbGllbnQ
java.io.FileNotFoundException: Failed to open document for writing Y29tLm5leHRjbG91ZC5jbGllbnQ
	at android.database.DatabaseUtils.readExceptionWithFileNotFoundExceptionFromParcel(DatabaseUtils.java:151)
	at android.content.ContentProviderProxy.openAssetFile(ContentProviderNative.java:704)
	at android.content.ContentResolver.openAssetFileDescriptor(ContentResolver.java:1816)
	at android.content.ContentResolver.openOutputStream(ContentResolver.java:1518)
	at com.stevesoltys.seedvault.plugins.saf.DocumentsStorage.getOutputStream(DocumentsStorage.kt:164)
	at com.stevesoltys.seedvault.plugins.saf.DocumentsProviderKVBackup.getOutputStreamForRecord(DocumentsProviderKVBackup.kt:66)
	at com.stevesoltys.seedvault.transport.backup.KVBackup.storeRecord(KVBackup.kt:169)
	at com.stevesoltys.seedvault.transport.backup.KVBackup.storeRecords(KVBackup.kt:139)
	at com.stevesoltys.seedvault.transport.backup.KVBackup.performBackup(KVBackup.kt:113)
	at com.stevesoltys.seedvault.transport.backup.KVBackup$performBackup$1.invokeSuspend(Unknown Source:13)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.ResumeModeKt.resumeUninterceptedMode(ResumeMode.kt:45)
	at kotlinx.coroutines.TimeoutCoroutine.afterCompletionInternal(Timeout.kt:100)
	at kotlinx.coroutines.JobSupport.completeStateFinalization(JobSupport.kt:310)
	at kotlinx.coroutines.JobSupport.tryFinalizeFinishingState(JobSupport.kt:236)
	at kotlinx.coroutines.JobSupport.tryMakeCompletingSlowPath(JobSupport.kt:849)
	at kotlinx.coroutines.JobSupport.tryMakeCompleting(JobSupport.kt:811)
	at kotlinx.coroutines.JobSupport.makeCompletingOnce$kotlinx_coroutines_core(JobSupport.kt:787)
	at kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:111)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
	at kotlinx.coroutines.DispatchedTask.run(Dispatched.kt:241)
	at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:270)
	at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:79)
	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:54)
	at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source:1)
	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:36)
	at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source:1)
	at com.stevesoltys.seedvault.transport.ConfigurableBackupTransport.performBackup(ConfigurableBackupTransport.kt:147)
	at android.app.backup.BackupTransport$TransportImpl.performBackup(BackupTransport.java:704)
	at com.android.internal.backup.IBackupTransport$Stub.onTransact(IBackupTransport.java:626)
	at android.os.Binder.execTransactInternal(Binder.java:1159)
	at android.os.Binder.execTransact(Binder.java:1123)

[10-29 13:47:06.731 18678:18695 I/KVBackup]
Resetting state because of K/V Backup error of @pm@

[10-29 13:47:06.732 18678:18728 I/NotificationBackupObserver]
Completed. Target: @pm@, status: -1000

[10-29 13:47:06.732 1443:18746 E/KeyValueBackupTask]
Error during PM metadata backup
com.android.server.backup.keyvalue.TaskException
	at com.android.server.backup.keyvalue.KeyValueBackupTask.handleTransportStatus(KeyValueBackupTask.java:1120)
	at com.android.server.backup.keyvalue.KeyValueBackupTask.sendDataToTransport(KeyValueBackupTask.java:1054)
	at com.android.server.backup.keyvalue.KeyValueBackupTask.sendDataToTransport(KeyValueBackupTask.java:567)
	at com.android.server.backup.keyvalue.KeyValueBackupTask.backupPm(KeyValueBackupTask.java:669)
	at com.android.server.backup.keyvalue.KeyValueBackupTask.run(KeyValueBackupTask.java:358)
	at java.lang.Thread.run(Thread.java:923)

[10-29 13:47:06.732 18678:18728 I/NotificationBackupObserver]
Showing progress notification for null 0/204

[10-29 13:47:06.732 18678:18728 I/BackupNotificationManager]
60/263 - 23% - System-Paketmanager

[10-29 13:47:06.736 18678:18695 I/BackupCoordinator]
Request incremental backup time. Returned 0

[10-29 13:47:06.736 1443:18746 I/KeyValueBackupTask]
K/V backup pass finished

[10-29 13:47:06.743 18678:18678 D/ConfigurableBackupTransportService]
Service destroyed.

[10-29 13:47:06.746 655:694 I/BpBinder]
onLastStrongRef automatically unlinking death recipients: <uncached descriptor>

[10-29 13:47:06.747 18678:18695 I/NotificationBackupObserver]
Backup finished 1/204. Status: -1000

[10-29 13:47:06.747 1443:18746 V/BackupManagerService]
[UserID:0] Released wakelock:*backup*-0-3233

[10-29 13:47:06.804 655:1501 I/BpBinder]
onLastStrongRef automatically unlinking death recipients: <uncached descriptor>

[10-29 13:47:06.923 943:1049 D/VSC]
@ 148027.760: [WO] isFlat() nearest_rotation: 0, flat_angle: 65

[10-29 13:47:06.923 943:1049 D/VSC]
@ 148027.761: [WO] orientation angle 13, orientation 0

[10-29 13:47:06.923 943:1049 D/VSC]
@ 148027.761: [WO] rejected by isOrientationAngleAcceptable

[10-29 13:47:06.928 948:2583 I/WifiHAL]
event received NL80211_CMD_VENDOR, vendor_id = 0x1374, subcmd = 0xd

[10-29 13:47:06.928 1199:1199 I/cnss-daemon]
nl80211 response handler invoked

[10-29 13:47:06.928 1199:1199 I/cnss-daemon]
nl80211_response_handler: cmd 103, vendorID 4980, subcmd 13  received

[10-29 13:47:06.944 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.stevesoltys.seedvault|1|null|10104

[10-29 13:47:06.944 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.stevesoltys.seedvault|1|null|10104

[10-29 13:47:06.965 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.stevesoltys.seedvault|1|null|10104

[10-29 13:47:06.966 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.stevesoltys.seedvault|1|null|10104

[10-29 13:47:07.025 14367:14367 I/chatty]
uid=10190(com.nextcloud.client) expire 1 line

[10-29 13:47:07.277 1915:1915 D/InterruptionStateProvider]
No bubble up: not allowed to bubble: 0|com.kunzisoft.keepass.libre|593|null|10207

[10-29 13:47:07.277 1915:1915 D/InterruptionStateProvider]
No heads up: unimportant notification: 0|com.kunzisoft.keepass.libre|593|null|10207

[10-29 13:47:07.432 1915:1915 D/StatusBar]
disable<e i a s b h r c s > disable2<q i n >

System

v11-2.3 CalyxOS v2.10.0 / Android 11 / Build No. RQ3A.211001.001.202102100 Pixel 4

Notes

possibly related: https://github.com/seedvault-app/seedvault/issues/335

rugk avatar Oct 30 '21 01:10 rugk

The menu of Seedvault shows a red icon next to the app "Nextcloud" indicating that the Nexctcloud app could not be backed up.

That is normal. The app being used as a backup transport can't be backed up, because it would get killled for backup making writing the backup fail.

Your backup seems to fail due to:

E/KVBackup: Unable to update base64Key file for base64Key Y29tLm5leHRjbG91ZC5jbGllbnQ java.io.FileNotFoundException: Failed to open document for writing Y29tLm5leHRjbG91ZC5jbGllbnQ

which might be due to Nextcloud. Does that file exist on Nextcloud, is it locked?

Thanks for the logcat. That's very helpful and seems to hint at some storage backup bugs.

Stuff to investigate:

[10-29 13:46:38.763 18678:18709 E/SmallFileBackup]
Error backing up content://media/external/downloads/3551
java.io.IOException: read failed: EISDIR (Is a directory)
	at libcore.io.IoBridge.read(IoBridge.java:519)
	at java.io.FileInputStream.read(FileInputStream.java:320)
	at android.os.ParcelFileDescriptor$AutoCloseInputStream.read(ParcelFileDescriptor.java:1005)
	at java.io.FileInputStream.read(FileInputStream.java:289)
	at android.os.ParcelFileDescriptor$AutoCloseInputStream.read(ParcelFileDescriptor.java:996)
	at kotlin.io.ByteStreamsKt.copyTo(IOStreams.kt:106)
	at kotlin.io.ByteStreamsKt.copyTo$default(IOStreams.kt:103)
	at org.calyxos.backup.storage.backup.ChunkWriter.writeNewZipEntry(Unknown Source:20)
	at org.calyxos.backup.storage.backup.ZipChunker.addFile(Unknown Source:16)
	at org.calyxos.backup.storage.backup.SmallFileBackup.makeZipChunk(Unknown Source:28)
	at org.calyxos.backup.storage.backup.SmallFileBackup.backupFiles(Unknown Source:681)
	at org.calyxos.backup.storage.backup.Backup.backupFiles(Unknown Source:198)
Caused by: android.system.ErrnoException: read failed: EISDIR (Is a directory)

[10-29 13:46:38.769 18678:18709 E/SmallFileBackup]
Error backing up content://media/external/downloads/3552
java.util.zip.ZipException: duplicate entry: 1
	at java.util.zip.ZipOutputStream.putNextEntry(ZipOutputStream.java:234)
	at org.calyxos.backup.storage.backup.ChunkWriter.writeNewZipEntry(Unknown Source:14)
	at org.calyxos.backup.storage.backup.ZipChunker.addFile(Unknown Source:16)
	at org.calyxos.backup.storage.backup.SmallFileBackup.makeZipChunk(Unknown Source:28)
	at org.calyxos.backup.storage.backup.SmallFileBackup.backupFiles(Unknown Source:681)
	at org.calyxos.backup.storage.backup.Backup.backupFiles(Unknown Source:198)

[10-29 13:46:54.283 18678:18713 E/Pruner]
Error pruning StoredSnapshot(userId=7d307f7cea69dd15.sv, timestamp=1634164425281)
java.io.IOException
	at org.calyxos.backup.storage.restore.RestoreKt.readVersion(Unknown Source:63)
	at org.calyxos.backup.storage.restore.RestoreKt.readVersion$default(Unknown Source:5)
	at org.calyxos.backup.storage.plugin.SnapshotRetriever.getSnapshot(Unknown Source:89)
	at org.calyxos.backup.storage.prune.Pruner.pruneSnapshot(Unknown Source:149)
	at org.calyxos.backup.storage.prune.Pruner.prune(Unknown Source:283)

grote avatar Nov 01 '21 14:11 grote

which might be due to Nextcloud. Does that file exist on Nextcloud, is it locked?

Hmm, I checked it now and it exists:

image

Edit: BTW, this seems to be the file's path: image

However, I have to say the backup also suddenly started working again, i.e. up to the point where it shows in the settings "Last backup: 1 day ago" or some other recent time, so this could correlate with the upload time Nextcloud there shows 2 days ago (screenshot taken just now).

Maybe it's indeed Nextcloud being flaky and not uploading a file it was supposed to do, which broke the whole backup process.

rugk avatar Nov 20 '21 20:11 rugk

I encountered the same issue today with version 11-2.3 (Android 11) and Nextcloud 25.0.2.

After manually deleting the specific file mentioned in FileNotFoundException from Nextcloud, the backup went further but then failed in the same way on another file.

A couple of attempts later, it failed again on the very first file that it failed on.

Through the Nextcloud web UI the file is accessible and doesn't seem to be locked. I cannot try writing to it as the web UI doesn't know what to open it with (so it offers to download it instead).

There seem to be at least some consistency as it repeatedly fails on the same file, even after it's deleted (manually) and re-uploaded (by Seedvault).

Is there any way we could try to access the file in a similar way (through the same API? Is it using WebDAV?) to what Seedvault does to see if that works?

rmelotte avatar Jan 08 '23 13:01 rmelotte

with version 11-2.3 (Android 11)

Note that this is very old, misses many fixes and isn't supported anymore.

Is there any way we could try to access the file in a similar way (through the same API? Is it using WebDAV?) to what Seedvault does to see if that works?

You can use the normal Files app or other apps using android's storage access framework (SAF).

grote avatar Jan 09 '23 22:01 grote

I'm hitting both this and https://github.com/seedvault-app/seedvault/issues/266 on Lineage OS 18.1 (Android 11, 11-2.3 too). Wanted to create backup before switching to another device, but looks like no luck.

nazar-pc avatar Jan 21 '23 16:01 nazar-pc

@rugk thanks so much for your report and the logcat! I have been able to identify and fix two bugs with the files/storage backup (see above) thanks to your report. You've saved the backups of countless users!

grote avatar Feb 12 '24 13:02 grote

Wow thanks! Did not expect that given how old the issue is.

In any case, big thanks for fixing hem! You actually saved the backups and continue saving it here hehe.. 👍

As for this issue, i guess it can now close it...?

rugk avatar Feb 14 '24 13:02 rugk