Logging with optional parameters

Question

I have method where I want to add specific logging:

@Slf4j
@Service
public class SomethingService {

    public void doSomething(Something data, String comment, Integer limit) {
        Long id = saveSomethingToDatabase(data, comment);
        boolean sentNotification = doSomething(id);
        // ...

        // Log what you done.
        // Variables that always have important data: data.getName(), id
        // Variables that are optional: sentNotification, comment, limit 
        // (optional means they aren't mandatory, rarely contains essential data, often null, false or empty string).
    }
}

I can simply log all:

log.info("Done something '{}' and saved (id {}, sentNotification={}) with comment '{}' and limit {}",
                something.getName(), id, sentNotification, comment, limit);
// Done something 'Name of data' and saved (id 23, sentNotification=true) with comment 'Comment about something' and limit 2

But most of the time most of the parameters are irrelevant. With the above I get logs like:

// Done something 'Name of data' and saved (id 23, sentNotification=false) with comment 'null' and limit null

That makes logs hard to read, long and unnecessarily complicated (in most cases other parameters aren't present).

I want to handle all cases with preserving only essential data. Examples:

// Done something 'Name of data' and saved (id 23)
// Done something 'Name of data' and saved (id 23) with comment 'Comment about something'
// Done something 'Name of data' and saved (id 23) with limit 2
// Done something 'Name of data' and saved (id 23) with comment 'Comment about something' and limit 2
// Done something 'Name of data' and saved (id 23, sent notification)
// Done something 'Name of data' and saved (id 23, sent notification) with limit 2
// Done something 'Name of data' and saved (id 23, sent notification) with comment 'Comment about something'
// Done something 'Name of data' and saved (id 23, sent notification) with comment 'Comment about something' and limit 2

I can code it by hand:

String notificationMessage = sentNotification ? ", sent notification" : "";
String commentMessage = comment != null ? String.format(" with comment '%s'", comment) : "";
String limitMessage = "";
if (limit != null) {
    limitMessage = String.format("limit %s", limit);
    limitMessage = comment != null ? String.format(" and %s", limitMessage) : String.format(" with %s", limitMessage);
}
log.info("Done something '{}' and saved (id {}{}){}{}",
        something.getName(), id, notificationMessage, commentMessage, limitMessage);

But it's hard to write, hard to read, complicated and causes errors.

I would like something like specify part of logs.

Example pseudocode:

log.info("Done something '{}' and saved (id {} $notification) $parameters",
        something.getName(), id,
        $notification: sentNotification ? "sent notification" : "",
        $parameters: [comment, limit]);

It should supports optional parameters, replace boolean/condition with given string, supports separating spaces, commas and words with and and.

Maybe are there existing library for this? Or maybe is there at least a simpler way for coding this?

If not, it remains for me nothing else to write my own library for messages to logging. Additionally, this kind of library will provide that all logs would be consistent.

If you don't see a problem with three optional parameters, just imagine there are more (and you can't always pack them into a class - another class layer only for parameter logging cause even more complications).

At the end, I know I can log each action separately. But with this I get many more logs and I won't have the most important information in one place. Other logs are in the debug level, not info.

Answer 1

both of these are possible. You can either:

• register a component with the Logger to do the work for you
• write a wrapper class for your logger to use

I will demonstrate both and explain why I think the second is the better choice. Let's start with that:

Instead of having the Logger own the knowledge of how to format your specific properties, let your code own this responsibility.

For example, rather than logging each parameter, collect them and define their logging separately. See this code:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class LoggingExample {

  private static final Logger LOGGER = LoggerFactory.getLogger(LoggingExample.class);

  public static void main(String[] args) {
    LogObject o = new LogObject();

    LOGGER.info("{}", o);

    o.first = "hello";

    LOGGER.info("{}", o);

    o.second = "World";

    LOGGER.info("{}", o);

    o.last = "And finally";

    LOGGER.info("{}", o);
  }

  public static class LogObject {

    String first;
    String second;
    String last;

    @Override
    public String toString() {
      StringBuffer buffer = new StringBuffer();
      buffer.append("Log Object: ");
      if (first != null) {
        buffer.append("First: " + first + " ");
      }
      if (second != null) {
        buffer.append("Second: " + second + " ");
      }
      if (last != null) {
        buffer.append("Second: " + last + " ");
      }
      return buffer.toString();
    }
  }
}

We define LogObject as a container and this container implements toString. All Loggers will call toString() on their objects, that is how they figure out what they should print (unless special formatters applied etc).

With this, the log statements print:

11:04:12.465 [main] INFO LoggingExample - Log Object: 
11:04:12.467 [main] INFO LoggingExample - Log Object: First: hello 
11:04:12.467 [main] INFO LoggingExample - Log Object: First: hello Second: World 
11:04:12.467 [main] INFO LoggingExample - Log Object: First: hello Second: World Second: And finally 

Advantages:

• this works with any Logger. You won't have to implement specifics depending on what you want to use
• the knowledge is encapsulated in 1 object that can be easily tested. This should mitigate the error prone formatting problem you stated.
• no need for a complex formatter library or implementation
• It will make the logging look much nicer and compact in the end. log.info("{}", object);

Disadvantage:

• You are required to write the Bean.

Now the same can be achieved using for example a custom Layout. I am using logback, so this is an example for logback.

We may define a Layout that owns the knowledge of what to do with your custom formatting instructions.

import org.slf4j.LoggerFactory;
import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.encoder.PatternLayoutEncoder;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.ConsoleAppender;
import ch.qos.logback.core.LayoutBase;

public class LoggingExample2 {


  private static final Logger CUSTOM_LOGGER = createLoggerFor("test");
  
  public static void main(String[] args) {
    LogObject o = new LogObject();

    CUSTOM_LOGGER.info("{}", o);

    o.first = "hello";

    CUSTOM_LOGGER.info("{}", o);
    
    o.second = "World";

    CUSTOM_LOGGER.info("{}", o);
    
    o.last = "And finally";

    CUSTOM_LOGGER.info("{}", o);
  }

  public static class LogObject {

    String first;
    String second;
    String last;

    @Override
    public String toString() {
      StringBuffer buffer = new StringBuffer();
      buffer.append("Log Object: ");
      if (first != null) {
        buffer.append("First: " + first + " ");
      }
      if (second != null) {
        buffer.append("Second: " + second + " ");
      }
      if (last != null) {
        buffer.append("Second: " + last + " ");
      }
      return buffer.toString();
    }
  }

  public static class ModifyLogLayout extends LayoutBase<ILoggingEvent> {

    @Override
    public String doLayout(ILoggingEvent event) {
      String formattedMessage = event.getFormattedMessage() + "\n";
      Object[] args = event.getArgumentArray();

      return String.format(formattedMessage, args);
    }

  }
  
  private static Logger createLoggerFor(String string) {
      LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory();
      PatternLayoutEncoder ple = new PatternLayoutEncoder();
      
      ple.setPattern("%date %level [%thread] %logger{10} [%file:%line] %msg%n");
      ple.setContext(lc);
      ple.start();
      
      ConsoleAppender<ILoggingEvent> consoleAppender = new ConsoleAppender<ILoggingEvent>();
      consoleAppender.setEncoder(ple);
      consoleAppender.setLayout(new ModifyLogLayout());
      consoleAppender.setContext(lc);
      consoleAppender.start();

      Logger logger = (Logger) LoggerFactory.getLogger(string);
      logger.addAppender(consoleAppender);
      logger.setLevel(Level.DEBUG);
      logger.setAdditive(false); /* set to true if root should log too */

      return logger;
   }
}

I borrowed the Logger instatiation from: Programmatically configure LogBack appender

Note that I have not found a library that can parse the complex expressions that you have listed. I think you may have to write your own implementation.

In my example, i only illustrate how to intercept and modify the message based on the arguments.

Why I would not recommend this unless it is really needed:

• the implementation is specific to logback
• writing correct formatting is hard ... it will produce more errors than creating a custom object to format
• It is harder to test because you literally have unlimited objects that may pass through this (and formatting). Your code must be resilient to this now, and in the future since any developer may add the weirdest things at any time.

The last (unasked) answer:

Why don't you use a json encoder? And then use something like logstash to aggregate (or cloudlwatch, or anything else).

This should solve all your problems.

This is what I have done in the past:

Define 1 bean that you like to log "differently". I call it metadata. This bean can be i.e.

public class MetaHolder {
 // map holding key/values 
} 

This basically just stores all your variables with a key. It allows you to effectively search on these keys, sink them into databases, etc. etc.

In your log, you simply do:

var meta = // create class 
meta.put("comment", comment); 
// put other properties here
log.info("formatted string", formattedArguments, meta); // meta is always the last arg

In the Layout this can then be converted quite nicely. Because you are no longer logging "human language", there are no "withs" and "in" to replace. Your log will simply be:

{
    "time" : "...",
    "message" : "...",
    "meta" : {
        "comment" : "this is a comment"
        // no other variables set, so this was it 
    }
}

And one last (last) one in just pure java, if you wanted that. You could write:

public static void main(String[] args) {

    String comment = null;
    String limit = "test";
    String id = "id";

    LOGGER.info(
        "{} {} {}",
        Optional.ofNullable(comment).map(s -> "The comment " + s).orElse(""),
        Optional.ofNullable(limit).map(s -> "The Limit " + s).orElse(""),
        Optional.ofNullable(id).map(s -> "The id " + s).orElse(""));
  }

Which effectively moves the conditional logic you want in your formatting into Java's Optional.

I find this also is hard to read and test and would still recommend the first solution