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-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-22