Spring logging support enhancement

[garyrussell]

Affects: 5.2.x

Many Spring projects use the pattern

if (this.logger.isDebugEnabled()) {
    this.logger.debug(<someStringExpression>);
}

To avoid evaluating <someSpringExpression> (often a StringBuilder) unless the level is enabled.

With the advent of lambdas, this code could be simpler, using Supplier...

this.logger.debug(() -> <someStringExpression>);

or

this.logger.debug(new LogMessage(() -> <someStringExpression>));

After some discussion with Juergen, a couple of options emerged...

Anyway, in terms of common code, I could imagine both a LogAccessor type (including Supplier-based log methods) and a LogMessage type (including a Supplier-based constructor) in the core.log package, leaving the choice up to the caller.

[rstoyanchev]

Note that in 5.1 we added LogFormatUtils which has a couple of methods already with a similar purpose, i.e. to enhance the logging API, for example traceDebug which is used in places where we want to log slightly different information for debug vs trace. I can imagine more methods there.

[jhoeller]

@rstoyanchev I've considered that already but since this is really about Supplier convenience we're talking about 12 variants of log methods (2 per log category) which are arguably better off on a dedicated LogAccessor decorator type. Also, LogMessage is a really simple Supplier-to-lazy-toString adapter which LogAccessor internally uses but which can also used explicitly with any Log instance.

From my perspective, those pieces complement each other quite nicely.

[jhoeller]

@garyrussell FYI, in my local tests, the LogMessage instance has no noticeable impact... even in a non-warmed up JVM but in particular in a warmed-up scenario. I'm therefore using it in the LogAccessor implementation internally, avoiding a double log enabled check that way. So eventually, LogAccessor is just a convenience for repeated LogMessage use:

Log logger = LogFactory.getLog(MyClass.class);
logger.info(new LogMessage(() -> ...));

LogAccessor logger = new LogAccessor(MyClass.class);
logger.info(() -> ...);

Note that LogAccessor has CharSequence arguments in contrast to Log's Object arguments, for clean disambiguation between plain message objects and Supplier instances among its overloaded methods.

[garyrussell]

Sounds good; thanks.

[sbrannen]

@jhoeller, when I introduced similar log message Supplier support in the Logger façade for JUnit 5, I decided to put the Supplier as the last argument for methods accepting a Throwable and a Supplier.

Although that contradicts conventional API design practices whereby optional arguments (in this case a Throwable) come last, the JUnit team and I felt it was more readable/usable to have the Supplier follow the Throwable in the argument list due to the typical formatting of inline lambda expressions spanning more than one line.

What do you think about switching the order of those arguments in methods in the new LogAccessor API?

[jhoeller]

@sbrannen Good point indeed! Given that the order of arguments for the Supplier variants should switch, I'm inclined to align the regular CharSequence variants as well: all taking the Throwable first, then the message. Since LogAccessor is primarily designed for Supplier use, it seems sensible to prefer alignment for that convention. Whoever wants to use a logger the usual way can stick with a regular Log anyway.

[sbrannen]

SGTM.

[jhoeller]

Reopening for printf-style format string support in LogMessage.

My current implementation turns LogMessage into an abstract class now: with internal subclasses for Supplier bindings as well as printf-style format strings, created through corresponding static factory methods LogMessage.lazy(Supplier) and LogMessage.format(...) (several overloads for fixed numbers of arguments, with a less efficient varargs array variant as fallback).

[philwebb]

I wonder if we should consider renaming the lazy method? The fact that it's lazy is somewhat of an implementation detail and I think of might read better:

logger.debug(LogMessage.of(() -> "foo" + "bar"))`

That might also work for the format method as well (although I quite like that format aligns with String.format).

logger.debug(LogMessage.of("%s %s", foo, bar))

[jhoeller]

of is a great suggestion there, changing it right away :-) FWIW, I don't see lazy as as a plain implementation detail but rather as a key characteristic of why you would use this, but then again, the format variants are lazy as well, so it's not an ideal factory method name. It would rather suggest itself as part of the class name I guess, but LazyLogMessage seems so wordy.

As for format, the distinct name there seems quite sensible, not least of it all since the argument types are so generic. With of potentially overloaded for other plain types in the future, having those five format methods with a distinct name next to it seems like a good choice. Also, format lends itself well to a static import, which is particularly useful since it is not available on LogAccessor out of the box, and which reads just like the commonly used static import for String.format itself (the difference being the lazy resolution which is quite transparent then):

import static org.springframework.core.log.LogMessage.format;

logger.debug(format("%s %s", foo, bar));

[philwebb]

Indeed, I wasn't too sure on renaming format, it did seem to be asking for override trouble and the existing name gives some nice clues that it's looking for a String.format pattern and not a log Log4J {} type placeholder.

[garyrussell]

Hi Juergen,

I wonder if you would consider adding is*Enabled() methods to LogAccessor?

I can see 2 use cases...

• a superclass with a protected final LogAccessor with many subclasses - it would make the transition easier because we wouldn't have to transition every subclass at the same time.
• logging non-final (or effectively final) variables from the Supplier lambda - right now, we have to create a dummy final variable before logging; with these methods, we could continue to use the existing style.

Thoughts?

Thanks