powered by Jive Software

Wildfire 3.2.2 crash

Wildfire 3.2.2 (Enterprise plugin)+ http-bind + apapche mod_proxy + JsJac + plain auth

OS: Suse 2.6.11.4-20a-smp, with 4G RAM, 4 DualCode CPU.

Wildfire http-bind not responding to apache with ~1100 concurent users.

-Xms512m -Xmx1536m

xmpp.httpbind.client.requests.polling = 0

xmpp.httpbind.client.requests.wait = 60

Before crach i found some “dispatch failed” (posibble jetty error) in wildfire warn.log, 1263 “pool-wildfire(n)” thread.

Some errors in warn.log (before crash)

2007.03.09 00:55:53 Error for /http-bind/

java.lang.InternalError: Could not locate connection: 786156

at org.jivesoftware.wildfire.http.HttpSession.getResponse(HttpSession.java:343)

at org.jivesoftware.wildfire.http.HttpBindServlet.handleSessionRequest(HttpBindSer vlet.java:177)

at org.jivesoftware.wildfire.http.HttpBindServlet.doPost(HttpBindServlet.java:105)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)

at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:491)

at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:367)

at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:185)

at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)

at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:689)

at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:391)

at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollect ion.java:146)

at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)

at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)

at org.mortbay.jetty.Server.handle(Server.java:285)

at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:457)

at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:765 )

at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:627)

at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:209)

at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:357)

at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:329)

at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:475)

2007.03.09 00:55:54 Error for /http-bind/

java.lang.InternalError: Could not locate connection: 786156

at org.jivesoftware.wildfire.http.HttpSession.getResponse(HttpSession.java:343)

at org.jivesoftware.wildfire.http.HttpBindServlet.handleSessionRequest(HttpBindSer vlet.java:177)

at org.jivesoftware.wildfire.http.HttpBindServlet.doPost(HttpBindServlet.java:105)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)

at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:491)

at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:367)

at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:185)

at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)

at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:689)

at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:391)

at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollect ion.java:146)

at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)

at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)

at org.mortbay.jetty.Server.handle(Server.java:285)

at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:457)

at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:765 )

at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:627)

at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:209)

at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:357)

at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:329)

at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:475)

2007.03.09 00:56:00 Client provided invalid session: 7ba17633.

2007.03.09 00:56:10 Client provided invalid session: f6fca7ec.

2007.03.09 00:56:11 Request 564701 > 564699, ending session.

2007.03.09 00:56:36 Error for /http-bind/

java.lang.InternalError: Could not locate connection: 772905

at org.jivesoftware.wildfire.http.HttpSession.getResponse(HttpSession.java:343)

at org.jivesoftware.wildfire.http.HttpBindServlet.handleSessionRequest(HttpBindSer vlet.java:177)

at org.jivesoftware.wildfire.http.HttpBindServlet.doPost(HttpBindServlet.java:105)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)

at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:491)

at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:367)

at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:185)

at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)

at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:689)

at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:391)

at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollect ion.java:146)

at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)

at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)

at org.mortbay.jetty.Server.handle(Server.java:285)

at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:457)

at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:765 )

at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:627)

at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:209)

at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:357)

at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:329)

at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:475)

2007.03.09 00:56:53 Connection timed out: 426093. Request 426093 exceded response time from server of 60 seconds.

2007.03.09 00:57:07 Connection timed out: 564700. Request 564700 exceded response time from server of 60 seconds.

2007.03.09 00:57:23 Deliverable unavailable for 786163

2007.03.09 00:58:24 dispatch failed!

“Found 3 deadlocks.” in thread dump.

Found one Java-level deadlock:

=============================

“pool-wildfire1259”:

waiting to lock monitor 0x080633fc (object 0x4bf810d8, a org.jivesoftware.wildfire.http.HttpSession),

which is held by “btpool0-282”

“btpool0-282”:

waiting to lock monitor 0x0865b8f8 (object 0x4b1d5100, a org.jivesoftware.wildfire.http.HttpSession),

which is held by “btpool0-133”

“btpool0-133”:

waiting to lock monitor 0x0865a444 (object 0x4a337010, a org.jivesoftware.wildfire.http.HttpSession),

which is held by “btpool0-426”

“btpool0-426”:

waiting to lock monitor 0x08658c70 (object 0x4b0610f0, a org.jivesoftware.wildfire.http.HttpSession),

which is held by “btpool0-76”

“btpool0-76”:

waiting to lock monitor 0x0865924c (object 0x4b001780, a org.jivesoftware.wildfire.http.HttpSession),

which is held by “btpool0-434”

“btpool0-434”:

waiting to lock monitor 0x08659314 (object 0x4ae7f938, a org.jivesoftware.wildfire.http.HttpSession),

which is held by “btpool0-341”

“btpool0-341”:

waiting to lock monitor 0x0865924c (object 0x4b001780, a org.jivesoftware.wildfire.http.HttpSession),

which is held by “btpool0-434”

I have a full thread dump, how post it?

All “pool-wildfire” thread blocked at HttpSession.getLastActivity

“pool-wildfire1032” daemon prio=10 tid=0x70e60c00 nid=0x7fb9 waiting for monitor entry (0x85a28000…0x85a28ea0)

java.lang.Thread.State: BLOCKED (on object monitor)

at org.jivesoftware.wildfire.http.HttpSession.getLastActivity(HttpSession.java:314 )

  • waiting to lock <0x4bf810d8> (a org.jivesoftware.wildfire.http.HttpSession)

at org.jivesoftware.wildfire.http.HttpSessionManager$HttpSessionReaper.run(HttpSes sionManager.java:285)

at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)

at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)

at java.util.concurrent.FutureTask.run(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

Apache error log after crash:

(Fri Mar 09 01:00:37 2007) (error) (110)Connection timed out: proxy: HTTP: attempt to connect to 192.168.20.32:8080 (xxx) failed

(Fri Mar 09 01:00:37 2007) (error) ap_proxy_connect_backend disabling worker for (xxx)

(Fri Mar 09 01:00:37 2007) (error) (110)Connection timed out: proxy: HTTP: attempt to connect to 192.168.20.32:8080 (xxx) failed

and some

(Fri Mar 09 01:10:58 2007) (error) (client 90.10.39.110) proxy: error reading status line from remote server xxx

(Fri Mar 09 01:10:58 2007) (error) (client 90.10.39.110) proxy: Error reading from remote server returned by /bind

before crash (possible apache bug).

… and sorry for my english.

Message was edited by: ikan

HttpSession.connectionQueue is not syncronized and accesed by multiple threads.

Hey Ikan,

Can you email me the full thread dump, alex@jivesoftware.com ?

thanks,

Alex

I have investigated all places where the connectionQueue is used and all synchronize on the session:

addConnection:

  1. createConnection->HttpSessionManager#forwardRequest-> syncrhonized(session) - handleSessionRequest

deliver:

  1. addConnection->createConnection->HttpSessionManager#forwardRequest-> syncrhonized(session) - handleSessionRequest

  2. deliver(deliverable)

  3. deliver(String) -> synchronized(session)

  4. deliver(Element) -> synchronized(session)

failDelivery:

  1. failDelivery-> synchronized(session) - closeConnection

getConnectionCount:

  1. no usages -> removed

getLastActivity: synchornized(session)

getOpenConnectionCount:

  1. addConnection->createConnection->HttpSessionManager#forwardRequest-> syncrhonized(session) - handleSessionRequest

getResponse:

  1. getResponse(long)->

  2. synchronized(session) - HttpBindServlet#handleSessionRequest

  3. synchronized(session) - HttpBindServlet#isContinuation

Hi Alex,

java.lang.Thread.State: BLOCKED (on object monitor)
at org.jivesoftware.wildfire.http.HttpSession.getLastActivity(HttpSession.java:314)

is interesting, as this should not block.

/*313*/    public synchronized long getLastActivity() {
/*314*/        if (connectionQueue.size() <= 0) {
/*315*/            return lastActivity;
}}

So I wonder if connectionQueue.size() blocks as it is not thread safe.

/*302*/    public int getConnectionCount() {
/*303*/        return connectionQueue.size();
/*304*/    }

here you access connectionQueue without synchronized but I wonder if this method is ever used.

LG

It isn’'t used, and will be removed in the next release. getLastActivity is synchronized which is why it is saying the thread is blocked. With a full thread dump I will be able to tell who is holding the object monitor and where the deadlock lies.

Thanks,

Alex

Hi, Alex

Any solution for this blocker bug?

Ikan,

Could you send me your thread dump, it is imperative to finding the root of the issue?

Thanks,

Alex

I have created an issue for this:

JM-1001

And will be checking in a fix shortly, it will be in 3.2.3.

Thanks,

Alex

Thanx.