Files will not download when using curl 7.62.0

[abraunegg]

I did this

Arch Linux updated to Curl to 7.62.0, which subsequently broke how the Linux OneDrive client (https://github.com/abraunegg/onedrive) operates. It appears to be some sort of 'flip / flop' between each request between HTTP 1.1 and HTTP 2 when downloading content.

The impact of this is, that whilst the files / data is uploaded / downloaded - the actual operations fail as some sort of internal mechanics is barfing the buffer streams thus files fail to download and get deleted - data loss.

OneDrive Linux Client issue: abraunegg/onedrive#220

OneDrive Linux Application log file below:

* Connection #1 to host graph.microsoft.com left intact
OneDrive Response: {"@odata.context":"https:\/\/graph.microsoft.com\/v1.0\/$metadata#drives('66d53be8a5056eca')\/items\/$entity","cTag":"adDo2NkQ1M0JFOEE1MDU2RUNBITEwMS42MzY3NzMzMTI2OTk1MDAwMDA","eTag":"aNjZENTNCRThBNTA1NkVDQSExMDEuMA","fileSystemInfo":{"createdDateTime":"2018-06-06T20:45:24.436Z","lastModifiedDateTime":"2018-06-06T20:45:24.436Z"},"folder":{"childCount":0,"view":{"sortBy":"name","sortOrder":"ascending","viewType":"thumbnails"}},"id":"66D53BE8A5056ECA!101","name":"root","parentReference":{"driveId":"66d53be8a5056eca","driveType":"personal"},"root":{}}
* Found bundle for host graph.microsoft.com: 0x55b20212fbe0 [can pipeline]
* Could pipeline, but not asked to!
* Re-using existing connection! (#1) with host graph.microsoft.com
* Connected to graph.microsoft.com (20.190.142.179) port 443 (#1)
> GET /v1.0/drives/66d53be8a5056eca/items/66D53BE8A5056ECA!101/delta?select=id%2cname%2ceTag%2ccTag%2cdeleted%2cfile%2cfolder%2croot%2cfileSystemInfo%2cremoteItem%2cparentReference&token=aTE09NjM2NzczMTcyODQ5NDA7SUQ9NjZENTNCRThBNTA1NkVDQSExMDE7TFI9NjM2NzczMzEyNDQ0MDM7RVA9MTg7U0k9NjU7U0c9MTtTTz0yO1BJPTM HTTP/1.1
Host: graph.microsoft.com
User-Agent: onedrive client testing
Accept: */*
Authorization: bearer <redacted>

< HTTP/1.1 200 OK
< Cache-Control: private
< Transfer-Encoding: chunked
< Content-Type: application/json;odata.metadata=minimal;odata.streaming=true;IEEE754Compatible=false;charset=utf-8
< request-id: 82ea2d6b-339e-4543-a228-e065adf20a3d
< client-request-id: 82ea2d6b-339e-4543-a228-e065adf20a3d
< x-ms-ags-diagnostic: {"ServerInfo":{"DataCenter":"Australia Southeast","Slice":"SliceC","Ring":"5","ScaleUnit":"002","Host":"AGSFE_IN_14","ADSiteName":"ASE"}}
< OData-Version: 4.0
< Duration: 314.7767
< Strict-Transport-Security: max-age=31536000
< Date: Fri, 09 Nov 2018 03:42:39 GMT
< 
* Connection #1 to host graph.microsoft.com left intact
OneDrive Response: {"@odata.context":"https:\/\/graph.microsoft.com\/v1.0\/$metadata#Collection(driveItem)","@odata.deltaLink":"https:\/\/graph.microsoft.com\/v1.0\/drives\/66d53be8a5056eca\/items\/66D53BE8A5056ECA!101\/delta?select=id%2cname%2ceTag%2ccTag%2cdeleted%2cfile%2cfolder%2croot%2cfileSystemInfo%2cremoteItem%2cparentReference&token=aTE09NjM2NzczMzEyNjk5NTA7SUQ9NjZENTNCRThBNTA1NkVDQSExMDE7TFI9NjM2NzczMzE3NTk5ODM7RVA9MTg7U0k9NjU7U0c9MTtTTz0yO1BJPTM","value":[{"@odata.type":"#microsoft.graph.driveItem","cTag":"adDo2NkQ1M0JFOEE1MDU2RUNBITEwMS42MzY3NzMzMTI2OTk1MDAwMDA","eTag":"aNjZENTNCRThBNTA1NkVDQSExMDEuMA","fileSystemInfo":{"createdDateTime":"2018-06-06T20:45:24.436Z","lastModifiedDateTime":"2018-06-06T20:45:24.436Z"},"folder":{"childCount":0,"view":{"sortBy":"name","sortOrder":"ascending","viewType":"thumbnails"}},"id":"66D53BE8A5056ECA!101","name":"root","parentReference":{"driveId":"66d53be8a5056eca","driveType":"personal","id":"66D53BE8A5056ECA!0","path":"\/drive\/root:"},"root":{}},{"@odata.type":"#microsoft.graph.driveItem","cTag":"aYzo2NkQ1M0JFOEE1MDU2RUNBITI0OTUuMjU3","eTag":"aNjZENTNCRThBNTA1NkVDQSEyNDk1LjE","file":{"hashes":{"sha1Hash":"3A6CB7F48975040D7CEAD7049CABAB7652A3993F"},"mimeType":"application\/x-rar-compressed"},"fileSystemInfo":{"createdDateTime":"2018-11-09T03:34:15.356Z","lastModifiedDateTime":"2018-11-09T03:33:36.756Z"},"id":"66D53BE8A5056ECA!2495","name":"file.rar","parentReference":{"driveId":"66d53be8a5056eca","driveType":"personal","id":"66D53BE8A5056ECA!101","name":"root:","path":"\/drive\/root:"}},{"@odata.type":"#microsoft.graph.driveItem","deleted":{"state":"softDeleted"},"eTag":"aNjZENTNCRThBNTA1NkVDQSEyNDk0LjM","file":{},"id":"66D53BE8A5056ECA!2494","name":"newfile-ubuntu-x64-18","parentReference":{"driveId":"66d53be8a5056eca","driveType":"personal","id":"66D53BE8A5056ECA!101"}}]}
Downloading file file.rar ... * Found bundle for host graph.microsoft.com: 0x55b20212fbe0 [can pipeline]
* Could pipeline, but not asked to!
* Re-using existing connection! (#1) with host graph.microsoft.com
* Connected to graph.microsoft.com (20.190.142.179) port 443 (#1)
> GET /v1.0/drives/66d53be8a5056eca/items/66D53BE8A5056ECA!2495?select=size,malware HTTP/1.1
Host: graph.microsoft.com
User-Agent: onedrive client testing
Accept: */*
Authorization: bearer <redacted>

< HTTP/1.1 200 OK
< Cache-Control: private
< Transfer-Encoding: chunked
< Content-Type: application/json;odata.metadata=minimal;odata.streaming=true;IEEE754Compatible=false;charset=utf-8
< request-id: caa49bbc-f1d3-4970-97ad-3e46c5e1c25d
< client-request-id: caa49bbc-f1d3-4970-97ad-3e46c5e1c25d
< x-ms-ags-diagnostic: {"ServerInfo":{"DataCenter":"Australia Southeast","Slice":"SliceC","Ring":"5","ScaleUnit":"002","Host":"AGSFE_IN_14","ADSiteName":"ASE"}}
< OData-Version: 4.0
< Duration: 652.1868
< Strict-Transport-Security: max-age=31536000
< Date: Fri, 09 Nov 2018 03:42:39 GMT
< 
* Connection #1 to host graph.microsoft.com left intact
OneDrive Response: {"@odata.context":"https:\/\/graph.microsoft.com\/v1.0\/$metadata#drives('66d53be8a5056eca')\/items\/$entity","size":7864320}

* Found bundle for host graph.microsoft.com: 0x55b20212fbe0 [can pipeline]
* Could pipeline, but not asked to!
* Re-using existing connection! (#1) with host graph.microsoft.com
* Connected to graph.microsoft.com (20.190.142.179) port 443 (#1)
> GET /v1.0/drives/66d53be8a5056eca/items/66D53BE8A5056ECA!2495/content?AVOverride=1 HTTP/1.1
Host: graph.microsoft.com
User-Agent: onedrive client testing
Accept: */*
Authorization: bearer <redacted>

< HTTP/1.1 302 Found
< Cache-Control: private
< Transfer-Encoding: chunked
< Content-Type: text/plain
< Location: https://public.sn.files.1drv.com/y4mlilSx8ho3tufsLjoFaArlp28LR_50cPk9symt2FSWxcjA4mzgFhaQ52ipsGwgCcWxX2lcH_LeNEPMb3wxjZPK1gdHe3Fum3tGGeatdNWAgRIUlXdqQQHZJgfrQ_k87E9gvuasDmYeMdt2dLOPbYq8Cn2sDAzQNZDvbHBRoxQme8WqOXxuPp3Qf0NS_nr1xhXP7quUy9RLHdS4MHSRrBPtCJIMRXyZnBCCA3oi6jGLwheUVPVzkX48PFNJBeKD9Ul/file.rar?AVOverride=1
< request-id: 758c284c-2988-489d-ba32-55dfa8f92af8
< client-request-id: 758c284c-2988-489d-ba32-55dfa8f92af8
< x-ms-ags-diagnostic: {"ServerInfo":{"DataCenter":"Australia Southeast","Slice":"SliceC","Ring":"5","ScaleUnit":"002","Host":"AGSFE_IN_14","ADSiteName":"ASE"}}
< Duration: 287.3558
< Strict-Transport-Security: max-age=31536000
< Date: Fri, 09 Nov 2018 03:42:40 GMT
< 
* Ignoring the response-body
* Connection #1 to host graph.microsoft.com left intact
* Issue another request to this URL: 'https://public.sn.files.1drv.com/y4mlilSx8ho3tufsLjoFaArlp28LR_50cPk9symt2FSWxcjA4mzgFhaQ52ipsGwgCcWxX2lcH_LeNEPMb3wxjZPK1gdHe3Fum3tGGeatdNWAgRIUlXdqQQHZJgfrQ_k87E9gvuasDmYeMdt2dLOPbYq8Cn2sDAzQNZDvbHBRoxQme8WqOXxuPp3Qf0NS_nr1xhXP7quUy9RLHdS4MHSRrBPtCJIMRXyZnBCCA3oi6jGLwheUVPVzkX48PFNJBeKD9Ul/file.rar?AVOverride=1'
*   Trying 131.253.33.213...
* TCP_NODELAY set
* Connected to public.sn.files.1drv.com (131.253.33.213) port 443 (#2)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: none
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=US; ST=WA; L=Redmond; O=Microsoft Corporation; OU=Microsoft Corporation; CN=storage.live.com
*  start date: Oct 19 22:20:20 2017 GMT
*  expire date: Oct 19 22:20:20 2019 GMT
*  subjectAltName: host "public.sn.files.1drv.com" matched cert's "*.sn.files.1drv.com"
*  issuer: C=US; ST=Washington; L=Redmond; O=Microsoft Corporation; OU=Microsoft IT; CN=Microsoft IT TLS CA 5
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x55b2020c3690)
> GET /y4mlilSx8ho3tufsLjoFaArlp28LR_50cPk9symt2FSWxcjA4mzgFhaQ52ipsGwgCcWxX2lcH_LeNEPMb3wxjZPK1gdHe3Fum3tGGeatdNWAgRIUlXdqQQHZJgfrQ_k87E9gvuasDmYeMdt2dLOPbYq8Cn2sDAzQNZDvbHBRoxQme8WqOXxuPp3Qf0NS_nr1xhXP7quUy9RLHdS4MHSRrBPtCJIMRXyZnBCCA3oi6jGLwheUVPVzkX48PFNJBeKD9Ul/file.rar?AVOverride=1 HTTP/2
Host: public.sn.files.1drv.com
User-Agent: onedrive client testing
Accept: */*

* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
< HTTP/2 200 
< cache-control: public
< content-length: 7864320
< content-type: application/x-rar-compressed
< content-location: https://public.sn.files.1drv.com/y4m1C36QL3I39BfzW_2Wl4bopztJFR30vhR0d2StTTw535btUhrwLp2V5GfSswv5V3_N-gOMyic2rCt9dxze0L8OtPlD-lfbjrA2A16cLr6OZv48nff4GwybF5ipAebzegbLjGNJIcvezVWoUuuUU-89fbRSLujk9kybuGSSNgB_hIT8HrvhtUQFHZzQFUS0cM6Xad5-tZAp_qP68_p7rURBAYWMBQmQw4Q_j8X6xqH8InhVuYTWf7S9mfn91EI4bPI
< expires: Thu, 07 Feb 2019 03:42:41 GMT
< last-modified: Fri, 09 Nov 2018 03:34:15 GMT
< accept-ranges: bytes
< etag: aNjZENTNCRThBNTA1NkVDQSEyNDk1LjE
< p3p: CP="BUS CUR CONo FIN IVDo ONL OUR PHY SAMo TELo"
< x-msnserver: SN3PPFABCC100A0
< strict-transport-security: max-age=31536000; includeSubDomains
< x-sqldataorigin: S
< ctag: aYzo2NkQ1M0JFOEE1MDU2RUNBITI0OTUuMjU3
< x-preauthinfo: rv;poba;
< content-disposition: attachment; filename="file.rar"
< x-content-type-options: nosniff
< x-streamorigin: X
< x-asmversion: UNKNOWN; 19.151.1105.2004
< x-msedge-ref: Ref A: A66C43A252C54FE99D940B2E79F19930 Ref B: MEL01EDGE0217 Ref C: 2018-11-09T03:42:41Z
< date: Fri, 09 Nov 2018 03:42:41 GMT
< 
Downloading 100% |oooooooooooooooooooooooooooooooooooooooo| DONE IN 00:00:05 * Connection #2 to host public.sn.files.1drv.com left intact                                               

done.
file.rar: No such file or directory

I expected the following

Correct download of files as per 7.61.x curl version

curl/libcurl version

curl 7.62.0 (x86_64-pc-linux-gnu) libcurl/7.62.0 OpenSSL/1.1.1 zlib/1.2.11 libidn2/2.0.5 libpsl/0.20.2 (+libidn2/2.0.4) libssh2/1.8.0 nghttp2/1.34.0
Release-Date: 2018-10-31
Protocols: dict file ftp ftps gopher http https imap imaps pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: AsynchDNS IDN IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets HTTPS-proxy PSL

(As per Arch Linux package)

operating system

Linux 127.0.0.1localhost 4.18.16-arch1-1-ARCH #1 SMP PREEMPT Sat Oct 20 22:06:45 UTC 2018 x86_64 GNU/Linux

[abraunegg]

Reading through #3206, potentially same issue - although unsure on how to increase verbosity of curl through dmd for compiled executable beyond what I have already provided.

[bagder]

I don't see any "flip flop" in this log. I see curl using HTTP/1.1 for one of the hosts and HTTP/2 for the other, and that HTTP/2 transfer seems to get you the data.

Have you tried to "enforce" HTTP/1.1 for the transfers to see if that chances anything?

sort of internal mechanics is barfing the buffer streams

I think you need to explain this better because that protocol log you showed doesn't seem to show any problems at all.

Does libcurl return an error even?

If you rebuild libcurl with ./configure --enable-debug you will get additional verbose message in the output that could help shedding some light on the issue.

[abraunegg]

I see curl using HTTP/1.1 for one of the hosts and HTTP/2 for the other, and that HTTP/2 transfer seems to get you the data.

This is what I was meaning - I was expecting the same method to be used 100% of the time.

I think you need to explain this better because that protocol log you showed doesn't seem to show any problems at all.
Does libcurl return an error even?

It appears that the file "does" get downloaded, and is being written to a temporary file.

At the point to transfer completion, the file 'disappears' with no error generated. The 'onedrive' client code - as no error has been generated, proceeds to try and analyse the file - which is not there thus fails. If there was an error, ths would be handled.

I suspect 'something' is happening at the point of file receive being finalised inside 'curl'.

If you rebuild libcurl with ./configure --enable-debug you will get additional verbose message in the output that could help shedding some light on the issue.

I am not a Arch linux user, so will have to get some assistance with that.

[bagder]

I was expecting the same method to be used 100% of the time.

If both servers had accepted HTTP/2, curl would've used it with both.

It appears that the file "does" get downloaded, and is being written to a temporary file.

libcurl does not write to a (temporary) file on its own. The application made the output end up in that file.

At the point to transfer completion, the file 'disappears' with no error generated.

libcurl did not do that. It didn't know about the file and it can't and won't remove local files. That sounds like the application did that.

I suspect 'something' is happening at the point of file receive being finalised inside 'curl'.

To curl, all data is just a stream of bytes and it passes that stream on to the callback. It doesn't "finalise" the output.

So again: did libcurl return any error somewhere? If not, you probably need to either provide logs with more details or, preferably, an example source code that can reproduce this problem.

[abraunegg]

I am working on gathering additional logs to rule out a libcurl problem, will also be doing a wireshark capture to see if anything is occuring at the network layer.

It seems odd to me that it works without issue with http 1.1 but fails when libcurl switches to http2

[bagder]

It seems odd to me that it works without issue with http 1.1 but fails when libcurl switches to http2

I totally agree that it seems to have a correlation with the issue, but without more information I can't properly deduce where the problem actually lies or how to fix it.

[abraunegg]

@bagder
So I have managed to force the 'onedrive' client to use http 1.1 for connections and using 7.62.0 - and files are able to be downloaded / uploaded without issue

Will see how I can get the further debug items from libcurl, however it certainly points to something in the libcurl library and http2

[bagder]

something in the libcurl library and http2

... or bad assumptions or wrong handling in the application, yes. But we need details to tell for sure.

[abraunegg]

No bad assumptions - I think there is certainly something up with this release:

skilion/onedrive#430
abraunegg/onedrive#220

I have asked for the details from users regarding getting additional debug details for you - alas nothing as yet.

[bagder]

I think I'm not expressing myself clearly enough.

curl 7.62.0 now makes lots of requests use HTTP/2 by default compared previous versions, which of course changes things a bit. Servers will now speak HTTP/2 and respond with that protocol version instead of HTTP/1.1 like before, unless the application explicitly asks for HTTP/1.

This changes the responses slightly and an application that has made assumptions about the response being exactly like before in HTTP/1 land might get into trouble with HTTP/2. Unless you've actually debugged the problem or reviewed the application code, you can't know if there are such "bad" assumptions or not.

HTTP/2 is also quite different than HTTP/1 for servers so there's also the risk that this change triggers new issues in the server software that it previously didn't. Like #3206.

Then we can of course not rule out that there's a libcurl issue or bug that gets triggered here. We're far from perfect and we also have our share of bugs. But we need a way to reproduce or understand the reported issue before we'd make that conclusion or even just start digging around the code to research this deeper. You have only so far reported some weirdo symptoms in an curl-using application.

I would urge you to work with the author(s) of this app to try to reproduce an as small reproducible example as possible that shows this problem happen. Be it either a small C source code that uses libcurl or perhaps even a curl command line.

[abraunegg]

@bagder
Thanks for the details. Closing this as issue was found that HTTP/2 was throwing a 302 redirect which was not being handled.