Re: 501 Method not implemented with successive POST requests

Thu, 12 Aug 2010 11:26:54 -0700 

 Hello,

as requested the wire / context log of the issue:

best regards
Werner
2010/08/12 20:20:13:218 CEST [DEBUG] SingleClientConnManager - Get connection for route HttpRoute[{}->http://localhost:8080] 2010/08/12 20:20:13:468 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match 2010/08/12 20:20:13:484 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request 2010/08/12 20:20:13:484 CEST [DEBUG] DefaultClientConnection - Sending request: POST /test/secure/ HTTP/1.1 2010/08/12 20:20:13:484 CEST [DEBUG] wire - >> "POST /test/secure/ HTTP/1.1[EOL]" 
2010/08/12 20:20:13:484 CEST [DEBUG] wire - >> "Content-Length: 35[EOL]"
2010/08/12 20:20:13:484 CEST [DEBUG] wire - >> "Content-Type: application/x-www-form-urlencoded; charset=UTF-8[EOL]" 
2010/08/12 20:20:13:484 CEST [DEBUG] wire - >> "Host: localhost:8080[EOL]"
2010/08/12 20:20:13:484 CEST [DEBUG] wire - >> "Connection: Keep-Alive[EOL]"
2010/08/12 20:20:13:484 CEST [DEBUG] wire - >> "User-Agent: Apache-HttpClient/4.0.1 (java 1.5)[EOL]" 
2010/08/12 20:20:13:484 CEST [DEBUG] wire - >> "Expect: 100-Continue[EOL]"
2010/08/12 20:20:13:484 CEST [DEBUG] wire - >> "[EOL]"
2010/08/12 20:20:13:484 CEST [DEBUG] headers - >> POST /test/secure/ HTTP/1.1 
2010/08/12 20:20:13:484 CEST [DEBUG] headers - >> Content-Length: 35
2010/08/12 20:20:13:484 CEST [DEBUG] headers - >> Content-Type: application/x-www-form-urlencoded; charset=UTF-8 
2010/08/12 20:20:13:484 CEST [DEBUG] headers - >> Host: localhost:8080
2010/08/12 20:20:13:484 CEST [DEBUG] headers - >> Connection: Keep-Alive
2010/08/12 20:20:13:484 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.0.1 (java 1.5) 
2010/08/12 20:20:13:484 CEST [DEBUG] headers - >> Expect: 100-Continue
2010/08/12 20:20:15:500 CEST [DEBUG] wire - >> "j_username=tomcat&j_password=tomcat" 
2010/08/12 20:20:15:671 CEST [DEBUG] wire - << "HTTP/1.1 200 OK[EOL]"
2010/08/12 20:20:15:671 CEST [DEBUG] wire - << "Server: Apache-Coyote/1.1[EOL]" 2010/08/12 20:20:15:671 CEST [DEBUG] wire - << "Set-Cookie: JSESSIONID=DA224C1B02E94524187858267D70A830; Path=/test; HttpOnly[EOL]" 2010/08/12 20:20:15:671 CEST [DEBUG] wire - << "Content-Type: text/html;charset=ISO-8859-1[EOL]" 
2010/08/12 20:20:15:671 CEST [DEBUG] wire - << "Content-Length: 711[EOL]"
2010/08/12 20:20:15:671 CEST [DEBUG] wire - << "Date: Thu, 12 Aug 2010 18:20:15 GMT[EOL]" 
2010/08/12 20:20:15:671 CEST [DEBUG] wire - << "[EOL]"
2010/08/12 20:20:15:671 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK 
2010/08/12 20:20:15:671 CEST [DEBUG] headers - << HTTP/1.1 200 OK
2010/08/12 20:20:15:687 CEST [DEBUG] headers - << Server: Apache-Coyote/1.1
2010/08/12 20:20:15:687 CEST [DEBUG] headers - << Set-Cookie: JSESSIONID=DA224C1B02E94524187858267D70A830; Path=/test; HttpOnly 2010/08/12 20:20:15:687 CEST [DEBUG] headers - << Content-Type: text/html;charset=ISO-8859-1 
2010/08/12 20:20:15:687 CEST [DEBUG] headers - << Content-Length: 711
2010/08/12 20:20:15:687 CEST [DEBUG] headers - << Date: Thu, 12 Aug 2010 18:20:15 GMT 2010/08/12 20:20:15:703 CEST [DEBUG] ResponseProcessCookies - Cookie accepted: "[version: 0][name: JSESSIONID][value: DA224C1B02E94524187858267D70A830][domain: localhost][path: /test][expiry: null]". 2010/08/12 20:20:15:703 CEST [DEBUG] DefaultHttpClient - Connection can be kept alive indefinitely 
Response Status: HTTP/1.1 200 OK
2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">[\r][\n]" 
2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "<html>[\r][\n]"
2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9]<head>[\r][\n]"
2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9]<title>Authentication required</title>[\r][\n]" 
2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9]</head>[\r][\n]"
2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9]<body>[\r][\n]"
2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9]<form method="POST" action='j_security_check;jsessionid=DA224C1B02E94524187858267D70A830' >[\r][\n]" 2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9][0x9]<table border="0" cellspacing="5">[\r][\n]" 2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9][0x9][0x9]<tr>[\r][\n]" 2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9][0x9][0x9][0x9]<th align="right">Username:</th>[\r][\n]" 2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9][0x9][0x9][0x9]<td align="left"><input type="text" name="j_username"></td>[\r][\n]" 2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9][0x9][0x9]</tr>[\r][\n]" 2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9][0x9][0x9]<tr>[\r][\n]" 2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9][0x9][0x9][0x9]<th align="right">Password:</th>[\r][\n]" 2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9][0x9][0x9][0x9]<td align="left"><input type="password" name="j_password"></td>[\r][\n]" 2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9][0x9][0x9]</tr>[\r][\n]" 2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9][0x9][0x9]<tr>[\r][\n]" 2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9][0x9][0x9][0x9]<td align="right"><input type="submit" value="Login"></td>[\r][\n]" 2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9][0x9][0x9][0x9]<td align="left"><input type="Reset"></td>[\r][\n]" 2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9][0x9][0x9]</tr>[\r][\n]" 2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9][0x9]</table>[\r][\n]" 
2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9][0x9]</form>[\r][\n]"
2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "[0x9]</body>[\r][\n]"
2010/08/12 20:20:15:703 CEST [DEBUG] wire - << "</html>[\r][\n]"
2010/08/12 20:20:15:703 CEST [DEBUG] SingleClientConnManager - Releasing connection org.apache.http.impl.conn.singleclientconnmanager$connadap...@f84386 2010/08/12 20:20:15:703 CEST [DEBUG] SingleClientConnManager - Get connection for route HttpRoute[{}->http://localhost:8080] 2010/08/12 20:20:15:703 CEST [DEBUG] DefaultHttpClient - Stale connection check 2010/08/12 20:20:15:718 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match 2010/08/12 20:20:15:718 CEST [DEBUG] RequestAddCookies - Cookie [version: 0][name: JSESSIONID][value: DA224C1B02E94524187858267D70A830][domain: localhost][path: /test][expiry: null] match [localhost:8080/test/secure/j_security_check] 2010/08/12 20:20:15:718 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request 2010/08/12 20:20:15:718 CEST [DEBUG] DefaultClientConnection - Sending request: POST /test/secure/j_security_check HTTP/1.1 2010/08/12 20:20:15:718 CEST [DEBUG] wire - >> "POST /test/secure/j_security_check HTTP/1.1[EOL]" 
2010/08/12 20:20:15:718 CEST [DEBUG] wire - >> "Content-Length: 35[EOL]"
2010/08/12 20:20:15:718 CEST [DEBUG] wire - >> "Content-Type: application/x-www-form-urlencoded; charset=UTF-8[EOL]" 
2010/08/12 20:20:15:718 CEST [DEBUG] wire - >> "Host: localhost:8080[EOL]"
2010/08/12 20:20:15:718 CEST [DEBUG] wire - >> "Connection: Keep-Alive[EOL]"
2010/08/12 20:20:15:718 CEST [DEBUG] wire - >> "User-Agent: Apache-HttpClient/4.0.1 (java 1.5)[EOL]" 
2010/08/12 20:20:15:718 CEST [DEBUG] wire - >> "Expect: 100-Continue[EOL]"
2010/08/12 20:20:15:718 CEST [DEBUG] wire - >> "Cookie: JSESSIONID=DA224C1B02E94524187858267D70A830[EOL]" 
2010/08/12 20:20:15:718 CEST [DEBUG] wire - >> "Cookie2: $Version=1[EOL]"
2010/08/12 20:20:15:718 CEST [DEBUG] wire - >> "[EOL]"
2010/08/12 20:20:15:718 CEST [DEBUG] headers - >> POST /test/secure/j_security_check HTTP/1.1 
2010/08/12 20:20:15:718 CEST [DEBUG] headers - >> Content-Length: 35
2010/08/12 20:20:15:718 CEST [DEBUG] headers - >> Content-Type: application/x-www-form-urlencoded; charset=UTF-8 
2010/08/12 20:20:15:718 CEST [DEBUG] headers - >> Host: localhost:8080
2010/08/12 20:20:15:718 CEST [DEBUG] headers - >> Connection: Keep-Alive
2010/08/12 20:20:15:718 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.0.1 (java 1.5) 
2010/08/12 20:20:15:718 CEST [DEBUG] headers - >> Expect: 100-Continue
2010/08/12 20:20:15:718 CEST [DEBUG] headers - >> Cookie: JSESSIONID=DA224C1B02E94524187858267D70A830 
2010/08/12 20:20:15:718 CEST [DEBUG] headers - >> Cookie2: $Version=1
2010/08/12 20:20:17:718 CEST [DEBUG] wire - >> "j_username=tomcat&j_password=tomcat" 2010/08/12 20:20:17:750 CEST [DEBUG] wire - << "HTTP/1.1 302 Moved Temporarily[EOL]" 2010/08/12 20:20:17:750 CEST [DEBUG] wire - << "Server: Apache-Coyote/1.1[EOL]" 2010/08/12 20:20:17:750 CEST [DEBUG] wire - << "Location: http://localhost:8080/test/secure/[EOL]"; 
2010/08/12 20:20:17:750 CEST [DEBUG] wire - << "Content-Length: 0[EOL]"
2010/08/12 20:20:17:750 CEST [DEBUG] wire - << "Date: Thu, 12 Aug 2010 18:20:17 GMT[EOL]" 
2010/08/12 20:20:17:750 CEST [DEBUG] wire - << "[EOL]"
2010/08/12 20:20:17:750 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 302 Moved Temporarily 2010/08/12 20:20:17:750 CEST [DEBUG] headers - << HTTP/1.1 302 Moved Temporarily 
2010/08/12 20:20:17:750 CEST [DEBUG] headers - << Server: Apache-Coyote/1.1
2010/08/12 20:20:17:750 CEST [DEBUG] headers - << Location: http://localhost:8080/test/secure/ 
2010/08/12 20:20:17:750 CEST [DEBUG] headers - << Content-Length: 0
2010/08/12 20:20:17:750 CEST [DEBUG] headers - << Date: Thu, 12 Aug 2010 18:20:17 GMT 2010/08/12 20:20:17:750 CEST [DEBUG] DefaultHttpClient - Connection can be kept alive indefinitely 2010/08/12 20:20:17:750 CEST [DEBUG] SingleClientConnManager - Releasing connection org.apache.http.impl.conn.singleclientconnmanager$connadap...@19dfbff 2010/08/12 20:20:17:750 CEST [DEBUG] SingleClientConnManager - Get connection for route HttpRoute[{}->http://localhost:8080] 2010/08/12 20:20:17:750 CEST [DEBUG] DefaultHttpClient - Stale connection check 
Response Status: HTTP/1.1 302 Moved Temporarily
==> REDIRECT to http://localhost:8080/test/secure/
2010/08/12 20:20:17:750 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match 2010/08/12 20:20:17:750 CEST [DEBUG] RequestAddCookies - Cookie [version: 0][name: JSESSIONID][value: DA224C1B02E94524187858267D70A830][domain: localhost][path: /test][expiry: null] match [localhost:8080/test/secure/] 2010/08/12 20:20:17:750 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request 2010/08/12 20:20:17:750 CEST [DEBUG] DefaultClientConnection - Sending request: POST /test/secure/ HTTP/1.1 2010/08/12 20:20:17:750 CEST [DEBUG] wire - >> "POST /test/secure/ HTTP/1.1[EOL]" 
2010/08/12 20:20:17:750 CEST [DEBUG] wire - >> "Content-Length: 18[EOL]"
2010/08/12 20:20:17:750 CEST [DEBUG] wire - >> "Content-Type: application/x-www-form-urlencoded; charset=UTF-8[EOL]" 
2010/08/12 20:20:17:750 CEST [DEBUG] wire - >> "Host: localhost:8080[EOL]"
2010/08/12 20:20:17:750 CEST [DEBUG] wire - >> "Connection: Keep-Alive[EOL]"
2010/08/12 20:20:17:750 CEST [DEBUG] wire - >> "User-Agent: Apache-HttpClient/4.0.1 (java 1.5)[EOL]" 
2010/08/12 20:20:17:750 CEST [DEBUG] wire - >> "Expect: 100-Continue[EOL]"
2010/08/12 20:20:17:750 CEST [DEBUG] wire - >> "Cookie: JSESSIONID=DA224C1B02E94524187858267D70A830[EOL]" 
2010/08/12 20:20:17:765 CEST [DEBUG] wire - >> "Cookie2: $Version=1[EOL]"
2010/08/12 20:20:17:765 CEST [DEBUG] wire - >> "[EOL]"
2010/08/12 20:20:17:765 CEST [DEBUG] headers - >> POST /test/secure/ HTTP/1.1 
2010/08/12 20:20:17:765 CEST [DEBUG] headers - >> Content-Length: 18
2010/08/12 20:20:17:765 CEST [DEBUG] headers - >> Content-Type: application/x-www-form-urlencoded; charset=UTF-8 
2010/08/12 20:20:17:765 CEST [DEBUG] headers - >> Host: localhost:8080
2010/08/12 20:20:17:765 CEST [DEBUG] headers - >> Connection: Keep-Alive
2010/08/12 20:20:17:765 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.0.1 (java 1.5) 
2010/08/12 20:20:17:765 CEST [DEBUG] headers - >> Expect: 100-Continue
2010/08/12 20:20:17:765 CEST [DEBUG] headers - >> Cookie: JSESSIONID=DA224C1B02E94524187858267D70A830 
2010/08/12 20:20:17:765 CEST [DEBUG] headers - >> Cookie2: $Version=1
2010/08/12 20:20:17:781 CEST [DEBUG] wire - << "HTTP/1.1 100 Continue[EOL]"
2010/08/12 20:20:17:781 CEST [DEBUG] wire - << "[EOL]"
2010/08/12 20:20:17:781 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 100 Continue 
2010/08/12 20:20:17:781 CEST [DEBUG] headers - << HTTP/1.1 100 Continue
2010/08/12 20:20:17:781 CEST [DEBUG] wire - >> "testName=testValue"
2010/08/12 20:20:17:781 CEST [DEBUG] wire - << "HTTP/1.1 200 OK[EOL]"
2010/08/12 20:20:17:781 CEST [DEBUG] wire - << "Server: Apache-Coyote/1.1[EOL]" 2010/08/12 20:20:17:781 CEST [DEBUG] wire - << "Set-Cookie: JSESSIONID=A5FB87E6199EADB2AB18010DA295EC99; Path=/test; HttpOnly[EOL]" 
2010/08/12 20:20:17:781 CEST [DEBUG] wire - << "Content-Length: 20[EOL]"
2010/08/12 20:20:17:781 CEST [DEBUG] wire - << "Date: Thu, 12 Aug 2010 18:20:17 GMT[EOL]" 
2010/08/12 20:20:17:781 CEST [DEBUG] wire - << "[EOL]"
2010/08/12 20:20:17:781 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK 
2010/08/12 20:20:17:781 CEST [DEBUG] headers - << HTTP/1.1 200 OK
2010/08/12 20:20:17:781 CEST [DEBUG] headers - << Server: Apache-Coyote/1.1
2010/08/12 20:20:17:781 CEST [DEBUG] headers - << Set-Cookie: JSESSIONID=A5FB87E6199EADB2AB18010DA295EC99; Path=/test; HttpOnly 
2010/08/12 20:20:17:781 CEST [DEBUG] headers - << Content-Length: 20
2010/08/12 20:20:17:781 CEST [DEBUG] headers - << Date: Thu, 12 Aug 2010 18:20:17 GMT 2010/08/12 20:20:17:796 CEST [DEBUG] ResponseProcessCookies - Cookie accepted: "[version: 0][name: JSESSIONID][value: A5FB87E6199EADB2AB18010DA295EC99][domain: localhost][path: /test][expiry: null]". 2010/08/12 20:20:17:796 CEST [DEBUG] DefaultHttpClient - Connection can be kept alive indefinitely 2010/08/12 20:20:17:796 CEST [DEBUG] wire - << "HelloTomcatServlet[\r][\n]"Response Status: HTTP/1.1 200 OK
2010/08/12 20:20:17:796 CEST [DEBUG] SingleClientConnManager - Releasing connection org.apache.http.impl.conn.singleclientconnmanager$connadap...@10b4b2f 2010/08/12 20:20:17:796 CEST [DEBUG] SingleClientConnManager - Get connection for route HttpRoute[{}->http://localhost:8080] 2010/08/12 20:20:17:796 CEST [DEBUG] DefaultHttpClient - Stale connection check 2010/08/12 20:20:17:796 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match 2010/08/12 20:20:17:796 CEST [DEBUG] RequestAddCookies - Cookie [version: 0][name: JSESSIONID][value: A5FB87E6199EADB2AB18010DA295EC99][domain: localhost][path: /test][expiry: null] match [localhost:8080/test/secure/] 2010/08/12 20:20:17:796 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request 2010/08/12 20:20:17:796 CEST [DEBUG] DefaultClientConnection - Sending request: POST /test/secure/ HTTP/1.1 2010/08/12 20:20:17:796 CEST [DEBUG] wire - >> "POST /test/secure/ HTTP/1.1[EOL]" 
2010/08/12 20:20:17:796 CEST [DEBUG] wire - >> "Content-Length: 18[EOL]"
2010/08/12 20:20:17:796 CEST [DEBUG] wire - >> "Content-Type: application/x-www-form-urlencoded; charset=UTF-8[EOL]" 
2010/08/12 20:20:17:796 CEST [DEBUG] wire - >> "Host: localhost:8080[EOL]"
2010/08/12 20:20:17:796 CEST [DEBUG] wire - >> "Connection: Keep-Alive[EOL]"
2010/08/12 20:20:17:796 CEST [DEBUG] wire - >> "User-Agent: Apache-HttpClient/4.0.1 (java 1.5)[EOL]" 
2010/08/12 20:20:17:796 CEST [DEBUG] wire - >> "Expect: 100-Continue[EOL]"
2010/08/12 20:20:17:796 CEST [DEBUG] wire - >> "Cookie: JSESSIONID=A5FB87E6199EADB2AB18010DA295EC99[EOL]" 
2010/08/12 20:20:17:796 CEST [DEBUG] wire - >> "Cookie2: $Version=1[EOL]"
2010/08/12 20:20:17:796 CEST [DEBUG] wire - >> "[EOL]"
2010/08/12 20:20:17:796 CEST [DEBUG] headers - >> POST /test/secure/ HTTP/1.1 
2010/08/12 20:20:17:796 CEST [DEBUG] headers - >> Content-Length: 18
2010/08/12 20:20:17:796 CEST [DEBUG] headers - >> Content-Type: application/x-www-form-urlencoded; charset=UTF-8 
2010/08/12 20:20:17:796 CEST [DEBUG] headers - >> Host: localhost:8080
2010/08/12 20:20:17:796 CEST [DEBUG] headers - >> Connection: Keep-Alive
2010/08/12 20:20:17:796 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.0.1 (java 1.5) 
2010/08/12 20:20:17:796 CEST [DEBUG] headers - >> Expect: 100-Continue
2010/08/12 20:20:17:796 CEST [DEBUG] headers - >> Cookie: JSESSIONID=A5FB87E6199EADB2AB18010DA295EC99 
2010/08/12 20:20:17:796 CEST [DEBUG] headers - >> Cookie2: $Version=1
2010/08/12 20:20:17:796 CEST [DEBUG] wire - << "HTTP/1.1 100 Continue[EOL]"
2010/08/12 20:20:17:796 CEST [DEBUG] wire - << "[EOL]"
2010/08/12 20:20:17:796 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 100 Continue 
2010/08/12 20:20:17:796 CEST [DEBUG] headers - << HTTP/1.1 100 Continue
2010/08/12 20:20:17:796 CEST [DEBUG] wire - >> "testName=testValue"
2010/08/12 20:20:17:796 CEST [DEBUG] wire - << "HTTP/1.1 501 Not Implemented[EOL]" 2010/08/12 20:20:17:796 CEST [DEBUG] wire - << "Server: Apache-Coyote/1.1[EOL]" 
2010/08/12 20:20:17:796 CEST [DEBUG] wire - << "Pragma: No-cache[EOL]"
2010/08/12 20:20:17:796 CEST [DEBUG] wire - << "Cache-Control: no-cache[EOL]" 2010/08/12 20:20:17:796 CEST [DEBUG] wire - << "Expires: Thu, 01 Jan 1970 01:00:00 CET[EOL]" 2010/08/12 20:20:17:796 CEST [DEBUG] wire - << "Content-Type: text/html;charset=utf-8[EOL]" 
2010/08/12 20:20:17:796 CEST [DEBUG] wire - << "Content-Length: 1278[EOL]"
2010/08/12 20:20:17:796 CEST [DEBUG] wire - << "Date: Thu, 12 Aug 2010 18:20:17 GMT[EOL]" 
2010/08/12 20:20:17:796 CEST [DEBUG] wire - << "Connection: close[EOL]"
2010/08/12 20:20:17:796 CEST [DEBUG] wire - << "[EOL]"
2010/08/12 20:20:17:796 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 501 Not Implemented 2010/08/12 20:20:17:796 CEST [DEBUG] headers - << HTTP/1.1 501 Not Implemented 
2010/08/12 20:20:17:796 CEST [DEBUG] headers - << Server: Apache-Coyote/1.1
2010/08/12 20:20:17:796 CEST [DEBUG] headers - << Pragma: No-cache
2010/08/12 20:20:17:796 CEST [DEBUG] headers - << Cache-Control: no-cache
2010/08/12 20:20:17:796 CEST [DEBUG] headers - << Expires: Thu, 01 Jan 1970 01:00:00 CET 2010/08/12 20:20:17:796 CEST [DEBUG] headers - << Content-Type: text/html;charset=utf-8 
2010/08/12 20:20:17:796 CEST [DEBUG] headers - << Content-Length: 1278
2010/08/12 20:20:17:796 CEST [DEBUG] headers - << Date: Thu, 12 Aug 2010 18:20:17 GMT 
2010/08/12 20:20:17:796 CEST [DEBUG] headers - << Connection: close
2010/08/12 20:20:17:812 CEST [DEBUG] SingleClientConnManager - Releasing connection org.apache.http.impl.conn.singleclientconnmanager$connadap...@1abab88 2010/08/12 20:20:17:812 CEST [DEBUG] SingleClientConnManager - Released connection open but not reusable. 2010/08/12 20:20:17:812 CEST [DEBUG] DefaultClientConnection - Connection shut down 2010/08/12 20:20:17:812 CEST [DEBUG] SingleClientConnManager - Get connection for route HttpRoute[{}->http://localhost:8080]Response Status: HTTP/1.1 501 Not Implemented
2010/08/12 20:20:17:812 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match 2010/08/12 20:20:17:812 CEST [DEBUG] RequestAddCookies - Cookie [version: 0][name: JSESSIONID][value: A5FB87E6199EADB2AB18010DA295EC99][domain: localhost][path: /test][expiry: null] match [localhost:8080/test/secure/] 2010/08/12 20:20:17:812 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request 2010/08/12 20:20:17:812 CEST [DEBUG] DefaultClientConnection - Sending request: POST /test/secure/ HTTP/1.1 2010/08/12 20:20:17:812 CEST [DEBUG] wire - >> "POST /test/secure/ HTTP/1.1[EOL]" 
2010/08/12 20:20:17:812 CEST [DEBUG] wire - >> "Content-Length: 18[EOL]"
2010/08/12 20:20:17:812 CEST [DEBUG] wire - >> "Content-Type: application/x-www-form-urlencoded; charset=UTF-8[EOL]" 
2010/08/12 20:20:17:812 CEST [DEBUG] wire - >> "Host: localhost:8080[EOL]"
2010/08/12 20:20:17:812 CEST [DEBUG] wire - >> "Connection: Keep-Alive[EOL]"
2010/08/12 20:20:17:812 CEST [DEBUG] wire - >> "User-Agent: Apache-HttpClient/4.0.1 (java 1.5)[EOL]" 
2010/08/12 20:20:17:812 CEST [DEBUG] wire - >> "Expect: 100-Continue[EOL]"
2010/08/12 20:20:17:812 CEST [DEBUG] wire - >> "Cookie: JSESSIONID=A5FB87E6199EADB2AB18010DA295EC99[EOL]" 
2010/08/12 20:20:17:812 CEST [DEBUG] wire - >> "Cookie2: $Version=1[EOL]"
2010/08/12 20:20:17:812 CEST [DEBUG] wire - >> "[EOL]"
2010/08/12 20:20:17:812 CEST [DEBUG] headers - >> POST /test/secure/ HTTP/1.1 
2010/08/12 20:20:17:812 CEST [DEBUG] headers - >> Content-Length: 18
2010/08/12 20:20:17:812 CEST [DEBUG] headers - >> Content-Type: application/x-www-form-urlencoded; charset=UTF-8 
2010/08/12 20:20:17:812 CEST [DEBUG] headers - >> Host: localhost:8080
2010/08/12 20:20:17:812 CEST [DEBUG] headers - >> Connection: Keep-Alive
2010/08/12 20:20:17:812 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.0.1 (java 1.5) 
2010/08/12 20:20:17:812 CEST [DEBUG] headers - >> Expect: 100-Continue
2010/08/12 20:20:17:812 CEST [DEBUG] headers - >> Cookie: JSESSIONID=A5FB87E6199EADB2AB18010DA295EC99 
2010/08/12 20:20:17:812 CEST [DEBUG] headers - >> Cookie2: $Version=1
2010/08/12 20:20:17:828 CEST [DEBUG] wire - << "HTTP/1.1 100 Continue[EOL]"
2010/08/12 20:20:17:828 CEST [DEBUG] wire - << "[EOL]"
2010/08/12 20:20:17:828 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 100 Continue 
2010/08/12 20:20:17:828 CEST [DEBUG] headers - << HTTP/1.1 100 Continue
2010/08/12 20:20:17:828 CEST [DEBUG] wire - >> "testName=testValue"
2010/08/12 20:20:17:828 CEST [DEBUG] wire - << "HTTP/1.1 200 OK[EOL]"
2010/08/12 20:20:17:828 CEST [DEBUG] wire - << "Server: Apache-Coyote/1.1[EOL]" 
2010/08/12 20:20:17:828 CEST [DEBUG] wire - << "Content-Length: 20[EOL]"
2010/08/12 20:20:17:828 CEST [DEBUG] wire - << "Date: Thu, 12 Aug 2010 18:20:17 GMT[EOL]"Response Status: HTTP/1.1 200 OK 

2010/08/12 20:20:17:828 CEST [DEBUG] wire - << "[EOL]"
2010/08/12 20:20:17:828 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK 
2010/08/12 20:20:17:828 CEST [DEBUG] headers - << HTTP/1.1 200 OK
2010/08/12 20:20:17:828 CEST [DEBUG] headers - << Server: Apache-Coyote/1.1
2010/08/12 20:20:17:828 CEST [DEBUG] headers - << Content-Length: 20
2010/08/12 20:20:17:828 CEST [DEBUG] headers - << Date: Thu, 12 Aug 2010 18:20:17 GMT 2010/08/12 20:20:17:828 CEST [DEBUG] DefaultHttpClient - Connection can be kept alive indefinitely 
2010/08/12 20:20:17:828 CEST [DEBUG] wire - << "HelloTomcatServlet[\r][\n]"
2010/08/12 20:20:17:828 CEST [DEBUG] SingleClientConnManager - Releasing connection org.apache.http.impl.conn.singleclientconnmanager$connadap...@18a7efd 2010/08/12 20:20:17:828 CEST [DEBUG] SingleClientConnManager - Get connection for route HttpRoute[{}->http://localhost:8080] 2010/08/12 20:20:17:828 CEST [DEBUG] DefaultHttpClient - Stale connection check 2010/08/12 20:20:17:875 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match 2010/08/12 20:20:17:875 CEST [DEBUG] RequestAddCookies - Cookie [version: 0][name: JSESSIONID][value: A5FB87E6199EADB2AB18010DA295EC99][domain: localhost][path: /test][expiry: null] match [localhost:8080/test/secure/] 2010/08/12 20:20:17:875 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request 2010/08/12 20:20:17:875 CEST [DEBUG] DefaultClientConnection - Sending request: POST /test/secure/ HTTP/1.1 2010/08/12 20:20:17:875 CEST [DEBUG] wire - >> "POST /test/secure/ HTTP/1.1[EOL]" 
2010/08/12 20:20:17:875 CEST [DEBUG] wire - >> "Content-Length: 18[EOL]"
2010/08/12 20:20:17:890 CEST [DEBUG] wire - >> "Content-Type: application/x-www-form-urlencoded; charset=UTF-8[EOL]" 
2010/08/12 20:20:17:890 CEST [DEBUG] wire - >> "Host: localhost:8080[EOL]"
2010/08/12 20:20:17:890 CEST [DEBUG] wire - >> "Connection: Keep-Alive[EOL]"
2010/08/12 20:20:17:890 CEST [DEBUG] wire - >> "User-Agent: Apache-HttpClient/4.0.1 (java 1.5)[EOL]" 
2010/08/12 20:20:17:890 CEST [DEBUG] wire - >> "Expect: 100-Continue[EOL]"
2010/08/12 20:20:17:890 CEST [DEBUG] wire - >> "Cookie: JSESSIONID=A5FB87E6199EADB2AB18010DA295EC99[EOL]" 
2010/08/12 20:20:17:890 CEST [DEBUG] wire - >> "Cookie2: $Version=1[EOL]"
2010/08/12 20:20:17:890 CEST [DEBUG] wire - >> "[EOL]"
2010/08/12 20:20:17:890 CEST [DEBUG] headers - >> POST /test/secure/ HTTP/1.1 
2010/08/12 20:20:17:890 CEST [DEBUG] headers - >> Content-Length: 18
2010/08/12 20:20:17:890 CEST [DEBUG] headers - >> Content-Type: application/x-www-form-urlencoded; charset=UTF-8 
2010/08/12 20:20:17:890 CEST [DEBUG] headers - >> Host: localhost:8080
2010/08/12 20:20:17:890 CEST [DEBUG] headers - >> Connection: Keep-Alive
2010/08/12 20:20:17:890 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.0.1 (java 1.5) 
2010/08/12 20:20:17:890 CEST [DEBUG] headers - >> Expect: 100-Continue
2010/08/12 20:20:17:890 CEST [DEBUG] headers - >> Cookie: JSESSIONID=A5FB87E6199EADB2AB18010DA295EC99 
2010/08/12 20:20:17:890 CEST [DEBUG] headers - >> Cookie2: $Version=1
2010/08/12 20:20:17:890 CEST [DEBUG] wire - << "HTTP/1.1 100 Continue[EOL]"
2010/08/12 20:20:17:890 CEST [DEBUG] wire - << "[EOL]"
2010/08/12 20:20:17:890 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 100 Continue 
2010/08/12 20:20:17:890 CEST [DEBUG] headers - << HTTP/1.1 100 Continue
2010/08/12 20:20:17:890 CEST [DEBUG] wire - >> "testName=testValue"
2010/08/12 20:20:17:906 CEST [DEBUG] wire - << "HTTP/1.1 200 OK[EOL]"
2010/08/12 20:20:17:906 CEST [DEBUG] wire - << "Server: Apache-Coyote/1.1[EOL]" 
2010/08/12 20:20:17:906 CEST [DEBUG] wire - << "Content-Length: 20[EOL]"
2010/08/12 20:20:17:906 CEST [DEBUG] wire - << "Date: Thu, 12 Aug 2010 18:20:17 GMT[EOL]" 
2010/08/12 20:20:17:906 CEST [DEBUG] wire - << "[EOL]"
2010/08/12 20:20:17:906 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK 
2010/08/12 20:20:17:906 CEST [DEBUG] headers - << HTTP/1.1 200 OK
2010/08/12 20:20:17:906 CEST [DEBUG] headers - << Server: Apache-Coyote/1.1
2010/08/12 20:20:17:906 CEST [DEBUG] headers - << Content-Length: 20
2010/08/12 20:20:17:906 CEST [DEBUG] headers - << Date: Thu, 12 Aug 2010 18:20:17 GMT 2010/08/12 20:20:17:906 CEST [DEBUG] DefaultHttpClient - Connection can be kept alive indefinitely 
2010/08/12 20:20:17:906 CEST [DEBUG] wire - << "HelloTomcatServlet[\r][\n]"
Response Status: HTTP/1.1 200 OK
2010/08/12 20:20:17:906 CEST [DEBUG] SingleClientConnManager - Releasing connection org.apache.http.impl.conn.singleclientconnmanager$connadap...@1971afc 2010/08/12 20:20:17:906 CEST [DEBUG] SingleClientConnManager - Get connection for route HttpRoute[{}->http://localhost:8080] 2010/08/12 20:20:17:906 CEST [DEBUG] DefaultHttpClient - Stale connection check 2010/08/12 20:20:17:906 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match 2010/08/12 20:20:17:906 CEST [DEBUG] RequestAddCookies - Cookie [version: 0][name: JSESSIONID][value: A5FB87E6199EADB2AB18010DA295EC99][domain: localhost][path: /test][expiry: null] match [localhost:8080/test/secure/] 2010/08/12 20:20:17:906 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request 2010/08/12 20:20:17:906 CEST [DEBUG] DefaultClientConnection - Sending request: POST /test/secure/ HTTP/1.1 2010/08/12 20:20:17:906 CEST [DEBUG] wire - >> "POST /test/secure/ HTTP/1.1[EOL]" 
2010/08/12 20:20:17:906 CEST [DEBUG] wire - >> "Content-Length: 18[EOL]"
2010/08/12 20:20:17:906 CEST [DEBUG] wire - >> "Content-Type: application/x-www-form-urlencoded; charset=UTF-8[EOL]" 
2010/08/12 20:20:17:906 CEST [DEBUG] wire - >> "Host: localhost:8080[EOL]"
2010/08/12 20:20:17:906 CEST [DEBUG] wire - >> "Connection: Keep-Alive[EOL]"
2010/08/12 20:20:17:906 CEST [DEBUG] wire - >> "User-Agent: Apache-HttpClient/4.0.1 (java 1.5)[EOL]" 
2010/08/12 20:20:17:906 CEST [DEBUG] wire - >> "Expect: 100-Continue[EOL]"
2010/08/12 20:20:17:906 CEST [DEBUG] wire - >> "Cookie: JSESSIONID=A5FB87E6199EADB2AB18010DA295EC99[EOL]" 
2010/08/12 20:20:17:906 CEST [DEBUG] wire - >> "Cookie2: $Version=1[EOL]"
2010/08/12 20:20:17:906 CEST [DEBUG] wire - >> "[EOL]"
2010/08/12 20:20:17:906 CEST [DEBUG] headers - >> POST /test/secure/ HTTP/1.1 
2010/08/12 20:20:17:906 CEST [DEBUG] headers - >> Content-Length: 18
2010/08/12 20:20:17:906 CEST [DEBUG] headers - >> Content-Type: application/x-www-form-urlencoded; charset=UTF-8 
2010/08/12 20:20:17:906 CEST [DEBUG] headers - >> Host: localhost:8080
2010/08/12 20:20:17:906 CEST [DEBUG] headers - >> Connection: Keep-Alive
2010/08/12 20:20:17:906 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.0.1 (java 1.5) 
2010/08/12 20:20:17:906 CEST [DEBUG] headers - >> Expect: 100-Continue
2010/08/12 20:20:17:906 CEST [DEBUG] headers - >> Cookie: JSESSIONID=A5FB87E6199EADB2AB18010DA295EC99 
2010/08/12 20:20:17:906 CEST [DEBUG] headers - >> Cookie2: $Version=1
2010/08/12 20:20:17:906 CEST [DEBUG] wire - << "HTTP/1.1 100 Continue[EOL]"
2010/08/12 20:20:17:906 CEST [DEBUG] wire - << "[EOL]"
2010/08/12 20:20:17:906 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 100 Continue 
2010/08/12 20:20:17:906 CEST [DEBUG] headers - << HTTP/1.1 100 Continue
2010/08/12 20:20:17:906 CEST [DEBUG] wire - >> "testName=testValue"
2010/08/12 20:20:17:906 CEST [DEBUG] wire - << "HTTP/1.1 200 OK[EOL]"
2010/08/12 20:20:17:906 CEST [DEBUG] wire - << "Server: Apache-Coyote/1.1[EOL]" 
2010/08/12 20:20:17:906 CEST [DEBUG] wire - << "Content-Length: 20[EOL]"
2010/08/12 20:20:17:906 CEST [DEBUG] wire - << "Date: Thu, 12 Aug 2010 18:20:17 GMT[EOL]" 
2010/08/12 20:20:17:906 CEST [DEBUG] wire - << "[EOL]"
2010/08/12 20:20:17:906 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK 
2010/08/12 20:20:17:906 CEST [DEBUG] headers - << HTTP/1.1 200 OK
2010/08/12 20:20:17:906 CEST [DEBUG] headers - << Server: Apache-Coyote/1.1
2010/08/12 20:20:17:906 CEST [DEBUG] headers - << Content-Length: 20
2010/08/12 20:20:17:906 CEST [DEBUG] headers - << Date: Thu, 12 Aug 2010 18:20:17 GMT 2010/08/12 20:20:17:906 CEST [DEBUG] DefaultHttpClient - Connection can be kept alive indefinitely 
2010/08/12 20:20:17:906 CEST [DEBUG] wire - << "HelloTomcatServlet[\r][\n]"
2010/08/12 20:20:17:906 CEST [DEBUG] SingleClientConnManager - Releasing connection org.apache.http.impl.conn.singleclientconnmanager$connadap...@16cd7d5 2010/08/12 20:20:17:906 CEST [DEBUG] DefaultClientConnection - Connection shut down 
Response Status: HTTP/1.1 200 OK





On 12.08.2010 14:30, Oleg Kalnichevski wrote:

On Wed, 2010-08-11 at 21:02 +0200, [email protected] wrote:

Hello HttpComponents-Users,

I'm facing a strange issue when using HttpComponents with successive
POST requests against a simple Tomcat servlet (Form-based POST
Authentication is enabled). After a sucessfull authentication, the
client requests the same protected resource a few times in a row, but
the second request always returns a "501 Method not implemented" status.
All other requests succeed .

The following communication takes place:
1. Client requests a protected resource; Tomcat returns the login page
(HTTP200)
2. Client provides the user credentials and calls the auth check page;
If successful Tomcat returns a redirect (HTTP302)
3. Client sets the location from the redirect for the next
request(identical to URI from #1) and requests it; Tomcat returns the
page (HTTP200)
4. Client requests the same page again; Tomcat returns a HTTP501 -
Method not implemented
5. Client requests the same page again; Tomcat returns the page (HTTP200)
6. Client requests the same page again; Tomcat returns the page (HTTP200)
7. Client requests the same page again; Tomcat returns the page (HTTP200)


The log message regarding the 501 says: '"testName=testValuePOST
/test/secure/ HTTP/1.1" 501 1278', which may indicate that the entity
and the HTTP-method name somehow got mixed up!?

Please post a wire / context log of the session

http://hc.apache.org/httpcomponents-client-4.0.1/logging.html

Oleg



---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]




---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]

Reply via email to