On Tue, Apr 14, 2009 at 02:01:22PM +0100, Sam Crawford wrote: > Apologies, it looks like the mailing list may have bounced my email earlier > due to it being marked as spam. I've reattached it... > > Thanks > > Sam >
Hi Sam This one turned out quite tricky. It took me a while to figure what was wrong with the messages. The last two HTTP responses look almost perfectly okay. The catch is that 304 response MAY NOT have a response body at all. RFC 2616: --- 10.3.5 304 Not Modified If the client has performed a conditional GET request and access is allowed, but the document has not been modified, the server SHOULD respond with this status code. The 304 response MUST NOT contain a message-body, and thus is always terminated by the first empty line after the header fields. --- The 0000 bit you are seeing is the closing chunk of the chunk coded body. It is perfectly well formed. The trouble is that the response body was not meant to be there in the first place. The servlet engine your application is talking to appears broken. Hope this helps Oleg > > 2009/4/14 Oleg Kalnichevski <[email protected]> > > > On Tue, Apr 14, 2009 at 01:15:32PM +0100, Sam Crawford wrote: > > > Scrub my earlier suspicion, I'm consuming the full contents of the HTTP > > > response regardless of the response code. > > > Watching this in a debugger, I see that the HttpResponse returned by the > > > second request (using method.execute(...)) returned null on the call to > > > response.getEntity(). This should have returned me the stream containing > > > "0000", no? > > > > > > Thanks, > > > > > > Sam > > > > > > > Sam > > > > I could not find the wirelog. I will not be able to do much without a > > wirelog of the session. > > > > Oleg > > > > > > > 2009/4/14 Sam Crawford <[email protected]> > > > > > > > Oleg, > > > > Thanks for getting back to me. I've been able to reproduce the issue > > fairly > > > > easily and have a wire capture from a development environment. See > > attached. > > > > > > > > There are three requests in the wire capture, all for the same content. > > > > > > > > Lines 1-122 show the initial request, the subsequent 200 reply, and all > > > > works well > > > > > > > > Lines 124-203 show the re-request for the same URL, with the server > > > > responding 304 Unmodified, and this works well > > > > > > > > Lines 205-324 show the re-request for the same URL, with the 304 > > > > Unmodified ? this request produces the exception after waiting 30 > > seconds > > > > > > > > Looking at the wire captures alongside the tcpdump captures, I think I > > may > > > > see the cause of the issue... > > > > > > > > In the second request/response a bunch of headers are sent back with > > the > > > > 304 reply. In the tcpdump capture, I see "0000" is returned as the body > > of > > > > the response, although this is not shown in the wire capture (at this > > > > point). > > > > > > > > In the third request/response we see "0000" as the first line of the > > > > response in the HttpClient wire capture (which is not present in the > > tcpdump > > > > capture), *then* the 304 headers, then another "0000" string. > > > > Please correct me if I'm wrong, but it looks as though HttpClient is > > not > > > > consuming the "0000" string in the second response, which causes it to > > spill > > > > over to the third response, and thus mistakenly leads the HttpClient to > > > > believe that it's not received the response from the third request. > > > > > > > > I'm going to have another skim over my code now... I have a nasty > > feeling > > > > that I may not be consuming the response of 304 reply. > > > > > > > > Thanks, > > > > > > > > Sam > > > > > > > > > > > > 2009/4/14 Oleg Kalnichevski <[email protected]> > > > > > > > > On Tue, Apr 14, 2009 at 12:17:18AM +0100, Sam Crawford wrote: > > > >> > Evening all, > > > >> > > > > >> > I'm encountering an odd issue with HttpClient 4.0b2 and HttpCore 4.0 > > GA. > > > >> > Sending a fairly benign request to a server running JIRA is causing > > > >> > HttpClient to throw a ProtocolException with the message "The server > > > >> failed > > > >> > to respond with a valid HTTP response" after waiting 30 seconds. 30 > > > >> seconds > > > >> > is incidentally the connection and query timeout I defined in the > > > >> HttpClient > > > >> > parameters. > > > >> > > > > >> > It looks to me like the HttpClient is not recognising that the > > server > > > >> has > > > >> > responded completely. The headers being sent back from the server > > look > > > >> okay > > > >> > to me. > > > >> > > > > >> > A tcpdump capture of the communication that triggered the error is > > shown > > > >> > below, alongside a stacktrace from the application, and the options > > I > > > >> set on > > > >> > the ThreadSafeClientConnManager and HttpClient. > > > >> > > > > >> > Any suggestions would be much appreciated. > > > >> > > > > >> > Thanks again, > > > >> > > > > >> > Sam > > > >> > > > > >> > > > >> Sam, > > > >> > > > >> Could you please post a complete wire / context log of the session? > > > >> > > > >> http://hc.apache.org/httpcomponents-client/logging.html > > > >> > > > >> Oleg > > > >> > > > >> > > > >> > > > > >> > #### TCPDUMP CAPTURE OF HTTP COMMUNICATION #### > > > >> > > > > >> > GET /JRA/s/330/1/_/styles/combined.css HTTP/1.1 > > > >> > accept: */* > > > >> > referer: > > > >> > > > http://jira.company.com/JRA/secure/ViewUserIssueColumns!default.jspa > > > >> > accept-language: en-gb > > > >> > ua-cpu: x86 > > > >> > if-modified-since: Sun, 12 Apr 2009 06:41:46 GMT > > > >> > if-none-match: "1239518506000" > > > >> > user-agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; .NET > > CLR > > > >> > 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.04506.30; .NET CLR > > > >> 3.0.04506.648; > > > >> > .NET CLR 3.5.21022; InfoPath.2) > > > >> > Host: jira.company.com:80 > > > >> > pragma: no-cache > > > >> > Connection: Keep-Alive > > > >> > Cookie: ARPT=YZPUQIS10.132.147.33CKMLK; > > > >> > > > > >> > > JSESSIONID=xpLZJj7fly2Ymnnmp4TgC2YyPnG4ZF684hWqZbvTGwHMqTkzKwxG!119119743 > > > >> > > > > >> > HTTP/1.1 304 Not Modified > > > >> > Cache-Control: private > > > >> > Date: Mon, 13 Apr 2009 22:39:59 GMT > > > >> > Transfer-Encoding: chunked > > > >> > Content-Type: text/css; charset=UTF-8 > > > >> > Expires: Thu, 11 Apr 2019 22:39:59 GMT > > > >> > Last-Modified: Sun, 12 Apr 2009 06:41:46 GMT > > > >> > ETag: "1239518506000" > > > >> > X-Powered-By: Servlet/2.4 JSP/2.0 > > > >> > > > > >> > 0000 > > > >> > > > > >> > > > > >> > > > > >> > #### STACKTRACE FROM APPLICATION (Note 30 second delay between > > making > > > >> > request and the exception) ##### > > > >> > > > > >> > > > > >> > > [#|2009-04-13T23:40:00.010+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=24;_ThreadName=httpSSLWorkerThread-8080-3;| > > > >> > Mon Apr 13 23:40:00 BST 2009|com.a.b.c.ProxyFilter|D|Forwarding GET > > > >> > /JRA/s/330/1/7/_/styles/global.css|#] > > > >> > > > > >> > > > > >> > > [#|2009-04-13T23:40:31.449+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=23;_ThreadName=httpSSLWorkerThread-8080-2;| > > > >> > Mon Apr 13 23:40:31 BST > > > >> 2009|com.a.b.c.ProxyFilter|E|ClientProtocolException > > > >> > thrown when fetching > > > >> /JRA/s/330/1/_/includes/js/combined-javascript.js|#] > > > >> > > > > >> > > > > >> > > [#|2009-04-13T23:40:31.451+0100|WARNING|sun-appserver9.1|javax.enterprise.system.stream.err|_ThreadID=23;_ThreadName=httpSSLWorkerThread-8080-2; > > > >> > > > > >> > > _RequestID=6d978520-35f4-45ac-a79e-bce8ae9712e6;|org.apache.http.client.ClientProtocolException > > > >> > at > > > >> > > > > >> > > org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:557) > > > >> > at > > > >> > > > > >> > > org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:487) > > > >> > at > > > >> com.a.b.c.ProxyFilter.processProxyRequest(ProxyFilter.java:175) > > > >> > at com.a.b.c.ProxyFilter.doFilter(ProxyFilter.java:108) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:230) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:198) > > > >> > at > > com.a.b.c.UserInjectFilter.doFilter(UserInjectFilter.java:52) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:230) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:198) > > > >> > at > > > >> > > > > >> > > com.sun.identity.agents.filter.AmAgentBaseFilter.allowRequestToContinue(AmAgentBaseFilter.java:126) > > > >> > at > > > >> > > > > >> > > com.sun.identity.agents.filter.AmAgentBaseFilter.doFilter(AmAgentBaseFilter.java:75) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:230) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:198) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:288) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.StandardContextValve.invokeInternal(StandardContextValve.java:271) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:202) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:632) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:577) > > > >> > at > > > >> com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:94) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:206) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:632) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:577) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:571) > > > >> > at > > > >> > > > org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:1080) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:150) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:632) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:577) > > > >> > at > > > >> > > > > >> > > org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:571) > > > >> > at > > > >> > > > org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:1080) > > > >> > at > > > >> > > > org.apache.coyote.tomcat5.CoyoteAdapter.service(CoyoteAdapter.java:272) > > > >> > at > > > >> > > > > >> > > com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.invokeAdapter(DefaultProcessorTask.java:637) > > > >> > at > > > >> > > > > >> > > com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.doProcess(DefaultProcessorTask.java:568) > > > >> > at > > > >> > > > > >> > > com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.process(DefaultProcessorTask.java:813) > > > >> > at > > > >> > > > > >> > > com.sun.enterprise.web.connector.grizzly.DefaultReadTask.executeProcessorTask(DefaultReadTask.java:341) > > > >> > at > > > >> > > > > >> > > com.sun.enterprise.web.connector.grizzly.DefaultReadTask.doTask(DefaultReadTask.java:263) > > > >> > at > > > >> > > > > >> > > com.sun.enterprise.web.connector.grizzly.DefaultReadTask.doTask(DefaultReadTask.java:214) > > > >> > at > > > >> > > > com.sun.enterprise.web.connector.grizzly.TaskBase.run(TaskBase.java:265) > > > >> > at > > > >> > > > > >> > > com.sun.enterprise.web.connector.grizzly.ssl.SSLWorkerThread.run(SSLWorkerThread.java:106) > > > >> > Caused by: org.apache.http.ProtocolException: The server failed to > > > >> respond > > > >> > with a valid HTTP response > > > >> > at > > > >> > > > > >> > > org.apache.http.impl.conn.DefaultResponseParser.parseHead(DefaultResponseParser.java:93) > > > >> > at > > > >> > > > > >> > > org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:210) > > > >> > at > > > >> > > > > >> > > org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:271) > > > >> > at > > > >> > > > > >> > > org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:235) > > > >> > at > > > >> > > > > >> > > org.apache.http.impl.conn.AbstractClientConnAdapter.receiveResponseHeader(AbstractClientConnAdapter.java:259) > > > >> > at > > > >> > > > > >> > > org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:292) > > > >> > at > > > >> > > > > >> > > org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:126) > > > >> > at > > > >> > > > > >> > > org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:410) > > > >> > at > > > >> > > > > >> > > org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:555) > > > >> > ... 37 more > > > >> > |#] > > > >> > > > > >> > > > > >> > > > > >> > ##### HTTP CLIENT SETTINGS ###### > > > >> > > > > >> > HttpConnectionParams.setTcpNoDelay(params, true); > > > >> > HttpConnectionParams.setLinger(params, 30); > > > >> > HttpConnectionParams.setConnectionTimeout(params, 30000); > > > >> > HttpConnectionParams.setSoTimeout(params, 30000); > > > >> > HttpProtocolParams.setVersion(params, HttpVersion.HTTP_1_1); > > > >> > HttpClientParams.setRedirecting(params, false); > > > >> > HttpProtocolParams.setUseExpectContinue(params, false); > > > >> > ConnManagerParams.setMaxConnectionsPerRoute(params, new > > > >> > ConnPerRouteBean(50)); > > > >> > ConnManagerParams.setMaxTotalConnections(params, 500); > > > >> > HttpClientParams.setCookiePolicy(params, > > > >> > CookiePolicy.BROWSER_COMPATIBILITY); > > > >> > > > >> --------------------------------------------------------------------- > > > >> 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] > > > > > > --------------------------------------------------------------------- > 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]
