Uploaded image for project: 'ActiveMQ Artemis'
  1. ActiveMQ Artemis
  2. ARTEMIS-2733

Stopping broker while there are pending address auto-deletes produces many ERROR messages on shut down

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Minor
    • Resolution: Fixed
    • 2.11.0
    • 2.13.0
    • Broker
    • None

    Description

      Start broker with default configuration, with user admin/admin, and the following changes applied, using artemis run in the terminal.

      diff --git a/artemis.profile b/artemis.profile
      index 140db52..62857b7 100644
      --- a/artemis.profile
      +++ b/artemis.profile
      @@ -34,6 +34,10 @@ ARTEMIS_INSTANCE_ETC_URI='file:/home/jdanek/Downloads/AMQ7/apache-artemis-2.11.0
       # Java Opts
       JAVA_ARGS=" -XX:+PrintClassHistogram -XX:+UseG1GC -Xms512M -Xmx2G -Dhawtio.realm=activemq  -Dhawtio.offline=true -Dhawtio.role=amq -Dhawtio.rolePrincipalClasses=org.apache.activemq.artemis.spi.core.security.jaas.RolePrincipal -Djolokia.policyLocation=${ARTEMIS_INSTANCE_ETC_URI}jolokia-access.xml"
       
      +JAVA_ARGS+=" -Dcom.sun.management.jmxremote=true -Dcom.sun.management.jmxremote.port=1099 -Dcom.sun.management.jmxremote.rmi.port=1099 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false"
      +
      +
      +
       #
       # Logs Safepoints JVM pauses: Uncomment to enable them
       # In addition to the traditional GC logs you could enable some JVM flags to know any meaningful and "hidden" pause that could
      diff --git a/broker.xml b/broker.xml
      index 66d3f1d..0b9cdb4 100644
      --- a/broker.xml
      +++ b/broker.xml
      @@ -106,7 +106,7 @@ under the License.
       
             <!-- once the disk hits this limit the system will block, or close the connection in certain protocols
                  that won't support flow control. -->
      -      <max-disk-usage>90</max-disk-usage>
      +      <max-disk-usage>100</max-disk-usage>
       
             <!-- should the broker detect dead locks and other issues -->
             <critical-analyzer>true</critical-analyzer>
      

      Start the attached code which creates and deletes MULTICAST queues on the broker. When it reaches queue number 2000 or so, stop the broker with Ctrl+c. It should take about 5 minutes to reach queue number 2000.

      Observe many errors of the following kind printed

      2020-04-22 16:08:00,486 ERROR [org.apache.activemq.artemis.core.server] AMQ224065: Failed to remove auto-created queue feasdft775.p: ActiveMQShutdownException[errorType=SHUTDOWN_ERROR message=Journal must be in state=LOADED, was [STOPPED]]
      	at org.apache.activemq.artemis.core.journal.impl.JournalImpl.checkJournalIsLoaded(JournalImpl.java:1087) [artemis-journal-2.11.0.jar:2.11.0]
      	at org.apache.activemq.artemis.core.journal.impl.JournalImpl.appendDeleteRecordTransactional(JournalImpl.java:1160) [artemis-journal-2.11.0.jar:2.11.0]
      	at org.apache.activemq.artemis.core.journal.impl.JournalBase.appendDeleteRecordTransactional(JournalBase.java:98) [artemis-journal-2.11.0.jar:2.11.0]
      	at org.apache.activemq.artemis.core.journal.impl.JournalImpl.appendDeleteRecordTransactional(JournalImpl.java:93) [artemis-journal-2.11.0.jar:2.11.0]
      	at org.apache.activemq.artemis.core.persistence.impl.journal.AbstractJournalStorageManager.deleteAddressBinding(AbstractJournalStorageManager.java:1396) [artemis-server-2.11.0.jar:2.11.0]
      	at org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl.removeAddressInfo(ActiveMQServerImpl.java:3312) [artemis-server-2.11.0.jar:2.11.0]
      	at org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl.removeAddressInfo(ActiveMQServerImpl.java:3292) [artemis-server-2.11.0.jar:2.11.0]
      	at org.apache.activemq.artemis.core.postoffice.impl.PostOfficeImpl$AddressQueueReaper.run(PostOfficeImpl.java:1762) [artemis-server-2.11.0.jar:2.11.0]
      	at org.apache.activemq.artemis.core.server.ActiveMQScheduledComponent$2.run(ActiveMQScheduledComponent.java:306) [artemis-commons-2.11.0.jar:2.11.0]
      	at org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:42) [artemis-commons-2.11.0.jar:2.11.0]
      	at org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:31) [artemis-commons-2.11.0.jar:2.11.0]
      	at org.apache.activemq.artemis.utils.actors.ProcessorBase.executePendingTasks(ProcessorBase.java:66) [artemis-commons-2.11.0.jar:2.11.0]
      	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [java.base:]
      	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [java.base:]
      	at org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118) [artemis-commons-2.11.0.jar:2.11.0]
      

      after which, many errors of the following form are printed

      2020-04-22 16:08:13,071 ERROR [org.apache.activemq.artemis.core.server] AMQ224065: Failed to remove auto-created queue feasdfc888.p: java.lang.NullPointerException
      

      When I encountered this for the first time, I left the JMX program running for a long time, and let it to go to queue number 30000 or so before stopping the broker, When I started the broker again, it started slowly, and eventually ran out of heap space without completing startup. I was unable to replicate this afterwards.

      2020-04-22 19:51:08,723 INFO  [org.apache.activemq.artemis.integration.bootstrap] AMQ101000: Starting ActiveMQ Artemis Server
      2020-04-22 19:51:08,821 INFO  [org.apache.activemq.artemis.core.server] AMQ221000: live Message Broker is starting with configuration Broker Configuration (clustered=false,journalDirectory=data/journal,bindingsDirectory=data/bindings,largeMessagesDirectory=data/large-messages,pagingDirectory=data/paging)
      2020-04-22 19:51:08,926 INFO  [org.apache.activemq.artemis.core.server] AMQ221013: Using NIO Journal
      2020-04-22 19:51:09,070 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,073,741,824
      2020-04-22 19:51:09,126 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-server]. Adding protocol support for: CORE
      2020-04-22 19:51:09,127 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-amqp-protocol]. Adding protocol support for: AMQP
      2020-04-22 19:51:09,132 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-hornetq-protocol]. Adding protocol support for: HORNETQ
      2020-04-22 19:51:09,139 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-mqtt-protocol]. Adding protocol support for: MQTT
      2020-04-22 19:51:09,146 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-openwire-protocol]. Adding protocol support for: OPENWIRE
      2020-04-22 19:51:09,147 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-stomp-protocol]. Adding protocol support for: STOMP
      2020-04-22 19:51:09,316 INFO  [org.apache.activemq.artemis.core.server] AMQ221034: Waiting indefinitely to obtain live lock
      2020-04-22 19:51:09,317 INFO  [org.apache.activemq.artemis.core.server] AMQ221035: Live Server Obtained live lock
      2020-04-22 19:51:31,614 INFO  [org.apache.activemq.artemis.core.server] AMQ221080: Deploying address DLQ supporting [ANYCAST]
      2020-04-22 19:51:31,614 INFO  [org.apache.activemq.artemis.core.server] AMQ221003: Deploying ANYCAST queue DLQ on address DLQ
      2020-04-22 19:51:31,615 INFO  [org.apache.activemq.artemis.core.server] AMQ221080: Deploying address ExpiryQueue supporting [ANYCAST]
      2020-04-22 19:51:31,615 INFO  [org.apache.activemq.artemis.core.server] AMQ221003: Deploying ANYCAST queue ExpiryQueue on address ExpiryQueue
      2020-04-22 19:51:32,318 INFO  [org.apache.activemq.artemis.core.server] AMQ221020: Started EPOLL Acceptor at 0.0.0.0:61616 for protocols [CORE,MQTT,AMQP,STOMP,HORNETQ,OPENWIRE]
      2020-04-22 19:51:32,322 INFO  [org.apache.activemq.artemis.core.server] AMQ221020: Started EPOLL Acceptor at 0.0.0.0:5445 for protocols [HORNETQ,STOMP]
      2020-04-22 19:51:32,332 INFO  [org.apache.activemq.artemis.core.server] AMQ221020: Started EPOLL Acceptor at 0.0.0.0:5672 for protocols [AMQP]
      2020-04-22 19:51:32,336 INFO  [org.apache.activemq.artemis.core.server] AMQ221020: Started EPOLL Acceptor at 0.0.0.0:1883 for protocols [MQTT]
      2020-04-22 19:51:32,340 INFO  [org.apache.activemq.artemis.core.server] AMQ221020: Started EPOLL Acceptor at 0.0.0.0:61613 for protocols [STOMP]
      2020-04-22 19:51:32,345 INFO  [org.apache.activemq.artemis.core.server] AMQ221007: Server is now live
      2020-04-22 19:51:32,345 INFO  [org.apache.activemq.artemis.core.server] AMQ221001: Apache ActiveMQ Artemis Message Broker version 2.11.0 [0.0.0.0, nodeID=6fd8a068-84bb-11ea-bfc4-c6a0bfa68374] 
      2020-04-22 19:51:32,658 INFO  [org.apache.activemq.hawtio.branding.PluginContextListener] Initialized activemq-branding plugin
      2020-04-22 19:51:32,730 INFO  [org.apache.activemq.hawtio.plugin.PluginContextListener] Initialized artemis-plugin plugin
      2020-04-22 19:51:33,516 INFO  [io.hawt.HawtioContextListener] Initialising hawtio services
      2020-04-22 19:51:33,564 INFO  [io.hawt.system.ConfigManager] Configuration will be discovered via system properties
      2020-04-22 19:51:33,566 INFO  [io.hawt.jmx.JmxTreeWatcher] Welcome to hawtio 1.5.5 : http://hawt.io/ : Don't cha wish your console was hawt like me? ;-)
      2020-04-22 19:51:33,575 INFO  [io.hawt.jmx.UploadManager] Using file upload directory: /home/jdanek/Downloads/AMQ7/apache-artemis-2.11.0/i0/tmp/uploads
      2020-04-22 19:51:33,594 INFO  [io.hawt.web.AuthenticationFilter] Starting hawtio authentication filter, JAAS realm: "activemq" authorized role(s): "amq" role principal classes: "org.apache.activemq.artemis.spi.core.security.jaas.RolePrincipal"
      2020-04-22 19:51:33,642 INFO  [io.hawt.web.JolokiaConfiguredAgentServlet] Jolokia overridden property: [key=policyLocation, value=file:/home/jdanek/Downloads/AMQ7/apache-artemis-2.11.0/i0/etc/jolokia-access.xml]
      2020-04-22 19:51:33,893 INFO  [io.hawt.web.RBACMBeanInvoker] Using MBean [hawtio:type=security,area=jmx,rank=0,name=HawtioDummyJMXSecurity] for role based access control
      2020-04-22 19:51:34,786 INFO  [io.hawt.system.ProxyWhitelist] Initial proxy whitelist: [localhost, 127.0.0.1, 10.40.208.18, 192.168.86.172]
      2020-04-22 19:51:35,120 INFO  [org.apache.activemq.artemis] AMQ241001: HTTP Server started at http://localhost:8161
      2020-04-22 19:51:35,121 INFO  [org.apache.activemq.artemis] AMQ241002: Artemis Jolokia REST API available at http://localhost:8161/console/jolokia
      2020-04-22 19:51:35,121 INFO  [org.apache.activemq.artemis] AMQ241004: Artemis Console available at http://localhost:8161/console
      2020-04-22 19:51:42,554 INFO  [io.hawt.web.LoginServlet] hawtio login is using 1800 sec. HttpSession timeout
      2020-04-22 19:52:11,771 INFO  [io.hawt.web.keycloak.KeycloakServlet] Keycloak integration is disabled
      2020-04-22 19:53:08,114 WARN  [org.apache.activemq.artemis.utils.actors.OrderedExecutor] Java heap space: java.lang.OutOfMemoryError: Java heap space
      
      2020-04-22 20:00:30,746 WARN  [org.apache.activemq.artemis.utils.actors.OrderedExecutor] Java heap space: java.lang.OutOfMemoryError: Java heap space
      

      The code to create the queues over JMX is

      import com.redhat.amqx.management.artemis.ArtemisResolver;
      import org.apache.activemq.artemis.api.core.management.ActiveMQServerControl;
      
      import javax.management.MBeanServerConnection;
      import javax.management.remote.JMXConnector;
      import javax.management.remote.JMXConnectorFactory;
      import javax.management.remote.JMXServiceURL;
      import java.io.IOException;
      import java.util.HashMap;
      import java.util.Map;
      
      public class Main {
          public static void main(String[] args) {
              for (char c = 'a'; c < 'z'; c++) {
                  String prefix = String.valueOf(c);
                  new Thread(() -> {
                      try {
                          createAndDeleteQueues(prefix);
                      } catch (Exception e) {
                          e.printStackTrace();
                          System.exit(1);
                      }
                  }).start();
              }
          }
      
          public static void createAndDeleteQueues(String prefix) throws Exception {
              for (long i = 1; i < 5000; i++) {
                  String addressName = prefix + i;
                  String routingType = "MULTICAST";
      
                  System.out.println("createAndDeleteAddresses: " + addressName);
                  createQueue(addressName, routingType);
                  deleteQueue(addressName);
              }
          }
      
          public static void createQueue(String addressName, String routingType) throws Exception {
              MyArtemisResolver jmx = new MyArtemisResolver();
              ArtemisResolver artemisResolver = jmx.getArtemisResolver();
              final ActiveMQServerControl brokerView = artemisResolver.getBrokerView();
      
              brokerView.createQueue(addressName, addressName, routingType);
      
              jmx.close();
          }
      
          public static void deleteQueue(String addressName) throws Exception {
              MyArtemisResolver jmx = new MyArtemisResolver();
              ArtemisResolver artemisResolver = jmx.getArtemisResolver();
              final ActiveMQServerControl brokerView = artemisResolver.getBrokerView();
      
              brokerView.destroyQueue(addressName, true, false);
      
              jmx.close();
          }
      
          static class MyArtemisResolver {
              private final JMXConnector jmxc;
              private final String brokerName;
      
              MyArtemisResolver() throws IOException {
                  String url = "service:jmx:rmi:///jndi/rmi://localhost:1099/jmxrmi";
                  brokerName = "0.0.0.0";
      
                  Map<String, String[]> env = new HashMap<>();
                  String[] creds = {"admin", "admin"};
                  env.put(JMXConnector.CREDENTIALS, creds);
      
                  jmxc = JMXConnectorFactory.connect(new JMXServiceURL(url), env);
              }
      
              public ArtemisResolver getArtemisResolver() throws IOException {
                  MBeanServerConnection mBeanServerConnection = jmxc.getMBeanServerConnection();
                  return new ArtemisResolver(mBeanServerConnection, brokerName);
              }
      
              public void close() throws IOException {
                  if (jmxc != null) {
                      jmxc.close();
                  }
              }
          }
      }
      

      There seem to be the following issues

      • Broker does not shut down cleanly
      • (Broker was then unable to start once. I did not manage to reproduce this afterwards.)
      • Error message talks about auto-created queues when in fact there is auto-created addresses

      Workaround for the issue seems to be to wait sufficient time after deleting the queues so that all address autodeletes complete.

      Attachments

        Issue Links

          Activity

            People

              Unassigned Unassigned
              jdanek Jiri Daněk
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: