I forgot to add that the issue only happens with a VM Transport, i.e., if I configure a tcp transport, shutdown works correctly.
Kind regards, Martijn Brinkers On Mon, 2020-12-14 at 15:51 +0100, Martijn Brinkers (list) wrote: > Hi Tim > > It took some time to debug. When I set a breakpoint (Eclipse), the > issue does not happen so it looks like some timing issue (race > condition). > > I added a stack dump to the start method of a modified BrokerService > class. > > The stack dump from BrokerService#start when the application is > shutting down: > > [exec] java.lang.Thread.getStackTrace(Thread.java:1559) > [exec] > org.apache.activemq.broker.BrokerService.start(BrokerService.java:612 > ) > [exec] > org.apache.activemq.transport.vm.VMTransportFactory.doCompositeConnec > t( > VMTransportFactory.java:127) > [exec] > org.apache.activemq.transport.vm.VMTransportFactory.doConnect(VMTrans > po > rtFactory.java:56) > [exec] > org.apache.activemq.transport.TransportFactory.connect(TransportFacto > ry > .java:65) > [exec] > org.apache.activemq.ActiveMQConnectionFactory.createTransport(ActiveM > QC > onnectionFactory.java:331) > [exec] > org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnectio > n( > ActiveMQConnectionFactory.java:346) > [exec] > org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnectio > n( > ActiveMQConnectionFactory.java:304) > [exec] > org.apache.activemq.ActiveMQConnectionFactory.createConnection(Active > MQ > ConnectionFactory.java:244) > [exec] > org.springframework.jms.connection.SingleConnectionFactory.doCreateCo > nn > ection(SingleConnectionFactory.java:342) > [exec] > org.springframework.jms.connection.SingleConnectionFactory.initConnec > ti > on(SingleConnectionFactory.java:288) > [exec] > org.springframework.jms.connection.SingleConnectionFactory.createConn > ec > tion(SingleConnectionFactory.java:225) > [exec] > org.springframework.jms.support.JmsAccessor.createConnection(JmsAcces > so > r.java:184) > [exec] > org.springframework.jms.listener.AbstractJmsListeningContainer.create > Sh > aredConnection(AbstractJmsListeningContainer.java:405) > [exec] > org.springframework.jms.listener.AbstractJmsListeningContainer.refres > hS > haredConnection(AbstractJmsListeningContainer.java:390) > [exec] > org.springframework.jms.listener.DefaultMessageListenerContainer.refr > es > hConnectionUntilSuccessful(DefaultMessageListenerContainer.java:885) > [exec] > org.springframework.jms.listener.DefaultMessageListenerContainer.reco > ve > rAfterListenerSetupFailure(DefaultMessageListenerContainer.java:861) > [exec] > org.springframework.jms.listener.DefaultMessageListenerContainer$Asyn > cM > essageListenerInvoker.run(DefaultMessageListenerContainer.java:1012) > > It looks like > DefaultMessageListenerContainer#recoverAfterListenerSetupFailure > creates a new instance of > > > Additional DEBUG output: > > [exec] 14 Dec 2020 15:41:32 | DEBUG ID:martijn-laptop-46343- > 1607956885604-4:1:1 Transaction Commit > :null (org.apache.activemq.ActiveMQSession) > [org.springframework.jms.listener.DefaultMessageListenerContainer#0- > 1] > [exec] 14 Dec 2020 15:41:32 | DEBUG Publishing: vm://localhost > for > broker transport URI: > vm://localhost (org.apache.activemq.broker.TransportConnector) > [ActiveMQ BrokerService[localhost] Task-2] > [exec] 14 Dec 2020 15:41:32 | DEBUG Publishing: vm://localhost > for > broker transport URI: > vm://localhost (org.apache.activemq.broker.TransportConnector) > [ActiveMQ BrokerService[localhost] Task-2] > [exec] 14 Dec 2020 15:41:32 | DEBUG Connection Stopped: > vm://localhost#0 (org.apache.activemq.broker.TransportConnection) > [ActiveMQ BrokerService[localhost] Task-2] > [exec] 14 Dec 2020 15:41:32 | INFO Connector vm://localhost > stopped (org.apache.activemq.broker.TransportConnector) [ActiveMQ > ShutdownHook] > [exec] 14 Dec 2020 15:41:32 | > INFO PListStore:[/home/martijn/git/ciphermail-core/var/jms- > data/localhost/tmp_storage] > stopped (org.apache.activemq.store.kahadb.plist.PListStoreImpl) > [ActiveMQ ShutdownHook] > [exec] 14 Dec 2020 15:41:32 | INFO Stopping async queue > tasks (org.apache.activemq.store.kahadb.KahaDBStore) [ActiveMQ > ShutdownHook] > [exec] 14 Dec 2020 15:41:32 | INFO Stopping async topic > tasks (org.apache.activemq.store.kahadb.KahaDBStore) [ActiveMQ > ShutdownHook] > [exec] 14 Dec 2020 15:41:32 | DEBUG Forcing shutdown of > ExecutorService: > org.apache.activemq.store.kahadb.KahaDBStore$StoreTaskExecutor@7ae5430d > [Running, pool size = 0, active threads = 0, queued tasks = 0, > completed tasks = 0] (org.apache.activemq.util.ThreadPoolUtils) > [ActiveMQ ShutdownHook] > [exec] 14 Dec 2020 15:41:32 | DEBUG Shutdown of ExecutorService: > java.util.concurrent.ThreadPoolExecutor@7cd2745d[Terminated, pool > size > = 0, active threads = 0, queued tasks = 0, completed tasks = 1] is > shutdown: true and terminated: false took: 0.000 > seconds. (org.apache.activemq.util.ThreadPoolUtils) [ActiveMQ > Connection Executor: vm://localhost#0] > [exec] 14 Dec 2020 15:41:32 | DEBUG Forcing shutdown of > ExecutorService: > org.apache.activemq.store.kahadb.KahaDBStore$StoreTaskExecutor@30030b95 > [Running, pool size = 0, active threads = 0, queued tasks = 0, > completed tasks = 0] (org.apache.activemq.util.ThreadPoolUtils) > [ActiveMQ ShutdownHook] > [exec] 14 Dec 2020 15:41:32 | INFO Stopped > KahaDB (org.apache.activemq.store.kahadb.KahaDBStore) [ActiveMQ > ShutdownHook] > [exec] 14 Dec 2020 15:41:32 | DEBUG Shutdown of ExecutorService: > java.util.concurrent.ThreadPoolExecutor@14ef957c[Shutting down, pool > size = 1, active threads = 1, queued tasks = 1, completed tasks = 0] > is > shutdown: true and terminated: false took: 0.000 > seconds. (org.apache.activemq.util.ThreadPoolUtils) [ActiveMQ > Connection Executor: vm://localhost#0] > [exec] 14 Dec 2020 15:41:32 | DEBUG Forcing shutdown of > ExecutorService: > java.util.concurrent.ThreadPoolExecutor@7a50bc0d[Running, pool size = > 2, active threads = 0, queued tasks = 0, completed tasks = > 6] (org.apache.activemq.util.ThreadPoolUtils) [ActiveMQ Connection > Executor: vm://localhost#0] > [exec] 14 Dec 2020 15:41:32 | DEBUG Checkpoint > started. (org.apache.activemq.store.kahadb.MessageDatabase) > [ActiveMQ ShutdownHook] > [exec] 14 Dec 2020 15:41:32 | DEBUG Checkpoint > done. (org.apache.activemq.store.kahadb.MessageDatabase) [ActiveMQ > ShutdownHook] > [exec] java.lang.Thread.getStackTrace(Thread.java:1559) > [exec] > org.apache.activemq.broker.BrokerService.start(BrokerService.java:612 > ) > [exec] > org.apache.activemq.transport.vm.VMTransportFactory.doCompositeConnec > t( > VMTransportFactory.java:127) > [exec] > org.apache.activemq.transport.vm.VMTransportFactory.doConnect(VMTrans > po > rtFactory.java:56) > [exec] > org.apache.activemq.transport.TransportFactory.connect(TransportFacto > ry > .java:65) > [exec] > org.apache.activemq.ActiveMQConnectionFactory.createTransport(ActiveM > QC > onnectionFactory.java:331) > [exec] > org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnectio > n( > ActiveMQConnectionFactory.java:346) > [exec] > org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnectio > n( > ActiveMQConnectionFactory.java:304) > [exec] > org.apache.activemq.ActiveMQConnectionFactory.createConnection(Active > MQ > ConnectionFactory.java:244) > [exec] > org.springframework.jms.connection.SingleConnectionFactory.doCreateCo > nn > ection(SingleConnectionFactory.java:342) > [exec] > org.springframework.jms.connection.SingleConnectionFactory.initConnec > ti > on(SingleConnectionFactory.java:288) > [exec] > org.springframework.jms.connection.SingleConnectionFactory.createConn > ec > tion(SingleConnectionFactory.java:225) > [exec] > org.springframework.jms.support.JmsAccessor.createConnection(JmsAcces > so > r.java:184) > [exec] > org.springframework.jms.listener.AbstractJmsListeningContainer.create > Sh > aredConnection(AbstractJmsListeningContainer.java:405) > [exec] > org.springframework.jms.listener.AbstractJmsListeningContainer.refres > hS > haredConnection(AbstractJmsListeningContainer.java:390) > [exec] > org.springframework.jms.listener.DefaultMessageListenerContainer.refr > es > hConnectionUntilSuccessful(DefaultMessageListenerContainer.java:885) > [exec] > org.springframework.jms.listener.DefaultMessageListenerContainer.reco > ve > rAfterListenerSetupFailure(DefaultMessageListenerContainer.java:861) > [exec] > org.springframework.jms.listener.DefaultMessageListenerContainer$Asyn > cM > essageListenerInvoker.run(DefaultMessageListenerContainer.java:1012) > [exec] java.lang.Thread.run(Thread.java:748) > [exec] 14 Dec 2020 15:41:32 | WARN Memory Usage for the Broker > (1024mb) is more than the maximum available for the JVM: 455 mb - > resetting to 70% of maximum available: 318 > mb (org.apache.activemq.broker.BrokerService) > [org.springframework.jms.listener.DefaultMess > > Kind regards, > > Martijn Brinkers > > > > On Sat, 2020-12-12 at 18:17 -0700, Tim Bain wrote: > > Can you set a debugger breakpoint in one of the methods of the > > broker's > > initialization process and then trigger the behavior? Then you'll > > have > > access to the call stack (including the values of all variables at > > each > > call in the stack) that resulted in the decision to start a new > > broker, and > > hopefully by walking up the stack you'll be able to see what caused > > initialization to occur when it otherwise wouldn't be expected to. > > > > Tim > > > > On Fri, Dec 11, 2020, 11:11 AM Martijn Brinkers < > > martijn.l...@gmail.com> > > wrote: > > > > > On 11-12-2020 18:37, Jean-Baptiste Onofre wrote: > > > > Do you use the vm connector in your broker service ? > > > > > > Yes that is correct. I only use it for internal JMS messaging. > > > The > > > transportConnector is therefore set vm://localhost > > > > > > Kind regards, > > > > > > Martijn Brinkers > > > > > > > > > > > Le 11 déc. 2020 à 16:17, Martijn Brinkers (list) < > > > > > > martijn.l...@gmail.com> a écrit : > > > > > > > > > > Unfortunately it looks like it's not easy (for me) to > > > > > replicate > > > > > in a > > > > > simple application. > > > > > > > > > > It looks like the issue is related to a shutdown hook somehow > > > > > resurrecting the broker after the broker was stopped. > > > > > > > > > > Unfortunately the logging lines are a bit long so I hope it's > > > > > somewhat > > > > > readable. > > > > > > > > > > The shutdown logging shows that ActiveMQ is shutting down but > > > > > then just > > > > > after the shutdown hook, a new instance of the BrokerService > > > > > is > > > > > created > > > > > with the default values. For example it reports a warning > > > > > about > > > > > max > > > > > memory 1024mb. In the spring config however the max memory is > > > > > set to > > > > > 20MB. > > > > > > > > > > INFO Apache ActiveMQ 5.16.0 (localhost, ID:martijn-laptop- > > > > > 45763- > > > > > 1607698489325-0:1) is shutting > > > > > down (org.apache.activemq.broker.BrokerService) [ActiveMQ > > > > > ShutdownHook] > > > > > > > > > > INFO Connector vm://localhost > > > > > stopped (org.apache.activemq.broker.TransportConnector) > > > > > [ActiveMQ > > > > > ShutdownHook] > > > > > > > > > > INFO PListStore:[/home/martijn/git/ciphermail-core/var/jms- > > > > > data/localhost/tmp_storage] > > > > > stopped (org.apache.activemq.store.kahadb.plist.PListStore > > > > > Im > > > > > pl) > > > > > [ActiveMQ ShutdownHook] > > > > > > > > > > INFO Stopping async queue > > > > > tasks (org.apache.activemq.store.kahadb.KahaDBStore) > > > > > [ActiveMQ > > > > > ShutdownHook] > > > > > > > > > > INFO Stopping async topic > > > > > tasks (org.apache.activemq.store.kahadb.KahaDBStore) > > > > > [ActiveMQ > > > > > ShutdownHook] > > > > > > > > > > INFO Stopped > > > > > KahaDB (org.apache.activemq.store.kahadb.KahaDBStore) > > > > > [ActiveMQ ShutdownHook] > > > > > > > > > > WARN Memory Usage for the Broker (1024mb) is more than the > > > > > maximum > > > > > available for the JVM: 455 mb - resetting to 70% of maximum > > > > > available: > > > > > 318 mb (org.apache.activemq.broker.BrokerService) > > > > > [org.springframework.jms.listener.DefaultMessageListenerConta > > > > > in > > > > > er#0-1] > > > > > > > > > > INFO Using Persistence Adapter: > > > > > KahaDBPersistenceAdapter[/home/martijn/git/ciphermail- > > > > > core/activemq- > > > > > data/localhost/KahaDB] (org.apache.activemq.broker.BrokerS > > > > > er > > > > > vice) > > > > > [org.springframework.jms.listener.DefaultMessageListenerConta > > > > > in > > > > > er#0-1] > > > > > > > > > > INFO Apache ActiveMQ 5.16.0 (localhost, ID:martijn-laptop- > > > > > 45763- > > > > > 1607698489325-0:1) uptime 7.446 > > > > > seconds (org.apache.activemq.broker.BrokerService) > > > > > [ActiveMQ > > > > > ShutdownHook] > > > > > > > > > > INFO Apache ActiveMQ 5.16.0 (localhost, ID:martijn-laptop- > > > > > 45763- > > > > > 1607698489325-0:1) is > > > > > shutdown (org.apache.activemq.broker.BrokerService) > > > > > [ActiveMQ > > > > > ShutdownHook] > > > > > > > > > > A simple test application does not show this issue. > > > > > > > > > > If I disable (i.e., comment out) the following > > > > > DefaultMessageListenerContainer, then the shutdown works > > > > > normally. > > > > > > > > > > <bean > > > > > class="org.springframework.jms.listener.DefaultMessageListene > > > > > rC > > > > > ontainer > > > > > " > > > > > > <property name="connectionFactory" > > > > > ref="connectionFactory"/> > > > > > <property name="destination" > > > > > ref="certificateCreatedTopic"/> > > > > > <property name="sessionTransacted" value="true" /> > > > > > <property name="pubSubDomain" value="true"/> > > > > > <property name="subscriptionDurable" value="true" /> > > > > > <property name="clientId" value="ciphermail.gateway" /> > > > > > <property name="durableSubscriptionName" > > > > > value="certificate- > > > > > created-listener" /> > > > > > </bean> > > > > > > > > > > For some reason adding DefaultMessageListenerContainer > > > > > instance > > > > > somehow > > > > > results in restarting and instance of BrokerService which is > > > > > then > > > > > shutdown. > > > > > > > > > > Any idea? > > > > > > > > > > Kind regards, > > > > > > > > > > Martijn Brinkers > > > > > > > > > > On Fri, 2020-12-11 at 06:09 -0700, Tim Bain wrote: > > > > > > This sounds like a bug. Please submit a bug in JIRA, > > > > > > ideally > > > > > > attaching a > > > > > > minimal reproducer. > > > > > > > > > > > > Thanks, > > > > > > Tim > > > > > > > > > > > > On Fri, Dec 11, 2020, 5:58 AM Martijn Brinkers (list) < > > > > > > martijn.l...@gmail.com> wrote: > > > > > > > > > > > > > I have embedded ActiveMQ inside a spring application. > > > > > > > > > > > > > > The broker is configured in XML and I explicitly set the > > > > > > > dataDirectory: > > > > > > > > > > > > > > <amq:broker useJmx="false" persistent="true" > > > > > > > dataDirectory="var/jms"> > > > > > > > <amq:transportConnectors> > > > > > > > <amq:transportConnector uri="vm://localhost" /> > > > > > > > </amq:transportConnectors> > > > > > > > </amq:broker> > > > > > > > > > > > > > > When I startup my application, the var/jms directory is > > > > > > > created and > > > > > > > JMS > > > > > > > messages are stored when required. If however I shutdown > > > > > > > my > > > > > > > application, an addtional directory "activemq- > > > > > > > data/localhost/KahaDB" is > > > > > > > created. This only happens if "useShutdownHook" is true > > > > > > > (which is > > > > > > > the > > > > > > > default). > > > > > > > > > > > > > > It looks like the shutdownhook tries to create the "data > > > > > > > directory" > > > > > > > but ignores the configured value and therefore uses the > > > > > > > default > > > > > > > data > > > > > > > directory name. > > > > > > > > > > > > > > Is this a bug? Or did I make a configuration error? > > > > > > > > > > > > > > Kind regards, > > > > > > > > > > > > > > Martijn Brinkers > > > > > > > > > > > > > > > > > > > > > >
