Uploaded image for project: 'Spring AMQP'
  1. Spring AMQP
  2. AMQP-743

Shutdown log4j2 amqp appender in web applications

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Minor
    • Resolution: Complete
    • Affects Version/s: 1.7.2
    • Fix Version/s: 1.6.10, 2.0 M5, 1.7.3
    • Component/s: RabbitMQ
    • Labels:
    • Environment:
      log4j 2.8.2
      Spring AMQP 1.7.2-RELEASE
      Tomcat 8.5.11

      Description

      Using log4j 2.8.2 (with log4j-web), Spring AMQP 1.7.2-RELEASE in web application. During application re-deploy log4j2 AMQP appender is not shut down properly. Below startup and shutdown logs with TRACE option for log4j2:
      Startup log:

      2017-05-25 09:44:07,549 localhost-startStop-1 DEBUG Starting LoggerContext[name=/Log4j2AppenderTest] from configuration at null
      2017-05-25 09:44:07,551 localhost-startStop-1 DEBUG Starting LoggerContext[name=/Log4j2AppenderTest, org.apache.logging.log4j.core.LoggerContext@3492d9ea] with configuration XmlConfiguration[location=/home/asidorov/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/Log4j2AppenderTest/WEB-INF/classes/log4j2.xml]...
      2017-05-25 09:44:07,551 localhost-startStop-1 DEBUG Shutdown hook enabled. Registering a new one.
      2017-05-25 09:44:07,552 localhost-startStop-1 DEBUG Initializing configuration XmlConfiguration[location=/home/asidorov/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/Log4j2AppenderTest/WEB-INF/classes/log4j2.xml]
      2017-05-25 09:44:07,555 localhost-startStop-1 DEBUG Installed script engines
      2017-05-25 09:44:07,832 localhost-startStop-1 DEBUG Oracle Nashorn Version: 1.8.0_131, Language: ECMAScript, Threading: Not Thread Safe, Compile: true, Names: {nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript}
      2017-05-25 09:44:07,833 localhost-startStop-1 DEBUG PluginManager 'Core' found 114 plugins
      2017-05-25 09:44:07,833 localhost-startStop-1 DEBUG PluginManager 'Level' found 0 plugins
      2017-05-25 09:44:07,836 localhost-startStop-1 DEBUG PluginManager 'Lookup' found 14 plugins
      2017-05-25 09:44:07,838 localhost-startStop-1 DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
      2017-05-25 09:44:07,847 localhost-startStop-1 TRACE TypeConverterRegistry initializing.
      2017-05-25 09:44:07,848 localhost-startStop-1 DEBUG PluginManager 'TypeConverter' found 26 plugins
      2017-05-25 09:44:07,858 localhost-startStop-1 DEBUG PatternLayout$Builder(pattern="%d [%t] %-5p %c{1.} - %m%n", PatternSelector=null, Configuration(/home/asidorov/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/Log4j2AppenderTest/WEB-INF/classes/log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
      2017-05-25 09:44:07,859 localhost-startStop-1 DEBUG PluginManager 'Converter' found 41 plugins
      2017-05-25 09:44:07,871 localhost-startStop-1 DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender].
      2017-05-25 09:44:07,877 localhost-startStop-1 DEBUG ConsoleAppender$Builder(target="null", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d [%t] %-5p %c{1.} - %m%n), name="Console", Configuration(/home/asidorov/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/Log4j2AppenderTest/WEB-INF/classes/log4j2.xml), Filter=null)
      2017-05-25 09:44:07,878 localhost-startStop-1 DEBUG Starting OutputStreamManager SYSTEM_OUT.false.false
      2017-05-25 09:44:07,878 localhost-startStop-1 DEBUG Building Plugin[name=appender, class=org.springframework.amqp.rabbit.log4j2.AmqpAppender].
      2017-05-25 09:44:07,887 localhost-startStop-1 DEBUG createAppender(Configuration(/home/asidorov/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/Log4j2AppenderTest/WEB-INF/classes/log4j2.xml), name="Rabbit", Layout=null, Filter=null, ignoreExceptions="false", host="192.168.120.78", port="5672", addresses="null", user="logstash", password="logstash", virtualHost="hiqsrv78", senderPoolSize="0", maxSenderRetries="0", applicationId="test", routingKeyPattern="logstash-routing-key", generateId="false", deliveryMode="PERSISTENT", exchange="logstash-exchange", exchangeType="direct", declareExchange="true", durable="true", autoDelete="false", contentType="text/plain", contentEncoding="null", clientConnectionProperties="null", charset="UTF-8")
      2017-05-25 09:44:07,888 localhost-startStop-1 DEBUG PluginManager 'Converter' found 41 plugins
      2017-05-25 09:44:07,888 localhost-startStop-1 DEBUG Starting OutputStreamManager SYSTEM_OUT.false.false-2
      2017-05-25 09:44:07,896 localhost-startStop-1 DEBUG Starting AmqpManager Rabbit
      2017-05-25 09:44:07,958 localhost-startStop-1 DEBUG PluginManager 'Converter' found 41 plugins
      2017-05-25 09:44:07,959 localhost-startStop-1 DEBUG Starting OutputStreamManager SYSTEM_OUT.false.false-3
      2017-05-25 09:44:07,968 localhost-startStop-1 DEBUG Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin].
      2017-05-25 09:44:07,969 localhost-startStop-1 DEBUG createAppenders(={Console, Rabbit})
      2017-05-25 09:44:07,969 localhost-startStop-1 DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
      2017-05-25 09:44:07,970 localhost-startStop-1 DEBUG createAppenderRef(ref="Console", level="null", Filter=null)
      2017-05-25 09:44:07,970 localhost-startStop-1 DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
      2017-05-25 09:44:07,970 localhost-startStop-1 DEBUG createAppenderRef(ref="Rabbit", level="null", Filter=null)
      2017-05-25 09:44:07,970 localhost-startStop-1 DEBUG Building Plugin[name=root, class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
      2017-05-25 09:44:07,971 localhost-startStop-1 DEBUG createLogger(additivity="null", level="DEBUG", includeLocation="null", ={Console, Rabbit}, ={}, Configuration(/home/asidorov/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/Log4j2AppenderTest/WEB-INF/classes/log4j2.xml), Filter=null)
      2017-05-25 09:44:07,973 localhost-startStop-1 DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin].
      2017-05-25 09:44:07,973 localhost-startStop-1 DEBUG createLoggers(={root})
      2017-05-25 09:44:07,974 localhost-startStop-1 DEBUG Configuration XmlConfiguration[location=/home/asidorov/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/Log4j2AppenderTest/WEB-INF/classes/log4j2.xml] initialized
      2017-05-25 09:44:07,974 localhost-startStop-1 DEBUG Starting configuration XmlConfiguration[location=/home/asidorov/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/Log4j2AppenderTest/WEB-INF/classes/log4j2.xml]
      2017-05-25 09:44:07,974 localhost-startStop-1 DEBUG Started configuration XmlConfiguration[location=/home/asidorov/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/Log4j2AppenderTest/WEB-INF/classes/log4j2.xml] OK.
      2017-05-25 09:44:07,974 localhost-startStop-1 TRACE Stopping org.apache.logging.log4j.core.config.DefaultConfiguration@5becc634...
      2017-05-25 09:44:07,974 localhost-startStop-1 TRACE DefaultConfiguration notified 1 ReliabilityStrategies that config will be stopped.
      2017-05-25 09:44:07,975 localhost-startStop-1 TRACE DefaultConfiguration stopping root LoggerConfig.
      2017-05-25 09:44:07,975 localhost-startStop-1 TRACE DefaultConfiguration notifying ReliabilityStrategies that appenders will be stopped.
      2017-05-25 09:44:07,975 localhost-startStop-1 TRACE DefaultConfiguration stopping remaining Appenders.
      2017-05-25 09:44:07,975 localhost-startStop-1 DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false-1
      2017-05-25 09:44:07,975 localhost-startStop-1 DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false-1, all resources released: true
      2017-05-25 09:44:07,975 localhost-startStop-1 DEBUG Appender DefaultConsole-1 stopped with status true
      2017-05-25 09:44:07,976 localhost-startStop-1 TRACE DefaultConfiguration stopped 1 remaining Appenders.
      2017-05-25 09:44:07,976 localhost-startStop-1 TRACE DefaultConfiguration cleaning Appenders from 1 LoggerConfigs.
      2017-05-25 09:44:07,976 localhost-startStop-1 DEBUG Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@5becc634 OK
      2017-05-25 09:44:07,977 localhost-startStop-1 TRACE Reregistering MBeans after reconfigure. Selector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector@60399be2
      2017-05-25 09:44:07,977 localhost-startStop-1 TRACE Reregistering context (1/1): '/Log4j2AppenderTest' org.apache.logging.log4j.core.LoggerContext@3492d9ea
      2017-05-25 09:44:07,978 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=/Log4j2AppenderTest'
      2017-05-25 09:44:07,978 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=StatusLogger'
      2017-05-25 09:44:07,978 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=ContextSelector'
      2017-05-25 09:44:07,978 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=Loggers,name=*'
      2017-05-25 09:44:07,979 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=Appenders,name=*'
      2017-05-25 09:44:07,979 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=AsyncAppenders,name=*'
      2017-05-25 09:44:07,979 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=AsyncLoggerRingBuffer'
      2017-05-25 09:44:07,979 localhost-startStop-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=Loggers,name=*,subtype=RingBuffer'
      2017-05-25 09:44:07,981 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=/Log4j2AppenderTest
      2017-05-25 09:44:07,982 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=StatusLogger
      2017-05-25 09:44:07,983 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=ContextSelector
      2017-05-25 09:44:07,984 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=Loggers,name=
      2017-05-25 09:44:07,986 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=Appenders,name=Console
      2017-05-25 09:44:07,986 localhost-startStop-1 DEBUG Registering MBean org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=Appenders,name=Rabbit
      2017-05-25 09:44:07,988 localhost-startStop-1 TRACE Using default SystemClock for timestamps.
      2017-05-25 09:44:07,988 localhost-startStop-1 TRACE Using DummyNanoClock for nanosecond timestamps.
      2017-05-25 09:44:07,988 localhost-startStop-1 DEBUG LoggerContext[name=/Log4j2AppenderTest, org.apache.logging.log4j.core.LoggerContext@3492d9ea] started OK with configuration XmlConfiguration[location=/home/asidorov/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/Log4j2AppenderTest/WEB-INF/classes/log4j2.xml].
      May 25, 2017 9:44:07 AM org.apache.catalina.core.ApplicationContext log
      INFO: No Spring WebApplicationInitializer types detected on classpath
      2017-05-25 09:44:07,989 localhost-startStop-1 DEBUG Log4jServletContextListener ensuring that Log4j starts up properly.
      2017-05-25 09:44:07,991 localhost-startStop-1 DEBUG Log4jServletFilter initialized.
      

      And shutdown log:

      INFO: Stopping service Catalina
      2017-05-25 09:46:02,486 localhost-startStop-2 DEBUG Log4jServletFilter destroyed.
      2017-05-25 09:46:02,486 localhost-startStop-2 DEBUG Log4jServletContextListener ensuring that Log4j shuts down properly.
      2017-05-25 09:46:02,487 localhost-startStop-2 DEBUG Removing LoggerContext for [/Log4j2AppenderTest].
      2017-05-25 09:46:02,487 localhost-startStop-2 DEBUG Stopping LoggerContext[name=/Log4j2AppenderTest, org.apache.logging.log4j.core.LoggerContext@3492d9ea]...
      2017-05-25 09:46:02,487 localhost-startStop-2 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=/Log4j2AppenderTest]
      2017-05-25 09:46:02,487 localhost-startStop-2 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=StatusLogger]
      2017-05-25 09:46:02,487 localhost-startStop-2 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=ContextSelector]
      2017-05-25 09:46:02,488 localhost-startStop-2 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=Loggers,name=]
      2017-05-25 09:46:02,488 localhost-startStop-2 TRACE Unregistering 2 MBeans: [org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=Appenders,name=Rabbit, org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=Appenders,name=Console]
      2017-05-25 09:46:02,488 localhost-startStop-2 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=AsyncAppenders,name=*'
      2017-05-25 09:46:02,488 localhost-startStop-2 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=AsyncLoggerRingBuffer'
      2017-05-25 09:46:02,489 localhost-startStop-2 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=/Log4j2AppenderTest,component=Loggers,name=*,subtype=RingBuffer'
      2017-05-25 09:46:02,489 localhost-startStop-2 TRACE Stopping XmlConfiguration[location=/home/asidorov/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/Log4j2AppenderTest/WEB-INF/classes/log4j2.xml]...
      2017-05-25 09:46:02,489 localhost-startStop-2 TRACE XmlConfiguration notified 2 ReliabilityStrategies that config will be stopped.
      2017-05-25 09:46:02,489 localhost-startStop-2 TRACE XmlConfiguration stopping 1 LoggerConfigs.
      2017-05-25 09:46:02,489 localhost-startStop-2 TRACE XmlConfiguration stopping root LoggerConfig.
      2017-05-25 09:46:02,489 localhost-startStop-2 TRACE XmlConfiguration notifying ReliabilityStrategies that appenders will be stopped.
      2017-05-25 09:46:02,489 localhost-startStop-2 TRACE XmlConfiguration stopping remaining Appenders.
      2017-05-25 09:46:02,489 localhost-startStop-2 DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false
      2017-05-25 09:46:02,490 localhost-startStop-2 DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false, all resources released: true
      2017-05-25 09:46:02,490 localhost-startStop-2 DEBUG Appender Console stopped with status true
      2017-05-25 09:46:02,490 localhost-startStop-2 TRACE XmlConfiguration stopped 2 remaining Appenders.
      2017-05-25 09:46:02,490 localhost-startStop-2 TRACE XmlConfiguration cleaning Appenders from 2 LoggerConfigs.
      2017-05-25 09:46:02,490 localhost-startStop-2 DEBUG Stopped XmlConfiguration[location=/home/asidorov/workspace/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/Log4j2AppenderTest/WEB-INF/classes/log4j2.xml] OK
      2017-05-25 09:46:02,490 localhost-startStop-2 DEBUG Stopped LoggerContext[name=/Log4j2AppenderTest, org.apache.logging.log4j.core.LoggerContext@3492d9ea] with status true
      May 25, 2017 9:46:02 AM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
      WARNING: The web application [Log4j2AppenderTest] appears to have started a thread named [log-event-retry-delay] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
       java.lang.Object.wait(Native Method)
       java.lang.Object.wait(Object.java:502)
       java.util.TimerThread.mainLoop(Timer.java:526)
       java.util.TimerThread.run(Timer.java:505)
      May 25, 2017 9:46:02 AM org.apache.coyote.AbstractProtocol stop
      INFO: Stopping ProtocolHandler ["http-nio-8080"]
      May 25, 2017 9:46:02 AM org.apache.coyote.AbstractProtocol stop
      INFO: Stopping ProtocolHandler ["ajp-nio-8009"]
      May 25, 2017 9:46:02 AM org.apache.coyote.AbstractProtocol destroy
      INFO: Destroying ProtocolHandler ["http-nio-8080"]
      May 25, 2017 9:46:02 AM org.apache.coyote.AbstractProtocol destroy
      INFO: Destroying ProtocolHandler ["ajp-nio-8009"]
      

      Did some investigation - apparently manager of AMQP appender is not closed.

        Attachments

          Activity

            People

            • Assignee:
              abilan Artem Bilan
              Reporter:
              alsid Alexander Sidorov
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: