seedvault icon indicating copy to clipboard operation
seedvault copied to clipboard

"Backup running" notification sometimes remains after backup is complete

Open t-m-w opened this issue 8 months ago • 6 comments

The "Backup running" notification should always be removed when a backup is no longer running.

My last backup "failed" and notified me as such, but even now, a half an hour after the failure notification, there is still a notification present that says "Backup running" for Cromite.

I have occasionally seen this behavior (for various apps) even after an overall successful backup, too.

It can be confusing not knowing which to believe! :smile:

The relevant lines might be the ones with NotificationBackupObserver?

Logcat snippet
06-18 10:06:52.070 1010168 20318 20332 I NotificationBackupObserver: Completed. Target: org.calyxos.ripple, status: 0
06-18 10:06:52.075 1010168 20318 20332 I FullBackup: Perform full backup for org.cromite.cromite.
06-18 10:06:52.079 1010168 20318 20332 I BackupCoordinator: Get backup quota for org.cromite.cromite. Is full backup: true.
06-18 10:06:52.079 1010168 20318 20332 I BackupCoordinator: Reported quota of 9223372036854775807 bytes.
06-18 10:06:52.538 1010168 20318 20332 I FullBackup: Check full backup size of 26632192 bytes.
06-18 10:06:52.545 1010168 20318 20332 D FullBackup: Initializing OutputStream for org.cromite.cromite.
06-18 10:06:52.549 1010168 20318 21201 I NotificationBackupObserver: Showing progress notification for org.calyxos.ripple 233/253
06-18 10:06:52.550 1010168 20318 21201 I NotificationBackupObserver: 233/253 - Cromite (org.cromite.cromite)
[...]
06-18 10:07:07.122 1010168 20318 20416 E FullBackup: Error handling backup data for org.cromite.cromite: 
06-18 10:07:07.122 1010168 20318 20416 E FullBackup: java.io.IOException: Pipe closed
[...]
06-18 10:11:52.249  1000  1581 14419 D BackupManagerService: Timeout message received for token=5b634c50
06-18 10:11:52.546  1000  1581 14419 D BackupManagerService: Timeout message received for token=432d53c
06-18 10:11:52.546  1000  1581 14419 V LifecycleOperationStorage: [UserID:10] Cancel: token=432d53c
06-18 10:11:52.546  1000  1581 14419 W PFTBT   : Full backup cancel of org.cromite.cromite
06-18 10:11:52.553 1010168 20318 20416 I BackupCoordinator: Cancel full backup of org.cromite.cromite because of UNKNOWN_ERROR
06-18 10:11:52.554 1010331 25347 25347 I Process : Sending signal. PID: 25347 SIG: 9
06-18 10:11:52.627  1000  1581  4506 I ActivityManager: Process org.cromite.cromite (pid 25347) has died: bkup TRNB
06-18 10:11:52.628 shell 10848  1587 D BinderSender: onProcessDied: pid=25347, uid=1010331
06-18 10:11:52.628 shell 10848 13061 D BinderSender: onUidGone: uid=1010331, disabled=false
06-18 10:11:52.628 shell 10848 13061 V BinderSender: Uid 1010331 dead
06-18 10:11:52.629  root   864   864 I Zygote  : Process 25347 exited due to signal 9 (Killed)
06-18 10:11:52.629  1000  1581  1809 I libprocessgroup: Removed cgroup /sys/fs/cgroup/uid_1010331/pid_25347
06-18 10:11:52.629  1000  1581  1791 D DisplayManagerService: Drop pending events for gone uid 1010331
06-18 10:11:53.079  1000  1581 14228 E AppOps  : Operation not found: uid=1041 pkg=audioserver(null) op=WAKE_LOCK
06-18 10:11:53.080  1000  1581 14223 E AppOps  : Operation not found: uid=1041 pkg=audioserver(null) op=WAKE_LOCK
06-18 10:11:53.081  1000  1581  4506 E AppOps  : Operation not found: uid=1041 pkg=audioserver(null) op=WAKE_LOCK
06-18 10:11:53.082  1000  1581  4506 E AppOps  : Operation not found: uid=1041 pkg=audioserver(null) op=WAKE_LOCK
06-18 10:11:53.082  1000  1581  4506 E AppOps  : Operation not found: uid=1041 pkg=audioserver(null) op=WAKE_LOCK
06-18 10:11:53.086  1000  1581  4506 E AppOps  : Operation not found: uid=1041 pkg=audioserver(null) op=WAKE_LOCK
06-18 10:11:54.545  1000  1581 14223 E AppOps  : Operation not found: uid=1041 pkg=audioserver(null) op=WAKE_LOCK
06-18 10:11:55.059  1046  1145  3541 D BufferPoolAccessor2.0: evictor expired: 1, evicted: 0
06-18 10:11:56.060 media  1117  6242 D BufferPoolAccessor2.0: evictor expired: 1, evicted: 0
06-18 10:11:56.907 10167  3490  3503 I ndroid.systemui: Background concurrent mark compact GC freed 92MB AllocSpace bytes, 195(3136KB) LOS objects, 70% free, 39MB/135MB, paused 3.052ms,6.968ms total 714.982ms
06-18 10:11:56.959  1000  1581  2049 D ActivityManager: freezing 21437 com.google.android.gms
06-18 10:11:56.961  1000  1581  2049 D ActivityManager: freezing 24296 org.tasks
06-18 10:11:56.964  1000  1581  2049 D ActivityManager: freezing 24322 com.android.externalstorage
06-18 10:11:56.965  1000  1581  2049 D ActivityManager: freezing 24788 com.android.providers.calendar
06-18 10:11:57.060 media  1117  6242 D BufferPoolAccessor2.0: bufferpool2 0xe47c3748 : 0(0 size) total buffers - 0(0 size) used buffers - 78/86 (recycle/alloc) - 8/166 (fetch/transfer)
06-18 10:11:57.060 media  1117  6242 D BufferPoolAccessor2.0: evictor expired: 1, evicted: 1
06-18 10:11:57.060  1046  1145  3541 D BufferPoolAccessor2.0: bufferpool2 0xb4000072c866aa58 : 0(0 size) total buffers - 0(0 size) used buffers - 77/81 (recycle/alloc) - 4/80 (fetch/transfer)
06-18 10:11:57.060  1046  1145  3541 D BufferPoolAccessor2.0: evictor expired: 1, evicted: 1
06-18 10:11:57.278 10167  3490  3505 W System  : A resource failed to call close. 
06-18 10:11:57.278 10167  3490  3505 W System  : A resource failed to call close. 
06-18 10:12:01.780 1010168 20318 20355 D WebDavStorage: getOutputStream (redacted)
06-18 10:12:01.798 1010168 20318 20416 I FullBackup: Cancel full backup
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: Error cancelling full backup for org.cromite.cromite
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: java.io.IOException: at.bitfire.dav4jvm.exception.NotFoundException: HTTP 404 
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at com.stevesoltys.seedvault.plugins.webdav.WebDavStoragePlugin.removeData(WebDavStoragePlugin.kt:159)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at com.stevesoltys.seedvault.transport.backup.FullBackup.clearBackupData(FullBackup.kt:189)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at com.stevesoltys.seedvault.transport.backup.FullBackup.cancelFullBackup(FullBackup.kt:196)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at com.stevesoltys.seedvault.transport.backup.BackupCoordinator.cancelFullBackup(BackupCoordinator.kt:307)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at com.stevesoltys.seedvault.transport.ConfigurableBackupTransport$cancelFullBackup$1.invokeSuspend(ConfigurableBackupTransport.kt:207)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:108)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:280)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source:1)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source:1)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at com.stevesoltys.seedvault.transport.ConfigurableBackupTransport.cancelFullBackup(ConfigurableBackupTransport.kt:206)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at android.app.backup.BackupTransport$TransportImpl.cancelFullBackup(BackupTransport.java:910)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at com.android.internal.backup.IBackupTransport$Stub.onTransact(IBackupTransport.java:786)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at android.os.Binder.execTransactInternal(Binder.java:1505)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at android.os.Binder.execTransact(Binder.java:1444)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: Caused by: at.bitfire.dav4jvm.exception.NotFoundException: HTTP 404 
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at at.bitfire.dav4jvm.DavResource.checkStatus(DavResource.kt:583)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at at.bitfire.dav4jvm.DavResource.checkStatus(DavResource.kt:565)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at at.bitfire.dav4jvm.DavResource.delete(DavResource.kt:441)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at at.bitfire.dav4jvm.DavResource.delete$default(DavResource.kt:429)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	at com.stevesoltys.seedvault.plugins.webdav.WebDavStoragePlugin.removeData(WebDavStoragePlugin.kt:152)
06-18 10:12:03.024 1010168 20318 20416 W FullBackup: 	... 17 more
06-18 10:12:03.052  1000  1581 24858 W PFTBT   : Error -1000 backing up org.cromite.cromite
06-18 10:12:03.056 1010168 20318 20416 I BackupCoordinator: Request full backup time. Returned 0
06-18 10:12:03.057  1000  1581 24858 I PFTBT   : Transport suggested backoff=0
06-18 10:12:03.057  1000  1581 24858 W PFTBT   : Transport failed; aborting backup: -1000
06-18 10:12:03.057 1010168 20318 20416 I NotificationBackupObserver: Completed. Target: org.cromite.cromite, status: -1000
06-18 10:12:03.058  1000  1581 24858 W ActivityManager: Unbinding backup agent with no active backup
06-18 10:12:03.058  1000  1581 24858 W ActivityManager: Process/uid not found attempting kill of org.cromite.cromite / 1010331
06-18 10:12:03.058  1000  1581 24858 I PFTBT   : Full backup completed with status: -1000
06-18 10:12:03.058 1010168 20318 20416 I NotificationBackupObserver: Backup finished 234/253. Status: -1000
06-18 10:12:03.061  1000  1581 25341 E BackupManagerService: Error backing up org.cromite.cromite: write failed: EPIPE (Broken pipe)
06-18 10:12:03.066 1010168 20318 20318 I BackupStateManager: appBackupRunning: false, filesBackupRunning: false, workInfoState: ENQUEUED
06-18 10:12:03.067 1010168 20318 20318 D ConfigurableBackupTransportService: Service destroyed.

t-m-w avatar Jun 18 '24 14:06 t-m-w