[ https://issues.apache.org/jira/browse/ARTEMIS-1317?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
clebert suconic closed ARTEMIS-1317. ------------------------------------ > Messages that expire on OpenWire client are lost (never make it to > ExpiryQueue, if one is configured) > ----------------------------------------------------------------------------------------------------- > > Key: ARTEMIS-1317 > URL: https://issues.apache.org/jira/browse/ARTEMIS-1317 > Project: ActiveMQ Artemis > Issue Type: Bug > Components: Broker, OpenWire > Affects Versions: 2.2.0, 2.3.0 > Reporter: Jiri Danek > Priority: Critical > Fix For: 2.3.0 > > > The scenario is tested by an openwire test from activemq5, which is currently > failing. > {noformat} > Running org.apache.activemq.JmsSendReceiveWithMessageExpirationTest > xxxxxcreating conn: > tcp://localhost:61616?invmBrokerId=localhost&broker.persistent=false > 2017-08-01 08:40:22,905 [main ] - INFO TcpTransportFactory > - deciding whether starting an internal broker: null flag: false > 2017-08-01 08:40:22,905 [main ] - INFO TcpTransportFactory > - starting internal broker: tcp://localhost:61616 > 2017-08-01 08:40:22,905 [main ] - INFO ArtemisBrokerHelper > - ---starting broker, service is there? null > 2017-08-01 08:40:22,905 [main ] - INFO BrokerService > - Apache ActiveMQ Artemis Wrapper 5.14.0 (localhost, Artemis Broker) is > starting > acceptor =>: TransportConfiguration(name=home, > factory=org-apache-activemq-artemis-core-remoting-impl-netty-NettyAcceptorFactory) > ?port=61616&host=localhost > [main] 08:40:22,906 INFO [org.apache.activemq.artemis.core.server] > AMQ221000: live Message Broker is starting with configuration Broker > Configuration > (clustered=false,journalDirectory=/root/workspace/peline_jdanek_artemis_junit-MXKODGBZMK2IRSU3ZGP3WXI5HYEVJ64OU2VN7HHODGYVOJ5FA7IQ/tests/activemq5-unit-tests/./target/tmp/junit5554952782813333836/journal,bindingsDirectory=/root/workspace/peline_jdanek_artemis_junit-MXKODGBZMK2IRSU3ZGP3WXI5HYEVJ64OU2VN7HHODGYVOJ5FA7IQ/tests/activemq5-unit-tests/./target/tmp/junit5554952782813333836/bindings,largeMessagesDirectory=/root/workspace/peline_jdanek_artemis_junit-MXKODGBZMK2IRSU3ZGP3WXI5HYEVJ64OU2VN7HHODGYVOJ5FA7IQ/tests/activemq5-unit-tests/./target/tmp/junit5554952782813333836/large-msg,pagingDirectory=/root/workspace/peline_jdanek_artemis_junit-MXKODGBZMK2IRSU3ZGP3WXI5HYEVJ64OU2VN7HHODGYVOJ5FA7IQ/tests/activemq5-unit-tests/./target/tmp/junit5554952782813333836/page) > [main] 08:40:22,906 INFO [org.apache.activemq.artemis.core.server] > AMQ221057: Global Max Size is being adjusted to 1/2 of the JVM max size > (-Xmx). being defined as 1,851,260,928 > [main] 08:40:22,906 INFO [org.apache.activemq.artemis.core.server] > AMQ221043: Protocol module found: [artemis-server]. Adding protocol support > for: CORE > [main] 08:40:22,907 INFO [org.apache.activemq.artemis.core.server] > AMQ221043: Protocol module found: [artemis-openwire-protocol]. Adding > protocol support for: OPENWIRE > [main] 08:40:22,907 INFO [org.apache.activemq.artemis.core.server] > AMQ221043: Protocol module found: [artemis-stomp-protocol]. Adding protocol > support for: STOMP > [main] 08:40:22,910 INFO [org.apache.activemq.artemis.core.server] > AMQ221020: Started EPOLL Acceptor at localhost:61616 for protocols > [CORE,STOMP,OPENWIRE] > [main] 08:40:22,910 INFO [org.apache.activemq.artemis.core.server] > AMQ221007: Server is now live > [main] 08:40:22,910 INFO [org.apache.activemq.artemis.core.server] > AMQ221001: Apache ActiveMQ Artemis Message Broker version 2.3.0-SNAPSHOT > [localhost, nodeID=95e57e85-76b6-11e7-aa4e-fa163e5a2b31] > 2017-08-01 08:40:22,910 [main ] - INFO BrokerService > - Apache ActiveMQ Artemis Wrapper 5.14.0 (localhost, Artemis Broker) > started > 2017-08-01 08:40:22,910 [main ] - INFO BrokerService > - For help or more information please see: http://activemq.apache.org > 2017-08-01 08:40:22,910 [main ] - INFO ArtemisBrokerHelper > - started a service instance: > BrokerService[localhost]org.apache.activemq.broker.BrokerService@47a71f54 > 2017-08-01 08:40:22,910 [main ] - INFO TcpTransportFactory > - just created > tcp://localhost:61616?invmBrokerId=localhost&broker.persistent=false@1501591222910 > 2017-08-01 08:40:22,910 [main ] - INFO TcpTransportFactory > - bound: localhost > xxxxxxxxxxxx created transporttcp://localhost:61616 > 2017-08-01 08:40:22,934 [main ] - INFO > ceiveWithMessageExpirationTest - Dumping stats... > 2017-08-01 08:40:22,934 [main ] - INFO > ceiveWithMessageExpirationTest - Closing down connection > [Thread-1 (activemq-netty-threads)] 08:40:22,935 WARN > [org.apache.activemq.artemis.core.server] AMQ222061: Client connection > failed, clearing up resources for session 95e68ff6-76b6-11e7-aa4e-fa163e5a2b31 > [Thread-1 (activemq-netty-threads)] 08:40:22,935 WARN > [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for > session 95e68ff6-76b6-11e7-aa4e-fa163e5a2b31 > [Thread-1 (activemq-netty-threads)] 08:40:22,935 WARN > [org.apache.activemq.artemis.core.server] AMQ222061: Client connection > failed, clearing up resources for session > ID:host-172-0-0-126.openstacklocal-39842-1501590872918-807:1:-1 > [Thread-1 (activemq-netty-threads)] 08:40:22,935 WARN > [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for > session ID:host-172-0-0-126.openstacklocal-39842-1501590872918-807:1:-1 > xxxxxcreating conn: > tcp://localhost:61616?invmBrokerId=localhost&broker.persistent=false > 2017-08-01 08:40:22,937 [main ] - INFO TcpTransportFactory > - deciding whether starting an internal broker: > tcp://localhost:61616?invmBrokerId=localhost&broker.persistent=false@1501591222910 > flag: false > xxxxxxxxxxxx created transporttcp://localhost:61616 > 2017-08-01 08:40:22,975 [main ] - INFO > ceiveWithMessageExpirationTest - Dumping stats... > 2017-08-01 08:40:22,976 [main ] - INFO > ceiveWithMessageExpirationTest - Closing down connection > [Thread-2 (activemq-netty-threads)] 08:40:22,976 WARN > [org.apache.activemq.artemis.core.server] AMQ222061: Client connection > failed, clearing up resources for session 95ea608a-76b6-11e7-aa4e-fa163e5a2b31 > [Thread-2 (activemq-netty-threads)] 08:40:22,977 WARN > [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for > session 95ea608a-76b6-11e7-aa4e-fa163e5a2b31 > [Thread-2 (activemq-netty-threads)] 08:40:22,977 WARN > [org.apache.activemq.artemis.core.server] AMQ222061: Client connection > failed, clearing up resources for session > ID:host-172-0-0-126.openstacklocal-39842-1501590872918-809:1:-1 > [Thread-2 (activemq-netty-threads)] 08:40:22,977 WARN > [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for > session ID:host-172-0-0-126.openstacklocal-39842-1501590872918-809:1:-1 > xxxxxcreating conn: > tcp://localhost:61616?invmBrokerId=localhost&broker.persistent=false > 2017-08-01 08:40:22,980 [main ] - INFO TcpTransportFactory > - deciding whether starting an internal broker: > tcp://localhost:61616?invmBrokerId=localhost&broker.persistent=false@1501591222910 > flag: false > xxxxxxxxxxxx created transporttcp://localhost:61616 > 2017-08-01 08:40:30,014 [main ] - INFO > ceiveWithMessageExpirationTest - Dumping stats... > 2017-08-01 08:40:30,014 [main ] - INFO > ceiveWithMessageExpirationTest - Closing down connection > [Thread-3 (activemq-netty-threads)] 08:40:30,015 WARN > [org.apache.activemq.artemis.core.server] AMQ222061: Client connection > failed, clearing up resources for session 95f13e5e-76b6-11e7-aa4e-fa163e5a2b31 > [Thread-3 (activemq-netty-threads)] 08:40:30,015 WARN > [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for > session 95f13e5e-76b6-11e7-aa4e-fa163e5a2b31 > [Thread-3 (activemq-netty-threads)] 08:40:30,015 WARN > [org.apache.activemq.artemis.core.server] AMQ222061: Client connection > failed, clearing up resources for session > ID:host-172-0-0-126.openstacklocal-39842-1501590872918-811:1:-1 > [Thread-3 (activemq-netty-threads)] 08:40:30,015 WARN > [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for > session ID:host-172-0-0-126.openstacklocal-39842-1501590872918-811:1:-1 > xxxxxcreating conn: > tcp://localhost:61616?invmBrokerId=localhost&broker.persistent=false > 2017-08-01 08:40:30,017 [main ] - INFO TcpTransportFactory > - deciding whether starting an internal broker: > tcp://localhost:61616?invmBrokerId=localhost&broker.persistent=false@1501591222910 > flag: false > xxxxxxxxxxxx created transporttcp://localhost:61616 > 2017-08-01 08:40:37,049 [main ] - INFO > ceiveWithMessageExpirationTest - Dumping stats... > 2017-08-01 08:40:37,049 [main ] - INFO > ceiveWithMessageExpirationTest - Closing down connection > [Thread-4 (activemq-netty-threads)] 08:40:37,049 WARN > [org.apache.activemq.artemis.core.server] AMQ222061: Client connection > failed, clearing up resources for session 9a22da22-76b6-11e7-aa4e-fa163e5a2b31 > [Thread-4 (activemq-netty-threads)] 08:40:37,050 WARN > [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for > session 9a22da22-76b6-11e7-aa4e-fa163e5a2b31 > [Thread-4 (activemq-netty-threads)] 08:40:37,050 WARN > [org.apache.activemq.artemis.core.server] AMQ222061: Client connection > failed, clearing up resources for session > ID:host-172-0-0-126.openstacklocal-39842-1501590872918-813:1:-1 > [Thread-4 (activemq-netty-threads)] 08:40:37,050 WARN > [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for > session ID:host-172-0-0-126.openstacklocal-39842-1501590872918-813:1:-1 > xxxxxcreating conn: > tcp://localhost:61616?invmBrokerId=localhost&broker.persistent=false > 2017-08-01 08:40:37,053 [main ] - INFO TcpTransportFactory > - deciding whether starting an internal broker: > tcp://localhost:61616?invmBrokerId=localhost&broker.persistent=false@1501591222910 > flag: false > xxxxxxxxxxxx created transporttcp://localhost:61616 > xxxxxcreating conn: > tcp://localhost:61616?invmBrokerId=localhost&broker.persistent=false > 2017-08-01 08:40:37,058 [main ] - INFO TcpTransportFactory > - deciding whether starting an internal broker: > tcp://localhost:61616?invmBrokerId=localhost&broker.persistent=false@1501591222910 > flag: false > xxxxxxxxxxxx created transporttcp://localhost:61616 > 2017-08-01 08:40:40,284 [main ] - INFO > ceiveWithMessageExpirationTest - Dumping stats... > 2017-08-01 08:40:40,284 [main ] - INFO > ceiveWithMessageExpirationTest - Closing down connection > [Thread-5 (activemq-netty-threads)] 08:40:40,285 WARN > [org.apache.activemq.artemis.core.server] AMQ222061: Client connection > failed, clearing up resources for session 9e544ed6-76b6-11e7-aa4e-fa163e5a2b31 > [Thread-5 (activemq-netty-threads)] 08:40:40,285 WARN > [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for > session 9e544ed6-76b6-11e7-aa4e-fa163e5a2b31 > [Thread-5 (activemq-netty-threads)] 08:40:40,285 WARN > [org.apache.activemq.artemis.core.server] AMQ222061: Client connection > failed, clearing up resources for session > ID:host-172-0-0-126.openstacklocal-39842-1501590872918-815:1:-1 > [Thread-5 (activemq-netty-threads)] 08:40:40,285 WARN > [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for > session ID:host-172-0-0-126.openstacklocal-39842-1501590872918-815:1:-1 > Tests run: 5, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 17.381 sec > <<< FAILURE! - in org.apache.activemq.JmsSendReceiveWithMessageExpirationTest > testConsumeExpiredQueueAndDlq(org.apache.activemq.JmsSendReceiveWithMessageExpirationTest) > Time elapsed: 3.235 sec <<< FAILURE! > junit.framework.AssertionFailedError: got dlq messages expected:<99> but > was:<90> > at junit.framework.Assert.fail(Assert.java:57) > at junit.framework.Assert.failNotEquals(Assert.java:329) > at junit.framework.Assert.assertEquals(Assert.java:78) > at junit.framework.Assert.assertEquals(Assert.java:234) > at junit.framework.TestCase.assertEquals(TestCase.java:401) > at > org.apache.activemq.JmsSendReceiveWithMessageExpirationTest.testConsumeExpiredQueueAndDlq(JmsSendReceiveWithMessageExpirationTest.java:164) > {noformat} > I've discussed the test with Clebert at ARTEMIS-1276 > (https://github.com/apache/activemq-artemis/pull/1407) > IMO, the reason for the assertion error is that the client's prefetch value > is 10 messages, out of which 1 message is consumed immediately (on time), > while the remaining 9 messages are left to expire in the prefetch cache. > The test then tries to get the expired messages from ExpiryQueue, but gets > only 90 that expired on the server. The 9 that expired on client are missing. -- This message was sent by Atlassian JIRA (v6.4.14#64029)