Don't log to `stderr` when `slf4j.provider` is used.

[garretwilson]

I didn't realize SLF4J-450 was already implemented, so I was excited to look into this. Thanks for the work on this, @ceki and @KengoTODA.

In the source code I see:

    static SLF4JServiceProvider loadExplicitlySpecified(ClassLoader classLoader) {
        String explicitlySpecified = System.getProperty(PROVIDER_PROPERTY_KEY);
        if (null == explicitlySpecified || explicitlySpecified.isEmpty()) {
            return null;
        }
        try {
            String message = String.format("Attempting to load provider \"%s\" specified via \"%s\" system property", explicitlySpecified, PROVIDER_PROPERTY_KEY);
            Util.report(message);
…

Unfortunately this logs a message to stderr every time we use the slf4j.provider property. I don't quite understand the point of that. Logging something to stderr outside of the normal SLF4J logging system should only be done as a last resort, if there is some unexpected error. For example, if no logger implementation is present, SLF4J indicates, "No SLF4J providers were found.". The point here is that the user should be warned if they inadvertently don't include a logging implementation. (I'm not sure I fully agree with that decision, but I certain understand the motivation.)

But there is nothing inadvertent about the slf4j.provider. If you include it, you know you're specifically requesting a logging provider. You don't need SLF4J to remind you of that. If SLF4J uses a provider it finds on the classpath, SLF4J doesn't send a message to stderr notifying the user of which provider they chose. I don't see the difference here—if any thing, there is less of a reason to log information, because nothing happened "by default"—there was an explicit configuration.

Let's say that I want all my unit tests to ignore all logging output of the libraries they use, so that I won't have to have a logging implementation in test scope at all. (See SLF4J-592.) By default SLF4J does a a NOP, so I could just leave it at that, except that all my unit tests will have this:

SLF4J: No SLF4J providers were found. SLF4J: Defaulting to no-operation (NOP) logger implementation SLF4J: See https://www.slf4j.org/codes.html#noProviders for further details.

SLF4J-450 should fix that! Now I can do this in JUnit:

@BeforeAll
static void disableLogging() {
  System.setProperty("slf4j.provider", NOP_FallbackServiceProvider.class.getName());
}

Now I get the following, which defeats the purpose of what I was trying to do. 🤦‍♂️

SLF4J: Attempting to load provider "org.slf4j.helpers.NOP_FallbackServiceProvider" specified via "slf4j.provider" system property

I can do an ugly hack to get rid of the message:

@BeforeAll
static void disableLogging() {
  System.setProperty("slf4j.provider", NOP_FallbackServiceProvider.class.getName());
  final PrintStream originalSystemErr = System.err;
  try {
    System.setErr(new PrintStream(OutputStream.nullOutputStream()));
    LoggerFactory.getILoggerFactory();
  } finally {
    System.setErr(originalSystemErr);
  }
}

That suppresses the message. But if I'm going to do that, there's no point in using slf4j.provider at all, because SLF4J would default to the NOP provider anyway.

Please remove messages to stderr when slf4j.provider is used. Or just let me know that you're OK with this change, and I can file a pull request.

[garretwilson]

I went ahead and filed a pull request, because this issue is impeding me from implementing my own JAVA-357: adding the no-op logger to the Maven build to prevent extra logging cruft from unit tests. Without this fix, the logging suppression causes its own cruft. 😒

[garretwilson]

Another consideration: even if you decide that you really, really, really want to log some message that the provider is coming from slf4j.provider (I disagree, but it's a valid opinion), remember that at this point you know what logging implementation you should be using! So instead of logging to stderr, the message (really a debug-level message at most) should go to whatever logger we went went with from slf4j.provider, which will follow its configuration for logging levels, etc.

If you want that change, I can make it as well, but I I prefer just taking out the message altogether as I have done in the pull request.

[garretwilson]

Note also that the main project readme still indicates linking to a Jira ticket, but since the Jira site indicates SLF4J is migrating to GitHub, I inferred this part of the readme simply needs updated.

[ceki]

How about another a flag telling SLF4J to be quiet at initialization time, e.g. a system property such as "slf4j.silentInit" ?

Regarding the argument about the user knowing the slf4j implementation, people can forget that they have set up "slf4j.provider" and spend hours trying to understand why they are using slf4j-simple and not slf4j-jul. I see such silly mistakes all the time and that is the reason why SLF4J is chatty at initialization time. The goal is to guide the distracted developer.

[garretwilson]

How about another a flag telling SLF4J to be quiet at initialization time, e.g. a system property such as "slf4j.silentInit" ?

Are you proposing that this would be a general flag, applying to the "No SLF4J providers were found." messages as well? If so it might be useful. Otherwise there's the danger that the API would be cluttered with a lot of arbitrary one-off settings.

In general I don't know how I feel about this. On one hand it would be nice if SLF4J just works "as expected" out of the box, and I don't expect it to tell me that I set a system property because I know that already. Telling me I forgot something on the other hand, such as that there are no providers, and that the system is in an invalid state, is more expected. So now I would have a quandary: if I set slf4j.silentInit to keep SLF4J quiet about things I do set, then it will no longer warn me about things I forget!

At the end of the day I don't think this warning is appropriate, especially not to stderr, because the message is about a known, explicitly set system state. If you think the message is appropriate, it would be better sent at DEBUG level to the chosen provider. But finally if slf4j.silentInit is the only acceptable way forward, then yes, it would be better for my user case than the current situation.

Regarding the name of slf4j.silentInit: you might consider "quiet" rather than "silent", as I think that is a more common word in this context; see https://tldp.org/LDP/abs/html/standard-options.html for the CLI option for example. Also "silentInit" looks a little like "Silent Night". 😆

[ceki]

@garretwilson I have made an attempt at solving this issue in commit 316b5d1727d647250ff791565

This commit adds a system property called slf4j.verbosity which can be set to one of "INFO", "WARN" and "ERROR", defaulting to "INFO". Setting this property allows the user to control the messages emitted by SLF4J

I think this solution is a little more general than what was discussed earlier.

I should also mention that the target stream can be set with the "slf4j.reportStream" property to Stdout or Stderr (the default).

[garretwilson]

Thanks for attempting to address this.

On the face of it, it doesn't feel right that we're creating sort of a duplicate of the logging framework itself—a sort of shadow framework. It also raises other questions:

• What slf4j.verbosity level do I set to say "don't send any information to stderr, ever, that doesn't go through an SLF4J logger"?
• What slf4j.verbosity level is used to indicate that slf4j.provider has been set? Will this be documented and set in stone?
• How can I indicate that I want a warning if no logger can be found at all, but no warning if slf4j.provider has been set?

I would be hesitant to essentially recreate the log levels for a "shadow logging system", especially when the use cases aren't clear, and they are duplicating functionality withing SLF4J itself.

I think a safer way forward in the short term would be to add an slf4j.quiet flag (similar to the slf4j.silentInit flag you suggested earlier) which would simply disable all out-of-band logging. You could still add slf4j.verbosity in the future, which would only take effect if slf4j.quiet wasn't set to true.

To summarize, I guess it feels like overengineering in the face of a lack of known use cases, while duplicating existing functionality.

I'm not trying to be critical. I'm just trying to provide feedback to help you make your decision, because once it's in, it's something you'll have to support.

[garretwilson]

To look at this another way: if you're going all out and having an internal, out-of-band logger with a system of log levels and everything, aren't you essentially re-implementing slf4j-simple? If you're going that far, it's a small step include slf4j-simple and use an internal Logger so that you wouldn't be reimplementing everything. Or you could even implement a slf4j-even-simpler internal implementation—which is really what this is, except that it invents new interfaces rather than using the SLF4J ones.

[garretwilson]

I think the slf4j.verbosity approach could also be confusing to users, who might be thinking that they are setting the logging level for whatever provider they have chosen. (Setting the default logging level in a consistent way across providers already is a common need, so users might jump to the conclusion that this has finally been addressed.)

[ceki]

IMO, 120 lines of code do not qualify as a "framework". Your remark about confusing users is valid. Indeed, "slf4j.internalVerbosity" would probably be a better name albeit more verbose.

As for the the level of messages you mention above, it is all up for discussion. I should also mention that the target stream can be set with the "slf4j.reportStream" property to Stdout or Stderr (the default).

[garretwilson]

IMO, 120 lines of code do not qualify as a "framework"

I was referring mainly to duplicated functionality, not to size.

I want to stress that I'm trying to help by raising potential drawbacks—I figure you'd rather be aware of them now rather than think of them after they are released. 🙂

[garretwilson]

"slf4j.internalVerbosity"

I think that does bring up the point that we might want to think about what we're calling this new thing. Is it "the internal logging ~framework~ system?".

If the "external" logging system uses log level, wouldn't we want to call the internal one similarly? Perhaps slf4j.internal.log.level? If they both mean the same thing, I don't know why one would be called "level" and the other "verbosity".

[ceki]

Thank you for your valuable input.

People have been complaining about SLF4J's internal messages on and off for a long time. It seems that now is a good time to fix this issue.

I think that does bring up the point that we might want to think about what we're calling this new thing. Is it "the internal logging ~~framework~~ system?".

Internal logging feature? 🙂

The term "verbosity" was meant to convey that this property only affects SLF4J's own chattiness. However, if the property name is prefixed with "internal" then the term "level" is just as good.

In any case, the documentation should make it clear that setting slf4j.internal.log.level does not affect logging done by the SLF4J back-end. Regarding the name of the property, I think that "slf4j.internal.verbosity" is a good name because this new logging feature is rather primitive and is not a general logging framework.

[ceki]

More documentation was added in commit c12667b9063b2b9409ed49072d9746f34f968440