Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

"Pipe closed" when file measurements take long time #693

Open
t-m-w opened this issue Jun 18, 2024 · 5 comments
Open

"Pipe closed" when file measurements take long time #693

t-m-w opened this issue Jun 18, 2024 · 5 comments
Assignees
@grote
Labels
bug
Milestone
Roadmap

Comments

@t-m-w
Copy link
Collaborator

t-m-w commented Jun 18, 2024 •
edited
Loading

D2D enabled, unlimited quota.

This is currently only happening for me in a couple of work profiles. I can't reproduce it on a test device, in or out of a work profile - at least for Brave.

Backup fails, and notification for backing up Brave remains for quite a while before proceeding. This happens on each backup attempt. At the end, an overall failure is reported, with "0 B" backed up.

I do not have the log for Nextcloud, currently, but here it is for Brave, starting with the app backed up prior to Brave (Aurora Store). I cut it off at this particular failure point, because as of this writing, the backup is still running.

brave_backup_failure_pipe_closed.txt
@t-m-w t-m-w added the bug label Jun 18, 2024
@grote
Copy link
Collaborator

grote commented Jun 18, 2024 •
edited
Loading

This is weird. Measuring the files takes so long, it even continues after it already started to send data. Even after Check full backup size of 37605376 bytes. it is still measuring. Problem is that at 10:00:40.467 where are initializing the output stream (probably because the system started sending data) which for WebDAV means starting the HTTP request. Then at 10:00:43.683 it is still measuring files and probably not sending any data, so we run into an HTTP timeout.

06-18 10:00:40.012 1010168 20318 21201 I FullBackup: Perform full backup for com.brave.browser.
06-18 10:00:40.014 1010168 20318 21201 I BackupCoordinator: Get backup quota for com.brave.browser. Is full backup: true.
06-18 10:00:40.015 1010168 20318 21201 I BackupCoordinator: Reported quota of 9223372036854775807 bytes.
06-18 10:00:40.153  1000  1581 14351 D BackupManagerService: [UserID:10] agentConnected pkg=com.brave.browser agent=android.os.BinderProxy@8de5499
06-18 10:00:40.153  1000  1581 24267 I BackupManagerService: [UserID:10] got agent android.app.IBackupAgent$Stub$Proxy@bc6d35e
06-18 10:00:40.167 1010259 24273 24288 I FullBackup_native: measured [/data/user/10/com.brave.browser] at 0
06-18 10:00:40.167 1010259 24273 24288 I FullBackup_native: measured [/data/user/10/com.brave.browser/app_top_sites] at 512
[...]
06-18 10:00:40.463 1010259 24273 24288 I FullBackup_native: measured [/storage/emulated/10/Android/data/com.brave.browser/files/Download] at 512
06-18 10:00:40.464 1010168 20318 21201 I FullBackup: Check full backup size of 37605376 bytes.
06-18 10:00:40.467  1000  1581 24289 I file_backup_helper:    Name: apps/com.brave.browser/_manifest
06-18 10:00:40.467  1000  1581 24289 I FullBackup_native: measured [/data/system_ce/10/backup_stage/_manifest] at 2560
06-18 10:00:40.467  1000  1581 24289 I BackupRestoreController: Getting widget state for user: 10
06-18 10:00:40.467 1010168 20318 21201 D FullBackup: Initializing OutputStream for com.brave.browser.
06-18 10:00:40.467  1000  1581 24289 D BackupManagerService: Calling doFullBackup() on com.brave.browser
06-18 10:00:40.468 1010168 20318 21201 I NotificationBackupObserver: Showing progress notification for com.aurora.store 195/253
06-18 10:00:40.470 1010168 20318 21201 I NotificationBackupObserver: 195/253 - Brave (com.brave.browser)
06-18 10:00:40.472 1010259 24273 24288 I FullBackup_native: measured [/data/user/10/com.brave.browser] at 0
06-18 10:00:40.472 1010259 24273 24288 I file_backup_helper:    Name: apps/com.brave.browser/r/app_top_sites
06-18 10:00:40.472 1010259 24273 24288 I FullBackup_native: measured [/data/user/10/com.brave.browser/app_top_sites] at 512
[...]
06-18 10:00:42.661 1010259 24273 24288 I FullBackup_native: measured [/data/user/10/com.brave.browser/app_chrome/oofiananboodjbbmdelgdommihjbkfag/1.0.170/6.0/httpse.leveldb/000006.log] at 512
06-18 10:00:42.662 1010259 24273 24288 I file_backup_helper:    Name: apps/com.brave.browser/r/app_chrome/oofiananboodjbbmdelgdommihjbkfag/1.0.170/6.0/httpse.leveldb/000005.ldb
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: Error handling backup data for com.brave.browser: 
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: java.io.IOException: Pipe closed
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at java.io.PipedInputStream.checkStateForReceive(PipedInputStream.java:263)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at java.io.PipedInputStream.awaitSpace(PipedInputStream.java:271)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at java.io.PipedInputStream.receive(PipedInputStream.java:234)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at java.io.PipedOutputStream.write(PipedOutputStream.java:149)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at com.google.crypto.tink.subtle.StreamingAeadEncryptingStream.write(StreamingAeadEncryptingStream.java:85)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at com.google.crypto.tink.subtle.StreamingAeadEncryptingStream.write(StreamingAeadEncryptingStream.java:59)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at com.stevesoltys.seedvault.transport.backup.FullBackup.sendBackupData(FullBackup.kt:177)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at com.stevesoltys.seedvault.transport.backup.BackupCoordinator.sendBackupData(BackupCoordinator.kt:280)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at com.stevesoltys.seedvault.transport.ConfigurableBackupTransport$sendBackupData$1.invokeSuspend(ConfigurableBackupTransport.kt:203)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:108)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:280)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source:1)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source:1)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at com.stevesoltys.seedvault.transport.ConfigurableBackupTransport.sendBackupData(ConfigurableBackupTransport.kt:202)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at android.app.backup.BackupTransport$TransportImpl.sendBackupData(BackupTransport.java:900)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at com.android.internal.backup.IBackupTransport$Stub.onTransact(IBackupTransport.java:778)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at android.os.Binder.execTransactInternal(Binder.java:1505)
06-18 10:00:43.683 1010168 20318 21201 E FullBackup: 	at android.os.Binder.execTransact(Binder.java:1444)

@t-m-w I guess this build already includes #677 ?

@grote grote changed the title "Pipe closed" when backing up Brave browser or Nextcloud "Pipe closed" when file measurements take long time Jun 18, 2024
@t-m-w
Copy link
Collaborator Author

t-m-w commented Jun 18, 2024

This happened ~5min later, past the end of the above log, and then it resumed until it came to Cromite, where the same thing happened.

06-18 10:05:40.471  1000  1581 14419 W PFTBT   : Full backup cancel of com.brave.browser
06-18 10:05:40.478 1010259 24273 24273 I Process : Sending signal. PID: 24273 SIG: 9
06-18 10:05:40.481 1010168 20318 20330 I BackupCoordinator: Cancel full backup of com.brave.browser because of UNKNOWN_ERROR
06-18 10:05:40.563  1000  1581 14061 I ActivityManager: Process com.brave.browser (pid 24273) has died: bkup TRNB
06-18 10:05:40.564  root   864   864 I Zygote  : Process 24273 exited due to signal 9 (Killed)
06-18 10:05:40.565 shell 10848 13061 D BinderSender: onProcessDied: pid=24273, uid=1010259
06-18 10:05:40.565 shell 10848  4941 D BinderSender: onUidGone: uid=1010259, disabled=false
06-18 10:05:40.565 shell 10848  4941 V BinderSender: Uid 1010259 dead
06-18 10:05:40.566  1000  1581  1791 D DisplayManagerService: Drop pending events for gone uid 1010259
06-18 10:05:49.606 1010168 20318 20355 D WebDavStorage: getOutputStream(redacted)
06-18 10:05:49.614 1010168 20318 20330 I FullBackup: Cancel full backup
06-18 10:05:50.883 1010168 20318 20330 W FullBackup: Error cancelling full backup for com.brave.browser
06-18 10:05:50.883 1010168 20318 20330 W FullBackup: java.io.IOException: at.bitfire.dav4jvm.exception.NotFoundException: HTTP 404 
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at com.stevesoltys.seedvault.plugins.webdav.WebDavStoragePlugin.removeData(WebDavStoragePlugin.kt:159)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at com.stevesoltys.seedvault.transport.backup.FullBackup.clearBackupData(FullBackup.kt:189)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at com.stevesoltys.seedvault.transport.backup.FullBackup.cancelFullBackup(FullBackup.kt:196)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at com.stevesoltys.seedvault.transport.backup.BackupCoordinator.cancelFullBackup(BackupCoordinator.kt:307)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at com.stevesoltys.seedvault.transport.ConfigurableBackupTransport$cancelFullBackup$1.invokeSuspend(ConfigurableBackupTransport.kt:207)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:108)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:280)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source:1)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source:1)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at com.stevesoltys.seedvault.transport.ConfigurableBackupTransport.cancelFullBackup(ConfigurableBackupTransport.kt:206)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at android.app.backup.BackupTransport$TransportImpl.cancelFullBackup(BackupTransport.java:910)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at com.android.internal.backup.IBackupTransport$Stub.onTransact(IBackupTransport.java:786)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at android.os.Binder.execTransactInternal(Binder.java:1505)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at android.os.Binder.execTransact(Binder.java:1444)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup: Caused by: at.bitfire.dav4jvm.exception.NotFoundException: HTTP 404 
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at at.bitfire.dav4jvm.DavResource.checkStatus(DavResource.kt:583)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at at.bitfire.dav4jvm.DavResource.checkStatus(DavResource.kt:565)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at at.bitfire.dav4jvm.DavResource.delete(DavResource.kt:441)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at at.bitfire.dav4jvm.DavResource.delete$default(DavResource.kt:429)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    at com.stevesoltys.seedvault.plugins.webdav.WebDavStoragePlugin.removeData(WebDavStoragePlugin.kt:152)
06-18 10:05:50.883 1010168 20318 20330 W FullBackup:    ... 17 more
06-18 10:05:50.909  1000  1581 22784 W PFTBT   : Error -1000 backing up com.brave.browser
06-18 10:05:50.916 1010168 20318 20330 I BackupCoordinator: Request full backup time. Returned 0
06-18 10:05:50.919  1000  1581 22784 I PFTBT   : Transport suggested backoff=0
06-18 10:05:50.920  1000  1581 22784 W PFTBT   : Transport failed; aborting backup: -1000
06-18 10:05:50.921 1010168 20318 20330 I NotificationBackupObserver: Completed. Target: com.brave.browser, status: -1000
06-18 10:05:50.921  1000  1581 22784 W ActivityManager: Unbinding backup agent with no active backup
06-18 10:05:50.921  1000  1581 22784 W ActivityManager: Process/uid not found attempting kill of com.brave.browser / 1010259
06-18 10:05:50.922  1000  1581 22784 I PFTBT   : Full backup completed with status: -1000
06-18 10:05:50.923 1010168 20318 20330 I BackupRequester: Requesting backup for 253 of 253 packages...
06-18 10:05:50.925  1000  1581 24267 E BackupManagerService: Error backing up com.brave.browser: write failed: EPIPE (Broken pipe)
06-18 10:05:50.926  1000  1581 24267 W ActivityManager: Unbinding backup agent with no active backup
06-18 10:05:50.927  1000  1581 24267 W ActivityManager: Process/uid not found attempting kill of com.brave.browser / 1010259
06-18 10:05:50.934 1010168 20318 20318 I BackupStateManager: appBackupRunning: false, filesBackupRunning: false, workInfoState: ENQUEUED
06-18 10:05:50.935 1010168 20318 20318 D ConfigurableBackupTransportService: Service destroyed.
06-18 10:05:50.936 shell 10848 13061 D BinderSender: onForegroundActivitiesChanged: pid=20318, uid=1010168, foregroundActivities=false
06-18 10:05:50.937  1000  1581 22784 I PFTBT   : Full data backup pass finished.
06-18 10:05:50.942  1000  1581 22784 V BackupManagerService: [UserID:10] Released wakelock:*backup*-10-14419
06-18 10:05:50.945  root   687   687 W powerhal-libperfmgr: Sess(10970), cannot resume, already active
06-18 10:05:50.946 1010168 20318 20318 I BackupStateManager: appBackupRunning: true, filesBackupRunning: false, workInfoState: ENQUEUED
06-18 10:05:50.946 1010168 20318 20318 D ConfigurableBackupTransportService: Service created.
06-18 10:05:50.955 1010168 20318 20318 D ConfigurableBackupTransportService: Transport bound.
06-18 10:05:50.956 shell 10848 13061 D BinderSender: onForegroundActivitiesChanged: pid=20318, uid=1010168, foregroundActivities=true
06-18 10:05:50.957  1000  1581  1581 I TransportConnection: ConfigurableBackupTransportService#7: Notifying [BMS.getBackupDestinationFromTransport] transport = BackupTransportClient
06-18 10:05:50.967  1000  1581 14222 D CompatibilityChangeReporter: Compat change id reported: 183147249; UID 1010228; state: ENABLED
06-18 10:05:50.968 1010168 20318 20330 I BackupRequester: Backup request succeeded
06-18 10:05:50.968 1010168 20318 21201 I NotificationBackupObserver: Completed. Target: com.google.android.iwlan, status: -2001
06-18 10:05:50.968 1010168 20318 21201 I NotificationBackupObserver: Showing progress notification for com.brave.browser 197/253
06-18 10:05:50.970 1010168 20318 21201 I NotificationBackupObserver: 197/253 - com.google.android.iwlan (com.google.android.iwlan)
06-18 10:05:50.974  1000  1581 14419 V BackupManagerService: [UserID:10] Acquired wakelock:*backup*-10-14419
06-18 10:05:50.974  1000  1581 14419 D KeyValueBackupTask: Spinning thread key-value-backup-47
06-18 10:05:50.980  1000  1581 24833 D PFTBT   : backupmanager pftbt token=7e31323b
06-18 10:05:50.980 1010168 20318 21201 I NotificationBackupObserver: Completed. Target: com.google.euiccpixel, status: -2001
06-18 10:05:50.980 1010168 20318 21201 I NotificationBackupObserver: Showing progress notification for com.google.android.iwlan 198/253
06-18 10:05:50.980  1000  1581 24833 V KeyValueBackupTask: Beginning backup of 3 targets
06-18 10:05:50.985 1010168 20318 21201 I NotificationBackupObserver: 198/253 - NFC/eSE/eSIM firmware updater (com.google.euiccpixel)
06-18 10:05:50.986  1000  1581 24833 D KeyValueBackupTask: Starting key-value backup of @pm@
06-18 10:05:50.988 1010168 20318 21201 I NotificationBackupObserver: Completed. Target: com.samsung.slsi.telephony.oem.oemrilhookservice, status: -2001
06-18 10:05:50.988 1010168 20318 21201 I NotificationBackupObserver: Showing progress notification for com.google.euiccpixel 199/253

@grote grote added this to the 3.x milestone Jun 18, 2024
@grote grote self-assigned this Jun 18, 2024
@grote
Copy link
Collaborator

grote commented Jun 20, 2024

When logging exceptions thrown while closing, we don't get the underlying cause either, because the crypto stream still wants to write something before really closing:

06-20 10:39:31.817 1010168 30423 30460 W FullBackup: Error closing: 
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: java.io.IOException: Pipe closed
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at java.io.PipedInputStream.checkStateForReceive(PipedInputStream.java:263)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at java.io.PipedInputStream.receive(PipedInputStream.java:229)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at java.io.PipedOutputStream.write(PipedOutputStream.java:149)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at com.google.crypto.tink.subtle.StreamingAeadEncryptingStream.close(StreamingAeadEncryptingStream.java:111)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at com.stevesoltys.seedvault.transport.backup.FullBackup.closeLogging(FullBackup.kt:228)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at com.stevesoltys.seedvault.transport.backup.FullBackup.clearState(FullBackup.kt:215)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at com.stevesoltys.seedvault.transport.backup.FullBackup.cancelFullBackup(FullBackup.kt:202)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at com.stevesoltys.seedvault.transport.backup.BackupCoordinator.cancelFullBackup(BackupCoordinator.kt:307)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at com.stevesoltys.seedvault.transport.ConfigurableBackupTransport$cancelFullBackup$1.invokeSuspend(ConfigurableBackupTransport.kt:207)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:108)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:280)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source:1)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source:1)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at com.stevesoltys.seedvault.transport.ConfigurableBackupTransport.cancelFullBackup(ConfigurableBackupTransport.kt:206)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at android.app.backup.BackupTransport$TransportImpl.cancelFullBackup(BackupTransport.java:910)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at com.android.internal.backup.IBackupTransport$Stub.onTransact(IBackupTransport.java:786)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at android.os.Binder.execTransactInternal(Binder.java:1505)
06-20 10:39:31.817 1010168 30423 30460 W FullBackup: 	at android.os.Binder.execTransact(Binder.java:1444)

@grote
Copy link
Collaborator

grote commented Jun 20, 2024 

06-20 10:40:29.658  1000  1581 17014 D BackupManagerService: Calling doFullBackup() on org.cromite.cromite
06-20 10:40:29.659 1010168 30423 31873 I FullBackup: sendBackupData of 3072 bytes
06-20 10:40:29.659 1010168 30423 31873 D FullBackup: Initializing OutputStream for org.cromite.cromite.
06-20 10:40:29.660 1010168 30423 31873 I NotificationBackupObserver: Showing progress notification for org.calyxos.ripple 233/253
06-20 10:40:29.661 1010168 30423 31873 I NotificationBackupObserver: 233/253 - Cromite (org.cromite.cromite)
06-20 10:40:29.667 1010331 16998 17012 I FullBackup_native: measured [/data/user/10/org.cromite.cromite] at 0
06-20 10:40:29.667 1010331 16998 17012 I file_backup_helper:    Name: apps/org.cromite.cromite/r/app_top_sites
[...]
06-20 10:40:32.691 1010168 30423 30460 I FullBackup: sendBackupData of 65536 bytes
06-20 10:40:32.691 1010331 16998 17012 I FullBackup_native: measured [/data/user/10/org.cromite.cromite/app_chrome/Default/Service Worker/CacheStorage/2088a2e28445b6466cd2e6e9e64ba713a7567a6c/852f6e7e-cd21-42b5-a6e6-36403db54ea8/246f5591cfd649db_0] at 131584
06-20 10:40:32.691 1010331 16998 17012 I file_backup_helper:    Name: apps/org.cromite.cromite/r/app_chrome/Default/Service Worker/CacheStorage/2088a2e28445b6466cd2e6e9e64ba713a7567a6c/852f6e7e-cd21-42b5-a6e6-36403db54ea8/9d21e5ad5d56d623_0
[...]
06-20 10:40:54.415 1010168 30423 30460 E FullBackup: Error handling backup data for org.cromite.cromite: 
06-20 10:40:54.415 1010168 30423 30460 E FullBackup: java.io.IOException: Pipe closed
06-20 10:40:54.415 1010168 30423 30460 E FullBackup: 	at java.io.PipedInputStream.checkStateForReceive(PipedInputStream.java:263)
06-20 10:40:54.415 1010168 30423 30460 E FullBackup: 	at java.io.PipedInputStream.awaitSpace(PipedInputStream.java:271)
06-20 10:40:54.415 1010168 30423 30460 E FullBackup: 	at java.io.PipedInputStream.receive(PipedInputStream.java:234)
06-20 10:40:54.415 1010168 30423 30460 E FullBackup: 	at java.io.PipedOutputStream.write(PipedOutputStream.java:149)
06-20 10:40:54.415 1010168 30423 30460 E FullBackup: 	at com.google.crypto.tink.subtle.StreamingAeadEncryptingStream.write(StreamingAeadEncryptingStream.java:85)
06-20 10:40:54.415 1010168 30423 30460 E FullBackup: 	at com.google.crypto.tink.subtle.StreamingAeadEncryptingStream.write(StreamingAeadEncryptingStream.java:59)
06-20 10:40:54.415 1010168 30423 30460 E FullBackup: 	at com.stevesoltys.seedvault.transport.backup.FullBackup.sendBackupData(FullBackup.kt:179)
[...]
06-20 10:45:29.674 1010168 30423 30460 I BackupCoordinator: Cancel full backup of org.cromite.cromite because of UNKNOWN_ERROR

It started the stream at 10:40:29, then send data last time 10:40:32 and had the pipe closed 10:40:54, 22 seconds later. Write timeout is 60 and read timeout 240 seconds, so that shouldn't be causing the closed pipe.

The system for some reason takes almost 5min to handle our TRANSPORT_ERROR that we return from sendData().

@grote
Copy link
Collaborator

grote commented Jun 27, 2024

Part of a test to get the underlying exception:

06-25 14:07:02.770 2210174  5639 11763 E JavaBinder: *** Uncaught remote exception! Exceptions are not yet supported across processes. Client PID 0 UID 1000.
06-25 14:07:02.770 2210174  5639 11763 E JavaBinder: at.bitfire.dav4jvm.exception.HttpException: HTTP 413 
06-25 14:07:02.770 2210174  5639 11763 E JavaBinder:    at at.bitfire.dav4jvm.DavResource.checkStatus(DavResource.kt:661)
06-25 14:07:02.770 2210174  5639 11763 E JavaBinder:    at at.bitfire.dav4jvm.DavResource.checkStatus(DavResource.kt:635)
06-25 14:07:02.770 2210174  5639 11763 E JavaBinder:    at at.bitfire.dav4jvm.DavResource.put(DavResource.kt:478)
06-25 14:07:02.770 2210174  5639 11763 E JavaBinder:    at at.bitfire.dav4jvm.DavResource.put$default(DavResource.kt:459)
06-25 14:07:02.770 2210174  5639 11763 E JavaBinder:    at com.stevesoltys.seedvault.plugins.webdav.WebDavStorage$getOutputStream$deferred$1.invokeSuspend(WebDavStorage.kt:98)
06-25 14:07:02.770 2210174  5639 11763 E JavaBinder:    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
06-25 14:07:02.770 2210174  5639 11763 E JavaBinder:    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:108)
06-25 14:07:02.770 2210174  5639 11763 E JavaBinder:    at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:115)
06-25 14:07:02.770 2210174  5639 11763 E JavaBinder:    at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:103)
06-25 14:07:02.770 2210174  5639 11763 E JavaBinder:    at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:584)
06-25 14:07:02.770 2210174  5639 11763 E JavaBinder:    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:793)
06-25 14:07:02.770 2210174  5639 11763 E JavaBinder:    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:697)
06-25 14:07:02.770 2210174  5639 11763 E JavaBinder:    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:684)
06-25 14:07:02.770 2210174  5639 11763 I IPCThreadState: oneway function results for code 21 on binder at 0xb400006fbec93090 will be dropped but finished with status UNKNOWN_TRANSACTION

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@grote grote

Labels
bug
Projects
None yet
Milestone
Roadmap
Development

No branches or pull requests
2 participants
@grote @t-m-w