Forum Discussion

klauern's avatar
klauern
Contributor
12 years ago

No NTLM Re-Negotiation when following HTTP 303 See Other URL

Hello,

I see that when using NTLM based authentication for a request, I get an HTTP 303 (See Other). In the logs, I can tell that it is doing the right NTLM negotiation when making the initial request, but once it gets that HTTP 303, it then just blindly follows the new URL, without going or even passing along the WWW-Authenticate handshaking again.

I'm pasting a slightly modified http log to avoid sharing too much secure information.

Thu May 29 11:36:00 CDT 2014:DEBUG:>> "GET /WHATEVER/outputFormat/report/i1B82A9D79BC044D2BB7077CE86AEA1A6/PDF?p_requestid=10 HTTP/1.1[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "Accept-Encoding: gzip,deflate[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "Host: WHATEVER-SERVER.com:443[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "Connection: Keep-Alive[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "User-Agent: Apache-HttpClient/4.1.1 (java 1.5)[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "HTTP/1.1 401 Unauthorized[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "Content-Type: text/html[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "Server: Microsoft-IIS/7.5[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "WWW-Authenticate: Negotiate[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "WWW-Authenticate: NTLM[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "X-Powered-By: ASP.NET[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "Date: Thu, 29 May 2014 16:36:00 GMT[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "Content-Length: 1293[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Strict//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<html xmlns="http://www.w3.org/1999/xhtml">[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<head>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<meta http-equiv="Content-Type" content="text/html; charset=iso-8859-1"/>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<title>401 - Unauthorized: Access is denied due to invalid credentials.</title>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<style type="text/css">[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<!--[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "body{margin:0;font-size:.7em;font-family:Verdana, Arial, Helvetica, sans-serif;background:#EEEEEE;}[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "fieldset{padding:0 15px 10px 15px;} [\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "h1{font-size:2.4em;margin:0;color:#FFF;}[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "h2{font-size:1.7em;margin:0;color:#CC0000;} [\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "h3{font-size:1.2em;margin:10px 0 0 0;color:#000000;} [\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "#header{width:96%;margin:0 0 0 0;padding:6px 2% 6px 2%;font-family:"trebuchet MS", Verdana, sans-serif;color:#FFF;[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "background-color:#555555;}[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "#content{margin:0 0 0 2%;position:relative;}[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< ".content-container{background:#FFF;width:96%;margin-top:8px;padding:10px;position:relative;}[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "-->[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "</style>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "</head>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<body>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<div id="header"><h1>Server Error</h1></div>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<div id="content">[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< " <div class="content-container"><fieldset>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "  <h2>401 - Unauthorized: Access is denied due to invalid credentials.</h2>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "  <h3>You do not have permission to view this directory or page using the c"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "redentials that you supplied.</h3>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< " </fieldset></div>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "</div>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "</body>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "</html>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "GET /WHATEVER/outputFormat/report/i1B82A9D79BC044D2BB7077CE86AEA1A6/PDF?p_requestid=10 HTTP/1.1[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "Accept-Encoding: gzip,deflate[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "Host: WHATEVER-SERVER.com:443[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "Connection: Keep-Alive[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "User-Agent: Apache-HttpClient/4.1.1 (java 1.5)[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "Authorization: NTLM XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX==[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "HTTP/1.1 401 Unauthorized[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "Content-Type: text/html; charset=us-ascii[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "Server: Microsoft-HTTPAPI/2.0[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "WWW-Authenticate: NTLM <SNIPPING OUT AUTHENTICATION INFO.....> [\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "Date: Thu, 29 May 2014 16:36:00 GMT[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "Content-Length: 341[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01//EN""http://www.w3.org/TR/html4/strict.dtd">[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<HTML><HEAD><TITLE>Not Authorized</TITLE>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<META HTTP-EQUIV="Content-Type" Content="text/html; charset=us-ascii"></HEAD>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<BODY><h2>Not Authorized</h2>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "<hr><p>HTTP Error 401. The requested resource requires user authentication.</p>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:<< "</BODY></HTML>[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "GET /WHATEVER/outputFormat/report/i1B82A9D79BC044D2BB7077CE86AEA1A6/PDF?p_requestid=10 HTTP/1.1[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "Accept-Encoding: gzip,deflate[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "Host: WHATEVER-SERVER.com:443[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "Connection: Keep-Alive[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "User-Agent: Apache-HttpClient/4.1.1 (java 1.5)[\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "Authorization: NTLM <SNIPPING AUTHENTICATION INFORMATION......> [\r][\n]"
Thu May 29 11:36:00 CDT 2014:DEBUG:>> "[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "HTTP/1.1 303 See Other[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "Content-Type: text/xml;charset=UTF-8[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "Location: ../../../../sessionOutput/conversationID/iDEB1206646FC4ADEAD705E51F563F0E5[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "Server: Microsoft-IIS/7.5[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "set-cookie: .............................[\r][\n]"  // I'm snipping out all of this, but it sets a bunch of cookies for the application server I connect to
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "set-cookie: .............................[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "set-cookie: .............................[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "set-cookie: .............................[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "set-cookie: .............................[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "zipi.step: 0[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "Persistent-Auth: true[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "X-Powered-By: ASP.NET[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "Date: Thu, 29 May 2014 16:36:01 GMT[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "Connection: close[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "Content-Length: 290[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:>> "GET /WHATEVER/sessionOutput/conversationID/iDEB1206646FC4ADEAD705E51F563F0E5 HTTP/1.1[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:>> "Host: WHATEVER-SERVER.com:443[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:>> "Connection: Keep-Alive[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:>> "User-Agent: Apache-HttpClient/4.1.1 (java 1.5)[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:>> "Cookie: .............................................[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:>> "Cookie2: $Version=1[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:>> "[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "HTTP/1.1 401 Unauthorized[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "Content-Type: text/html[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "Server: Microsoft-IIS/7.5[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "WWW-Authenticate: Negotiate[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "WWW-Authenticate: NTLM[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "X-Powered-By: ASP.NET[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "Date: Thu, 29 May 2014 16:36:01 GMT[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "Content-Length: 1293[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Strict//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "<html xmlns="http://www.w3.org/1999/xhtml">[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "<head>[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "<meta http-equiv="Content-Type" content="text/html; charset=iso-8859-1"/>[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "<title>401 - Unauthorized: Access is denied due to invalid credentials.</title>[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "<style type="text/css">[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "<!--[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "body{margin:0;font-size:.7em;font-family:Verdana, Arial, Helvetica, sans-serif;background:#EEEEEE;}[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "fieldset{padding:0 15px 10px 15px;} [\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "h1{font-size:2.4em;margin:0;color:#FFF;}[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "h2{font-size:1.7em;margin:0;color:#CC0000;} [\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "h3{font-size:1.2em;margin:10px 0 0 0;color:#000000;} [\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "#header{width:96%;margin:0 0 0 0;padding:6px 2% 6px 2%;font-family:"trebuchet MS", Verdana, sans-serif;color:#FFF;[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "background-color:#555555;}[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "#content{margin:0 0 0 2%;position:relative;}[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< ".content-container{background:#FFF;width:96%;margin-top:8px;padding:10px;position:relative;}[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "-->[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "</style>[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "</head>[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "<body>[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "<div id="header"><h1>Server Error</h1></div>[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "<div id="content">[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< " <div class="content-container"><fieldset>[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "  <h2>401 - Unauthorized: Access is denied due to invalid credentials.</h2>[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "  <h3>You do not have permission to view this directory or page using the c"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "redentials that you supplied.</h3>[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< " </fieldset></div>[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "</div>[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "</body>[\r][\n]"
Thu May 29 11:36:02 CDT 2014:DEBUG:<< "</html>[\r][\n]"

2 Replies

  • klauern's avatar
    klauern
    Contributor
    12 years ago
    I suppose I should add that this might be an issue for ANY HTTP-redirect codes, not just 303. As I found it with that specific error, I didn't want to assume it would apply to all 3xx-related requests.
  • klauern's avatar
    klauern
    Contributor
    12 years ago
    Adding a bit more from the SoapUI log, it appears that Apache's HttpClient loses the Credentials information (third to last line):

    Scheduling autosave every 5 minutes
    Scheduling garbage collection every 60 seconds
    The cajo server is running on localhost:1198/soapuiIntegration
    Fri May 30 15:36:33 CDT 2014:INFO:Loaded project from [file:/......SOMETHING.XML]
    Fri May 30 15:36:44 CDT 2014:DEBUG:Attempt 1 to execute request
    Fri May 30 15:36:44 CDT 2014:DEBUG:Sending request: GET /WHATEVER/outputFormat/report/i1B82A9D79BC044D2BB7077CE86AEA1A6/PDF?p_requestid=10 HTTP/1.1
    Fri May 30 15:36:44 CDT 2014:DEBUG:Receiving response: HTTP/1.1 401 Unauthorized
    Fri May 30 15:36:44 CDT 2014:DEBUG:Connection can be kept alive indefinitely
    Fri May 30 15:36:44 CDT 2014:DEBUG:Target requested authentication
    Fri May 30 15:36:44 CDT 2014:DEBUG:Authorization challenge processed
    Fri May 30 15:36:44 CDT 2014:DEBUG:Authentication scope: NTLM <any realm>@Some-Server.somewhereville.com:443
    Fri May 30 15:36:44 CDT 2014:INFO:Some-Server.somewhereville.com:443 requires Windows authentication
    Fri May 30 15:36:44 CDT 2014:DEBUG:Found credentials
    Fri May 30 15:36:44 CDT 2014:DEBUG:Attempt 2 to execute request
    Fri May 30 15:36:44 CDT 2014:DEBUG:Sending request: GET /WHATEVER/outputFormat/report/i1B82A9D79BC044D2BB7077CE86AEA1A6/PDF?p_requestid=10 HTTP/1.1
    Fri May 30 15:36:44 CDT 2014:DEBUG:Receiving response: HTTP/1.1 401 Unauthorized
    Fri May 30 15:36:44 CDT 2014:DEBUG:Connection can be kept alive indefinitely
    Fri May 30 15:36:44 CDT 2014:DEBUG:Target requested authentication
    Fri May 30 15:36:44 CDT 2014:DEBUG:Authorization challenge processed
    Fri May 30 15:36:44 CDT 2014:DEBUG:Authentication scope: NTLM <any realm>@Some-Server.somewhereville.com:443
    Fri May 30 15:36:44 CDT 2014:DEBUG:Attempt 3 to execute request
    Fri May 30 15:36:44 CDT 2014:DEBUG:Sending request: GET /WHATEVER/outputFormat/report/i1B82A9D79BC044D2BB7077CE86AEA1A6/PDF?p_requestid=10 HTTP/1.1
    Fri May 30 15:36:47 CDT 2014:DEBUG:Receiving response: HTTP/1.1 303 See Other
    Fri May 30 15:36:47 CDT 2014:DEBUG:Connection shut down
    Fri May 30 15:36:47 CDT 2014:DEBUG:Attempt 1 to execute request
    Fri May 30 15:36:47 CDT 2014:DEBUG:Sending request: GET /WHATEVER/sessionOutput/conversationID/i2CDF6FAB63D74AE88C8A5653342DEF9F HTTP/1.1
    Fri May 30 15:36:47 CDT 2014:DEBUG:Receiving response: HTTP/1.1 401 Unauthorized
    Fri May 30 15:36:47 CDT 2014:DEBUG:Connection can be kept alive indefinitely
    Fri May 30 15:36:47 CDT 2014:DEBUG:Target requested authentication
    Fri May 30 15:36:47 CDT 2014:DEBUG:Authorization challenge processed
    Fri May 30 15:36:47 CDT 2014:DEBUG:Authentication scope: NTLM <any realm>@Some-Server.somewhereville.com:443
    Fri May 30 15:36:47 CDT 2014:DEBUG:Credentials not found
    Fri May 30 15:36:47 CDT 2014:INFO:Got response for [http://Some-Server.somewhereville.com:80.PDF:Request 1] in 39ms (1293 bytes)
    Connection refused: connect