5 Replies Latest reply on Nov 13, 2013 12:23 PM by jbertram

JMS messageProducer.send(objectMessage) hangs after 216 sucessfull sends??

foutjo Nov 13, 2013 11:44 AM

I have a process that is trying to send 500 messages to a JMS message queue.

This process consistantly hangs when attempting to send the 217 message.

It always hangs on the following statement:

messageProducer.send(objectMessage);

I have been looking at every possible setting and I can't figure out why this is hanging.

Any ideas?

Here is what my server logs looks like:

09:29:30,110 TRACE [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (EJB default - 1) registering connection from connection manager: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl@78630ffa, connection : org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6@3b9b0e0d, key: org.jboss.as.connector.deployers.processors.CachedConnectionManagerSetupProcessor$CachedConnectionManagerSetupAction@12876401

09:29:30,110 DEBUG [jboss.jdbc.spy] (EJB default - 1) java:/db2DataSource [Connection] prepareStatement(Select KEY0 From JDBRGAC WHERE KEY0 = 'QA1 RGF150624709:29:1700217' FOR READ ONLY)

09:29:30,111 DEBUG [jboss.jdbc.spy] (EJB default - 1) java:/db2DataSource [Statement] setQueryTimeout(60)

09:29:30,111 DEBUG [jboss.jdbc.spy] (EJB default - 1) java:/db2DataSource [PreparedStatement] executeQuery()

09:29:30,114 DEBUG [jboss.jdbc.spy] (EJB default - 1) java:/db2DataSource [ResultSet] next()

09:29:30,114 DEBUG [jboss.jdbc.spy] (EJB default - 1) java:/db2DataSource [Statement] close()

09:29:30,114 DEBUG [jboss.jdbc.spy] (EJB default - 1) java:/db2DataSource [Connection] isClosed()

09:29:30,114 DEBUG [jboss.jdbc.spy] (EJB default - 1) java:/db2DataSource [Connection] close()

09:29:30,114 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (EJB default - 1) connectionClosed called mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@2cec0130

09:29:30,114 TRACE [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (EJB default - 1) unregistering connection from connection manager: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl@78630ffa, connection: org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6@3b9b0e0d, key: org.jboss.as.connector.deployers.processors.CachedConnectionManagerSetupProcessor$CachedConnectionManagerSetupAction@12876401

09:29:30,115 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (EJB default - 1) unregisterConnection: 0 handles left

09:29:30,115 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (EJB default - 1) isManagedConnectionFree=false mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@2cec0130

09:29:30,115 DEBUG [jboss.jdbc.spy] (EJB default - 1) java:/db2DataSource [Connection] isClosed()

09:29:30,115 TRACE [com.lidp.enterprise.persistence.entities.dbutil.ADBRGAC_DBUtil] (EJB default - 1) [2013-11-12][09:29:17][1506247][SEGRMA ][ADBRGAC_DBUtil ][insert ]

09:29:30,115 TRACE [com.lidp.enterprise.persistence.entities.dbutil.ADBRGAC_DBUtil] (EJB default - 1) insert_LoadDBStatement

09:29:30,115 TRACE [com.lidp.enterprise.persistence.entities.dbutil.ADBRGAC_DBUtil] (EJB default - 1) [2013-11-12][09:29:17][1506247][SEGRMA ][ADBRGAC_DBUtil ][setOverrideTableName ]

09:29:30,115 TRACE [com.lidp.enterprise.persistence.entities.dbutil.ADBRGAC_DBUtil] (EJB default - 1) ajSwapFirstChar

09:29:30,115 TRACE [org.jboss.jca.core.connectionmanager.TxConnectionManager] (EJB default - 1) Subject: null

09:29:30,115 TRACE [org.jboss.jca.core.connectionmanager.TxConnectionManager] (EJB default - 1) getManagedConnection interleaving=false , tx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING >

09:29:30,116 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (EJB default - 1) Previous connection tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7aa9f84a[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@2cec0130 connection handles=0 lastUse=1384356557257 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@3a420d5a pool internal context=SemaphoreArrayListManagedConnectionPool@2a93424f[pool=db2DataSource] xaResource=LocalXAResourceImpl@467aad97[connectionListener=7aa9f84a connectionManager=78630ffa warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:-1a751229:52839abd:f, node_name=1, branch_uid=0:ffff7f000001:-1a751229:52839abd:11, subordinatenodename=null, eis_name=unknown eis name >] txSync=TxSync647719910{tx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=true}] tx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING >

09:29:30,116 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (EJB default - 1) Pre-enlist: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7aa9f84a[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@2cec0130 connection handles=0 lastUse=1384356557257 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@3a420d5a pool internal context=SemaphoreArrayListManagedConnectionPool@2a93424f[pool=db2DataSource] xaResource=LocalXAResourceImpl@467aad97[connectionListener=7aa9f84a connectionManager=78630ffa warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:-1a751229:52839abd:f, node_name=1, branch_uid=0:ffff7f000001:-1a751229:52839abd:11, subordinatenodename=null, eis_name=unknown eis name >] txSync=TxSync647719910{tx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=true}] threadTx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING >

09:29:30,116 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (EJB default - 1) Get synchronizer org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7aa9f84a[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@2cec0130 connection handles=0 lastUse=1384356557257 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@3a420d5a pool internal context=SemaphoreArrayListManagedConnectionPool@2a93424f[pool=db2DataSource] xaResource=LocalXAResourceImpl@467aad97[connectionListener=7aa9f84a connectionManager=78630ffa warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:-1a751229:52839abd:f, node_name=1, branch_uid=0:ffff7f000001:-1a751229:52839abd:11, subordinatenodename=null, eis_name=unknown eis name >] txSync=TxSync647719910{tx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=true}] threadTx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING >

09:29:30,116 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (EJB default - 1) Check enlisted org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7aa9f84a[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@2cec0130 connection handles=0 lastUse=1384356557257 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@3a420d5a pool internal context=SemaphoreArrayListManagedConnectionPool@2a93424f[pool=db2DataSource] xaResource=LocalXAResourceImpl@467aad97[connectionListener=7aa9f84a connectionManager=78630ffa warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:-1a751229:52839abd:f, node_name=1, branch_uid=0:ffff7f000001:-1a751229:52839abd:11, subordinatenodename=null, eis_name=unknown eis name >] txSync=TxSync647719910{tx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=true}] threadTx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING >

09:29:30,116 TRACE [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (EJB default - 1) registering connection from connection manager: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl@78630ffa, connection : org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6@8a07b6c, key: org.jboss.as.connector.deployers.processors.CachedConnectionManagerSetupProcessor$CachedConnectionManagerSetupAction@12876401

09:29:30,116 DEBUG [jboss.jdbc.spy] (EJB default - 1) java:/db2DataSource [Connection] prepareStatement(INSERT into JDBRGAC ( KEY0, KEY1, COMPANY_CODE, POLICY_NUMBER, RECORD_ID, TASK_NUMBER, SYSTEM_TIME, SEQUENCE_COUNT, AK1_COMPANY_CODE, AK1_REPORT_ID, PRINT_STATUS, AK1_VARIABLE_KEY, PREV_JRNL_DATE, PREV_JRNL_DUP, CURRENT_PROC_DATE, CYCLE_DUP_NO, DPDSK, AC_TIME, AC_DATE, TRANSACTION_CODE, COMP_CD, POL_NO, COMMENTS, WORD_PROC_SW, DEST_TYPE, FAX_NUMBER, BEEPER_NUMBER, MOBILE_NUMBER, EMAIL_ADDRESS, ROUTE_DESK, VDO_RULE, VARIABLE_DATA_OBJECT ) values ( ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?))

09:29:30,116 TRACE [com.lidp.enterprise.persistence.entities.dbutil.ADBRGAC_DBUtil] (EJB default - 1) insert_LoadDB

09:29:30,117 TRACE [com.lidp.enterprise.util.QMaint_Util] (EJB default - 1) [2013-11-12][09:29:17][1506247][SEGRMA ][QMaint_Util ][writeMessage ]

09:29:30,117 TRACE [org.jboss.jca.core.connectionmanager.TxConnectionManager] (EJB default - 1) Subject: null

09:29:30,117 TRACE [org.jboss.jca.core.connectionmanager.TxConnectionManager] (EJB default - 1) getManagedConnection interleaving=false , tx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING >

09:29:30,117 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (EJB default - 1) Previous connection tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@5ce684c5[state=NORMAL managed connection=org.hornetq.ra.HornetQRAManagedConnection@2216d129 connection handles=0 lastUse=1384356565160 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7fdec3b pool internal context=SemaphoreArrayListManagedConnectionPool@77594090[pool=HornetQConnectionDefinition] xaResource=XAResourceWrapperImpl@2fa01996[xaResource=org.hornetq.ra.HornetQRAXAResource@37efdf47 pad=false overrideRmValue=false productName=HornetQ productVersion=2.0 jndiName=java:/JmsXA] txSync=TxSync1697368833{tx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=true}] tx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING >

09:29:30,117 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (EJB default - 1) Pre-enlist: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@5ce684c5[state=NORMAL managed connection=org.hornetq.ra.HornetQRAManagedConnection@2216d129 connection handles=0 lastUse=1384356565160 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7fdec3b pool internal context=SemaphoreArrayListManagedConnectionPool@77594090[pool=HornetQConnectionDefinition] xaResource=XAResourceWrapperImpl@2fa01996[xaResource=org.hornetq.ra.HornetQRAXAResource@37efdf47 pad=false overrideRmValue=false productName=HornetQ productVersion=2.0 jndiName=java:/JmsXA] txSync=TxSync1697368833{tx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=true}] threadTx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING >

09:29:30,117 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (EJB default - 1) Get synchronizer org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@5ce684c5[state=NORMAL managed connection=org.hornetq.ra.HornetQRAManagedConnection@2216d129 connection handles=0 lastUse=1384356565160 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7fdec3b pool internal context=SemaphoreArrayListManagedConnectionPool@77594090[pool=HornetQConnectionDefinition] xaResource=XAResourceWrapperImpl@2fa01996[xaResource=org.hornetq.ra.HornetQRAXAResource@37efdf47 pad=false overrideRmValue=false productName=HornetQ productVersion=2.0 jndiName=java:/JmsXA] txSync=TxSync1697368833{tx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=true}] threadTx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING >

09:29:30,117 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (EJB default - 1) Check enlisted org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@5ce684c5[state=NORMAL managed connection=org.hornetq.ra.HornetQRAManagedConnection@2216d129 connection handles=0 lastUse=1384356565160 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7fdec3b pool internal context=SemaphoreArrayListManagedConnectionPool@77594090[pool=HornetQConnectionDefinition] xaResource=XAResourceWrapperImpl@2fa01996[xaResource=org.hornetq.ra.HornetQRAXAResource@37efdf47 pad=false overrideRmValue=false productName=HornetQ productVersion=2.0 jndiName=java:/JmsXA] txSync=TxSync1697368833{tx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=true}] threadTx=TransactionImple < ac, BasicAction: 0:ffff7f000001:-1a751229:52839abd:f status: ActionStatus.RUNNING >

09:29:30,117 TRACE [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (EJB default - 1) registering connection from connection manager: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl@1bb94fcf, connection : org.hornetq.ra.HornetQRASession@68752860, key: org.jboss.as.connector.deployers.processors.CachedConnectionManagerSetupProcessor$CachedConnectionManagerSetupAction@12876401

----> 09:29:30,118 TRACE [com.lidp.enterprise.util.QMaint_Util] (EJB default - 1) Writing process message.

09:31:21,669 DEBUG [org.jboss.jca.core.tx.jbossts.XAResourceRecoveryImpl] (Periodic Recovery) RecoverySecurityDomain was empty

09:31:21,670 DEBUG [org.jboss.jca.core.tx.jbossts.XAResourceRecoveryImpl] (Periodic Recovery) Subject for recovery was null

09:33:31,673 DEBUG [org.jboss.jca.core.tx.jbossts.XAResourceRecoveryImpl] (Periodic Recovery) RecoverySecurityDomain was empty

09:33:31,673 DEBUG [org.jboss.jca.core.tx.jbossts.XAResourceRecoveryImpl] (Periodic Recovery) Subject for recovery was null

1. Re: JMS messageProducer.send(objectMessage) hangs after 216 sucessfull sends??

jbertram Nov 13, 2013 11:47 AM (in response to foutjo)

What <address-full-policy> are you using?
Actions
2. Re: JMS messageProducer.send(objectMessage) hangs after 216 sucessfull sends??

foutjo Nov 13, 2013 11:51 AM (in response to jbertram)

               <address-settings>
                    <address-setting match="#">
                        <dead-letter-address>jms.queue.DLQ</dead-letter-address>
                        <expiry-address>jms.queue.ExpiryQueue</expiry-address>
                        <redelivery-delay>1000000</redelivery-delay>
                        <max-size-bytes>10485760</max-size-bytes>
       -->                 <address-full-policy>BLOCK</address-full-policy>
                        <message-counter-history-day-limit>10</message-counter-history-day-limit>
                    </address-setting>
                </address-settings>
Actions
3. Re: JMS messageProducer.send(objectMessage) hangs after 216 sucessfull sends??

jbertram Nov 13, 2013 11:57 AM (in response to foutjo)

That's why your producer is hanging. The address has reached its <max-size-bytes> (i.e. it is full) so it is blocking the producer from sending any more messages. You should either change the <address-full-policy> to match your requirements (see the documentation for more details on this) or increase the <max-size-bytes> to an appropriate size for your use-case or consume the messages you've sent so that the size of the address decreases and you can send more messages.
Actions
4. Re: JMS messageProducer.send(objectMessage) hangs after 216 sucessfull sends??

foutjo Nov 13, 2013 12:15 PM (in response to jbertram)

Thanks Justin that was indeed the problem.
I increased the <max-size-bytes> and all 500 were sent.
Actions
5. Re: JMS messageProducer.send(objectMessage) hangs after 216 sucessfull sends??

jbertram Nov 13, 2013 12:23 PM (in response to foutjo)

Keep in mind that if you increase it too much and send too many messages you'll get an OOME.
Actions

Go to original post