Planned/possible fluent API change in SLF4J 2.0

[ceki]

Hello all,

Preamble

SLF4J version 2.0 adds a fluent API to the Logger interface with the traditional API from version 1.7.x staying as is, untouched.

The fluent API builds a "logging event" object piecemeal using a LoggingEventBuilder. The atTrace(), atDebug(), atInfo(), atWarn() and atError() methods, all new in the org.slf4j.Logger interface, return an instance of LoggingEventBuilder. For disabled log levels, the returned LoggingEventBuilder instance does nothing, thus preserving the nano-second level performance of the traditional logging interface.

Rationale behind the fluent API

The fluent API is intended to reduce the combinatorial explosion in the number of methods required to support multiple inputs such as message, zero or more arguments, zero ore more markers, zero or more key-value-pairs and zero or one throwable. Moreover, some of these values may be passed via lambda expressions adding further method combinations. With just 17 (=5+12) methods the current API supports all possible combinations of the above (instead of 280 methods).

Description of proposal

In SLF4J-526, Adrian Shum proposed to modify the fluent API.

In the current version of the fluent API (SLF4J 2.0), to emit a debug message with two parameters, one has to write the following

Existing variant

logger.atDebug()
        .addArgument(room).addArgument(oldTemp).addArgument(newTemp)
        .log("Temperature of {} changed from {} to {}");

We propose that the fluent API be changed as follows.

Proposed variant

logger.atDebug()
        .message("Temperature of {} changed from {} to {}" )
        .arg(room).arg(oldTemp).arg(newTemp).log();

The proposed variant is a little easier to write and also to read. However, it entails one inconvenience. Indeed, in case the user forgets to call the no-argument log() method, then nothing will happen, i.e. no logging will occur. With the current API, it is harder for the user to forget the log(String) method containing the message content.

Before going forward with this proposal, we would like to receive input by the user community.

Update (release 2.0.0-beta0)

API was updated in 2.0.0-beta0 by adding the setMessage(String), setMessage(Supplier<String>) and log() methods to the LoggingEventBuilder interface.

Update (release 2.0.0-beta1)

Methods in the LoggingEventBuilder interface returning an instance of LoggingEventBuilder are now annotated with @CheckReturnValue. This allows compile time detection of missing calls to one of the terminating log() methods. Many thanks to @jreznot and @vlsi their help and suggestions.

[vorburger]

Anything that can be forgotten to be written (and isn't caught by the compiler) will be by some people, so I'm not sure this is a great idea.

[Ordiel]

I also agree with this comment, I think it's better to learn a "complex" (whatever that is) and highly descriptive API than a fluent API that allows you to shoot yourself in the foot, which in turn may make the library more unwelcoming to new users (students); this, not discarding the (already suggested) approach of implementing the fluent API as an abstraction layer to the already existing one.

On the other hand, I consider a drastic change on the API may discourage many of the already existing users from upgrading their code base to the new API; this should not be a problem if we maintain the old API.

[ShadowLordAlpha]

Honestly I prefer the look and readability of the Proposed change much more then how it is currently. However from what I can see there is nothing stopping us from having both types. Its fluent so I prefer shorter names or at least no get/set though honestly that is just preference.

The main thing is that its much more common for arguments to be added after the message, it will feel wrong to a lot of people if its not. Think of String.format or other similar methods in other systems like Androids Timber or any other single method logger, its not the end all be all but the ability for a user to just know how something works is very powerful in how they feel about something.

Both formats can easily be supported though just by having a log(String) that is basically just.

log(String log) { message(log); log(); }

And that would take the decision and put it in the users hands how they want their code formatted while providing a shortcut instead of message and then log. If only one can be supported though I would prefer the second one. and as it is so close to a Builder I believe it won't be confusing for most people as its a common style used. IDEs are also really good at detecting these kinds of mistakes and warning the user as just because something is technically correct doesn't mean its a good idea or what the user wants

[KengoTODA]

I have the same opinion with @ShadowLordAlpha about the following part:

The main thing is that its much more common for arguments to be added after the message, it will feel wrong to a lot of people if its not

On the other hand, I feel that calling an empty log() is just confusing. It is natural for builders because we expect a returned value with a specific type. But we do not expect the same to the logging API.

So I will probably do not use both, use "using fluent API, log message with arguments" instead:

logger.atDebug()
        .log("Temperature of {} changed from {} to {}", room, oldTemp, newTemp);

BTW If the LoggingEventBuilder is immutable, the new API would be useful to shorten the code in the loop like below:

var logBuilder = logger.atDebug()
        .message("Temperature of {} changed from {} to {}");

for (var room : rooms) {
    logBuilder.arg(room).arg(loadOldTemp(room)).arg(loadNewTemp(room)).log();
}

But for now, the LoggingEventBuilder is mutable.

[ceki]

The possibility of an immutable `LoggingEventBuilder had not occurred to me.

[bratmobileum]

And add an args() method with var-args too. I should be able to use:

for (var room : rooms) {

logBuilder.args(room, loadOldTemp(room), loadNewTemp(room)).log();

}

[pedrolamarao]

An immutable builder sounds strange if builders are expected to accumulate-then-generate. If it is immutable, it cannot accumulate. In the example with the for loop, there must be a temporary unnamed mutable object to accumulate all the "args". If a mutable object is acceptable to accumulate the "args", making the initial builder immutable seems pointless. If the purpose is to allow the reuse of the builder to log multiple times from the same template, it would be sufficient to allow "cloning" a builder. But that would be as performant as just creating a new builder to begin with.

[leviramsey]

If log clears the accumulated state, then at least in cases where something else is ensuring only one thread accesses the builder (e.g. it's only used inside one particular Akka actor) it's reusable without allocating a new builder. A related approach would be to have a builder variant which opts into enforced thread-safety across calls in a way similar to what Akka does with the (typed) ActorContext: keeping which thread entered the builder in state and only allowing that thread to perform operations (at least immediately) on the builder until log is called.

[Inoy1st]

I like the general direction of a snippet proposed by @KengoTODA, but IMO it should be like this:

logger.debug("Temperature of {} changed from {} to {}", room, oldTemp, newTemp);

[Thunderforge]

Isn't that the current, non-fluent behavior?

I do admit that it seems far simpler to me and I'm not seeing the benefits of the fluent behavior, but maybe there are some performance cases or something that are important for certain critical applications.

[ceki]

The fluent API is intended to reduce the combinatorial explosion in the number of methods required to support multiple inputs such as message, zero or more arguments, zero ore more markers, zero or more key-value-pairs and zero or one throwable. Moreover, some of these values may be passed via lambda expressions adding further method combinations.

[Inoy1st]

@ceki I understand that support of multiple inputs is troublesome, but it's so convenient to use!

[ceki]

@Inoy1st It goes without saying that the traditional SLF4J API will be available without change.

[trandersen-ufst]

The fluent API is intended to reduce the combinatorial explosion in the number of methods required to support multiple inputs such as message, zero or more arguments, zero ore more markers, zero or more key-value-pairs and zero or one throwable. Moreover, some of these values may be passed via lambda expressions adding further method combinations.

I agree that the combinatorial explosion indicate that the original way to do it needs to be rethought now that functionality grows, but perhaps a step further back is needed to discuss possible options instead of asking the community to discuss essentially a fixed new implementation. It is very hard to think outside a very familiar box.

[Thunderforge]

Having logger.atDebug() followed by .message() makes me wonder if we could just combine the two methods into one.

logger.atDebug("Temperature of {} changed from {} to {}")
    .arg(room).arg(oldTemp).arg(newTemp)
    .log();

Or even .debug() instead of .atDebug() to match the shorter style used by SLF4J 1.x.

I suppose you could still allow logger.atDebug() with no parameters if you did want to add a message later.

[gavenkoa]

.atXxx(String) make sense: we cannot have 2 messages, like following should lead to warning in stderr or in static code analyzer:

log.atDebug().message("First").message("Oops... second").

[larrywest42]

Wouldn't this be solved (i.e., compile-time error) by having message() return an interface that does not include .message(), only .arg() and .log() (and, I hope, a varargs .args(...)... update: I forgot about the hidden cost.)?

[gavenkoa]

We need structural logging: to produce NDJson files which then delivered to Elasticsearch by Fluentbit. Writing to file is the "most" resilient way to recover from network / log-collector outages.

Oftentimes we are not interested in message but in structured arguments. With old API:

log.atInfo().addKeyValue("old", 10).addKeyValue("new", 12).log("ignore me");

With new API we can make message null:

log.atInfo().addKeyValue("old", 10).addKeyValue("new", 12).log();

There is a rise of structured logging, the days of formatted messages in their sunset... ))

Please consider better name than arg for new API. I think val & kv are good (or value & keyValue). See StructuredArguments in https://github.com/logfellow/logstash-logback-encoder#event-specific-custom-fields - it is what people actually need and use without waiting for Slf4j 2.x

[pedrolamarao]

Nice!

[pedrolamarao]

Admitting Java's Map as precedence, those methods could be beautifully shortened to put:

log.atInfo().put("old",10).put("new",12).log();

[pmendelson]

I would love to use the put("var1",x).put("var2",y).put("var3,z) style instead of .message("....{}....{}....{}",x,y,z).

[ijliym]

Why not add some overloaded methods to the org.slf4j.Logger class with parameters of type Supplier? I think that's pretty good.
This is my simple idea.

[vlsi]

log.info("some things, key1: {}", () -> getKey()); would be indistinguishable from the current API which accepts Object, and it is not clear how logger would know if it should call supplier.get().toString() or just supplier.toString() (the current behavior).

So it looks like the supplier-based methods should have different names from the regular ones.

[psuvjd]

I think we can refer log4j2's method：
https://github.com/apache/logging-log4j2/blob/c30a1398a6697fb832c650870c44284d0052103e/log4j-api/src/main/java/org/apache/logging/log4j/Logger.java#L2161
https://github.com/apache/logging-log4j2/blob/c30a1398a6697fb832c650870c44284d0052103e/log4j-api/src/main/java/org/apache/logging/log4j/Logger.java#L1985
In the logger of log4j2, there are also two api which both accepts Object and Supplier
void info(String message, Object p0);
void info(String message, Supplier<?>... paramSuppliers);

[vlsi]

There's a risk that user was calling info(String, Object) method and passed user-provided object that happen to implements Supplier for some reason.
In that case, re-compiling user code would accidentally switch to the new method yielding the new behaviour.

I'm not sure if that is significant or not, however, adding Supplier overloads would be a silent behaviour change.

[psuvjd]

If we add a new interface named Supplier in slf4j, like org.apache.logging.log4j.util.Supplier in log4j2, may be better.

[liuzhihang]

I think it is necessary to add Supplier. Because when I close the log, I don't want to execute that part of the logic.

[azhuchkov]

I assume the fluent API necessity is quite a rare case and it is not going to totally replace the standard API, so I'd prefer the existing variant. But addArgument() and addKeyValue() look too verbose to me. Maybe there is possibility to make it shorter, like arg() in the proposal? Or withArg(), etc.

[ceki]

Although it might look that way, when you actually write and especially read log statements, there is no big difference, even more so when reading the code where the current more verbose method names actually read better.

See for example:

Current API:

        logger.atDebug().setMessage("Measurement report for probe {}").addArgument(() -> getProbeId())
                .addKeyValue("delta", 0.4).addKeyValue("temperature", 23).log();

hypothetical terser API:

        logger.atDebug().message("Measurement report for probe {}").arg(() -> getProbeId())
                .kvp("delta", 0.4).kvp("temperature", 23).log();

[jbduncan]

I'm personally happy with the existing API, as it allows for the following code:

logger.atDebug()
        .log("Temperature of {} changed from {} to {}", room, oldTemp, newTemp);

But I'm aware that this doesn't allow any of the arguments to be lambdas for lazy logging. So I suggest looking at Google's flogger and copying their lazy method's API. It would allow for the following:

logger.atDebug()
        .log("Temperature of {} changed from {} to {}", lazy(() -> getExpensiveRoom()), oldTemp, newTemp);

Then, by my understanding, this would make .addArgument() redundant, so it could be removed.

I've not thought about the key-value use case, though...

[jbduncan]

To add my earlier comment, I'd personally advocate for removing .addArgument() and not adding .arg(), since in my view it's easier to forget to add each needed call to .addArgument()/.arg() than it is to add said arguments to the .log() call.

To get around the lack of ability to lazily log arguments, this is where I'd see that an API like Google flogger's lazy() would help.

(Sorry, I've still not thought about the key-value case. I think flogger has its own solution for this, but I don't have time to look into it right now...)

[tbroyer]

The combinatorial explosion is mostly due to non-argument values: markers, throwable, key-value pairs; but arguments are tightly related to the message, and should IMO be passed all at once.

So +1 for log(String message, Object... arguments), and for lazily-computed arguments, I don't see many other options apart from Flogger's one (and BTW I'm sure Google iterated a lot on their API and this was the best compromise)

[mcompton13]

I think something along this proposal is the best, having individual addArgument(...) calls is too verbose and it makes sense to keep the args with the log message themselves. This is the most common case it it would be more streamlined this way.

Having a separate fluent methods for adding an exception or key-value pairs still make sense since those are not formatted in the log message anyway. Those fluent methods combined with having a lazy(...) helper method that accepts lambda expressions as proposed above makes it so there's not an explosion of possible argument types. Everything in the log call after the message just needs to be turned into a string and there should be a matching number of {}'s in the format. Easy to read, easy to lint.

The one tricky thing might be the lazy(...) method, but if it returns an object that evaluates the lambda when its toString() is called then I don't think the logging code actually needs a special case.

[pedrolamarao]

This design's usability depends on injecting lazy with a static import. Doing this competes with everybody else who wants lazy, a critical term in computer science, to express their own API.

[mcompton13]

Yup, you would have to qualify the lazy(...) method with a class name if there was an existing lazy() method in scope.

But all my years of writing code I can't think of a case where I've written a method named lazy(...), other than mocking this proposed API. I've seen annotation classes called @Lazy, and even some normal Java classes with with Lazy in the name, but those are all capitalized and wouldn't conflict with a method name which are usually lowercase in Java.

So I think the only time it would be a problem is if I needed to delay execute some code in a logging statement and I had another method named lazy() in scope (and it would have to be a method in the current class I'm working in, or another method statically imported), both of which are uncommon occurrences in my own code. And all I have to do to fix it is fully qualify the SLF4J lazy() method with a class name. Not the end of the world, but others may disagree.

[jorisgeer]

I arrived here when searching in vain for support for an atLevel() call. I consider this the only really useful addition, others being more like syntactic convenience. Yet being able to specify the level as a parameter greatly reduces code clutter and code coverage requirements, as otherwise you end up wrapping 'if' statements around each log line. The traditional API does not have such option.
To summarize, if a fluent API brings such a runtime 'level' as parameter, then yes please.

[q3769]

why can you avoid the "if" guard with the atLevel() API? the only way you could completely make due without the level guard is when the message argument(s) is a Supplier lambda; otherwise, you would incur the cost of creating the log message object(s) if any. no?

[antme0]

I saw on the SLF4J website you are asking for opinions regarding a change to the fluent API. So here are my 2 cents worth. My preference would be something along the lines of:

        logger.msg("debug message {} {}","arg1","arg2").logDebug();
        logger.msg("Warning {}", "arg1").logWarn();
        logger.msg("error {}", "arg1").withCause(ex).logError();
        logger.msg("error").with("key",value).withCause(ex).logError();
        logger.msg("error {}, {}", "a", "b").withCause(ex).logDebug();
        logger.msg().withCause(ex).logError();

[pedrolamarao]

As discussed above, this requires constructing the "builder" before discovering that the level is disabled, which is poorly performant.

[antme0]

As discussed above, this requires constructing the "builder" before discovering that the level is disabled, which is poorly performant.

Ah yes, good point.

[pedrolamarao]

The fluent API is a very welcome addition!
In my opinion the proposed API is the most readable one.

I agree that a missing "commit" call is an important hazard.
In my opinion it will be enough to teach static analyzers to detect SLF4J fluent call chains with a missing "commit".
This should not be terribly difficult to do.
SLF4J is high profile enough that projects such as SpotBugs and PMD, and IDEs such as Intellij and Eclipse, shall certainly accept this PR.
Or maybe static analyzer plugins would be provided by the SLF4J project.

[ExE-Boss]

That can be achieved using a @CheckReturnValue annotation.

[j3graham]

I'm also a proponent of structured logging. One thought would be to apply idea of adding key/value pairs to the log message to regular text logs as well. With this in mind, perhaps there is no longer a need for the message template.

I think having short method names is important in an api that is likely to get used a lot. Also, I would find some value in using the same method names as flogger where the concepts overlap.

These thoughts lead to something like this as a proposal: (I'm not attached to the method names, as long as they are short )

        LoggingEventBuilder withCause(Throwable cause);
        LoggingEventBuilder marker(Marker marker);

        LoggingEventBuilder keyVal(String key, Object value);
        LoggingEventBuilder keyVal(String key, Supplier<Object> value);
        LoggingEventBuilder val(Object value);
        LoggingEventBuilder val(Supplier<Object> value);
       // maybe add some overloads to avoid auto-boxing overhead eventually...

        void log();
        void log(String message);

A call like this:

        logger.atDebug()
                .keyVal("room",room)
                .keyVal("oldTemp",oldTemp)
                .keyVal("newTemp",temp)
                .val( ()->getCurrentStats() )
                .log("Room temperature changed");

might result in something like this:

DEBUG: Room temperature changed - room='living room' oldTemp='21' newTemp='18' Stats[max=24.0, min=13.0, avg=20.1]

This has the attraction of removing the formatting details from each log message, and letting either the logger setup at instantiation, or the backend do it in a consistent manner. Also, it reduces the opportunities for mismatching placeholders and variables. I suspect the use of the arg calls to provide template parameters will be an extra challenge for static analysis tools.

With regard to the issue of the missing log call at the end, I think the addition of appropriate annotations would at least let existing tools warn you of the mistake.

[pedrolamarao]

This seems effectively the same as logging the "thread map".

[transentia]

I wonder if there is an appetite for the following...

I often find myself doing:

if (log.isDebugEnabled()) {
	log.debug("message => {}", field);
	log.debug("message2 => {}", field2);
	log.debug("message3 => {}", field3);
}

I like this 'cos it actually makes 3 formatted lines in the log.
I dislike it 'cos it means a lot of boilerplate typing...and--more importantly--it doesn't say "keep this stuff together"

PERHAPS the fluent API might be able to offer something like:

log.atDebug()
  .message("message => {}").arg(field)
  .message("message2 => {}").arg(field2)
  .message("message3 => {}").arg(field3);

again: 3 formatted lines created by a single logging operation...
might be a (teeny, tiny, trivially) bit more efficient?

[gavenkoa]

Logging each parameter per individual log statement is practice in its sunset. We enter the time of structured logging, your proposal covers legacy usage and might bloats API with something that doesn't have future.

[transentia]

I so look forward to you explaining that to the relevant team ;-)
...a VERY "conservative" bunch of public servants who are just itching to change what they have done for XXX years...and fully expect to do until retirement.
I'm still fighting to get them past the "stdout was always good enough for me" stage.

Anyway, I just "threw it out there" to see if it stuck (or if it sucked). Thanks for the response.

[transentia]

I just want to throw my hat in the ring for something like:

var theLevel = Level.DEBUG;

log.atLevel(theLevel)
  .log("message => {}").arg(field);

I know I am being lazy, but when starting in on a new block of code (or major change/discovery process)
I often find myself writing:

if (log.isErrorEnabled()) {
	log.error("message => {}", field);
	log.error("message2 => {}", field2);
	log.error("message3 => {}", field3);
}

This forces logging statements to appear, pretty much regardless of how logging is configured (I mean: no-one disables ERROR level, right...right?) Then, when I get nearer to proper code, I change my debugging:

if (log.isDebugEnabled()) {
	log.debug("message => {}", field);
	log.debug("message2 => {}", field2);
	log.debug("message3 => {}", field3);
}

Call me a weirdo or an API abuser if you must, but...I THINK my way of working boils down to: "when I'm 'in the groove' editing a bit of code, I'm happy to edit a variable in the source but I don't want to go off and edit (maybe make a new configuration in) a logback.xml (or whatever) file."

I see/accept the issue with changing levels at runtime...with this thought, I'm more focuseed on the typical compile-run-fail-change-repeat DEV lifecycle than how a runtime reconfiguration might play out.

[ExE-Boss]

I just want to throw my hat in the ring for something like:

var theLevel = Level.DEBUG;

log.atLevel(theLevel)
  .log("message => {}").arg(field);

That wouldn’t work as the log(…) method is a void method (so that the LoggingEventBuilder knows when all the arguments were added), because if your code was valid and correct, then the only way for it to work would either be a try‑with‑resources, or logging only when the LoggingEventBuilder is being garbage collected.

---

You therefore need to perform all your addArgument(…) calls before the log(…) call:

var theLevel = Level.DEBUG;

log.atLevel(theLevel)
	.addArgument(field)
	.log("message => {}");

Also, the atLevel(…) method is already supported:

slf4j/slf4j-api/src/main/java/org/slf4j/Logger.java

Lines 116 to 123 in ae032b1

	/**
	* A convenient alias for {@link #makeLoggingEventBuilder}.
	*
	* @since 2.0
	*/
	default public LoggingEventBuilder atLevel(Level level) {
	return makeLoggingEventBuilder(level);
	}

[Yaytay]

Reading all the comments and trying to think of what I want from slf4j:

• If the intention is to continue to support the existing API then adding a new API doesn't do anything to make the slf4j code simpler.
• slf4j has lacked "atLevel(debug)", that would be a nice addition and could reduce one multiplier on the current API.
• being able to log lambdas would be a reason for me to change (largely so I can objects as JSON via an ObjectMapper rather than toString).
• brevity in logging is more important to me as a user than the size of the API - I'd rather the writer of slf4j suffer verbose code than me :)
• adding in custom metadata at point of logging is very useful (particularly as we head towards log lines being output as json).

So I think my conclusion is that there are some benefits to the fluent API for me as a user (atLevel, lambdas, custom data that is not in the message), but that my message formatting is usually best served by log("{}", arg1).
So I think I'd end up with:

logger.atLevel(debug)
    .meta('thing', value)
    .meta('other-thing', otherValue)
    .log("Message: {}/{}", thirdValue, () -> fourthValue);

The .log method still taking a variable number of arguments (though I'd be happy with that being just one method with Object...).

[tbroyer]

Your suppliers are typed as such. If you tried to pass them "inline" to the method, chances are you'd have to explicitly type them with a cast.

Also, inside the methods, do you check (instanceof) each arg and always call suppliers? So if one has an object that happens to implement Supplier but you'd like its toString to be called, you'd have to take care of passing its toString as a supplier itself (myObj::toString), and of course that only "works" if the compiler can correctly infer the type of tht argument.

Fwiw, having an overload with Supplier... vararg is error prone and won't "work" in practice: have one argument that's not a supplier and you end up actually calling the Object... overload.

[ceki]

Your suppliers are typed as such. If you tried to pass them "inline" to the method, chances are
you'd have to explicitly type them with a cast.

@tbroyer This is not what I am observing. Can you please provide a counter example?

[tbroyer]

I took your code and simply inlined the lambdas:

        api.anArg(i0);
        api.anArg(() -> i0);
        api.manyArgs(i0, i1);
        api.manyArgs(() -> i0, () -> i0);
        api.manyArgs(i0, () -> i0);

This fails compilation:

API.java:16: error: no suitable method found for manyArgs(Integer,()->i0)
        api.manyArgs(i0, () -> i0);
           ^
    method API.manyArgs(Object...) is not applicable
      (varargs mismatch; Object is not a functional interface)
    method API.manyArgs(Supplier...) is not applicable
      (varargs mismatch; Integer cannot be converted to Supplier)
1 error

To make it compile, you have to explicitly cast the lambda to a Supplier:

        api.manyArgs(i0, (Supplier) () -> i0);

[tbroyer]

BTW, having Supplier overloads calls for IntSupplier, LongSupplier, DoubleSupplier and BooleanSupplier overloads as well, so given that you'd have to handle suppliers passed to the Object... overload anyway, you'd probably better only have Object on the API.

[ceki]

Mixing Objects and Suppliers in a varargs set up leads to compiler error as you mentioned or to the selection of the "Object..." variant.

Put differently, when both manyArgs(Object...) and manyArgs(Supplier...) methods are available, mixing Object and Supplier instances leads to ambiguity.

One option is to offer only an Object... method for passing the argument and disambiguate within the ma manyArgs(Object...) method itself.

ps. There will be no manyArgs method in the actual API. That name is used for the purposes of this discussion.

[ExOh2021]

So what's the actual initial outcome ?

…

On Tue, 7 Jun 2022, 7:41 pm Clément MATHIEU, ***@***.***> wrote: You pointed to ThreadContext (of Log4j 2) & MDC. At the moment I see thread local storage as a "broken" concept Yes, it doesn't play well with async. I mentioned MDC because with the current alpha API I ended up using it a few times as a workaround to the lack of being able to add several named attributes succinctly. It's trivial to write your own utility method that add multiple attributes to the MDC and clean them up using try-with-resource. By contrast, as a SLF4J user you cannot add this functionality to LoggingEventBuilder. Another major drawback of MDC is that those attributes will be added to all logging events until they are cleared. It is semantically very different from being able to pass a set of attributes to a some LoggingEventBuilders. I do agree that LoggingEventBuilder should provide such method (that's why I wrote my initial comment). — Reply to this email directly, view it on GitHub <#280 (reply in thread)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AS7LQCEOGW2L6ZYKBOBPD5LVN4KOJANCNFSM5SFYLD6A> . You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

[pedrolamarao]

I have just reread this discussion and found no mention of the following, that I think is worth keeping in mind: the log(String,Object...) style depends on varags, which cost the allocation of an array.

[mcompton13]

I was assuming that the log(...) API would still have non-vararg overrides that take fewer arguments that don't have the allocation problem, while still providing a varags option for flexibility/code clarity.

See:

slf4j/slf4j-api/src/main/java/org/slf4j/Logger.java

Line 166 in c0001d4

public void trace(String msg);

slf4j/slf4j-api/src/main/java/org/slf4j/Logger.java

Line 179 in c0001d4

public void trace(String format, Object arg);

slf4j/slf4j-api/src/main/java/org/slf4j/Logger.java

Line 193 in c0001d4

public void trace(String format, Object arg1, Object arg2);

slf4j/slf4j-api/src/main/java/org/slf4j/Logger.java

Line 209 in c0001d4

public void trace(String format, Object... arguments);

[pedrolamarao]

This defeats the purpose of designing an API to avoid the explosion of overloads.

[mcompton13]

Having overloads for two types of methods means there are still less than half as many methods vs the current API (there are overloads like I linked above for trace(...), debug(...), info(...), warn(...), and error(...)).

That being said, I'm perfectly happy if there's just one log(...) method and a static lazy(...) method to deal with lambdas, just like what Flogger does.

[Yaytay]

True, but that explosion of overloads is what makes it so convenient for the users, so is there a compromise that keeps it both manageable in the slf4j codebase and convenient for the users?
Removing the per-level methods is an easy move that has minimal impact on the users.
We don't need separate methods for lambdas, we just need a static method that takes a lambda and returns an object that has a toString that calls the lambda and then calls toString on the result.
What else needs to be done so that there is a single set of message formatting methods?

[pedrolamarao]

In my opinion, the "log(message,args)" style is not so superior to the log-builder style to justify creating a new anonymous object just to accomodate a lambda. The original style is still error-prone on the special "cause" argument, and still requires overloading on the "marker" argument. It is not superior. It is just familiar.

[xeus2001]

Our own logger works garbage free and looks like:

  import namespace.logger.*;

  msg("debug message {} {}", args().add("arg1").add("arg2"));
  warn("Warning {}", args().add("arg1");
  error("error {}", args().add("arg1").add(ex));
  error("error {}, {}", args().add("a").add("b").add(ex));
  error("", args().add(ex));

The static args() call returns a thread local instance that basically has two arrays, one for references and one for scalars and if the reference at index X is LONG, it reads the scalar as long, when it is DOUBLE it reads it as double aso.. This means that the invocation of the log method does only copy references or values into an array and updates the length.

All these methods are internally written like:

public static void error(String msg, WArgs args) {
 if (ERROR) {
   log("ERROR", msg, args);
 } 
}
private static void log(String type, String msg, WArgs args) {
}

When the logging of for example trace is disabled, the JIT eliminates the call to trace(...), except you start do somehow add strings or alike. The WArgs implementation does have an add method for any scalar type and alike. Simplified it looks like:

public class WArgs {
  private WArgs();
  private static final Object DOUBLE = new Object();
  private Object[] refs = new Object[64];
  private long[] scalar = new long[64];
  private int len = 0;

  public WArgs add(double value) {
    refs[length] = DOUBLE;
    scalar[length] = Double.doubleToRawLongBits(value);
    length++;
    return this;
  }
}

private static final ThreadLocal<WArgs> wargs = ThreadLocals.withInitial(WArgs::new);
public static WArgs args() {
  var args = wargs.get();
  args.length = 0;
  return args;
}

We have within the log method (should it be reached) some clever hacks to enable per log level for example stack traces and alike, as we know exactly that we have three method calls (code -> level() -> log()), we can use stack walker in java 9 and some internals via unsafe in java 8 to get the name and line number. You can enable and disable this per log or globally per level (e.g. args().addLine().addFile()), which will put the file and line to the front of the log line like com.foo.Bar:123 INFO ....

In fact, internally we only use JSON, there is much more, but I personally like the approach a lot. Feel free to think if you like this as well.

[pedrolamarao]

Garbage-wise, creating an args-accumulator and creating a log-builder should have the same cost.
In your design, there is no need for a commit-like operation at the end, which seems an advantage.
However, it does not seem very readable to add set-marker or put-key-value with this design.

[xeus2001]

IMHO key-value pairs are total over-engineering. We allow the marker as first argument, basically:

  public static void error(final Marker marker, final CharSequence text) {
    if (Type.ERROR.produce)
    _log(Type.ERROR, marker, text, null);
  }

  public static void error(final Marker marker, final CharSequence text, final WArgs args) {
    if (Type.ERROR.produce)
    _log(Type.ERROR, marker, text, args);
  }

  public static void log(final Type type, final Marker marker, final CharSequence text) {
    _log(type, marker, text, null);
  }

  public static void log(final Type type, final Marker marker, final CharSequence text, final WArgs arguments) {
    _log(type, marker, text, arguments);
  }

  private static void _log(
      final Type type,
      final Marker slf4j_marker,
      final CharSequence text,
      final WArgs arguments)
{
      if (!type.produce) {
        return;
      }
}

And usage for example:

info(Stream.get(), "Use OSM database: {}", args().add(osmDb.config.writeJdbcUrl()));

At least the last 10+ years this worked perfectly fine and was easy to learn. The only thing that sometimes happens, is that devs try to concat strings. However, you can't get the arguments wrong as they are clearly typed. The only thing I would change, is that I would rather add an explicit method to attach an exception (args().e(ex)), instead of rely upon that it is the last argument. So currently the logger reads all the placeholders {} and when the end is reached and another additional argument is there, which is an exception, it treats this special.

BTW: We use the marker to track requests, even between microservices, which all forward a request-id between them and we create a new marker for every incoming request. We keep the marker as thread local variable (the implementation of it), so we do have it available as context everywhere and we can in real time query the service to return which thread is currently processing which request and, when we send a request to another service, we forward the marker name (which is the tracking id).

Anyway, this is only my personal experience, I never ever missed anything from this.

[pedrolamarao]

A practiced engineer or technician, trained to achieve all their goals with a certain set of techniques, will never "miss" anything except by a powerful exercise of imagination. In modern computing, all our goals are achievable in principle by programming in any turing-complete language. We use higher level languages because they are easier, not more complete. New API designs are rarely about allowing new programs, they are usually about the same programs at a reduced cost.

[pedrolamarao]

There are many comments about how a static helper could be introduced, as used in Flogger, to allow lambda arguments with the old API. Seeing that there is precedence and interest, it may be valuable to fork this discussion and start a new thread to propose exactly this: extending the old API with a static helper to ease passing lambdas.

This thread is about the new builder-like API, which is an alternative to the old API, not a replacement. The point of the current discussion, as stated in the opening message, is to evaluate moving the set-argument, set-cause, set-marker, put-key-value etc. method calls to after the set-message call, with the purpose of improving readability and with the consequence of requiring a commit-like call at the end.

The case of the new builder-like API being unnecessary does not seem to be under discussion, and I think that would be a very difficult case to defend.

[benefg]

Hello,

I'd like to participate in the discussion with my two cents. I think with the new proposal is quite easy to forget to add the .log() and I'd try to avoid that situation. I'd expect that it writes something, even if it's not well formatted, but it writes something instead of doing nothing. I'd go for the proposal made by Adrian Shum in SLF4J-526 with lambda.

logger.atDebug(builder ->
        builder.message("Temperature of {} changed from {} to {}" )
        .arg(room).arg(oldTemp).arg(newTemp));

And taking the opportunity of the discussion, at the risk that what I'm going to propose was already discussed, I'd like to propose to avoid the parametrized messages in the fluent API in favor of less error prone sintax, leaving the parametrized messages for the traditional API. The proposal is to generate the message with the consecutive calls to the builder avoiding the error of diferent number of brakets and arguments. It would be something like:

logger.atInfo(builder -> builder.text("Temperature of ").value(room).text(" changed from ").value(oldTemp).text(" to ").value(newTemp));

In any case, I like the new fluent API and I'm looking forward to have a slf4j stable version including the API :)

Thanks!

[ExE-Boss]

One downside of your code is that it requires a capturing lambda, regardless of whether the log level is enabled.

[trandersen-ufst]

What is the problem with a capturing lambda? b-> b.. can be quite concise, and lambdas are not inherently slow.

[ExE-Boss]

A capturing lambda always allocates a new instance of the underlying hidden class, whereas a non‑capturing lambda becomes a singleton instance that’s returned using MethodHandles.constant(…), which has a fast‑path in the JIT.

[trandersen-ufst]

Why the atX() instead of just having the X() method without arguments return the appropriate builder?

logger.debug().message("{}: {}").args("Foo", "Bar");

[larrywest42]

Many thoughtful replies here. My personal take, as a long-time user and advocate of SLF4J 1.x who hasn't used 2.0 at all:

• I prefer the message-before-args approach. But then I never really took to Reverse Polish Notation calculators.
• All the devs I work with use an IDE so @CheckReturnValue, as ExE-Boss said, will mitigate the forgetfulness issue
  • should be a language feature IMHO
• I really really like briefer method names, like arg(a) and kv(k,v) or put(k,v): long names fill up the screen with no added value
• Have .message(), arg(), put() return an interface that doesn't allow .message() if they don't already
• Lambdas should be possible for all arguments (arg(a), put(k,v)), including the label
• like varargs a lot — it allows for easier wrapping of methods — but as someone pointed out, the cost of allocating the array should be made clearer, so if you were to have a varargs method, it should call that out, like: addArgumentArray()

My apologies if my ignorance has caused me to suggest things already in place, or already discarded.

[Yaytay]

(not in reply to @larrywest42)
If there is a chain of arg() method calls, what do you do with the arguments?
Somehow they need to be stored, and that's going to involve allocation - doesn't that negate benefits over varargs?

[larrywest42]

If the initial .atDebug() or .debug() or .at(level) method determines the level is not reached, subsequent calls to .arg() do nothing at all with the arguments, so nothing is allocated.

As is done with Logger.atLevel() now, via NOPLoggingEventBuilder.

[pedrolamarao]

Also, the memory allocated for varargs cannot be reused by an implementation which accumulates arguments, so it is wasted even in that case.

[flemingadam]

Can you not use the builder to allow both? The general idea is that you always end with a log method but allow the message and arguments to be built in the order desired by the caller.

This would utilize varargs for some of the methods, but I would think that to be acceptable as long as the JavaDoc states that this will incur a performance penalty for those methods.

All of the following would be ways to build the same thing:

logger.debug()
	.message("Temperature of {} changed from {} to {}" )
	.arg(room).arg(oldTemp).arg(newTemp)
	.log();

logger.debug()
	.arg(room).arg(oldTemp).arg(newTemp)
	.message("Temperature of {} changed from {} to {}" )
	.log();
	
logger.debug()
	.arg(room).arg(oldTemp).arg(newTemp)
	.log("Temperature of {} changed from {} to {}");

logger.debug()
	.log("Temperature of {} changed from {} to {}", room, oldTemp, newTemp);

logger.debug()
	.message("Temperature of {} changed from {} to {}" )
	.log(room, oldTemp, newTemp);

One other note, the message method should return an object that only allows arguments to be set and prevent the message from being overwritten. This would remove the potential ambiguity of whether the first argument in log is a message or argument:

logger.debug()
	.message("Temperature of {} changed from {} to {}" )
	.log("bedroom", oldTemp, newTemp);

[pedrolamarao]

Varags based on Object cannot distinguish arguments which are in fact supplier-like lambdas. Offering argument setters allow supporting both Object and Supplier arguments without the need for a large number of log method overloads.

[xzel23]

Sorry, I am late to the party. I don't really see a big benefit in having a fluent API here. What I need in formatting can easily be achieved by passing a lambda like () -> String.format("Temperature of %s changed from %s to %s", room, oldTemp, newTemp)to the logger. The problem that lambda parameters have to be effectively final can be circumvented by a one line utility method. In case you don't like the standard string formatting, any other formatter can be used.

If you want to use a fluent API: since message and arguments IMHO belong together, why not just pull both together like message(String fmt, Object... args) and have different methods for supplying a throwable or markers?

But I really have no strong feelings about the fluent API. But I think that this and other things should be settled rather sooner than later because SLF4J really needs a stable version properly supporting jigsaw modules. At least for me, that is currently the biggest problem with SLF4J.

[pedrolamarao]

Building the message first and pushing it to the logger later requires building the message invariably, no matter if the logger is enabled or not.

[matt-w-au]

This concepts outlined about are explicitly around deferral of message building rather than preemptively building it so it sounds as though the comment is missing that aspect - if the builder implemented an interface such as Supplier then the call to .get() or similar would result in the message being built only when relevant (hence why it doesn't have the equivalent of a final log() as in the original examples as that would be conditionally invoked). Prior to that message construction any object would largely just be a container for references which would have a far lower cost than building the message but still a non-zero cost if it resulted in unnecessary instantiation and subsequent GCing.

[pedrolamarao]

The builder needs to be allocated, needs to accumulate arguments and do whatever other bookeeping it needs to do, even for disabled loggers. Both designs for the fluent API proposed in the opening comment of this discussion preserve the desirable property of doing nothing in case the logger is disabled.

[matt-w-au]

Yes, that sounds largely accurate and aligns with the repeated sentiment that there may be non-zero additional costs but the more substantial costs of message construction would be avoided. The suggested argument accumulation and bookkeeping seem leading in terms of practicality - as a base line for establishing costs there could be a reused no-op builder (which simply ignored its arguments) which provides a counter-example to any implied work. Such an object in isolation that consistently does nothing is unlikely to offer utility but it's not unreasonable to think of constructing such an object based on the current logger value or utilizing a factory method which produced builders for different levels where the inactive levels were no-ops (therefore likely mirroring the fluent API behavior in a more awkward but more obviously extensible form).

The intent here is not to advocate that design but simply to try to unearth the specific points where practical costs arise and also recognize that while many use cases need to aggressively minimize costs other use cases may be be better off incurring some controlled costs to provide a less likely to be misused interface. In practice I have very often encountered lines such as:

logger.debug("my data is {}", foo.serializeInSomeCostlyWayOrDoOtherUnfortunateCalculation());

where the highly cost-effective API inadvertently introduces higher costs at the call site. In areas where logging costs are not a practical concern (or are not a hill worth dying on) it may be far easier to uniformly push for an interface that makes use of a capturing lambda or a custom builder as suggested here (where the underlying premise is that the same signature enables both).

Identifying the specific tradeoffs of different approaches and how they map on to different contexts can facilitate keeping a wider range of users out of trouble while still avoiding unnecessary costs for those cases where it is desired.

[pedrolamarao]

In the new fluent API, the case you quote will be optimizable by passing the calculation as a lambda object, which will never be called for a disabled logger.

In the original design for the fluent API:

logger.atDebug().addArgument(foo::serializeInSomeCostlyWayOrDoOtherUnfortunateCalculation).log("my data is {}");

In the proposed design for the fluent API:

logger.atDebug().message("my data is {}").arg(foo::serializeInSomeCostlyWayOrDoOtherUnfortunateCalculation).log();

There are those who would love for the old API to be improved to better support lambdas. As has been pointed out before, Flogger offers a lazy static method which applications may use to adapt a lambda object, something like this:

logger.debug("my data is {}", lazy(foo::serializeInSomeCostlyWayOrDoOtherUnfortunateCalculation));

This merits a separate discussion.

[meganalnico]

I've probably missed this discussion somewhere but, are lambdas performant enough to use them for logging?

// structured logging of key-value pairs
logger.info(msg -> msg.put("old",10).put("new",12));

// string formatted logging
logger.info("Temperature of {} changed from {} to {}", msg ->  msg.arg(room).arg(oldTemp).arg(newTemp));

// naive implementation, you can proabably defer the FluentApiBuilder creation until you actually need it. 
public void info(Consumer<FluentApiBuilder> logIt){
    FluentApiBuilder builder = new FluentApiBuilder();
    logit.accept(builder); 
    // or defer .build()/.log() until later
    logBuilder(Level.INFO, builder.build()));
} 

public void info(String template, Consumer<FluentApiBuilder> logIt){
    FluentApiBuilder builder = new FluentApiBuilder(template);
    logit.accept(builder); 
    // or defer .build()/.log() until later
    logBuilder(Level.INFO, builder.build()));
} 

The msg -> part is kinda ugly but you can never forget to call log().

[matt-w-au]

I think that's covered at length in the previous thread; in most cases that is likely performant enough. It probably falls somewhere along the standard lines that the overhead is acceptable for the 80% of code that handles 20% of the work but may not be for the 20% of the code that does the 80% of the work.

[meganalnico]

Thanks. I missed the previous thread. I stumbled on this one because I want to do structured logging at the individual message level. MDC is very verbose for one log line.

[pedrolamarao]

The new fluent API will allow you to do what want, something like this:

logger.atDebug().put("key","value").log();

If debug is disabled, atDebug will return a special no-op log builder and the optimizer will be able to elide the calls to put and log.

[jreznot]

SLF4J may define a Java annotation @CheckReturnValue and annotate all intermediate methods with it. Then IntelliJ IDEA will highlight any calls where log() is missing. IntelliJ IDEA supports any annotations with CheckReturnValue name, IDE detects them by name no matter where they are defined. No additional dependencies required.

This annotation is also supported by many static analysis tools, so definitely will help not to miss the log() call at the end.

[ceki]

Brilliant. Thank you Vladimir.

[ceki]

Added in commits 0dcfa19 and 4e4e56a to be included in version 2.0.0-beta1 to be released shortly.

[sysmat]

Please update the documentation to match:

• on https://www.slf4j.org/manual.html you have:

SINCE 2.0.0 SLF4J API version 2.0.0 requires Java 8 and introduces a backward-compatible fluent logging API. By backward-compatible, we mean that existing logging frameworks do not have to be changed in order for the user to benefit from the fluent logging API.

• on github page https://github.com/qos-ch/slf4j you have:

All versions upto and including 1.7.x require Java 5 or later to build. SLF4J version 2.0.x requires Java 9 or later.

[sysmat]

Do you have a change log, it is one of a basic concepts of software development

[tbroyer]

Build and use are different things.

[q3769]

The API methods can be categorized in Intermediate and Terminal operations, similar to jdk Stream API.

Intermediate ops would be e.g. the Logger.atXXX() methods. Terminal ones would be the Logger.log(....) methods.

Agreed that the no-arg Logger.log() method is not the most user-friendly or error-resisting. Rather, it'd be nicer to have/keep Terminal ops such as:

• Logger.log(String message)
• Logger.log(String message, Object... args)
• Logger.log(Throwable t, String message)
• Logger.log(Throwable t, String message, Object... args)
• etc...

which means removing the Intermediate APIs such .setMessage(...), .setCause(Throwable t), .... because those, as Intermediate ops, are confusing if the Logger.log(....) methods are now Terminal ones.

The other proposed Intermediate ops APIs are nice.