Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

curl reuses connection when non-chunked data has not entirely been sent #11678

Closed
dfandrich opened this issue Aug 15, 2023 · 1 comment
Closed

curl reuses connection when non-chunked data has not entirely been sent #11678

dfandrich opened this issue Aug 15, 2023 · 1 comment
Labels
connecting & proxies HTTP

Comments

@dfandrich
Copy link
Contributor

I did this

I caught a case where test 357 hung, while running the test suite under CPU starvation conditions. What seems to happen is this:

  1. curl sends a PUT request with Expect: 100-continue with HTTP/1.1
  2. it waits a moment for a 100 Continue response which doesn't come
  3. it starts sending its ~1 MiB payload in non-chunked mode
  4. while sending that payload (in 64 KiB blocks) the server returns a 417 "expectation failed" code
  5. curl immediately stops sending the remaining payload bytes, in order to start again without the Expect: 100-continue (again, in non-chunked mode)
  6. curl improperly reuses the existing connection to send the new response
  7. the server treats the start of the new request as part of the payload of the first request, and finishes reading the remaining bytes that it expected
  8. the server then finds itself in the middle of the payload of the second request, gets confused and just sits there
  9. curl completes sending the data of the second request and starts waiting for the HTTP response, which never comes

Here is an annotated excerpt from the trace log for the hanging test 357:

10:15:31.811080 == Info: !!! WARNING !!!
10:15:31.811167 == Info: This is a debug build of libcurl, do not use in production.
10:15:31.811171 == Info: processing: http://127.0.0.1:44697/we/want/357
10:15:31.811190 == Info: STATE: INIT => CONNECT handle 0x19dbde8; line 1974
10:15:31.811405 == Info: Added connection 0. The cache now contains 1 members
10:15:31.811451 == Info: STATE: CONNECT => CONNECTING handle 0x19dbde8; line 2027
10:15:31.811647 == Info:   Trying 127.0.0.1:44697...
10:15:31.811776 == Info: Connected to 127.0.0.1 (127.0.0.1) port 44697
10:15:31.811784 == Info: STATE: CONNECTING => PROTOCONNECT handle 0x19dbde8; line 2135
10:15:31.811789 == Info: STATE: PROTOCONNECT => DO handle 0x19dbde8; line 2165
10:15:31.811852 => Send header, 140 bytes (0x8c)
0000: PUT /we/want/357 HTTP/1.1
001b: Host: 127.0.0.1:44697
0032: User-Agent: curl/8.3.0-DEV
004e: Accept: */*
005b: Content-Length: 1053701
0074: Expect: 100-continue
008a:
10:15:31.811888 == Info: STATE: DO => DID handle 0x19dbde8; line 2259
10:15:31.811893 == Info: STATE: DID => PERFORMING handle 0x19dbde8; line 2377
10:15:32.889446 == Info: Done waiting for 100-continue
10:15:32.889863 => Send data, 65536 bytes (0x10000)
0000: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
0040: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
0080: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
(more of this, to reach exactly 65536 bytes of payload)
ff40: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
ff80: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
ffc0: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx

That's 65536 bytes, when the server is expecting 1053701 bytes.

10:15:33.872300 == Info: HTTP 1.1 or later with persistent connection
10:15:33.872316 <= Recv header, 26 bytes (0x1a)
0000: HTTP/1.1 417 OK swsbounce.
10:15:33.872359 <= Recv header, 36 bytes (0x24)
0000: Date: Tue, 09 Nov 2010 14:49:00 GMT.
10:15:33.872374 <= Recv header, 25 bytes (0x19)
0000: Server: test-server/fake.
10:15:33.872385 <= Recv header, 18 bytes (0x12)
0000: Content-Length: 0.
10:15:33.872398 == Info: Got 417 while waiting for a 100
10:15:33.872404 <= Recv header, 1 bytes (0x1)
0000: .
10:15:33.872412 == Info: multi_done: status: 0 prem: 0 done: 0
10:15:33.872476 == Info: Connection #0 to host 127.0.0.1 left intact
10:15:33.872540 == Info: Issue another request to this URL: 'http://127.0.0.1:44697/we/want/357'
10:15:33.872545 == Info: STATE: PERFORMING => CONNECT handle 0x19dbde8; line 2553
10:15:33.872655 == Info: Found bundle for host: 0x19d77b8 [serially]
10:15:33.872659 == Info: Can not multiplex, even if we wanted to
10:15:33.872679 == Info: Re-using existing connection with host 127.0.0.1

That's the smoking gun ^^^

10:15:33.872685 == Info: STATE: CONNECT => CONNECTING handle 0x19dbde8; line 2027
10:15:33.872690 == Info: STATE: CONNECTING => PROTOCONNECT handle 0x19dbde8; line 2135
10:15:33.872694 == Info: STATE: PROTOCONNECT => DO handle 0x19dbde8; line 2154
10:15:33.873002 => Send header, 118 bytes (0x76)
0000: PUT /we/want/357 HTTP/1.1
001b: Host: 127.0.0.1:44697
0032: User-Agent: curl/8.3.0-DEV
004e: Accept: */*
005b: Content-Length: 1053701
0074:
10:15:33.873029 == Info: STATE: DO => DID handle 0x19dbde8; line 2259
10:15:33.873034 == Info: STATE: DID => PERFORMING handle 0x19dbde8; line 2377
10:15:33.873367 => Send data, 65536 bytes (0x10000)
0000: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
0040: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
…

I expected the following

In step 6, curl should close the existing connection (since it is incomplete) and start a new one instead.

curl/libcurl version

8.3.0-DEV

operating system

Linux x86_64
@dfandrich
Copy link
Contributor Author

Here's a somewhat complicated reproduction procedure, but it also seems pretty reliable:

In xterm 1 run:

  1. printf 'HTTP/1.1 417\r\nContent-Length: 0\r\n\r\n' | xclip -i
  2. nc -l 8000

In xterm 2 run:

  1. mkfifo /tmp/fifo
  2. dd if=/dev/zero of=/tmp/zero64 bs=65536 count=1
  3. while true; do sleep 1; echo -n .;cat /tmp/zero64 >>/tmp/fifo; done

In xterm 3 run:

  1. curl --write-out 'Result: %{http_code}\n' --trace-ascii /tmp/trace --trace-time -T /tmp/fifo -H 'Content-Length: 2000000' -H 'Transfer-Encoding:' http://localhost:8000

As soon as you run the command in xterm 3, wait for the next period to appear in xterm 2, then immediately paste the clipboard into xterm 1. You should see a new set of headers from curl appear in xterm 1, then the system will hang. Examining the curl trace log should show substantially the same conditions mentioned in the bug report (although curl will likely have sent 128 KiB of data in the first connection instead of only 64 KiB).

dfandrich added a commit that referenced this issue Aug 15, 2023
@dfandrich
http: close the connection after a late 417 received
c7a6996 
In this situation, only part of the data has been sent before aborting
so the connection is no longer usable.

Fixes #11678
Closes #11679
@dfandrich dfandrich mentioned this issue Aug 15, 2023
Closed
dfandrich added a commit that referenced this issue Aug 16, 2023
@dfandrich
http: close the connection after a late 417 is received
e44d190 
In this situation, only part of the data has been sent before aborting
so the connection is no longer usable.

Assisted-by: Jay Satiro
Fixes #11678
Closes #11679
dfandrich added a commit that referenced this issue Aug 17, 2023
@dfandrich
http: close the connection after a late 417 is received
da9efef 
In this situation, only part of the data has been sent before aborting
so the connection is no longer usable.

Assisted-by: Jay Satiro
Fixes #11678
Closes #11679
dfandrich added a commit that referenced this issue Aug 17, 2023
@dfandrich
http: close the connection after a late 417 is received
fc44fd9 
In this situation, only part of the data has been sent before aborting
so the connection is no longer usable.

Assisted-by: Jay Satiro
Fixes #11678
Closes #11679
dfandrich added a commit that referenced this issue Aug 18, 2023
@dfandrich
http: close the connection after a late 417 is received
a555251 
In this situation, only part of the data has been sent before aborting
so the connection is no longer usable.

Assisted-by: Jay Satiro
Fixes #11678
Closes #11679
dfandrich added a commit that referenced this issue Aug 21, 2023
@dfandrich
http: close the connection after a late 417 is received
6a5dd3c 
In this situation, only part of the data has been sent before aborting
so the connection is no longer usable.

Assisted-by: Jay Satiro
Fixes #11678
Closes #11679
dfandrich added a commit that referenced this issue Aug 21, 2023
@dfandrich
http: close the connection after a late 417 is received
d48d55f 
In this situation, only part of the data has been sent before aborting
so the connection is no longer usable.

Assisted-by: Jay Satiro
Fixes #11678
Closes #11679
ptitSeb pushed a commit to wasix-org/curl that referenced this issue Sep 25, 2023
@dfandrich @ptitSeb
http: close the connection after a late 417 is received
4804819 
In this situation, only part of the data has been sent before aborting
so the connection is no longer usable.

Assisted-by: Jay Satiro
Fixes curl#11678
Closes curl#11679
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
connecting & proxies HTTP
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

http: close the connection after a late 417 received curl/curl
1 participant
@dfandrich