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

File suddenly became empty/corrupted #8239

Closed
mcarbonne opened this issue Jan 17, 2024 · 10 comments
Closed

File suddenly became empty/corrupted #8239

mcarbonne opened this issue Jan 17, 2024 · 10 comments
Labels
Priority:p1-urgent Consider a hotfix release with only that fix Type:Bug
Milestone
Release 5.0.0

Comments

@mcarbonne
Copy link

Describe the bug

Version: ocis 5.0.0 rc1

I don't know how exactly to reproduce the bug but it happened several times (also with previous 5.0.0 alpha/beta versions).

The file is listed in the web interface with a size >0 :
bug ocis

But If I download the file, the file is empty (size=0).
Also, I cannot get a preview of the file. In OCIS log, I have the following errors :

2024-01-17T21:19:16Z WRN Failed to execute error="{\"id\":\"com.owncloud.api.thumbnails\",\"code\":500,\"detail\":\"could not get image\",\"status\":\"Internal Server Error\"}" duration=23.770166 line=github.com/owncloud/ocis/v2/services/thumbnails/pkg/service/grpc/v0/decorators/logging.go:46 method=Thumbnails.GetThumbnail service=thumbnails

And if I try to open the file history in the web interface, it is loading forever.

The behavior is the same with all clients (web, android, linux/desktop).

A quick history of this file:

  1. the file was uploaded (automatically) with the android client (photo backup).
  2. then, the file was synced on my computer. At this step, the file was OK on my computer.
  3. As I'm still testing OCIS, I removed and re-added the connection to my server (forcing a resync) :
    I noticed this file was in conflict. The version on my computer was the correct one (real picture), but the version re-synced from the server was empty. So the file content disappeared from the server.

Note : this isn't the first time I end up with empty files on my server. But this time, the picture was successfully synced to my computer before being "corrupted" (empty) so now I'm 100% sure that the file was correctly uploaded to my ocis server.

Here are the access logs (from traefik) during the picture upload (~ 3 days ago) :

XXXXXXXXXXXXX - - [14/Jan/2024:17:32:25 +0000] "PROPFIND /remote.php/dav/files/XXX//IMG_20240114_181428.jpg HTTP/1.1" 404 201 "-" "-" 32982 "ocis@docker" "http://10.89.1.3:9200" 14ms
XXXXXXXXXXXXX - - [14/Jan/2024:17:32:25 +0000] "PROPFIND /remote.php/dav/files/XXX//IMG_20240114_181428.jpg HTTP/1.1" 404 201 "-" "-" 32983 "ocis@docker" "http://10.89.1.3:9200" 20ms
XXXXXXXXXXXXX - - [14/Jan/2024:17:32:25 +0000] "PUT /remote.php/dav/files/XXX//IMG_20240114_181428.jpg HTTP/1.1" 201 0 "-" "-" 32984 "ocis@docker" "http://10.89.1.3:9200" 1595ms
XXXXXXXXXXXXX - - [14/Jan/2024:17:32:54 +0000] "GET /dav/spaces/XXXX$XXXX/Photos/IMG_20240114_181428.jpg HTTP/1.1" 200 1759966 "-" "-" 32992 "ocis@docker" "http://10.89.1.3:9200" 45ms
XXXXXXXXXXXXX - - [14/Jan/2024:17:32:27 +0000] "PUT /remote.php/dav/files/XXX//IMG_20240114_181428.jpg HTTP/1.1" 499 21 "-" "-" 32986 "ocis@docker" "http://10.89.1.3:9200" 74525ms

The upload seems to have been very slow (~70s), which explain why access logs seems "out of order".
Also, I'm not 100% sure, but the log line "14/Jan/2024:17:32:54" might correspond to my computer downloading the file.
So there may be a race condition underlying this issue.

I have all the access logs from traefik, and also OCIS logs (at "info" log level) but I did not find anything relevant.

Currently, I have 13 photos with size=0 on my server (out of 406).

Setup

  • ocis 5.0.0 rc1 (podman) with keycloak SSO
  • issue on all clients (web, linux, android)
  • underlying file system is BTRFS
@micbar micbar added the Priority:p1-urgent Consider a hotfix release with only that fix label Jan 17, 2024
@micbar micbar moved this from Qualification to Prio 1 in Infinite Scale Team Board Jan 17, 2024
@micbar
Copy link
Contributor

micbar commented Jan 17, 2024

@mcarbonne Escalated to P1. We will take a look tomorrow.

@aduffeck
Copy link
Contributor

@mcarbonne unfortunately I didn't succeed with reproducing the issue yet. Any chance you could provide more logs regarding the upload of one of the corrupted files?
And can you also let us know which version of the Android client you are using?

@mcarbonne
Copy link
Author

I'm using the latest version (4.1.1). I extracted the logs on the application side (android):

D: 2024-01-14 18:32:26:401(UploadFileFromFileSystemOperation.kt:120) .uploadFile()File uploaded successfully. New etag for file IMG_20240114_181428.jpg is 52d4967354dcdb12b21b52ba4eb6a753
D: 2024-01-14 18:32:26:401(OwnCloudClient.java:129) .saveExecuteHttpMethod()Executing in request with id 4d7f7d8e-5245-43a1-8406-c7526e2db1b5
I: 2024-01-14 18:32:26:402(UploadFileFromFileSystemOperation.kt:79) .run()Upload of /data/user/0/com.owncloud.android/files/owncloud/tmp/USER@ocis.MYDOMAIN.COM%3AXXX/Photos//IMG_20240114_181428.jpg to /Photos//IMG_20240114_181428.jpg: Operation finished with HTTP status code -1 (success)
D: 2024-01-14 18:32:26:403(LogBuilder.kt:38) .logHttp()[Network, request] [info] [4d7f7d8e-5245-43a1-8406-c7526e2db1b5] Method: PUT URL: https://ocis.MYDOMAIN.COM:XXX/remote.php/dav/files/USER/Photos//IMG_20240114_181428.jpg
D: 2024-01-14 18:32:26:403(LogBuilder.kt:38) .logHttp()[Network, request] [header] [4d7f7d8e-5245-43a1-8406-c7526e2db1b5] Authorization: [redacted]
D: 2024-01-14 18:32:26:404(LogBuilder.kt:38) .logHttp()[Network, request] [header] [4d7f7d8e-5245-43a1-8406-c7526e2db1b5] X-OC-Mtime: 1705252471
D: 2024-01-14 18:32:26:405(LogBuilder.kt:38) .logHttp()[Network, request] [header] [4d7f7d8e-5245-43a1-8406-c7526e2db1b5] OC-Total-Length: 1759966
D: 2024-01-14 18:32:26:406(LogBuilder.kt:38) .logHttp()[Network, request] [header] [4d7f7d8e-5245-43a1-8406-c7526e2db1b5] X-Request-ID: 4d7f7d8e-5245-43a1-8406-c7526e2db1b5
D: 2024-01-14 18:32:26:407(LogBuilder.kt:38) .logHttp()[Network, request] [header] [4d7f7d8e-5245-43a1-8406-c7526e2db1b5] User-Agent: Mozilla/5.0 (Android) ownCloud-android/4.1.1
D: 2024-01-14 18:32:26:408(LogBuilder.kt:38) .logHttp()[Network, request] [header] [4d7f7d8e-5245-43a1-8406-c7526e2db1b5] Accept-Encoding: identity
D: 2024-01-14 18:32:26:409(LogBuilder.kt:38) .logHttp()[Network, request] [header] [4d7f7d8e-5245-43a1-8406-c7526e2db1b5] Accept-Language: fr
D: 2024-01-14 18:32:26:410(LogBuilder.kt:38) .logHttp()[Network, request] [header] [4d7f7d8e-5245-43a1-8406-c7526e2db1b5] Content-Length: 1759966
D: 2024-01-14 18:32:26:412(LogBuilder.kt:38) .logHttp()[Network, request] [header] [4d7f7d8e-5245-43a1-8406-c7526e2db1b5] Host: ocis.MYDOMAIN.COM:XXX
D: 2024-01-14 18:32:26:413(LogBuilder.kt:38) .logHttp()[Network, request] [header] [4d7f7d8e-5245-43a1-8406-c7526e2db1b5] Connection: Keep-Alive
D: 2024-01-14 18:32:26:415(LogBuilder.kt:38) .logHttp()[Network, request] [body] [4d7f7d8e-5245-43a1-8406-c7526e2db1b5] One shot body -- Omitted
E: 2024-01-14 18:32:26:423(FileRequestBody.kt:72) .writeTo()java.io.FileNotFoundException: /data/user/0/com.owncloud.android/files/owncloud/tmp/USER@ocis.MYDOMAIN.COM%3AXXX/Photos/IMG_20240114_181428.jpg: open failed: ENOENT (No such file or directory)
	at libcore.io.IoBridge.open(IoBridge.java:574)
	at java.io.FileInputStream.<init>(FileInputStream.java:160)
	at okio.Okio__JvmOkioKt.source(JvmOkio.kt:182)
	at okio.Okio.source(Unknown Source:1)
	at com.owncloud.android.lib.common.network.FileRequestBody.writeTo(FileRequestBody.kt:57)
	at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:59)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at com.owncloud.android.lib.common.http.DummyInterceptor.intercept(DummyInterceptor.kt:30)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at com.owncloud.android.lib.common.http.LogInterceptor.intercept(LogInterceptor.kt:59)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201)
	at okhttp3.internal.connection.RealCall.execute(RealCall.kt:154)
	at at.bitfire.dav4jvm.DavOCResource$put$2.invoke(DavOCResource.kt:64)
	at at.bitfire.dav4jvm.DavOCResource$put$2.invoke(DavOCResource.kt:12)
	at at.bitfire.dav4jvm.DavResource.followRedirects(DavResource.kt:452)
	at at.bitfire.dav4jvm.DavOCResource.put(DavOCResource.kt:58)
	at com.owncloud.android.lib.common.http.methods.webdav.PutMethod.onDavExecute(PutMethod.kt:44)
	at com.owncloud.android.lib.common.http.methods.webdav.DavMethod.onExecute(DavMethod.kt:62)
	at com.owncloud.android.lib.common.http.methods.HttpBaseMethod.execute(HttpBaseMethod.kt:75)
	at com.owncloud.android.lib.common.OwnCloudClient.saveExecuteHttpMethod(OwnCloudClient.java:138)
	at com.owncloud.android.lib.common.OwnCloudClient.executeHttpMethod(OwnCloudClient.java:107)
	at com.owncloud.android.lib.resources.files.UploadFileFromFileSystemOperation.uploadFile(UploadFileFromFileSystemOperation.kt:112)
	at com.owncloud.android.lib.resources.files.UploadFileFromFileSystemOperation.run(UploadFileFromFileSystemOperation.kt:78)
	at com.owncloud.android.lib.common.operations.RemoteOperation.runOperation(RemoteOperation.java:264)
	at com.owncloud.android.lib.common.operations.RemoteOperation.execute(RemoteOperation.java:229)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker$uploadPlainFile$2.invoke(UploadFileFromContentUriWorker.kt:286)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker$uploadPlainFile$2.invoke(UploadFileFromContentUriWorker.kt:286)
	at com.owncloud.android.data.RemoteOperationHandlerKt.executeRemoteOperation(RemoteOperationHandler.kt:79)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker.uploadPlainFile(UploadFileFromContentUriWorker.kt:286)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker.uploadDocument(UploadFileFromContentUriWorker.kt:269)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker.doWork(UploadFileFromContentUriWorker.kt:121)
	at androidx.work.CoroutineWorker$startWork$1.invokeSuspend(CoroutineWorker.kt:68)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:570)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:750)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:677)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:664)
Caused by: android.system.ErrnoException: open failed: ENOENT (No such file or directory)
	at libcore.io.Linux.open(Native Method)
	at libcore.io.ForwardingOs.open(ForwardingOs.java:563)
	at libcore.io.BlockGuardOs.open(BlockGuardOs.java:274)
	at libcore.io.ForwardingOs.open(ForwardingOs.java:563)
	at android.app.ActivityThread$AndroidOs.open(ActivityThread.java:8094)
	at libcore.io.IoBridge.open(IoBridge.java:560)
	... 46 more

E: 2024-01-14 18:33:40:885(RemoteOperationResult.java:120) .<init>()---------------------------------
Create RemoteOperationResult from exception.
 Message: SocketTimeoutException: timeout
 Stacktrace: java.net.SocketTimeoutException: timeout
	at okio.SocketAsyncTimeout.newTimeoutException(JvmOkio.kt:147)
	at okio.AsyncTimeout.access$newTimeoutException(AsyncTimeout.kt:158)
	at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:337)
	at okio.RealBufferedSource.indexOf(RealBufferedSource.kt:427)
	at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:320)
	at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:29)
	at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:178)
	at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106)
	at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at com.owncloud.android.lib.common.http.DummyInterceptor.intercept(DummyInterceptor.kt:30)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at com.owncloud.android.lib.common.http.LogInterceptor.intercept(LogInterceptor.kt:59)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201)
	at okhttp3.internal.connection.RealCall.execute(RealCall.kt:154)
	at at.bitfire.dav4jvm.DavOCResource$put$2.invoke(DavOCResource.kt:64)
	at at.bitfire.dav4jvm.DavOCResource$put$2.invoke(DavOCResource.kt:12)
	at at.bitfire.dav4jvm.DavResource.followRedirects(DavResource.kt:452)
	at at.bitfire.dav4jvm.DavOCResource.put(DavOCResource.kt:58)
	at com.owncloud.android.lib.common.http.methods.webdav.PutMethod.onDavExecute(PutMethod.kt:44)
	at com.owncloud.android.lib.common.http.methods.webdav.DavMethod.onExecute(DavMethod.kt:62)
	at com.owncloud.android.lib.common.http.methods.HttpBaseMethod.execute(HttpBaseMethod.kt:75)
	at com.owncloud.android.lib.common.OwnCloudClient.saveExecuteHttpMethod(OwnCloudClient.java:138)
	at com.owncloud.android.lib.common.OwnCloudClient.executeHttpMethod(OwnCloudClient.java:107)
	at com.owncloud.android.lib.resources.files.UploadFileFromFileSystemOperation.uploadFile(UploadFileFromFileSystemOperation.kt:112)
	at com.owncloud.android.lib.resources.files.UploadFileFromFileSystemOperation.run(UploadFileFromFileSystemOperation.kt:78)
	at com.owncloud.android.lib.common.operations.RemoteOperation.runOperation(RemoteOperation.java:264)
	at com.owncloud.android.lib.common.operations.RemoteOperation.execute(RemoteOperation.java:229)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker$uploadPlainFile$2.invoke(UploadFileFromContentUriWorker.kt:286)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker$uploadPlainFile$2.invoke(UploadFileFromContentUriWorker.kt:286)
	at com.owncloud.android.data.RemoteOperationHandlerKt.executeRemoteOperation(RemoteOperationHandler.kt:79)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker.uploadPlainFile(UploadFileFromContentUriWorker.kt:286)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker.uploadDocument(UploadFileFromContentUriWorker.kt:269)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker.doWork(UploadFileFromContentUriWorker.kt:121)
	at androidx.work.CoroutineWorker$startWork$1.invokeSuspend(CoroutineWorker.kt:68)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:570)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:750)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:677)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:664)
Caused by: java.net.SocketException: Socket closed
	at java.net.SocketInputStream.read(SocketInputStream.java:188)
	at java.net.SocketInputStream.read(SocketInputStream.java:143)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.readFromSocket(ConscryptEngineSocket.java:983)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.processDataFromSocket(ConscryptEngineSocket.java:947)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.readUntilDataAvailable(ConscryptEngineSocket.java:862)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.read(ConscryptEngineSocket.java:835)
	at okio.InputStreamSource.read(JvmOkio.kt:94)
	at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:125)
	... 47 more

---------------------------------
E: 2024-01-14 18:33:40:898(UploadFileFromFileSystemOperation.kt:87) .run()Upload of /data/user/0/com.owncloud.android/files/owncloud/tmp/USER@ocis.MYDOMAIN.COM%3AXXX/Photos//IMG_20240114_181428.jpg to /Photos//IMG_20240114_181428.jpg has failed with this message: Socket timeout exception
java.net.SocketTimeoutException: timeout
	at okio.SocketAsyncTimeout.newTimeoutException(JvmOkio.kt:147)
	at okio.AsyncTimeout.access$newTimeoutException(AsyncTimeout.kt:158)
	at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:337)
	at okio.RealBufferedSource.indexOf(RealBufferedSource.kt:427)
	at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:320)
	at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:29)
	at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:178)
	at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106)
	at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at com.owncloud.android.lib.common.http.DummyInterceptor.intercept(DummyInterceptor.kt:30)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at com.owncloud.android.lib.common.http.LogInterceptor.intercept(LogInterceptor.kt:59)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201)
	at okhttp3.internal.connection.RealCall.execute(RealCall.kt:154)
	at at.bitfire.dav4jvm.DavOCResource$put$2.invoke(DavOCResource.kt:64)
	at at.bitfire.dav4jvm.DavOCResource$put$2.invoke(DavOCResource.kt:12)
	at at.bitfire.dav4jvm.DavResource.followRedirects(DavResource.kt:452)
	at at.bitfire.dav4jvm.DavOCResource.put(DavOCResource.kt:58)
	at com.owncloud.android.lib.common.http.methods.webdav.PutMethod.onDavExecute(PutMethod.kt:44)
	at com.owncloud.android.lib.common.http.methods.webdav.DavMethod.onExecute(DavMethod.kt:62)
	at com.owncloud.android.lib.common.http.methods.HttpBaseMethod.execute(HttpBaseMethod.kt:75)
	at com.owncloud.android.lib.common.OwnCloudClient.saveExecuteHttpMethod(OwnCloudClient.java:138)
	at com.owncloud.android.lib.common.OwnCloudClient.executeHttpMethod(OwnCloudClient.java:107)
	at com.owncloud.android.lib.resources.files.UploadFileFromFileSystemOperation.uploadFile(UploadFileFromFileSystemOperation.kt:112)
	at com.owncloud.android.lib.resources.files.UploadFileFromFileSystemOperation.run(UploadFileFromFileSystemOperation.kt:78)
	at com.owncloud.android.lib.common.operations.RemoteOperation.runOperation(RemoteOperation.java:264)
	at com.owncloud.android.lib.common.operations.RemoteOperation.execute(RemoteOperation.java:229)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker$uploadPlainFile$2.invoke(UploadFileFromContentUriWorker.kt:286)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker$uploadPlainFile$2.invoke(UploadFileFromContentUriWorker.kt:286)
	at com.owncloud.android.data.RemoteOperationHandlerKt.executeRemoteOperation(RemoteOperationHandler.kt:79)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker.uploadPlainFile(UploadFileFromContentUriWorker.kt:286)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker.uploadDocument(UploadFileFromContentUriWorker.kt:269)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker.doWork(UploadFileFromContentUriWorker.kt:121)
	at androidx.work.CoroutineWorker$startWork$1.invokeSuspend(CoroutineWorker.kt:68)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:570)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:750)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:677)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:664)
Caused by: java.net.SocketException: Socket closed
	at java.net.SocketInputStream.read(SocketInputStream.java:188)
	at java.net.SocketInputStream.read(SocketInputStream.java:143)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.readFromSocket(ConscryptEngineSocket.java:983)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.processDataFromSocket(ConscryptEngineSocket.java:947)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.readUntilDataAvailable(ConscryptEngineSocket.java:862)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.read(ConscryptEngineSocket.java:835)
	at okio.InputStreamSource.read(JvmOkio.kt:94)
	at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:125)
	... 47 more

E: 2024-01-14 18:33:40:906(UploadFileFromContentUriWorker.kt:125) .doWork()com.owncloud.android.domain.exceptions.ServerResponseTimeoutException
	at com.owncloud.android.data.RemoteOperationHandlerKt.handleRemoteOperationResult(RemoteOperationHandler.kt:95)
	at com.owncloud.android.data.RemoteOperationHandlerKt.executeRemoteOperation(RemoteOperationHandler.kt:80)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker.uploadPlainFile(UploadFileFromContentUriWorker.kt:286)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker.uploadDocument(UploadFileFromContentUriWorker.kt:269)
	at com.owncloud.android.workers.UploadFileFromContentUriWorker.doWork(UploadFileFromContentUriWorker.kt:121)
	at androidx.work.CoroutineWorker$startWork$1.invokeSuspend(CoroutineWorker.kt:68)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:570)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:750)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:677)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:664)

I'm not an expert but it seems the file was uplaoded twice, first time OK, second try failed.

In the previsous logs I posted above (access logs from traefik), there are indeed 2 uploads:

XXXXXXXXXXXXX - - [14/Jan/2024:17:32:25 +0000] "PUT /remote.php/dav/files/XXX//IMG_20240114_181428.jpg HTTP/1.1" 201 0 "-" "-" 32984 "ocis@docker" "http://10.89.1.3:9200" 1595ms
[...]
XXXXXXXXXXXXX - - [14/Jan/2024:17:32:27 +0000] "PUT /remote.php/dav/files/XXX//IMG_20240114_181428.jpg HTTP/1.1" 499 21 "-" "-" 32986 "ocis@docker" "http://10.89.1.3:9200" 74525ms

First one => http OK (201)
Second one => 499 (connection closed by the client, due to timeout most likely).
I don't know if the double upload issue is on application or server side but anyway there is still an issue on ocis side too: the file is in a dummy status (cannot retrieve history at least).

@aduffeck
Copy link
Contributor

Thanks!

It looks to me like there are two different issues involved. The android client seems to attempt a second upload which runs into a strange condition:

E: 2024-01-14 18:32:26:423(FileRequestBody.kt:72) .writeTo()java.io.FileNotFoundException: /data/user/0/com.owncloud.android/files/owncloud/tmp/USER@ocis.MYDOMAIN.COM%3AXXX/Photos/IMG_20240114_181428.jpg: open failed: ENOENT (No such file or directory)

which then triggers the 499 Client Closed Request.

That in return seems to cause the corrupted file in ocis, which of course should never happen. I'll look into that.

@JuancaG05 any idea about the 2-uploads problem on Android?

@aduffeck
Copy link
Contributor

@JuancaG05 I'm also a bit confused about the PUT against /remote.php/dav/files. I think you mentioned that it should talk to /dav/spaces/ in the ocis case, no?

@JuancaG05
Copy link

Hey @aduffeck!
Yes, we have some issues with duplicated auto-uploads since some time ago, but it happens just sometimes so it's difficult to reproduce. I leave here two open tickets in our repo to see if the problem in this case is similar:

We'll try to take a look ASAP anyway (other priorities now).

About the endpoint stuff, oCIS should always point to /dav/spaces, so it's strange that we have PUT operations against /remote.php/dav/files, and my guess is that it could be even related with the duplicated uploads issue. Would be interesting if @mcarbonne could post the previous log lines of the snippet already posted, so that we can compare the logs of a successful upload (maybe to /dav/spaces?) with the logs of a failed one (as we can see here, to /remote.php/dav/files), for IMG_20240114_181428.jpg in this case. BTW, thanks for the research, it's so nice! 😉

In any case, you can always open a issue in our repo (https://github.com/owncloud/android) to keep track of it easily and we'll prioritize 👍

@mcarbonne
Copy link
Author

Thanks for the links, I'll track the 2 already opened issues related to duplicated auto-uploads (no need to open a third issue I guess).
Therefore, this issue only concerns the corruption occurring with ocis in this specific scenario (and maybe some other ?).

Here are the log from another successful upload, the same day :

Traefik access logs:

PHONE_IP - - [14/Jan/2024:17:58:02 +0000] "PROPFIND /remote.php/dav/files/USER/Photos//IMG_20240114_183757.jpg HTTP/1.1" 404 201 "-" "-" 33403 "ocis@docker" "http://10.89.1.3:9200" 8ms
PHONE_IP - - [14/Jan/2024:17:58:02 +0000] "PUT /remote.php/dav/files/USER/Photos//IMG_20240114_183757.jpg HTTP/1.1" 201 0 "-" "-" 33405 "ocis@docker" "http://10.89.1.3:9200" 4298ms
COMPUTER_IP - - [14/Jan/2024:17:58:54 +0000] "GET /dav/spaces/XXXX$XXXX/Photos/IMG_20240114_183757.jpg HTTP/1.1" 200 3565754 "-" "-" 33413 "ocis@docker" "http://10.89.1.3:9200" 72ms

(one upload only)

Android application log:

D: 2024-01-14 18:58:01:778(LogBuilder.kt:38) .logHttp()[Network, request] [info] [66e74519-1549-4e26-ba7f-b902ba071fd1] Method: PROPFIND URL: https://ocis.DOMAIN.COM:XXX/remote.php/dav/files/USER/Photos//IMG_20240114_183757.jpg
D: 2024-01-14 18:58:01:780(LogBuilder.kt:38) .logHttp()[Network, request] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] Depth: 0
D: 2024-01-14 18:58:01:785(LogBuilder.kt:38) .logHttp()[Network, request] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] Authorization: [redacted]
D: 2024-01-14 18:58:01:787(LogBuilder.kt:38) .logHttp()[Network, request] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] X-Request-ID: 66e74519-1549-4e26-ba7f-b902ba071fd1
D: 2024-01-14 18:58:01:789(LogBuilder.kt:38) .logHttp()[Network, request] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] User-Agent: Mozilla/5.0 (Android) ownCloud-android/4.1.1
D: 2024-01-14 18:58:01:791(LogBuilder.kt:38) .logHttp()[Network, request] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] Accept-Encoding: identity
D: 2024-01-14 18:58:01:793(LogBuilder.kt:38) .logHttp()[Network, request] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] Accept-Language: fr
D: 2024-01-14 18:58:01:795(LogBuilder.kt:38) .logHttp()[Network, request] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] Content-Type: application/xml; charset=utf-8
D: 2024-01-14 18:58:01:796(LogBuilder.kt:38) .logHttp()[Network, request] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] Content-Length: 432
D: 2024-01-14 18:58:01:799(LogBuilder.kt:38) .logHttp()[Network, request] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] Host: ocis.DOMAIN.COM:XXX
D: 2024-01-14 18:58:01:801(LogBuilder.kt:38) .logHttp()[Network, request] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] Connection: Keep-Alive
D: 2024-01-14 18:58:01:803(LogBuilder.kt:38) .logHttp()[Network, request] [body] [66e74519-1549-4e26-ba7f-b902ba071fd1] Length: 432 byte body
D: 2024-01-14 18:58:01:805(LogBuilder.kt:38) .logHttp()[Network, request] [body] [66e74519-1549-4e26-ba7f-b902ba071fd1] Type: application/xml; charset=utf-8
D: 2024-01-14 18:58:01:807(LogBuilder.kt:38) .logHttp()[Network, request] [body] [66e74519-1549-4e26-ba7f-b902ba071fd1] --> Body start for request
D: 2024-01-14 18:58:01:809(LogBuilder.kt:38) .logHttp()[Network, request] [body] [66e74519-1549-4e26-ba7f-b902ba071fd1] <?xml version='1.0' encoding='UTF-8' ?><propfind xmlns="DAV:" xmlns:CAL="urn:ietf:params:xml:ns:caldav" xmlns:CARD="urn:ietf:params:xml:ns:carddav" xmlns:SABRE="http://sabredav.org/ns" xmlns:OC="http://owncloud.org/ns"><prop><displayname /><getcontenttype /><resourcetype /><getcontentlength /><getlastmodified /><creationdate /><getetag /><OC:permissions /><OC:id /><OC:size /><OC:privatelink /><OC:share-types /></prop></propfind>
D: 2024-01-14 18:58:01:812(LogBuilder.kt:38) .logHttp()[Network, request] [body] [66e74519-1549-4e26-ba7f-b902ba071fd1] <-- Body end for request -- Omitted: 0 bytes
D: 2024-01-14 18:58:01:881(LogBuilder.kt:38) .logHttp()[Network, response] [info] [66e74519-1549-4e26-ba7f-b902ba071fd1] Method: PROPFIND URL: https://ocis.DOMAIN.COM:XXX/remote.php/dav/files/USER/Photos//IMG_20240114_183757.jpg Code: 404 Message: Not Found
D: 2024-01-14 18:58:01:884(LogBuilder.kt:38) .logHttp()[Network, response] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] Access-Control-Allow-Origin: *
D: 2024-01-14 18:58:01:887(LogBuilder.kt:38) .logHttp()[Network, response] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] Content-Length: 201
D: 2024-01-14 18:58:01:888(LogBuilder.kt:38) .logHttp()[Network, response] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] Content-Security-Policy: default-src 'none';
D: 2024-01-14 18:58:01:891(LogBuilder.kt:38) .logHttp()[Network, response] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] Content-Type: text/xml; charset=utf-8
D: 2024-01-14 18:58:01:892(LogBuilder.kt:38) .logHttp()[Network, response] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] Date: Sun, 14 Jan 2024 17:58:02 GMT
D: 2024-01-14 18:58:01:894(LogBuilder.kt:38) .logHttp()[Network, response] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] Vary: Origin
D: 2024-01-14 18:58:01:896(LogBuilder.kt:38) .logHttp()[Network, response] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] X-Content-Type-Options: nosniff
D: 2024-01-14 18:58:01:898(LogBuilder.kt:38) .logHttp()[Network, response] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] X-Download-Options: noopen
D: 2024-01-14 18:58:01:899(LogBuilder.kt:38) .logHttp()[Network, response] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] X-Frame-Options: SAMEORIGIN
D: 2024-01-14 18:58:01:902(LogBuilder.kt:38) .logHttp()[Network, response] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] X-Permitted-Cross-Domain-Policies: none
D: 2024-01-14 18:58:01:904(LogBuilder.kt:38) .logHttp()[Network, response] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] X-Request-Id: 66e74519-1549-4e26-ba7f-b902ba071fd1
D: 2024-01-14 18:58:01:906(LogBuilder.kt:38) .logHttp()[Network, response] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] X-Robots-Tag: none
D: 2024-01-14 18:58:01:908(LogBuilder.kt:38) .logHttp()[Network, response] [header] [66e74519-1549-4e26-ba7f-b902ba071fd1] X-Xss-Protection: 1; mode=block
D: 2024-01-14 18:58:01:911(LogBuilder.kt:38) .logHttp()[Network, response] [body] [66e74519-1549-4e26-ba7f-b902ba071fd1] Length: 201 byte body
D: 2024-01-14 18:58:01:913(LogBuilder.kt:38) .logHttp()[Network, response] [body] [66e74519-1549-4e26-ba7f-b902ba071fd1] Type: text/xml; charset=utf-8
D: 2024-01-14 18:58:01:917(LogBuilder.kt:38) .logHttp()[Network, response] [body] [66e74519-1549-4e26-ba7f-b902ba071fd1] --> Body start for response
D: 2024-01-14 18:58:01:919(LogBuilder.kt:38) .logHttp()[Network, response] [body] [66e74519-1549-4e26-ba7f-b902ba071fd1] <?xml version="1.0" encoding="UTF-8"?>
<d:error xmlns:d="DAV" xmlns:s="http://sabredav.org/ns"><s:exception>Sabre\DAV\Exception\NotFound</s:exception><s:message>Resource not found</s:message></d:error>
D: 2024-01-14 18:58:01:920(LogBuilder.kt:38) .logHttp()[Network, response] [body] [66e74519-1549-4e26-ba7f-b902ba071fd1] <-- Body end for response -- Omitted: 0 bytes
D: 2024-01-14 18:58:01:935(OwnCloudClient.java:129) .saveExecuteHttpMethod()Executing in request with id f01f6728-b163-413a-9a59-3f59d0dae069
D: 2024-01-14 18:58:01:935(CheckPathExistenceRemoteOperation.kt:71) .run()Existence check for https://ocis.DOMAIN.COM:XXX/remote.php/dav/files/USER/Photos//IMG_20240114_183757.jpg finished with HTTP status 404(FAIL)
D: 2024-01-14 18:58:01:937(LogBuilder.kt:38) .logHttp()[Network, request] [info] [f01f6728-b163-413a-9a59-3f59d0dae069] Method: PROPFIND URL: https://ocis.DOMAIN.COM:XXX/remote.php/dav/files/USER/Photos//IMG_20240114_183801.jpg
D: 2024-01-14 18:58:01:938(LogBuilder.kt:38) .logHttp()[Network, request] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] Depth: 0
D: 2024-01-14 18:58:01:940(LogBuilder.kt:38) .logHttp()[Network, request] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] Authorization: [redacted]
D: 2024-01-14 18:58:01:941(LogBuilder.kt:38) .logHttp()[Network, request] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] X-Request-ID: f01f6728-b163-413a-9a59-3f59d0dae069
D: 2024-01-14 18:58:01:943(LogBuilder.kt:38) .logHttp()[Network, request] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] User-Agent: Mozilla/5.0 (Android) ownCloud-android/4.1.1
D: 2024-01-14 18:58:01:945(LogBuilder.kt:38) .logHttp()[Network, request] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] Accept-Encoding: identity
D: 2024-01-14 18:58:01:949(LogBuilder.kt:38) .logHttp()[Network, request] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] Accept-Language: fr
D: 2024-01-14 18:58:01:951(UploadFileFromContentUriWorker.kt:264) .uploadDocument()Chunking is allowed: false, and file size is greater than the minimum chunk size: false
D: 2024-01-14 18:58:01:952(LogBuilder.kt:38) .logHttp()[Network, request] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] Content-Type: application/xml; charset=utf-8
D: 2024-01-14 18:58:01:954(LogBuilder.kt:38) .logHttp()[Network, request] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] Content-Length: 432
D: 2024-01-14 18:58:01:956(LogBuilder.kt:38) .logHttp()[Network, request] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] Host: ocis.DOMAIN.COM:XXX
D: 2024-01-14 18:58:01:957(LogBuilder.kt:38) .logHttp()[Network, request] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] Connection: Keep-Alive
D: 2024-01-14 18:58:01:959(LogBuilder.kt:38) .logHttp()[Network, request] [body] [f01f6728-b163-413a-9a59-3f59d0dae069] Length: 432 byte body
D: 2024-01-14 18:58:01:960(LogBuilder.kt:38) .logHttp()[Network, request] [body] [f01f6728-b163-413a-9a59-3f59d0dae069] Type: application/xml; charset=utf-8
D: 2024-01-14 18:58:01:962(LogBuilder.kt:38) .logHttp()[Network, request] [body] [f01f6728-b163-413a-9a59-3f59d0dae069] --> Body start for request
D: 2024-01-14 18:58:01:965(LogBuilder.kt:38) .logHttp()[Network, request] [body] [f01f6728-b163-413a-9a59-3f59d0dae069] <?xml version='1.0' encoding='UTF-8' ?><propfind xmlns="DAV:" xmlns:CAL="urn:ietf:params:xml:ns:caldav" xmlns:CARD="urn:ietf:params:xml:ns:carddav" xmlns:SABRE="http://sabredav.org/ns" xmlns:OC="http://owncloud.org/ns"><prop><displayname /><getcontenttype /><resourcetype /><getcontentlength /><getlastmodified /><creationdate /><getetag /><OC:permissions /><OC:id /><OC:size /><OC:privatelink /><OC:share-types /></prop></propfind>
D: 2024-01-14 18:58:01:967(LogBuilder.kt:38) .logHttp()[Network, request] [body] [f01f6728-b163-413a-9a59-3f59d0dae069] <-- Body end for request -- Omitted: 0 bytes
D: 2024-01-14 18:58:02:032(LogBuilder.kt:38) .logHttp()[Network, response] [info] [f01f6728-b163-413a-9a59-3f59d0dae069] Method: PROPFIND URL: https://ocis.DOMAIN.COM:XXX/remote.php/dav/files/USER/Photos//IMG_20240114_183801.jpg Code: 404 Message: Not Found
D: 2024-01-14 18:58:02:035(LogBuilder.kt:38) .logHttp()[Network, response] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] Access-Control-Allow-Origin: *
D: 2024-01-14 18:58:02:037(LogBuilder.kt:38) .logHttp()[Network, response] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] Content-Length: 201
D: 2024-01-14 18:58:02:039(LogBuilder.kt:38) .logHttp()[Network, response] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] Content-Security-Policy: default-src 'none';
D: 2024-01-14 18:58:02:040(LogBuilder.kt:38) .logHttp()[Network, response] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] Content-Type: text/xml; charset=utf-8
D: 2024-01-14 18:58:02:042(LogBuilder.kt:38) .logHttp()[Network, response] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] Date: Sun, 14 Jan 2024 17:58:02 GMT
D: 2024-01-14 18:58:02:045(LogBuilder.kt:38) .logHttp()[Network, response] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] Vary: Origin
D: 2024-01-14 18:58:02:047(LogBuilder.kt:38) .logHttp()[Network, response] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] X-Content-Type-Options: nosniff
D: 2024-01-14 18:58:02:050(LogBuilder.kt:38) .logHttp()[Network, response] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] X-Download-Options: noopen
D: 2024-01-14 18:58:02:052(LogBuilder.kt:38) .logHttp()[Network, response] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] X-Frame-Options: SAMEORIGIN
D: 2024-01-14 18:58:02:053(LogBuilder.kt:38) .logHttp()[Network, response] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] X-Permitted-Cross-Domain-Policies: none
D: 2024-01-14 18:58:02:055(LogBuilder.kt:38) .logHttp()[Network, response] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] X-Request-Id: f01f6728-b163-413a-9a59-3f59d0dae069
D: 2024-01-14 18:58:02:056(LogBuilder.kt:38) .logHttp()[Network, response] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] X-Robots-Tag: none
D: 2024-01-14 18:58:02:057(LogBuilder.kt:38) .logHttp()[Network, response] [header] [f01f6728-b163-413a-9a59-3f59d0dae069] X-Xss-Protection: 1; mode=block
D: 2024-01-14 18:58:02:058(LogBuilder.kt:38) .logHttp()[Network, response] [body] [f01f6728-b163-413a-9a59-3f59d0dae069] Length: 201 byte body
D: 2024-01-14 18:58:02:059(LogBuilder.kt:38) .logHttp()[Network, response] [body] [f01f6728-b163-413a-9a59-3f59d0dae069] Type: text/xml; charset=utf-8
D: 2024-01-14 18:58:02:061(LogBuilder.kt:38) .logHttp()[Network, response] [body] [f01f6728-b163-413a-9a59-3f59d0dae069] --> Body start for response
D: 2024-01-14 18:58:02:062(LogBuilder.kt:38) .logHttp()[Network, response] [body] [f01f6728-b163-413a-9a59-3f59d0dae069] <?xml version="1.0" encoding="UTF-8"?>
<d:error xmlns:d="DAV" xmlns:s="http://sabredav.org/ns"><s:exception>Sabre\DAV\Exception\NotFound</s:exception><s:message>Resource not found</s:message></d:error>
D: 2024-01-14 18:58:02:064(LogBuilder.kt:38) .logHttp()[Network, response] [body] [f01f6728-b163-413a-9a59-3f59d0dae069] <-- Body end for response -- Omitted: 0 bytes
D: 2024-01-14 18:58:02:067(OwnCloudClient.java:129) .saveExecuteHttpMethod()Executing in request with id 22b90bae-d3f5-4781-b128-b8ce4a107af9
D: 2024-01-14 18:58:02:067(CheckPathExistenceRemoteOperation.kt:71) .run()Existence check for https://ocis.DOMAIN.COM:XXX/remote.php/dav/files/USER/Photos//IMG_20240114_183801.jpg finished with HTTP status 404(FAIL)
D: 2024-01-14 18:58:02:069(LogBuilder.kt:38) .logHttp()[Network, request] [info] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Method: PUT URL: https://ocis.DOMAIN.COM:XXX/remote.php/dav/files/USER/Photos//IMG_20240114_183757.jpg
D: 2024-01-14 18:58:02:069(UploadFileFromContentUriWorker.kt:264) .uploadDocument()Chunking is allowed: false, and file size is greater than the minimum chunk size: false
D: 2024-01-14 18:58:02:070(LogBuilder.kt:38) .logHttp()[Network, request] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Authorization: [redacted]
D: 2024-01-14 18:58:02:070(LogBuilder.kt:38) .logHttp()[Network, request] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] X-OC-Mtime: 1705253882
D: 2024-01-14 18:58:02:071(LogBuilder.kt:38) .logHttp()[Network, request] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] OC-Total-Length: 3565754
D: 2024-01-14 18:58:02:071(LogBuilder.kt:38) .logHttp()[Network, request] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] X-Request-ID: 22b90bae-d3f5-4781-b128-b8ce4a107af9
D: 2024-01-14 18:58:02:072(LogBuilder.kt:38) .logHttp()[Network, request] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] User-Agent: Mozilla/5.0 (Android) ownCloud-android/4.1.1
D: 2024-01-14 18:58:02:073(LogBuilder.kt:38) .logHttp()[Network, request] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Accept-Encoding: identity
D: 2024-01-14 18:58:02:074(LogBuilder.kt:38) .logHttp()[Network, request] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Accept-Language: fr
D: 2024-01-14 18:58:02:074(LogBuilder.kt:38) .logHttp()[Network, request] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Content-Length: 3565754
D: 2024-01-14 18:58:02:075(LogBuilder.kt:38) .logHttp()[Network, request] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Host: ocis.DOMAIN.COM:XXX
D: 2024-01-14 18:58:02:076(LogBuilder.kt:38) .logHttp()[Network, request] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Connection: Keep-Alive
D: 2024-01-14 18:58:02:077(LogBuilder.kt:38) .logHttp()[Network, request] [body] [22b90bae-d3f5-4781-b128-b8ce4a107af9] One shot body -- Omitted
D: 2024-01-14 18:58:04:857(FileRequestBody.kt:70) .writeTo()File with name IMG_20240114_183757.jpg and size 3565754 written in request body
D: 2024-01-14 18:58:06:433(LogBuilder.kt:38) .logHttp()[Network, response] [info] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Method: PUT URL: https://ocis.DOMAIN.COM:XXX/remote.php/dav/files/USER/Photos//IMG_20240114_183757.jpg Code: 201 Message: Created
D: 2024-01-14 18:58:06:436(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Access-Control-Allow-Origin: *
D: 2024-01-14 18:58:06:439(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Content-Length: 0
D: 2024-01-14 18:58:06:442(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Content-Security-Policy: default-src 'none';
D: 2024-01-14 18:58:06:445(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Date: Sun, 14 Jan 2024 17:58:07 GMT
D: 2024-01-14 18:58:06:447(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Etag: "31394126183e22d59adcbc405437e931"
D: 2024-01-14 18:58:06:450(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Last-Modified: Sun, 14 Jan 2024 17:38:02 +0000
D: 2024-01-14 18:58:06:452(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Oc-Etag: "31394126183e22d59adcbc405437e931"
D: 2024-01-14 18:58:06:455(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Oc-Fileid: XXXX$XXXX!45276aeb-4865-4c11-ac46-12977729d194
D: 2024-01-14 18:58:06:457(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Vary: Origin
D: 2024-01-14 18:58:06:459(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] X-Content-Type-Options: nosniff
D: 2024-01-14 18:58:06:461(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] X-Download-Options: noopen
D: 2024-01-14 18:58:06:462(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] X-Frame-Options: SAMEORIGIN
D: 2024-01-14 18:58:06:463(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] X-Oc-Mtime: accepted
D: 2024-01-14 18:58:06:465(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] X-Permitted-Cross-Domain-Policies: none
D: 2024-01-14 18:58:06:467(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] X-Request-Id: 22b90bae-d3f5-4781-b128-b8ce4a107af9
D: 2024-01-14 18:58:06:468(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] X-Robots-Tag: none
D: 2024-01-14 18:58:06:471(LogBuilder.kt:38) .logHttp()[Network, response] [header] [22b90bae-d3f5-4781-b128-b8ce4a107af9] X-Xss-Protection: 1; mode=block
D: 2024-01-14 18:58:06:473(LogBuilder.kt:38) .logHttp()[Network, response] [body] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Length: 0 byte body
D: 2024-01-14 18:58:06:475(LogBuilder.kt:38) .logHttp()[Network, response] [body] [22b90bae-d3f5-4781-b128-b8ce4a107af9] Type: null
D: 2024-01-14 18:58:06:476(LogBuilder.kt:38) .logHttp()[Network, response] [body] [22b90bae-d3f5-4781-b128-b8ce4a107af9] --> Body start for response
D: 2024-01-14 18:58:06:477(LogBuilder.kt:38) .logHttp()[Network, response] [body] [22b90bae-d3f5-4781-b128-b8ce4a107af9] <-- Body end for response -- Binary -- Omitted: 0 bytes
D: 2024-01-14 18:58:06:483(OwnCloudClient.java:129) .saveExecuteHttpMethod()Executing in request with id fde6613f-1ac7-474c-9209-74909e98e0f8
D: 2024-01-14 18:58:06:486(LogBuilder.kt:38) .logHttp()[Network, request] [info] [fde6613f-1ac7-474c-9209-74909e98e0f8] Method: PUT URL: https://ocis.DOMAIN.COM:XXX/remote.php/dav/files/USER/Photos//IMG_20240114_183801.jpg
D: 2024-01-14 18:58:06:487(LogBuilder.kt:38) .logHttp()[Network, request] [header] [fde6613f-1ac7-474c-9209-74909e98e0f8] Authorization: [redacted]
D: 2024-01-14 18:58:06:488(LogBuilder.kt:38) .logHttp()[Network, request] [header] [fde6613f-1ac7-474c-9209-74909e98e0f8] X-OC-Mtime: 1705253886
D: 2024-01-14 18:58:06:489(LogBuilder.kt:38) .logHttp()[Network, request] [header] [fde6613f-1ac7-474c-9209-74909e98e0f8] OC-Total-Length: 3860720
D: 2024-01-14 18:58:06:490(UploadFileFromFileSystemOperation.kt:120) .uploadFile()File uploaded successfully. New etag for file IMG_20240114_183757.jpg is 31394126183e22d59adcbc405437e931
I: 2024-01-14 18:58:06:491(UploadFileFromFileSystemOperation.kt:79) .run()Upload of /data/user/0/com.owncloud.android/files/owncloud/tmp/USER@ocis.DOMAIN.COM%3AXXX/Photos//IMG_20240114_183757.jpg to /Photos//IMG_20240114_183757.jpg: Operation finished with HTTP status code -1 (success)

@mcarbonne mcarbonne mentioned this issue Jan 19, 2024
Open
@mcarbonne
Copy link
Author

mcarbonne commented Jan 19, 2024 •
edited
Loading

While commenting the other issue (owncloud/android#3983 (comment)), I add a look at all my uploaded photos, and I noticed that I have also partially corrupted files.
Some photos are partially uploaded (0<size<real size) and then the android app re-upload the file with a (1) in the name.

It might be related to the corruption issue too.

How is file upload handled in OCIS ? Is it transactional ? (is the file available even if upload did not succeed ?)

EDIT : to reproduce the bug, maybe the scenario is the following:

  • start uploading file A at a very slow rate
  • start another upload of the same file A, but at full speed (before the first upload ends)
  • wait for first upload to finish ? / make it timeout ?
    I'll try to test those scenario with --limit-rate from curl. What I expect is the second upload to fail (due to a locking mechanism), or eventually both versions are kept (but available through file history).

@aduffeck
Copy link
Contributor

Little update from my side: while uploads into ocis should be atomic (they either complete or they don't) I was able to trigger wrong behavior using curl -X PUT -T - -m 10 ... which starts an upload but then closes the connection before finishing it.
This doesn't lead to a broken file in ocis like in the initial report but the file does end up getting truncated, which clearly isn't the expected behavior. Something's fishy.

@aduffeck aduffeck mentioned this issue Jan 22, 2024
Merged
@micbar micbar added this to the Release 5.0.0 milestone Jan 22, 2024
@aduffeck aduffeck moved this from Prio 1 to In progress in Infinite Scale Team Board Jan 24, 2024
@aduffeck
Copy link
Contributor

Fixed with the merge of #8278

@github-project-automation github-project-automation bot moved this from In progress to Done in Infinite Scale Team Board Jan 24, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Priority:p1-urgent Consider a hotfix release with only that fix Type:Bug
Projects
Infinite Scale Team Board
Archived in project
Milestone
Release 5.0.0
Development

No branches or pull requests
4 participants
@aduffeck @micbar @mcarbonne @JuancaG05