Backup to Davx5 fails with "Couldn't get operation status from transport" in log

[t-m-w]

Issue reported by a user. They can reproduce it 100% of the time with Davx5 -> Nextcloud backups, even with the disable-Circles-app workaround mentioned in #490 (which merely changes the cause of the backup failure to this).

What would cause this?

The backup of APKs seems to continue even after the @pm@ metadata backup seemingly fails out of nowhere.

Maybe related/similar to #471.

NOTE: Timestamps not included here, but exactly 5 minutes elapse between PMBA : Previous metadata null mismatch vs 22404000 - rewriting and W TransportStatusCallback: Couldn't get operation status from transport. From framework code as well, this appears to be a timeout.

Log ("details open" for easier search)

D ConfigurableBackupTransportService: Backup is enabled, request backup...
I BackupNotificationManager: 0/168 - 0% - 
D ConfigurableBackupTransportService: Service created.
ConfigurableBackupTransportService: Transport bound.
I TransportConnection: ConfigurableBackupTransportService#24: Notifying [BMS.getOperationTypeFromTransport] transport = BackupTransportClient
I ConfigurableBackupTransportService: Backup succeeded 
V BackupManagerService: [UserID:0] Acquired wakelock:*backup*-0-2677
D KeyValueBackupTask: Spinning thread key-value-backup-8
D PFTBT   : backupmanager pftbt token=redacted.token
V KeyValueBackupTask: Beginning backup of 15 targets
I KeyValueBackupTask: Initializing transport and resetting backup state
I BackupCoordinator: Initialize Device!
D DocumentsStorage: Wait for children to get loaded...
D DocumentsStorage: Children loaded. Continue...
[...]
D KeyValueBackupTask: Starting key-value backup of @pm@
KeyValueBackupTask: Invoking agent on @pm@
I BackupCoordinator: Get backup quota for @pm@. Is full backup: false.
I BackupCoordinator: Reported quota of 10485760 bytes.
I PMBA    : Previous metadata null mismatch vs 22404000 - rewriting
I BackupRestoreController: Getting widget state for user: 0
I KVBackup: Performing non-incremental K/V backup for @pm@
V KVBackup:   Delta operation key @ancestral_record@   size 4
[...]
V KVBackup:   Delta operation key android.auto_generated_rro_vendor__   size 44
I KVBackup: Finish K/V Backup of @pm@ - needs upload: true
D KVBackup: Uploaded db file for @pm@
D BackupCoordinator: Checking if APKs of opt-out apps need backup...
I PackageService: 19 apps do not allow backup:
I PackageService: [redacted.package.01, redacted.package.02, redacted.package.03, redacted.package.04, redacted.package.05, redacted.package.06, redacted.package.07, redacted.package.08, redacted.package.09, redacted.package.10, redacted.package.11, redacted.package.12, redacted.package.13, redacted.package.14, redacted.package.15, redacted.package.16, redacted.package.17, redacted.package.18, redacted.package.19]
I BackupNotificationManager: 1/187 - 1% - Opt-out APK for redacted.package.01
D ApkBackup: Backed up new APK of redacted.package.01 with version redacted.version.01.
D DocumentsStorage: Wait for children to get loaded...
D DocumentsStorage: Children loaded. Continue...
I BackupNotificationManager: 2/168 - 1% - Opt-out APK for redacted.package.02
[...]
I BackupNotificationManager: 14/187 - 7% - Opt-out APK for redacted.package.14
D DocumentsStorage: Wait for children to get loaded...
D DocumentsStorage: Children loaded. Continue...
D ApkBackup: Backed up new APK of redacted.package.14 with version redacted.version.14.
I BackupNotificationManager: 15/187 - 8% - Opt-out APK for redacted.package.15
D DocumentsStorage: Wait for children to get loaded...
D DocumentsStorage: Children loaded. Continue...
W TransportStatusCallback: Couldn't get operation status from transport
E KeyValueBackupTask: Error during PM metadata backup
E KeyValueBackupTask: com.android.server.backup.keyvalue.TaskException
E KeyValueBackupTask: 	at com.android.server.backup.keyvalue.KeyValueBackupTask.handleTransportStatus(KeyValueBackupTask.java:1135)
E KeyValueBackupTask: 	at com.android.server.backup.keyvalue.KeyValueBackupTask.sendDataToTransport(KeyValueBackupTask.java:1069)
E KeyValueBackupTask: 	at com.android.server.backup.keyvalue.KeyValueBackupTask.sendDataToTransport(KeyValueBackupTask.java:576)
E KeyValueBackupTask: 	at com.android.server.backup.keyvalue.KeyValueBackupTask.backupPm(KeyValueBackupTask.java:681)
E KeyValueBackupTask: 	at com.android.server.backup.keyvalue.KeyValueBackupTask.run(KeyValueBackupTask.java:367)
E KeyValueBackupTask: 	at java.lang.Thread.run(Thread.java:1012)
I NotificationBackupObserver: Completed. Target: @pm@, status: -1000
I NotificationBackupObserver: Showing progress notification for null 0/168
I BackupNotificationManager: 20/187 - 10% - System package manager
[...]
D ApkBackup: Backed up new APK of redacted.package.15 with version redacted.version.15
I BackupNotificationManager: 16/187 - 9% - Opt-out APK for redacted.package.16
D DocumentsStorage: Wait for children to get loaded...
D DocumentsStorage: Children loaded. Continue...
D ApkBackup: Backed up new APK of redacted.package.16 with version redacted.version.16.
I BackupNotificationManager: 17/187 - 9% - Opt-out APK for redacted.package.17
D DocumentsStorage: Wait for children to get loaded...
D DocumentsStorage: Children loaded. Continue...
D ApkBackup: Backed up new APK of redacted.package.17 with version redacted.version.17.
I BackupNotificationManager: 18/187 - 10% - Opt-out APK for redacted.package.18
D DocumentsStorage: Wait for children to get loaded...
D DocumentsStorage: Children loaded. Continue...
D ApkBackup: Backed up new APK of redacted.package.18 with version redacted.version.18.
I BackupNotificationManager: 19/187 - 10% - Opt-out APK for redacted.package.19
D DocumentsStorage: Wait for children to get loaded...
D DocumentsStorage: Children loaded. Continue...
D ApkBackup: Backed up new APK of redacted.package.19 with version redacted.version.19.
I BackupCoordinator: Request incremental backup time. Returned 0
I KeyValueBackupTask: K/V backup pass finished
I NotificationBackupObserver: Backup finished 1/168. Status: -1000
V BackupManagerService: [UserID:0] Released wakelock:*backup*-0-2677
W BackupNotificationManager: Needed to clean up notification with ID 1
D ConfigurableBackupTransportService: Service destroyed.

Logs with more detail available if needed, but Davx5 info is not included because Verbose Logging was not enabled. (Davx5's Verbose Logging shares way too much info, currently, but at least it warns as much.)

[grote]

Hard to tell what's going on without DavX5 logs. Might be a reproducible I/O error, maybe causes by nextcloud locking a file or something like that?

[grote]

We have a user that did backup to USB that ran into the same issue. Here a shortened log:

11-22 12:11:57.713  1540  6450 V BackupManagerService: [UserID:0] Acquired wakelock:*backup*-0-6450
11-22 12:11:57.714  1540  6450 D KeyValueBackupTask: Spinning thread key-value-backup-5
11-22 12:11:57.731  1540 17832 D PFTBT   : backupmanager pftbt token=6d9dde11
11-22 12:11:57.732  1540 17832 V KeyValueBackupTask: Beginning backup of 27 targets
11-22 12:11:57.738  1540 17832 I KeyValueBackupTask: Initializing transport and resetting backup state
11-22 12:11:57.746  1540 17832 V BackupManagerService: [UserID:0] Ancestral packages:  225
11-22 12:11:57.899  1540  1540 W NotificationHistory: Attempted to add notif for locked/gone/disabled user 0
11-22 12:11:59.124  1540 17832 D KeyValueBackupTask: Starting key-value backup of @pm@
11-22 12:11:59.152  1540 17832 D KeyValueBackupTask: Invoking agent on @pm@
11-22 12:11:59.185  1540 17832 I PMBA    : Previous metadata null mismatch vs 23501000 - rewriting
11-22 12:11:59.255  1540 17832 I BackupRestoreController: Getting widget state for user: 0
...
11-22 12:27:00.914  1540 17832 W TransportStatusCallback: Couldn't get operation status from transport
11-22 12:27:00.921  1540 17832 E KeyValueBackupTask: Error during PM metadata backup
11-22 12:27:00.921  1540 17832 E KeyValueBackupTask: com.android.server.backup.keyvalue.TaskException
11-22 12:27:00.921  1540 17832 E KeyValueBackupTask: 	at com.android.server.backup.keyvalue.KeyValueBackupTask.handleTransportStatus(KeyValueBackupTask.java:1138)
11-22 12:27:00.921  1540 17832 E KeyValueBackupTask: 	at com.android.server.backup.keyvalue.KeyValueBackupTask.sendDataToTransport(KeyValueBackupTask.java:1072)
11-22 12:27:00.921  1540 17832 E KeyValueBackupTask: 	at com.android.server.backup.keyvalue.KeyValueBackupTask.sendDataToTransport(KeyValueBackupTask.java:577)
11-22 12:27:00.921  1540 17832 E KeyValueBackupTask: 	at com.android.server.backup.keyvalue.KeyValueBackupTask.backupPm(KeyValueBackupTask.java:682)
11-22 12:27:00.921  1540 17832 E KeyValueBackupTask: 	at com.android.server.backup.keyvalue.KeyValueBackupTask.run(KeyValueBackupTask.java:368)
11-22 12:27:00.921  1540 17832 E KeyValueBackupTask: 	at java.lang.Thread.run(Thread.java:1012)

One idea here is that this ran into a timeout when doing opt-out apps' APK backup. Unfortunately, it seems like Seedvault itself isn't part of this log.