"Backup running" notification sometimes remains after backup is complete #694
Comments
|
Looks like there's around I only see two options:
|
|
Here we had 5ms: 06-20 11:18:36.755 1010168 30423 31899 I NotificationBackupObserver: Backup finished 253/253. Status: 0
06-20 11:18:36.760 1010168 30423 30423 I BackupStateManager: appBackupRunning: false, filesBackupRunning: false, workInfoState: ENQUEUED
06-20 11:18:36.760 1000 1581 22520 I PFTBT : Full data backup pass finished.
06-20 11:18:36.760 1010168 30423 30423 I BackupStateManager: appBackupRunning: false, filesBackupRunning: false, workInfoState: ENQUEUED
06-20 11:18:36.760 1010168 30423 30423 D ConfigurableBackupTransportService: Service destroyed.
06-20 11:18:36.761 1000 1581 22520 V BackupManagerService: [UserID:10] Released wakelock:*backup*-10-23616 |
|
Turns out that my theory that our process simply got killed fast is wrong. We can in fact keep running for quite some time after the backup transport service was destroyed. This makes it even more of a mystery why the notification sometimes stays around. |
|
New theory: In the same millisecond (above one ms before) we cancel the notification, we update the same notification with the status of the app backup ( So maybe there's a race-condition between this cancel and the update, if the system 07-02 16:44:40.768 1320 12557 E BackupManagerService: Error backing up org.fdroid.basic: write failed: EPIPE (Broken pipe)
07-02 16:44:40.768 1320 12557 W ActivityManager: Unbinding backup agent with no active backup
07-02 16:44:40.769 1320 12557 W ActivityManager: Process/uid not found attempting kill of org.fdroid.basic / 10210
07-02 16:44:40.775 1320 12140 I PFTBT : Full data backup pass finished.
07-02 16:44:40.777 3917 3917 I BackupStateManager: appBackupRunning: false, filesBackupRunning: false, workInfoState: ENQUEUED
07-02 16:44:40.777 3917 7338 I NotificationBackupObserver: Completed. Target: org.fdroid.basic, status: -1000
07-02 16:44:40.777 3917 7338 E NotificationBackupObserver: CANCELLING NOTIFICATION
07-02 16:44:40.777 3917 3917 I BackupStateManager: appBackupRunning: false, filesBackupRunning: false, workInfoState: ENQUEUED
07-02 16:44:40.778 3917 7338 I NotificationBackupObserver: Backup finished 257/270. Status: -1000
07-02 16:44:40.778 3917 3917 D ConfigurableBackupTransportService: Service destroyed.
07-02 16:44:40.779 1320 12140 V BackupManagerService: [UserID:0] Released wakelock:*backup*-0-2657 |
|
Comment from the code: So this sounds like are aware of a potential race and took measures to avoid it. Also, the callbacks into our In the code, there are some conditions when the system doesn't cancel our notification. We can test for those and see if they are at fault. |
|
hacky debug code we used to check for notification flags: Log.e("TEST", "CANCEL NOTIFICATION!")
val mustHaveFlags = 0
val mustNotHaveFlags =
(FLAG_FOREGROUND_SERVICE or
Notification.FLAG_USER_INITIATED_JOB or
Notification.FLAG_AUTOGROUP_SUMMARY or 0x00010000)
nm.activeNotifications.forEach {
if (it.packageName == context.packageName) {
val flags = it.notification.flags
Log.e(
"TEST",
"${it.id} ${it.isOngoing} ${it.postTime} ${it.notification.channelId}"
)
Log.e(
"TEST",
"$ mustHaveFlags $flags - ${(flags and mustHaveFlags) != mustHaveFlags}"
)
Log.e("TEST", "$ mustNotHaveFlags $flags - ${(flags and mustNotHaveFlags) != 0}")
}
} |
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! 😄
The relevant lines might be the ones with NotificationBackupObserver?
Logcat snippet
The text was updated successfully, but these errors were encountered: