-
Bug
-
Resolution: Done
-
Major
-
JBoss A-MQ 6.3
-
None
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