Bug 1083676

Summary:	'Session exception occured while trying to commit: timed out waiting for sync' when commiting to a clustered destination
Product:	Red Hat Enterprise MRG	Reporter:	Valiantsina Hubeika <vhubeika>
Component:	qpid-java	Assignee:	Rajith Attapattu <rattapat+nobody>
Status:	CLOSED DUPLICATE	QA Contact:	Valiantsina Hubeika <vhubeika>
Severity:	high	Docs Contact:
Priority:	medium
Version:	Development	CC:	esammons, jross, lzhaldyb, masterQi, mtoth, rattapat+nobody
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2014-08-14 10:34:02 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Valiantsina Hubeika 2014-04-02 17:27:38 UTC

Description of problem:

When publishing to topic or sending to queue on a transacted session in Vienna HA setup, exception is thrown, unless an explicit  sleep is issued before commit.

javax.jms.JMSException: Session exception occured while trying to commit: timed out waiting for sync: complete = 1, point = 3
	at org.apache.qpid.client.AMQSession.toJMSException(AMQSession.java:3439)
	at org.apache.qpid.client.AMQSession.commit(AMQSession.java:843)
	at org.apache.qpid.client.AMQSessionAdapter.commit(AMQSessionAdapter.java:92)
	at org.apache.qpid.example.TestTCK.runTestTopicTx(TestTCK.java:128)
	at org.apache.qpid.example.TestTCK.main(TestTCK.java:39)
Caused by: org.apache.qpid.transport.SessionException: timed out waiting for sync: complete = 1, point = 3
	at org.apache.qpid.transport.Session.sync(Session.java:867)
	at org.apache.qpid.transport.Session.sync(Session.java:837)
	at org.apache.qpid.transport.Session.invoke(Session.java:789)
	at org.apache.qpid.transport.Session.invoke(Session.java:627)
	at org.apache.qpid.transport.SessionInvoker.txCommit(SessionInvoker.java:145)
	at org.apache.qpid.client.AMQSession_0_10.commitImpl(AMQSession_0_10.java:1022)
	at org.apache.qpid.client.AMQSession.commit(AMQSession.java:830)
	... 3 more
javax.jms.JMSException: Error closing connection: javax.jms.JMSException: Error closing session: org.apache.qpid.AMQException: timed out waiting for sync: complete = 1, point = 3 [error code 541: internal error]



Version-Release number of selected component (if applicable):


How reproducible:
100%

Steps to Reproduce:
0. setup Vienna HA
1. connect to the broker
2. send or publish message on a transacted session
3. commit message

Actual results:

exception is thrown

Expected results:

transaction is commited

Additional info:

transaction commits successfully if a sleep is issued before commit, e.i.:

  pub.send(message);
  Thread.sleep (1);
  ssn.commit ();

Comment 2 Rajith Attapattu 2014-04-10 15:15:34 UTC

This happens bcos the broker does not respond within the timeout period.
The sleep allows the broker a bit more time to respond hence it completes successfully. 

For this env the timeout can be increased.

Comment 3 Valiantsina Hubeika 2014-04-10 18:53:06 UTC

please note that even when a client is run with a longer time-out, for instance 10 times longer, the client hangs for the time-out period and then fails. 

^Croot @mrg-qe-26 ~/tckjms_fails_ant 12:10:19 # time ant runclient
Buildfile: build.xml

compile:

build-jar:

runclient:
     [java] Topic is topic://amq.topic/testTopic0/?routingkey='testTopic0'&exclusive='true'&autodelete='true'
     [java] Topic name is testTopic0
     [java] javax.jms.JMSException: Session exception occured while trying to commit: timed out waiting for sync: complete = 13, point = 15
     [java] 	at org.apache.qpid.client.AMQSession.toJMSException(AMQSession.java:3439)
     [java] 	at org.apache.qpid.client.AMQSession.commit(AMQSession.java:843)
     [java] 	at org.apache.qpid.client.AMQSessionAdapter.commit(AMQSessionAdapter.java:92)
     [java] 	at com.redhat.mrg.TestTCK.runTestTopicTx(TestTCK.java:134)
     [java] 	at com.redhat.mrg.TestTCK.main(TestTCK.java:40)
     [java] Caused by: org.apache.qpid.transport.SessionException: timed out waiting for sync: complete = 13, point = 15
     [java] 	at org.apache.qpid.transport.Session.sync(Session.java:867)
     [java] 	at org.apache.qpid.transport.Session.sync(Session.java:837)
     [java] 	at org.apache.qpid.transport.Session.invoke(Session.java:789)
     [java] 	at org.apache.qpid.transport.Session.invoke(Session.java:627)
     [java] 	at org.apache.qpid.transport.SessionInvoker.txCommit(SessionInvoker.java:145)
     [java] 	at org.apache.qpid.client.AMQSession_0_10.commitImpl(AMQSession_0_10.java:1022)
     [java] 	at org.apache.qpid.client.AMQSession.commit(AMQSession.java:830)
     [java] 	... 3 more
     [java] log4j:WARN No appenders could be found for logger (org.apache.qpid.client.AMQConnection).
     [java] log4j:WARN Please initialize the log4j system properly.
     [java] javax.jms.JMSException: Error closing connection: javax.jms.JMSException: Error closing session: org.apache.qpid.AMQException: timed out waiting for sync: complete = 13, point = 15 [error code 541: internal error]
     [java] 	at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:926)
     [java] 	at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:879)
     [java] 	at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:863)
     [java] 	at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:854)
     [java] 	at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:849)
     [java] 	at com.redhat.mrg.TestTCK.runTestTopicTx(TestTCK.java:167)
     [java] 	at com.redhat.mrg.TestTCK.main(TestTCK.java:40)
     [java] Caused by: javax.jms.JMSException: Error closing session: org.apache.qpid.AMQException: timed out waiting for sync: complete = 13, point = 15 [error code 541: internal error]
     [java] 	at org.apache.qpid.client.AMQSession.close(AMQSession.java:720)
     [java] 	at org.apache.qpid.client.AMQSession.close(AMQSession.java:682)
     [java] 	at org.apache.qpid.client.AMQConnection.closeAllSessions(AMQConnection.java:1005)
     [java] 	at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:890)
     [java] 	... 6 more
     [java] Caused by: org.apache.qpid.AMQException: timed out waiting for sync: complete = 13, point = 15 [error code 541: internal error]
     [java] 	at org.apache.qpid.client.AMQSession_0_10.setCurrentException(AMQSession_0_10.java:1070)
     [java] 	at org.apache.qpid.client.AMQSession_0_10.sendClose(AMQSession_0_10.java:431)
     [java] 	at org.apache.qpid.client.AMQSession.close(AMQSession.java:714)
     [java] 	... 9 more

BUILD SUCCESSFUL
Total time: 20 minutes 1 second

real	20m1.789s
user	0m2.290s
sys	0m0.478s



-----

When the client is run with the default time-out and a sleep is used, client finishes successfully:

root @mrg-qe-26 ~/tckjms_fails_ant 12:35:18 # time ant runclient
Buildfile: build.xml

compile:
    [javac] Compiling 1 source file to /root/tckjms_fails_ant/classes

build-jar:
      [jar] Building jar: /root/tckjms_fails_ant/jars/app.jar

runclient:
     [java] Topic is topic://amq.topic/testTopic0/?routingkey='testTopic0'&exclusive='true'&autodelete='true'
     [java] Topic name is testTopic0
     [java] read message is Message1
     [java] not a last message 
     [java] read message is Message1

BUILD SUCCESSFUL
Total time: 2 seconds

real	0m2.903s
user	0m3.237s
sys	0m0.171s

Comment 6 masterQi 2014-05-08 09:16:49 UTC

i met this proplem with ha ,how to fix?




 trying to recover. Cause: Session exception occured while trying to commit: timed out waiting for sync: complete = 8, point = 10
"javax.jms.JMSException: Session exception occured while trying to commit: timed out waiting for sync: complete = 8, point = 10
	at org.apache.qpid.client.AMQSession.toJMSException(AMQSession.java:3465)
	at org.apache.qpid.client.AMQSession.commit(AMQSession.java:843)
	at org.springframework.jms.support.JmsUtils.commitIfNecessary(JmsUtils.java:217)
	at org.springframework.jms.listener.AbstractMessageListenerContainer.commitIfNecessary(AbstractMessageListenerContainer.java:575)
	at org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(AbstractMessageListenerContainer.java:481)
	at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:325)
	at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:263)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1058)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1050)
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:947)
	at java.lang.Thread.run(Thread.java:722)
Caused by: org.apache.qpid.transport.SessionException: timed out waiting for sync: complete = 8, point = 10
	at org.apache.qpid.transport.Session.sync(Session.java:867)
	at org.apache.qpid.transport.Session.sync(Session.java:837)
	at org.apache.qpid.transport.Session.invoke(Session.java:789)
	at org.apache.qpid.transport.Session.invoke(Session.java:627)
	at org.apache.qpid.transport.SessionInvoker.txCommit(SessionInvoker.java:145)
	at org.apache.qpid.client.AMQSession_0_10.commitImpl(AMQSession_0_10.java:1037)
	at org.apache.qpid.client.AMQSession.commit(AMQSession.java:830)
	... 9 more
2014-05-08 17:15:05,129 ERROR [org.apache.qpid.client.AMQConnection] Throwable Received but no listener set: org.apache.qpid.AMQException: timed out waiting for sync: complete = 9, point = 13 [error code 541: internal error]

Comment 8 Leonid Zhaldybin 2014-08-14 10:34:02 UTC


*** This bug has been marked as a duplicate of bug 1095849 ***