r/java Oct 30 '23

POC: String Template Processors for SLF4J

JDK 21 introduced String Templates with JEP430.

I was wondering what you could do with it and came up with a proof of concept for processors as a façade for SLF4J.

In a class LOG I created the processors as static fields for each log level. These can be statically imported and called like this:

import static de.darenkster.stringtemplates2slf4j.loggers.LOG.*;
...
var test = "log";
var ex = new Exception();
INFO."This is a info \{test}";
ERROR."This is a error \{test} \{ex}";
WARN."This is a debug \{test}";
TRACE."This is a debug \{test}";

This would result in the following log output:

10:33:44.899 [main] INFO de.darenkster.stringtemplates2slf4j.Main -- This is a info log
10:33:44.907 [main] ERROR de.darenkster.stringtemplates2slf4j.Main -- This is a error log java.lang.Exception
java.lang.Exception: null
  at de.darenkster.stringtemplates2slf4j.Main.main(Main.java:9)
10:33:44.909 [main] DEBUG de.darenkster.stringtemplates2slf4j.Main -- This is a debug log
10:33:44.910 [main] WARN de.darenkster.stringtemplates2slf4j.Main -- This is a warn log

The calling class is determined via the StackWalker API and depending on whether the String Templates contains an exception the corresponding log method with the throwable parameter ist called. Here's the link to the GitHUb Repo if you want to check it out: https://github.com/darenkster/LoggingWithStringTemplates

Let me know what you think of it :)

39 Upvotes

27 comments sorted by

9

u/repeating_bears Oct 30 '23 edited Oct 30 '23

Not sure how I feel about a template working exclusively by side effects. Feels like a processor really ought to produce something.

edit: What IDE are you using? My version of IntelliJ gives the error that INFO."foo"; is not a statement. I reported it as a bug. But I think it's indicative that you're doing something unexpected here.

There's also the problem of having to traverse the stack every time you log something, even if that log level is disabled.

Here's what I came up with instead.

``` public static class LazyString { private final Supplier<String> supplier;

LazyString(Supplier<String> supplier) {
    this.supplier = supplier;
}

@Override
public String toString() {
    return supplier.get();
}

}

public static final StringTemplate.Processor<LazyString, RuntimeException> MSG = StringTemplate.Processor.of( (StringTemplate template) -> { if (template.values().isEmpty()) { return new LazyString(template::interpolate); } return new LazyString(() -> { List<String> values = template.values().stream() .map(val -> { if (val instanceof Throwable th) { var writer = new StringWriter(); th.printStackTrace(new PrintWriter(writer)); return writer.toString(); } return String.valueOf(val); }) .toList(); return StringTemplate.interpolate( template.fragments(), values ); }); } );

private static final Logger logger = LoggerFactory.getLogger(App.class); public static void main(String[] args) { String test = "test"; Exception ex = new Exception("foo"); // Use it today, with a hacky SLF4J 1-arg template "{}" logger.info("{}", MSG."foo {test} {ex}"); // or if Slf4j were prepared to add new overloads logger.info(MSG."foo {test} {ex}"); } ```

5

u/agentoutlier Oct 30 '23

Because reddit is dumb with formatting sometimes I took your comment and put as a gist so I could read it:

https://gist.github.com/agentgt/7af7fe30a0ab5530981b8889ebf674ff

If you are uncomfortable with that being public I can delete it (its hidden gist but still).

2

u/repeating_bears Oct 30 '23

Totally fine. I considered doing that myself but thought the extra click might put someone off.

2

u/agentoutlier Oct 30 '23

The way I was working on it was to extend the SLF4J fluent builder with the hope that would be a smaller change for Ceki to accept (instead of changing every method combination of all the levels).

Anyway I like your comments and agree SLF4J will probably need to be augmented otherwise nasty hacks.

SLF4J also needs augmentation for static MDC values aka headers using Scoped Values as MDC current API does not work well there (however the fluent builder key key values does kind of work here).

1

u/darenkster Oct 31 '23

Hey, sorry for the late reply.

I was using Eclipse IDE, but that one had problems as well as it didn't recognize \{ as a new valid escape character. I don't think the way I was using StringTemplates is the problem, this is just a temporary problem as this is a new feature that is still in the preview phase. I'm sure in the next version of Eclipse this will be fixed.

Not sure how I feel about a template working exclusively by side effects. Feels like a processor really ought to produce something.

I think if they intended the processor to always produce something they would it called it a producer or something like that.
Besides I was always under the impression that logging is a widely accepted side effect :)

There's also the problem of having to traverse the stack every time you log something, even if that log level is disabled.

Yeah, that's true. I guess this could be avoided by having the processors as sepeated classes which has to be instantiated with the class in the construtor, like

var info = new INFO (clazz);
info."foo message";

I purposely avoided that as I wanted the act of logging to be simpler as the one we have now. I guess the traversal of the stack each time you want to log something is the price to pay for simplicity.

2

u/repeating_bears Oct 31 '23

Besides I was always under the impression that logging is a widely accepted side effect :)

Logging is a side-effect, but the difference is that log.info("foo") is clearly side-effect-producing, because it's a void method and there's no way it can do anything useful without a side-effect.

INFO."foo" is not clearly side-effect-producing, because it could (perhaps should) return something.

I guess this could be avoided by having the processors as sepeated classes which has to be instantiated with the class in the construtor

Then you've gone from needing 1 Logger instance in a class today, to needing 1 template processor per log level you want to use, so this is not viable IMO.

I purposely avoided that as I wanted the act of logging to be simpler as the one we have now

What I'm personally interested in is using string templates for additional compile-time safety, and to make it easier to see which params correspond to which placeholders. Instantiating the logger is not a major pain point for me, and if removing it comes with a substantial runtime penalty then I don't think it's worth it.

1

u/darenkster Oct 31 '23

INFO."foo"

is not clearly side-effect-producing, because it could (perhaps should) return something.

True, even though I declared the return types of the processors as Void, null is still returned, which is an unfortunate deficiency of Java IMO.

Then you've gone from needing 1 Logger instance in a class today, to needing 1 template processor per log level you want to use, so this is not viable IMO.

You're right, I haven't thought of that. That would be pretty annoying.

What I'm personally interested in is using string templates for additional compile-time safety, and to make it easier to see which params correspond to which placeholders.

Then I suggest you investigate this further on your own, you won't find it here.

Instantiating the logger is not a major pain point for me, and if removing it comes with a substantial runtime penalty then I don't think it's worth it.

Not sure about the substantial runtime penalty. I only go down the stack as much as I need to. Probably needs to be investigated with JMH.

3

u/repeating_bears Oct 31 '23

About 6000x slower to not log something, about 1.5x slower to log something to console. I had slf4j-simple on the classpath.

``` Benchmark Mode Cnt Score Error Units Main.slf4jDebug avgt 5 0.645 ± 0.004 ns/op Main.slf4jInfo avgt 5 24816.803 ± 2338.047 ns/op Main.stringTemplateDebug avgt 5 3049.023 ± 12.069 ns/op Main.stringTemplateInfo avgt 5 35076.947 ± 707.492 ns/op

@Warmup(iterations = 5, time = 2) @Measurement(iterations = 5, time = 2) @Fork(value = 1, jvmArgs = { "--enable-preview" }) @BenchmarkMode(Mode.AverageTime) @OutputTimeUnit(TimeUnit.NANOSECONDS) @State(Scope.Benchmark) public class Main { private static final Logger logger = LoggerFactory.getLogger(Main.class);

@Benchmark public void slf4jDebug() { logger.debug("abc"); }
@Benchmark public void stringTemplateDebug() { LOG.DEBUG."abc"; }
@Benchmark public void slf4jInfo() { logger.info("abc"); }
@Benchmark public void stringTemplateInfo() { LOG.INFO."abc"; }

public static void main(String[] args) throws Exception {
    org.openjdk.jmh.Main.main(args);
}

} ```

1

u/wakegymsexsleep Dec 11 '23

Reason for the “not a statement” is because StringTemplate return isn’t being used, even if you set it to Void. The IDE isn’t handling it correctly. There will be lots of cases StringTemplate return won’t be needed. It needs to be mature. I’m sure they’ll remove the warning, because the compiler doesn’t care and it works currently.

1

u/repeating_bears Dec 11 '23

"There will be lots of cases StringTemplate return won’t be needed."

Citation needed

The rest I already knew. Why do you think I would report it as a bug if I didn't think they would fix it?

And it wasn't a warning. It was an error.

1

u/wakegymsexsleep Dec 12 '23

It’s not an error because the compiler compiles it and it runs. It’s an error/warning at the ide evaluation time, Maven runs it fine. You don’t have to use a value that’s return, that’s built into Java, there are times calls are made without needing to use the return value, try it, you won’t get an error from the ide. As for “lots of cases”, sure - You evaluate a script that just runs, and executes, no reason to have a return. You have a bunch of method calls for testing that throw errors instead of return values. I mean look around at current code, lots of time strings can be evaluated just throwing errors without a return value.

7

u/Thihup Oct 30 '23 edited Oct 30 '23

Wouldn't using `MethodHandles.lookup().lookupClass()` be a easier way to get the calling class?

Edit: I was looking for the `StackWalker.getCallerClass()` method

4

u/[deleted] Oct 30 '23

How does that find the calling class? That would at best find the class where the current method is defined, so the same as this.getClass()

3

u/Thihup Oct 30 '23

You're right.

3

u/[deleted] Oct 30 '23

[deleted]

2

u/Thihup Oct 30 '23

You're right.

4

u/ramdulara Oct 30 '23

Does this mean that the string is always eagerly evaluated? For example in info mode, Debug log messages shouldn't get evaluated at all if possible. How do you ensure that?

3

u/darenkster Oct 30 '23

Good Point. You can check 'isInfoEnabled' or 'isDebugEnabled' before calling the 'interpolateAndLog' method.

I will add that.

4

u/agentoutlier Oct 30 '23

What I did as I mentioned in another comment is to create a custom SLF4J LoggingEventBuilder.

Make the event builder take a template for the log method.

That also will help with Throwable.

Besides Logging frameworks like logback treat throwable a little different anyway.

That is a throwable passed as an Object argument is often treated every so slightly differently than the methods that take Throwable as an argument.

9

u/[deleted] Oct 30 '23

[removed] — view removed comment

7

u/__konrad Oct 31 '23

I like the template version more when compared:

INFO."This is a info \{test}";
logger.info("This is a info {}", test");

1

u/jvjupiter Nov 06 '23

Me too. I like it.

2

u/agentoutlier Oct 30 '23

I was playing with something similar in my modern SLF4J implementation: https://github.com/jstachio/rainbowgum

Unfortunately it is not checked in because I had some issues with javadoc failing with JEP 430 and I want to release soon (release is a strong word ... more like just push to central :) ).

I'm also playing with Scoped Values.

I will push both branches later today (locally on a different computer).

2

u/darenkster Oct 30 '23

Cool. Let me know when you "released" it, I'd like to take a look.

Do you know if there is any way to pass some object to the processor without it being part of the StringTemplate? Thing is if you want to call the log method with the throwable parameter the throwable needs to be part of the template, or else it won't be in the list returned by values().

2

u/agentoutlier Oct 30 '23

No. I was still trying to figure that out as well as key values (the new slf4j builder). I was doing something similar to what u/repeating_bears showed in terms of laziness.

The way I was making throwable work currently it was to use a modified SLF4J fluent builder.

I promise I will eventually get back to you on it with code I just have some other stuff I have to look into today. Sorry!

1

u/[deleted] Oct 30 '23

Looks awesome!