[Logging] Using log4j2 with asynchronous loggers via LMAX disruptor in an Eclipse RCP application, incl. solving sun.misc issue

When it was first released, the web was full of praise for Version 2.x of the quasi standard Java logging framework Apache Log4j. One of its main selling points is that it includes asynchronous loggers for low-latency logging, which apparently comes with pretty amazing performance.

As I needed to include logging into my Eclipse RCP application anyway, I wanted to do it correctly right from the start and leverage the best possible config for logging.

Unfortunately as it turned out, including Log4j 2 in an Eclipse RCP (or any OSGi) application isn’t standard procedure, and not really straightforward. The issues one is likely to encounter are:

  • How to get the Log4j 2 configuration file onto the classpath (cf. Google search).
  • How to get Log4j 2′s core and api bundles OSGified.
  • How to set all loggers async via the LMAX Disruptor high-performance inter-thread messaging library.
  • How to satisfy the dependency from LMAX disruptor to sun.misc (not as easy as you might think).

In the following, I will describe how I got the setup to work, and provide an example application.

DISCLAIMER: This solution was tested with a 3.x RCP application based on the Eclipse Mars (3.8.1) platform and Java JDK 1.7.0_79.

Make the Eclipse RCP use Log4j 2

Setting up an Eclipse 3.x RCP application on Mars

This is described in great details elsewhere. And I guess if you are reading this you have an existing application and have done it already, so I’ll leave this bit out.

Creating a plugin for Log4j 2

The first step is to create a plugin for Log4j 2. Download Log4j 2 and unpack the archive. The trick now is to create a plugin from the Log4j 2 JARs. Why? Because this is by far the easiest way to get the log4j-core packages onto the classpath! On the downside, we will have to re-create the plugin every time we want to update the Log4j 2 version to be used by our application. Fortunately, Eclipse provides a function under New > Plug-in from existing JAR Archives, which is just what we’ll use.

In the wizard, first click “Add external” to select the JARs. Select log4j-core-2.4.1.jar and log4j-api-2.4.1.jar. Click Next. Fill in the details and check “Unzip the JAR archives into the project“. Then press Finish. The wizard is now extracting the JARs and will create a plug-in project as per your details.

Add a dependency on the new logging plugin to your main RCP plugin. Now you can already use the Log4j 2 API. Try it out:

  1. Add the following field to your Application.java:
    private static final Logger logger = LogManager.getLogger(Application.class);
  2. Then, in the start() method, log your first message:
    logger.info("Works!");

Run your RCP, and you will see the following output in the console:

ERROR StatusLogger No log4j2 configuration file found. Using default configuration: logging only errors to the console.

This is because Log4j 2 must be configured first. You can change the message line as follows to test it.

logger.error("Works!");

This gives you the following console output:

ERROR StatusLogger No log4j2 configuration file found. Using default configuration: logging only errors to the console.
11:36:53.523 [main] ERROR net.sdruskat.blog.rcp.asynclog4j2.Application - Works!

Wahey, your first logging output! Still, you will need to configure Log4j 2.

Configuring Log4j 2

Now is a good time to read the Log4j 2 configuration page! We will use a log4j2.xml file.

Create the file in the root of your logging plug-in (New > General > File, fill in details accordingly. Don’t forget to name the file log4j2.xml and not log4.xml (as used for Log4j 1.x)), and fill it with the following content (taken from the Log4j 2 configuration site, see above).

<?xml version="1.0" encoding="UTF-8"?>
    <Configuration status="WARN">
      <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
          <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
        </Console>
      </Appenders>
      <Loggers>
        <Root level="error">
          <AppenderRef ref="Console"/>
        </Root>
      </Loggers>
    </Configuration>

Run your RCP app again, and you will see that the error warning in the console disappears, and only the pseudo-error log message remains. All good, but if we were to export the application now and run it outside of Eclipse, we would (I think) get the error message again. Solution: we need to add the configuration file to the binary build! To do so, edit your build.properties file in the logging plugin to look like this:

source.. = .
output.. = .
bin.includes = META-INF/,\
               Log4j-config.xsd,\
               Log4j-events.dtd,\
               Log4j-events.xsd,\
               Log4j-levels.xsd,\
               org/,\
               log4j2.xml

This makes the config file available to exported applications. Great! We have an Eclipse RCP application running Log4j 2! Now, let's make all the loggers asynchronous (which is where the "fun" starts).

Make the Eclipse RCP use asynchronous loggers

Configure Log4j 2 to log asynchronously (in theory)

Now we want to set all logger asynchronously, so we'll have to change log4j2.xml first, according to the Log4j 2 website.

<?xml version="1.0" encoding="UTF-8"?>

    <!-- Don't forget to set system property
    -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
         to make all loggers asynchronous. -->

    <Configuration status="WARN">
      <Appenders>
        <!-- Async Loggers will auto-flush in batches, so switch off immediateFlush. -->
        <RandomAccessFile name="RandomAccessFile" fileName="async.log" immediateFlush="false" append="false">
          <PatternLayout>
            <Pattern>%d %p %c{1.} [%t] %m %ex%n</Pattern>
          </PatternLayout>
        </RandomAccessFile>
      </Appenders>
      <Loggers>
        <Root level="info" includeLocation="false">
          <AppenderRef ref="RandomAccessFile"/>
        </Root>
      </Loggers>
    </Configuration>

Note that it says "Don't forget to set system property -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector to make all loggers asynchronous.", so this is what we'll add to our product definition (under Launching > VM Arguments), and to the run configuration as well (to be able to test), under Arguments > VM Arguments: -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector.

Running the whole affair won't work. Eclipse will complain that

Caused by: java.lang.ClassNotFoundException: com.lmax.disruptor.EventFactory cannot be found ...

Going back to the Log4j 2 config website, we can read that [Making all loggers asynchronous r]equires disruptor-3.0.0.jar or higher on the classpath. No problem (we think), let's do that then.

Getting the LMAX Disruptor library on the classpath

After searching the relevant p2 repositories for a while, you probably find out that there is no p2-ified (and hence target platform consumable) version of the LMAX Disruptor readily available. But there's a mavenized version in the central repo!

So luckily it's Maven to the rescue (don't fret, it's easy-going): We simply need to p2-ify the bundle. And thankfully there is an easy way to do that via the p2-maven-plugin! With this plugin you can supply any mavenized JAR in a p2 repository! This thing saved me numerous times already!

Have a look at the documentation on how to set up a respective POM and package the LMAX Disruptor (tip: groupId is com.lmax, artifactId is disruptor). You should now have a p2 software site built by the plugin, from which you can add the com.lmax.disruptor bundle to the target platform (Window > Preferences > search for "Target Platform" > create a new target platform > add your newly built p2 site to it > pick the disruptor bundle to add to the target platform. You can of course use a target definition file if you are so inclined, it's what I do.).

In your logging plugin, add com.lmax.disruptor as a dependency to MANIFEST.MF. All good to go now! Right? No! Eclipse complains about a

Missing Constraint: Import-Package: sun.misc; version="0.0.0"

This is for the newly added com.lmax.disruptor. Ouch. What to do?

Solving the sun.misc problem

The problem with sun.misc is that ...

... none of the standard OSGi execution environments exposes the package sun.misc, so the bundle using this package will not work on a standard OSGi runtime. (source)

The solution given in the answer on StackOverflow (see source) is to "build a system bundle fragment which declares an Export-Package of sun.misc". What's a "system bundle fragment"? Sounds very OSGi-ish to me. But it's actually fairly simple: You take the JAR (available from your OSGi environment), create a bundle manifest for it, let it export sun.misc. Then you create a fragment bundle. It's easily achieved with the maven-jar-plugin (to create the manifest) and the maven-bundle-plugin (to create the fragment). Simply set up a pom.xml file somewhere, fill it with the following, and run mvn clean install.

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/maven-v4_0_0.xsd">
    <modelVersion>4.0.0</modelVersion>
      <groupId>net.sdruskat</groupId>
      <version>1.0.0</version>

    <artifactId>net.sdruskat.fragment.sun.misc</artifactId>
    <packaging>jar</packaging>
    <name>System Bundle Fragment exporting sun.misc</name>

    <description>This bundle extends the System Bundle export list with the sun.misc package such that OSGi bundles may refer to Sun's misc implementation without the OSGi framework itself to provide it in a non-portable way.</description>

    <build>
        <plugins>
            <plugin>
                <artifactId>maven-jar-plugin</artifactId>
                <configuration>
                    <forceCreation>true</forceCreation>
                    <archive>
                        <manifestFile>${project.build.outputDirectory}/META-INF/MANIFEST.MF</manifestFile>
                        <manifestEntries>
                            <Export-Package>sun.misc</Export-Package>
                        </manifestEntries>
                    </archive>
                </configuration>
            </plugin>
            <plugin>
                <groupId>org.apache.felix</groupId>
                <artifactId>maven-bundle-plugin</artifactId>
                <version>2.5.4</version>
                <executions>
                    <execution>
                        <id>bundle-manifest</id>
                        <phase>process-classes</phase>
                        <goals>
                            <goal>manifest</goal>
                        </goals>
                    </execution>
                </executions>
                <configuration>
                    <instructions>
                        <Bundle-Category>net.sdruskat</Bundle-Category>
                        <Fragment-Host>system.bundle; extension:=framework</Fragment-Host>
                    </instructions>
                </configuration>
            </plugin>

        </plugins>
    </build>

</project>

This will build and install the respective system bundle fragment. Now you should already know what's next: p2-ify the whole affair, i.e., go back to the POM you've set up to use the p2-maven-plugin in the section before, and add your newly created fragment to the <artifacts> section. Build, and add the new bundle to the target platform.

At this point you might ask yourself why we haven't done the same for the Log4j 2 libraries. I have tried hard, but it's a nightmare to get the bundle onto the classpath if I simply add it as a dependency to a plugin. You could use the Buddy Class Loader technique, but this will brutally break loose coupling between your plugins, so I didn't want to use it.

Once the OSGi-fied LMAX Disruptor is in the target platform, you can add it to the run config, and the error will disappear! To check whether Log4j 2 really logs asynchronously, simply set the configuration status in log4j2.xml to "trace" and search for "disruptor" in the console log.

Now everything is set up for async logging! In case you are wondering where the error message has gone to from the console, check your home directory where there should be a file named "async.log" containing the error message.

Shortcut

Also, I am providing a p2 software site at http://blog-p2.sdruskat.net, where the com.lmax.disruptor (version 3.3.2) and the OSGi-fied sun.misc bundles are available, so you can just add that site to your target platform and forget about what I have written above :).

This example is on github.

This example is on github.

You can download the sources for this example (contained in a minimal RCP application) from github. The clone URL is: https://github.com/sdruskat/eclipse-rcp-with-async-logging.git.

TwitterFacebookGoogle+EmailLinkedInPinterestDiggRedditStumbleUpon
If you found this post helpful, you may want to consider donating to help cover server costs.
Tagged with: , , , , , , , , , , ,
Posted in Eclipse RCP, Log4j, Logging, Maven, Tycho

Leave a Comment

%d bloggers like this: