Too many messages: Unable to get a connection from the database pool

polianomartini · January 26, 2022, 10:23pm

I’m noticing that it’s getting a lot of messages like below in stdoutt.log:

14:25:25.581 [Jetty-QTP-BOSH-83] INFO  org.jivesoftware.database.DbConnectionManager - Unable to get a connection from the database pool (attempt 0 out of 10).
java.sql.SQLException: Cannot get a connection, pool error Timeout waiting for idle object
	at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:142) ~[commons-dbcp2-2.6.0.jar:2.6.0]
	at org.jivesoftware.database.DefaultConnectionProvider.getConnection(DefaultConnectionProvider.java:91) ~[xmppserver-4.6.0.jar:4.6.0]
	at org.jivesoftware.database.DbConnectionManager.getConnection(DbConnectionManager.java:171) [xmppserver-4.6.0.jar:4.6.0]
	at org.jivesoftware.openfire.auth.DefaultAuthProvider.getUserInfo(DefaultAuthProvider.java:89) [xmppserver-4.6.0.jar:4.6.0]
	at org.jivesoftware.openfire.auth.DefaultAuthProvider.getUserInfo(DefaultAuthProvider.java:78) [xmppserver-4.6.0.jar:4.6.0]
	at org.jivesoftware.openfire.auth.DefaultAuthProvider.getIterations(DefaultAuthProvider.java:141) [xmppserver-4.6.0.jar:4.6.0]
	at org.jivesoftware.openfire.auth.AuthFactory.getIterations(AuthFactory.java:288) [xmppserver-4.6.0.jar:4.6.0]
	at org.jivesoftware.openfire.sasl.ScramSha1SaslServer.getIterations(ScramSha1SaslServer.java:338) [xmppserver-4.6.0.jar:4.6.0]
	at org.jivesoftware.openfire.sasl.ScramSha1SaslServer.generateServerFirstMessage(ScramSha1SaslServer.java:159) [xmppserver-4.6.0.jar:4.6.0]
	at org.jivesoftware.openfire.sasl.ScramSha1SaslServer.evaluateResponse(ScramSha1SaslServer.java:114) [xmppserver-4.6.0.jar:4.6.0]
	at org.jivesoftware.openfire.net.SASLAuthentication.handle(SASLAuthentication.java:370) [xmppserver-4.6.0.jar:4.6.0]
	at org.jivesoftware.openfire.websocket.XmppWebSocket.processStanza(XmppWebSocket.java:224) [xmppserver-4.6.0.jar:4.6.0]
	at org.jivesoftware.openfire.websocket.XmppWebSocket.onTextMethod(XmppWebSocket.java:116) [xmppserver-4.6.0.jar:4.6.0]
	at sun.reflect.GeneratedMethodAccessor18.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_202]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_202]
	at org.eclipse.jetty.websocket.common.events.annotated.CallableMethod.call(CallableMethod.java:70) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.events.annotated.OptionalSessionCallableMethod.call(OptionalSessionCallableMethod.java:72) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onTextMessage(JettyAnnotatedEventDriver.java:248) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.message.SimpleTextMessage.messageComplete(SimpleTextMessage.java:69) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:65) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onTextFrame(JettyAnnotatedEventDriver.java:240) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:150) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:326) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.extensions.AbstractExtension.nextIncomingFrame(AbstractExtension.java:147) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.extensions.compress.PerMessageDeflateExtension.nextIncomingFrame(PerMessageDeflateExtension.java:112) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.extensions.compress.CompressExtension.forwardIncoming(CompressExtension.java:168) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.extensions.compress.PerMessageDeflateExtension.incomingFrame(PerMessageDeflateExtension.java:92) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:202) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:225) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.Parser.parseSingleFrame(Parser.java:259) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:459) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:440) [websocket-common-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [jetty-io-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [jetty-io-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [jetty-io-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) [jetty-util-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) [jetty-util-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) [jetty-util-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) [jetty-util-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375) [jetty-util-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806) [jetty-util-9.4.31.v20200723.jar:9.4.31.v20200723]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938) [jetty-util-9.4.31.v20200723.jar:9.4.31.v20200723]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_202]
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:439) ~[commons-pool2-2.6.2.jar:2.6.2]
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:349) ~[commons-pool2-2.6.2.jar:2.6.2]
	at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134) ~[commons-dbcp2-2.6.0.jar:2.6.0]
	... 43 more

Does anyone know why?

guus · January 27, 2022, 10:38am

Openfire is configured to use not more than a specific amount of database connections. When these connections are all in use, and some part of Openfire needs another connection (but can’t get one), these kind of exceptions can occur.

This doesn’t typically happen in normal use cases. Are you using custom plugins, or are you running a very (very!) busy server?

A common cause of this problem is execution of queries that take a long time (as that would keep the connection ‘occupied’ for a long time). It might be worth looking at diagnostics data from your database, to try and identify those. The Openfire admin console also contains some basic debugging tools, as shown in this screenshot: