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

[dfandrich]

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]

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).