IOException: Socket read failed using Apache 2, mod_jk and Tomcat over AJP

Question

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

Solution

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.

Comments

[Christopher Schultz]

Do you know what happens on the client in these cases? It's possible this is just a client dropping the connection.

[Gurvinder Rajpal]

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)

[Gurvinder Rajpal]

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?

[gfountis]

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]

Do me a favor and access the service directly via Tomcat and not via Apache/AJP and see if the timeouts occur again.

[Gurvinder Rajpal]

that will not be possible as I have about 5000 users out there using the app with the URL connecting to port 80 ;-)

[gfountis]

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.

[polm23]

Did this fix the problem?

[asmodai]

Upvoted this answer because it fits perfectly for a case on Ubuntu server with Apache + Tomcat where we run into the exact same problem. Thanks for this.