Ok, I found the issue with faulty server. The problem is that when client uses compression server responds with 20 bytes of data for a 204 response which is causing the issue.
Sorry for the false alarm. Thanks a lot guys. On Mon, Jul 14, 2014 at 10:01 AM, srikalyan swayampakula < [email protected]> wrote: > Hi Oleg, > > I guess I found the root cause it is due to some garbage value getting > into the line buffer representing status line which is not present in the > status line. I am using the same logging as above and I am getting the > following log output. I will reply to your actual request soon sorry for > the delay. > > Sun Jul 13 22:30:12.243 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.impl.execchain.MainClientExec | DEBUG | Executing request > DELETE /service/delete//653 HTTP/1.1 > Sun Jul 13 22:30:12.243 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.impl.execchain.MainClientExec | DEBUG | Proxy auth state: > UNCHALLENGED > Sun Jul 13 22:30:12.244 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.headers | DEBUG | http-outgoing-1 >> DELETE > /service/delete//653 HTTP/1.1 > Sun Jul 13 22:30:12.244 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.headers | DEBUG | http-outgoing-1 >> Authorization: Basic > dmNpLXZhZ3JhbnQta25pZ2h0OnZjaS12YWdyYW50LWtuaWdodA== > Sun Jul 13 22:30:12.244 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.headers | DEBUG | http-outgoing-1 >> Accept: > application/json; charset=UTF-8 > Sun Jul 13 22:30:12.244 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.headers | DEBUG | http-outgoing-1 >> Host: localhost > Sun Jul 13 22:30:12.244 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.headers | DEBUG | http-outgoing-1 >> Connection: Keep-Alive > Sun Jul 13 22:30:12.245 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.headers | DEBUG | http-outgoing-1 >> User-Agent: > Apache-HttpClient/4.3.4 (java 1.5) > Sun Jul 13 22:30:12.245 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.headers | DEBUG | http-outgoing-1 >> Cookie: > JSESSIONID=44CDB11E4DDC92B14A17EAC4F27899F5 > Sun Jul 13 22:30:12.245 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.headers | DEBUG | http-outgoing-1 >> Cookie2: $Version=1 > Sun Jul 13 22:30:12.245 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.headers | DEBUG | http-outgoing-1 >> Accept-Encoding: > gzip,deflate > Sun Jul 13 22:30:12.245 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 >> "DELETE > /service/delete//653 HTTP/1.1[\r][\n]" > Sun Jul 13 22:30:12.245 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 >> "Authorization: Basic > dmNpLXZhZ3JhbnQta25pZ2h0OnZjaS12YWdyYW50LWtuaWdodA==[\r][\n]" > Sun Jul 13 22:30:12.246 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 >> "Accept: > application/json; charset=UTF-8[\r][\n]" > Sun Jul 13 22:30:12.246 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 >> "Host: localhost[\r][\n]" > Sun Jul 13 22:30:12.246 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 >> "Connection: > Keep-Alive[\r][\n]" > Sun Jul 13 22:30:12.246 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 >> "User-Agent: > Apache-HttpClient/4.3.4 (java 1.5)[\r][\n]" > Sun Jul 13 22:30:12.246 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 >> "Cookie: > JSESSIONID=44CDB11E4DDC92B14A17EAC4F27899F5[\r][\n]" > Sun Jul 13 22:30:12.246 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 >> "Cookie2: > $Version=1[\r][\n]" > Sun Jul 13 22:30:12.247 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 >> "Accept-Encoding: > gzip,deflate[\r][\n]" > Sun Jul 13 22:30:12.247 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 >> "[\r][\n]" > *Sun Jul 13 22:30:12.348 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 << "HTTP/1.1 204 No > Content[\r][\n]"* > *Sun Jul 13 22:30:12.348 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 << "Date: Mon, 14 Jul 2014 > 05:30:12 GMT[\r][\n]"* > *Sun Jul 13 22:30:12.349 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 << "Server: Apache[\r][\n]"* > *Sun Jul 13 22:30:12.349 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 << > "Access-Control-Allow-Origin: *[\r][\n]"* > *Sun Jul 13 22:30:12.349 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 << > "Access-Control-Allow-Methods: GET, POST, PUT, DELETE, OPTIONS[\r][\n]"* > *Sun Jul 13 22:30:12.349 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 << > "Access-Control-Allow-Headers: Authorization, Content-Type[\r][\n]"* > *Sun Jul 13 22:30:12.350 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 << "Access-Control-Max-Age: > 86400[\r][\n]"* > *Sun Jul 13 22:30:12.350 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 << "Content-Encoding: > gzip[\r][\n]"* > *Sun Jul 13 22:30:12.350 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 << "Content-Length: > 20[\r][\n]"* > *Sun Jul 13 22:30:12.350 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 << "Keep-Alive: timeout=15, > max=65[\r][\n]"* > *Sun Jul 13 22:30:12.350 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 << "Connection: > Keep-Alive[\r][\n]"* > *Sun Jul 13 22:30:12.351 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 << "Content-Type: > application/json;charset=UTF-8[\r][\n]"* > *Sun Jul 13 22:30:12.351 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.wire | DEBUG | http-outgoing-1 << "[\r][\n]"* > Sun Jul 13 22:30:12.351 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG |* Testing the line: > ^_<U+008B>^H^@^@^@^@^@^@^@^C^@^@^@^@^@^@^@^@^@HTTP/1.1 204 No Content the > cursor is: [0>0>43] the protname is: HTTP* > Sun Jul 13 22:30:12.351 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG |* buffer.charAt(0+j) == > protoname.charAt(j) : ^_ == H ok is: false* > Sun Jul 13 22:30:12.351 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | The value of ok after for > is : ^_<U+008B>^H^@^@^@^@^@^@^@^C^@^@^@^@^@^@^@^@^@HTTP/1.1 204 No Content > the cursor is: [0>0>43] the protname is: HTTP the index is: 0 and ok is: > false > Sun Jul 13 22:30:12.352 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | The value of ok after > last if is : ^_<U+008B>^H^@^@^@^@^@^@^@^C^@^@^@^@^@^@^@^@^@HTTP/1.1 204 No > Content the cursor is: [0>0>43] the protname is: HTTP the index is: 0 and > ok is: false > Sun Jul 13 22:30:12.352 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.impl.conn.DefaultHttpResponseParser | DEBUG | Garbage in > response: ^_<U+008B>^H^@^@^@^@^@^@^@^C^@^@^@^@^@^@^@^@^@HTTP/1.1 204 No > Content > Sun Jul 13 22:30:12.352 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | Testing the line: Date: > Mon, 14 Jul 2014 05:30:12 GMT the cursor is: [0>0>35] the protname is: HTTP > Sun Jul 13 22:30:12.352 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | buffer.charAt(0+j) == > protoname.charAt(j) : D == H ok is: false > Sun Jul 13 22:30:12.352 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | The value of ok after for > is : Date: Mon, 14 Jul 2014 05:30:12 GMT the cursor is: [0>0>35] the > protname is: HTTP the index is: 0 and ok is: false > Sun Jul 13 22:30:12.353 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | The value of ok after > last if is : Date: Mon, 14 Jul 2014 05:30:12 GMT the cursor is: [0>0>35] > the protname is: HTTP the index is: 0 and ok is: false > Sun Jul 13 22:30:12.353 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.impl.conn.DefaultHttpResponseParser | DEBUG | Garbage in > response: Date: Mon, 14 Jul 2014 05:30:12 GMT > Sun Jul 13 22:30:12.353 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | Testing the line: Server: > Apache the cursor is: [0>0>14] the protname is: HTTP > Sun Jul 13 22:30:12.353 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | buffer.charAt(0+j) == > protoname.charAt(j) : S == H ok is: false > Sun Jul 13 22:30:12.353 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | The value of ok after for > is : Server: Apache the cursor is: [0>0>14] the protname is: HTTP the index > is: 0 and ok is: false > Sun Jul 13 22:30:12.354 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | The value of ok after > last if is : Server: Apache the cursor is: [0>0>14] the protname is: HTTP > the index is: 0 and ok is: false > Sun Jul 13 22:30:12.354 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.impl.conn.DefaultHttpResponseParser | DEBUG | Garbage in > response: Server: Apache > Sun Jul 13 22:30:12.354 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | Testing the line: > Access-Control-Allow-Origin: * the cursor is: [0>0>30] the protname is: HTTP > Sun Jul 13 22:30:12.354 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | buffer.charAt(0+j) == > protoname.charAt(j) : A == H ok is: false > Sun Jul 13 22:30:12.354 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | The value of ok after for > is : Access-Control-Allow-Origin: * the cursor is: [0>0>30] the protname > is: HTTP the index is: 0 and ok is: false > Sun Jul 13 22:30:12.355 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | The value of ok after > last if is : Access-Control-Allow-Origin: * the cursor is: [0>0>30] the > protname is: HTTP the index is: 0 and ok is: false > Sun Jul 13 22:30:12.355 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.impl.conn.DefaultHttpResponseParser | DEBUG | Garbage in > response: Access-Control-Allow-Origin: * > Sun Jul 13 22:30:12.355 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | Testing the line: > Access-Control-Allow-Methods: GET, POST, PUT, DELETE, OPTIONS the cursor > is: [0>0>61] the protname is: HTTP > Sun Jul 13 22:30:12.355 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | buffer.charAt(0+j) == > protoname.charAt(j) : A == H ok is: false > Sun Jul 13 22:30:12.355 PDT 2014 | "ajp-bio-8009"-exec-2 | > org.apache.http.message.BasicLineParser | DEBUG | The value of ok after for > is : Access-Control-Allow-Methods: GET, POST, PUT, DELETE, OPTIONS the > cursor is: [0>0>61] the protname is: HTTP the index is: 0 and ok is: false > > > As you can see in the highlighted section that wire is saying that it has > no garbage values at the start of the status line but there is some garbage > value in the buffer passed to the method hasProtocolVersion. This seems > like something from the previous request. > > > > On Sun, Jul 13, 2014 at 5:38 PM, srikalyan swayampakula < > [email protected]> wrote: > >> Thanks Oleg, Seems like a faulty server issue (I am really sure :) ) but >> I could pin point the issue by adding more logging to BasicLineParser in >> the method hasProtocolVersion like this >> >> {code} >> public boolean hasProtocolVersion(final CharArrayBuffer buffer, >> final ParserCursor cursor) { >> Args.notNull(buffer, "Char array buffer"); >> Args.notNull(cursor, "Parser cursor"); >> int index = cursor.getPos(); >> >> final String protoname = this.protocol.getProtocol(); >> final int protolength = protoname.length(); >> >> if (this.log.isDebugEnabled()) { >> this.log.debug("Testing the line: " + buffer.toString() + " the >> cursor is: " + cursor >> + " the protname is: " + protoname); >> } >> >> if (buffer.length() < protolength+4) >> { >> >> return false; // not long enough for "HTTP/1.1" >> } >> >> if (index < 0) { >> // end of line, no tolerance for trailing whitespace >> // this works only for single-digit major and minor version >> index = buffer.length() -4 -protolength; >> } else if (index == 0) { >> // beginning of line, tolerate leading whitespace >> while ((index < buffer.length()) && >> HTTP.isWhitespace(buffer.charAt(index))) { >> index++; >> } >> } // else within line, don't tolerate whitespace >> >> >> if (index + protolength + 4 > buffer.length()) { >> if (this.log.isDebugEnabled()) { >> this.log.debug("Returning false for buffer: " + >> buffer.toString() + " the cursor is: " + cursor >> + " the protname is: " + protoname +" the >> index is: "+index); >> } >> return false; >> } >> >> >> // just check protocol name and slash, no need to analyse the >> version >> boolean ok = true; >> for (int j=0; ok && (j<protolength); j++) { >> ok = (buffer.charAt(index+j) == protoname.charAt(j)); >> if (this.log.isDebugEnabled()) { >> this.log.debug( >> "buffer.charAt("+index+"+j) == protoname.charAt(j) : " + >> buffer.charAt(index + j) >> + " == " + protoname.charAt(j) + " ok is: " + ok); >> } >> } >> >> if (this.log.isDebugEnabled()) { >> this.log.debug("The value of ok after for is : " + >> buffer.toString() + " the cursor is: " + cursor >> + " the protname is: " + protoname +" the index >> is: "+index + " and ok is: "+ok); >> } >> >> if (ok) { >> ok = (buffer.charAt(index+protolength) == '/'); >> } >> >> if (this.log.isDebugEnabled()) { >> this.log.debug("The value of ok after last if is : " + >> buffer.toString() + " the cursor is: " + cursor >> + " the protname is: " + protoname +" the index >> is: "+index + " and ok is: "+ok); >> } >> >> return ok; >> } >> {code} >> >> and I found the stack trace to be >> >> >> Sun Jul 13 00:51:06.140 PDT 2014 | "ajp-bio-8009"-exec-2 | >> org.apache.http.message.BasicLineParser | DEBUG | Testing the line: >> ^_<U+008B>^H^@^@^@^@^@^@^@^C^@^@^@^@^@^@^@^@^@HTTP/1.1 204 No Con >> tent the cursor is: [0>0>43] the protname is: HTTP >> Sun Jul 13 00:51:06.140 PDT 2014 | "ajp-bio-8009"-exec-2 | >> org.apache.http.message.BasicLineParser | DEBUG | buffer.charAt(0+j) == >> protoname.charAt(j) : ^_ == H ok is: false >> Sun Jul 13 00:51:06.141 PDT 2014 | "ajp-bio-8009"-exec-2 | >> org.apache.http.message.BasicLineParser | DEBUG | The value of ok after for >> is : ^_<U+008B>^H^@^@^@^@^@^@^@^C^@^@^@^@^@^@^@^@^@HTTP/1 >> .1 204 No Content the cursor is: [0>0>43] the protname is: HTTP the index >> is: 0 and ok is: false >> Sun Jul 13 00:51:06.141 PDT 2014 | "ajp-bio-8009"-exec-2 | >> org.apache.http.message.BasicLineParser | DEBUG | The value of ok after >> last if is : ^_<U+008B>^H^@^@^@^@^@^@^@^C^@^@^@^@^@^@^@^@^@HT >> TP/1.1 204 No Content the cursor is: [0>0>43] the protname is: HTTP the >> index is: 0 and ok is: false >> Sun Jul 13 00:51:06.141 PDT 2014 | "ajp-bio-8009"-exec-2 | >> org.apache.http.impl.conn.DefaultHttpResponseParser | DEBUG | Garbage in >> response: ^_<U+008B>^H^@^@^@^@^@^@^@^C^@^@^@^@^@^@^@^@^@HTTP >> /1.1 204 No Content >> >> >> funny thing is we are not doing any weird just with the server settings >> we are using apache server with a tomcat running behind. >> >> I will dig deeper and let you know if there is an issue and really sorry >> if this a false alarm. >> >> Thank you. >> >> >> >> On Sun, Jul 13, 2014 at 4:43 AM, Oleg Kalnichevski <[email protected]> >> wrote: >> >>> On Sat, 2014-07-12 at 08:18 -0700, srikalyan swayampakula wrote: >>> > Hi, >>> > >>> > I am getting a ClientProtocolException for a delete request. The >>> response >>> > is "204 No Content" and seems to be a bug in httpclient. >>> > >>> > I am creating the transport like this >>> > >>> > transport = new ApacheHttpTransport(); >>> > >>> > final RequestConfig defaultRequestConfig = >>> RequestConfig.DEFAULT; >>> > >>> > final RegistryBuilder<ConnectionSocketFactory> builder = >>> > RegistryBuilder.<ConnectionSocketFactory>create() >>> > .register("http", >>> > PlainConnectionSocketFactory.getSocketFactory()); >>> > >>> > // allow a customized SSLConnectionSocketFactory to be used >>> > if (this.sslConnectionSocketFactory != null) { >>> > builder.register("https", this.sslConnectionSocketFactory); >>> > } else { >>> > builder.register("https", >>> > SSLConnectionSocketFactory.getSocketFactory()); >>> > } >>> > >>> > final Registry<ConnectionSocketFactory> registry = >>> builder.build(); >>> > >>> > final PoolingHttpClientConnectionManager cm = >>> > new PoolingHttpClientConnectionManager(registry); >>> > >>> > // Increase max total connection >>> > cm.setMaxTotal(this.maxConnections); >>> > // Increase default max connection per route >>> > cm.setDefaultMaxPerRoute(this.maxConnections); >>> > //close expired connections >>> > cm.closeExpiredConnections(); >>> > >>> > >>> > >>> > final HttpClient client = HttpClientBuilder.create() >>> > >>> .setConnectionManager(cm) >>> > >>> > .setDefaultRequestConfig(defaultRequestConfig) >>> > >>> > .setMaxConnPerRoute(this.maxConnections) >>> > >>> > .setConnectionReuseStrategy( >>> > >>> > DefaultConnectionReuseStrategy.INSTANCE) >>> > .build(); >>> > >>> > transport.setClient(client); >>> > transport.setServerUrl(serverUrl); >>> > transport.setUsername(username); >>> > transport.setPassword(password); >>> > transport.setBasicAuth(hasText(username) || hasText(password)); >>> > >>> > return transport; >>> > >>> > and calling transport.delete(httpparams) and the server it is trying to >>> > call seem to be fine no stack trace and access log seems behave as >>> expected. >>> > >>> > I enabled some debug logging which is indicating that there might be >>> a bug >>> > with the library >>> > >>> >>> Please reproduce the problem outside the servlet container and post the >>> _complete_ wire / context of the session to this list >>> >>> http://hc.apache.org/httpcomponents-client-4.3.x/logging.html >>> >>> Oleg >>> >>> >>> >>> --------------------------------------------------------------------- >>> To unsubscribe, e-mail: [email protected] >>> For additional commands, e-mail: [email protected] >>> >>> >> >> >> -- >> >> -SK. >> > > > > -- > > -SK. > -- -SK.
