[BUG] Image autoupload uploads images twice under certain conditions

Dehumanizer77 commented 1 year ago

Actual behaviour

When image autoupload is turned on, images are uploaded twice, the second time with (2) at the end of the file name.

Expected behaviour

Images get uploaded only once.

Steps to reproduce

It usually happens when both image and video autoupload is turned on, however for example right now I only have image autoupload turned on and it still happens. Also yesterday, I took two images, one was uploaded once and the second one got uploaded twice. Fiddling with enabling/disabling image and/or video autoupload sometimes fixes the issue.

Can this problem be reproduced with the official owncloud server? not when I tried it now

Environment data

Android version: 12

Device model: Xiaomi Poco F3

Stock or customized system: Custom ROM (Pixel Experience 12)

ownCloud app version: 4.0-beta1 (but I have the problem with the latest stable version as well)

ownCloud server version: 10.11

Logs

ownCloud log (data/owncloud.log)

owncloud.2023-03-22.log

JuancaG05 commented 1 year ago

Hi @Dehumanizer77! Thanks for opening a new issue for this! We'll take a look and let you know about our findings 😉

web2wire commented 1 year ago

I have had this for several months now, it basically happens every time. The difference being for me I often get (2), (3) and several more versions of the same file. The original is sometimes, but not always zero sized. I am happy to provide further info if this helps.

Dehumanizer77 commented 1 year ago

It's totally unreliable, sometimes it uploads the file fine, sometimes with zero size, sometimes multiple times, sometimes just once...

vvzinovyev commented 1 year ago

Hi. Same for me. I did not notice zero size on the original file. I get even (3), (4), (5) sometimes. Usually I just delete such files and the original ones seem to be OK. It happens for quite a while already - half a year for sure and survived a few app upgrades. Just upgraded to the most recent version recently. I have Samsung S10e.

vvzinovyev commented 1 year ago

Actually, I upgraded to v3.0.4, and first time in a while did not have these dupes today. Let's see..

Dehumanizer77 commented 1 year ago

Since 4.0 beta does have the problem as well, I would be surprised if it was fixed in 3.0.4, but maybe some accidental change fixed it, let us know if the problem didn't reappear later.

vvzinovyev commented 1 year ago

So far only one file got a dupe since I upgraded to 3.0.4. This version is definitely better than whatever 2.x I had before.

web2wire commented 1 year ago

I'm on 3.0.4 and still getting the same issues. Multiple dupes, sometimes zero sized, along with sometimes originals zero sized also. This is the most worrying for me as it means that images are not in fact being synced but the OwnCloud app thinks they have been. Until later when I go to import them for processing and find that the images are empty/broken and have to see if I've still got the originals on my phone.

mihha commented 1 year ago

I have a similar issue where one image is uploaded to the /CameraUploads folder and the same image is uploaded to the /Camera/Igor folder.

That second folder is actually the one I configured in the ownCloud android client Settings and that is the folder I would expect to get uploaded files

I can't get rid of the original /CameraUpload folder

Dehumanizer77 commented 1 year ago

The original problem seems to be fixed now, at least with 4.0-beta4 I didn't notice duplicate files anymore.

vvzinovyev commented 1 year ago

The original problem seems to be fixed now, at least with 4.0-beta4 I didn't notice duplicate files anymore.

Cool, installed, let's see!

mihha commented 1 year ago

I installed the latest 4.0 beta version, but this bug still exists

Good thing is that it seems that other issue (uploading files to the default /CameraUpload and custom folder set in the settings) is being fixed

Dehumanizer77 commented 1 year ago

strange, so I'm just lucky now

mihha commented 1 year ago

It is getting worse

After some time, I get this

JuancaG05 commented 1 year ago

This is a known issue right now, no specific fix for it in the 4.0 version of the app. We'll check it ASAP and will keep you updated in this thread 🚀

jsiddall commented 11 months ago

FWIW this is still happening in version 4.1.1, only some files and usually only one extra copy

vvzinovyev commented 11 months ago

I moved to Nextcloud, and don't have this issue anytime

On Tue, 24 Oct 2023, 02:36 Jeff Siddall, @.***> wrote:

FWIW this is still happening in version 4.1.1, only some files and usually only one extra copy

— Reply to this email directly, view it on GitHub https://github.com/owncloud/android/issues/3983#issuecomment-1775980087, or unsubscribe https://github.com/notifications/unsubscribe-auth/ATBZIJSL5OJYFJP2PUBCT2LYA3IN5AVCNFSM6AAAAAAWDUUNWSVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTONZVHE4DAMBYG4 . You are receiving this because you commented.Message ID: @.***>

mcarbonne commented 8 months ago

Almost same issue observed with latest version (4.1.1) and with OCIS backend. Some detailed logs (android app) available: https://github.com/owncloud/ocis/issues/8239

I observed 2 slightly different outcomes:

one file on OCIS, but corrupted
two file on OCIS, the first one is partially uploaded (0 < size < real size) and the second one is OK, but with (1) in the name.

jsiddall commented 4 months ago

I updated to the latest Android client 4.2.2 a couple of days back and today opened up the app for the first time since the upgrade. After a while it auto-uploaded all the new photos exactly twice. No errors or failures in any of the uploaded files. This seems to be happening on the client because in the upload list I noticed it uploaded the photos, in date order, once and then immediately uploaded them again in the exact same order. Somehow it seems to be detecting new photos twice.

jsiddall commented 2 months ago

Android client recently updated to 4.3.1. This time I got exactly triplicates of every file!

I happened to see the client uploading and got a screenshot of the client simultaneously uploading the same file twice so the duplicates are being initiated by the client for sure. I don't know how to upload screenshots from Android but if it would be helpful I can figure it out.

Dehumanizer77 commented 2 months ago

I did not get any duplicates or triplicates with 4.3.1 so far... But I'll keep an eye on that for a few days or a week if I just have been lucky.

jsiddall commented 2 months ago

Yeah, I should have been more clear: I don't think 4.3.1 in itself is the cause of the triplicates. Just that whatever bug is causing it is still around in 4.3.1.

It is definitely somewhere in the code that finds new images. I don't know about other people's experience, but my client goes dormant after some time and doesn't upload new images until I open it again. Then, some minutes after re-opening, it uploads all the new images, and sometimes more than once.

Guessing that Android is preventing it from running in the background for some reason, but I am not sure how to fix that, or whether it would even prevent this issue.

JuancaG05 commented 2 months ago

Hi everyone! 👋

Just as an update: no, we have not been working on this lately, so the bug must be somewhere yet... 😿 We know this is so ugly, but we have a problem and it's that we are not able to reproduce this bug consistently. This happens arbitrarily, only some times and only with some files, so, it's also difficult for us to locate the error somehow. You know logs are welcome (if you get them just ask and we'll provide a secure way of uploading them so that only us are able to see them), or if you find out a way to reproduce it consistently, it would be very useful as well.

I don't know about other people's experience, but my client goes dormant after some time and doesn't upload new images until I open it again. Then, some minutes after re-opening, it uploads all the new images, and sometimes more than once.

Guessing that Android is preventing it from running in the background for some reason, but I am not sure how to fix that, or whether it would even prevent this issue.

About this, as you say, it is likely provoked by the Android Operating System. Android tries to save energy by killing, revoking permissions or even "deactivating" apps that have not been used for a long time (time decided by Android internally, not by apps developers). So, to help here, I would advice you to check your battery saving settings, but if everything looks OK there, just try to open the app more oftenly (once per week should be enough I guess...).

We'll keep updating here in any case, thanks for your patience and help 👍

vvzinovyev commented 2 months ago

After I switched to Nextcloudpi, zero issues with duplicates and overall much better experience :)

JuancaG05 commented 2 months ago

Hi @vvzinovyev! Glad to hear that! But this issue is aimed to discuss about the bug in the ownCloud Android app, and you already commented the same some messages above, so please, don't spam the GitHub tickets. Thanks for your collaboration 😃

vvzinovyev commented 2 months ago

Oops, sorry, did not see I'm repeating. Unsubscribing from this conversation )

jsiddall commented 2 months ago

After I switched to Nextcloudpi, zero issues with duplicates and overall much better experience :)

Interesting. Since the client seems to be the thing doing the duplication it is surprising that it would work differently on NextCloud.

Hi everyone! 👋

Just as an update: no, we have not been working on this lately, so the bug must be somewhere yet... 😿 We know this is so ugly, but we have a problem and it's that we are not able to reproduce this bug consistently. This happens arbitrarily, only some times and only with some files, so, it's also difficult for us to locate the error somehow. You know logs are welcome (if you get them just ask and we'll provide a secure way of uploading them so that only us are able to see them), or if you find out a way to reproduce it consistently, it would be very useful as well.

I don't know about other people's experience, but my client goes dormant after some time and doesn't upload new images until I open it again. Then, some minutes after re-opening, it uploads all the new images, and sometimes more than once. Guessing that Android is preventing it from running in the background for some reason, but I am not sure how to fix that, or whether it would even prevent this issue.

About this, as you say, it is likely provoked by the Android Operating System. Android tries to save energy by killing, revoking permissions or even "deactivating" apps that have not been used for a long time (time decided by Android internally, not by apps developers). So, to help here, I would advice you to check your battery saving settings, but if everything looks OK there, just try to open the app more oftenly (once per week should be enough I guess...).

We'll keep updating here in any case, thanks for your patience and help 👍

Ah, yeah, I think I have the Android power saving mode enabled. Maybe that is making this occur more often for me than others. Still, I don't get duplicates every time so there is an element of unpredictability to it.

I do have logging enabled. There are lots of files. Am I looking for one that has the next more recent date after the problem occurred? The last issue occurred 2024-07-28 about 11:47 PM local time. There is a large log file (3M) dated 2024-07-28_22.54.00 which is earlier than the problem. The next log is dated 2024-07-29 and it is tiny (1K).

Please let me know about which files and where I can provide those.

jesmrec commented 2 months ago

I do have logging enabled. There are lots of files. Am I looking for one that has the next more recent date after the problem occurred? The last issue occurred 2024-07-28 about 11:47 PM local time. There is a large log file (3M) dated 2024-07-28_22.54.00 which is earlier than the problem. The next log is dated 2024-07-29 and it is tiny (1K).

Please let me know about which files and where I can provide those.

It's important that the Log HTTP requests and responses is also enabled. I'll will give you some context about how the feature works, so that, it's easier to understand what's going on:

When pictures/videos auto-uploads are enabled, a background process runs every fifteen minutes (time slot is internally decided by the Android operating system), saving the latest execution timestamp after every run. The background process checks the camera roll to find pictures/videos which capture timestamp is newer than its own latest execution. Then, it sends those pictures/videos to the uploads queue, and finally updates the execution time as reference for the next run.

If you have duplications, it means that the background process is enqueuing pictures/videos that were already enqueued in previous runs. I have some guesses, then:

The latest execution timestamp is not being correctly updated. Iin that case, it'd be easier to reproduce, it'd be a bug in the logic.
The pictures/videos' capture date is stored somehow wrongly, leading the background process to kind of confusion when fetching the items to enqueue. Every vendor or camera app running over any OS variant might cause this... but nothing to assure at the moment.

I hope that it helps to understand. We agree that this is an ugly bug, you are totally right. But, as @JuancaG05 stated, we can not fix it without reproducing it correctly.

If you are kind to fetch some logs including the repeated uploads' scenario, you can push them to this link:

https://infinite.owncloud.com/s/IcWNuXBUbQwMUti Pwd: aa55AA..

Any other further idea or suggestion from anyone is also welcome!

DerFuz commented 2 months ago

How is the upload-mechnism handling network connection problems when a picture is in the upload-queue?

For myself, I experience this problem more often when I am hiking and taking pictures. In the mountains I do not always have a (stable) data connection but the queueing should still take place. Is it maybe requeuing a failed upload and therefore uploading multiple queued files when it's online again?

I can't remember a duplicate when I am home and have a stable WiFi connection, but I will pay more attention to these scenarios going forward.

Just as another input and this scenario should somehow be reproducible.

jesmrec commented 2 months ago

How is the upload-mechnism handling network connection problems when a picture is in the upload-queue?

this should not have nothing to do, but i'll explain a little bit: we handle different statuses for a transfer: enqueued, current, uploaded and failed. A new upload is enqueued, then goes to current (ongoing) and finally uploaded. If something wrong happens, it goes to failed. Here, we have two different scenarios: failed because a lack of connection or connection problems, and other failures (f. ex. server down). In case of failure because lack of connection, failed uploads are automatically retried when connection is back, otherwise they must be retried manually (retry button available) when the blocking issue is fixed.

I said it does not has to do, because the background process that i described above just sends the new pictures/videos to the queue. Transfer's handling it is not its responsibility, that's other process.

Anyway, i will get your idea. Maybe @Aitorbp can check in the code whether the execution date is always updated with no restrictions, after every process runs (it should but sometimes bugs happen).

DerFuz commented 2 months ago

Yesterday it happened to me again. One picture was uploaded totally fine while two hours later three other images were duplicated. The collected logs for these 4 activities are dropped into the mentioned share.

I tried to interpret the logs + source code (https://github.com/owncloud/android/blob/master/owncloudApp/src/main/java/com/owncloud/android/workers/CameraUploadsWorker.kt), but I have no knowledge of Kotlin and Android programming to give suggestions.

Some things I still wanna point out in the logs:

The OCTransfer-object of the successful upload (single image) sources the Camera directly via the localpath (localPath=content://com.android.externalstorage.documents/tree/...), while the 3 other images have 2 OCTransfer-objects each (one from camerapath and one from a temp directory inside the app (localPath=/data/user/0/com.owncloud.android/files/owncloud/tmp/...) ← would explain duplicates
The duplicates are created right after the last image was uploaded successfully (feels like a second run of syncFolder - I got picture and video uploads enabled with copy behavior)
The FileNotFoundException seems to be the reason for empty duplicates (E: 2024-08-02 17:20:24:252(FileRequestBody.kt:72)java.io.FileNotFoundException: /data/user/0/com.owncloud.android/files/owncloud/tmp/...)
The upload of the 3 problematic images took quite a long time according to the duration field of the response logs (could be a bad connection - I was inside a big building with thick walls at that time)

One question about updating of the timestamp in https://github.com/owncloud/android/blob/01716a626576cd8b72035f0268519d99ba93d3ac/owncloudApp/src/main/java/com/owncloud/android/workers/CameraUploadsWorker.kt#L167 The timestamp will be updated after all files have been enqueued. Does the enqueueSingleUpload function just queue the file and return or does it have to wait for a successful upload? As said I have no idea about Android Programming and don't know what the WorkManager does. :)

Anyway, I am open to help troubleshoot this issue but I also understand it's quite difficult if the issue can't be reproduced consistently.

jesmrec commented 2 months ago

thanks a lot @DerFuz !!! i will review your logs and comments, pretty useful.

The timestamp will be updated after all files have been enqueued. Does the enqueueSingleUpload function just queue the file and return or does it have to wait for a successful upload? As said I have no idea about Android Programming and don't know what the WorkManager does. :)

this is a question for @Aitorbp

Anyway, I am open to help troubleshoot this issue but I also understand it's quite difficult if the issue can't be reproduced consistently.

thanks again!!

jesmrec commented 2 months ago

The OCTransfer-object of the successful upload (single image) sources the Camera directly via the localpath (localPath=content://com.android.externalstorage.documents/tree/...), while the 3 other images have 2 OCTransfer-objects each (one from camerapath and one from a temp directory inside the app

that's a good point. Will check if it does mean something bad/good

The duplicates are created right after the last image was uploaded successfully (feels like a second run of syncFolder - I got picture and video uploads enabled with copy behavior)

but there is no logged run in the middle, that is making me freaking out

The FileNotFoundException seems to be the reason for empty duplicates (E: 2024-08-02 17:20:24:252(FileRequestBody.kt:72)java.io.FileNotFoundException: /data/user/0/com.owncloud.android/files/owncloud/tmp/...)

not sure if the error itself affects, because just before the name collision was detected and just after, the PUT request sends the dup file to the server. But, will require attention as well.

The upload of the 3 problematic images took quite a long time according to the duration field of the response logs (could be a bad connection - I was inside a big building with thick walls at that time)

shouldn't be related. Anyway, i will not discard any option.

keep working on it

jesmrec commented 2 months ago

I will comment the log file you sent, just in case anyone else wants to contribute, in order to explain the clear problem. Thanks again for sending it, @DerFuz, because it's not an easy one to reproduce.

Starting at this point:

I: 2024-08-02 17:14:15:192(CameraUploadsWorker.kt:254)Last sync PICTURE_UPLOADS: Fri Aug 02 15:56:28 GMT+02:00 2024
I: 2024-08-02 17:14:15:193(CameraUploadsWorker.kt:255)CurrentTimestamp Fri Aug 02 17:10:18 GMT+02:00 2024
I: 2024-08-02 17:14:15:194(CameraUploadsWorker.kt:256)3611 files found in folder: /tree/primary:DCIM/Camera
I: 2024-08-02 17:14:15:194(CameraUploadsWorker.kt:257)3 files are PICTURE_UPLOADS and were taken after last sync

The background process detects that 3 new items were added since the latest sync. So, everything OK ✅ . In fact, the next log lines tell us which those files are:

I: 2024-08-02 17:14:15:285(UploadFileFromContentUriUseCase.kt:62)Plain upload of /tree/primary:DCIM/Camera/document/primary:DCIM/Camera/IMG_20240802_155756.jpg has been enqueued.
I: 2024-08-02 17:14:15:303(UploadFileFromContentUriUseCase.kt:62)Plain upload of /tree/primary:DCIM/Camera/document/primary:DCIM/Camera/IMG_20240802_155757.jpg has been enqueued.
I: 2024-08-02 17:14:15:327(UploadFileFromContentUriUseCase.kt:62)Plain upload of /tree/primary:DCIM/Camera/document/primary:DCIM/Camera/IMG_20240802_155758_1.jpg has been enqueued.

the has been enqueued annotation also remarks that the work is correctly done ✅ . From now on, I will track just one of them, the first one IMG_20240802_155756.jpg

The next step in IMG_20240802_155756.jpg 's travel is creating an OCTransfer object. It contains all the relevant information to perform a transfer

D: 2024-08-02 17:14:15:377(UploadFileFromContentUriWorker.kt:155)Upload info: OCTransfer(id=2471, localPath=content://com.android.externalstorage.documents/tree/primary%3ADCIM%2FCamera/document/primary%3ADCIM%2FCamera%2FIMG_20240802_155756.jpg, remotePath=/CameraUpload/IMG_20240802_155756.jpg, accountName=xxx, fileSize=7444368, status=TRANSFER_QUEUED, localBehaviour=COPY, forceOverwrite=false, transferEndTimestamp=null, lastResult=null, createdBy=ENQUEUED_AS_CAMERA_UPLOAD_PICTURE, transferId=null, spaceId=null)

That's right. Here we will take also the id of the OCTransfer = 2471.

Next: mobile client will transfer the file to the server, but first, it checks if another file with same name and location already exists in the server side. Here is the propfind request

D: 2024-08-02 17:14:16:999(LogInterceptor.kt:67)REQUEST 5d955519-a643-4524-baf0-1894d88b55e9 
{
  "request": {
    "body": "<?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>",
    "headers": {
      "Depth": "0",
      "Authorization": "Basic [redacted]",
      "X-Request-ID": "5d955519-a643-4524-baf0-1894d88b55e9",
      "User-Agent": "Mozilla/5.0 (Android) ownCloud-android/4.3.1",
      "Accept-Encoding": "identity",
      "Accept-Language": "en",
      "Content-Type": "application/xml; charset=utf-8",
      "Content-Length": "432",
      "Host": "xxx",
      "Connection": "Keep-Alive",
      "Cookie": "oc_sessionPassphrase=somePassphrase; ocoybz17zi9o=1ev0ee7pcbrosurr3dbumse1ti; cookie_test=test"
    },
    "info": {
      "id": "5d955519-a643-4524-baf0-1894d88b55e9",
      "method": "PROPFIND",
      "url": "https://xxx/remote.php/dav/files/user/CameraUpload/IMG_20240802_155756.jpg"
    }
  }
}

and the response:

D: 2024-08-02 17:14:17:003(LogInterceptor.kt:133)RESPONSE 5d955519-a643-4524-baf0-1894d88b55e9 
{
  "response": {
    "body": {
      "data": "",
      "length": 0
    },
    "headers": {
      "Date": "Fri, 02 Aug 2024 15:14:16 GMT",
      "Server": "Apache",
      "X-Content-Type-Options": "nosniff",
      "X-XSS-Protection": "0",
      "X-Robots-Tag": "none",
      "X-Frame-Options": "SAMEORIGIN",
      "X-Download-Options": "noopen",
      "X-Permitted-Cross-Domain-Policies": "none",
      "Expires": "Thu, 19 Nov 1981 08:52:00 GMT",
      "Cache-Control": "no-store, no-cache, must-revalidate",
      "Pragma": "no-cache",
      "Content-Security-Policy": "default-src 'self'; script-src 'self' 'unsafe-eval'; style-src 'self' 'unsafe-inline'; frame-src *; img-src * data: blob:; font-src 'self' data:; media-src *; connect-src *",
      "Location": "http://xxx/apps/files/",
      "Content-Length": "0",
      "Content-Type": "text/html; charset=UTF-8",
      "Set-Cookie": "oc_sessionPassphrase=somePassphrase; expires=Fri, 02-Aug-2024 15:34:16 GMT; Max-Age=1200; path=/; HttpOnly; SameSite=Strict",
      "Strict-Transport-Security": "max-age=31536000; preload",
      "Feature-Policy": "sync-xhr 'self'",
      "Keep-Alive": "timeout=5, max=97",
      "Connection": "Keep-Alive"
    },
    "info": {
      "id": "5d955519-a643-4524-baf0-1894d88b55e9",
      "method": "PROPFIND",
      "reply": {
        "cached": false,
        "duration": 752,
        "durationString": "duration(0h, 0min, 0s, 752ms)",
        "status": 404,
        "version": "http/1.1"
      },
      "url": "https://xxx/remote.php/dav/files/yyy/CameraUpload/IMG_20240802_155756.jpg"
    }
  }
}

the "status":404 means that there is no item with same name in same location in the server. So, we can push the file with its own name ✅ . Next line tells explicitly:

D: 2024-08-02 17:14:17:006(CheckPathExistenceRemoteOperation.kt:71)Existence check for https://xxx/remote.php/dav/files/yyy/CameraUpload/IMG_20240802_155756.jpg finished with HTTP status 404(FAIL)

Next: OCTransfer (2471) changes status to TRANSFER_IN_PROGRESS. Things start to move. The original file is copied first in /tmp to help to handle posible errors that could happen during the transfer. ✅

D: 2024-08-02 17:15:10:019(UploadFileFromContentUriWorker.kt:155)Upload info: OCTransfer(id=2471, localPath=/data/user/0/com.owncloud.android/files/owncloud/tmp/yyy@zzz/CameraUpload/IMG_20240802_155756.jpg, remotePath=/CameraUpload/IMG_20240802_155756.jpg, accountName=yyy@xxx, fileSize=7444368, status=TRANSFER_IN_PROGRESS, localBehaviour=COPY, forceOverwrite=false, transferEndTimestamp=null, lastResult=null, createdBy=ENQUEUED_AS_CAMERA_UPLOAD_PICTURE, transferId=null, spaceId=null)

Next: the file content is set as the body of the request that will send to the server:

D: 2024-08-02 17:16:11:862(FileRequestBody.kt:70)File with name IMG_20240802_155756.jpg and size 7444368 written in request body

Next: a PUT operation sends the file:

D: 2024-08-02 17:16:42:930(LogInterceptor.kt:67)REQUEST 2a242b62-3e9e-4639-a70f-22555acaeed9 
{
  "request": {
    "body": "One shot body --   Omitted",
    "headers": {
      "Authorization": "Basic [redacted]",
      "X-OC-Mtime": "1722607076",
      "OC-Total-Length": "7444368",
      "X-Request-ID": "2a242b62-3e9e-4639-a70f-22555acaeed9",
      "User-Agent": "Mozilla/5.0 (Android) ownCloud-android/4.3.1",
      "Accept-Encoding": "identity",
      "Accept-Language": "en",
      "Content-Length": "7444368",
      "Host": "xxx",
      "Connection": "Keep-Alive",
      "Cookie": "oc_sessionPassphrase=somePassphrase; ocoybz17zi9o=1ev0ee7pcbrosurr3dbumse1ti; cookie_test=test"
    },
    "info": {
      "id": "2a242b62-3e9e-4639-a70f-22555acaeed9",
      "method": "PUT",
      "url": "https://xxx/remote.php/dav/files/yyy/CameraUpload/IMG_20240802_155756.jpg"
    }
  }
}

and the response is successful ("status": 201) ✅

D: 2024-08-02 17:16:42:955(LogInterceptor.kt:133)RESPONSE 2a242b62-3e9e-4639-a70f-22555acaeed9 
{
  "response": {
    "body": {
      "data": "",
      "length": 0
    },
    "headers": {
      "Date": "Fri, 02 Aug 2024 15:14:18 GMT",
      "Server": "Apache",
      "X-Content-Type-Options": "nosniff",
      "X-XSS-Protection": "0",
      "X-Robots-Tag": "none",
      "X-Frame-Options": "SAMEORIGIN",
      "X-Download-Options": "noopen",
      "X-Permitted-Cross-Domain-Policies": "none",
      "Expires": "Thu, 19 Nov 1981 08:52:00 GMT",
      "Cache-Control": "no-store, no-cache, must-revalidate",
      "Pragma": "no-cache",
      "Content-Security-Policy": "default-src 'none';",
      "X-OC-MTime": "accepted",
      "OC-FileId": "00018076ocoybz17zi9o",
      "Content-Length": "0",
      "ETag": "\"d4bcf1d9bff859a5fc08bc1c0dba4633\"",
      "OC-ETag": "\"d4bcf1d9bff859a5fc08bc1c0dba4633\"",
      "Content-Type": "text/html; charset=UTF-8",
      "Set-Cookie": "oc_sessionPassphrase=somePassphrase; expires=Fri, 02-Aug-2024 15:34:18 GMT; Max-Age=1200; path=/; HttpOnly; SameSite=Strict",
      "Strict-Transport-Security": "max-age=31536000; preload",
      "Feature-Policy": "sync-xhr 'self'",
      "Keep-Alive": "timeout=5, max=91",
      "Connection": "Keep-Alive"
    },
    "info": {
      "id": "2a242b62-3e9e-4639-a70f-22555acaeed9",
      "method": "PUT",
      "reply": {
        "cached": false,
        "duration": 145229,
        "durationString": "duration(0h, 2min, 145s, -119771ms)",
        "status": 201,
        "version": "http/1.1"
      },
      "url": "https://xxx/remote.php/dav/files/yyy/CameraUpload/IMG_20240802_155756.jpg"
    }
  }
}

so, at this point: file was detected as new, name is collision-free, and file is sent to the server successfully 💯 ✅ :

D: 2024-08-02 17:16:42:966(UploadFileFromFileSystemOperation.kt:130)File uploaded successfully. New etag for file IMG_20240802_155756.jpg is d4bcf1d9bff859a5fc08bc1c0dba4633
I: 2024-08-02 17:16:42:967(UploadFileFromFileSystemOperation.kt:89)Upload of /data/user/0/com.owncloud.android/files/owncloud/tmp/yyy@xxx/CameraUpload/IMG_20240802_155756.jpg to /CameraUpload/IMG_20240802_155756.jpg - HTTP status code: 207

at 2024-08-02 17:16:42:967 everything should be done, but, at 2024-08-02 17:20:22:705 everything starts again:

D: 2024-08-02 17:20:22:705: sent a request to check if the file exists in server D: 2024-08-02 17:20:22:711: response with 207 because file exist (it was created above) D: 2024-08-02 17:20:22:714: check existence of file: file exists -> name collision:

D: 2024-08-02 17:20:23:424(UploadFileFromContentUriWorker.kt:248)Name collision detected, let's rename it to /CameraUpload/IMG_20240802_155756 (1).jpg

After reviewing what's going on in the middle, nothing bad appears there. There is no background process execution that scans the camera folder to get new pics... at least, nothing logged.

Next is the following error:

I: 2024-08-02 17:20:24:585(UploadFileFromFileSystemOperation.kt:89)Upload of /data/user/0/com.owncloud.android/files/owncloud/tmp/yyy@xxx/CameraUpload/IMG_20240802_155756.jpg to /CameraUpload/IMG_20240802_155756 (1).jpg - HTTP status code: 207
D: 2024-08-02 17:20:24:586(OwnCloudClient.java:129)Executing in request with id 2a5fd15d-a100-4f83-94ad-3428e53c805c
E: 2024-08-02 17:20:24:252(FileRequestBody.kt:72)java.io.FileNotFoundException: /data/user/0/com.owncloud.android/files/owncloud/tmp/UserX@cloud.user1.xyz/CameraUpload/IMG_20240802_155756.jpg: open failed: ENOENT (No such file or directory)
    at libcore.io.IoBridge.open(IoBridge.java:496)
    at java.io.FileInputStream.<init>(FileInputStream.java:159)
    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.logging.LogInterceptor.intercept(LogInterceptor.kt:56)
    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:122)
    at com.owncloud.android.lib.resources.files.UploadFileFromFileSystemOperation.run(UploadFileFromFileSystemOperation.kt:88)
    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: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)
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:167)
    at libcore.io.BlockGuardOs.open(BlockGuardOs.java:252)
    at libcore.io.ForwardingOs.open(ForwardingOs.java:167)
    at android.app.ActivityThread$AndroidOs.open(Unknown Source:15)
    at libcore.io.IoBridge.open(IoBridge.java:482)
    ... 46 more

that seems to be related with the origin of the file. That's only a guess, but i think this error does not cause the problem. Just after that, a PUT is sent and...

I: 2024-08-02 17:20:24:585(UploadFileFromFileSystemOperation.kt:89)Upload of /data/user/0/com.owncloud.android/files/owncloud/tmp/yyy@xxx/CameraUpload/IMG_20240802_155756.jpg to /CameraUpload/IMG_20240802_155756 (1).jpg - HTTP status code: 207

so, we have here the duplication. But there is nothing that triggers it. My new guess:

could it be a race condition? kinda concurrency problem. We'll need to take a look, probably with another eyes.

jsiddall commented 2 months ago

In case it helps I also uploaded my log file that had triplicates, and confirmed that you can see the file getting uploaded the third time as ...(2).jpg after collisions were detected on the previous 2 uploads of the same file.

DerFuz commented 2 months ago

@jesmrec Thanks for your thorough analysis. I am happy to end with almost the same conclusion as you.

Next: OCTransfer (2471) changes status to TRANSFER_IN_PROGRESS. Things start to move. The original file is copied first in /tmp to help to handle posible errors that could happen during the transfer. ✅

Why can't I find a second OCTransfer object for 2470 then (with tmp as localPath)?

jesmrec commented 2 months ago

Why can't I find a second OCTransfer object for 2470 then (with tmp as localPath)?

it's weird because the uploaded file was somewhen in /tmp, as any uploaded file. I have no explanation for that at this point.

JuancaG05 commented 1 month ago

Hi @DerFuz! Thanks for your collaboration, you did a great job with your findings 😃.

About this point:

The OCTransfer-object of the successful upload (single image) sources the Camera directly via the localpath (localPath=content://com.android.externalstorage.documents/tree/...), while the 3 other images have 2 OCTransfer-objects each (one from camerapath and one from a temp directory inside the app (localPath=/data/user/0/com.owncloud.android/files/owncloud/tmp/...) ← would explain duplicates

Could be a great idea. In the new 4.4.0-beta.1, we made some changes and now the localPath field doesn't change ever, we keep there the original path in the device and in a newly created field, the temporal path. Could you check if the duplicates problem can still be reproduced in this new version? You can find it in the Beta Program in Play Store, or installing the APK uploaded here: https://github.com/owncloud/android/releases/tag/v4.4.0-beta.1

EDIT: It seems that localPath keeps changing yet despite the new field. We'll address this in a new issue. In any case, you can try the beta version and give us your feedback 👍

jesmrec commented 5 days ago

Will check after https://github.com/owncloud/android/issues/4461

owncloud / android