Files written via DocumentsProvider often 0 bytes

[grote]

Steps to reproduce

1. Get permission to use Nextcloud's DocumentsProvider via OPEN_DOCUMENT_TREE
2. Create a new file and gets its Uri
3. Write bytes to context.contentResolver.openOutputStream(uri) and close the stream
4. Create a second file and get its Uri
5. Write bytes to context.contentResolver.openOutputStream(uri2) and close the stream
6. Observe one of these files having 0 bytes and no corresponding Upload log in the app's Uploads screen

Expected behaviour

All files should get successfully uploaded or an error thrown or at least logged.

Actual behaviour

In almost all runs of the reproduction steps above, one of the files is not uploaded, but no errors was thrown/logged.

Can you reproduce this problem on https://try.nextcloud.com?

I have not yet tried this, but can do so if someone things this matters.

Environment data

Android version: 10
Nextcloud app version: 3.12.1 and master
Nextcloud server version: 18.0.7

Reverse proxy: no

Logs

Web server error log

Can provide them when needed.

Nextcloud log (data/nextcloud.log)

2020-08-17 16:54:35.793 D/DocumentsStorageProvider: isChildDocument(), parent=861986647/5, id=861986647/13
2020-08-17 16:54:35.798 D/DocumentsStorageProvider: queryDocument(), id=861986647/13
2020-08-17 16:54:35.804 D/DocumentsStorageProvider: isChildDocument(), parent=861986647/5, id=861986647/13
2020-08-17 16:54:35.808 D/DocumentsStorageProvider: queryDocument(), id=861986647/13
2020-08-17 16:54:35.940 D/DocumentsStorageProvider: isChildDocument(), parent=861986647/5, id=861986647/13
2020-08-17 16:54:35.950 D/DocumentsStorageProvider: openDocument(), id=861986647/13
2020-08-17 16:54:35.961 D/FileDownloader: Starting command with id 6
2020-08-17 16:54:35.968 D/FileDownloader: Account [redacted] exists
2020-08-17 16:54:35.985 D/OwnCloudClient #0: REQUEST GET /remote.php/webdav/.SeedVaultAndroidBackup/3BpkMhCD2Jo6RyF9ciRkATB8pLIi_R3qE0WRdOBl6LM%3Dp9Z2iQsFlkLctqJV1QNDS3DVx5scCzhLG_gXN27I_n6f3sMUfnbKHjaN3nyDpuwcLHhiZhAfWAp%3DREauYt5wE_HV5GzADASe%3DatpCzOhC7BtXj2qR%2BYU1whuO6oYzJXEF%2B2FoOSq%2BxQdognJmb_1K9Riy6X
2020-08-17 16:54:36.702 I/DownloadFileRemoteOperation: Download of /.SeedVaultAndroidBackup/3BpkMhCD2Jo6RyF9ciRkATB8pLIi_R3qE0WRdOBl6LM=p9Z2iQsFlkLctqJV1QNDS3DVx5scCzhLG_gXN27I_n6f3sMUfnbKHjaN3nyDpuwcLHhiZhAfWAp=REauYt5wE_HV5GzADASe=atpCzOhC7BtXj2qR+YU1whuO6oYzJXEF+2FoOSq+xQdognJmb_1K9Riy6X to /storage/emulated/0/Android/media/com.nextcloud.android.beta/nextcloud/tmp/[redacted]/.SeedVaultAndroidBackup/3BpkMhCD2Jo6RyF9ciRkATB8pLIi_R3qE0WRdOBl6LM=p9Z2iQsFlkLctqJV1QNDS3DVx5scCzhLG_gXN27I_n6f3sMUfnbKHjaN3nyDpuwcLHhiZhAfWAp=REauYt5wE_HV5GzADASe=atpCzOhC7BtXj2qR+YU1whuO6oYzJXEF+2FoOSq+xQdognJmb_1K9Riy6X: Operation finished with HTTP status code 200 (success)
2020-08-17 16:54:36.702 D/DownloadFileOperation: Unable to create parent folder /storage/emulated/0/Android/media/com.nextcloud.android.beta/nextcloud/[redacted]/.SeedVaultAndroidBackup
2020-08-17 16:54:36.703 I/DownloadFileOperation: Download of /.SeedVaultAndroidBackup/3BpkMhCD2Jo6RyF9ciRkATB8pLIi_R3qE0WRdOBl6LM=p9Z2iQsFlkLctqJV1QNDS3DVx5scCzhLG_gXN27I_n6f3sMUfnbKHjaN3nyDpuwcLHhiZhAfWAp=REauYt5wE_HV5GzADASe=atpCzOhC7BtXj2qR+YU1whuO6oYzJXEF+2FoOSq+xQdognJmb_1K9Riy6X to /storage/emulated/0/Android/media/com.nextcloud.android.beta/nextcloud/[redacted]/.SeedVaultAndroidBackup/3BpkMhCD2Jo6RyF9ciRkATB8pLIi_R3qE0WRdOBl6LM=p9Z2iQsFlkLctqJV1QNDS3DVx5scCzhLG_gXN27I_n6f3sMUfnbKHjaN3nyDpuwcLHhiZhAfWAp=REauYt5wE_HV5GzADASe=atpCzOhC7BtXj2qR+YU1whuO6oYzJXEF+2FoOSq+xQdognJmb_1K9Riy6X: Operation finished with HTTP status code 200 (success)
2020-08-17 16:54:36.743 D/FileDataStorageManager: Number of files updated with CONFLICT: 1
2020-08-17 16:54:36.743 D/FileDataStorageManager: checking parents to remove conflict; STARTING with /.SeedVaultAndroidBackup/
2020-08-17 16:54:36.745 D/FileDataStorageManager: NO MORE conflicts in /.SeedVaultAndroidBackup/
2020-08-17 16:54:36.753 D/FileDataStorageManager: checking parents to remove conflict; NEXT /
2020-08-17 16:54:36.758 D/FileDataStorageManager: NO MORE conflicts in /
2020-08-17 16:54:36.770 D/FileDataStorageManager: checking parents to remove conflict; NEXT 
2020-08-17 16:54:36.778 D/FileDownloader: Stopping after command with id 6
2020-08-17 16:54:37.006 D/DocumentsStorageProvider: isChildDocument(), parent=861986647/5, id=861986647/13
2020-08-17 16:54:37.012 D/FileDataStorageManager: Number of files updated with CONFLICT: 1
2020-08-17 16:54:37.012 D/FileDataStorageManager: checking parents to remove conflict; STARTING with /.SeedVaultAndroidBackup/
2020-08-17 16:54:37.015 D/FileDataStorageManager: NO MORE conflicts in /.SeedVaultAndroidBackup/
2020-08-17 16:54:37.021 D/FileDataStorageManager: checking parents to remove conflict; NEXT /
2020-08-17 16:54:37.024 D/DocumentsStorageProvider: isChildDocument(), parent=861986647/5, id=861986647/13
2020-08-17 16:54:37.026 D/FileDataStorageManager: NO MORE conflicts in /
2020-08-17 16:54:37.034 D/FileDataStorageManager: checking parents to remove conflict; NEXT 
2020-08-17 16:54:37.034 I/SynchronizeFileOperation: Synchronizing [redacted], file /.SeedVaultAndroidBackup/3BpkMhCD2Jo6RyF9ciRkATB8pLIi_R3qE0WRdOBl6LM=p9Z2iQsFlkLctqJV1QNDS3DVx5scCzhLG_gXN27I_n6f3sMUfnbKHjaN3nyDpuwcLHhiZhAfWAp=REauYt5wE_HV5GzADASe=atpCzOhC7BtXj2qR+YU1whuO6oYzJXEF+2FoOSq+xQdognJmb_1K9Riy6X: Operation finished with HTTP status code -1 (success)
2020-08-17 16:54:37.037 D/DocumentsStorageProvider: openDocument(), id=861986647/13
2020-08-17 16:54:37.050 D/OwnCloudClient #0: REQUEST PROPFIND /remote.php/webdav/.SeedVaultAndroidBackup/3BpkMhCD2Jo6RyF9ciRkATB8pLIi_R3qE0WRdOBl6LM%3Dp9Z2iQsFlkLctqJV1QNDS3DVx5scCzhLG_gXN27I_n6f3sMUfnbKHjaN3nyDpuwcLHhiZhAfWAp%3DREauYt5wE_HV5GzADASe%3DatpCzOhC7BtXj2qR%2BYU1whuO6oYzJXEF%2B2FoOSq%2BxQdognJmb_1K9Riy6X
2020-08-17 16:54:37.396 D/FileDataStorageManager: Number of files updated with CONFLICT: 1
2020-08-17 16:54:37.397 D/FileDataStorageManager: checking parents to remove conflict; STARTING with /.SeedVaultAndroidBackup/
2020-08-17 16:54:37.401 D/FileDataStorageManager: NO MORE conflicts in /.SeedVaultAndroidBackup/
2020-08-17 16:54:37.412 D/FileDataStorageManager: checking parents to remove conflict; NEXT /
2020-08-17 16:54:37.416 D/FileDataStorageManager: NO MORE conflicts in /
2020-08-17 16:54:37.427 D/FileDataStorageManager: checking parents to remove conflict; NEXT 
2020-08-17 16:54:37.427 I/SynchronizeFileOperation: Synchronizing [redacted], file /.SeedVaultAndroidBackup/3BpkMhCD2Jo6RyF9ciRkATB8pLIi_R3qE0WRdOBl6LM=p9Z2iQsFlkLctqJV1QNDS3DVx5scCzhLG_gXN27I_n6f3sMUfnbKHjaN3nyDpuwcLHhiZhAfWAp=REauYt5wE_HV5GzADASe=atpCzOhC7BtXj2qR+YU1whuO6oYzJXEF+2FoOSq+xQdognJmb_1K9Riy6X: Operation finished with HTTP status code -1 (success)

Observe the status code of -1 which doesn't exist and hints at an unnoticed problem. Also, it seems that files are uploaded asynchronously. Not sure if this is the expected behavior or if a consumer of the DocumentsProvider needs to observe the Uri for changes to find out when a write was complete.

I will dig into this more later and update the issue.

[grote]

I tried the same test against the system's DocumentsProvider and there everything is fine. It seems to write the files to storage synchronously while Nextcloud does it asynchronously which probably is not a good idea as we can't inform the caller of a problem and also might run into trouble if the caller keeps telling us to write more files faster than we can keep up with.

Here's a simple test that passes with system, but not Nextcloud:

val file: DocumentFile = getFile()
context.contentResolver.openOutputStream(file.uri).use {
    it.write(data)
}
assertEquals(data.size.toLong(), file.length())

[grote]

So DocumentsStorageProvider#openDocument() is opening a ParcelFileDescriptor on the local file after ensuring that it actually exists locally (if not, it downloads it before). When the caller is done writing and closes the descriptor, a SynchronizeFileOperation is executed. This eventually starts the FileUploader service that then uploads the changed file on a dedicated thread.

My preferred behavior would be to stream the written bytes directly to the server, but I understand that this is not how the Nextcloud app generally works.

As changing this behavior to synchronous blocking uploads would involve bigger changes to the code base, we should discuss this before I start any further work here.

---

The real underlying bug (apart from hiding it via async uploads) is that often SynchronizeFileOperation is NOT detecting that the file we just wrote to has changed and thus is NOT request the upload of the file via the FileUploader service.

This is because OCFile#getLocalModificationTimestamp() is often older than OCFile#getLastSyncDateForData() at the time this check is made. Apart from the fact that comparing timestamps is not reliable as clocks sometimes can move backward, it seems that getLocalModificationTimestamp() has only a precision of seconds while getLastSyncDateForData() has millisecond precision. So a change is only detected if the last sync happened in the second before the file completed writing. In my tests, it happens more often in the same second explaining frequent failures to detect the change.

Now the question to the Nextcloud devs (@tobiasKaminsky and @AndyScherzinger) is how do you want to detect changes?

A minimally invasive change would be simply to reset the LastSyncDate right before starting the SynchronizeFileOperation from DocumentsStorageProvider#openDocument() that happens right after the writeable descriptor gets closed. As far as I can see, this shouldn't have any negative side-effects. I hope that it is also reliable, aka nothing sets this date to something else in the meantime.

[tobiasKaminsky]

Thanks for your very detailed analysis of the root problem.
I guess that we did not encountered this right now as there is no automatic upload/download (apart from auto upload, which handles "only" upload of mostly big files).

reset the LastSyncDate right before starting the SynchronizeFileOperation from DocumentsStorageProvider#openDocument()

This might be a quick win for now 👍

[grote]

Unfortunately, in actual testing with a real Seedvault backup (not limited instrumentation tests) I found that there's instances where the OCFile is re-fetched from the DB overriding the reset of the sync data. I still need to figure out why and under what circumstances this happens.

As for the general issue of doing async uploads, I will experiment with watching the content URI for changes and waiting for this change to happen before continuing. However, this is tricky and hacky for several reasons. It would be good to find out how other implementations of DocumentsProvider are handling this. If you know any, especially cloud-based ones, please let me know, so I can test against them.

[grote]

So sometimes before returning the ParcelFileDescriptor, a sync operation is started on a dedicated thread which produced a false positive. Then there can be OfflineSyncWork or a sync operation on an entire folder running in parallel picking up files still to be uploading also producing false positives. But overall, the main issue seems to be resolved (or at least greatly improved) by resetting the sync time of a file before syncing it. So I'd suggest starting with this fix and then looking into other issues.

Code quality wise, I wonder why the sync operation needs to be run in a syncThread in DocumentsStorageProvider instead of just on the same thread. We are joining the thread after starting it anyway. Then if a file isn't downloaded, we start a FileDownloader service and do a busy loop waiting for it to complete. Can't we just start the FileDownloadOperation directly like we do with sync operations?

[grote]

As for the general issue of doing async uploads, I will experiment with watching the content URI for changes and waiting for this change to happen before continuing.

This doesn't work, because your DocumentsProvider implementation is not notifying about changes. It is just sending its own broadcasts. As these broadcasts are currently changing, I wonder if what the best way forward is.

• listen to those broadcasts and notify when the right one is received
• wait for a listener-based approach
• make FileUploads from DocumentsProvider run on the same I/O thread that starts its operations

I personally prefer the last option ;)