Uploaded image for project: 'JBoss A-MQ'
  1. JBoss A-MQ
  2. ENTMQ-2321

Duplicates after durable sub failover during a batched local TX

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Major Major
    • JBoss A-MQ 6.3.x
    • JBoss A-MQ 6.3
    • None
    • Hide

      Minimal JMS reproducer attached.
      There is a README with detailed instructions on how to reproduce it.

      Show
      Minimal JMS reproducer attached. There is a README with detailed instructions on how to reproduce it.

      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
      

        1. FailoverDurableSubTransactionTest.java
          9 kB
          Gary Tully
        2. Screenshot 2019-08-12 at 4.31.32 PM.jpg
          916 kB
          Federico Valeri

              gtully@redhat.com Gary Tully
              rhn-support-fvaleri Federico Valeri
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Created:
                Updated:
                Resolved: