log4j2 : Async logger is NOT starting

Question

I have recently upgraded my application to use log4j2. I am trying to make use of its async logger feature. However looks like its not creating one. As per Log4j Async config, it says,

1. To make all loggers asynchronous, add the disruptor jar to the classpath and set the system property Log4jContextSelector to org.apache.logging.log4j.core.async.AsyncLoggerContextSelector. I also set the status="trace" in log4j.xml to see if it configures and instantiate async logger. But looks like it failing.

2017-01-25 01:58:30,799 main TRACE Reregistering context (1/1): 'AsyncContext@18b4aac2' org.apache.logging.log4j.core.async.AsyncLoggerContext@6bf08014 2017-01-25 01:58:30,800 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=AsyncContext@18b4aac2' 2017-01-25 01:58:30,800 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=AsyncContext@18b4aac2,component=StatusLogger' 2017-01-25 01:58:30,800 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=AsyncContext@18b4aac2,component=ContextSelector' 2017-01-25 01:58:30,801 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=AsyncContext@18b4aac2,component=Loggers,name=' 2017-01-25 01:58:30,801 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=AsyncContext@18b4aac2,component=Appenders,name=' 2017-01-25 01:58:30,801 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=AsyncContext@18b4aac2,component=AsyncAppenders,name=' 2017-01-25 01:58:30,801 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=AsyncContext@18b4aac2,component=AsyncLoggerRingBuffer' 2017-01-25 01:58:30,802 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=AsyncContext@18b4aac2,component=Loggers,name=,subtype=RingBuffer' 2017-01-25 01:58:30,803 main DEBUG Registering MBean org.apache.logging.log4j2:type=AsyncContext@18b4aac2 2017-01-25 01:58:30,805 main DEBUG Registering MBean org.apache.logging.log4j2:type=AsyncContext@18b4aac2,component=AsyncLoggerRingBuffer 2017-01-25 01:58:30,806 main DEBUG Registering MBean org.apache.logging.log4j2:type=AsyncContext@18b4aac2,component=StatusLogger 2017-01-25 01:58:30,807 main DEBUG Registering MBean org.apache.logging.log4j2:type=AsyncContext@18b4aac2,component=ContextSelector 2017-01-25 01:58:30,816 main TRACE Using default SystemClock for timestamps. 2017-01-25 01:58:30,816 main TRACE Using DummyNanoClock for nanosecond timestamps. 2017-01-25 01:58:30,817 main DEBUG Reconfiguration complete for context[name=AsyncContext@18b4aac2] at URI /etc/opt/sun/im/default/config/log4j2.xml (org.apache.logging.log4j.core.async.AsyncLoggerContext@6bf08014) with optional ClassLoader: null 2017-01-25 01:58:30,817 main DEBUG Shutdown hook enabled. Registering a new one. 2017-01-25 01:58:30,818 main DEBUG LoggerContext[name=AsyncContext@18b4aac2, org.apache.logging.log4j.core.async.AsyncLoggerContext@6bf08014] started OK.

As I don't see anything like "Starting AsyncLogger disruptor".

2. Then as suggested, I tried using asyncLogger tag, I could see it printing,

   2017-01-25 00:27:26,970 main TRACE AsyncLoggerConfigDisruptor creating new disruptor for this configuration. 2017-01-25 00:27:26,971 main TRACE property AsyncLoggerConfig.WaitStrategy=TIMEOUT 2017-01-25 00:27:26,987 main DEBUG Starting AsyncLoggerConfig disruptor for this configuration with ringbufferSize=4096, waitStrategy=TimeoutBlockingWaitStrategy, exceptionHandler=org.apache.logging.log4j.core.async.AsyncLoggerConfigDefaultExceptionHandler@7f284218... 2017-01-25 00:27:26,988 main TRACE AsyncLoggerConfig[xmppd] starting...

   But again at later stage it throws exception for class not found,

   2017-01-25 00:27:31,658 main ERROR Unable to invoke factory method in class class org.apache.logging.log4j.core.async.AsyncLoggerConfig for element AsyncLogger. java.lang.reflect.InvocationTargetException at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:132) at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:942) at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:882) at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:874) at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:498) at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:227) at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:239) at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:530) at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:603) at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:620) at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:226) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:242) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45) at org.apache.logging.log4j.LogManager.getContext(LogManager.java:174) at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:618) at org.apache.logging.log4j.LogManager.getRootLogger(LogManager.java:652) Caused by: java.lang.NoClassDefFoundError: com/lmax/disruptor/EventFactory at org.apache.logging.log4j.core.config.AbstractConfiguration.getAsyncLoggerConfigDelegate(AbstractConfiguration.java:197) at org.apache.logging.log4j.core.async.AsyncLoggerConfig.(AsyncLoggerConfig.java:81) at org.apache.logging.log4j.core.async.AsyncLoggerConfig.createLogger(AsyncLoggerConfig.java:188) ... 23 more Caused by: java.lang.ClassNotFoundException: com.lmax.disruptor.EventFactory at java.net.URLClassLoader.findClass(URLClassLoader.java:381) at java.lang.ClassLoader.loadClass(ClassLoader.java:424) at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:331) at java.lang.ClassLoader.loadClass(ClassLoader.java:357) ... 26 more

I have verified, the disruptor jar which I included has this class. I am using disruptor-3.3.6.jar.

Also How to verify that the async logger has started ?

Any help would be appreciated.

Disincline

Answer 1

Add the LMAX Disruptor dependency.To use AsyncLogger, your pom.xml should be like this

    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter</artifactId>
        <exclusions>
            <exclusion>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-starter-logging</artifactId>
            </exclusion>
        </exclusions>
    </dependency>
    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-log4j2</artifactId>
    </dependency>
    <dependency> 
        <groupId>com.lmax</groupId>
        <artifactId>disruptor</artifactId>
        <version>3.3.7</version>
    </dependency>

Further reading : Performance of log4j2 compared to log4j1

Uremia

Answer 2

Having tried all the suggestions, I had to look for another solution.

First, make sure you have a file called log4j2.component.properties in the classpath. ( in the same place you have log4j2 file src/main/resources)

its content is :

Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector 

Next, verify you have this dependency ( I was getting this Exception in thread "main" java.lang.NoClassDefFoundError: com/lmax/disruptor/EventTranslatorVararg when I didn't have it)

<dependency>
  <groupId>com.lmax</groupId>
  <artifactId>disruptor</artifactId>
  <version>3.4.1</version>
</dependency>

Rus

FYI: If you using report portal dependency, it's recommended not to add log4j2.component.properties file. I was facing issue attaching the logs to this tool, only once I delete this file it worked – Rus

Answer 3

I need to investigate further but it seems that Log4j2 depends on a class com.lmax.disruptor.EventFactory which is no longer present in the disruptor version you are using. Can you use an older version? 3.3.2 should work.

Tarpon

Thanks for the advice. It looks strange to me, I could see the required class(com.lmax.disruptor.EventFactory) is present in jar(both version 3.3.6 and 3.3.2). I have also made sure that the jar is included in classpath as well. Not sure whats going wrong. Anyways whats your suggestion for configuring Async logger. And how to verify that its up and running. Thanks again for the help. – Disincline

could you please suggest, why setting system property Log4jContextSelector to org.apache.logging.log4j.core.async.AsyncLoggerContextSelector doesn't work ? – Disincline

Hey Remko, Looks like I have resolved the issue. Since I run bunch of apps and each of them has its own logging stream. So the one which is configured with asyncLogger tag works fine, however other was throwing this error. SO any idea about enabling system wide async logging(something like setting system property Log4jContextSelector to org.apache.logging.log4j.core.async.AsyncLoggerContextSelect‌​or, which doesn't work in my case) ? Thanks for looking in to it. – Disincline

What do you mean "doesn't work "? When setting the property the status log ends with "AsyncLoggerContext@6bf08014] started OK", indicating that the AsyncLoggerContextSelector was successfully installed. So that seems to work. What I don't understand is why configuring with AsyncRootLogger throws a NoClassDefFoundError... why aren't you seeing this error with the AsyncLoggerContextSelector? – Tarpon

Just saw your comment that explained the NoClassDefFound. Good. All good now? – Tarpon

Thanks for your response and time Remko. I got confused thinking setting system property Log4jContextSelector to org.apache.logging.log4j.core.async.AsyncLoggerContextSelect‌​or doesn't work, as I don't see anyting like Starting AsyncLogger disruptor, which in other case I was seeing. That's why I was trying to figure out a way to make sure that async logger indeed started. Looking at number of threads associated to that particular process is one way. Anyways looks like I am good as of now, that for your help and time. – Disincline

Answer 4

Add these dependancy in your Pom file:

<!-- Exclude Spring Boot's Default Logging -->
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter</artifactId>
            <exclusions>
                <exclusion>
                    <groupId>org.springframework.boot</groupId>
                    <artifactId>spring-boot-starter-logging</artifactId>
                </exclusion>
            </exclusions>
        </dependency>

        <!-- Add Log4j2 Dependency -->
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-log4j2</artifactId>
        </dependency>

        <dependency> 
             <groupId>com.lmax</groupId> 
             <artifactId>disruptor</artifactId> 
                     <version>3.3.7</version> 
        </dependency> 

Zoila

Answer 5

Adding this dependency solved the issue for me :

<dependency> 
    <groupId>com.lmax</groupId> 
    <artifactId>disruptor</artifactId> 
    <version>3.3.7</version> 
</dependency> 

Coenesthesia