Logging with the Couchbase Java Client

[This blog was syndicated from http://nitschinger.at/]

Introduction

There is a huge variety in logging frameworks for Java, and its hard to please everyone. To understand how logging is currently handled in the SDK, we have to go back a few years. As you may know, the SDK depends on the spymemcached library and therefore also inherits its logging mechanisms. Back in the days when @dustin wrote spy, there was no good abstraction for logging available (like SLF4J), so he wrote his own. Nowadays things have changed, but spy still inherits this legacy.

At the time of writing, the SDK supports logging to a simple default logger (logs to STDERR from INFO level up), Log4J and the SunLogger (java.util.logging). In the upcoming 2.9.0 release of spymemcached, it will also support the SLF4J logging facade where you can plug in your own implementation. The next version of the SDK (most likely 1.1.7) will depend on spy 2.9, so you'll also get the benefits there.

Before we dig into the concepts, here are the supported Log Levels (defined by net.spy.memcached.compat.log.Level):

1. TRACE (with 2.9)
2. DEBUG
3. INFO
4. WARN
5. ERROR
6. FATAL

Keep in mind that different loggers implement different levels, so for some of them a mapping needs top happen. This will be noted during the descriptions of each implementation.

We'll now look at the different logging mechanisms available and how you can configure them. SLF4J will be covered towards the end.

Switching Logging

If you don't change anything, the default logger will be used. This mechanism just prints log messages to STDERR (from INFO level upwards). Chances are that you want to integrate the SDK with the same logging library that you use as well. The LoggerFactory inside spy decides at construction which one to choose, based on a system property. So you can either change this programmatically or through a param to the java command.

If you want to use the Log4JLogger programmatically, do it this way (before initializing the CouchbaseClient object):

Of course, you need to add the Log4J JAR to your CLASSPATH to make it work (as we'll see later). Alternatively, you can set it this way on the command line:

Now that we know how to enable the different implementations, let's look at them in greater detail.

The Simple Default Logger

If you don't change anything, the SDK will use the DefaultLogger (net.spy.memcached.compat.log.DefaultLogger). This logger has no dependencies and prints every log message that is INFO level or higher (INFO, WARN, ERROR and FATAL) to the systems STDERR. Since the STDERR is covered by most IDEs automatically, you'll also see them in the console output window.

Since its so simple, you can't customize this behavior. Every log message gets timestamped as well (the format is yyyy-MM-dd HH:mm:ss.SSS). Connecting to Couchbase commonly looks like this:

So the format is always: . Remeber that DEBUG messages or so will not be logged, so you won't see them with the DefaultLogger.

The SunLogger (java.util.logging)

The SunLogger also doesn't introduce additional dependencies, since it depends on the java.util.logging implementation. The java.util.logging.Level enum defines the following levels: ALL, CONFIG, FINEST, FINER, FINE, INFO, WARNING, SEVERE and OFF. Since this does not map well to our defined Levels, here is the mapping that happens:

1. TRACE to FINEST (with 2.9)
2. DEBUG to FINE
3. INFO to INFO
4. WARN to WARNING
5. ERROR to SEVERE
6. FATAL to SEVERE

If you want to change the log level to DEBUG and lower, you can do it like this:

Now there is one more thing you need to do if you want to print all debug messages to the console. You set the logging level correctly, but the ConsoleHandler is not set to debug yet (so most likely you will pay the price for debug logging, but won't actually see anything in your IDE).

So, here is a full example on how to use the SunLogger and get all Debug messages on the console.

Then just go ahead and create your CouchbaseClient object, you will see detailed output like this (trimmed here):

Log4J

Most people will need more flexibility, and Log4J was (and still is) standard in lots of applications. The SDK provides support for Log4J as well. To make it work, you first need to set the instance correctly:

Now if you run this, you'll get an error that some of the Log4J classes can not be found. This is not a surprise, because its not on the classpath. Let's fix this by adding it accordingly. If you use maven, add the log4j.log4j dependency (current version is 1.2.17). You can also just download the JAR and add it to the CLASSPATH as needed.

One way to fix this is to get a correct log4j.xml configuration file into our CLASSPATH, but to make it work quickly Log4J provides a BasicConfigurator. Right after the system property configurations, add this:

If you run it with the code change applied, you will see that we get nicely printed log messages. You can also see that they show up straight from the DEBUG level (and even contain information from which thread they got logged):

You can control the logging levels through the usual Log4J mechanisms. I won't go into detail about them here, so please check out their official documentation (for example on how to use the PropertyConfigurator instead).

Speaking of Log4J,  Steffen Larsen implemented a Log4J appender to store logs in Couchbase (instead of a file)!

The new Facade: SLF4J

Not binding the application to a specific logging library is always a good idea. SLF4J is a facade for various pluggable logging frameworks behind it. So you can choose the logging implementation during runtime, be it logback, Log4J or others. Since we already tried Log4J, let's make SLF4J work with Logback, one of the other very common log frameworks out there.

Note that SLF4J support will be available in the 1.9.0 release of spymemcached and therefore also in one of the next releases of the Couchbase Java SDK.

First, we need to configure it accordingly:

Now, we need to include two JARs into our classpath. The first one is the SLF4J facade API and the other one is our logging framework of choice. The facade API package is called slf4j-api (this package always needs to be in place) and since we want to use logback we need to include the logback-classic JAR. Note that this is not specific to the SDK, you can find this information here. If you use maven, you can use this snippet:

SLF4J will automatically pick up our logback implementation, so the logs will look like this:

As you can see, they also include DEBUG level logging here. If you don't include the logging implementation during runtime, SLF4J will complain at startup:

Summary

Once you know the abstraction in spymemcached and how it works, switching logging implementations is easy and straightforward. If you work with one of the Couchbase people to report errors, please try to include output with DEBUG turned on, because this includes lots of useful information that can be used to determine the failure sources.

With the SLF4J facade added in the next spy release (2.9), you will be able to plug every large logging framework out there into the SDK. Let us know if you see a use case not covered with these mechanisms or if you have other comments on this.