Idle system logs WARN IJ000612 Destroying connection that could not be successfully matched.

Solution Unverified - Updated -

Environment

  • Red Hat JBoss Enterprise Application Platform (EAP)
    • 6.x

Issue

  • If the system is idle it throws lot of MySQL warnings in the logs. Is there a way to configure JBoss so that it would not give these warnings and stacktraces in the logs, or would it be wrong to hide them?
WARN [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (http-executor-threads - 65) IJ000305: Connection error occured:org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@dc936c3[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@152a4347 connection handles=0 lastUse=1366166700560 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@642fca78 pool internal context=SemaphoreArrayListManagedConnectionPool@73147b02[pool=testDB_Pool] xaResource=XAResourceWrapperImpl@9a6f52c[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@152a4347 pad=false overrideRmValue=false productName=MySQL productVersion=5.5.29-enterprise-commercial-advanced-log jndiName=java:jboss/datasources/testDB] txSync=null]: java.sql.SQLException: Ping failed: java.lang.reflect.InvocationTargetException 
 at org.jboss.jca.adapters.jdbc.extensions.mysql.MySQLValidConnectionChecker.isValidConnection(MySQLValidConnectionChecker.java:94) 
 at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnectionFactory.isValidConnection(BaseWrapperManagedConnectionFactory.java:1097) 
 at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.checkValid(BaseWrapperManagedConnection.java:501) 
 at org.jboss.jca.adapters.jdbc.xa.XAManagedConnectionFactory.matchManagedConnections(XAManagedConnectionFactory.java:538) 
 at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool.getConnection(SemaphoreArrayListManagedConnectionPool.java:284) 
 at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getTransactionNewConnection(AbstractPool.java:495) 
 at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getConnection(AbstractPool.java:374) 
 at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.getManagedConnection(AbstractConnectionManager.java:329) 
 at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:368) 
.. ..
WARN [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (http-executor-threads - 65) IJ000612: Destroying connection that could not be successfully matched:org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@dc936c3[state=DESTROYED managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@152a4347 connection handles=0 lastUse=0000000000000 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@642fca78 pool internal context=SemaphoreArrayListManagedConnectionPool@73147b02[pool=testDB_Pool] xaResource=XAResourceWrapperImpl@9a6f52c[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@152a4347 pad=false overrideRmValue=false productName=MySQL productVersion=5.5.29-enterprise-commercial-advanced-log jndiName=java:jboss/datasources/testDB] txSync=null]
  • User have a lot of warnings like:
11:52:27,492 WARN  [org.jboss.jca.core.connectionmanager.listener.NoTxConnectionListener] (ajp-/10.28.48.28:8109-51) IJ000305: Connection error occured: org.jboss.jca.core.connectionmanager.listener.NoTxConnectionListener@55ed179f[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@3affb71c connection handles=1 lastUse=1431942747324 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@4622a310 pool internal context=SemaphoreArrayListManagedConnectionPool@3e2912ad[pool=ORACLE_DS]]: java.lang.ArrayIndexOutOfBoundsException
  • User use jdk1.8u45 and ojdbc7.jar.

Resolution

  • There is no configuration option to disable these WARN messages.

  • Lowering the log verbosity for org.jboss.jca to ERROR means such WARN messages and others highlighting connection and datasource connectivity issues are hidden - making it impossible to prevent the detection of issues before they become critical

  • When the ping invocation in isValidConnection() -- org/jboss/jca/adapters/jdbc/extensions/mysql/MySQLValidConnectionChecker.java fails, and returns an SQLException the message Destroying connection that could not be successfully matched is logged.

499    public boolean checkValid()
500    {
501       SQLException e = mcf.isValidConnection(con);
502 
503       if (e == null)
504       {
505          // It's ok
506          return true;
507       }
508       else
509       {
510          getLog().warn("Destroying connection that is not valid, due to the following exception: " + con, e);
511          broadcastConnectionError(e);
512          return false;
513       }
514    }
  • If it throws a WARN message with the IJ000612 code, like the following then it means that the ConnectionRequestInfo and/or Subject passed to the matchManagedConnection() method couldn't find a match in the pool.
2012.09.03 15:26:28,272 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (EventProcessingMDB-Thread-211 (HornetQ-client-global-threads-22451656)) IJ000612: Destroying connection that could not be successfully matched: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@897852[state=NORMAL managed connection=org.hornetq.ra.HornetQRAManagedConnection@5bd1d1 connection handles=0 lastUse=1346666188255 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@c3df7e pool internal context=SemaphoreArrayListManagedConnectionPool@f4fbc[pool=HornetQConnectionDefinition] xaResource=XAResourceWrapperImpl@2c2f19[xaResource=org.hornetq.ra.HornetQRAXAResource@c823d6 pad=false overrideRmValue=false productName=HornetQ productVersion=2.0 jndiName=java:/JmsXA] txSync=null]

  • This is often due to fact that an incorrect pooling strategy is used - select the correct one based on the use-case.

  • Note: The is per credential key, and destroying a connection means having to creating a new one leading to a performance overhead.

  • The WARN messages (IJ000305 and Destroying connection) are normal when a connection is interrupted or severed by something outside of JBoss. It could be that the database is timing out the connection (from the database server side) or else that some network issue has occurred.

  • It is recommend that need to use validate-on-match rather than background-validation to reduce the risk at application code encountering a connection failure (validate-on-match will be enforced on each connection request whereas background-validation runs only periodically). The use of background validation is recommended only in cases where a very high frequency of connection requests occurs (in which case validation might be costly) but background validation has a higher risk that the application code may be given an invalid connection (since no check is done at the time of the request). Please follow article EAP 6 JDBC datasource not fault tolerant in JBoss and needs connection validation enabled which describes making the datasource more fault tolerant.

Root Cause

  • The WARN messages are logged during connection validation when it fails.

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.

Comments