Ah ha, thanks very much for taking the time to investigate - I'll go beat find out what app server is being used and beat them up ! All the best,
Sam 2009/4/14 Oleg Kalnichevski <[email protected]> > 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] > >
