-
Bug
-
Resolution: Done
-
Major
-
JBoss A-MQ 6.3
-
None
-
6.3.0 R12 HF2 (batched local TX)
Duplicate message after durable subscriber failover during a batched local TX.
jms.prefetchPolicy.all=100 and jms.redeliveryPolicy.maximumRedeliveries=-1
Test client logs:
2019-08-12 14:53:14,996 [Consumer.main()] INFO it.fvaleri.fuse.Consumer - Running client
2019-08-12 14:53:15,077 [Consumer.main()] DEBUG it.fvaleri.fuse.Consumer - JNDI context: {java.naming.provider.url=failover:(tcp://localhost:61616)?jms.watchTopicAdvisories=false&jms.prefetchPolicy.all=100&jms.alwaysSyncSend=true&jms.redeliveryPolicy.maximumRedeliveries=-1, java.naming.factory.initial=org.apache.activemq.jndi.ActiveMQInitialContextFactory, topic.TestTopic=TestTopic}
2019-08-12 14:53:15,244 [ActiveMQ Task-1] INFO ort.failover.FailoverTransport - Successfully connected to tcp://localhost:61616
2019-08-12 14:53:15,289 [Consumer.main()] INFO it.fvaleri.fuse.Consumer - Got message: Hello World 0
2019-08-12 14:53:15,392 [Consumer.main()] INFO it.fvaleri.fuse.Consumer - Got message: Hello World 1
2019-08-12 14:53:15,497 [Consumer.main()] INFO it.fvaleri.fuse.Consumer - Got message: Hello World 2
...
2019-08-12 14:53:46,277 [Consumer.main()] INFO it.fvaleri.fuse.Consumer - Got message: Hello World 299
2019-08-12 14:54:35,997 [0.1:61616@63072] WARN ort.failover.FailoverTransport - Transport (tcp://localhost:61616) failed, attempting to automatically reconnect
java.net.SocketException: Operation timed out (Read failed)
at java.net.SocketInputStream.socketRead0(Native Method) ~[?:1.8.0_181]
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[?:1.8.0_181]
at java.net.SocketInputStream.read(SocketInputStream.java:171) ~[?:1.8.0_181]
at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[?:1.8.0_181]
at org.apache.activemq.transport.tcp.TcpBufferedInputStream.fill(TcpBufferedInputStream.java:50) ~[activemq-client-5.11.0.redhat-630396.jar:5.11.0.redhat-630396]
at org.apache.activemq.transport.tcp.TcpTransport$2.fill(TcpTransport.java:609) ~[activemq-client-5.11.0.redhat-630396.jar:5.11.0.redhat-630396]
at org.apache.activemq.transport.tcp.TcpBufferedInputStream.read(TcpBufferedInputStream.java:58) ~[activemq-client-5.11.0.redhat-630396.jar:5.11.0.redhat-630396]
at org.apache.activemq.transport.tcp.TcpTransport$2.read(TcpTransport.java:594) ~[activemq-client-5.11.0.redhat-630396.jar:5.11.0.redhat-630396]
at java.io.DataInputStream.readInt(DataInputStream.java:387) ~[?:1.8.0_181]
at org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:259) ~[activemq-client-5.11.0.redhat-630396.jar:5.11.0.redhat-630396]
at org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:221) ~[activemq-client-5.11.0.redhat-630396.jar:5.11.0.redhat-630396]
at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:213) ~[activemq-client-5.11.0.redhat-630396.jar:5.11.0.redhat-630396]
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196) [activemq-client-5.11.0.redhat-630396.jar:5.11.0.redhat-630396]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_181]
2019-08-12 14:55:02,007 [ActiveMQ Task-3] WARN ort.failover.FailoverTransport - Failed to connect to [tcp://localhost:61616] after: 1 attempt(s) with Operation timed out (Connection timed out), continuing to retry.
2019-08-12 14:55:32,085 [ActiveMQ Task-3] INFO ort.failover.FailoverTransport - Successfully reconnected to tcp://localhost:61616
2019-08-12 14:55:32,095 [Consumer.main()] INFO it.fvaleri.fuse.Consumer - Got message: Hello World 0
2019-08-12 14:55:32,198 [Consumer.main()] INFO it.fvaleri.fuse.Consumer - Got message: Hello World 1
2019-08-12 14:55:32,303 [Consumer.main()] INFO it.fvaleri.fuse.Consumer - Got message: Hello World 2
...
2019-08-12 14:55:33,446 [Consumer.main()] INFO it.fvaleri.fuse.Consumer - Got message: Hello World 13
2019-08-12 14:55:33,548 [Consumer.main()] INFO it.fvaleri.fuse.Consumer - Got message: Hello World 300
2019-08-12 14:55:33,649 [Consumer.main()] INFO it.fvaleri.fuse.Consumer - Got message: Hello World 301
...
2019-08-12 14:56:44,180 [Consumer.main()] INFO it.fvaleri.fuse.Consumer - Got message: Hello World 985
2019-08-12 14:56:44,284 [Consumer.main()] WARN tivemq.ActiveMQMessageConsumer - rolling back transaction (TX:ID:localhost-63071-1565614395096-1:1:1) post failover recovery. 14 previously delivered message(s) not replayed to consumer: ID:localhost-63071-1565614395096-1:1:1:1
2019-08-12 14:56:44,297 [Consumer.main()] ERROR it.fvaleri.fuse.Consumer - Client error
javax.jms.TransactionRolledBackException: rolling back transaction (TX:ID:localhost-63071-1565614395096-1:1:1) post failover recovery. 14 previously delivered message(s) not replayed to consumer: ID:localhost-63071-1565614395096-1:1:1:1
at org.apache.activemq.ActiveMQMessageConsumer.rollbackOnFailedRecoveryRedelivery(ActiveMQMessageConsumer.java:1165) ~[activemq-client-5.11.0.redhat-630396.jar:5.11.0.redhat-630396]
at org.apache.activemq.ActiveMQMessageConsumer.acknowledge(ActiveMQMessageConsumer.java:1099) ~[activemq-client-5.11.0.redhat-630396.jar:5.11.0.redhat-630396]
at org.apache.activemq.ActiveMQMessageConsumer$5.beforeEnd(ActiveMQMessageConsumer.java:1062) ~[activemq-client-5.11.0.redhat-630396.jar:5.11.0.redhat-630396]
at org.apache.activemq.TransactionContext.beforeEnd(TransactionContext.java:207) ~[activemq-client-5.11.0.redhat-630396.jar:5.11.0.redhat-630396]
at org.apache.activemq.TransactionContext.commit(TransactionContext.java:310) ~[activemq-client-5.11.0.redhat-630396.jar:5.11.0.redhat-630396]
at org.apache.activemq.ActiveMQSession.commit(ActiveMQSession.java:582) ~[activemq-client-5.11.0.redhat-630396.jar:5.11.0.redhat-630396]
at it.fvaleri.fuse.Consumer.run(Consumer.java:60) [classes/:?]
at it.fvaleri.fuse.Consumer.main(Consumer.java:20) [classes/:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_181]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_181]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_181]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_181]
at org.codehaus.mojo.exec.ExecJavaMojo$1.run(ExecJavaMojo.java:282) [exec-maven-plugin-1.6.0.jar:?]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_181]
2019-08-12 14:56:44,298 [Consumer.main()] WARN it.fvaleri.fuse.Consumer - Rollback
Broker stats after test:
JBossA-MQ:karaf@root> activemq:dstat Name Queue Size Producer # Consumer # Enqueue # Dequeue # Forward # Memory % TestTopic 0 0 1 3000 0 0 1