[jboss-jira] [JBoss JIRA] (JBJCA-1310) NPE when validating database connection (and the validation failed) if connection pool statistics is enabled
Hugh Nguyen (JIRA)
issues at jboss.org
Mon Feb 29 02:46:00 EST 2016
[ https://issues.jboss.org/browse/JBJCA-1310?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13169310#comment-13169310 ]
Hugh Nguyen commented on JBJCA-1310:
------------------------------------
Hi Jesper,
I enabled the trace (however I still have to keep the statistics disabled, as I can't bring the server down), and I got the following log.
The third line from the bottom, you can see that it reach line 436. If statistics is enabled, then NPE would be thrown.
Thank you for your help.
{code}
2016-02-28 07:00:00,030 TRACE [org.jboss.jca.core.connectionmanager.TxConnectionManager] (DefaultQuartzScheduler_Worker-1) Subject: null
2016-02-28 07:00:00,030 TRACE [org.jboss.jca.core.connectionmanager.TxConnectionManager] (DefaultQuartzScheduler_Worker-1) getManagedConnection interleaving=false , tx=TransactionImple < ac, BasicAction: 0:ffffac10003c:13be63f2:56bd22e8:85c76 status: ActionStatus.RUNNING >
2016-02-28 07:00:00,031 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (DefaultQuartzScheduler_Worker-1) getConnection(null, WrappedConnectionRequestInfo at 4ac36f26[userName=db2admin])
Method: getConnection(null, WrappedConnectionRequestInfo at 4ac36f26[userName=db2admin])
Subject: null
CRI: 4ac36f26
ManagedConnectionPool:
Class: org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool
Object: 10dbe79b
ManagedConnectionFactory:
Class: org.jboss.as.connector.subsystems.datasources.AbstractDataSourceService$WildFlyXaMCF
Object: 28b22c2b
ConnectionManager:
Class: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl
Object: 35431c37
Pool:
Name: ctrlDataSource
Class: org.jboss.jca.core.connectionmanager.pool.strategy.OnePool
Object: 59164fb1
FIFO: false
PoolConfiguration:
MinSize: 5
InitialSize: 5
MaxSize: 100
BlockingTimeout: 30000
IdleTimeoutMinutes: 1
ValidateOnMatch: true
BackgroundValidation: false
BackgroundValidationMillis: 0
StrictMin: true
UseFastFail: false
Decrementer: org.jboss.jca.core.connectionmanager.pool.capacity.TimedOutDecrementer
Available (5):
7805dca2 (NORMAL) (Returned: 1456603200517) (Validated: 1456603200517) (Pool: 10799514)
192affde (NORMAL) (Returned: 1456603200554) (Validated: 1456603200544) (Pool: 10799477)
39236e5e (NORMAL) (Returned: 1456603200590) (Validated: 1456603200590) (Pool: 10799441)
63a41f42 (NORMAL) (Returned: 1456603200671) (Validated: 1456603200671) (Pool: 10799360)
19e47679 (NORMAL) (Returned: 1456610400386) (Validated: 1456603200715) (Pool: 3599645)
InUse (0):
Statistics:
ActiveCount: 0
AvailableCount: 0
AverageBlockingTime: 0
AverageCreationTime: 0
AverageGetTime: 0
AveragePoolTime: 0
AverageUsageTime: 0
BlockingFailureCount: 0
CreatedCount: 0
DestroyedCount: 0
IdleCount: 0
InUseCount: 0
MaxCreationTime: 0
MaxGetTime: 0
MaxPoolTime: 0
MaxUsageTime: 0
MaxUsedCount: 0
MaxWaitTime: 0
TimedOut: 0
TotalBlockingTime: 0
TotalCreationTime: 0
TotalGetTime: 0
TotalPoolTime: 0
TotalUsageTime: 0
WaitCount: 0
XAResource:
CommitCount: 0
CommitTotalTime: 0
CommitAverageTime: 0
CommitMaxTime: 0
EndCount: 0
EndTotalTime: 0
EndAverageTime: 0
EndMaxTime: 0
ForgetCount: 0
ForgetTotalTime: 0
ForgetAverageTime: 0
ForgetMaxTime: 0
PrepareCount: 0
PrepareTotalTime: 0
PrepareAverageTime: 0
PrepareMaxTime: 0
RecoverCount: 0
RecoverTotalTime: 0
RecoverAverageTime: 0
RecoverMaxTime: 0
RollbackCount: 0
RollbackTotalTime: 0
RollbackAverageTime: 0
RollbackMaxTime: 0
StartCount: 0
StartTotalTime: 0
StartAverageTime: 0
StartMaxTime: 0
2016-02-28 07:00:00,039 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (DefaultQuartzScheduler_Worker-1) supplying ManagedConnection from pool: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener at 19e47679[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 connection handles=0 lastReturned=1456610400386 lastValidated=1456603200715 lastCheckedOut=1456610400382 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool at 59164fb1 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool at 10dbe79b[pool=ctrlDataSource] xaResource=XAResourceWrapperImpl at 253673cd[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/ctrlDataSource] txSync=null]
2016-02-28 07:00:00,040 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (DefaultQuartzScheduler_Worker-1) Got connection from pool tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener at 19e47679[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 connection handles=0 lastReturned=1456610400386 lastValidated=1456603200715 lastCheckedOut=1456614000040 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool at 59164fb1 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool at 10dbe79b[pool=ctrlDataSource] xaResource=XAResourceWrapperImpl at 253673cd[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/ctrlDataSource] txSync=null] tx=TransactionImple < ac, BasicAction: 0:ffffac10003c:13be63f2:56bd22e8:85c76 status: ActionStatus.RUNNING >
2016-02-28 07:00:00,040 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (DefaultQuartzScheduler_Worker-1) Using connection from pool tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener at 19e47679[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 connection handles=0 lastReturned=1456610400386 lastValidated=1456603200715 lastCheckedOut=1456614000040 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool at 59164fb1 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool at 10dbe79b[pool=ctrlDataSource] xaResource=XAResourceWrapperImpl at 253673cd[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/ctrlDataSource] txSync=null] tx=TransactionImple < ac, BasicAction: 0:ffffac10003c:13be63f2:56bd22e8:85c76 status: ActionStatus.RUNNING >
2016-02-28 07:00:00,040 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) Pre-enlist: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener at 19e47679[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 connection handles=0 lastReturned=1456610400386 lastValidated=1456603200715 lastCheckedOut=1456614000040 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool at 59164fb1 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool at 10dbe79b[pool=ctrlDataSource] xaResource=XAResourceWrapperImpl at 253673cd[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/ctrlDataSource] txSync=null] threadTx=TransactionImple < ac, BasicAction: 0:ffffac10003c:13be63f2:56bd22e8:85c76 status: ActionStatus.RUNNING >
2016-02-28 07:00:00,040 TRACE [org.jboss.jca.core.connectionmanager.transaction.TransactionSynchronizer] (DefaultQuartzScheduler_Worker-1) Adding: 520529016 [TransactionImple < ac, BasicAction: 0:ffffac10003c:13be63f2:56bd22e8:85c76 status: ActionStatus.RUNNING >]
2016-02-28 07:00:00,040 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) Get synchronizer org.jboss.jca.core.connectionmanager.listener.TxConnectionListener at 19e47679[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 connection handles=0 lastReturned=1456610400386 lastValidated=1456603200715 lastCheckedOut=1456614000040 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool at 59164fb1 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool at 10dbe79b[pool=ctrlDataSource] xaResource=XAResourceWrapperImpl at 253673cd[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/ctrlDataSource] txSync=null] threadTx=TransactionImple < ac, BasicAction: 0:ffffac10003c:13be63f2:56bd22e8:85c76 status: ActionStatus.RUNNING >
2016-02-28 07:00:00,040 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) TransactionSynchronization at 1580160865{tx=TransactionImple < ac, BasicAction: 0:ffffac10003c:13be63f2:56bd22e8:85c76 status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=false cancel=false}: Constructor
2016-02-28 07:00:00,040 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) Enlisting resource org.jboss.jca.core.connectionmanager.listener.TxConnectionListener at 19e47679[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 connection handles=0 lastReturned=1456610400386 lastValidated=1456603200715 lastCheckedOut=1456614000040 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool at 59164fb1 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool at 10dbe79b[pool=ctrlDataSource] xaResource=XAResourceWrapperImpl at 253673cd[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/ctrlDataSource] txSync=TransactionSynchronization at 1580160865{tx=TransactionImple < ac, BasicAction: 0:ffffac10003c:13be63f2:56bd22e8:85c76 status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=false cancel=false}]
2016-02-28 07:00:00,041 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) Enlisted resource org.jboss.jca.core.connectionmanager.listener.TxConnectionListener at 19e47679[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 connection handles=0 lastReturned=1456610400386 lastValidated=1456603200715 lastCheckedOut=1456614000040 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool at 59164fb1 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool at 10dbe79b[pool=ctrlDataSource] xaResource=XAResourceWrapperImpl at 253673cd[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/ctrlDataSource] txSync=TransactionSynchronization at 1580160865{tx=TransactionImple < ac, BasicAction: 0:ffffac10003c:13be63f2:56bd22e8:85c76 status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=true cancel=false}]
2016-02-28 07:00:00,041 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) Check enlisted org.jboss.jca.core.connectionmanager.listener.TxConnectionListener at 19e47679[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 connection handles=0 lastReturned=1456610400386 lastValidated=1456603200715 lastCheckedOut=1456614000040 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool at 59164fb1 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool at 10dbe79b[pool=ctrlDataSource] xaResource=XAResourceWrapperImpl at 253673cd[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/ctrlDataSource] txSync=TransactionSynchronization at 1580160865{tx=TransactionImple < ac, BasicAction: 0:ffffac10003c:13be63f2:56bd22e8:85c76 status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=true cancel=false}] threadTx=TransactionImple < ac, BasicAction: 0:ffffac10003c:13be63f2:56bd22e8:85c76 status: ActionStatus.RUNNING >
2016-02-28 07:00:00,041 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) [TxConnectionListener at 19e47679] registerConnection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7 at 3dce223a [size=1] ([org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7 at 3dce223a])
2016-02-28 07:00:00,041 TRACE [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (DefaultQuartzScheduler_Worker-1) registering connection from connection manager: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl at 35431c37, connection : org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7 at 3dce223a, key: null
2016-02-28 07:00:00,099 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (DefaultQuartzScheduler_Worker-1) SQL Warning Code: 4223, SQLState: null
2016-02-28 07:00:00,099 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (DefaultQuartzScheduler_Worker-1) Origination unknown: [10228][11541][4.14.122] Security exceptions occurred while loading driver. ERRORCODE=4223, SQLSTATE=null
2016-02-28 07:00:00,099 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) connectionClosed called mc=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408
2016-02-28 07:00:00,099 TRACE [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (DefaultQuartzScheduler_Worker-1) unregistering connection from connection manager: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl at 35431c37, connection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7 at 3dce223a, key: null
2016-02-28 07:00:00,099 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) [TxConnectionListener at 19e47679] unregisterConnection: 0 handles left ([])
2016-02-28 07:00:00,099 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) isManagedConnectionFree=false mc=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408
2016-02-28 07:00:00,099 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) delistResource(XAResourceWrapperImpl at 253673cd[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/ctrlDataSource], TMSUCCESS)
2016-02-28 07:00:00,100 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) afterCompletion(3) isTrackByTx=true for org.jboss.jca.core.connectionmanager.listener.TxConnectionListener at 19e47679[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 connection handles=0 lastReturned=1456610400386 lastValidated=1456603200715 lastCheckedOut=1456614000040 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool at 59164fb1 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool at 10dbe79b[pool=ctrlDataSource] xaResource=XAResourceWrapperImpl at 253673cd[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/ctrlDataSource] txSync=null]
2016-02-28 07:00:00,100 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) [TxConnectionListener at 19e47679] isManagedConnectionFree: true
2016-02-28 07:00:00,100 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (DefaultQuartzScheduler_Worker-1) returnConnection(19e47679, false)
Method: returnConnection(19e47679, false)
Subject: null
CRI: null
ManagedConnectionPool:
Class: org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool
Object: 10dbe79b
ManagedConnectionFactory:
Class: org.jboss.as.connector.subsystems.datasources.AbstractDataSourceService$WildFlyXaMCF
Object: 28b22c2b
ConnectionManager:
Class: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl
Object: 35431c37
Pool:
Name: ctrlDataSource
Class: org.jboss.jca.core.connectionmanager.pool.strategy.OnePool
Object: 59164fb1
FIFO: false
PoolConfiguration:
MinSize: 5
InitialSize: 5
MaxSize: 100
BlockingTimeout: 30000
IdleTimeoutMinutes: 1
ValidateOnMatch: true
BackgroundValidation: false
BackgroundValidationMillis: 0
StrictMin: true
UseFastFail: false
Decrementer: org.jboss.jca.core.connectionmanager.pool.capacity.TimedOutDecrementer
Available (4):
7805dca2 (NORMAL) (Returned: 1456603200517) (Validated: 1456603200517) (Pool: 10799583)
192affde (NORMAL) (Returned: 1456603200554) (Validated: 1456603200544) (Pool: 10799546)
39236e5e (NORMAL) (Returned: 1456603200590) (Validated: 1456603200590) (Pool: 10799510)
63a41f42 (NORMAL) (Returned: 1456603200671) (Validated: 1456603200671) (Pool: 10799429)
InUse (1):
19e47679 (NORMAL) (CheckedOut: 1456614000040) (Validated: 1456603200715) (Usage: 60)
Statistics:
ActiveCount: 0
AvailableCount: 0
AverageBlockingTime: 0
AverageCreationTime: 0
AverageGetTime: 0
AveragePoolTime: 0
AverageUsageTime: 0
BlockingFailureCount: 0
CreatedCount: 0
DestroyedCount: 0
IdleCount: 0
InUseCount: 0
MaxCreationTime: 0
MaxGetTime: 0
MaxPoolTime: 0
MaxUsageTime: 0
MaxUsedCount: 0
MaxWaitTime: 0
TimedOut: 0
TotalBlockingTime: 0
TotalCreationTime: 0
TotalGetTime: 0
TotalPoolTime: 0
TotalUsageTime: 0
WaitCount: 0
XAResource:
CommitCount: 0
CommitTotalTime: 0
CommitAverageTime: 0
CommitMaxTime: 0
EndCount: 0
EndTotalTime: 0
EndAverageTime: 0
EndMaxTime: 0
ForgetCount: 0
ForgetTotalTime: 0
ForgetAverageTime: 0
ForgetMaxTime: 0
PrepareCount: 0
PrepareTotalTime: 0
PrepareAverageTime: 0
PrepareMaxTime: 0
RecoverCount: 0
RecoverTotalTime: 0
RecoverAverageTime: 0
RecoverMaxTime: 0
RollbackCount: 0
RollbackTotalTime: 0
RollbackAverageTime: 0
RollbackMaxTime: 0
StartCount: 0
StartTotalTime: 0
StartAverageTime: 0
StartMaxTime: 0
2016-02-28 07:00:00,100 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (DefaultQuartzScheduler_Worker-1) Returning connection to pool org.jboss.jca.core.connectionmanager.listener.TxConnectionListener at 19e47679[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 connection handles=0 lastReturned=1456614000100 lastValidated=1456603200715 lastCheckedOut=1456614000040 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool at 59164fb1 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool at 10dbe79b[pool=ctrlDataSource] xaResource=XAResourceWrapperImpl at 253673cd[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 5af92408 pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/ctrlDataSource] txSync=null]
2016-02-28 07:00:00,100 TRACE [org.jboss.jca.core.connectionmanager.transaction.TransactionSynchronizer] (DefaultQuartzScheduler_Worker-1) Removed: 520529016 [TransactionImple < ac, BasicAction: 0:ffffac10003c:13be63f2:56bd22e8:85c76 status: ActionStatus.COMMITTED >]
2016-02-28 07:00:00,101 DEBUG [synergix.th6.framework.persistence.SynEntityManagerImpl] (DefaultQuartzScheduler_Worker-1) SynEntityManager CLOSED: SynEntityManagerImpl at 3def80f1 - {companyCode=CTRL, entityManagerRegistry=TransactionScopedEntityManagerRegistryImpl at 48656ce2}
2016-02-28 07:00:00,101 DEBUG [synergix.th6.framework.persistence.SynEntityManagerFactory] (DefaultQuartzScheduler_Worker-1) SynEntityManagerFactory.disposeSynEntityManager(SynEntityManagerImpl at 3def80f1 - {companyCode=CTRL, entityManagerRegistry=TransactionScopedEntityManagerRegistryImpl at 48656ce2})
2016-02-28 07:00:00,102 DEBUG [synergix.th6.business.util.persistence.EmLocator] (DefaultQuartzScheduler_Worker-1) Current Company Code not available in User Session. Retrieved from ThreadLocal: LS1INT
2016-02-28 07:00:00,103 DEBUG [synergix.th6.framework.persistence.SynEntityManagerFactory] (DefaultQuartzScheduler_Worker-1) SynEntityManager CREATED: SynEntityManagerImpl at 5f0258a5 - {companyCode=LS1INT, entityManagerRegistry=TransactionScopedEntityManagerRegistryImpl at 40137234}
2016-02-28 07:00:00,103 DEBUG [org.hibernate.SQL] (DefaultQuartzScheduler_Worker-1) select mt_sys_rev0_.employment_type_code as employme1_1706_0_, mt_sys_rev0_.review_type_code as review_t2_1706_0_, mt_sys_rev0_.created_by as created_3_1706_0_, mt_sys_rev0_.created_datetime as created_4_1706_0_, mt_sys_rev0_.last_updated_by as last_upd5_1706_0_, mt_sys_rev0_.last_updated_datetime as last_upd6_1706_0_, mt_sys_rev0_.object_version as object_v7_1706_0_, mt_sys_rev0_.check_mt_employee_exclusion as check_mt8_1706_0_, mt_sys_rev0_.reminder_frequency as reminder9_1706_0_, mt_sys_rev0_.reminder_to_flow_seq as reminde10_1706_0_, mt_sys_rev0_.EMPLOYMENT_TYPE_CODE as EMPLOYME1_1706_0_, mt_sys_rev0_.REVIEW_TYPE_CODE as REVIEW_T2_1706_0_, mt_sys_rev0_.trigger_code as trigger11_1706_0_, mt_sys_rev0_.trigger_param_1 as trigger12_1706_0_, mt_sys_rev0_.trigger_param_2 as trigger13_1706_0_, mt_sys_rev0_.week_day_to_remind_reviewer as week_da14_1706_0_ from Mt_sys_review_trigger_and_reminder mt_sys_rev0_ where mt_sys_rev0_.employment_type_code=? and mt_sys_rev0_.review_type_code=?
2016-02-28 07:00:00,103 TRACE [org.jboss.jca.core.connectionmanager.TxConnectionManager] (DefaultQuartzScheduler_Worker-1) Subject: null
2016-02-28 07:00:00,103 TRACE [org.jboss.jca.core.connectionmanager.TxConnectionManager] (DefaultQuartzScheduler_Worker-1) getManagedConnection interleaving=false , tx=TransactionImple < ac, BasicAction: 0:ffffac10003c:13be63f2:56bd22e8:85c7d status: ActionStatus.RUNNING >
2016-02-28 07:00:00,103 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (DefaultQuartzScheduler_Worker-1) getConnection(null, WrappedConnectionRequestInfo at 5e6abda5[userName=db2admin])
Method: getConnection(null, WrappedConnectionRequestInfo at 5e6abda5[userName=db2admin])
Subject: null
CRI: 5e6abda5
ManagedConnectionPool:
Class: org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool
Object: 2665f4d6
ManagedConnectionFactory:
Class: org.jboss.as.connector.subsystems.datasources.AbstractDataSourceService$WildFlyXaMCF
Object: 50907673
ConnectionManager:
Class: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl
Object: 1075eec3
Pool:
Name: pemain1
Class: org.jboss.jca.core.connectionmanager.pool.strategy.OnePool
Object: 55209893
FIFO: false
PoolConfiguration:
MinSize: 5
InitialSize: 5
MaxSize: 100
BlockingTimeout: 30000
IdleTimeoutMinutes: 1
ValidateOnMatch: true
BackgroundValidation: false
BackgroundValidationMillis: 0
StrictMin: true
UseFastFail: false
Decrementer: org.jboss.jca.core.connectionmanager.pool.capacity.TimedOutDecrementer
Available (5):
322500c (NORMAL) (Returned: 1456527600419) (Validated: 1456527600419) (Pool: 86399684)
35bd4931 (NORMAL) (Returned: 1456527600471) (Validated: 1456527600455) (Pool: 86399632)
8d8ede3 (NORMAL) (Returned: 1456527600502) (Validated: 1456527600502) (Pool: 86399601)
6fd4da32 (NORMAL) (Returned: 1456527600550) (Validated: 1456527600550) (Pool: 86399553)
4aad6c0 (NORMAL) (Returned: 1456554069609) (Validated: 1456527600612) (Pool: 59930494)
InUse (0):
Statistics:
ActiveCount: 0
AvailableCount: 0
AverageBlockingTime: 0
AverageCreationTime: 0
AverageGetTime: 0
AveragePoolTime: 0
AverageUsageTime: 0
BlockingFailureCount: 0
CreatedCount: 0
DestroyedCount: 0
IdleCount: 0
InUseCount: 0
MaxCreationTime: 0
MaxGetTime: 0
MaxPoolTime: 0
MaxUsageTime: 0
MaxUsedCount: 0
MaxWaitTime: 0
TimedOut: 0
TotalBlockingTime: 0
TotalCreationTime: 0
TotalGetTime: 0
TotalPoolTime: 0
TotalUsageTime: 0
WaitCount: 0
XAResource:
CommitCount: 0
CommitTotalTime: 0
CommitAverageTime: 0
CommitMaxTime: 0
EndCount: 0
EndTotalTime: 0
EndAverageTime: 0
EndMaxTime: 0
ForgetCount: 0
ForgetTotalTime: 0
ForgetAverageTime: 0
ForgetMaxTime: 0
PrepareCount: 0
PrepareTotalTime: 0
PrepareAverageTime: 0
PrepareMaxTime: 0
RecoverCount: 0
RecoverTotalTime: 0
RecoverAverageTime: 0
RecoverMaxTime: 0
RollbackCount: 0
RollbackTotalTime: 0
RollbackAverageTime: 0
RollbackMaxTime: 0
StartCount: 0
StartTotalTime: 0
StartAverageTime: 0
StartMaxTime: 0
2016-02-28 07:00:00,106 WARN [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) IJ000305: Connection error occured: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener at 4aad6c0[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 4d66892d connection handles=0 lastReturned=1456554069609 lastValidated=1456527600612 lastCheckedOut=1456554069554 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool at 55209893 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool at 2665f4d6[pool=pemain1] xaResource=XAResourceWrapperImpl at 9a0673a[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 4d66892d pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/PEMAIN1] txSync=null]: com.ibm.db2.jcc.am.DisconnectNonTransientConnectionException: [jcc][t4][2030][11211][4.14.122] A communication error occurred during operations on the connection's underlying socket, socket input stream,
or socket output stream. Error location: T4Agent.sendRequest() - flush (-1). Message: Software caused connection abort: socket write error. ERRORCODE=-4499, SQLSTATE=08001
at com.ibm.db2.jcc.am.ed.a(ed.java:320)
at com.ibm.db2.jcc.t4.a.a(a.java:546)
at com.ibm.db2.jcc.t4.a.a(a.java:541)
at com.ibm.db2.jcc.t4.a.f(a.java:482)
at com.ibm.db2.jcc.t4.a.flush_(a.java:388)
at com.ibm.db2.jcc.am.Agent.flow(Agent.java:231)
at com.ibm.db2.jcc.am.oo.a(oo.java:3178)
at com.ibm.db2.jcc.am.oo.e(oo.java:1073)
at com.ibm.db2.jcc.am.oo.execute(oo.java:1056)
at org.jboss.jca.adapters.jdbc.extensions.db2.DB2ValidConnectionChecker.isValidConnection(DB2ValidConnectionChecker.java:65)
at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnectionFactory.isValidConnection(BaseWrapperManagedConnectionFactory.java:1261)
at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.checkValid(BaseWrapperManagedConnection.java:508)
at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnectionFactory.getInvalidConnections(BaseWrapperManagedConnectionFactory.java:1082)
at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool.getConnection(SemaphoreConcurrentLinkedDequeManagedConnectionPool.java:378)
at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getTransactionNewConnection(AbstractPool.java:708)
at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getConnection(AbstractPool.java:607)
at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.getManagedConnection(AbstractConnectionManager.java:590)
at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:429)
at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:747)
at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:138)
at org.jboss.as.connector.subsystems.datasources.WildFlyDataSource.getConnection(WildFlyDataSource.java:66)
at org.hibernate.engine.jdbc.connections.spi.AbstractDataSourceBasedMultiTenantConnectionProviderImpl.getConnection(AbstractDataSourceBasedMultiTenantConnectionProviderImpl.java:35)
at org.hibernate.internal.AbstractSessionImpl$ContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:429)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:87)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:112)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:47)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:146)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:172)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:148)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.prepareQueryStatement(AbstractLoadPlanBasedLoader.java:241)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:185)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:121)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:86)
at org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader.load(AbstractLoadPlanBasedEntityLoader.java:167)
at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3956)
at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:508)
at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:478)
at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:219)
at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:278)
at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:121)
at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:89)
at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1129)
at org.hibernate.internal.SessionImpl.access$2600(SessionImpl.java:164)
at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.load(SessionImpl.java:2696)
at org.hibernate.internal.SessionImpl.get(SessionImpl.java:975)
at org.hibernate.jpa.spi.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:1075)
at org.hibernate.jpa.spi.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:1033)
at synergix.th6.framework.persistence.EntityManagerAbstractWrapper.find(EntityManagerAbstractWrapper.java:50)
at synergix.th6.business.entity.mtsys.Mt_sys_review_trigger_and_reminder.find(Mt_sys_review_trigger_and_reminder.java:37)
at synergix.th6.business.action.scheduledjob.hr.InitiateReviewsJob.triggerYearEnd(InitiateReviewsJob.java:74)
at synergix.th6.business.action.scheduledjob.hr.InitiateReviewsJob.access$0(InitiateReviewsJob.java:73)
at synergix.th6.business.action.scheduledjob.hr.InitiateReviewsJob$2.call(InitiateReviewsJob.java:56)
at synergix.th6.business.action.scheduledjob.hr.InitiateReviewsJob$2.call(InitiateReviewsJob.java:1)
at synergix.th6.framework.persistence.transaction.IsolatedTransactionExecutor.__do_not_call_directly_executeWithIsolatedTransaction(IsolatedTransactionExecutor.java:27)
at synergix.th6.framework.persistence.transaction.IsolatedTransactionExecutor$Proxy$_$$_WeldSubclass.__do_not_call_directly_executeWithIsolatedTransaction$$super(Unknown Source)
at sun.reflect.GeneratedMethodAccessor2385.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:49)
at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:77)
at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:117)
at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequiresNew.doIntercept(TransactionalInterceptorRequiresNew.java:60)
at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:76)
at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequiresNew.intercept(TransactionalInterceptorRequiresNew.java:47)
at sun.reflect.GeneratedMethodAccessor2384.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:74)
at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)
at synergix.th6.framework.persistence.transaction.IsolatedTransactionExecutor$Proxy$_$$_WeldSubclass.__do_not_call_directly_executeWithIsolatedTransaction(Unknown Source)
at synergix.th6.framework.persistence.transaction.IsolatedTransactionExecutor$Proxy$_$$_WeldClientProxy.__do_not_call_directly_executeWithIsolatedTransaction(Unknown Source)
at synergix.th6.framework.persistence.transaction.IsolatedTransactionExecutor.executeWithIsolatedTransaction(IsolatedTransactionExecutor.java:14)
at synergix.th6.business.action.scheduledjob.hr.InitiateReviewsJob.triggerReviews(InitiateReviewsJob.java:49)
at synergix.th6.business.action.scheduledjob.hr.InitiateReviewsJob.execute(InitiateReviewsJob.java:34)
at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
Caused by: java.net.SocketException: Software caused connection abort: socket write error
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
at com.ibm.db2.jcc.t4.db.b(db.java:1685)
at com.ibm.db2.jcc.t4.db.a(db.java:1633)
at com.ibm.db2.jcc.t4.a.f(a.java:449)
... 76 more
2016-02-28 07:00:00,110 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) [TxConnectionListener at 4aad6c0] unregisterConnections
2016-02-28 07:00:00,110 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (DefaultQuartzScheduler_Worker-1) returnConnection(4aad6c0, true)
Method: returnConnection(4aad6c0, true)
Subject: null
CRI: null
ManagedConnectionPool:
Class: org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool
Object: 2665f4d6
ManagedConnectionFactory:
Class: org.jboss.as.connector.subsystems.datasources.AbstractDataSourceService$WildFlyXaMCF
Object: 50907673
ConnectionManager:
Class: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl
Object: 1075eec3
Pool:
Name: pemain1
Class: org.jboss.jca.core.connectionmanager.pool.strategy.OnePool
Object: 55209893
FIFO: false
PoolConfiguration:
MinSize: 5
InitialSize: 5
MaxSize: 100
BlockingTimeout: 30000
IdleTimeoutMinutes: 1
ValidateOnMatch: true
BackgroundValidation: false
BackgroundValidationMillis: 0
StrictMin: true
UseFastFail: false
Decrementer: org.jboss.jca.core.connectionmanager.pool.capacity.TimedOutDecrementer
Available (4):
322500c (NORMAL) (Returned: 1456527600419) (Validated: 1456527600419) (Pool: 86399691)
35bd4931 (NORMAL) (Returned: 1456527600471) (Validated: 1456527600455) (Pool: 86399639)
8d8ede3 (NORMAL) (Returned: 1456527600502) (Validated: 1456527600502) (Pool: 86399608)
6fd4da32 (NORMAL) (Returned: 1456527600550) (Validated: 1456527600550) (Pool: 86399560)
InUse (1):
4aad6c0 (NORMAL) (CheckedOut: 1456554069554) (Validated: 1456527600612) (Usage: 59930556)
Statistics:
ActiveCount: 0
AvailableCount: 0
AverageBlockingTime: 0
AverageCreationTime: 0
AverageGetTime: 0
AveragePoolTime: 0
AverageUsageTime: 0
BlockingFailureCount: 0
CreatedCount: 0
DestroyedCount: 0
IdleCount: 0
InUseCount: 0
MaxCreationTime: 0
MaxGetTime: 0
MaxPoolTime: 0
MaxUsageTime: 0
MaxUsedCount: 0
MaxWaitTime: 0
TimedOut: 0
TotalBlockingTime: 0
TotalCreationTime: 0
TotalGetTime: 0
TotalPoolTime: 0
TotalUsageTime: 0
WaitCount: 0
XAResource:
CommitCount: 0
CommitTotalTime: 0
CommitAverageTime: 0
CommitMaxTime: 0
EndCount: 0
EndTotalTime: 0
EndAverageTime: 0
EndMaxTime: 0
ForgetCount: 0
ForgetTotalTime: 0
ForgetAverageTime: 0
ForgetMaxTime: 0
PrepareCount: 0
PrepareTotalTime: 0
PrepareAverageTime: 0
PrepareMaxTime: 0
RecoverCount: 0
RecoverTotalTime: 0
RecoverAverageTime: 0
RecoverMaxTime: 0
RollbackCount: 0
RollbackTotalTime: 0
RollbackAverageTime: 0
RollbackMaxTime: 0
StartCount: 0
StartTotalTime: 0
StartAverageTime: 0
StartMaxTime: 0
2016-02-28 07:00:00,111 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (DefaultQuartzScheduler_Worker-1) Destroying returned connection org.jboss.jca.core.connectionmanager.listener.TxConnectionListener at 4aad6c0[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 4d66892d connection handles=0 lastReturned=1456554069609 lastValidated=1456527600612 lastCheckedOut=1456554069554 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool at 55209893 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool at 2665f4d6[pool=pemain1] xaResource=XAResourceWrapperImpl at 9a0673a[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 4d66892d pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/PEMAIN1] txSync=null]
2016-02-28 07:00:00,111 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (DefaultQuartzScheduler_Worker-1) Returning connection to pool org.jboss.jca.core.connectionmanager.listener.TxConnectionListener at 4aad6c0[state=DESTROYED managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 4d66892d connection handles=0 lastReturned=1456554069609 lastValidated=1456527600612 lastCheckedOut=1456554069554 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool at 55209893 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool at 2665f4d6[pool=pemain1] xaResource=XAResourceWrapperImpl at 9a0673a[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 4d66892d pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/PEMAIN1] txSync=null]
2016-02-28 07:00:00,112 WARN [org.jboss.as.connector.subsystems.datasources.AbstractDataSourceService$WildFlyXaMCF] (DefaultQuartzScheduler_Worker-1) IJ030027: Destroying connection that is not valid, due to the following exception: com.ibm.db2.jcc.am.ef at 12be0aa4: com.ibm.db2.jcc.am.DisconnectNonTransientConnectionException: [jcc][t4][2030][11211][4.14.122] A communication error occurred during operations on the connection's underlying socket, socket input stream,
or socket output stream. Error location: T4Agent.sendRequest() - flush (-1). Message: Software caused connection abort: socket write error. ERRORCODE=-4499, SQLSTATE=08001
at com.ibm.db2.jcc.am.ed.a(ed.java:320)
at com.ibm.db2.jcc.t4.a.a(a.java:546)
at com.ibm.db2.jcc.t4.a.a(a.java:541)
at com.ibm.db2.jcc.t4.a.f(a.java:482)
at com.ibm.db2.jcc.t4.a.flush_(a.java:388)
at com.ibm.db2.jcc.am.Agent.flow(Agent.java:231)
at com.ibm.db2.jcc.am.oo.a(oo.java:3178)
at com.ibm.db2.jcc.am.oo.e(oo.java:1073)
at com.ibm.db2.jcc.am.oo.execute(oo.java:1056)
at org.jboss.jca.adapters.jdbc.extensions.db2.DB2ValidConnectionChecker.isValidConnection(DB2ValidConnectionChecker.java:65)
at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnectionFactory.isValidConnection(BaseWrapperManagedConnectionFactory.java:1261)
at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.checkValid(BaseWrapperManagedConnection.java:508)
at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnectionFactory.getInvalidConnections(BaseWrapperManagedConnectionFactory.java:1082)
at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool.getConnection(SemaphoreConcurrentLinkedDequeManagedConnectionPool.java:378)
at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getTransactionNewConnection(AbstractPool.java:708)
at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getConnection(AbstractPool.java:607)
at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.getManagedConnection(AbstractConnectionManager.java:590)
at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:429)
at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:747)
at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:138)
at org.jboss.as.connector.subsystems.datasources.WildFlyDataSource.getConnection(WildFlyDataSource.java:66)
at org.hibernate.engine.jdbc.connections.spi.AbstractDataSourceBasedMultiTenantConnectionProviderImpl.getConnection(AbstractDataSourceBasedMultiTenantConnectionProviderImpl.java:35)
at org.hibernate.internal.AbstractSessionImpl$ContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:429)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:87)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:112)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:47)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:146)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:172)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:148)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.prepareQueryStatement(AbstractLoadPlanBasedLoader.java:241)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:185)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:121)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:86)
at org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader.load(AbstractLoadPlanBasedEntityLoader.java:167)
at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3956)
at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:508)
at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:478)
at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:219)
at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:278)
at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:121)
at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:89)
at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1129)
at org.hibernate.internal.SessionImpl.access$2600(SessionImpl.java:164)
at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.load(SessionImpl.java:2696)
at org.hibernate.internal.SessionImpl.get(SessionImpl.java:975)
at org.hibernate.jpa.spi.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:1075)
at org.hibernate.jpa.spi.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:1033)
at synergix.th6.framework.persistence.EntityManagerAbstractWrapper.find(EntityManagerAbstractWrapper.java:50)
at synergix.th6.business.entity.mtsys.Mt_sys_review_trigger_and_reminder.find(Mt_sys_review_trigger_and_reminder.java:37)
at synergix.th6.business.action.scheduledjob.hr.InitiateReviewsJob.triggerYearEnd(InitiateReviewsJob.java:74)
at synergix.th6.business.action.scheduledjob.hr.InitiateReviewsJob.access$0(InitiateReviewsJob.java:73)
at synergix.th6.business.action.scheduledjob.hr.InitiateReviewsJob$2.call(InitiateReviewsJob.java:56)
at synergix.th6.business.action.scheduledjob.hr.InitiateReviewsJob$2.call(InitiateReviewsJob.java:1)
at synergix.th6.framework.persistence.transaction.IsolatedTransactionExecutor.__do_not_call_directly_executeWithIsolatedTransaction(IsolatedTransactionExecutor.java:27)
at synergix.th6.framework.persistence.transaction.IsolatedTransactionExecutor$Proxy$_$$_WeldSubclass.__do_not_call_directly_executeWithIsolatedTransaction$$super(Unknown Source)
at sun.reflect.GeneratedMethodAccessor2385.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:49)
at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:77)
at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:117)
at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequiresNew.doIntercept(TransactionalInterceptorRequiresNew.java:60)
at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:76)
at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequiresNew.intercept(TransactionalInterceptorRequiresNew.java:47)
at sun.reflect.GeneratedMethodAccessor2384.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:74)
at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)
at synergix.th6.framework.persistence.transaction.IsolatedTransactionExecutor$Proxy$_$$_WeldSubclass.__do_not_call_directly_executeWithIsolatedTransaction(Unknown Source)
at synergix.th6.framework.persistence.transaction.IsolatedTransactionExecutor$Proxy$_$$_WeldClientProxy.__do_not_call_directly_executeWithIsolatedTransaction(Unknown Source)
at synergix.th6.framework.persistence.transaction.IsolatedTransactionExecutor.executeWithIsolatedTransaction(IsolatedTransactionExecutor.java:14)
at synergix.th6.business.action.scheduledjob.hr.InitiateReviewsJob.triggerReviews(InitiateReviewsJob.java:49)
at synergix.th6.business.action.scheduledjob.hr.InitiateReviewsJob.execute(InitiateReviewsJob.java:34)
at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
Caused by: java.net.SocketException: Software caused connection abort: socket write error
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
at com.ibm.db2.jcc.t4.db.b(db.java:1685)
at com.ibm.db2.jcc.t4.db.a(db.java:1633)
at com.ibm.db2.jcc.t4.a.f(a.java:449)
... 76 more
2016-02-28 07:00:00,112 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (JCA PoolFiller) fillTo(5)
Method: fillTo(5)
Subject: null
CRI: null
ManagedConnectionPool:
Class: org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool
Object: 2665f4d6
ManagedConnectionFactory:
Class: org.jboss.as.connector.subsystems.datasources.AbstractDataSourceService$WildFlyXaMCF
Object: 50907673
ConnectionManager:
Class: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl
Object: 1075eec3
Pool:
Name: pemain1
Class: org.jboss.jca.core.connectionmanager.pool.strategy.OnePool
Object: 55209893
FIFO: false
PoolConfiguration:
MinSize: 5
InitialSize: 5
MaxSize: 100
BlockingTimeout: 30000
IdleTimeoutMinutes: 1
ValidateOnMatch: true
BackgroundValidation: false
BackgroundValidationMillis: 0
StrictMin: true
UseFastFail: false
Decrementer: org.jboss.jca.core.connectionmanager.pool.capacity.TimedOutDecrementer
Available (4):
322500c (NORMAL) (Returned: 1456527600419) (Validated: 1456527600419) (Pool: 86399693)
35bd4931 (NORMAL) (Returned: 1456527600471) (Validated: 1456527600455) (Pool: 86399641)
8d8ede3 (NORMAL) (Returned: 1456527600502) (Validated: 1456527600502) (Pool: 86399610)
6fd4da32 (NORMAL) (Returned: 1456527600550) (Validated: 1456527600550) (Pool: 86399562)
InUse (0):
Statistics:
ActiveCount: 0
AvailableCount: 0
AverageBlockingTime: 0
AverageCreationTime: 0
AverageGetTime: 0
AveragePoolTime: 0
AverageUsageTime: 0
BlockingFailureCount: 0
CreatedCount: 0
DestroyedCount: 0
IdleCount: 0
InUseCount: 0
MaxCreationTime: 0
MaxGetTime: 0
MaxPoolTime: 0
MaxUsageTime: 0
MaxUsedCount: 0
MaxWaitTime: 0
TimedOut: 0
TotalBlockingTime: 0
TotalCreationTime: 0
TotalGetTime: 0
TotalPoolTime: 0
TotalUsageTime: 0
WaitCount: 0
XAResource:
CommitCount: 0
CommitTotalTime: 0
CommitAverageTime: 0
CommitMaxTime: 0
EndCount: 0
EndTotalTime: 0
EndAverageTime: 0
EndMaxTime: 0
ForgetCount: 0
ForgetTotalTime: 0
ForgetAverageTime: 0
ForgetMaxTime: 0
PrepareCount: 0
PrepareTotalTime: 0
PrepareAverageTime: 0
PrepareMaxTime: 0
RecoverCount: 0
RecoverTotalTime: 0
RecoverAverageTime: 0
RecoverMaxTime: 0
RollbackCount: 0
RollbackTotalTime: 0
RollbackAverageTime: 0
RollbackMaxTime: 0
StartCount: 0
StartTotalTime: 0
StartAverageTime: 0
StartMaxTime: 0
2016-02-28 07:00:00,115 WARN [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (DefaultQuartzScheduler_Worker-1) IJ000621: Destroying connection that could not be validated: null
2016-02-28 07:00:00,121 WARN [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (DefaultQuartzScheduler_Worker-1) IJ000305: Connection error occured: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener at 6fd4da32[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 202c95de connection handles=0 lastReturned=1456527600550 lastValidated=1456527600550 lastCheckedOut=1456527600550 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool at 55209893 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool at 2665f4d6[pool=pemain1] xaResource=XAResourceWrapperImpl at 62f34251[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection at 202c95de pad=false overrideRmValue=null productName=DB2/NT64 productVersion=SQL09078 jndiName=java:/jdbc/PEMAIN1] txSync=null]: com.ibm.db2.jcc.am.DisconnectNonTransientConnectionException: [jcc][t4][2030][11211][4.14.122] A communication error occurred during operations on the connection's underlying socket, socket input stream,
or socket output stream. Error location: T4Agent.sendRequest() - flush (-1). Message: Software caused connection abort: socket write error. ERRORCODE=-4499, SQLSTATE=08001
{code}
> NPE when validating database connection (and the validation failed) if connection pool statistics is enabled
> ------------------------------------------------------------------------------------------------------------
>
> Key: JBJCA-1310
> URL: https://issues.jboss.org/browse/JBJCA-1310
> Project: IronJacamar
> Issue Type: Bug
> Components: Core
> Affects Versions: WildFly/IronJacamar 1.3.2.Final, 1.2.6.Final
> Reporter: Hugh Nguyen
> Assignee: Jesper Pedersen
>
> - An xa-datasource connection pool is configured with: statistic-enabled=true, validate-on-match=true
> - When validation failed, after the failure, the following is logged:
> {code}
> 2016-02-10 12:23:12,580 WARN [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (Sched1_Worker-13) IJ000621: Destroying connection that could not be validated: null
> {code}
> - This appears to come from SemaphoreConcurrentLinkedDequeManagedConnectionPool.java, line 436:
> {code}
> log.destroyingConnectionNotValidated(clw.getConnectionListener());
> {code}
> - So apparently clw.getConnectionListener() is null at this point, causing line 441/442 to throw NPE, if statistics is enabled:
> {code}
> pool.getInternalStatistics().deltaTotalPoolTime(lastUsed - clw.getConnectionListener().getLastReturnedTime());
> {code}
> - NPE is caught by the catch clause, and line 456 write the following to the log:
> {code}
> 2016-02-10 12:23:12,580 WARN [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (Sched1_Worker-13) IJ000613: Throwable while trying to match managed connection, destroying connection: null: java.lang.NullPointerException
> at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool.getConnection(SemaphoreConcurrentLinkedDequeManagedConnectionPool.java:441)
> at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getTransactionNewConnection(AbstractPool.java:708)
> at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getConnection(AbstractPool.java:607)
> at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.getManagedConnection(AbstractConnectionManager.java:590)
> at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:429)
> at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:747)
> {code}
> - However, this catch clause try to do the same thing that cause the NPE in line 461/462
> {code}
> pool.getInternalStatistics().deltaTotalPoolTime(lastUsed - clw.getConnectionListener().getLastReturnedTime());
> {code}
> - And finally this NPE is throw all the way out to the user of the connection
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
More information about the jboss-jira
mailing list