Wildfire 3.2.2 crash

Openfire Openfire Support
1

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

2

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

3

Hey Ikan,

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

thanks,

Alex

4

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

5

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

6

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

7

Hi, Alex

Any solution for this blocker bug?

8

Ikan,

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

Thanks,

Alex

9

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

10

Thanx.