[QA] Checksum regression with external drives

[jnweiger]

Seen with 10.12.0 and desktop client 4.0.0. This issue cannot be reproduced with core 10.11.0

• Start server with an external SFTP mount.
  

---

• Add a file hello.txt with a one line of text into that mount.
• Connect client and allow syncing of external storages.
• The file hello.txt syncs to the desktop without problem.
• On the local desktop edit hello.txt by adding a line.
• An error occurs: 400 BAD Request, the computed checksum does not match

This is 100% reproducable with my SFTP setup.

The server log has:

{"reqId":"IgDk24V5ZVeN4aXztHSi","level":1,"time":"2023-06-07T16:21:24+00:00","remoteAddr":"","user":"--","app":"no app in context","method":"--","url":"--","message":"Creating new account with UID Alice and backend OC\\User\\Database"}
{"reqId":"s7ONOOKX19ucznKaR7tS","level":1,"time":"2023-06-07T16:21:24+00:00","remoteAddr":"","user":"--","app":"no app in context","method":"--","url":"--","message":"Creating new account with UID bob and backend OC\\User\\Database"}
{"reqId":"Ki6gB5evYS02VeRwpG5U","level":1,"time":"2023-06-07T16:21:25+00:00","remoteAddr":"","user":"--","app":"no app in context","method":"--","url":"--","message":"Creating new account with UID carol and backend OC\\User\\Database"}
{"reqId":"i0zbTwKtDBSWoZeolxnG","level":1,"time":"2023-06-07T16:21:25+00:00","remoteAddr":"","user":"--","app":"no app in context","method":"--","url":"--","message":"Creating new account with UID dave and backend OC\\User\\Database"}
{"reqId":"ZSEzzg4O8ZHGu0DfXw5z","level":1,"time":"2023-06-07T16:21:25+00:00","remoteAddr":"","user":"--","app":"no app in context","method":"--","url":"--","message":"Creating new account with UID einstein and backend OC\\User\\Database"}
{"reqId":"YNfKyFqHAEaXFnlTAYLD","level":3,"time":"2023-06-07T16:25:02+00:00","remoteAddr":"","user":"--","app":"core","method":"--","url":"--","message":"Can't get app storage, app files_external, user not logged in"}
{"reqId":"YNfKyFqHAEaXFnlTAYLD","level":3,"time":"2023-06-07T16:25:02+00:00","remoteAddr":"","user":"--","app":"core","method":"--","url":"--","message":"Can't get app storage, app files_external, user not logged in"}
{"reqId":"YNfKyFqHAEaXFnlTAYLD","level":1,"time":"2023-06-07T16:25:03+00:00","remoteAddr":"","user":"--","app":"no app in context","method":"--","url":"--","message":"0 orphaned previews deleted"}
{"reqId":"YNfKyFqHAEaXFnlTAYLD","level":1,"time":"2023-06-07T16:25:03+00:00","remoteAddr":"","user":"--","app":"cron","method":"--","url":"--","message":"Invalidating tokens older than 2023-06-07T16:05:03+00:00"}
{"reqId":"7lFSWdeJdaaqyOXxiIJH","level":1,"time":"2023-06-07T16:40:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"--","url":"--","message":"Invalidating tokens older than 2023-06-07T16:20:02+00:00"}
{"reqId":"7lFSWdeJdaaqyOXxiIJH","level":3,"time":"2023-06-07T16:40:02+00:00","remoteAddr":"","user":"--","app":"core","method":"--","url":"--","message":"Can't get app storage, app files_external, user not logged in"}
{"reqId":"7lFSWdeJdaaqyOXxiIJH","level":3,"time":"2023-06-07T16:40:02+00:00","remoteAddr":"","user":"--","app":"core","method":"--","url":"--","message":"Can't get app storage, app files_external, user not logged in"}
{"reqId":"ZICzEKOedw5bTmHOEO0RhwAAAAM","level":3,"time":"2023-06-07T16:40:52+00:00","remoteAddr":"80.139.85.31","user":"bob","app":"files_texteditor","method":"PUT","url":"\/apps\/files_texteditor\/ajax\/savefile","message":"File: \/SFTP\/hello.txt modified since opening."}
{"reqId":"ZICzEeugLu3BhAWc2r5zgQAAAAA","level":3,"time":"2023-06-07T16:40:53+00:00","remoteAddr":"80.139.85.31","user":"bob","app":"files_texteditor","method":"PUT","url":"\/apps\/files_texteditor\/ajax\/savefile","message":"File: \/SFTP\/hello.txt modified since opening."}
{"reqId":"ZICzEd6bLjil2wMLgoWGLwAAAAU","level":3,"time":"2023-06-07T16:40:53+00:00","remoteAddr":"80.139.85.31","user":"bob","app":"files_texteditor","method":"PUT","url":"\/apps\/files_texteditor\/ajax\/savefile","message":"File: \/SFTP\/hello.txt modified since opening."}
{"reqId":"ZICzEf7wQ4eTPFdlyk-oxgAAAAs","level":3,"time":"2023-06-07T16:40:54+00:00","remoteAddr":"80.139.85.31","user":"bob","app":"files_texteditor","method":"PUT","url":"\/apps\/files_texteditor\/ajax\/savefile","message":"File: \/SFTP\/hello.txt modified since opening."}
{"reqId":"ZICzEvfGgPNKsk2CNCwHiwAAAAY","level":3,"time":"2023-06-07T16:40:54+00:00","remoteAddr":"80.139.85.31","user":"bob","app":"files_texteditor","method":"PUT","url":"\/apps\/files_texteditor\/ajax\/savefile","message":"File: \/SFTP\/hello.txt modified since opening."}
{"reqId":"ZICzEiL1GEC9b@WZkR3P2gAAAAE","level":3,"time":"2023-06-07T16:40:54+00:00","remoteAddr":"80.139.85.31","user":"bob","app":"files_texteditor","method":"PUT","url":"\/apps\/files_texteditor\/ajax\/savefile","message":"File: \/SFTP\/hello.txt modified since opening."}
{"reqId":"ZICzFAG4UpxAwJEvY0NtAgAAAAg","level":3,"time":"2023-06-07T16:40:55+00:00","remoteAddr":"80.139.85.31","user":"bob","app":"files_texteditor","method":"PUT","url":"\/apps\/files_texteditor\/ajax\/savefile","message":"File: \/SFTP\/hello.txt modified since opening."}
{"reqId":"lV2RQhEOgcJhr844mR0V","level":1,"time":"2023-06-07T16:45:02+00:00","remoteAddr":"","user":"--","app":"cron","method":"--","url":"--","message":"Invalidating tokens older than 2023-06-07T16:25:02+00:00"}
{"reqId":"lV2RQhEOgcJhr844mR0V","level":3,"time":"2023-06-07T16:45:02+00:00","remoteAddr":"","user":"--","app":"core","method":"--","url":"--","message":"Can't get app storage, app files_external, user not logged in"}
{"reqId":"lV2RQhEOgcJhr844mR0V","level":3,"time":"2023-06-07T16:45:02+00:00","remoteAddr":"","user":"--","app":"core","method":"--","url":"--","message":"Can't get app storage, app files_external, user not logged in"}
{"reqId":"lV2RQhEOgcJhr844mR0V","level":1,"time":"2023-06-07T16:45:02+00:00","remoteAddr":"","user":"--","app":"files_versions","method":"--","url":"--","message":"Mark to expire \/SFTP\/hello.txt next version should be 1686156052 or smaller. (prevTimestamp: 1686156112; step: 60"}
{"reqId":"lV2RQhEOgcJhr844mR0V","level":1,"time":"2023-06-07T16:45:02+00:00","remoteAddr":"","user":"--","app":"files_versions","method":"--","url":"--","message":"Mark to expire \/SFTP\/hello.txt next version should be 1686156052 or smaller. (prevTimestamp: 1686156112; step: 60"}
{"reqId":"lV2RQhEOgcJhr844mR0V","level":1,"time":"2023-06-07T16:45:02+00:00","remoteAddr":"","user":"--","app":"files_versions","method":"--","url":"--","message":"Mark to expire \/SFTP\/hello.txt next version should be 1686155990 or smaller. (prevTimestamp: 1686156050; step: 60"}
{"reqId":"lV2RQhEOgcJhr844mR0V","level":1,"time":"2023-06-07T16:45:02+00:00","remoteAddr":"","user":"--","app":"files_versions","method":"--","url":"--","message":"Expire: \/SFTP\/hello.txt.v1686156058"}
{"reqId":"lV2RQhEOgcJhr844mR0V","level":1,"time":"2023-06-07T16:45:02+00:00","remoteAddr":"","user":"--","app":"files_versions","method":"--","url":"--","message":"Expire: \/SFTP\/hello.txt.v1686156055"}
{"reqId":"lV2RQhEOgcJhr844mR0V","level":1,"time":"2023-06-07T16:45:02+00:00","remoteAddr":"","user":"--","app":"files_versions","method":"--","url":"--","message":"Expire: \/SFTP\/hello.txt.v1686156043"}
{"reqId":"ZIC0Fq-AsmYUd82a7rVe4gAAAAI","level":3,"time":"2023-06-07T16:45:11+00:00","remoteAddr":"80.139.85.31","user":"bob","app":"files_texteditor","method":"PUT","url":"\/apps\/files_texteditor\/ajax\/savefile","message":"File: \/SFTP\/hello.txt modified since opening."}
{"reqId":"ZIC0FhcNaTu29e0fz@7k1QAAAAE","level":3,"time":"2023-06-07T16:45:11+00:00","remoteAddr":"80.139.85.31","user":"bob","app":"files_texteditor","method":"PUT","url":"\/apps\/files_texteditor\/ajax\/savefile","message":"File: \/SFTP\/hello.txt modified since opening."}
{"reqId":"945d4b09-d96b-4106-bd55-b33f0603ffcd","level":4,"time":"2023-06-07T16:47:40+00:00","remoteAddr":"80.139.85.31","user":"bob","app":"webdav","method":"PUT","url":"\/remote.php\/dav\/files\/bob\/SFTP\/hello.txt","message":"Exception: HTTP\/1.1 400 The computed checksum does not match the one received from the client.: {\"Exception\":\"Sabre\\\\DAV\\\\Exception\\\\BadRequest\",\"Message\":\"The computed checksum does not match the one received from the client.\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/gh-bisect-owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1137): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->put()\\n#1 \\\/var\\\/www\\\/gh-bisect-owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(492): Sabre\\\\DAV\\\\Server->updateFile()\\n#2 \\\/var\\\/www\\\/gh-bisect-owncloud\\\/lib\\\/composer\\\/sabre\\\/event\\\/lib\\\/WildcardEmitterTrait.php(89): Sabre\\\\DAV\\\\CorePlugin->httpPut()\\n#3 \\\/var\\\/www\\\/gh-bisect-owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(472): Sabre\\\\DAV\\\\Server->emit()\\n#4 \\\/var\\\/www\\\/gh-bisect-owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(253): Sabre\\\\DAV\\\\Server->invokeMethod()\\n#5 \\\/var\\\/www\\\/gh-bisect-owncloud\\\/apps\\\/dav\\\/lib\\\/Server.php(348): Sabre\\\\DAV\\\\Server->start()\\n#6 \\\/var\\\/www\\\/gh-bisect-owncloud\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(31): OCA\\\\DAV\\\\Server->exec()\\n#7 \\\/var\\\/www\\\/gh-bisect-owncloud\\\/remote.php(165): require_once('\\\/var\\\/www\\\/gh-bis...')\\n#8 {main}\",\"File\":\"\\\/var\\\/www\\\/gh-bisect-owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php\",\"Line\":219}"}
{"reqId":"945d4b09-d96b-4106-bd55-b33f0603ffcd","level":1,"time":"2023-06-07T16:47:40+00:00","remoteAddr":"80.139.85.31","user":"bob","app":"core","method":"PUT","url":"\/remote.php\/dav\/files\/bob\/SFTP\/hello.txt","message":"cleaning 1 stray shared locks for files\/70b8278f159a87a629cf415012267e97"}
{"reqId":"945d4b09-d96b-4106-bd55-b33f0603ffcd","level":1,"time":"2023-06-07T16:47:40+00:00","remoteAddr":"80.139.85.31","user":"bob","app":"core","method":"PUT","url":"\/remote.php\/dav\/files\/bob\/SFTP\/hello.txt","message":"cleaning 1 stray shared locks for files\/226b3b017949b01fea60cf4e54a233a9"}

Client log
tp400.log.zip

[jnweiger]

Bisecting server commits

This commit works fine:

commit 64a2380
Author: ownClouders devops@owncloud.com
Date: Fri Dec 23 01:19:49 2022 +0000

[tx] updated from transifex

---

The very next commit breaks it:

commit 4626cd3
Author: Juan Pablo Villafañez jvillafanez@solidgeargroup.com
Date: Fri Dec 23 19:24:43 2022 +0100

Set checksum if not seeked (#40513)

* Calculate checksum only if we read or write from the beginning to the end

* Add unit tests and fix some edge cases

* Fix writing case because eof returns false. Adjust code for edge cases

* Add additional unit tests

* Add changelog entry

---

[jnweiger]

@jvillafanez could you investigate into this, please?

[jvillafanez]

It seems there is a problem with the mode when the target file is opened.
We're getting a "r+" mode. When the file is closed, we get that the file is being read but we haven't reached the end of file, so we refuse to "publish" the checksum (we can't guarantee we've processed the whole file so the checksum is likely wrong). In the end, we compare the checksum we get from the HTTP header with nothing.

I'm pretty sure the mode should be "w".... need to check why we're getting a different mode.

[jvillafanez]

For SFTP, https://github.com/owncloud/core/blob/master/apps/files_external/lib/Lib/Storage/SFTP.php#L364 , can be changed to return $handle; to fix the issue.
As said, the RetryWrapper is forcing r+ mode regardless of whatever mode we want to use, and this is what is breaking the checksums.

[jvillafanez]

The CallbackWrapper, used by SMB does the same.

[jvillafanez]

#40832 might fix the issue. There could be missing calls, so I'm testing it

[jnweiger]

confirmed fixed in 10.13.0-rc.1