Jetty

Timeout related Deadlocks in HTTP Client

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Major Major
  • Resolution: Fixed
  • Affects Version/s: 6.1.12
  • Fix Version/s: 6.1.15.pre0
  • Component/s: None
  • Labels:
    None
  • Environment:
    OS: Linux 2.6.18-6-xen-vserver-amd64
    Java: java version "1.6.0_01"
    Java(TM) SE Runtime Environment (build 1.6.0_01-b06)
    Java HotSpot(TM) 64-Bit Server VM (build 1.6.0_01-b06, mixed mode)
  • Number of attachments :
    1

Description

I encountered two deadlocks in the HTTP Client which are both related to timeouts.

My setup in short:

  • 20 HTTP Clients send regular requests to a single HTTP server (also JETTY).
  • All HTTP requests are asynchronous.
  • The HTTP Client has a timeout of 10000 ms.

Both deadlocks occur when the HTTP server stops responding (I force this to test the timeouts in the HTTP Clients). In this case, the HTTP Clients can connect to the server but do not receive a response from the server within 10 seconds.

(Deadlock 1) Found one Java-level deadlock:
=============================
"HttpClient-1":
waiting to lock monitor 0x00002aaae41a6fc8 (object 0x00002aaab3a8f5e8, a java.lang.Object),
which is held by "HttpClient-0"
"HttpClient-0":
waiting to lock monitor 0x00002aaae4351ae8 (object 0x00002aaab3a8eeb8, a org.mortbay.jetty.client.HttpDestination),
which is held by "HttpClient-1"

Java stack information for the threads listed above:
===================================================
"HttpClient-1":
at org.mortbay.thread.Timeout.schedule(Timeout.java:185)

  • waiting to lock <0x00002aaab3a8f5e8> (a java.lang.Object)
    at org.mortbay.thread.Timeout.schedule(Timeout.java:173)
    at org.mortbay.jetty.client.HttpClient.schedule(HttpClient.java:183)
    at org.mortbay.jetty.client.HttpConnection.send(HttpConnection.java:164)
  • locked <0x00002aaab3b504c8> (a org.mortbay.jetty.client.HttpConnection)
    at org.mortbay.jetty.client.HttpDestination.onNewConnection(HttpDestination.java:278)
  • locked <0x00002aaab3a8eeb8> (a org.mortbay.jetty.client.HttpDestination)
    at org.mortbay.jetty.client.SelectConnector$Manager.newEndPoint(SelectConnector.java:144)
    at org.mortbay.io.nio.SelectorManager$SelectSet.doSelect(SelectorManager.java:375)
    at org.mortbay.io.nio.SelectorManager.doSelect(SelectorManager.java:185)
    at org.mortbay.jetty.client.SelectConnector.run(SelectConnector.java:82)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522)
    "HttpClient-0":
    at org.mortbay.jetty.client.HttpDestination.returnConnection(HttpDestination.java:334)
  • waiting to lock <0x00002aaab3a8eeb8> (a org.mortbay.jetty.client.HttpDestination)
    at org.mortbay.jetty.client.HttpConnection$1.expire(HttpConnection.java:85)
  • locked <0x00002aaab3b4d7a0> (a org.mortbay.jetty.client.HttpConnection)
    at org.mortbay.thread.Timeout.tick(Timeout.java:152)
  • locked <0x00002aaab3a8f5e8> (a java.lang.Object)
    at org.mortbay.thread.Timeout.tick(Timeout.java:167)
    at org.mortbay.jetty.client.HttpClient$1.run(HttpClient.java:358)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522)

(Deadlock 2) Found one Java-level deadlock:
=============================
"HttpClient-73":
waiting to lock monitor 0x00002aaae442b010 (object 0x00002aaab399ce18, a java.lang.Object),
which is held by "HttpClient-1"
"HttpClient-1":
waiting to lock monitor 0x00002aaae41f18e8 (object 0x00002aaab399c700, a org.mortbay.jetty.client.HttpDestination),
which is held by "Thread-282"
"Thread-282":
waiting to lock monitor 0x00002aaae442b010 (object 0x00002aaab399ce18, a java.lang.Object),
which is held by "HttpClient-1"

Java stack information for the threads listed above:
===================================================
"HttpClient-73":
at org.mortbay.thread.Timeout$Task.cancel(Timeout.java:356)

  • waiting to lock <0x00002aaab399ce18> (a java.lang.Object)
    at org.mortbay.jetty.client.HttpClient.cancel(HttpClient.java:189)
    at org.mortbay.jetty.client.HttpConnection.handle(HttpConnection.java:312)
    at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522)
    "HttpClient-1":
    at org.mortbay.jetty.client.HttpDestination.returnConnection(HttpDestination.java:338)
  • waiting to lock <0x00002aaab399c700> (a org.mortbay.jetty.client.HttpDestination)
    at org.mortbay.jetty.client.HttpConnection$1.expire(HttpConnection.java:85)
  • locked <0x00002aaab4064098> (a org.mortbay.jetty.client.HttpConnection)
    at org.mortbay.thread.Timeout.tick(Timeout.java:152)
  • locked <0x00002aaab399ce18> (a java.lang.Object)
    at org.mortbay.thread.Timeout.tick(Timeout.java:167)
    at org.mortbay.jetty.client.HttpClient$1.run(HttpClient.java:358)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522)
    "Thread-282":
    at org.mortbay.thread.Timeout.schedule(Timeout.java:183)
  • waiting to lock <0x00002aaab399ce18> (a java.lang.Object)
    at org.mortbay.thread.Timeout.schedule(Timeout.java:173)
    at org.mortbay.jetty.client.HttpClient.schedule(HttpClient.java:183)
    at org.mortbay.jetty.client.HttpConnection.send(HttpConnection.java:164)
  • locked <0x00002aaab4157470> (a org.mortbay.jetty.client.HttpConnection)
    at org.mortbay.jetty.client.HttpDestination.doSend(HttpDestination.java:423)
  • locked <0x00002aaab399c700> (a org.mortbay.jetty.client.HttpDestination)
    at org.mortbay.jetty.client.HttpDestination.send(HttpDestination.java:378)
    at org.mortbay.jetty.client.HttpClient.send(HttpClient.java:135)
    at net.avinity.test.AppServer.__doGet(AppServer.java:399)
    at net.avinity.test.AppServer.doGetSync(AppServer.java:243)
    at net.avinity.test.AppServer.exit(AppServer.java:124)
    at net.avinity.test.AppServer.stop(AppServer.java:115)
    at net.avinity.test.Session.stop_nolock(Session.java:118)
    at net.avinity.test.Session.stop(Session.java:135)
    at net.avinity.test.Session.fatalError(Session.java:216)
    at net.avinity.test.App$2$1.run(AppServer.java:290)
    at java.lang.Thread.run(Thread.java:619)

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Jesse McConnell added a comment -

Have you been able to replicate this with one or two exchanges in a test case at all or are you doing this manually? Trying to get this into a unit test is proving annoyingly difficult.

Show
Jesse McConnell added a comment - Have you been able to replicate this with one or two exchanges in a test case at all or are you doing this manually? Trying to get this into a unit test is proving annoyingly difficult.
Hide
Permalink
Jesse McConnell added a comment -

Also, you said you were using 20 HTTP Clients, your referring to one http client with a max connection per address of 20, or 20 instances of httpclient?

If you could attach your test case and process for reproducing it would be much appreciated in replicating this issue

cheers

Show
Jesse McConnell added a comment - Also, you said you were using 20 HTTP Clients, your referring to one http client with a max connection per address of 20, or 20 instances of httpclient? If you could attach your test case and process for reproducing it would be much appreciated in replicating this issue cheers
Hide
Permalink
Michiel Thuys added a comment -

Attached is a test case with which I can reproduce the issue.

The test does the following:
Start a HTTP server that sleeps 1 seconds for each HTTP request before responding.
Start 1 HTTP Client with a timeout of 500 mS.
Send a HTTP request to the server every 50 mS

The test sends 1000 request which is often enough to reproduce the deadlock. The deadlock can be detected when the 'onExpire()' callbacks no longer occur.

I hope this helps in reproducing the problem.

What I meant to say in the initial report is that I have 20 HTTP requests per second via 1 HTTP Client instance. Sorry for the confusion.

Show
Michiel Thuys added a comment - Attached is a test case with which I can reproduce the issue. The test does the following: Start a HTTP server that sleeps 1 seconds for each HTTP request before responding. Start 1 HTTP Client with a timeout of 500 mS. Send a HTTP request to the server every 50 mS The test sends 1000 request which is often enough to reproduce the deadlock. The deadlock can be detected when the 'onExpire()' callbacks no longer occur. I hope this helps in reproducing the problem. What I meant to say in the initial report is that I have 20 HTTP requests per second via 1 HTTP Client instance. Sorry for the confusion.
Hide
Permalink
Jesse McConnell added a comment -

resolved, it was an issue with locking on the _lock variable of the actual Timeout...resolved by implementing expired() instead of expire() for the actual Timeout.Task

Show
Jesse McConnell added a comment - resolved, it was an issue with locking on the _lock variable of the actual Timeout...resolved by implementing expired() instead of expire() for the actual Timeout.Task

People

  • Assignee:
    Jesse McConnell
    Reporter:
    Michiel Thuys
Vote (0)
Watch (0)

Dates

  • Created:
    Updated:
    Resolved: