Java Top

The early-bird price of the new Learn Spring Security OAuth course packages will increase by $50 on Wednesday:

>> CHECK OUT THE COURSE

 1. Overview

In this tutorial, we're going to talk about the Flogger framework, a fluent logging API for Java designed by Google.

2. Why use Flogger?

With all the logging frameworks that are currently in the market, like Log4j and Logback, why do we need yet another logging framework?

It turns out Flogger has several advantages over other frameworks – let's take a look.

2.1. Readability

The fluent nature of Flogger's API goes a long way to making it more readable.

Let's look at an example where we want to log a message every ten iterations.

With a traditional logging framework, we'd see something like:

int i = 0;

// ...

if (i % 10 == 0) {
    logger.info("This log shows every 10 iterations");
    i++;
}

But now, with Flogger, the above can be simplified to:

logger.atInfo().every(10).log("This log shows every 10 iterations");

While one would argue that the Flogger version of the logger statement looks a bit more verbose than the traditional versions, it does permit greater functionality and ultimately leads to more readable and expressive log statements.

2.2. Performance

Logging objects are optimized as long we avoid calling toString on the logged objects:

User user = new User();
logger.atInfo().log("The user is: %s", user);

If we log, as shown above, the backend has the opportunity to optimize the logging. On the other hand, if we call toString directly, or concatenate the strings then this opportunity is lost:

logger.atInfo().log("Ths user is: %s", user.toString());
logger.atInfo().log("Ths user is: %s" + user);

2.3. Extensibility

The Flogger framework already covers most of the basic functionality that we'd expect from a logging framework.

However, there are cases where we would need to add to the functionality. In these cases, it's possible to extend the API.

Currently, this requires a separate supporting class. We could, for example, extend the Flogger API by writing a UserLogger class:

logger.at(INFO).forUserId(id).withUsername(username).log("Message: %s", param);

This could be useful in cases where we want to format the message consistently. The UserLogger would then provide the implementation for the custom methods forUserId(String id) and withUsername(String username).

To do this, the UserLogger class will have to extend the AbstractLogger class and provide an implementation for the API. If we look at FluentLogger, it's just a logger with no additional methods, we can, therefore, start by copying this class as-is, and then build up from this foundation by adding methods to it.

2.4. Efficiency

Traditional frameworks extensively use varargs. These methods require a new Object[] to be allocated and filled before the method can be invoked. Additionally, any fundamental types passed in must be auto-boxed.

This all costs additional bytecode and latency at the call site. It's particularly unfortunate if the log statement isn’t actually enabled. The cost becomes more apparent in debug level logs that appear often in loops. Flogger ditches these costs by avoiding varargs totally.

Flogger works around this problem by using a fluent call chain from which logging statements can be built. This allows the framework to only have a small number of overrides to the log method, and thus be able to avoid things like varargs and auto-boxing. This means that the API can accommodate a variety of new features without a combinatorial explosion.

A typical logging framework would have these methods:

level(String, Object)
level(String, Object...)

where level can be one of about seven log level names (severe for example), as well as having a canonical log method which accepts an additional log level:

log(Level, Object...)

In addition to this, there are usually variants of the methods that take a cause (a Throwable instance) that is associated with the log statement:

level(Throwable, String, Object)
level(Throwable, String, Object...)

It's clear that the API is coupling three concerns into one method call:

  1. It's trying to specify the log level (method choice)
  2. Trying to attach metadata to the log statement (Throwable cause)
  3. And also, specifying the log message and arguments.

This approach quickly multiplies the number of different logging methods needed to satisfy these independent concerns.

We can now see why it’s important to have two methods in the chain:

logger.atInfo().withCause(e).log("Message: %s", arg);

Let's now take a look at how we can use it in our codebase.

3. Dependencies

It's pretty simple to set up Flogger. We just need to add flogger and flogger-system-backend to our pom:

<dependencies>
    <dependency>
        <groupId>com.google.flogger</groupId>
        <artifactId>flogger</artifactId>
        <version>0.4</version>
    </dependency>
    <dependency>
        <groupId>com.google.flogger</groupId>
        <artifactId>flogger-system-backend</artifactId>
        <version>0.4</version>
        <scope>runtime</scope>
    </dependency>
</dependencies>

With these dependencies set up, we can now go on to explore the API that is at our disposal.

4. Exploring the Fluent API

First off, let's declare a static instance for our logger:

private static final FluentLogger logger = FluentLogger.forEnclosingClass();

And now we can start logging. We'll start with something simple:

int result = 45 / 3;
logger.atInfo().log("The result is %d", result);

The log messages can use any of Java’s printf format specifiers, such as %s, %d or %016x.

4.1. Avoiding Work At Log Sites

Flogger creators recommend that we avoid doing work at the log site.

Let's say we have the following long-running method for summarising the current state of a component:

public static String collectSummaries() {
    longRunningProcess();
    int items = 110;
    int s = 30;
    return String.format("%d seconds elapsed so far. %d items pending processing", s, items);
}

It's tempting to call collectSummaries directly in our log statement:

logger.atFine().log("stats=%s", collectSummaries());

Regardless of the configured log levels or rate-limiting, though, the collectSummaries method will now be called every time.

Making the cost of disabled logging statements virtually free is at the core of the logging framework. This, in turn, means that more of them can be left intact in the code without harm. Writing the log statement like we just did takes away this advantage.

Instead, we should do use the LazyArgs.lazy method:

logger.atFine().log("stats=%s", LazyArgs.lazy(() -> collectSummaries()));

Now, almost no work is done at the log site — just instance creation for the lambda expression. Flogger will only evaluate this lambda if it intends to actually log the message.

Although it's allowed to guard log statements using isEnabled:

if (logger.atFine().isEnabled()) {
    logger.atFine().log("summaries=%s", collectSummaries());
}

This is not necessary and we should avoid it because Flogger does these checks for us. This approach also only guards log statements by level and does not help with rate-limited log statements.

4.2. Dealing With Exceptions

How about exceptions, how do we handle them?

Well, Flogger comes with a withStackTrace method that we can use to log a Throwable instance:

try {
    int result = 45 / 0;
} catch (RuntimeException re) {
    logger.atInfo().withStackTrace(StackSize.FULL).withCause(re).log("Message");
}

Where withStackTrace takes as an argument the StackSize enum with constant values SMALL, MEDIUM, LARGE or FULL. A stack trace generated by withStackTrace() will show up as a LogSiteStackTrace exception in the default java.util.logging backend. Other backends may choose to handle this differently though.

4.3. Logging Configuration and Levels

So far we've been using logger.atInfo in most of our examples, but Flogger does support many other levels. We'll look at these, but first, let's introduce how to configure the logging options.

To configure logging, we use the LoggerConfig class.

For example, when we want to set the logging level to FINE:

LoggerConfig.of(logger).setLevel(Level.FINE);

And Flogger supports various logging levels:

logger.atInfo().log("Info Message");
logger.atWarning().log("Warning Message");
logger.atSevere().log("Severe Message");
logger.atFine().log("Finest Message");
logger.atFine().log("Fine Message");
logger.atFiner().log("Finer Message");
logger.atConfig().log("Config Message");

4.4. Rate Limiting

How about the issue of rate-limiting? How do we handle the case where we don't want to log every iteration?

Flogger comes to our rescue with the every(int n) method:

IntStream.range(0, 100).forEach(value -> {
    logger.atInfo().every(40).log("This log shows every 40 iterations => %d", value);
});

We get the following output when we run the code above:

Sep 18, 2019 5:04:02 PM com.baeldung.flogger.FloggerUnitTest lambda$givenAnInterval_shouldLogAfterEveryTInterval$0
INFO: This log shows every 40 iterations => 0 [CONTEXT ratelimit_count=40 ]
Sep 18, 2019 5:04:02 PM com.baeldung.flogger.FloggerUnitTest lambda$givenAnInterval_shouldLogAfterEveryTInterval$0
INFO: This log shows every 40 iterations => 40 [CONTEXT ratelimit_count=40 ]
Sep 18, 2019 5:04:02 PM com.baeldung.flogger.FloggerUnitTest lambda$givenAnInterval_shouldLogAfterEveryTInterval$0
INFO: This log shows every 40 iterations => 80 [CONTEXT ratelimit_count=40 ]

What if we want to log say every 10 seconds? Then, we can use atMostEvery(int n, TimeUnit unit):

IntStream.range(0, 1_000_0000).forEach(value -> {
    logger.atInfo().atMostEvery(10, TimeUnit.SECONDS).log("This log shows [every 10 seconds] => %d", value);
});

With this, the outcome now becomes:

Sep 18, 2019 5:08:06 PM com.baeldung.flogger.FloggerUnitTest lambda$givenATimeInterval_shouldLogAfterEveryTimeInterval$1
INFO: This log shows [every 10 seconds] => 0 [CONTEXT ratelimit_period="10 SECONDS" ]
Sep 18, 2019 5:08:16 PM com.baeldung.flogger.FloggerUnitTest lambda$givenATimeInterval_shouldLogAfterEveryTimeInterval$1
INFO: This log shows [every 10 seconds] => 3545373 [CONTEXT ratelimit_period="10 SECONDS [skipped: 3545372]" ]
Sep 18, 2019 5:08:26 PM com.baeldung.flogger.FloggerUnitTest lambda$givenATimeInterval_shouldLogAfterEveryTimeInterval$1
INFO: This log shows [every 10 seconds] => 7236301 [CONTEXT ratelimit_period="10 SECONDS [skipped: 3690927]" ]

5. Using Flogger With Other Backends

So, what if we would like to add Flogger to our existing application that is already using say Slf4j or Log4j for example? This could be useful in cases where we would want to take advantage of our existing configurations. Flogger supports multiple backends as we'll see.

5.1 Flogger With Slf4j

It's simple to configure an Slf4j back-end. First, we need to add the flogger-slf4j-backend dependency to our pom:

<dependency>
    <groupId>com.google.flogger</groupId>
    <artifactId>flogger-slf4j-backend</artifactId>
    <version>0.4</version>
</dependency>

Next, we need to tell Flogger that we would like to use a different back-end from the default one. We do this by registering a Flogger factory through system properties:

System.setProperty(
  "flogger.backend_factory", "com.google.common.flogger.backend.slf4j.Slf4jBackendFactory#getInstance");

And now our application will use the existing configuration.

5.1 Flogger With Log4j

We follow similar steps for configuring Log4j back-end. Let's add the flogger-log4j-backend dependency to our pom:

<dependency>
    <groupId>com.google.flogger</groupId>
    <artifactId>flogger-log4j-backend</artifactId>
    <version>0.4</version>
    <exclusions>
        <exclusion>
            <groupId>com.sun.jmx</groupId>
            <artifactId>jmxri</artifactId>
        </exclusion>
        <exclusion>
            <groupId>com.sun.jdmk</groupId>
            <artifactId>jmxtools</artifactId>
        </exclusion>
        <exclusion>
            <groupId>javax.jms</groupId>
            <artifactId>jms</artifactId>
        </exclusion>
    </exclusions>
</dependency>

<dependency>
    <groupId>log4j</groupId>
    <artifactId>log4j</artifactId>
    <version>1.2.17</version>
</dependency>
<dependency>
    <groupId>log4j</groupId>
    <artifactId>apache-log4j-extras</artifactId>
    <version>1.2.17</version>
</dependency>

We also need to register a Flogger back-end factory for Log4j:

System.setProperty(
  "flogger.backend_factory", "com.google.common.flogger.backend.log4j.Log4jBackendFactory#getInstance");

And that's it, our application is now set up to use existing Log4j configurations!

6. Conclusion

In this tutorial, we've seen how to use the Flogger framework as an alternative for the traditional logging frameworks. We've seen some powerful features that we can benefit from when using the framework.

We've also seen how we can leverage our existing configurations by registering different back-ends like Slf4j and Log4j.

As usual, the source code for this tutorial is available over on GitHub.

Java bottom

The early-bird price of the new Learn Spring Security OAuth course packages will increase by $50 on Wednesday:

>> CHECK OUT THE COURSE
Comments are closed on this article!