[QA] dehydrated files show jumping progressbar when opened - download never completes

[jnweiger]

Pre-submission Checks

• [X] I checked for similar issues, but could not find any. I also checked the closed issues. I could not contribute additional information to any existing issue.
• [X] I will take the time to fill in all the required fields. I know that the bug report may be dismissed otherwise due to lack of information.

Describe the QA issue

Seen while testing client 2.11.0-rc1 8255 on windows-10.0.19043

• Connect to client-test.owncloud.works in VFS mode as user testy
• Wait for the initial sync to finish with the skeleton folders Documents and Photos.
• ssh into client-test.owncloud.works, and add 25000 files cd data/testy/files; randfiles.py -m 25000 rand25k; occ file:scan --all
• Wait for the sync to start with the new rand25k folder.
• while the client is slowly syncing, click open
  • Documents/example.odt
  • Photos/Portugal.jpg
• A download progress window opens for the two files, the owncloud client continues syncing. OK.
• The progressbar of the owncloud client continues at a steady pace. OK.
• The progress bar of Documents/example.odt hangs at 33%, BAD
• The progress bar of Photos/Portugal.jpg jumps around between 11% and 77% back and forth, never reaching 100%. BAD
• Eventually the client finises syncing all 25000 placeholders.
• The situation for the two files does not change, circling arrows, progress bar never reaches 100%.
• Click open Photos/Lake-Constance.jpg - the same wild back and forth jumping happens there. Circling arrows. BAD
• Right click on Photos/Teotihuacan.jpg -> Always keep on this device. The file dehydrates without problem. Green checkmark.

• Restart Windows
• navigate to the Photos folder with Explorer. Only teotihuacan.jpg is dehydrated.
• double-click Portugal.jpg -> same behaviour, jumping progressbar.
• The behaviour is apparently not related to downloading while the initial sync runs. Also happens on a fresh account, where only skeleton folders are present

ownCloud-logdir.zip

Steps to reproduce the issue

.

Screenshots

.

Expected behavior

.

Actual behavior

.

[jnweiger]

The behaviour is 100% reproducable.

Another test:

• Connect to client-test.owncloud.works in VFS mode as user testy with the 25000 files in place.
• Wait for the sync to start with the 25000 files.
• while the client is slowly syncing, navigate into folder Photos, right click Portugal.jpg -> Always keep on this device
• The cloud icon changes to blue arrows. No progress bar window appears. BAD
• The file remains with circling arrows until the entire initial sync is done. on another sync run, the download completes, Portugal.jpg shows a green checkmark.

Expected behaviour:

• The file should be downloaded in reasonable time (as described in #9956)
• A short file should complete downloading while the sync is still ongoing. Tried multiple times. That never happend.

[jnweiger]

Suspicious log entries: "don't know about the hydration, restarting ..."

08-10 01:12:32:515 [ info sync.networkjob ]:	Created OCC::GETFileJob("https://client-test.owncloud.works/remote.php/dav/files/admin/Photos/Lake-Constance.jpg", "9a60c44f-da94-4676-aaef-45e4e33b686c", "9a60c44f-da94-4676-aaef-45e4e33b686c") for OCC::HydrationContext(0x220b8345200)
08-10 01:12:33:756 [ info sync.httplogger ]:	"9a60c44f-da94-4676-aaef-45e4e33b686c: Response: GET 200 https://client-test.owncloud.works/remote.php/dav/files/admin/Photos/Lake-Constance.jpg Header: { Date: Wed, 10 Aug 2022 08:12:33 GMT, Server: Apache/2.4.41 (Ubuntu), Strict-Transport-Security: max-age=15552000; includeSubDomains, 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';, Last-Modified: Mon, 21 Mar 2022 10:53:39 GMT, ETag: \"51d9bd1f25984004345b5c70f2820c20\", Content-Length: 538942, OC-ETag: \"51d9bd1f25984004345b5c70f2820c20\", Content-Disposition: attachment; filename*=UTF-8''Lake-Constance.jpg; filename=\"Lake-Constance.jpg\", OC-Checksum: SHA1:b26d5544e642330e2858a4d8528cb108ddbca9e3, X-Accel-Buffering: no, Keep-Alive: timeout=5, max=100, Connection: Keep-Alive, Content-Type: image/jpeg, } Data: []"
08-10 01:12:33:756 [ debug sync.networkjob ]	[ OCC::AbstractNetworkJob::slotFinished ]:	Network job finished OCC::GETFileJob("https://client-test.owncloud.works/remote.php/dav/files/admin/Photos/Lake-Constance.jpg", "9a60c44f-da94-4676-aaef-45e4e33b686c", "9a60c44f-da94-4676-aaef-45e4e33b686c")
08-10 01:12:33:756 [ debug sync.networkjob.get ]	[ OCC::GETFileJob::slotReadyRead ]:	Actually finished!
08-10 01:12:33:756 [ info sync.vfs.win ]:	void __cdecl OCC::callbackValidateData(const struct CF_CALLBACK_INFO *,const struct CF_CALLBACK_PARAMETERS *)
08-10 01:12:33:756 [ info sync.vfs.win ]:	request to validate data "C:\\Users\\User\\ownCloud\\Photos\\Lake-Constance.jpg" 0 538942
08-10 01:12:33:756 [ warning sync.vfs.win ]:	don't know about the hydration, restarting "C:\\Users\\User\\ownCloud\\Photos\\Lake-Constance.jpg"
08-10 01:12:33:756 [ info sync.vfs.win ]:	void __cdecl OCC::callbackFetchData(const struct CF_CALLBACK_INFO *,const struct CF_CALLBACK_PARAMETERS *)
08-10 01:12:33:756 [ info sync.vfs.win ]:	fetch data request "C:/Users/User/ownCloud/" "C:\\Users\\User\\ownCloud\\Photos\\Lake-Constance.jpg" "00000009octcra33x7lp" 0 538942 0 0
08-10 01:12:33:756 [ debug sync.database.sql ]	[ OCC::SqlQuery::bindValue ]:	SQL bind 1 "00000009octcra33x7lp"
08-10 01:12:33:756 [ info sync.accessmanager ]:	2 "" "https://client-test.owncloud.works/remote.php/dav/files/admin/Photos/Lake-Constance.jpg" has X-Request-ID "020a0f0f-4815-4363-8a08-4ef3afc0b91d"
08-10 01:12:33:756 [ debug sync.cookiejar ]	[ OCC::CookieJar::cookiesForUrl ]:	QUrl("https://client-test.owncloud.works/remote.php/dav/files/admin/Photos/Lake-Constance.jpg") requests: (QNetworkCookie("oc_sessionPassphrase=s2sOlphvjKxEvHu9ZWCI2pf1xxLQewFHt23umuxf8%2FSQoHztXIilcpUQV8FLUzcCChiBhmm4bLw113hRlhPRHT1yPDLmingHU6PgrL9SnpWGwvf%2FmyOhSgTztKt9M5Vm; secure; HttpOnly; domain=client-test.owncloud.works; path=/"), QNetworkCookie("octcra33x7lp=igl2qnij9v9nitb40bk5r7ddi5; secure; HttpOnly; domain=client-test.owncloud.works; path=/"))
08-10 01:12:33:756 [ info sync.httplogger ]:	"020a0f0f-4815-4363-8a08-4ef3afc0b91d: Request: GET https://client-test.owncloud.works/remote.php/dav/files/admin/Photos/Lake-Constance.jpg Header: { Authorization: Bearer [redacted], User-Agent: Mozilla/5.0 (Windows) mirall/2.11.0rc1 (build 8255) (ownCloud, windows-10.0.22000 ClientArchitecture: x86_64 OsArchitecture: x86_64), Accept: */*, X-Request-ID: 020a0f0f-4815-4363-8a08-4ef3afc0b91d, Original-Request-ID: 020a0f0f-4815-4363-8a08-4ef3afc0b91d, Cookie: oc_sessionPassphrase=s2sOlphvjKxEvHu9ZWCI2pf1xxLQewFHt23umuxf8%2FSQoHztXIilcpUQV8FLUzcCChiBhmm4bLw113hRlhPRHT1yPDLmingHU6PgrL9SnpWGwvf%2FmyOhSgTztKt9M5Vm; octcra33x7lp=igl2qnij9v9nitb40bk5r7ddi5, } Data: []"
08-10 01:12:33:756 [ debug sync.networkjob.get ]	[ OCC::GETFileJob::start ]:	QObject(0x0) false false
08-10 01:12:33:756 [ info sync.networkjob ]:	Created OCC::GETFileJob("https://client-test.owncloud.works/remote.php/dav/files/admin/Photos/Lake-Constance.jpg", "020a0f0f-4815-4363-8a08-4ef3afc0b91d", "020a0f0f-4815-4363-8a08-4ef3afc0b91d") for OCC::HydrationContext(0x220b834b080)
08-10 01:12:34:552 [ info sync.httplogger ]:	"020a0f0f-4815-4363-8a08-4ef3afc0b91d: Response: GET 200 https://client-test.owncloud.works/remote.php/dav/files/admin/Photos/Lake-Constance.jpg Header: { Date: Wed, 10 Aug 2022 08:12:34 GMT, Server: Apache/2.4.41 (Ubuntu), Strict-Transport-Security: max-age=15552000; includeSubDomains, 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';, Last-Modified: Mon, 21 Mar 2022 10:53:39 GMT, ETag: \"51d9bd1f25984004345b5c70f2820c20\", Content-Length: 538942, OC-ETag: \"51d9bd1f25984004345b5c70f2820c20\", Content-Disposition: attachment; filename*=UTF-8''Lake-Constance.jpg; filename=\"Lake-Constance.jpg\", OC-Checksum: SHA1:b26d5544e642330e2858a4d8528cb108ddbca9e3, X-Accel-Buffering: no, Keep-Alive: timeout=5, max=99, Connection: Keep-Alive, Content-Type: image/jpeg, } Data: []"
08-10 01:12:34:552 [ debug sync.networkjob ]	[ OCC::AbstractNetworkJob::slotFinished ]:	Network job finished OCC::GETFileJob("https://client-test.owncloud.works/remote.php/dav/files/admin/Photos/Lake-Constance.jpg", "020a0f0f-4815-4363-8a08-4ef3afc0b91d", "020a0f0f-4815-4363-8a08-4ef3afc0b91d")
08-10 01:12:34:552 [ debug sync.networkjob.get ]	[ OCC::GETFileJob::slotReadyRead ]:	Actually finished!
08-10 01:12:34:568 [ info sync.vfs.win ]:	void __cdecl OCC::callbackValidateData(const struct CF_CALLBACK_INFO *,const struct CF_CALLBACK_PARAMETERS *)
08-10 01:12:34:568 [ info sync.vfs.win ]:	request to validate data "C:\\Users\\User\\ownCloud\\Photos\\Lake-Constance.jpg" 0 538942
08-10 01:12:34:582 [ warning sync.vfs.win ]:	don't know about the hydration, restarting "C:\\Users\\User\\ownCloud\\Photos\\Lake-Constance.jpg"

[jnweiger]

Verified with 2.10.2rc1 on the same windows systems: doubleclick open always works fine.

[TheOneRing]

Setting the icon depends on a sync run so it is expected to be out of sync. Opening a file however should complete. Small files might not display a widows progress indicator.

[TheOneRing]

Checked with @michaelstingl not a release blocker. Will be fixed in a later release.

[jnweiger]

@michaelstingl I disagree here.

Clicking on a file must download the file, so it can be opened. This is a basic VFS feature. Breaking this, is a severe regression. Without this, we would need to document a workaround: For every file that fails to open do:

1. Stop / restart the client,
2. select keep locally from the right click menu,
3. wait until downloaded
4. try opening again.

(I am okay with not always setting the correct icon, and small files not showing a progress indicator.)

[michaelstingl]

@michaelstingl I disagree here.

I was mostly thinking about the jumpiness. I need to better understand the "never completes" aspect of the problem.

[michaelstingl]

Breaking this, is a severe regression.

@TheOneRing will have another look. Thanks for providing the additional details. 👍

[TheOneRing]

The never finished part is fixed in https://github.com/owncloud/client-desktop-vfs-win/pull/38

[jnweiger]

Retested with owncloud-client 2.11.0-rc3 (build 8346)

• No more jumping progress bars. (the progress sometimes briefly pauses, but never goes backwards)
• Files can be downloaded by clicking!

Confirmed fixed. Thanks!