Bugs item #1945240, was opened at 2008-04-17 17:07
Message generated for change (Comment added) made by bvanhof
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=100976&aid=1945240&group_id=976

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: libcurl
Group: wrong behaviour
>Status: Open
Resolution: Fixed
Priority: 6
Private: No
Submitted By: Ben Van Hof (bvanhof)
Assigned to: Daniel Stenberg (bagder)
Summary: libcurl sometimes sends body twice when using CURL_AUTH_ANY

Initial Comment:
Hi,

I've encountered an intermittent problem when using libcurl to send requests with a body to a server which requires authentication, using the CURL_AUTH_ANY option. Normally, it works as expected, but occasionally the server returns a 400 Bad Request instead of succeeding. The (failing) transaction looks like this:

client says: PUT blah
             [headers]
             Expect: 100-continue

server says: HTTP/1.1 100 Continue

client says: [request body]

server says: HTTP/1.1 401 Authorization Required

client says: [request body] *** very bad
             PUT blah
             [headers]

server says: HTTP/1.1 400 Bad Request WTF!!

Near as I can tell, here's what's happening: when sending the request body the first time, Curl_readwrite gets called repeatedly until Curl_fillreadbuffer reports that it sent 0 bytes (see lines ~1445 ff of transfer.c), at which point it clears the KEEP_WRITE flag and calls it a day. The implication is that one "extra" call to Curl_readwrite is required AFTER the entire body has been sent off to the server (in order to get the 'zero bytes written' condition). If the server happens to respond before that final call to Curl_readwrite, though, it winds up getting into the read code first, where it will call Curl_http_auth_act(), and, through it, perhapsrewind(), which decides to rewind the input file. Oops. Now when it gets back into the write code, it winds up re-sending the body, which of course confuses the heck out of the poor server.

The couple of quick fixes I've tried have failed something in the test cases, so rather than submit a half-assed patch I'll leave this to someone who knows this code well enough not to break it. You can reproduce the problem by using the curl client to send a request with a body to any server requiring authentication, using the '--anyauth' flag (the problem doesn't appear if you request a specific auth method, since that bypasses the extra negotiation step.) E.g.:

curl --anyauth -u user:passwd -X PUT -T body.txt http://localhost/some/url

It does happen much more frequently if the server is local (since it's dependent on the server responding quickly), but you can reproduce the bug reliably in any case by running it under the debugger and setting a breakpoint on Curl_readwrite (the third call is the critical one), which creates a delay sufficient to trigger it.

curl -V
curl 7.18.1 (i686-pc-linux-gnu) libcurl/7.18.1 OpenSSL/0.9.8c zlib/1.2.3 libidn/0.6.5 libssh2/0.17
Protocols: tftp ftp telnet dict ldap http file https ftps scp sftp
Features: Debug IDN IPv6 Largefile NTLM SSL libz

Let me know if you need any other info.

Ben Van Hof

----------------------------------------------------------------------

>Comment By: Ben Van Hof (bvanhof)
Date: 2008-05-06 12:22

Message:
Logged In: YES
user_id=2065988
Originator: YES

Works great! Thanks for all your help.

Ben

----------------------------------------------------------------------

Comment By: Daniel Stenberg (bagder)
Date: 2008-05-03 17:47

Message:
Logged In: YES
user_id=1110
Originator: NO

Thanks. I don't get that smell from this change, although I prefer to move
the clearing of that bit to the actual rewind function. I did that and I
committed this change with some added comments too and your new test case
1030 to go with all this.

Can you just see if I messed up anything or if this code now works fine
for you?

----------------------------------------------------------------------

Comment By: Ben Van Hof (bvanhof)
Date: 2008-05-03 15:55

Message:
Logged In: YES
user_id=2065988
Originator: YES

I'm afraid that doesn't quite do it; the test case still fails on my
system, and so does the script that originally triggered the issue for me.
The problem is that libcurl can technically have sent the entire body (so
that bytessent == expectsend in perhapsrewind(), causing it to fall into
your new "else if" clause and rewind the file), but Curl_readwrite() still
thinks it has something to send (because k->keepon has KEEP_WRITE set). If
the file is not rewound, that works fine, because it sends zero bytes,
realizes that it's really done, and stops. But if the rewind happens, the
bug manifests.

With that in mind, here's another patch which simply clears the KEEP_WRITE
bit of req->keepon before rewinding, which prevents that pesky final pass
through the write code altogether. I'll be the first to admit that this
has the scent of an ugly hack around something more fundamentally wrong,
and someone who knows the codebase better may be able to figure out a more
elegant fix. It does, however, pass all the test cases and solves my
original problem.

Ben

File Added: keepon.patch

----------------------------------------------------------------------

Comment By: Daniel Stenberg (bagder)
Date: 2008-05-03 07:05

Message:
Logged In: YES
user_id=1110
Originator: NO

Ok, here's my take at your fix, slightly edited and it now runs both your
test case (I've renumbered it to 1030 for inclusion in CVS) and all other
current ones.

Any comments before I commit this fix and close this bug report?
File Added: rewind-2.patch

----------------------------------------------------------------------

Comment By: Daniel Stenberg (bagder)
Date: 2008-05-02 17:18

Message:
Logged In: YES
user_id=1110
Originator: NO

Thanks a lot for the test case and patch.

I now understand your problem completely and I do think your fix looks
fine, even if it does break at least one test case. I'll look into if
perhaps that test case (and possibly more) is just badly written.

----------------------------------------------------------------------

Comment By: Ben Van Hof (bvanhof)
Date: 2008-05-02 16:52

Message:
Logged In: YES
user_id=2065988
Originator: YES

File Added: http.c.patch

----------------------------------------------------------------------

Comment By: Ben Van Hof (bvanhof)
Date: 2008-05-02 16:48

Message:
Logged In: YES
user_id=2065988
Originator: YES

File Added: http.c.patch

----------------------------------------------------------------------

Comment By: Ben Van Hof (bvanhof)
Date: 2008-05-02 16:47

Message:
Logged In: YES
user_id=2065988
Originator: YES

OK, I'm attaching a test case based off of 154. Notable differences are
the removal of 'auth_required' from the <servercmd> section (which was
causing the test server to send back a 401 before curl could send the body
of the PUT, behavior I don't see with Apache 2.2) and the removal of
'swsclose' and 'Connection: close' from the <data> section (the bug only
triggers when the connection is left open).

When you run this test, it'll hang indefinitely. Curl (incorrectly) sends
the body a second time BEFORE it sends its second PUT request (as described
in the original report), which not only results in a malformed request, but
 leaves it unable to make good on the body it promises via the
Content-length header (since the file it's trying to put is already at
EOF), leaving the test server to wait forever in vain. You can see this if
you run the test server under gdb, and break out of it once it gets stuck.
You'll see that it's waiting on an sread(), and that reqbuf[] contains the
body and the headers in the wrong order.

I'm also attaching a one-line patch to lib/http.c which "fixes" the
problem (by not prematurely rewinding the body file), though I'm sure it
breaks other cases and is provided only to illustrate what a correct run of
the test case should look like.

Hope that helps. Let me know if you need anything else.

Ben
File Added: test999

----------------------------------------------------------------------

Comment By: Daniel Stenberg (bagder)
Date: 2008-04-24 18:44

Message:
Logged In: YES
user_id=1110
Originator: NO

Any chance you could try creating a test case in the curl test suite that
repeats the problem? Test 154, 155 and 156 all seem to be pretty similar to
your case.

----------------------------------------------------------------------

Comment By: Ben Van Hof (bvanhof)
Date: 2008-04-17 22:19

Message:
Logged In: YES
user_id=2065988
Originator: YES

Basic auth, though from what I've seen it would probably happen with other
auth methods, too.

Ben

----------------------------------------------------------------------

Comment By: Daniel Stenberg (bagder)
Date: 2008-04-17 17:18

Message:
Logged In: YES
user_id=1110
Originator: NO

One important piece of missing info: what authentication(s) does your test
server require?

----------------------------------------------------------------------

You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=100976&aid=1945240&group_id=976
Received on 2008-05-06