Both backup processes happening at once (app backup and file backup running at the same time) #830
Comments
|
What seems to happen in the following log is that it tries app backup first, then runs into #828 almost immediately, then manages to do a quick file backup. 01-01 00:25:01.934 26169 27174 E AppBackupWorker: Error during 'beforeBackup':
01-01 00:25:01.934 26169 27174 E AppBackupWorker: android.database.StaleDataException: Attempted to access a cursor after it has been closed.
01-01 00:25:02.014 26169 26169 I WM-SystemFgDispatcher: Stopping foreground service
01-01 00:25:02.015 1724 8851 D ActivityManager: Stop FGS timeout: ServiceRecord{6501750 u10 com.stevesoltys.seedvault/androidx.work.impl.foreground.SystemForegroundService c:com.stevesoltys.seedvault}
01-01 00:25:02.016 1724 8851 W ForegroundServiceTypeLoggerModule: FGS stop call for: 1010161 has no types!
01-01 00:25:02.019 1724 2150 W JobScheduler: Job didn't exist in JobStore: 6373edd #u10a161/3 com.stevesoltys.seedvault/androidx.work.impl.background.systemjob.SystemJobService
01-01 00:25:28.149 26169 27173 E Backup : Creating/writing snapshot took 1.106s (47 kB)
01-01 00:25:28.157 26169 27173 E Backup : Incrementing chunk ref counters took 8ms
01-01 00:25:28.164 26169 27173 E Backup : Updating last seen time took 7ms
01-01 00:25:28.164 26169 27173 E Backup : Changed files backup took 50.661s
01-01 00:25:28.176 26169 27173 D o.c.s.c.b.s.SafBackend: [DefaultDispatcher-worker-5] list(TopLevelFolder(name=f780dd57bf15af95.sv), [Snapshot])
01-01 00:25:28.379 1724 1724 W NotificationHistory: Attempted to add notif for locked/gone/disabled user 10
01-01 00:25:28.454 26169 27173 I Pruner : Pruning took 278ms
01-01 00:25:28.455 26169 27173 I AppBackupWorker: Asking to do app backup now...
01-01 00:25:28.462 26169 26169 I WM-SystemFgDispatcher: Stopping foreground service
01-01 00:25:28.462 1724 9018 D ActivityManager: Stop FGS timeout: ServiceRecord{d995b2e u10 com.stevesoltys.seedvault/androidx.work.impl.foreground.SystemForegroundService c:com.stevesoltys.seedvault}
01-01 00:25:28.463 1724 9018 W ForegroundServiceTypeLoggerModule: FGS stop call for: 1010161 has no types!
01-01 00:25:28.500 26169 26187 I WM-WorkerWrapper: Work [ id=00fdd21e-e14f-4be2-98ff-28730ccd2a16, tags={ com.stevesoltys.seedvault.worker.AppBackupWorker } ] was cancelled
01-01 00:25:28.500 26169 26187 I WM-WorkerWrapper: java.util.concurrent.CancellationException: Task was cancelled.
01-01 00:25:28.500 26169 26187 I WM-WorkerWrapper: at androidx.work.impl.utils.futures.AbstractFuture.cancellationExceptionWithCause(AbstractFuture.java:1183)
01-01 00:25:28.500 26169 26187 I WM-WorkerWrapper: at androidx.work.impl.utils.futures.AbstractFuture.getDoneValue(AbstractFuture.java:513)
01-01 00:25:28.500 26169 26187 I WM-WorkerWrapper: at androidx.work.impl.utils.futures.AbstractFuture.get(AbstractFuture.java:474)
01-01 00:25:28.500 26169 26187 I WM-WorkerWrapper: at androidx.work.impl.WorkerWrapper.runWorker$lambda$11(WorkerWrapper.kt:245)
01-01 00:25:28.500 26169 26187 I WM-WorkerWrapper: at androidx.work.impl.WorkerWrapper.$r8$lambda$wkz9nWP-OXAEOk_gLJU6CNnQajg(Unknown Source:0)
01-01 00:25:28.500 26169 26187 I WM-WorkerWrapper: at androidx.work.impl.WorkerWrapper$$ExternalSyntheticLambda4.run(D8$$SyntheticClass:0)
01-01 00:25:28.500 26169 26187 I WM-WorkerWrapper: at androidx.work.impl.utils.SerialExecutorImpl$Task.run(SerialExecutorImpl.java:96)
01-01 00:25:28.500 26169 26187 I WM-WorkerWrapper: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
01-01 00:25:28.500 26169 26187 I WM-WorkerWrapper: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
01-01 00:25:28.500 26169 26187 I WM-WorkerWrapper: at java.lang.Thread.run(Thread.java:1012)
01-01 00:25:28.505 26169 27173 I AppBackupWorker: Start worker com.stevesoltys.seedvault.worker.AppBackupWorker@9695827 (a4313c46-2103-4bef-bd21-c841bb84a8fd)
01-01 00:25:28.505 26169 26169 I BackupStateManager: B - appBackupRunning: false, filesBackupRunning: false, appBackupWorker: ENQUEUED
01-01 00:25:28.509 26169 26169 I BackupStateManager: B - appBackupRunning: false, filesBackupRunning: false, appBackupWorker: RUNNING
01-01 00:25:28.510 26169 27190 I BackupStateManager: C - pruneBackupWorker: null, appCheckerWorker: null, fileCheckerWorker: null |
|
OK, here's a probably better log: Here I plugged in USB, opened Seedvault, the backup process started and the issue happened, took a log almost right away. Main profile. |
|
Hm, this doesn't seem to happen when I plug in my drive with Seedvault already open, but seems to when I plug it in and THEN open it. Suspecting it could be related to #735 |
|
In one of the cases where I plugged in with Seedvault open, I got a backup error, but it seems like #828 01-03 23:15:54.017 18013 18058 E AppBackupWorker: Error during 'beforeBackup':
01-03 23:15:54.017 18013 18058 E AppBackupWorker: android.database.StaleDataException: Attempted to access a cursor after it has been closed.
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at android.database.BulkCursorToCursorAdaptor.throwIfCursorIsClosed(BulkCursorToCursorAdaptor.java:63)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at android.database.BulkCursorToCursorAdaptor.getExtras(BulkCursorToCursorAdaptor.java:165)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at android.database.CursorWrapper.getExtras(CursorWrapper.java:117)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at org.calyxos.seedvault.core.backends.saf.SafHelperKt$getLoadedCursor$2.invokeSuspend(SafHelper.kt:199)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at org.calyxos.seedvault.core.backends.saf.SafHelperKt$getLoadedCursor$2.invoke(Unknown Source:8)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at org.calyxos.seedvault.core.backends.saf.SafHelperKt$getLoadedCursor$2.invoke(Unknown Source:4)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at kotlinx.coroutines.intrinsics.UndispatchedKt.startUndispatchedOrReturnIgnoreTimeout(Undispatched.kt:89)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at kotlinx.coroutines.TimeoutKt.setupTimeout(Timeout.kt:151)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at kotlinx.coroutines.TimeoutKt.withTimeout(Timeout.kt:46)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at org.calyxos.seedvault.core.backends.saf.SafHelperKt.getLoadedCursor(SafHelper.kt:195)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at org.calyxos.seedvault.core.backends.saf.SafHelperKt.getLoadedCursor$default(SafHelper.kt:194)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at org.calyxos.seedvault.core.backends.saf.SafHelperKt.listFilesBlocking(SafHelper.kt:112)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at org.calyxos.seedvault.core.backends.saf.SafBackend.listFilesRecursive(SafBackend.kt:194)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at org.calyxos.seedvault.core.backends.saf.SafBackend.list(SafBackend.kt:124)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at com.stevesoltys.seedvault.repo.AppBackupManager.beforeBackup(AppBackupManager.kt:64)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at com.stevesoltys.seedvault.worker.AppBackupWorker.doBackup(AppBackupWorker.kt:156)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at com.stevesoltys.seedvault.worker.AppBackupWorker.doWork(AppBackupWorker.kt:134)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at com.stevesoltys.seedvault.worker.AppBackupWorker$doWork$1.invokeSuspend(Unknown Source:14)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:108)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:584)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:793)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:697)
01-03 23:15:54.017 18013 18058 E AppBackupWorker: at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:684)Complete log: (Ignore the dates, I set up my time to be in the future so I could get things happening on schedule) Edit: tried again and it didn't fail in this situation so just seems like 828 for this case |
|
In seedvault-14-5.2-1735825936254.txt, at 10:51 it seems to try backing up while the flash drive isn't plugged in. Something was hammering us to start several backups at the same time: 01-02 10:51:41.324 16900 16900 D BackupService: onStartCommand Intent { cmp=com.stevesoltys.seedvault/.storage.StorageBackupService (has extras) } 0 3
01-02 10:51:41.325 16900 16900 D BackupService: onStartCommand Intent { cmp=com.stevesoltys.seedvault/.storage.StorageBackupService (has extras) } 0 4
01-02 10:51:41.325 16900 17266 W StorageBackup: Backup or check already running, not starting a new one |
|
Not seeing this with #835 (1597c9e). Note however that I didn't check beforehand and am not 100% sure how to reproduce it. What I've done is plug in a flash drive a few times and observed a backup happening automatically (I modded it for shorter frequencies, but that shouldn't be relevant). When doing this, I see a notification for file backup first, then "Preparing existing backups for rescue", so it's definitely sequential in this testing. |
The mentioned PR has a fix for that.
There's also a fix preventing the system from auto-restarting the file backup. That may have caused the unintentional parallelism: File backup failed due to #828 then started app backup and then was restarted again by system. So for now, I assume it fixed, we can open new issue or reopen this one if it isn't. |
|
I have tested #835 and the USB issues and this are fixed! |
|
Nice! Thank you for testing! Let's keep this open for now, until that PR ships. (It may change slightly before then, too.) |
I often notice (except when manually triggering a backup) that Seedvault triggers the app and file backup proccesses at the same time (or something else is going on that makes that happen), I notice that two notifications show up for each process, one for file backups and one for the apps. Everytime this happens though, the backup process fails.
I'll get logs next time this happens. I actually have one file right now but it seems more things failed.
seedvault-14-5.2-1735701949982.txt
Here it is in case it's useful but I'm not sure
The text was updated successfully, but these errors were encountered: