Bugs item #1850730, was opened at 2007-12-14 12:13
Message generated for change (Comment added) made by sjasset
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: Spacen Jasset (sjasset)
Date: 2007-12-23 00: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 15: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 13: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 22: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 14: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 11: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 22: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 21: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
Received on 2007-12-23