Bugs item #1879375, was opened at 2008-01-25 03:10
Message generated for change (Comment added) made by bagder
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=100976&aid=1879375&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: https
Group: wrong behaviour
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: Kevin Reed (knreed)
Assigned to: Daniel Stenberg (bagder)
Summary: CONNECT with NTLM auth when proxy closes f

Initial Comment:
On December 5 there is the following fix reported:

-----------------------------------------------------
Daniel S (5 Dec 2007)
- Spacen Jasset reported a problem with doing POST (with data read with a callback) over a proxy when NTLM is used as auth with the proxy. The bug also concerned Digest and was limited to using callback only. Spacen worked with us to provide a useful patch. I added the test case 547 and 548 to verify two variations of POST over proxy with NTLM.
-----------------------------------------------------

We have a situation that matches this very closely. And in fact when testing with the CVS snapshot from Jan 20th it is fixed (Great work!). However, we found that it does not work correctly when using https. I suspect that if test cases 547 and 548 were run using https instead of http you would see what our applications are seeing.

Here is the output from our application:

1/24/2008 7:52:58 PM||Libraries: libcurl/7.18.0-20080120 OpenSSL/0.9.8g zlib/1.2.3
1/24/2008 8:04:25 PM|World Community Grid|Sending scheduler request: Requested by user. Requesting 0 seconds of work, reporting 2 completed tasks
1/24/2008 8:04:25 PM||[http_debug] HTTP_OP::init_post(): https://secure.worldcommunitygrid.org/boinc/wcg_cgi/fcgi
1/24/2008 8:04:25 PM||[http_debug] [ID#127] info: About to connect() to proxy www.romwnet.org port 8080 (#1)
1/24/2008 8:04:25 PM||[http_debug] [ID#127] info: Trying 75.144.221.229...
1/24/2008 8:04:26 PM||[http_debug] [ID#127] info: Connected to www.romwnet.org (75.144.221.229) port 8080 (#1)
1/24/2008 8:04:26 PM||[http_debug] [ID#127] info: Establish HTTP proxy tunnel to secure.worldcommunitygrid.org:443
1/24/2008 8:04:26 PM||[http_debug] [ID#127] Sent header to server: CONNECT secure.worldcommunitygrid.org:443 HTTP/1.0
Host: secure.worldcommunitygrid.org:443
User-Agent: BOINC client (windows_intelx86 5.10.38)
Proxy-Connection: Keep-Alive

1/24/2008 8:04:26 PM||[http_debug] [ID#127] Received header from server: HTTP/1.1 407 Proxy Authentication Required

1/24/2008 8:04:26 PM||[http_debug] [ID#127] Received header from server: Server: FreeProxy/4.0

1/24/2008 8:04:26 PM||[http_debug] [ID#127] Received header from server: Date: Fri, 25 Jan 2008 02:04:29 GMT

1/24/2008 8:04:26 PM||[http_debug] [ID#127] Received header from server: Content-Type: text/html

1/24/2008 8:04:26 PM||[http_debug] [ID#127] Received header from server: Transfer-Encoding: Chunked

1/24/2008 8:04:26 PM||[http_debug] [ID#127] info: CONNECT responded chunked
1/24/2008 8:04:26 PM||[http_debug] [ID#127] Received header from server: Proxy-Authenticate: NTLM

1/24/2008 8:04:26 PM||[http_debug] [ID#127] Received header from server: Proxy-Authenticate: Basic realm="ROMWNET"

1/24/2008 8:04:26 PM||[http_debug] [ID#127] Received header from server: Proxy-Connection: Close

1/24/2008 8:04:26 PM||[http_debug] [ID#127] Received header from server:

1/24/2008 8:04:26 PM||[http_debug] [ID#127] info: 1 bytes of chunk left
1/24/2008 8:04:26 PM||[http_debug] [ID#127] info: Read 0 bytes of chunk, continue
1/24/2008 8:04:26 PM||[http_debug] [ID#127] info: Read 1455 bytes of chunk, continue
1/24/2008 8:04:26 PM||[http_debug] [ID#127] info: Read 567 bytes of chunk, continue
1/24/2008 8:04:26 PM||[http_debug] [ID#127] info: Read 0 bytes of chunk, continue
1/24/2008 8:04:26 PM||[http_debug] [ID#127] info: chunk reading DONE
1/24/2008 8:04:26 PM||[http_debug] [ID#127] info: Received HTTP code 407 from proxy after CONNECT
1/24/2008 8:04:26 PM||[http_debug] HTTP error: Failure when receiving data from the peer
1/24/2008 8:04:26 PM||[http_debug] [ID#127] info: Expire cleared
1/24/2008 8:04:26 PM||[http_debug] [ID#127] info: Connection #1 to host www.romwnet.org left intact
1/24/2008 8:04:27 PM||Project communication failed: attempting access to reference site

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

>Comment By: Daniel Stenberg (bagder)
Date: 2008-01-26 12:05

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

Thanks for the further details and analysis. This just proves my previous
fix wasn't good enough, but I did write up test case 1021 that repeated a
problem that I fixed there (but yeah the test case obviously wasn't
covering your case closely enough)... As you possibly didn't see, is that I
committed the fix I mentioned previously so this is now already in current
CVS/snapshots.

I do have a hard time trying to repeat your problem with the use of the
curl test suite, can you please have a look at the attached test1022 file
and see if you can make this fail like your real-world case does? You can
run single the single test in the test suite like this:

$ cd tests
$ ./runtests.pl 1022

Regarding the closeConnection set TRUE, it should bail out from the loop
yes but below the loop it should check for
(closeConnection && data->req.newurl) and that should equal true and thus
a parent function _should_ call this function again...
File Added: test1022

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

Comment By: Kevin Reed (knreed)
Date: 2008-01-26 06:24

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

Daniel,

I don't know if this helps any since I am only beginning to look at the
source code. However, I found that the application was not reaching your
modified code because in this segment of http.c

                  else if(Curl_compareheader(line_start,
                                             "Proxy-Connection:",
"close")) {
                     closeConnection = TRUE;

The closeConnection flag was getting set to TRUE which caused it to exit
the loop on the first pass.

I commented out that line to see what happens if it passed it and I then
got the following output:

1/25/2008 11:08:13 PM|World Community Grid|Sending scheduler request:
Requested by user. Requesting 17280 seconds of work, reporting 0 completed
tasks
1/25/2008 11:08:13 PM||[http_debug] HTTP_OP::init_post():
https://secure.worldcommunitygrid.org/boinc/wcg_cgi/fcgi
1/25/2008 11:08:13 PM||[http_debug] [ID#0] info: STATE: INIT => CONNECT
handle 0xc96248; (connection #-5000)
1/25/2008 11:08:13 PM||[http_debug] [ID#0] info: STATE: CONNECT =>
WAITRESOLVE handle 0xc96248; (connection #0)
1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: About to connect() to
proxy www.romwnet.org port 8080 (#0)
1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: Trying
75.144.221.229...
1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: STATE: WAITRESOLVE =>
WAITCONNECT handle 0xc96248; (connection #0)
1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: Connected to
www.romwnet.org (75.144.221.229) port 8080 (#0)
1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: Establish HTTP proxy
tunnel to secure.worldcommunitygrid.org:443
1/25/2008 11:08:14 PM||[http_debug] [ID#0] Sent header to server: CONNECT
secure.worldcommunitygrid.org:443 HTTP/1.0
Host: secure.worldcommunitygrid.org:443
User-Agent: BOINC client (windows_intelx86 5.10.38)
Proxy-Connection: Keep-Alive
Content-Type: application/x-www-form-urlencoded

1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: STATE: WAITCONNECT =>
WAITPROXYCONNECT handle 0xc96248; (connection #0)
1/25/2008 11:08:14 PM||[http_debug] [ID#0] Received header from server:
HTTP/1.1 407 Proxy Authentication Required

1/25/2008 11:08:14 PM||[http_debug] [ID#0] Received header from server:
Server: FreeProxy/4.0

1/25/2008 11:08:14 PM||[http_debug] [ID#0] Received header from server:
Date: Sat, 26 Jan 2008 05:08:20 GMT

1/25/2008 11:08:14 PM||[http_debug] [ID#0] Received header from server:
Content-Type: text/html

1/25/2008 11:08:14 PM||[http_debug] [ID#0] Received header from server:
Transfer-Encoding: Chunked

1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: CONNECT responded
chunked
1/25/2008 11:08:14 PM||[http_debug] [ID#0] Received header from server:
Proxy-Authenticate: NTLM

1/25/2008 11:08:14 PM||[http_debug] [ID#0] Received header from server:
Proxy-Authenticate: Basic realm="ROMWNET"

1/25/2008 11:08:14 PM||[http_debug] [ID#0] Received header from server:
Proxy-Connection: Close

1/25/2008 11:08:14 PM||[http_debug] [ID#0] Received header from server:

1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: 2028 bytes of chunk left
1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: Read 2022 bytes of chunk,
continue
1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: chunk reading DONE
1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: KEVIN - Loop
1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: Establish HTTP proxy
tunnel to secure.worldcommunitygrid.org:443
1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: Proxy auth using NTLM
with user 'romwnet\knreed'
1/25/2008 11:08:14 PM||[http_debug] [ID#0] Sent header to server: CONNECT
secure.worldcommunitygrid.org:443 HTTP/1.0
Host: secure.worldcommunitygrid.org:443
Proxy-Authorization: NTLM TlRMTVNTUAABAAAABoIIAAAAAAAAAAAAAAAAAAAAAAA=
User-Agent: BOINC client (windows_intelx86 5.10.38)
Proxy-Connection: Keep-Alive
Content-Type: application/x-www-form-urlencoded

1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: Proxy CONNECT aborted
1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: STATE: WAITPROXYCONNECT
=> COMPLETED handle 0xc96248; (connection #-5000)
1/25/2008 11:08:14 PM||[http_debug] HTTP error: Failure when receiving
data from the peer
1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: Expire cleared
1/25/2008 11:08:14 PM||[http_debug] [ID#0] info: Connection #0 to host
www.romwnet.org left intact
1/25/2008 11:08:19 PM|World Community Grid|Scheduler request failed:
Failure when receiving data from the peer

Let me know if there is more information that I can provide.

thanks.

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

Comment By: Kevin Reed (knreed)
Date: 2008-01-26 04:28

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

Here is what I got after applying your patch the 7.18.0-20080120 snapshot
(let me know if you would rather that I update to the latest CVS snapshot
to test from).

1/25/2008 9:16:12 PM|World Community Grid|Sending scheduler request:
Project initialization. Requesting 1 seconds of work, reporting 0
completed tasks
1/25/2008 9:16:12 PM||[http_debug] HTTP_OP::init_post():
https://secure.worldcommunitygrid.org/boinc/wcg_cgi/fcgi
1/25/2008 9:16:13 PM||[http_debug] [ID#0] info: About to connect() to
proxy www.romwnet.org port 8080 (#0)
1/25/2008 9:16:13 PM||[http_debug] [ID#0] info: Trying 75.144.221.229...

1/25/2008 9:16:17 PM||[http_debug] [ID#0] info: Connected to
www.romwnet.org (75.144.221.229) port 8080 (#0)
1/25/2008 9:16:17 PM||[http_debug] [ID#0] info: Establish HTTP proxy
tunnel to secure.worldcommunitygrid.org:443
1/25/2008 9:16:17 PM||[http_debug] [ID#0] Sent header to server: CONNECT
secure.worldcommunitygrid.org:443 HTTP/1.0
Host: secure.worldcommunitygrid.org:443
User-Agent: BOINC client (windows_intelx86 5.10.38)
Proxy-Connection: Keep-Alive
Content-Type: application/x-www-form-urlencoded

1/25/2008 9:16:17 PM||[http_debug] [ID#0] Received header from server:
HTTP/1.1 407 Proxy Authentication Required

1/25/2008 9:16:17 PM||[http_debug] [ID#0] Received header from server:
Server: FreeProxy/4.0

1/25/2008 9:16:17 PM||[http_debug] [ID#0] Received header from server:
Date: Sat, 26 Jan 2008 03:16:23 GMT

1/25/2008 9:16:17 PM||[http_debug] [ID#0] Received header from server:
Content-Type: text/html

1/25/2008 9:16:17 PM||[http_debug] [ID#0] Received header from server:
Transfer-Encoding: Chunked

1/25/2008 9:16:17 PM||[http_debug] [ID#0] info: CONNECT responded chunked
1/25/2008 9:16:17 PM||[http_debug] [ID#0] Received header from server:
Proxy-Authenticate: NTLM

1/25/2008 9:16:17 PM||[http_debug] [ID#0] Received header from server:
Proxy-Authenticate: Basic realm="ROMWNET"

1/25/2008 9:16:17 PM||[http_debug] [ID#0] Received header from server:
Proxy-Connection: Close

1/25/2008 9:16:17 PM||[http_debug] [ID#0] Received header from server:

1/25/2008 9:16:17 PM||[http_debug] [ID#0] info: 1461 bytes of chunk left
1/25/2008 9:16:17 PM||[http_debug] [ID#0] info: Read 1455 bytes of chunk,
continue
1/25/2008 9:16:17 PM||[http_debug] [ID#0] info: Read 567 bytes of chunk,
continue
1/25/2008 9:16:17 PM||[http_debug] [ID#0] info: chunk reading DONE
1/25/2008 9:16:17 PM||[http_debug] [ID#0] info: Received HTTP code 407
from proxy after CONNECT
1/25/2008 9:16:17 PM||[http_debug] HTTP error: Failure when receiving data
from the peer
1/25/2008 9:16:17 PM||[http_debug] [ID#0] info: Expire cleared
1/25/2008 9:16:17 PM||[http_debug] [ID#0] info: Connection #0 to host
www.romwnet.org left intact

Which shows the problem still there. I ran the request through a tcp/ip
monitor to see the headers and this is what I saw:

The request:

CONNECT secure.worldcommunitygrid.org:443 HTTP/1.0
Host: secure.worldcommunitygrid.org:443
User-Agent: BOINC client (windows_intelx86 5.10.38)
Proxy-Connection: Keep-Alive
Content-Type: application/x-www-form-urlencoded

And the response:

HTTP/1.1 407 Proxy Authentication Required
Server: FreeProxy/4.0
Date: Sat, 26 Jan 2008 03:27:34 GMT
Content-Type: text/html
Transfer-Encoding: Chunked
Proxy-Authenticate: NTLM
Proxy-Authenticate: Basic realm="ROMWNET"
Proxy-Connection: Close

7E6

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

Comment By: Daniel Stenberg (bagder)
Date: 2008-01-26 00:22

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

I've written a test case (1021) that repeats the problem as I've
identified it, and with the attached patch I fixed the problem and it runs
fine.

I'd be happy if you could apply it and test if it fixes the problem in
your case as well!
File Added: proxy-connect-close.patch

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

Comment By: Daniel Stenberg (bagder)
Date: 2008-01-25 23:46

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

The bug is simply that the Curl_proxyCONNECT() function doesn't properly
deal with the fact that the proxy closes the connection to the proxy after
the first response.

I'm looking at doing a fix.

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

Comment By: Kevin Reed (knreed)
Date: 2008-01-25 16:15

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

Your question made me wonder what happens if I force the proxy auth to be
NTLM. I changed this line:

curlErr = curl_easy_setopt(curlEasy, CURLOPT_PROXYAUTH, CURLAUTH_ANY);

to

curlErr = curl_easy_setopt(curlEasy, CURLOPT_PROXYAUTH, CURLAUTH_NTLM);

to see if forcing the NTLM bit would work. With the NTLM bit forced it
works great. However, we are deploying this to an environment where the
proxy type is not known so we need to be able to set CURLAUTH_ANY.

thanks

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

Comment By: Kevin Reed (knreed)
Date: 2008-01-25 16:03

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

Thank you for taking a look at this so quickly. Here is the code that is
used to set the curl options. This code sets it up and it works (with the
fix from Dec 5) great for posts that use http. However, when using https
it fails.

    curlEasy = curl_easy_init(); // get a curl_easy handle to use
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_URL, m_url);
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_SSL_VERIFYHOST, 2L);
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_SSL_VERIFYPEER, 1L);
    if (boinc_file_exists(CA_BUNDLE_FILENAME)) {
        // call this only if a local copy of ca-bundle.crt exists;
        // otherwise, let's hope that it exists in the default place
        //
        curlErr = curl_easy_setopt(curlEasy, CURLOPT_CAINFO,
CA_BUNDLE_FILENAME);
    }

    // set the user agent as this boinc client & version
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_USERAGENT,
g_user_agent_string);

    // bypass any signal handlers that curl may want to install
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_NOSIGNAL, 1L);
    // bypass progress meter
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_NOPROGRESS, 1L);

    // setup timeouts
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_TIMEOUT, 0L);
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_LOW_SPEED_LIMIT, 10L);
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_LOW_SPEED_TIME, 300L);
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_CONNECTTIMEOUT, 120L);
    
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_MAXREDIRS, 50L);
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_AUTOREFERER, 1L);
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_FOLLOWLOCATION, 1L);

    // if we tell Curl to accept any encoding (e.g. deflate)
    // it seems to accept them all, which screws up projects that
    // use gzip at the application level.
    // So, detect this and don't accept any encoding in that case
    //
    if (!out || !ends_with(std::string(out), std::string(".gz"))) {
        curlErr = curl_easy_setopt(curlEasy, CURLOPT_ENCODING, "");
    }

    // setup a basic http proxy
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_PROXYTYPE,
CURLPROXY_HTTP);
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_PROXYPORT, (long)
pi.http_server_port);
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_PROXY, (char*)
pi.http_server_name);

        curlErr = curl_easy_setopt(curlEasy, CURLOPT_PROXYAUTH, CURLAUTH_ANY);
    sprintf(szCurlProxyUserPwd, "%s:%s", pi.http_user_name,
pi.http_user_passwd);
    curlErr = curl_easy_setopt(curlEasy, CURLOPT_PROXYUSERPWD,
szCurlProxyUserPwd);

    static const char g_content_type[] = {"Content-Type:
application/x-www-form-urlencoded"};
    pcurlList = curl_slist_append(pcurlList, g_content_type);

   curlErr = curl_easy_setopt(curlEasy, CURLOPT_WRITEFUNCTION,
libcurl_write);
   curlErr = curl_easy_setopt(curlEasy, CURLOPT_WRITEDATA, this);

   curl_off_t fs = (curl_off_t) content_length;

   pByte = NULL;
   lSeek = 0; // initialize the vars we're going to use for byte
transfers

   // CMC Note: we can make the libcurl_read "fancier" in the future,
   // for now it just fwrite's to the file request, which is sufficient
   curlErr = curl_easy_setopt(curlEasy, CURLOPT_POSTFIELDS, NULL);
   curlErr = curl_easy_setopt(curlEasy, CURLOPT_POSTFIELDSIZE_LARGE, fs);
   curlErr = curl_easy_setopt(curlEasy, CURLOPT_READFUNCTION,
libcurl_read);
   curlErr = curl_easy_setopt(curlEasy, CURLOPT_READDATA, this);

   // callback function to rewind input file
   curlErr = curl_easy_setopt(curlEasy, CURLOPT_IOCTLFUNCTION,
libcurl_ioctl);
   curlErr = curl_easy_setopt(curlEasy, CURLOPT_IOCTLDATA, this);

   curlErr = curl_easy_setopt(curlEasy, CURLOPT_POST, 1L);

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

Comment By: Daniel Stenberg (bagder)
Date: 2008-01-25 13:08

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

And CURLOPT_PROXYUSERPWD is set to something and CURLOPT_PROXYAUTH
includes the CURLAUTH_NTLM bit?

This output looks like libcurl simply doesn't trigger a remade request
with the authentication and thus it exits the loop and returns error since
it fails to go through the proxy.

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

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