Not able to use slf4j-backend

[PascalSchumacher]

Using these dependencies:

<dependency>
    <groupId>com.google.flogger</groupId>
    <artifactId>flogger</artifactId>
    <version>0.4</version>
</dependency>
<dependency>
    <groupId>com.google.flogger</groupId>
    <artifactId>flogger-slf4j-backend</artifactId>
    <version>0.4</version>
</dependency>
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.2.2</version>
</dependency>

should be enough if I understand https://github.com/google/flogger#how-to-use-flogger correctly.

But this test:

public class FloggerTest {

    private static final FluentLogger log = FluentLogger.forEnclosingClass();

    @Test
    public void test() {
        log.atWarning().log("Test: %s", "message");
    }
}

fails with:

java.lang.ExceptionInInitializerError
	at com.google.common.flogger.backend.Platform.getCallerFinder(Platform.java:142)
	at com.google.common.flogger.FluentLogger.forEnclosingClass(FluentLogger.java:70)
	at test.FloggerTest.<clinit>(FloggerTest.java:10)
Caused by: java.lang.IllegalStateException: No logging platforms found:
com.google.common.flogger.backend.system.DefaultPlatform: java.lang.ClassNotFoundException: com.google.common.flogger.backend.system.DefaultPlatform
	at com.google.common.flogger.backend.Platform$LazyHolder.loadFirstAvailablePlatform(Platform.java:99)
	at com.google.common.flogger.backend.Platform$LazyHolder.<clinit>(Platform.java:67)
	... 25 more

According to https://github.com/google/flogger/blob/master/log4j/src/main/java/com/google/common/flogger/backend/log4j/Log4jBackendFactory.java#L30 you have to set the flogger.backend_factory system property, so I started Java with -Dflogger.backend_factory=com.google.common.flogger.backend.slf4j.Slf4jBackendFactory#getInstance, but this resulted in the same exception.

What am I missing?

(the whole project can be found at: https://github.com/PascalSchumacher/flogger-slf4j-test)

[cslee00]

The SLF4J back-end would require a dependency on slf4j-api, that may be the ExceptionInInitializer error being unable to find required classes.

[PascalSchumacher]

slf4-api is present see:

[INFO] --- maven-dependency-plugin:2.8:tree (default-cli) @ flogger-slf4j-test ---
[INFO] test:flogger-slf4j-test:jar:0.0.1-SNAPSHOT
[INFO] +- com.google.flogger:flogger:jar:0.4:compile
[INFO] |  \- com.google.code.findbugs:jsr305:jar:3.0.1:compile
[INFO] +- com.google.flogger:flogger-slf4j-backend:jar:0.4:compile
[INFO] |  \- org.slf4j:slf4j-api:jar:1.7.14:compile
[INFO] +- ch.qos.logback:logback-classic:jar:1.2.2:compile
[INFO] |  \- ch.qos.logback:logback-core:jar:1.2.2:compile
[INFO] \- junit:junit:jar:4.12:test
[INFO]    \- org.hamcrest:hamcrest-core:jar:1.3:test

But I was missing the flogger-system-backend. I thought it would not be necessary when not using system (java.util.logging/android) logging.

Thanks for your help and sorry.

[cslee00]

Yea, that would do it. No worries.

The README documents this requirement:

All code that uses flogger should depend on com.google.flogger:flogger: and com.google.flogger:flogger-system-backend:.

Note: the dependency on flogger-system-backend is only required to be included when the binary is run. If you have a modularized build, you can include this dependency by the root module that builds your app/binary, and can be runtime scope.

[cslee00]

Looking at this further; wondering why flogger-slf4j-backend doesn't transitively pull in flogger-system-backend. Note the problem isn't limited to slf4j backend, log4j backend has the same behaviour.

This set of Gradle dependencies:

compile group: 'com.google.flogger', name: 'flogger', version: '0.4'
runtime group: 'com.google.flogger', name: 'flogger-slf4j-backend', version: '0.4'

Fails with:

java.lang.ExceptionInInitializerError
	at com.google.common.flogger.backend.Platform.getCallerFinder(Platform.java:142)
	at com.google.common.flogger.FluentLogger.forEnclosingClass(FluentLogger.java:70)
	at digitalascent.flogger.<clinit>(flogger.java:7)
Caused by: java.lang.IllegalStateException: No logging platforms found:
com.google.common.flogger.backend.system.DefaultPlatform: java.lang.ClassNotFoundException: com.google.common.flogger.backend.system.DefaultPlatform
	at com.google.common.flogger.backend.Platform$LazyHolder.loadFirstAvailablePlatform(Platform.java:99)
	at com.google.common.flogger.backend.Platform$LazyHolder.<clinit>(Platform.java:67)
	... 3 more

...due to missing flogger-system-backend classes. Adding flogger-system-backend corrects it, though that shouldn't be required.

Resolved dependency tree:

runtimeClasspath - Runtime classpath of source set 'main'.
+--- com.google.flogger:flogger:0.4
|    \--- com.google.code.findbugs:jsr305:3.0.1
\--- com.google.flogger:flogger-slf4j-backend:0.4
     +--- com.google.flogger:flogger:0.4 (*)
     \--- org.slf4j:slf4j-api:1.7.14

and for log4j backend:

runtimeClasspath - Runtime classpath of source set 'main'.
+--- com.google.flogger:flogger:0.4
|    \--- com.google.code.findbugs:jsr305:3.0.1
\--- com.google.flogger:flogger-log4j-backend:0.4
     +--- com.google.flogger:flogger:0.4 (*)
     +--- com.google.code.findbugs:jsr305:3.0.1
     \--- log4j:log4j:1.2.15
          +--- javax.mail:mail:1.4
          |    \--- javax.activation:activation:1.1
          +--- javax.jms:jms:1.1
          +--- com.sun.jdmk:jmxtools:1.2.1
          \--- com.sun.jmx:jmxri:1.2.1

Neither include flogger-system-backend as a transitive dependency.

Looks like flogger-system-backend should be included in published POM as a transitive dependency for flogger-slf4j-backend and flogger-log4j-backend. Documentation could be updated to state that one (and only one) back-end implementation is required; flogger-system-backend for JUL, flogger-log4j-backend for Log4J, flogger-slf4j-backend for SLF4J.

[hagbard]

Hmm, yes, this is all a bit unsatisfying at the moment (you can tell I'm a total noob at Maven stuff).

It'd be ideal if the current default backed was split, so any JDK specific code isn't strictly necessary when doing a custom backend. I'm afraid however that I am very unlikely to have time to do this in the near future. The reason for the current split is all a bit historical, so it might be possible to revisit (perhaps just moving the backend API classes into the main artifact). However I have the nagging suspicion some will need to move packages if we split that way, so it might not be trivial.

While I have your attention though, would you expect/want the formatting code to be shared (SimpleFormatter) or is it something each backend would have its own version of (given that you can have backends that log without formatting). Of should formatting be yet another dependency for those that want it? (it feels like it's in danger of getting a bit fine grained if we start down that road though).

I will ask Ron (the ever so wonderful keeper of the POM files) to do whatever's necessary to fix the deps for now, and I promise to come back to this as soon as I can.

[cslee00]

Thanks for having a look at this!

Was looking at SimpleFormatter for a different use case (JSON log output from back-end); observations:

1. Having message formatting for parameters is part of the API; when a user says "message %s" they expect a certain message to come out, regardless of the back end. All the context around that message - logger name, thread name, timestamp, etc - are back-end specific, the formatted message is one more field for the back-end to output however it sees fit. The back-end either uses SimpleFormatter to get a standard formatted message, or takes the raw data and displays it in a structured format (e.g. JSON - even then the formatted message is generally what is desired). It would be surprising - and likely a breakage of the implied API - to say have '%3.2f' be displayed in a way inconsistent with java.util.Formatter specifications. IMO, if there's a desire for other types of structured output the API needs to support that - currently "this is %s message %3.2f" is a string-formatting exercise; if those parameters are desired to be part of a structured data output then they should be provided as some form of metadata.
2. SimpleFormatter append metadata to the formatted message, not providing a separation between the message/parameters and metadata (which one may wish to output differently). In the case of JSON, metadata make nice attributes. Currently have to hack around this to resuse the printf-formatting from SimpleFormatter w/o the metadata appended.

IMO, SimpleFormatter should be shared such that message formatting is consistent between back-ends (without differences that are surprising to consumers of the Flogger API or deviate from what java.util.Formatter specifies). Displaying contextual information, such as metadata, should be separated out and left to the back-end to display in an appropriate manner.

On the topic of splitting the back-end: one area that could use some work is AbstractLogger, specifically the dependency on java.util.logging. Both the direct one (at(java.util.logging.Level level)) and conceptual one (atSevere and friends). Those dependencies pose a challenge (mostly conceptual) for development teams used to other logging frameworks where the log-level-paradigm is different (trace,debug,info,warn,error and perhaps fatal). While it's currently possible to subclass AbstractLogger and add 'atError' that's not great - the API surface area still includes java.util.logging.Level and atSevere() etc. Started something here to address this, not totally there yet (feels like a workaround still): https://github.com/cslee00/digitalascent-fluent-logger. The goal being to reduce the conceptual-shift for adopting flogger (fluent API & performance: good; changing log level names: bad).

[hagbard]

The issue is that there are those who use custom log levels, so it's hard to accommodate them without something that just ends up using the "value" of the level. It's also very difficult to make different loggers have a different idea of what "log level" means without breaking the compatibility with backends (the aim is that any logger can work easily with any backend, and "what a level is" has to have a single meaning across both sides. Every Java implementation should have "Level" present, and it's as good as anything as regards defining a threshold value. I think that, realistically, Level is here to stay, but you're welcome to define custom levels (but be aware that not all backends will understand their semantics).

The atFoo() methods are part of Flogger. Since Flogger is replacing upwards of 50 other logging APIs in Google (over many millions of lines of code), we decided not to "play favourites" with whichever log level semantics people preferred, and went with the default JDK levels (for better and worse). If you can't live with a logger that uses these level definitions at its heart, I'd suggest not using Flogger at all.

The formatting is defined to be ~100% (*) compatible with JDK printf, since that's another API that must always remain stable between loggers and backends (anything used on both sides must be stable). I agree that the SimpleMessageFormatter isn't ideal at the moment, feel free to suggest modifications to split metadata out (metadata formatting is one of the least satisfying things about the JDK backend behaviour at the moment).

• • tiny differences in error handling and pathological cases exist, but they really won't matter in the real world.

[Maaartinus]

"what a level is" has to have a single meaning across both sides

This would be nice, but with code from different frameworks, it's impossible. Especially, when the number of levels differ, like with JUL and SLF4J. Some mapping is necessary, which may be lossy like this one.

That said, I believe your choice was right. People used to different logging levels need to re-learn the levels or write an own version of FluentLogger, which should be pretty easy (assuming findLoggingClass is accessible), and do the mapping there. I guess, most frameworks (including SLF4J) have no more levels than JUL, so that's fine.

[hagbard]

For better or worse, you can mimic everything that SLF4J does using JUL Level, but not the other way round (because of custom levels). We went with the most flexible level scheme.

We had a bit of "push back" from people when switching back to JUL Levels, but overall having a single unified idea of what a log level is that works over all our code and having a single idea of how to control log levels during debugging far outweighs the slightly "old fashioned" level naming convention.

[ronshapiro]

Let's reserve this issue just for the issue of the artifact not being correctly configured in Maven. Anything related to slf4j/JUL/flogger should have it's own issue.

[automenta]

anatomy of a configuration headache i ended up putting this overriding class in com.google.common.flogger.backend.system

public final class SimpleBackendFactory extends BackendFactory { private static final BackendFactory INSTANCE = Slf4jBackendFactory.getInstance();

public static BackendFactory getInstance() { return INSTANCE; }

[robinp-tw]

For those wondering why their flogger logging works seemingly through slf4j, even if they didn't add that backend_factory system property - probably jul-to-slf4j is pulled in somehow (hinted by https://stackoverflow.com/a/41592332), for example by spring-boot-starter-logging.

So flogger still logs to JUL, but then that gets routed to slf4j due to jul-to-slf4j and all is dandy.

I wonder if the flogger-slf4j-backend might be just dropped in favor of using jul-to-slf4j explicitly? Since with the currently involved setup, I doubt many people get using the slf4j backend right (especially that the main README doesn't mention needing to set the backend_factory property).

[hagbard]

Sadly I just don't have time or experience with them to maintain the non-JDK backends. I'm happy for contributions to improve the configuration and usability (even if just to the README files).

[robinp-tw]

No problem. I might attempt a README PR to clarify the situation.

Actually, a litmus-test if you are using flogger through slf4j or the jul-to-slf4j mapping: Do

logger.atFiner().log("This is FINEr");

and see if it is logged at DEBUG (jul-to-slf4j) or TRACE (flogger-slf4j-backend).