Storage provider (Davx5) is killed during restoration, failing the entire process - at least with D2D
t-m-w opened this issue · 2 comments
t-m-w commented
Steps to reproduce:
- Have a backup which includes Davx5, probably with some existing Davx5 configuration.
- Have D2D turned on (unsure if optional).
- Restore the backup (I did so in a work profile).
Expected result: Davx5 does not get killed, and restore process continues.
Actual result: It does.
Logcat snippet
Tried to narrow it down to the relevant bits, since there's a lot of private stuff or even just annoyances in the logs.
06-17 11:38:59.421 1000 1783 7181 D BackupManagerService: restoreFinished packageName=org.fdroid.fdroid
06-17 11:38:59.426 1000 1783 7181 D BackupManagerService: Restore complete, killing host process of org.fdroid.fdroid
06-17 11:38:59.428 1010166 8290 10849 I RestoreCoordinator: Next restore package!
06-17 11:38:59.444 1010166 8290 10849 D DocumentsStorage: Wait for children to get loaded...
06-17 11:38:59.456 1000 1783 1783 I NotificationService: Cannot find enqueued record for key: 10|at.bitfire.davdroid|12|redacted
06-17 11:38:59.618 1010166 8290 8880 D DocumentsStorage: Children loaded. Continue...
06-17 11:38:59.679 1010166 8290 10849 I RestoreCoordinator: Found full backup data for com.termoneplus.
06-17 11:38:59.679 1000 1783 7181 I BackupManagerService: Next restore package: RestoreDescription{com.termoneplus : STREAM}
06-17 11:38:59.684 1010166 8290 10849 I FullRestore: First Chunk, initializing package input stream.
06-17 11:38:59.697 1010166 8290 10849 D DocumentsStorage: Wait for children to get loaded...
06-17 11:38:59.833 1010166 8290 8880 D DocumentsStorage: Children loaded. Continue...
06-17 11:39:00.045 1010166 8290 10849 I FullRestore: EOF
06-17 11:39:00.046 1000 1783 11112 I BackupManagerService: Sig + version match; taking data
06-17 11:39:00.046 1000 1783 11112 D BackupManagerService: Clearing app data preparatory to full restore
06-17 11:39:00.078 1000 1783 11112 D BackupManagerService: [UserID:10] awaiting agent for ApplicationInfo{56a87db com.termoneplus}
06-17 11:39:00.104 1000 1783 2064 I ActivityManager: Start proc 11141:com.termoneplus/u10a330 for backup {android/FullBackupAgent}
06-17 11:39:00.175 1000 1783 10850 D BackupManagerService: [UserID:10] agentConnected pkg=com.termoneplus agent=android.os.BinderProxy@688823e
06-17 11:39:00.175 1000 1783 11112 I BackupManagerService: [UserID:10] got agent android.app.IBackupAgent$Stub$Proxy@9c2889f
06-17 11:39:00.201 1000 1783 7181 D BackupManagerService: restoreFinished packageName=com.termoneplus
06-17 11:39:00.204 1000 1783 7181 D BackupManagerService: Restore complete, killing host process of com.termoneplus
06-17 11:39:00.206 1010166 8290 8304 I RestoreCoordinator: Next restore package!
06-17 11:39:00.219 1010166 8290 8304 D DocumentsStorage: Wait for children to get loaded...
06-17 11:39:00.233 1000 1783 1783 I NotificationService: Cannot find enqueued record for key: 10|at.bitfire.davdroid|12|redacted
06-17 11:39:00.379 1010166 8290 8880 D DocumentsStorage: Children loaded. Continue...
06-17 11:39:00.511 1010166 8290 8304 I RestoreCoordinator: Found full backup data for at.bitfire.davdroid.
06-17 11:39:00.511 1000 1783 7181 I BackupManagerService: Next restore package: RestoreDescription{at.bitfire.davdroid : STREAM}
06-17 11:39:00.518 1010166 8290 8863 I FullRestore: First Chunk, initializing package input stream.
06-17 11:39:00.530 1010166 8290 8863 D DocumentsStorage: Wait for children to get loaded...
06-17 11:39:00.680 1010166 8290 8304 D DocumentsStorage: Children loaded. Continue...
06-17 11:39:00.947 1000 1783 11161 I BackupManagerService: Sig + version match; taking data
06-17 11:39:00.947 1000 1783 11161 D BackupManagerService: Clearing app data preparatory to full restore
06-17 11:39:00.955 1000 1783 11161 I ActivityManager: Killing 8290:com.stevesoltys.seedvault/u10a166 (adj 0): depends on provider at.bitfire.davdroid/.webdav.DavDocumentsProvider in dying proc at.bitfire.davdroid (adj -10000)
06-17 11:39:01.042 1000 1783 2118 I libprocessgroup: Successfully killed process cgroup uid 1010166 pid 8290 in 0ms
06-17 11:39:01.044 1000 1783 10795 I ImeTracker: com.stevesoltys.seedvault:404cbee0: onRequestHide at ORIGIN_SERVER_HIDE_INPUT reason HIDE_REMOVE_CLIENT
06-17 11:39:01.045 1000 1783 10795 I ImeTracker: com.stevesoltys.seedvault:404cbee0: onCancelled at PHASE_SERVER_SHOULD_HIDE
06-17 11:39:01.045 1000 1783 1783 E TransportConnection: ConfigurableBackupTransportService#8: Service disconnected: client UNUSABLE
06-17 11:39:01.046 1000 1783 1783 W ActivityManager: Exception when unbinding service com.stevesoltys.seedvault/.transport.ConfigurableBackupTransportService
06-17 11:39:01.046 1000 1783 1783 W ActivityManager: at com.android.server.backup.transport.TransportConnection.onServiceDisconnected(TransportConnection.java:458)
06-17 11:39:01.046 1000 1783 1783 W ActivityManager: at com.android.server.backup.transport.TransportConnection.-$$Nest$monServiceDisconnected(TransportConnection.java:0)
06-17 11:39:01.046 1000 1783 1783 W ActivityManager: at com.android.server.backup.transport.TransportConnection$TransportConnectionMonitor.onServiceDisconnected(TransportConnection.java:692)
06-17 11:39:01.047 1000 1783 10850 I WindowManager: WIN DEATH: Window{e8072e1 u10 com.stevesoltys.seedvault/com.stevesoltys.seedvault.restore.RestoreActivity}
06-17 11:39:01.047 1000 1783 10850 W InputManager-JNI: Input channel object 'e8072e1 com.stevesoltys.seedvault/com.stevesoltys.seedvault.restore.RestoreActivity (client)' was disposed without first being removed with the input manager!
06-17 11:39:01.061 1000 1783 11161 D BackupManagerService: [UserID:10] awaiting agent for ApplicationInfo{ff0c55 at.bitfire.davdroid}
06-17 11:39:01.083 1000 1783 1783 I NotificationService: Cannot find enqueued record for key: 10|at.bitfire.davdroid|12|redacted
06-17 11:39:01.173 1000 1783 2025 D DisplayManagerService: Drop pending events for gone uid 1010166
06-17 11:39:01.173 1000 1783 3170 W ActivityTaskManager: Force removing ActivityRecord{961c557 u10 com.stevesoltys.seedvault/.restore.RestoreActivity t48}: app died, no saved state
06-17 11:39:01.184 1000 1783 6992 I ActivityManager: Start proc 11177:at.bitfire.davdroid/u10a214 for backup {android/FullBackupAgent}
06-17 11:39:01.247 1000 1783 11171 D BackupManagerService: [UserID:10] agentConnected pkg=at.bitfire.davdroid agent=android.os.BinderProxy@f75a6a3
06-17 11:39:01.249 1000 1783 11161 I BackupManagerService: [UserID:10] got agent android.app.IBackupAgent$Stub$Proxy@2efcda0
06-17 11:39:01.272 1000 1783 11160 W BackupManagerService: backup manager monitor went away
06-17 11:39:01.283 1000 1783 11161 W BackupManagerService: io exception on restore socket read: Unexpected EOF in padding
06-17 11:39:01.284 1000 1783 11160 W TransportConnection: ConfigurableBackupTransportService#8: [PerformUnifiedRestoreTask$StreamFeederThread.run()] Sync connect: UNUSABLE client
06-17 11:39:01.284 1000 1783 11160 E TransportConnection: ConfigurableBackupTransportService#8: [PerformUnifiedRestoreTask$StreamFeederThread.run()] Transport connection failed
06-17 11:39:01.294 1000 1783 2063 W BackupManagerService: agentDisconnected: the backup agent for at.bitfire.davdroid died: cancel current operations
06-17 11:39:01.324 1000 1783 2063 W BackupManagerService: agentDisconnected: the backup agent for at.bitfire.davdroid died: cancel current operations
06-17 11:39:01.328 1000 1783 7181 W TransportConnection: ConfigurableBackupTransportService#8: [PerformUnifiedRestoreTask.finalizeRestore()] Sync connect: UNUSABLE client
06-17 11:39:01.328 1000 1783 7181 E TransportConnection: ConfigurableBackupTransportService#8: [PerformUnifiedRestoreTask.finalizeRestore()] Transport connection failed
06-17 11:39:01.328 1000 1783 7181 E BackupManagerService: Error finishing restore
06-17 11:39:01.328 1000 1783 7181 E BackupManagerService: com.android.server.backup.transport.TransportNotAvailableException: Transport not available
06-17 11:39:01.328 1000 1783 7181 E BackupManagerService: at com.android.server.backup.transport.TransportConnection.connectOrThrow(TransportConnection.java:374)
06-17 11:39:01.328 1000 1783 7181 E BackupManagerService: at com.android.server.backup.restore.PerformUnifiedRestoreTask.finalizeRestore(PerformUnifiedRestoreTask.java:1318)
06-17 11:39:01.328 1000 1783 7181 E BackupManagerService: at com.android.server.backup.restore.PerformUnifiedRestoreTask.execute(PerformUnifiedRestoreTask.java:351)
06-17 11:39:01.328 1000 1783 7181 E BackupManagerService: at com.android.server.backup.internal.BackupHandler.handleMessage(BackupHandler.java:277)
06-17 11:39:01.328 1000 1783 7181 E BackupManagerService: at android.os.Handler.dispatchMessage(Handler.java:107)
06-17 11:39:01.328 1000 1783 7181 E BackupManagerService: at com.android.server.backup.internal.BackupHandler.dispatchMessageInternal(BackupHandler.java:138)
06-17 11:39:01.328 1000 1783 7181 E BackupManagerService: at com.android.server.backup.internal.BackupHandler.dispatchMessage(BackupHandler.java:126)
06-17 11:39:01.328 1000 1783 7181 E BackupManagerService: at android.os.Looper.loopOnce(Looper.java:232)
06-17 11:39:01.328 1000 1783 7181 E BackupManagerService: at android.os.Looper.loop(Looper.java:317)
06-17 11:39:01.328 1000 1783 7181 E BackupManagerService: at android.os.HandlerThread.run(HandlerThread.java:68)
06-17 11:39:01.329 1000 1783 7181 D BackupManagerService: Restore observer died at restoreFinished
06-17 11:39:01.329 1000 1783 7181 I BackupRestoreController: systemRestoreFinished for 10
06-17 11:39:01.329 1000 1783 7181 I BackupRestoreController: maybeSendWidgetRestoreBroadcasts for 10
06-17 11:39:01.347 1000 1783 7181 V BackupManagerService: [UserID:10] Ancestral packages: 193
06-17 11:39:01.461 1000 1783 7181 I BackupManagerService: Restore complete.
06-17 11:39:01.462 1000 1783 7181 W BackupManagerService: backup manager monitor is null unable to send event
06-17 11:39:01.463 1000 1783 7181 V BackupManagerService: [UserID:10] Released wakelock:*backup*-10-7181
grote commented
Key lines:
BackupManagerService: Clearing app data preparatory to full restore
ActivityManager: Killing 8290:com.stevesoltys.seedvault/u10a166 (adj 0): depends on provider at.bitfire.davdroid/.webdav.DavDocumentsProvider in dying proc at.bitfire.davdroid (adj -10000)