Client: Big files do not sync - chunks do not sum up

[kerlerm]

Expected behaviour

Big files should sync.

Actual behaviour

Bigger files do not sync when using the sync client 2.5.3
Upload is possible by Webbrowser & GUI. No changes where made on the server since 10/2018 and I synced files sized about 320 MB in 12/2018. No quota is applied to the user.

Steps to reproduce

Take file "test" with about 100-150 MB and initiate sync. Error "Chunks on server do not sum up to ..." is thrown after upload of chunks is complete.

Server configuration

Operating system:
Linux

Web server:
Apache

Database:
MySQL 5.7

PHP version:
7.2 FPM

ownCloud version:
10.0.10.4

Storage backend (external storage):

Client configuration

Client version:
2.5.3 build 342

Operating system:
Linux 64

OS language:
German

Qt version used by client package (Linux only, see also Settings dialog):
Qt 5.10.1

Client package (From ownCloud or distro) (Linux only):
GIT-Revision 80478b auf Feb 7 2019, 17:25:04 verwendet Qt 5.10.1, OpenSSL 1.0.2n 7 Dec 2017

Installation path of client:
/usr/bin/owncloud

Logs

1. Client logfile: Output of owncloud --logwindow or owncloud --logfile log.txt
   https://gist.githubusercontent.com/kerlerm/bb259a92d63e4b926b7ad3fe30ab0f62/raw/fd2740e5ffebfbef2d608ce28613317c3e76ee68/client_log.txt

2. Web server error log:
   https://gist.githubusercontent.com/kerlerm/9bc1dfcc073be59966b2c2d70592f29a/raw/4b60d3d6744c623c8ce43587bdea8bd3784d3989/gistfile1.txt

3. Server logfile: ownCloud log (data/owncloud.log):
   https://gist.githubusercontent.com/kerlerm/99f1ae603170e8ce0669987cc54cf055/raw/0711f8b296e7a68a902125dd0216ce98fa9d487b/server_log.txt

[michaelstingl]

@kerlerm Do you know the version that worked? 2.5.1? 2.4.3?

[kerlerm]

Unfortunately, I did not follow installed versions on my machine. I assume 2.4.3 still worked, 2.5.2 and 2.5.3 certainly do not. Should I try downgrading to verify?

[ckamm]

@kerlerm Thanks for the report and for including client logs!

@guruz The log contains warnings like this:

[ warning qt.network.http2 ]:   stream 15 finished with error: ""

Is there a way to disable http2 for testing?

From what I can see the client attempts to upload chunks and sees successes even though the server log shows a 400. For example there's a from-scratch upload that logs like this:

02-08 10:36:36:430 [ info sync.networkjob.put ]:    PUT of "https://xxxFQDNxx/remote.php/dav/uploads/xxUSERxx/1711918512/00000000" FINISHED WITH STATUS "OK" QVariant(Invalid) QVariant(Invalid)
02-08 10:36:36:430 [ warning qt.network.http2 ]:    stream 15 finished with error: ""
02-08 10:36:36:434 [ info sync.propagator.upload ]: Chunked upload of 10000000 bytes took ...

02-08 10:38:42:556 [ info sync.networkjob.put ]:    PUT of "https://xxxFQDNxx/remote.php/dav/uploads/xxUSERxx/1711918512/00000001" FINISHED WITH STATUS "OK" QVariant(Invalid) QVariant(Invalid)
02-08 10:38:42:561 [ info sync.propagator.upload ]: Chunked upload of 92645760 bytes took ...

10000000 + 92645760 = 102645760

02-08 10:38:43:099 [ warning sync.propagator ]: Could not complete propagation of "Software/Android/test" by OCC::PropagateUploadFileNG(0x558a8d9c4520) with status 2 and error: "Error transferring https://xxxFQDNxx/remote.php/dav/uploads/xxUSERxx/1711918512/.file - server replied:  
(Chunks on server do not sum up to 102645760 but to 75726848)"

and the server says

xxIPxx - - [08/Feb/2019:10:36:34 +0100] "PUT /remote.php/dav/uploads/xxUSERxx/1711918512/00000000 HTTP/2.0" 400 23 "-" "Mozilla/5.0 (Linux) mirall/2.5.3 (build 342)" xxxFQDNxx

[ckamm]

It looks like we end up in QHttp2ProtocolHandler::finishStreamWithError but error is NoError. If I read the Qt code correctly that can only happen when a GOAWAY or RST_STREAM frame has errorCode 0.

Should we check for putFileJob->device()->atEnd() after a successful job, just to make sure? Could be though that the data was sent successfully, just the reply didn't end up being processed correctly somehow.

[ckamm]

@kerlerm Do you think you might be able to capture the network traffic that happens while failing to sync this file with a tool like wireshark and upload the data? (shared privately with mail at ckamm de preferably, it might contain auth cookies) This could be your server speaking HTTP2 improperly, but could also be a bug in Qt.

You should definitely be able to work around the problem by disabling HTTP2 server side.

[kerlerm]

@ckamm Sent you a notice. PCAP is available on my owncloud for download.

[kerlerm]

Disabling HTTP/2 is bit of a hassle because this is not running on a root server but shared hosting...

[kerlerm]

@ckamm I tried mitmproxy of ubuntu, but the package is damaged (newer libs). Then I fetched the linux binaries of mitmproxy 4.0, but those froze at 6MB transfer while testing. So I'm a bit lost...

Should I provide a test account on my owncloud for you?

[ckamm]

@kerlerm Mitmproxy freezing mid-transfer might be an indication that something is indeed going wrong with the http2 stream. Yes, if you could give me a test account I'd try to reproduce and check it out.

[ckamm]

I think this is a bug in the Qt http2 stack.

Test setup: client <-> mitmproxy <-> server with mitmproxy dumping ssl secrets and wireshark listening to the comunication between mitmproxy and the server. That means I'm seeing how mitmproxy reacts to the server messages, but the data is sufficient to see what's going on.

• Client opens HTTP2 connection
• Requests data on streams 1, 3, 5, 7, 9
• Stream 1, 9 finish; Stream 3, 5, 7 are still streaming DATA frames and are not finished
• There's a GOAWAY 2^31-1 no-error frame
• mitmproxy closes the connection with a tls close_notify
• there are more DATA frames from the server on streams 3, 7 that aren't ACKed by the client
• finally a GOAWAY 9 no-error frame, and the server's close_notify

The GOAWAY processing seems to be the problem for mitmproxy, and also for Qt. Looking at https://code.woboq.org/qt5/qtbase/src/network/access/qhttp2protocolhandler.cpp.html#815 it seems that a GOAWAY with lastStreamId of 2^31-1 will close all active streams. If I read the spec correctly, it shouldn't do that (https://http2.github.io/http2-spec/#GOAWAY).

[ckamm]

Created upstream ticket: https://bugreports.qt.io/browse/QTBUG-73947

[ckamm]

@michaelstingl @guruz @ogoffart I'm working on the upstream issue but am strongly recommending to disable HTTP2 support until we have upgraded to a Qt version containing the fix.

[michaelstingl]

@ckamm Is there a config switch to disable HTTP2?

[ckamm]

No, not yet :/ I'd disable it for 2.5.4 and add a env variable to reenable it if desired.

[ckamm]

https://codereview.qt-project.org/#/c/254111/

[guruz]

@ckamm Wow. And meh!

[ckamm]

Note: PR doesn't solve the issue, just disables HTTP2. We'll need to update Qt once the patch is released.

[guruz]

@kerlerm Can you try a recent daily build?
https://download.owncloud.com/desktop/daily/owncloud-client-2.5.4.11579.451daily20190304.linux-repo.html

[kerlerm]

Sorry for the late reply: Version 2.5.4daily20190305 (build 453) syncs big files without problems.

@ckamm: Should I delete your account on my owncloud or will you do further testing once Qt is fixed?

[ckamm]

@kerlerm Thanks for testing! You can delete it now, I found a way to reproduce a very similar problem locally.

[jnweiger]

Tested on ubuntu 18.10 with 2.5.4rc1

allow haproxy to use HTTP/2.0
2.5.4rc1 connects per default with HTTP/1.1
export OWNCLOUD_HTTP2_ENABLED=1
2.5.4rc1 connects then with HTTP/2.0
OK