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.doCompositeConnect(
VMTransportFactory.java:127)
[exec]
org.apache.activemq.transport.vm.VMTransportFactory.doConnect(VMTranspo
rtFactory.java:56)
[exec]
org.apache.activemq.transport.TransportFactory.connect(TransportFactory
.java:65)
[exec]
org.apache.activemq.ActiveMQConnectionFactory.createTransport(ActiveMQC
onnectionFactory.java:331)
[exec]
org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(
ActiveMQConnectionFactory.java:346)
[exec]
org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(
ActiveMQConnectionFactory.java:304)
[exec]
org.apache.activemq.ActiveMQConnectionFactory.createConnection(ActiveMQ
ConnectionFactory.java:244)
[exec]
org.springframework.jms.connection.SingleConnectionFactory.doCreateConn
ection(SingleConnectionFactory.java:342)
[exec]
org.springframework.jms.connection.SingleConnectionFactory.initConnecti
on(SingleConnectionFactory.java:288)
[exec]
org.springframework.jms.connection.SingleConnectionFactory.createConnec
tion(SingleConnectionFactory.java:225)
[exec]
org.springframework.jms.support.JmsAccessor.createConnection(JmsAccesso
r.java:184)
[exec]
org.springframework.jms.listener.AbstractJmsListeningContainer.createSh
aredConnection(AbstractJmsListeningContainer.java:405)
[exec]
org.springframework.jms.listener.AbstractJmsListeningContainer.refreshS
haredConnection(AbstractJmsListeningContainer.java:390)
[exec]
org.springframework.jms.listener.DefaultMessageListenerContainer.refres
hConnectionUntilSuccessful(DefaultMessageListenerContainer.java:885)
[exec]
org.springframework.jms.listener.DefaultMessageListenerContainer.recove
rAfterListenerSetupFailure(DefaultMessageListenerContainer.java:861)
[exec]
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncM
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.doCompositeConnect(
VMTransportFactory.java:127)
[exec]
org.apache.activemq.transport.vm.VMTransportFactory.doConnect(VMTranspo
rtFactory.java:56)
[exec]
org.apache.activemq.transport.TransportFactory.connect(TransportFactory
.java:65)
[exec]
org.apache.activemq.ActiveMQConnectionFactory.createTransport(ActiveMQC
onnectionFactory.java:331)
[exec]
org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(
ActiveMQConnectionFactory.java:346)
[exec]
org.apache.activemq.ActiveMQConnectionFactory.createActiveMQConnection(
ActiveMQConnectionFactory.java:304)
[exec]
org.apache.activemq.ActiveMQConnectionFactory.createConnection(ActiveMQ
ConnectionFactory.java:244)
[exec]
org.springframework.jms.connection.SingleConnectionFactory.doCreateConn
ection(SingleConnectionFactory.java:342)
[exec]
org.springframework.jms.connection.SingleConnectionFactory.initConnecti
on(SingleConnectionFactory.java:288)
[exec]
org.springframework.jms.connection.SingleConnectionFactory.createConnec
tion(SingleConnectionFactory.java:225)
[exec]
org.springframework.jms.support.JmsAccessor.createConnection(JmsAccesso
r.java:184)
[exec]
org.springframework.jms.listener.AbstractJmsListeningContainer.createSh
aredConnection(AbstractJmsListeningContainer.java:405)
[exec]
org.springframework.jms.listener.AbstractJmsListeningContainer.refreshS
haredConnection(AbstractJmsListeningContainer.java:390)
[exec]
org.springframework.jms.listener.DefaultMessageListenerContainer.refres
hConnectionUntilSuccessful(DefaultMessageListenerContainer.java:885)
[exec]
org.springframework.jms.listener.DefaultMessageListenerContainer.recove
rAfterListenerSetupFailure(DefaultMessageListenerContainer.java:861)
[exec]
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncM
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.PListStoreIm
> > > > 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.DefaultMessageListenerContain
> > > > er#0-1]
> > > >
> > > > INFO Using Persistence Adapter:
> > > > KahaDBPersistenceAdapter[/home/martijn/git/ciphermail-
> > > > core/activemq-
> > > > data/localhost/KahaDB] (org.apache.activemq.broker.BrokerSer
> > > > vice)
> > > > [org.springframework.jms.listener.DefaultMessageListenerContain
> > > > 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.DefaultMessageListenerC
> > > > 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
> > > > > >
> > > > > >
> >
> >
