Bugs item #1850730, was opened at 2007-12-14 13:13
Message generated for change (Comment added) made by bagder
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=100976&aid=1850730&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: bad behaviour
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: Spacen Jasset (sjasset)
Assigned to: Daniel Stenberg (bagder)
Summary: Curl fails to call rewind during digest proxy authentication

Initial Comment:

We are using curl 7.17.0

We try to post 376 bytes to a server, through a squid proxy configured for digest authentication. We find that curl does not call the ioctl rewind function (CURLIOCMD_RESTARTREAD) when it re-tries the post with correct authentication credentials.

This problem may be difficult to reproduce; on some machines it happens rarely, say 1 in 50, on other machines it will happen constantly. This has been seen on Linux and OS X platforms.

We can't as yet see where the problem may lie. Please see the log output below (with comments)

When our rewind function is called, "proto_input_stream::rewind" is seen in the log output; Similarly "proto_input_stream::read" are calls to our read function

 16:43:14 url '192.168.100.204/Discovery/HTTPsvc/IISXferWanServer.DLL' proxy 'test:test_at_vm-fruitbat:3128'

 /* Our data of length 376 */
 16:43:14 proto_input_stream::stream_length - 376
 16:43:14 proto_input_stream::rewind

 16:43:14 CURL: About to connect() to proxy vm-fruitbat port 3128 (#0)
 16:43:14 CURL: Trying 192.168.100.106...
 16:43:14 CURL: connected
 16:43:14 CURL: Connected to vm-fruitbat (192.168.100.106) port 3128 (#0)
 16:43:14 CURL: POST http://192.168.100.204/Discovery/HTTPsvc/IISXferWanServer.DLL HTTP/1.1
 User-Agent: HttpXferwan 10.3.2 (20071123)
 Host: 192.168.100.204
 Pragma: no-cache
 Accept: */*
 Proxy-Connection: Keep-Alive
 Content-Type: application/octet-stream
 Content-Length: 376
 16:43:14 CURL: HTTP 1.0, assume close after body
 16:43:14 CURL: HTTP/1.0 407 Proxy Authentication Required
 16:43:14 CURL: Server: squid/2.6.STABLE14
 16:43:14 CURL: Date: Wed, 12 Dec 2007 16:27:24 GMT
 16:43:14 CURL: Content-Type: text/html
 16:43:14 CURL: Content-Length: 1450
 16:43:14 CURL: Expires: Wed, 12 Dec 2007 16:27:24 GMT
 16:43:14 CURL: X-Squid-Error: ERR_CACHE_ACCESS_DENIED 0
 16:43:14 CURL: Proxy-Authenticate: Digest realm="DIGEST", nonce="7AtgR1grWQiRspYH", qop="auth", stale=false
 16:43:14 CURL: X-Cache: MISS from vm-fruitbat.centennial.co.uk
 16:43:14 CURL: X-Cache-Lookup: NONE from vm-fruitbat.centennial.co.uk:3128
 16:43:14 CURL: Via: 1.0 vm-fruitbat.centennial.co.uk:3128 (squid/2.6.STABLE14)
 16:43:14 CURL: Proxy-Connection: close
 16:43:14 CURL:

 <..html error message...

 /* Our "stream" is read here. Note that there is no rewind called afer these reads. */
 16:43:14 proto_input_stream::read requested 16384 bytes
 16:43:14 proto_input_stream::read satisfied 376 bytes
 16:43:14 proto_input_stream::read requested 16384 bytes
 16:43:14 proto_input_stream::read satisfied 0 bytes

 16:43:14 CURL: Closing connection #0
 16:43:14 CURL: Issue another request to this URL: 'http://192.168.100.204/Discovery/HTTPsvc/IISXferWanServer.DLL'
 16:43:14 CURL: About to connect() to proxy vm-fruitbat port 3128 (#0)
 16:43:14 CURL: Trying 192.168.100.106...
 16:43:14 CURL: connected
 16:43:15 CURL: Connected to vm-fruitbat (192.168.100.106) port 3128 (#0)
 16:43:15 CURL: Proxy auth using Digest with user 'test'
 16:43:15 CURL: POST http://192.168.100.204/Discovery/HTTPsvc/IISXferWanServer.DLL HTTP/1.1
 Proxy-Authorization: Digest username="test", realm="DIGEST", nonce="7AtgR1grWQiRspYH", uri="/Discovery/HTTPsvc/IISXferWanServer.DLL", cnonce="MTE5NzQ3", nc=00000001, qop="auth", response="3b848ddfa0b8761bc5a79e03f32a4da9"
 User-Agent: HttpXferwan 10.3.2 (20071123)
 Host: 192.168.100.204
 Pragma: no-cache
 Accept: */*
 Proxy-Connection: Keep-Alive
 Content-Type: application/octet-stream
 Content-Length: 376

 /* Another read. Since no rewind has taken place it cannot be fulfilled */

 16:43:15 proto_input_stream::read requested 16384 bytes
 16:43:15 proto_input_stream::read satisfied 0 bytes
 16:45:16 CURL: Operation too slow. Less than 1 bytes/sec transfered the last 120 seconds
 16:45:16 CURL: Closing connection #0
 16:45:16 CURL: Timeout was reached
 16:45:16 CURL INFO: Version 'libcurl/7.17.0 06/12/2007 patch level 2 OpenSSL/0.9.7l'
 16:45:16 CURL INFO: CURLINFO_EFFECTIVE_URL http://192.168.100.204/Discovery/HTTPsvc/IISXferWanServer.DLL
 16:45:16 CURL INFO: CURLINFO_RESPONSE_CODE 407
 16:45:16 CURL INFO: CURLINFO_TOTAL_TIME 121.405
 16:45:16 CURL INFO: CURLINFO_NAMELOOKUP_TIME 0.000218
 16:45:16 CURL INFO: CURLINFO_CONNECT_TIME 0.043462
 16:45:16 CURL INFO: CURLINFO_STARTTRANSFER_TIME 0.140539
 16:45:16 CURL INFO: CURLINFO_REDIRECT_TIME 0.204195
 16:45:16 CURL INFO: CURLINFO_SIZE_UPLOAD 0
 16:45:16 CURL INFO: CURLINFO_SIZE_DOWNLOAD 0
 16:45:16 CURL INFO: CURLINFO_SPEED_DOWNLOAD 0 B/s
 16:45:16 CURL INFO: CURLINFO_SPEED_UPLOAD 0 B/s
 16:45:16 CURL INFO: CURLINFO_CONTENT_TYPE text/html
 16:45:16 CURL INFO: CURLINFO_PROXYAUTH_AVAIL 0x2 (DIGEST)
 16:45:16 CURL INFO: CURLINFO_NUM_CONNECTS 2
 16:45:16 CURL: transaction result status 28 (Timeout was reached)

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

>Comment By: Daniel Stenberg (bagder)
Date: 2008-01-07 20:34

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

We're setting CURLOPT_POSTFIELDSIZE, so data->set.postfieldsize will be
non-zero and thus so should the local variable 'postsize' be at the point I
was talking about in my previous post.

It seems you're not using the CVS version as there's no code on
http.c:2616. The code you seem to talk about is on line 2628 now...

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

Comment By: Spacen Jasset (sjasset)
Date: 2008-01-07 15:06

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

Here is my debug session. Since we aren't calling CURLOPT_POSTFIELDS will
data->set.postfields ever be set?

(gdb) run
The program being debugged has been started already.
Start it from the beginning? (y or n) y

Starting program: /home/user/curl/tests/libtest/.libs/lt-lib552
http://test.remote.server.com/path/552 http://s1lly:pers0n@127.0.0.1:8990/
Error in re-setting breakpoint 2:
No source file named http.c.
Breakpoint 2 at 0xb7f11ca6: file http.c, line 2616.
URL: http://test.remote.server.com/path/552
== Info: About to connect() to proxy 127.0.0.1 port 8990 (#0)
== Info: Trying 127.0.0.1... == Info: connected
== Info: Connected to 127.0.0.1 (127.0.0.1) port 8990 (#0)

Breakpoint 2, Curl_http (conn=0x80637d0, done=0xbfa1f176) at http.c:2616
2616 if(data->set.postfields) {
(gdb) print data->set.postfields
$2 = (void *) 0x0
(gdb) next
2682 result = add_buffer(req_buffer, "\r\n", 2); /* end of
headers! */

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

Comment By: Daniel Stenberg (bagder)
Date: 2008-01-07 13:38

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

I want to remain focused on creating a test case with the test suite that
can repeat your problems, and while identical files in the suite cause
different test results it indicates something wrong so I think we should
first make the existing test cases work the same for both of us.

In the test case 552 it sends 70000 bytes in a POST. At lib/http.c:2621,
libcurl _should_ call expect100() for this test case. Failing to do so
certainly indicates something terribly wrong internally and this problem
could very well lead to all sorts of funny side-effects.

Can you set a break-point on http.c:2620 for test case 552 and see why the
condition doesn't equal true?

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

Comment By: Spacen Jasset (sjasset)
Date: 2008-01-07 13:01

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

I have tried breakpointing the expect100 continue message. The function
does not get called.

This is odd, and you are right in that the test case does call rewind. Why
the case fails on my system I don't know. I have not debugged though to
trace the continue100 behaviour, as it's not something I get using curl
with a real sever. I realise we should focus on one thing at a time. I will
have a look at this 100 continue business, but I am unclear as to how it's
supposed to work. Presumably the expect message is not *required*, and it a
convenience to to cut short large post requests that may fail at the first
hurdle?

I have prepared a squid proxy server on the internet, that, if you are
willing can be used to reproduce the problem I initially reported. Here is
the line to change in the test552 script.

root_at_vm-fruitbat:~/curl/tests/data# diff -a test552.orig test552
61c61
< http://test.remote.server.com/path/552
http://s1lly:pers0n@%HOSTIP:%HTTPPORT/

---
> http://jason.spashett.com/cgi-bin/var.cgi
http://test:test@ionrift.ath.cx:8080
----------------------------------------------------------------------
Comment By: Daniel Stenberg (bagder)
Date: 2007-12-28 22:37
Message:
Logged In: YES 
user_id=1110
Originator: NO
Very interesting.
But what's most interesting perhaps, is that the rewinding is done for you
as the "stdout552" file shows in your tarball. So in fact, the POST
operation is successful over the proxy doing Digest.
What fails, is that your version of the lib552 client somehow doesn't send
"Expect: 100-continue" in the request headers, and thus the comparison
fails. I don't understand why!
If you run the single test case with "./runtests.pl -g 552" you can set a
break-point in lib/http.c:expect100() or possibly lib/http.c:2385 to see if
you can understand why you don't get that header added in the request!
----------------------------------------------------------------------
Comment By: Spacen Jasset (sjasset)
Date: 2007-12-28 15:21
Message:
Logged In: YES 
user_id=1400532
Originator: YES
I just ran test 552 and it failed on this system. 552_log_dir.tar.gz has
been attached.
root_at_vm-fruitbat:~/curl/tests# ./runtests.pl 552
********* System characteristics ********
* curl 7.17.2-CVS (i686-pc-linux-gnu)
* libcurl/7.17.2-CVS zlib/1.2.3.3
* Features: IPv6 Largefile libz
* Host: vm-fruitbat
* System: Linux vm-fruitbat 2.6.22-14-generic #1 SMP Sun Oct 14 23:05:12
GMT 2007 i686 GNU/Linux
* Server SSL:     OFF
* libcurl SSL:    OFF
* libcurl debug:  OFF
* valgrind:       ON
* HTTP IPv6       ON
* FTP IPv6        ON
* HTTP port:      8990
* FTP port:       8992
* FTP port 2:     8995
* HTTP IPv6 port: 8994
* FTP IPv6 port:  8996
* TFTP port:      8997
* SCP/SFTP port:  8999
* SOCKS port:     9000
* Libtool lib:    OFF
*****************************************
test 552...[HTTP proxy auth Digest with 70K POST data from read callback]
 protocol FAILED:
Binary files log/check-expected and log/check-generated differ
 - abort tests
TESTDONE: 0 tests out of 1 reported OK: 0%
TESTFAIL: These test cases failed: 552
TESTDONE: 1 tests were considered during 7 seconds.
File Added: 552_log_dir.tar.gz
----------------------------------------------------------------------
Comment By: Daniel Stenberg (bagder)
Date: 2007-12-26 23:29
Message:
Logged In: YES 
user_id=1110
Originator: NO
I've now committed test case 552 which tests this, see the
tests/libtest/lib552.c file for the exact source code - based on your test
case.
----------------------------------------------------------------------
Comment By: Daniel Stenberg (bagder)
Date: 2007-12-25 23:56
Message:
Logged In: YES 
user_id=1110
Originator: NO
Ok, in my case the rewinding is done in the following way. It would be
good to see if you could set a break-point in a suitable place and check
why your example doesn't do this same thing!
(backtrace from the ioctl callback)
#0  ioctl_callback (handle=0x80b99ac, cmd=1, clientp=0x0) at lib552.c:143
#1  0x080623b5 in Curl_readrewind (conn=0x80cb5e4) at transfer.c:243
#2  0x0807dc34 in perhapsrewind (conn=0x80cb5e4) at http.c:344
#3  0x0807de20 in Curl_http_auth_act (conn=0x80cb5e4) at http.c:393
#4  0x0806316c in Curl_readwrite (conn=0x80cb5e4, done=0xbff203a3)
    at transfer.c:648
#5  0x08065814 in Transfer (conn=0x80cb5e4) at transfer.c:1773
#6  0x0806637d in Curl_perform (data=0x80b99ac) at transfer.c:2343
#7  0x0804f732 in curl_easy_perform (curl=0x80b99ac) at easy.c:498
And to clarify the process in English:
In Curl_readwrite() it fins the auth stuff and calls
Curl_http_auth_act().
In Curl_http_auth_act() it continues all the way down to line 393 where it
calls perhapsrewind()
and then in perhapsrewind() it sees that it really sent a lot of data so
on http.c:344 it calls Curl_readrewind...
----------------------------------------------------------------------
Comment By: Spacen Jasset (sjasset)
Date: 2007-12-23 01:11
Message:
Logged In: YES 
user_id=1400532
Originator: YES
I have tried it with the latest cvs version and I have attached another
log. The same thing happens. I have also included a fprintf when rewind is
called (previously it was a printf) The rewind isn't called according to my
output.
At the top of the log: Curl version: libcurl/7.17.2-CVS OpenSSL/0.9.8e
zlib/1.2.3.3 libidn/1.0
I have run the unit tests with the lastest cvs version, and they all
pass:
TESTDONE: 333 tests out of 333 reported OK: 100%
TESTDONE: 412 tests were considered during 739 seconds.
TESTINFO: 79 tests were skipped due to these restraints:
TESTINFO: "curl lacks any scp support" 4 times (601, 603, 605, 607)
TESTINFO: "curl lacks SSL support" 22 times (94, 183, 184, 185, 300, 301,
302, 303, 304, 305, 306, 400, 401, 402, 403, 404, 405, 406, 407, 408, 409,
509)
TESTINFO: "curl lacks any sftp support" 13 times (600, 602, 604, 606, 608,
609, 610, 611, 612, 613, 614, 615, 2004)
TESTINFO: "rlimit problem: fds needed 1050 > system limit 1024" 1 times
(518)
TESTINFO: "curl lacks netrc_debug support" 6 times (130, 131, 132, 133,
134, 257)
TESTINFO: "curl lacks OpenSSL support" 2 times (307, 308)
TESTINFO: "failed starting SSH server" 6 times (700, 701, 702, 703, 706,
707)
TESTINFO: "curl lacks idn support" 1 times (165)
TESTINFO: "curl lacks NTLM support" 24 times (67, 68, 69, 70, 81, 89, 90,
91, 150, 155, 159, 162, 169, 170, 176, 209, 213, 239, 243, 265, 267, 547,
548, 1008)
File Added: 1850730_cvs_latest.log
----------------------------------------------------------------------
Comment By: Daniel Stenberg (bagder)
Date: 2007-12-22 16:01
Message:
Logged In: YES 
user_id=1110
Originator: NO
Ok, then I must urge you to retry this with a recent CVS/daily snapshot
version, since that is just about the exact thing I get with my tests and
my tests work fine.
You could also make sure the debug outputs in the ioctl() rewind action
gets sent to stderr as then you should see that the stream is indeed
rewinded at the end of the first post. At least it is for me.
----------------------------------------------------------------------
Comment By: Spacen Jasset (sjasset)
Date: 2007-12-22 14:34
Message:
Logged In: YES 
user_id=1400532
Originator: YES
Please find attached a debug log from curl using squid as a proxy.
File Added: 1850730_through_squid.log
----------------------------------------------------------------------
Comment By: Daniel Stenberg (bagder)
Date: 2007-12-21 23:01
Message:
Logged In: YES 
user_id=1110
Originator: NO
I have no desire to get, install and configure squid to get a digest-proxy
just for testing this. It is a lot easier if you'd simply provide the
detailed log your own test program provides. Please?
I created a test case with your code exactly, and it behaves just fine
with the test suite's digest proxy so there's clearly something different
between that and the squid (config) you use!
----------------------------------------------------------------------
Comment By: Spacen Jasset (sjasset)
Date: 2007-12-21 15:33
Message:
Logged In: YES 
user_id=1400532
Originator: YES
Please see attached tar file containing source code to reproduce problem.
We are using a squid proxy (Version 2.6.STABLE14) with digest auth
enabled. Our test program has been run on ubuntu 7.10, but the problem is
not specific to this platform. 
run the program with a proxy as an argument:
./debug test:test_at_vm-fruitbat:3128  2>&1 | tee out
The program should hang forever when it retries the request with proper
authentication credentials. 
File Added: 1850730.tar.gz
----------------------------------------------------------------------
Comment By: Spacen Jasset (sjasset)
Date: 2007-12-19 12:48
Message:
Logged In: YES 
user_id=1400532
Originator: YES
Our application is using curl more or less like that posted. I have not
had the chance to reproduce this yet, but will do so when I can get around
to it. Our temporary fix is working for us at the moment.
----------------------------------------------------------------------
Comment By: Daniel Stenberg (bagder)
Date: 2007-12-15 23:14
Message:
Logged In: YES 
user_id=1110
Originator: NO
Anyway, in an attempt to reproduce this report I wrote up and committed
test case 551, although it seems to do what it should...
----------------------------------------------------------------------
Comment By: Daniel Stenberg (bagder)
Date: 2007-12-15 22:39
Message:
Logged In: YES 
user_id=1110
Originator: NO
And your application is more or less like this:
http://curl.haxx.se/lxr/source/tests/libtest/lib547.c
?
----------------------------------------------------------------------
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=100976&aid=1850730&group_id=976