MDC logging with Apache Karaf and Camel

MDC (Mapped Diagnostic Context) logging is an interesting feature to log contextual messages.

It’s classic to want to log contextual messages in your application. For instance, we want to log the actions performed by an user (identified by an username or user id). As you have a lot of simultaneous users on your application, it’s easier to “follow” the log.

MDC is supported by several logging frameworks, like log4j or slf4j, and so by Karaf (thanks to pax-logging) as well.
The approach is pretty simple:

  1. You define the context using a key ID and a value for the key:
    MDC.put("userid", "user1");
  2. You use the logger as usual, the log messages to this logger will be contextual to the context:
    logger.debug("my message");
  3. After that, we can change the context by overriding the key:
    MDC.put("userid", "user2");logger.debug("another message");

    Or you can remove the key, so to remove the context, and the log will be “global” (not local to a context):

    MDC.remove("userid"); // or MDC.clear() to remove alllogger.debug("my global message");
  4. In the configuration, we can use pattern with %X{key} to log context. A pattern like %X{userid} - %m%n will result to a log file looking like:
    user1 - my messageuser2 - another message

In this blog, we will see how to use MDC in different cases (directly in your bundle, generic Karaf OSGi, and in Camel routes.

The source code of the blog post are available on my github: http://github.com/jbonofre/blog-mdc.

Using MDC in your application/bundle

The purpose here is to use slf4j MDC in our bundle and configure Karaf to create one log file per context.

To illustrate this, we will create multiple threads in the bundle, given a different context key for each thread:

package net.nanthrax.blog.mdc;import org.slf4j.Logger;import org.slf4j.LoggerFactory;import org.slf4j.MDC;public class MdcExampleBean {    private Logger logger = LoggerFactory.getLogger(MdcExampleBean.class);    public void init() throws Exception {        CycleThread thread1 = new CycleThread("thread1");        CycleThread thread2 = new CycleThread("thread2");        CycleThread thread3 = new CycleThread("thread3");        thread1.start();        thread2.start();        thread3.start();    }    class CycleThread extends Thread {        private String mdcContext;        public CycleThread(String mdcContext) {            this.mdcContext = mdcContext;        }        public void run() {            MDC.put("threadId", mdcContext);            for (int i = 0; i < 20; i++) {                logger.info("Cycle {}", i);            }        }    }}

After deploying this bundle in Karaf 3.0.1, we can see the log messages:

karaf@root()> bundle:install mvn:net.nanthrax.blog/mdc-bundle/1.0-SNAPSHOTkaraf@root()> log:display...2014-08-30 09:44:25,594 | INFO  | Thread-15        | MdcExampleBean                   | 78 - net.nanthrax.blog.mdc-bundle - 1.0.0.SNAPSHOT | Cycle 172014-08-30 09:44:25,594 | INFO  | Thread-13        | MdcExampleBean                   | 78 - net.nanthrax.blog.mdc-bundle - 1.0.0.SNAPSHOT | Cycle 192014-08-30 09:44:25,594 | INFO  | Thread-15        | MdcExampleBean                   | 78 - net.nanthrax.blog.mdc-bundle - 1.0.0.SNAPSHOT | Cycle 182014-08-30 09:44:25,595 | INFO  | Thread-15        | MdcExampleBean                   | 78 - net.nanthrax.blog.mdc-bundle - 1.0.0.SNAPSHOT | Cycle 19

Now, we can setup the Karaf etc/org.ops4j.pax.logging.cfg file to use our MDC. For that, we add a MDCSiftingAppender, providing the threadId as MDC key, and displaying the threadId in the log message pattern. We will create one log file per key (threadId in our case), and finally, we add this appender to the rootLogger:

...log4j.rootLogger=INFO, out, mdc-bundle, osgi:*...# MDC Bundle appenderlog4j.appender.mdc-bundle=org.apache.log4j.sift.MDCSiftingAppenderlog4j.appender.mdc-bundle.key=threadIdlog4j.appender.mdc-bundle.default=unknownlog4j.appender.mdc-bundle.appender=org.apache.log4j.FileAppenderlog4j.appender.mdc-bundle.appender.layout=org.apache.log4j.PatternLayoutlog4j.appender.mdc-bundle.appender.layout.ConversionPattern=%d | %-5.5p | %X{threadId} | %m%nlog4j.appender.mdc-bundle.appender.file=${karaf.data}/log/mdc-bundle-$\\{threadId\\}.loglog4j.appender.mdc-bundle.appender.append=true...

Now, in the Karaf data/log folder, we can see:

mdc-bundle-thread1.logmdc-bundle-thread2.logmdc-bundle-thread3.log

each file containing the log messages contextual to the thread:

$ cat data/log/mdc-bundle-thread1.log2014-08-30 09:54:48,287 | INFO  | thread1 | Cycle 02014-08-30 09:54:48,298 | INFO  | thread1 | Cycle 12014-08-30 09:54:48,298 | INFO  | thread1 | Cycle 22014-08-30 09:54:48,299 | INFO  | thread1 | Cycle 32014-08-30 09:54:48,299 | INFO  | thread1 | Cycle 4...$ cat data/log/mdc-bundle-thread2.log2014-08-30 09:54:48,287 | INFO  | thread2 | Cycle 02014-08-30 09:54:48,298 | INFO  | thread2 | Cycle 12014-08-30 09:54:48,298 | INFO  | thread2 | Cycle 22014-08-30 09:54:48,299 | INFO  | thread2 | Cycle 32014-08-30 09:54:48,299 | INFO  | thread2 | Cycle 42014-08-30 09:54:48,299 | INFO  | thread2 | Cycle 5...

In addition, Karaf “natively” provides OSGi MDC data that we can use.

Using Karaf OSGi MDC

So, in Karaf, you can use directly some OSGi headers for MDC logging, especially the bundle name.

We can use this MDC key to create one log file per bundle.

Karaf already provides a pre-defined appender configuration in etc/org.ops4j.pax.logging.cfg:

...# Sift appenderlog4j.appender.sift=org.apache.log4j.sift.MDCSiftingAppenderlog4j.appender.sift.key=bundle.namelog4j.appender.sift.default=karaflog4j.appender.sift.appender=org.apache.log4j.FileAppenderlog4j.appender.sift.appender.layout=org.apache.log4j.PatternLayoutlog4j.appender.sift.appender.layout.ConversionPattern=%d{ISO8601} | %-5.5p | %-16.16t | %-32.32c{1} | %m%nlog4j.appender.sift.appender.file=${karaf.data}/log/$\\{bundle.name\\}.loglog4j.appender.sift.appender.append=true...

The only thing that we have to do is to add this appender to the rootLogger:

log4j.rootLogger=INFO, out, sift, osgi:*

Now, in the Karaf data/log folder, we can see one file per bundle:

data/log$ ls -1karaf.lognet.nanthrax.blog.mdc-bundle.logorg.apache.aries.blueprint.core.logorg.apache.aries.jmx.core.logorg.apache.felix.fileinstall.logorg.apache.karaf.features.core.logorg.apache.karaf.region.persist.logorg.apache.karaf.shell.console.logorg.apache.sshd.core.log

Especially, we can see our mdc-bundle, containing the log messages “local” to the bundle.

However, if this approach works great, it doesn’t always create interesting log file. For instance, when you use Camel, using OSGi headers for MDC logging will gather most of the log messages into the camel-core bundle log file, so, not really contextual to something or easy to read/seek.

The good news is that Camel also provides MDC logging support.

Using Camel MDC

If Camel provides MDC logging support, it’s not enabled by default. It’s up to you to enable it on the camel context.

Once enabled, Camel provides the following MDC logging properties:

  • camel.exchangeId providing the exchange ID
  • camel.messageId providing the message ID
  • camel.routeId providing the route ID
  • camel.contextId providing the Camel Context ID
  • camel.breadcrumbId providing an unique id used for tracking messages across transports
  • camel.correlationId providing the correlation ID of the exchange (if it’s correlated, for instance like in Splitter EIP)
  • camel.trasactionKey providing the ID of the transaction (for transacted exchange).

To enable the MDC logging, you have to:

  • if you use the Blueprint or Spring XML DSL:
    <camelContext xmlns="http://camel.apache.org/schema/blueprint" useMDCLogging="true">
  • if you use the Java DSL:
    CamelContext context = ...context.setUseMDCLogging(true);
  • using the Talend ESB studio, you have to use a cConfig component from the palette:
    studio1

So, let say, we create the following route using the Blueprint DSL:

<?xml version="1.0" encoding="UTF-8"?> <blueprint xmlns="http://www.osgi.org/xmlns/blueprint/v1.0.0">    <camelContext xmlns="http://camel.apache.org/schema/blueprint" useMDCLogging="true">       <route id="my-route">          <from uri="timer:fire?period=5000"/>          <setBody>             <constant>Hello Blog</constant>          </setBody>          <to uri="log:net.nanthrax.blog?level=INFO"/>      </route>   </camelContext> </blueprint>

We want to create one log file per route (using the routeId). So, we update the Karaf etc/org.ops4j.pax.logging.cfg file to add a MDC sifting appender using the Camel MDC properties, and we add this appender to the rootLogger:

...log4j.rootLogger=INFO, out, camel-mdc, osgi:*...# Camel MDC appenderlog4j.appender.camel-mdc=org.apache.log4j.sift.MDCSiftingAppenderlog4j.appender.camel-mdc.key=camel.routeIdlog4j.appender.camel-mdc.default=unknown log4j.appender.camel-mdc.appender=org.apache.log4j.FileAppenderlog4j.appender.camel-mdc.appender.layout=org.apache.log4j.PatternLayoutlog4j.appender.camel-mdc.appender.layout.ConversionPattern=%d{ISO8601} | %-5.5p | %-16.16t | %-32.32c{1} | %X{camel.exchangeId} | %m%nlog4j.appender.camel-mdc.appender.file=${karaf.data}/log/camel-$\\{camel.routeId\\}.loglog4j.appender.camel-mdc.appender.append=true...

The camel-mdc appender will create one log file by route (named camel-(routeId).log). The log messages will contain the exchange ID.

We start Karaf, and after the installation of the camel-blueprint feature, we can drop our route.xml directly in the deploy folder:

karaf@root()> feature:repo-add camel 2.12.1Adding feature url mvn:org.apache.camel.karaf/apache-camel/2.12.1/xml/featureskaraf@root()> feature:install camel-blueprint
cp route.xml apache-karaf-3.0.1/deploy/

Using log:display command in Karaf, we can see the messages for our route:

karaf@root()> log:display
…
2014-08-31 08:58:24,176 | INFO | 0 – timer://fire | blog | 85 – org.apache.camel.camel-core – 2.12.1 | Exchange[ExchangePattern: InOnly, BodyType: String, Body: Hello Blog]
2014-08-31 08:58:29,176 | INFO | 0 – timer://fire | blog | 85 – org.apache.camel.camel-core – 2.12.1 | Exchange[ExchangePattern: InOnly, BodyType: String, Body: Hello Blog]

Now, if we go into the Karaf data/log folder, we can see the log file for our route:

$ ls -1 data/logcamel-my-route.log...

If we take a look in the camel-my-route.log file, we can see the messages contextual to the route, including the exchange ID:

2014-08-31 08:58:19,196 | INFO  | 0 - timer://fire | blog                             | ID-latitude-57336-1409468297774-0-2 | Exchange[ExchangePattern: InOnly, BodyType: String, Body: Hello Blog]2014-08-31 08:58:24,176 | INFO  | 0 - timer://fire | blog                             | ID-latitude-57336-1409468297774-0-4 | Exchange[ExchangePattern: InOnly, BodyType: String, Body: Hello Blog]2014-08-31 08:58:29,176 | INFO  | 0 - timer://fire | blog                             | ID-latitude-57336-1409468297774-0-6 | Exchange[ExchangePattern: InOnly, BodyType: String, Body: Hello Blog]2014-08-31 08:58:34,176 | INFO  | 0 - timer://fire | blog                             | ID-latitude-57336-1409468297774-0-8 | Exchange[ExchangePattern: InOnly, BodyType: String, Body: Hello Blog]

Comments

Post a Comment

Popular posts from this blog

Quarkus and "meta" extension

Quarkus is a great Java framework with a large ecosystem thanks to the extensions . Basically, if using Maven, your pom.xml contains the list of the extensions you want to use, meaning something like this: ... <dependency> <groupId>io.quarkus</groupId> <artifactId>quarkus-grpc</artifactId> </dependency> <dependency> <groupId>io.quarkus</groupId> <artifactId>quarkus-opentelemetry</artifactId> </dependency> ... It can quickly become large, and sometime you can have "conflict" between extensions (for example if you mix in the same dependencies set reactive and non reactive extensions). Quarkus "meta" extension To simplify the dependencies for the extensions you want to use (especially if it's basically the same extensions in all your services), you can create your own "meta" extension. This extension doesn't contain actual code, it "wraps" other exten
Read more

Getting started with Apache Karaf Minho

Image
Apache Karaf Minho Apache Karaf Minho is a new runtime, completely created from scratch. The objectives are: super easy to use and run ligtning fast, including GraalVM support Kubernetes compliant to be easily used on the cloud helping to optimize cloud costs by supporting applications colocation providing turnkey services allowing you to create Minho applications in a minute Minho is composed by: minho-boot is the core of Minho. It contains the runtime launcher and the core services (service registry, lifecycle service, configuration service, ...). minho-* services provided additional functionnalities in the runtime. You can use these services to create your own services, it's also where you will find the services managing sepcific kind of applications, allowing colocation. minho-tooling optionally provide convenient tools to create your own runtime. It includes minho-maven-plugin for instance. In this blog post, we will take a quick tour on A
Read more

Apache Karaf Minho and OpenTelemetry

Image
Telemetry is an important part of a software stack, especially on distributed system (where services call each others). OpenTelemetry is a CNCF project coming from OpenTracing and OpenCensus. It provides API to easily instrument your code and tools to collect and export telemetry data (metrics, logs and traces). Before going into how to use OpenTelemetry with Minho, we have to understand some key concepts: Span is a single building block representing an operation or some unit of work that you want to capture. They are capable of standing on their own, referencing (or following) from other spans, storing metadata, tags, etc. Trace is a visualisation of the life of a request (or series of other operations) that is made up of one or more spans. This collection of spans work together to paint a picture of the overall request, allowing you to easily reconstruct what happened within each span, etc. SpanContext is a wrapper of key values pairs that associates a trace to one or mor
Read more