Some Eclipse Foundation services are deprecated, or will be soon. Please ensure you've read this important communication.
Bug 314567 - HttpClient asynchronous invocation of send causes the client to hang
Summary: HttpClient asynchronous invocation of send causes the client to hang
Status: RESOLVED WONTFIX
Alias: None
Product: Jetty
Classification: RT
Component: client (show other bugs)
Version: unspecified   Edit
Hardware: PC Windows XP
: P3 normal (vote)
Target Milestone: 7.0.2.RC0   Edit
Assignee: Jan Bartel CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-05-26 16:18 EDT by Sachin CLA
Modified: 2010-05-27 12:54 EDT (History)
2 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Sachin CLA 2010-05-26 16:18:10 EDT
Build Identifier: 

I am making an asynchronous HTTP POST request using HttpClient. Following is the snippet of the client code:

********************************
HttpClient client = new HttpClient();
client.setConnectorType(HttpClient.CONNECTOR_SELECT_CHANNEL);
client.setThreadPool(new QueuedThreadPool());
client.start();

ContentExchange exchange = new ContentExchange()
{
  protected void onResponseComplete() throws IOException
  {
   super.onResponseComplete();
   int status = getResponseStatus();
   if (status == 200){
     byte[] response = this.getResponseContentBytes();
     System.out.println("Read from Servlet response : " + new String(response));
   }
   else{
     System.out.println("Didn't get expected response");
   }                        
 }
};
exchange.setMethod("POST");
exchange.setURL("http://localhost:8080/MyServlet");
exchange.setRequestContent(new ByteArrayBuffer("hello from client"));
client.send(exchange);
********************************

MyServlet returns the same string that I am passing in request. onResponseComplete received the correct response. But my client application doesn't exit. It keeps on running and I have explicitly kill the java process. 


Reproducible: Always

Steps to Reproduce:
1. Use the above client with following simple servlet:

***************************
import javax.servlet.http.*;
import javax.servlet.ServletInputStream;
import java.io.*;

public class MyServlet extends HttpServlet
{
    public void doPost(HttpServletRequest req, HttpServletResponse resp) {
        
        try{                     
            byte[] input = new byte[req.getContentLength()];
            ServletInputStream sin = req.getInputStream();
            sin.readLine(input,0,input.length);
            sin.close();
            System.out.println("Request content : " + new String(input));
            resp.setContentLength(input.length);
            resp.setStatus(HttpServletResponse.SC_OK);
            resp.getOutputStream().write(input);
        } catch (IOException e) {
        }
    }

    public void doGet(HttpServletRequest req, HttpServletResponse resp) {
        doPost(req, resp);        
    }
}
***************************
Comment 1 Greg Wilkins CLA 2010-05-27 03:30:53 EDT
Do you stop the HttpClient after you have received the response?
It has a thread pool running and may be keeping the JVM running.

Can you get a thread dump of the JVM after the response has been
received?

regards
Comment 2 Sachin CLA 2010-05-27 09:20:28 EDT
(In reply to comment #1)
> Do you stop the HttpClient after you have received the response?
> It has a thread pool running and may be keeping the JVM running.
> 
> Can you get a thread dump of the JVM after the response has been
> received?
> 
> regards

My initial implementation of onResponseComplete() was closing the client. But client.close() in onResponseComplete() results in java.lang.InterruptedException with following stack:

***********************************
java.lang.InterruptedException: sleep interrupted
	at java.lang.Thread.sleep(Native Method)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.doStop(QueuedThreadPool.java:124)
	at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:80)
	at org.eclipse.jetty.client.HttpClient.doStop(HttpClient.java:501)
	at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:80)
	at MATLABArrayToHttp$1.onResponseComplete(MATLABArrayToHttp.java:34)
	at org.eclipse.jetty.client.HttpExchange$Listener.onResponseComplete(HttpExchange.java:850)
	at org.eclipse.jetty.client.HttpExchange.setStatus(HttpExchange.java:255)
	at org.eclipse.jetty.client.HttpConnection$Handler.messageComplete(HttpConnection.java:530)
	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:752)
	at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:209)
	at org.eclipse.jetty.client.HttpConnection.handle(HttpConnection.java:239)
	at org.eclipse.jetty.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:462)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:436)
	at java.lang.Thread.run(Thread.java:619)
***********************************

As you have requested, here's the thread dump after I receive the resopnse:

***********************************
Full thread dump Java HotSpot(TM) Client VM (11.0-b16 mixed mode, sharing):

"DestroyJavaVM" prio=6 tid=0x002b7800 nid=0x230 waiting on condition [0x00000000..0x0096fd4c]
   java.lang.Thread.State: RUNNABLE

"qtp21091971-16" prio=6 tid=0x02ee4c00 nid=0x1764 waiting on condition [0x034bf000..0x034bfc94]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at org.eclipse.jetty.client.HttpClient$1.run(HttpClient.java:476)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:436)
	at java.lang.Thread.run(Thread.java:619)

"qtp21091971-15" prio=6 tid=0x02ee3400 nid=0xec8 waiting on condition [0x0346f000..0x0346fb94]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at org.eclipse.jetty.client.SelectConnector$1.run(SelectConnector.java:95)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:436)
	at java.lang.Thread.run(Thread.java:619)

"qtp21091971-14" prio=6 tid=0x02ee2000 nid=0x13ec waiting on condition [0x0341f000..0x0341fd14]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x22eba718> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1963)
	at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:320)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:451)
	at java.lang.Thread.run(Thread.java:619)

"qtp21091971-13" prio=6 tid=0x02ee0c00 nid=0x1730 runnable [0x0338f000..0x0338fc14]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
	at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:274)
	at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:256)
	at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:137)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
	- locked <0x22ea91a8> (a sun.nio.ch.Util$1)
	- locked <0x22ea9198> (a java.util.Collections$UnmodifiableSet)
	- locked <0x22ea2b40> (a sun.nio.ch.WindowsSelectorImpl)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
	at org.eclipse.jetty.io.nio.SelectorManager$SelectSet.doSelect(SelectorManager.java:497)
	at org.eclipse.jetty.io.nio.SelectorManager.doSelect(SelectorManager.java:180)
	at org.eclipse.jetty.client.SelectConnector.run(SelectConnector.java:179)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:436)
	at java.lang.Thread.run(Thread.java:619)

"qtp21091971-12" prio=6 tid=0x02edf800 nid=0x1404 waiting on condition [0x0333f000..0x0333fd94]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x22eba718> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1963)
	at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:320)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:451)
	at java.lang.Thread.run(Thread.java:619)

"qtp21091971-11" prio=6 tid=0x02eb3800 nid=0x1124 waiting on condition [0x032ef000..0x032efa14]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x22eba718> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1963)
	at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:320)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:451)
	at java.lang.Thread.run(Thread.java:619)

"qtp21091971-10" prio=6 tid=0x02edec00 nid=0x4a4 waiting on condition [0x0329f000..0x0329fa94]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x22eba718> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1963)
	at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:320)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:451)
	at java.lang.Thread.run(Thread.java:619)

"qtp21091971-9" prio=6 tid=0x02b61800 nid=0xee8 waiting on condition [0x0324f000..0x0324fb14]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x22eba718> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1963)
	at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:320)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:451)
	at java.lang.Thread.run(Thread.java:619)

"Monitor Ctrl-Break" daemon prio=6 tid=0x02bdd800 nid=0x680 runnable [0x031bf000..0x031bfb94]
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264)
	at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306)
	at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158)
	- locked <0x229c9640> (a java.io.InputStreamReader)
	at java.io.InputStreamReader.read(InputStreamReader.java:167)
	at java.io.BufferedReader.fill(BufferedReader.java:136)
	at java.io.BufferedReader.readLine(BufferedReader.java:299)
	- locked <0x229c9640> (a java.io.InputStreamReader)
	at java.io.BufferedReader.readLine(BufferedReader.java:362)
	at com.intellij.rt.execution.application.AppMain$1.run(AppMain.java:56)
	at java.lang.Thread.run(Thread.java:619)

"Low Memory Detector" daemon prio=6 tid=0x02b12800 nid=0x11f4 runnable [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x02b0c800 nid=0x1044 waiting on condition [0x00000000..0x02dbf9bc]
   java.lang.Thread.State: RUNNABLE

"Attach Listener" daemon prio=10 tid=0x02b0b000 nid=0x1ec runnable [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x02b09c00 nid=0x14b0 waiting on condition [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=8 tid=0x02b04c00 nid=0x1228 in Object.wait() [0x02ccf000..0x02ccfa94]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x22e8d3b8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
	- locked <0x22e8d3b8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x02b00000 nid=0x1538 in Object.wait() [0x02c7f000..0x02c7fb14]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x22e8d440> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:485)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
	- locked <0x22e8d440> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x02afe800 nid=0x148 runnable 

"VM Periodic Task Thread" prio=10 tid=0x02b1cc00 nid=0x1308 waiting on condition 

JNI global references: 952

Heap
 def new generation   total 960K, used 327K [0x22990000, 0x22a90000, 0x22e70000)
  eden space 896K,  29% used [0x22990000, 0x229d1cc0, 0x22a70000)
  from space 64K,  99% used [0x22a70000, 0x22a7fff8, 0x22a80000)
  to   space 64K,   0% used [0x22a80000, 0x22a80000, 0x22a90000)
 tenured generation   total 4096K, used 925K [0x22e70000, 0x23270000, 0x26990000)
   the space 4096K,  22% used [0x22e70000, 0x22f57570, 0x22f57600, 0x23270000)
 compacting perm gen  total 12288K, used 2073K [0x26990000, 0x27590000, 0x2a990000)
   the space 12288K,  16% used [0x26990000, 0x26b965f8, 0x26b96600, 0x27590000)
    ro space 8192K,  67% used [0x2a990000, 0x2aef2d98, 0x2aef2e00, 0x2b190000)
    rw space 12288K,  53% used [0x2b190000, 0x2b800640, 0x2b800800, 0x2bd90000)

***********************************
Comment 3 Sachin CLA 2010-05-27 11:33:05 EDT
(In reply to comment #1)
> Do you stop the HttpClient after you have received the response?
> It has a thread pool running and may be keeping the JVM running.
> 
> Can you get a thread dump of the JVM after the response has been
> received?
> 
> regards

Looks like Jetty is not happy about call to client.stop() from the onResponseComplete() handler. If I create another thread and have it call client.stop(), things work fine. So, I am changing the onResponseComplete() code to do the following after I read the response:


Thread t = new Thread(){
  public void run(){
     try{
       client.stop();
     }catch(Exception ex){
     }
  };
};
t.start();
Comment 4 Greg Wilkins CLA 2010-05-27 12:54:04 EDT
that fix looks reasonable.

the other approach would be to have your main thread wait on a Latch
and have the onResponseComplete count down that latch.
Main could then stop the client and exit.

A final solution might be to flag the thread pool as a daemon thread pool, but that will probably mean that the JVM will exit as soon as the main finishes.