24

I need something similar to String.format(...) method, but with lazy evaluation.

This lazyFormat method should return some object whose toString() method would then evaluate the format pattern.

I suspect that somebody has already done this. Is this available in any libararies?

I want to replace this (logger is log4j instance):

if(logger.isDebugEnabled() ) {
   logger.debug(String.format("some texts %s with patterns %s", object1, object2));
}

with this:

logger.debug(lazyFormat("some texts %s with patterns %s", object1, object2));

I need lazyFormat to format string only if debug logging is enabled.

Juha Syrjälä
  • 33,425
  • 31
  • 131
  • 183

10 Answers10

21

if you are looking for a "simple" solution:

 public class LazyFormat {

    public static void main(String[] args) {
        Object o = lazyFormat("some texts %s with patterns %s", "looong string", "another loooong string");
        System.out.println(o);
    }

    private static Object lazyFormat(final String s, final Object... o) {
        return new Object() {
            @Override
            public String toString() {
                return String.format(s,o);
            }
        };
    }
}

outputs:

some texts looong string with patterns another loooong string

you can of course add any isDebugEnabled() statement inside lazyFormat if you will.

vsminkov
  • 10,912
  • 2
  • 38
  • 50
Andreas Petersson
  • 16,248
  • 11
  • 59
  • 91
  • Newer versions of Log4J allow parameter substitution see http://stackoverflow.com/a/14078904/620113 – computermacgyver Jan 24 '13 at 04:26
  • Does this actually work -- it will format the string but is it doing the "lazy" thing? I made a small test where lazyFormat's args are calls to a function that prints to System.err and it seemed like the args in Object... o get evaluated even if the String.format(s,o) is not. – OneSolitaryNoob Apr 17 '13 at 17:36
  • OneSolitaryNoob - It is not doing the lazy thing. The answer provider indicates it can be done by using the "isDebugEnabled()" method in the toString() methdod. I've provided a more general lazy logging pattern in my answer: http://stackoverflow.com/a/18317629/501113 – chaotic3quilibrium Sep 09 '13 at 15:48
  • How about in Scala? – Coder Guy May 14 '19 at 22:33
17

It can be done by using parameter substitution in newest log4j 2.X version http://logging.apache.org/log4j/2.x/log4j-users-guide.pdf:

4.1.1.2 Parameter Substitution

Frequently the purpose of logging is to provide information about what is happening in the system, which requires including information about the objects being manipulated. In Log4j 1.x this could be accomplished by doing:

if (logger.isDebugEnabled()) {     
  logger.debug("Logging in user " + user.getName() + " with id " + user.getId()); 
} 

Doing this repeatedly has the effect of making the code feel like it is more about logging than the actual task at hand. In addition, it results in the logging level being checked twice; once on the call to isDebugEnabled and once on the debug method. A better alternative would be:

logger.debug("Logging in user {} with id {}", user.getName(), user.getId()); 

With the code above the logging level will only be checked once and the String construction will only occur when debug logging is enabled.

yurilo
  • 3,079
  • 2
  • 23
  • 14
  • 1
    Your example is a bit misleading in that there is little difference between your unformatted and formatted example; i.e. there is no real value in the formatter for the user.getName() or user.getId() operations as they are called immediately and their values passed into the logger.debug method. The original poster was passing two Object instances counting on the fact that the toString() method on those instances wouldn't be called unless they were needed. I posted an answer that more accurately captures this "only call for the data if it will be used" state. – chaotic3quilibrium Sep 06 '13 at 14:04
  • Log4j 2.4 [adds support for lambdas](http://logging.apache.org/log4j/2.x/manual/api.html#LambdaSupport). – Hollis Waite Dec 18 '15 at 23:24
  • In `logger.debug("Logging in user {} with id {}", user.getName(), user.getId());` the `get` methods will be called immediately just before the running of `logger.debug()`, to accomplish the lazy pattern of log4j you need to: `logger.debug("Logging in user {} with id {}", () -> user.getName(), () -> user.getId());` – Luciano Apr 23 '19 at 17:24
13

if you are looking for lazy concatenation for the sake of efficient logging, take a look at Slf4J this allows you to write:

LOGGER.debug("this is my long string {}", fatObject);

the string concatenation will only take place if the debug level is set.

Andreas Petersson
  • 16,248
  • 11
  • 59
  • 91
  • 2
    the problem of lazy evaluation was exactly why slf4j's {} syntax was introduced – Andreas Petersson Jun 03 '09 at 06:45
  • Otherwise good, but I am of stuck with log4j. I have kind of complex logging setup, so I can't just drop slf4j in. – Juha Syrjälä Jun 03 '09 at 06:50
  • 2
    SLF4J has a binding for log4j. So whatever your "complex logging setup" is, SLF4J will handle it nicely. You could continue to use log4j directly and SLF4J only when lazy string evaluation is necessary. – Ceki Jun 03 '09 at 14:50
5

IMPORTANT NOTE: It is strongly recommended all logging code be moved to use SLF4J (especially log4j 1.x). It protects you from being stuck with any sort of idiosyncratic issues (i.e. bugs) with specific logging implementations. Not only does it have "fixes" for well know backend implementation issues, it also works with newer faster implementations which have emerged over the years.


In direct response to your question, here what it would look like using SLF4J:

LOGGER.debug("some texts {} with patterns {}", object1, object2);

The most important bit of what you have provided is the fact you are passing two Object instances. The object1.toString() and the object2.toString() methods are not immediately evaluated. More importantly, the toString() methods are only evaluated if the data they return is actually going to be used; i.e. the real meaning of lazy evaluation.

I tried to think of a more general pattern I could use which didn't require my having to override toString() in tons of classes (and there are classes where I don't have access to do the override). I came up with a simple drop-in-place solution. Again, using SLF4J, I compose the string only if/when logging for the level is enabled. Here's my code:

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

      ...

      public void someCodeSomewhereInTheClass() {
//all the code between here
        LOGGER.debug(
            "{}"
          , new Object() {
              @Override
              public String toString() {
                return "someExpensiveInternalState=" + getSomeExpensiveInternalState();
              }
            }
//and here can be turned into a one liner
        );
      }

      private String getSomeExpensiveInternalState() {
        //do expensive string generation/concatenation here
      }
    }

And to simplify into the one-liner, you can shorten the LOGGER line in someCodeSomewhereInTheClass() to be:

LOGGER.debug("{}", new Object(){@Override public String toString(){return "someExpensiveInternalState=" + getSomeExpensiveInternalState();}});

I have now refactored all my logging code to follow this simple model. It has tidied things up considerably. And now when I see any logging code which does not use this, I refactor the logging code to use this new pattern even if it is needed yet. That way, if/when a change is made later to need to add some "expensive" operation, the infrastructure boilerplate is already there simplifying the task to just adding the operation.

chaotic3quilibrium
  • 5,661
  • 8
  • 53
  • 86
3

If you like the String.format Syntax better than the {0} Syntax and can use Java 8 / JDK 8 you can use lambdas / Suppliers:

logger.log(Level.FINER, () -> String.format("SomeOperation %s took %04dms to complete", name, duration));

()->... acts as a Supplier here and will be evaluated lazily.

smakks
  • 69
  • 4
3

Building upon Andreas' answer, I can think of a couple of approaches to the issue of only performing the formatting if the Logger.isDebugEnabled returns true:

Option 1: Pass in a "do formatting" flag

One option is to have a method argument that tells whether or not to actually perform the formatting. A use case could be:

System.out.println(lazyFormat(true, "Hello, %s.", "Bob"));
System.out.println(lazyFormat(false, "Hello, %s.", "Dave"));

Where the output would be:

Hello, Bob.
null

The code for lazyFormat is:

private String lazyFormat(boolean format, final String s, final Object... o) {
  if (format) {
    return String.format(s, o);
  }
  else {
    return null;
  }
}

In this case, the String.format is only executed when the format flag is set to true, and if it is set to false it will return a null. This would stop the formatting of the logging message to occur and will just send some "dummy" info.

So a use case with the logger could be:

logger.debug(lazyFormat(logger.isDebugEnabled(), "Message: %s", someValue));

This method doesn't exactly fit the formatting that is asked for in the question.

Option 2: Check the Logger

Another approach is to ask the logger directly if it isDebugEnabled:

private static String lazyFormat(final String s, final Object... o) {
  if (logger.isDebugEnabled()) {
    return String.format(s, o);
  }
  else {
    return null;
  }
}

In this approach, it is expected that logger will be visible in the lazyFormat method. And the benefit of this approach is that the caller will not need to be checking the isDebugEnabled method when lazyFormat is called, so the typical use can be:

logger.debug(lazyFormat("Debug message is %s", someMessage));
Community
  • 1
  • 1
coobird
  • 159,216
  • 35
  • 211
  • 226
3

You could wrap the Log4J logger instance inside your own Java5-compatible/String.format compatible class. Something like:

public class Log4jWrapper {

    private final Logger inner;

    private Log4jWrapper(Class<?> clazz) {
        inner = Logger.getLogger(clazz);
    }

    public static Log4jWrapper getLogger(Class<?> clazz) {
        return new Log4jWrapper(clazz);
    }

    public void trace(String format, Object... args) {
        if(inner.isTraceEnabled()) {
            inner.trace(String.format(format, args));    
        }
    }

    public void debug(String format, Object... args) {
        if(inner.isDebugEnabled()) {
            inner.debug(String.format(format, args));    
        }
    }

    public void warn(String format, Object... args) {
        inner.warn(String.format(format, args));    
    }

    public void error(String format, Object... args) {
        inner.error(String.format(format, args));    
    }

    public void fatal(String format, Object... args) {
        inner.fatal(String.format(format, args));    
    }    
}

To use the wrapper, change your logger field declaration to:

private final static Log4jWrapper logger = Log4jWrapper.getLogger(ClassUsingLogging.class);

The wrapper class would need a few extra methods, for example it does not currently handle of logging exceptions (ie logger.debug(message, exception)), but this shouldn't be hard to add.

Using the class would be almost identical to log4j, except strings are formatted:

logger.debug("User {0} is not authorized to access function {1}", user, accessFunction)
Andrew Newdigate
  • 6,005
  • 3
  • 37
  • 31
2

Introduced in Log4j 1.2.16 are two classes that will do this for you.

org.apache.log4j.LogMF which uses a java.text.MessageFormat for format you messages and org.apache.log4j.LogSF which uses the "SLF4J pattern syntax" and is said to be faster.

Here are examples:

LogSF.debug(log, "Processing request {}", req);

and

 LogMF.debug(logger, "The {0} jumped over the moon {1} times", "cow", 5); 
Victor
  • 3,395
  • 1
  • 23
  • 26
1

Or you could write it as

debug(logger, "some texts %s with patterns %s", object1, object2);

with

public static void debug(Logger logger, String format, Object... args) {
    if(logger.isDebugEnabled()) 
       logger.debug(String.format("some texts %s with patterns %s", args));
}
Peter Lawrey
  • 525,659
  • 79
  • 751
  • 1,130
0

You could defined a wrapper in order to call the String.format() only if needed.

See this question for a detailed code example.

The same question has also a variadic function example, as suggested in Andreas's answer.

Community
  • 1
  • 1
VonC
  • 1,262,500
  • 529
  • 4,410
  • 5,250