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.
