search

seedvault-app / seedvault

A backup application for the Android Open Source Project.
1.19k stars 73 forks source link

Storage provider (Davx5) is killed during restoration, failing the entire process - at least with D2D #687

Closed t-m-w closed 1 week ago

t-m-w commented 2 weeks ago

Steps to reproduce:

  1. Have a backup which includes Davx5, probably with some existing Davx5 configuration.
  2. Have D2D turned on (unsure if optional).
  3. 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 2 weeks ago

Related to https://github.com/seedvault-app/seedvault/issues/230, should have been fixed by https://github.com/seedvault-app/seedvault/pull/422

grote commented 1 week ago

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)