Problem with syncing (INSTRUCTION_SYNC) files that are bigger than 10M AND contain special characters

docker

#1

Setup:
Dockerized set of owncloud 10.0.10.4 (docker image tag 10.0), mariadb, nginx-proxy and letsencrypt-nginx-proxy-companion and redis, fresh install. Plain http between proxy and owncloud.

Problem:
Testfile with name üü.xlsx and size 16.5MB.
Initial upload (INSTRUCTION_NEW) proceeds fine, after modifying the file and saving it client (2.5.0 and 2.5.1)
fails to upload it. At first progression bar quickly moves to the end and then after some time client displays message: “Connection timed out”.
If file size is less than 10 000 000 bytes (no chunking) or it does not contain special characters, syncing succeeds.

Notes:
When syncing fails, chunks are present in user’s uploads directory.
From logs (both client and server side) I see that initial successful sync contains MKCOL followed by 2x PUT chunks followed by MOVE; consecutive syncs that fail never show MOVE on server side, it is present on client log though. Can’t see any errors server side with log level 0, except for non-existent tokens.
Same version of owncloud without nginx proxy works fine, also same setup with nginx-proxy but without ssl encryption works fine. Thanks for any ideas what to check or how to proceed.

Example of success (client side):

|12-18 14:34:16:548 [ info sync.checksums ]:|Computing "SHA1" checksum of "C:/test1/üü.xlsx" in a thread|
|12-18 14:34:16:627 [ info sync.accessmanager ]:|6 "MKCOL" "https_://test.example.com/remote.php/dav/uploads/test1/3475914426" has X-Request-ID "e61c5951-b3b9-4c72-8947-21a81b251895"|
|12-18 14:34:16:628 [ info sync.networkjob ]:|OCC::MkColJob created for "https_://test.example.com" + "" "OCC::PropagateUploadFileNG"|
|12-18 14:34:16:698 [ info sync.networkjob.mkcol ]:|MKCOL of QUrl("https_://test.example.com/remote.php/dav/uploads/test1/3475914426") FINISHED WITH STATUS "OK"|
|12-18 14:34:16:711 [ info sync.accessmanager ]:|3 "" "https_://test.example.com/remote.php/dav/uploads/test1/3475914426/00000000" has X-Request-ID "fdabac02-4f2c-4da9-95e8-6a6f8431fb06"|
|12-18 14:34:16:713 [ info sync.networkjob ]:|OCC::PUTFileJob created for "https_://test.example.com" + "" "OCC::PropagateUploadFileNG"|
|12-18 14:34:17:156 [ info sync.networkjob.put ]:|PUT of "https_://test.example.com/remote.php/dav/uploads/test1/3475914426/00000000" FINISHED WITH STATUS "OK" QVariant(int, 201) QVariant(QString, "")|
|12-18 14:34:17:158 [ info sync.propagator.upload ]:|Chunked upload of 10000000 bytes took 446 ms, desired is 60000 ms, expected good chunk size is 1345291479 bytes and nudged next chunk size to  100000000 bytes|
|12-18 14:34:17:167 [ info sync.accessmanager ]:|3 "" "https_://test.example.com/remote.php/dav/uploads/test1/3475914426/00000001" has X-Request-ID "f403005a-b29b-4569-9379-d7d41f8247a7"|
|12-18 14:34:17:169 [ info sync.networkjob ]:|OCC::PUTFileJob created for "https_://test.example.com" + "" "OCC::PropagateUploadFileNG"|
|12-18 14:34:17:486 [ info sync.networkjob.put ]:|PUT of "https_://test.example.com/remote.php/dav/uploads/test1/3475914426/00000001" FINISHED WITH STATUS "OK" QVariant(int, 201) QVariant(QString, "")|
|12-18 14:34:17:488 [ info sync.propagator.upload ]:|Chunked upload of 7322065 bytes took 319 ms, desired is 60000 ms, expected good chunk size is 1377190909 bytes and nudged next chunk size to  100000000 bytes|
|12-18 14:34:17:490 [ info sync.propagator.upload ]:|"//remote.php/dav/files/test1/üü.xlsx" "SHA1:aec65c62971a7d4a412df01cd4233aabe274677d"|
|12-18 14:34:17:492 [ info sync.accessmanager ]:|6 "MOVE" "https_://test.example.com/remote.php/dav/uploads/test1/3475914426/.file" has X-Request-ID "0f56f80b-cb1e-4f17-a4e2-885ceba16db3"|
|12-18 14:34:17:493 [ info sync.networkjob ]:|OCC::MoveJob created for "https_://test.example.com" + "" "OCC::PropagateUploadFileNG"|
|12-18 14:34:18:026 [ info sync.networkjob.move ]:|MOVE of QUrl("https_://test.example.com/remote.php/dav/uploads/test1/3475914426/.file") FINISHED WITH STATUS "OK"|
|12-18 14:34:18:026 [ info sync.database ]:|Updating file record for path: "\xC3\xBC\xC3\xBC.xlsx" inode: 578241 modtime: 1545126141 type: 0 etag: "86071964f0d21794742056c8838b95c1" fileId: "00000085oc8jncyfgxeq" remotePerm: "" fileSize: 17322065 checksum: "SHA1:aec65c62971a7d4a412df01cd4233aabe274677d"|
|12-18 14:34:18:026 [ info sync.propagator ]:|Completed propagation of "üü.xlsx" by OCC::PropagateUploadFileNG(0x8c04908) with status 4|
|12-18 14:34:18:037 [ info sync.database ]:|Closing DB "C:/test1/._sync_d5d6320b25a5.db"|

Example of failure (client side):

|12-18 14:35:53:258 [ info sync.propagator ]:|Starting INSTRUCTION_SYNC propagation of "üü.xlsx" by OCC::PropagateUploadFileNG(0x8c04b88)|
|---|---|
|12-18 14:35:53:259 [ info sync.checksums ]:|Computing "SHA1" checksum of "C:/test1/üü.xlsx" in a thread|
|12-18 14:35:53:324 [ info sync.accessmanager ]:|6 "MKCOL" "https_://test.example.com/remote.php/dav/uploads/test1/3474338122" has X-Request-ID "14d5078d-1074-4fc1-a95a-2195265839e1"|
|12-18 14:35:53:326 [ info sync.networkjob ]:|OCC::MkColJob created for "https_://test.example.com" + "" "OCC::PropagateUploadFileNG"|
|12-18 14:35:53:414 [ info sync.networkjob.mkcol ]:|MKCOL of QUrl("https_://test.example.com/remote.php/dav/uploads/test1/3474338122") FINISHED WITH STATUS "OK"|
|12-18 14:35:53:425 [ info sync.accessmanager ]:|3 "" "https_://test.example.com/remote.php/dav/uploads/test1/3474338122/00000000" has X-Request-ID "00df5ce7-1c14-4233-acd3-a93e664ba042"|
|12-18 14:35:53:426 [ info sync.networkjob ]:|OCC::PUTFileJob created for "https_://test.example.com" + "" "OCC::PropagateUploadFileNG"|
|12-18 14:35:53:900 [ info sync.networkjob.put ]:|PUT of "https_://test.example.com/remote.php/dav/uploads/test1/3474338122/00000000" FINISHED WITH STATUS "OK" QVariant(int, 201) QVariant(QString, "")|
|12-18 14:35:53:902 [ info sync.propagator.upload ]:|Chunked upload of 10000000 bytes took 476 ms, desired is 60000 ms, expected good chunk size is 1260504201 bytes and nudged next chunk size to  100000000 bytes|
|12-18 14:35:53:911 [ info sync.accessmanager ]:|3 "" "https_://test.example.com/remote.php/dav/uploads/test1/3474338122/00000001" has X-Request-ID "260d2b51-33c8-4450-97e7-8837a66a0fe9"|
|12-18 14:35:53:913 [ info sync.networkjob ]:|OCC::PUTFileJob created for "https_://test.example.com" + "" "OCC::PropagateUploadFileNG"|
|12-18 14:35:54:228 [ info sync.networkjob.put ]:|PUT of "https_://test.example.com/remote.php/dav/uploads/test1/3474338122/00000001" FINISHED WITH STATUS "OK" QVariant(int, 201) QVariant(QString, "")|
|12-18 14:35:54:228 [ info sync.propagator.upload ]:|Chunked upload of 7322089 bytes took 321 ms, desired is 60000 ms, expected good chunk size is 1368614766 bytes and nudged next chunk size to  100000000 bytes|
|12-18 14:35:54:228 [ info sync.propagator.upload ]:|"//remote.php/dav/files/test1/üü.xlsx" "SHA1:18e7e5ce4efd2f2da11476dbc0599044a8864a78"|
|12-18 14:35:54:228 [ info sync.accessmanager ]:|6 "MOVE" "https_://test.example.com/remote.php/dav/uploads/test1/3474338122/.file" has X-Request-ID "92ec0ffa-84e4-42ed-8927-e141f6bc6773"|
|12-18 14:35:54:238 [ info sync.networkjob ]:|OCC::MoveJob created for "https_://test.example.com" + "" "OCC::PropagateUploadFileNG"|
|12-18 14:36:05:088 [ info sync.accessmanager ]:|6 "PROPFIND" "https_://test.example.com/remote.php/dav/files/test1/" has X-Request-ID "61a9479e-8644-4742-96a5-608f1e73a150"|
|12-18 14:36:05:088 [ info sync.networkjob ]:|OCC::PropfindJob created for "https_://test.example.com" + "/" "OCC::QuotaInfo"|
|12-18 14:36:05:177 [ info sync.networkjob.propfind ]:|PROPFIND of QUrl("https_://test.example.com/remote.php/dav/files/test1/") FINISHED WITH STATUS "OK"|

#2

Hey,

maybe this topic with all related hints and suggestions is helping here as well?


#3

Thanks, but this part I have covered, no problem uploading big files unless they contain special characters (and even then first upload works, it’s following changes that fail to sync).


#4

Hey,

sorry completely missed that in your post. :slightly_frowning_face:

Maybe the sync client are using different requests / methods for uploading the initial file then when uploading the subsequent changes and your proxy / SSL setup has some issues with that?

I think the logfiles of your web server, proxy and/or ownCloud server might tell you more about this issue.


#5

In debug logging mode I can see that nginx chokes on headers of MOVE command:

2018/12/20 11:27:31 [debug] 52#52: *9 http uri: "/remote.php/dav/uploads/test1/3489455842/.file"
2018/12/20 11:27:31 [debug] 52#52: *9 http args: ""
2018/12/20 11:27:31 [debug] 52#52: *9 http exten: ""
2018/12/20 11:27:31 [debug] 52#52: *9 http2 header: ":path: /remote.php/dav/uploads/test1/3489455842/.file"
2018/12/20 11:27:31 [debug] 52#52: *9 http2 get indexed header: 7
2018/12/20 11:27:31 [debug] 52#52: *9 http2 header: ":scheme: https"
2018/12/20 11:27:31 [debug] 52#52: *9 http2 encoded string, len:8
2018/12/20 11:27:31 [debug] 52#52: *9 http2 encoded string, len:34
2018/12/20 11:27:31 [debug] 52#52: *9 http2 table add: "destination: / //remote.php/dav/files/test1/%C3%BC%C3%BC.xlsx"
2018/12/20 11:27:31 [debug] 52#52: *9 http2 table account: 89 free:7
2018/12/20 11:27:31 [debug] 52#52: *9 http2 header: "destination: //remote.php/dav/files/test1/%C3%BC%C3%BC.xlsx"
2018/12/20 11:27:31 [debug] 52#52: *9 http2 get indexed name: 31
2018/12/20 11:27:31 [debug] 52#52: *9 http2 encoded string, len:16
2018/12/20 11:27:31 [debug] 52#52: *9 http2 table add: "content-type: application/octet-stream"
2018/12/20 11:27:31 [debug] 52#52: *9 http2 table account: 68 free:78
2018/12/20 11:27:31 [debug] 52#52: *9 http2 header: "content-type: application/octet-stream"
2018/12/20 11:27:31 [debug] 52#52: *9 http2 encoded string, len:2
2018/12/20 11:27:31 [info] 52#52: *9 client sent header field with too long length value while processing HTTP/2 connection, client: 192.168.0.135, server: 0.0.0.0:443
2018/12/20 11:27:31 [debug] 52#52: *9 http2 state connection error
2018/12/20 11:27:31 [debug] 52#52: *9 http2 send GOAWAY frame: last sid 135, error 9
2018/12/20 11:27:31 [debug] 52#52: *9 http2 frame out: 00005638C27AAFC8 sid:0 bl:0 len:8

Cannot really see the line nginx doesnt like tough. Both successful syncs (either initial with name üü.xlsx or initial and following with name yy.xlsx) have “oc-async: 1” at that point.


#6

Interestingly, when file has special characters in it’s name, there is extra header line passed:

(no special chars)
2018/12/21 08:45:56 [debug] 53#53: *245 http header: "Destination: //remote.php/dav/files/test1/yy.xlsx"
2018/12/21 08:45:56 [debug] 53#53: *245 http header: "Content-Type: application/octet-stream"
2018/12/21 08:45:56 [debug] 53#53: *245 http header: "OC-Async: 1"

(special chars)
2018/12/21 08:41:30 [debug] 53#53: *42 http header: "Destination: //remote.php/dav/files/test1/%C3%BC%C3%BC.xlsx"
2018/12/21 08:41:30 [debug] 53#53: *42 http header: "Content-Type: application/octet-stream"
2018/12/21 08:41:30 [debug] 53#53: *42 http header: "If: <//remote.php/dav/files/test1/üü.xlsx (["269464a181f8ac35292b46f1a7663934"])"
2018/12/21 08:41:30 [debug] 53#53: *42 http header: "OC-Async: 1"

I guess it’s either not encoded right by owncloud client or not decoded properly by nginx when http2 is used. I ended up disabling http2 in nginx as a workaround.