[HTTPCORE-140] When using a ThrottlingHttpServiceHandler, a connection timeout does not relinquish the lock in SharedInputBuffer.waitForData()

• Type: Bug
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 4.0-alpha6
• Fix Version/s: 4.0-beta2
• Component/s: HttpCore NIO
• Environment: Linux RHEL 4, jdk 1.6.0_02-b05.
• Assignee: Unassigned
• Reporter: Lorenzo Moretti
• Created: 17/Jan/08 15:23
• Updated: 09/Feb/09 21:38
• Resolved: 26/Jan/08 12:52

Description

When the ThrottlingHttpServiceHandler.requestReceived() is invoked, the request handling can be passed to a worker thread through an implementation of org.apache.http.util.concurrent.Executor before the whole entity content (if any) is received by the server. If the worker thread tries to read the request entity content through HttpEntityEnclosingRequest.getEntity().getContent().read() before the whole content is received, then it waits for data using SharedInputBuffer.waitForData(). If the connection is closed through a socket timeout, waitForData() does not return, and the worker thread does not terminate.

I have set the severity to minor because there is a simple workaround: invoking ThrottlingHttpServiceHandler.shutdownConnection(conn, null) when ThrottlingHttpServiceHandler.closed() is called (an anonymous class that inherits from ThrottlingHttpServiceHandler works fine): shutdownConnection() invokes ServerConnState.shutdown() which in turn shuts down the SharedInputBuffer, interrupting the wait.
I am not sure however if this is the right way to fix the issue.

At the bottom is the source code for a simple application to demonstrate the issue. The code uses a copy of the NHttpServer found in the examples directory with a few modifications:
1) The socket timeout is set to 2 seconds.
2) The BufferingHttpServiceHandler was replaced with a ThrottlingHttpServiceHandler that spawns a thread through its executor to handle every incoming request.
3) The EventLogger prints the connection hash code in parenthesis to easily identify connection instances when closed.

Following is the console output (comments below) for a given execution:

=======
Request started at 09:47:07.007
Connection open: [/127.0.0.1:58694] (31578843)
Connection timed out: [closed] (31578843)
Connection closed: [closed] (31578843)
Response content
><
Request completed (4100 ms)

Request started at 09:47:11.011
Connection open: [/127.0.0.1:58695] (367156)
Incoming entity content (bytes): 5
Serving file /home/lorenzo/bla.html
Connection closed: [closed] (367156)
Response content
->HTTP/1.1 200 OK
Date: Thu, 17 Jan 2008 14:47:11 GMT
Server: Jakarta-HttpComponents-NIO/1.1
Content-Length: 4
Content-Type: text/html
Connection: Close

bla
<-
Request completed (137 ms)
=======

The first request (09:47:07.007) is too slow to send the entity content to the server. The server times out the connection, and the response consumer does not get anything back from the server (text between '>' and '<' is empty), which is expected.
The second request (09:47:11.011) shows that the server is still able to function perfectly well: the entity content is sent in a reasonable time span, and file /bla.html is served back to the client (the file contains the string "bla").

The thread dump (taken at 09:47:25) shows the executor thread for the 09:47:07.007 request still waiting for data (the reactor thread and the dispatch thread are polling events normally, I have ommitted their dump). The executor for the 09:47:11.011 request has terminated.

=======
"Executor_09:47:07.007" prio=10 tid=0x083c5000 nid=0x59e5 in Object.wait() [0xad498000..0xad498ec0]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

• waiting on <0xadca3968> (a java.lang.Object)
  at java.lang.Object.wait(Object.java:485)
  at org.apache.http.nio.util.SharedInputBuffer.waitForData(SharedInputBuffer.java:105)
• locked <0xadca3968> (a java.lang.Object)
  at org.apache.http.nio.util.SharedInputBuffer.read(SharedInputBuffer.java:155)
• locked <0xadca3968> (a java.lang.Object)
  at org.apache.http.nio.entity.ContentInputStream.read(ContentInputStream.java:59)
  at org.apache.http.util.EntityUtils.toByteArray(EntityUtils.java:79)
  at TestExecutorTermination$NHttpServer$HttpFileHandler.handle(TestExecutorTermination.java:314)
  at org.apache.http.nio.protocol.ThrottlingHttpServiceHandler.handleRequest(ThrottlingHttpServiceHandler.java:477)
  at org.apache.http.nio.protocol.ThrottlingHttpServiceHandler.access$000(ThrottlingHttpServiceHandler.java:91)
  at org.apache.http.nio.protocol.ThrottlingHttpServiceHandler$1.run(ThrottlingHttpServiceHandler.java:195)
  at TestExecutorTermination$SimpleExecutor$1.run(TestExecutorTermination.java:208)
  =======

The source code:

=======
import java.io.ByteArrayOutputStream;
import java.io.File;
import java.io.IOException;
import java.io.InputStream;
import java.io.InterruptedIOException;
import java.io.OutputStream;
import java.io.OutputStreamWriter;
import java.net.InetSocketAddress;
import java.net.Socket;
import java.net.URLDecoder;
import java.text.DateFormat;
import java.text.SimpleDateFormat;
import java.util.Date;

import org.apache.http.HttpEntity;
import org.apache.http.HttpEntityEnclosingRequest;
import org.apache.http.HttpException;
import org.apache.http.HttpRequest;
import org.apache.http.HttpResponse;
import org.apache.http.HttpStatus;
import org.apache.http.MethodNotSupportedException;
import org.apache.http.entity.ContentProducer;
import org.apache.http.entity.EntityTemplate;
import org.apache.http.entity.FileEntity;
import org.apache.http.impl.DefaultConnectionReuseStrategy;
import org.apache.http.impl.DefaultHttpResponseFactory;
import org.apache.http.impl.nio.DefaultServerIOEventDispatch;
import org.apache.http.impl.nio.reactor.DefaultListeningIOReactor;
import org.apache.http.nio.NHttpConnection;
import org.apache.http.nio.NHttpServerConnection;
import org.apache.http.nio.protocol.EventListener;
import org.apache.http.nio.protocol.ThrottlingHttpServiceHandler;
import org.apache.http.nio.reactor.IOEventDispatch;
import org.apache.http.nio.reactor.ListeningIOReactor;
import org.apache.http.params.BasicHttpParams;
import org.apache.http.params.CoreConnectionPNames;
import org.apache.http.params.CoreProtocolPNames;
import org.apache.http.params.HttpParams;
import org.apache.http.protocol.BasicHttpProcessor;
import org.apache.http.protocol.HttpContext;
import org.apache.http.protocol.HttpRequestHandler;
import org.apache.http.protocol.HttpRequestHandlerRegistry;
import org.apache.http.protocol.ResponseConnControl;
import org.apache.http.protocol.ResponseContent;
import org.apache.http.protocol.ResponseDate;
import org.apache.http.protocol.ResponseServer;
import org.apache.http.util.EntityUtils;
import org.apache.http.util.concurrent.Executor;

public class TestExecutorTermination
{
/**

• This value is used to configure the HttpParams and the delay in posting the
• HttpRequest entity content.
  */
  static private final int SOCKET_TIMEOUT = 2000;

static private final String DOC_ROOT = "/home/lorenzo/";

/**

• HTTP POST request sent to the server. It has an incomplete content. The remaining character
• will be sent to the server after a delay, to simulate a slow producer.
• The document bla.html must be present in the doc root.
  */
  static private final String REQUEST =
  "POST /bla.html HTTP/1.1\r\nConnection: Close\r\nContent-Length: 5\r\n\r\n1234";

/**

• User-friendly time to math the time an HTTP request is issued and the corresponding
• executor thread (the time is in the thread name and will be visible using a
• thread dump).
  */
  static private final DateFormat DATE_FORMAT = new SimpleDateFormat( "hh:mm:ss.sss" );

/**

• Start an HTTP server, perform a first request that creates an executor thread that
• hangs, then perform a second successful request.
  */
  static public void main( String[] args ) throws Exception
  {
  Thread.currentThread().setName( "RequestProducer" );

// Start NHttpServer on a separate thread
Thread server = new Thread( "server" )
{
public void run()
{
try
{
NHttpServer.main( new String[]

{ DOC_ROOT }

);
}
catch ( Throwable t )

{ t.printStackTrace(); }
}
};
server.start();

// Wait for the server to be up (hopefully)
Thread.sleep( 1000 );

hangExecutorThread();
System.out.println( "\n\n" );
successfulExecutorTermination();
}

/**
* Connect to the server, but send the whole entity before a socket timeout occurs
*/
static private void successfulExecutorTermination() throws Exception
{ queryHttpServer( SOCKET_TIMEOUT - 1900 ); }

/**
* Connect to the server, but send the whole entity after a socket timeout
* has closed the connection
*/
static private void hangExecutorThread() throws Exception
{ queryHttpServer( SOCKET_TIMEOUT * 2 ); }

/**
* Will start to write a post request to the HTTP server, start a thread
* awaiting for the response, and then will finish writing the request to the
* server after a delay.
*
* The file bla.html exists in the doc root and contains the string "bla"
*
* It seems that if the delay is longer than the configured socket timeout,
* the executor thread will never terminate (hangs inside
* org.apache.http.nio.util.SharedInputBuffer.waitForData()). If the delay is shorter than
* the socket timeout, then all content is sent to the server and the executor thread
* terminates properly.
*
* @param contentDelay
* millis before the entity content is completely sent to the
* HTTP server.
*/
static private void queryHttpServer( int contentDelay ) throws Exception
{
Date start = new Date();
System.out.println( "Request started at " + DATE_FORMAT.format( start ) + "" );

// start the producer, but send only 4 of the 5 expected bytes of the entity content
final Socket socket = new Socket( "localhost", 8080 );
socket.getOutputStream().write( REQUEST.getBytes() );

// start the consumer on a different thread
Thread client = new Thread( "ResponseConsumer" )
{
public void run()
{
try
{ System.out.println( "Response content\n" + "->" + getResponse( socket.getInputStream() ) + "<-" ); }
catch ( Throwable t )
{ t.printStackTrace(); }

}
};
client.start();

// simulate a slow producer: the end of the content is sent after contentDelay
Thread.sleep( contentDelay );
socket.getOutputStream().write( "5".getBytes() );

// wait for the consumer to finish
client.join();
socket.close();

// console feedback to know when client.join() finishes
System.out.println( "Request completed (" + ( System.currentTimeMillis() - start.getTime() ) + " ms)" );
}

static private String getResponse( InputStream is ) throws IOException
{
ByteArrayOutputStream bos = new ByteArrayOutputStream();
int b;
while ( ( b = is.read() ) != -1 )

{ bos.write( b ); }

return new String( bos.toByteArray() );
}

/**

• This executor starts a thread for the execution of the command.
• It is used by the ThrottlingHttpServiceHandler instance.
  */
  static private final class SimpleExecutor implements Executor
  {
  public void execute( final Runnable command )
  {
  new Thread( "Executor_" + DATE_FORMAT.format( new Date() ) )
  {
  public void run()
  Unknown macro: { try { command.run(); } catch ( Throwable t ) { t.printStackTrace(); } }

  }.start();
  }
  }

/**

• NHttpServer taken from the HttpCore example directory with the following
• changes:
• 1) Socket timeout set to 2 seconds.
• 2) BufferingHttpServiceHandler
• replaced with a ThrottlingHttpServiceHandler that uses a SimpleExecutor
• (defined above) to execute incoming requests.
• 3) EventLogger prints the connection hash code to easily identify connection instances
• when closed.
  */
  static private class NHttpServer {

public static void main(String[] args) throws Exception {
if (args.length < 1)

{ System.err.println("Please specify document root directory"); System.exit(1); }

HttpParams params = new BasicHttpParams(null);
params
.setIntParameter(CoreConnectionPNames.SO_TIMEOUT, SOCKET_TIMEOUT)
.setIntParameter(CoreConnectionPNames.SOCKET_BUFFER_SIZE, 8 * 1024)
.setBooleanParameter(CoreConnectionPNames.STALE_CONNECTION_CHECK, false)
.setBooleanParameter(CoreConnectionPNames.TCP_NODELAY, true)
.setParameter(CoreProtocolPNames.ORIGIN_SERVER, "Jakarta-HttpComponents-NIO/1.1");

BasicHttpProcessor httpproc = new BasicHttpProcessor();
httpproc.addInterceptor(new ResponseDate());
httpproc.addInterceptor(new ResponseServer());
httpproc.addInterceptor(new ResponseContent());
httpproc.addInterceptor(new ResponseConnControl());

/*
BufferingHttpServiceHandler handler = new BufferingHttpServiceHandler(
httpproc,
new DefaultHttpResponseFactory(),
new DefaultConnectionReuseStrategy(),
params);*/

ThrottlingHttpServiceHandler handler =
new ThrottlingHttpServiceHandler( httpproc,
new DefaultHttpResponseFactory(),
new DefaultConnectionReuseStrategy(),
new SimpleExecutor(),
params )
{
public void closed(final NHttpServerConnection conn)

{ //shutdownConnection( conn, null ); // un-comment this line for the workaround super.closed( conn ); }

};

// Set up request handlers
HttpRequestHandlerRegistry reqistry = new HttpRequestHandlerRegistry();
reqistry.register("*", new HttpFileHandler(args[0]));

handler.setHandlerResolver(reqistry);

// Provide an event logger
handler.setEventListener(new EventLogger());

IOEventDispatch ioEventDispatch = new DefaultServerIOEventDispatch(handler, params);
ListeningIOReactor ioReactor = new DefaultListeningIOReactor(1, params);
try

{ ioReactor.listen(new InetSocketAddress(8080)); ioReactor.execute(ioEventDispatch); }

catch (InterruptedIOException ex)

{ System.err.println("Interrupted"); }

catch (IOException e)

{ System.err.println("I/O error: " + e.getMessage()); }

System.out.println("Shutdown");
}

static class HttpFileHandler implements HttpRequestHandler {

private final String docRoot;

public HttpFileHandler(final String docRoot)

{ super(); this.docRoot = docRoot; }

public void handle(
final HttpRequest request,
final HttpResponse response,
final HttpContext context) throws HttpException, IOException {

String method = request.getRequestLine().getMethod().toUpperCase();
if (!method.equals("GET") && !method.equals("HEAD") && !method.equals("POST"))

{ throw new MethodNotSupportedException(method + " method not supported"); }

if (request instanceof HttpEntityEnclosingRequest)

{ HttpEntity entity = ((HttpEntityEnclosingRequest) request).getEntity(); byte[] entityContent = EntityUtils.toByteArray(entity); System.out.println("Incoming entity content (bytes): " + entityContent.length); }

String target = request.getRequestLine().getUri();
final File file = new File(this.docRoot, URLDecoder.decode(target, "UTF-8"));
if (!file.exists()) {

response.setStatusCode(HttpStatus.SC_NOT_FOUND);
EntityTemplate body = new EntityTemplate(new ContentProducer() {

public void writeTo(final OutputStream outstream) throws IOException

{ OutputStreamWriter writer = new OutputStreamWriter(outstream, "UTF-8"); writer.write("<html><body><h1>"); writer.write("File "); writer.write(file.getPath()); writer.write(" not found"); writer.write("</h1></body></html>"); writer.flush(); }

});
body.setContentType("text/html; charset=UTF-8");
response.setEntity(body);
System.out.println("File " + file.getPath() + " not found");

} else if (!file.canRead() || file.isDirectory()) {

response.setStatusCode(HttpStatus.SC_FORBIDDEN);
EntityTemplate body = new EntityTemplate(new ContentProducer() {

public void writeTo(final OutputStream outstream) throws IOException

{ OutputStreamWriter writer = new OutputStreamWriter(outstream, "UTF-8"); writer.write("<html><body><h1>"); writer.write("Access denied"); writer.write("</h1></body></html>"); writer.flush(); }

});
body.setContentType("text/html; charset=UTF-8");
response.setEntity(body);
System.out.println("Cannot read file " + file.getPath());

} else

{ response.setStatusCode(HttpStatus.SC_OK); FileEntity body = new FileEntity(file, "text/html"); response.setEntity(body); System.out.println("Serving file " + file.getPath()); }

}

}

static class EventLogger implements EventListener {

public void connectionOpen(final NHttpConnection conn)

{ System.out.println("Connection open: " + conn + " (" + conn.hashCode() + ")"); }

public void connectionTimeout(final NHttpConnection conn)

{ System.out.println("Connection timed out: " + conn + " (" + conn.hashCode() + ")"); }

public void connectionClosed(final NHttpConnection conn)

{ System.out.println("Connection closed: " + conn + " (" + conn.hashCode() + ")"); }

public void fatalIOException(final IOException ex, final NHttpConnection conn)

{ System.err.println("I/O error: " + ex.getMessage()); }

public void fatalProtocolException(final HttpException ex, final NHttpConnection conn)

{ System.err.println("HTTP error: " + ex.getMessage()); }

}
}
}
=======

Thanks for your time,

– Lorenzo