4

I am getting the following Exception from time to time when my users are connecting with their Android devices to out JSON Rest Service:

java.io.IOException: Socket read failed
       at org.apache.coyote.ajp.AjpProcessor.read(AjpProcessor.java:313)
       at org.apache.coyote.ajp.AjpProcessor.readMessage(AjpProcessor.java:364)
       at org.apache.coyote.ajp.AjpProcessor.receive(AjpProcessor.java:331)
       at org.apache.coyote.ajp.AbstractAjpProcessor.refillReadBuffer(AbstractAjpProcessor.java:614)
       at org.apache.coyote.ajp.AbstractAjpProcessor$SocketInputBuffer.doRead(AbstractAjpProcessor.java:1065)
       at org.apache.coyote.Request.doRead(Request.java:422)
       at org.apache.catalina.connector.InputBuffer.realReadBytes(InputBuffer.java:290)
       at org.apache.tomcat.util.buf.ByteChunk.substract(ByteChunk.java:431)
       at org.apache.catalina.connector.InputBuffer.read(InputBuffer.java:315)
       at org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:200)
       at org.codehaus.jackson.impl.ByteSourceBootstrapper.ensureLoaded(ByteSourceBootstrapper.java:340)
       at org.codehaus.jackson.impl.ByteSourceBootstrapper.detectEncoding(ByteSourceBootstrapper.java:137)
       at org.codehaus.jackson.impl.ByteSourceBootstrapper.constructParser(ByteSourceBootstrapper.java:197)
       at org.codehaus.jackson.JsonFactory._createJsonParser(JsonFactory.java:542)
       at org.codehaus.jackson.JsonFactory.createJsonParser(JsonFactory.java:389)
       at org.codehaus.jackson.map.ObjectMapper.readValue(ObjectMapper.java:1454)
       at org.springframework.http.converter.json.MappingJacksonHttpMessageConverter.readInternal(MappingJacksonHttpMessageConverter.java:124)
       at org.springframework.http.converter.AbstractHttpMessageConverter.read(AbstractHttpMessageConverter.java:153)
       at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.readWithMessageConverters(HandlerMethodInvoker.java:641)
       at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.resolveRequestBody(HandlerMethodInvoker.java:605)
       at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.resolveHandlerArguments(HandlerMethodInvoker.java:354)
       at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(HandlerMethodInvoker.java:171)
       at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:436)
       at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.handle(AnnotationMethodHandlerAdapter.java:424)
       at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:923)
       at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:852)
       at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:882)
       at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:789)

I am running

  • Apache/2.2.20
  • mod_jk 1.2.36
  • Tomcat 7.0.27

Could this have something to do with a timeout? Like the client closes the connection and the server is not able to read from the socket anymore? Or is it more likely a problem of the server configuration?

UPDATE:

Doing some Apache log awk I found the following Apache log lines corresponding to those Tomcat log exceptions:

192.186.30.116 - - [25/Jun/2012:10:47:14 +0200] "POST /myapp/methodX HTTP/1.1" 400 145 "-" "clientApp BlackBerry9360/7.0.0.530 VendorID/168" 10012655 
192.186.30.120 - - [25/Jun/2012:10:53:13 +0200] "POST /myapp/methodY HTTP/1.1" 400 145 "-" "clientApp BlackBerry9800/6.0.0.668 VendorID/124" 10012164 
192.186.30.116 - - [25/Jun/2012:10:53:36 +0200] "POST /myapp/methodZ HTTP/1.1" 400 145 "-" "clientApp BlackBerry9360/7.0.0.530 VendorID/168" 10012677 
192.82.68.16 - - [25/Jun/2012:11:22:31 +0200] "POST /myapp/methodX HTTP/1.1" 400 145 "-" "clientApp BlackBerry9930/7.1.0.402 VendorID/104" 10012667 
192.82.68.16 - - [25/Jun/2012:11:23:21 +0200] "POST /myapp/methodZ HTTP/1.1" 400 145 "-" "clientApp BlackBerry9930/7.1.0.402 VendorID/104" 10012562 

You can see the status code 400 Bad Request sent to the clients for those requests.

The large numbers at the end of the line (e.g. 10012562) show the time the request was processed on the server in microseconds: 10012562 = about 10 seconds

Looks like the connection is somehow terminated after ten seconds? I looked into the AJP configuration but there is no timeout defined - 10 seconds would be the timeout for async requests which I am not using

Thomas Einwaller
  • 288
  • 1
  • 3
  • 12
  • Do you know what happens on the client in these cases? It's possible this is just a client dropping the connection. – Christopher Schultz May 24 '12 at 16:31
  • that is what I thought first but we have clients for BlackBerry, Android and iOS and all those platforms show the same error (though it happens more frequent on the BlackBerry clients) – Thomas Einwaller Jun 29 '12 at 18:51

2 Answers2

3

I found the reason. Problem was caused by default configuration of Apache module mod_reqtimeout:

<IfModule reqtimeout_module>

# mod_reqtimeout limits the time waiting on the client to prevent an
# attacker from causing a denial of service by opening many connections
# but not sending requests. This file tries to give a sensible default
# configuration, but it may be necessary to tune the timeout values to
# the actual situation. Note that it is also possible to configure
# mod_reqtimeout per virtual host.


# Wait max 20 seconds for the first byte of the request line+headers
# From then, require a minimum data rate of 500 bytes/s, but don't
# wait longer than 40 seconds in total.
# Note: Lower timeouts may make sense on non-ssl virtual hosts but can
# cause problem with ssl enabled virtual hosts: This timeout includes
# the time a browser may need to fetch the CRL for the certificate. If
# the CRL server is not reachable, it may take more than 10 seconds
# until the browser gives up.
RequestReadTimeout header=20-40,minrate=500

# Wait max 10 seconds for the first byte of the request body (if any)
# From then, require a minimum data rate of 500 bytes/s
RequestReadTimeout body=10,minrate=500

</IfModule>

I guess BlackBerry clients wer hit harder because sending request body via RIM BIS infrastructure takes longer.

Set the value to 100 seconds and monitoring if clients are still affected.

Thomas Einwaller
  • 288
  • 1
  • 3
  • 12
0

It looks like its a timeout, but have you tried (or is it possible) to access the REST service directly via Tomcat? (and not pass through apache/ajp). If you try it and you see that you don't get these exceptions anymore, it may be a apache2/mod_jk thing.

In my previous job I discovered that some versions of mod_jk worked better with apache2 (of course, we didn't really put this to a strict test, we just used the versions that seemed to work everywhere without changing them as there was no need)

gfountis
  • 1
  • 2
  • I was thinking it has to be some kind of timeout - could it be that the timeout is cause by the client? e.g. the client (im my case a BlackBerry Java app) closes the connection while the server wants to read some of the sent request body data? – Thomas Einwaller Jun 15 '12 at 12:13
  • Have no idea! I would first try to make sure its not an apache2/mod_jk thing before starting to bleed from my eyes doing client-side tests =) – gfountis Jun 16 '12 at 10:27
  • I update the question with information from the apache log files – Thomas Einwaller Jun 29 '12 at 12:48
  • Do me a favor and access the service directly via Tomcat and not via Apache/AJP and see if the timeouts occur again. – gfountis Jun 29 '12 at 13:15
  • that will not be possible as I have about 5000 users out there using the app with the URL connecting to port 80 ;-) – Thomas Einwaller Jun 29 '12 at 18:50
  • I didn't mean shutting down apache/AJP or anything. What I meant is, point a Blackberry or something to the service's URL but use Tomcat's port instead of Apache's and see if you get any delays. – gfountis Jul 01 '12 at 13:43