New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Noisy print messages from logging framework #516

Closed
phillord opened this Issue Apr 23, 2016 · 20 comments

Comments

Projects
None yet
3 participants
@phillord
Copy link
Contributor

phillord commented Apr 23, 2016

The OWL API is using slf4j. This framework has the irritating habit of printing a message to screen to tell you that it isn't going to print any messages to screen.

I would suggest that the OWL API includes slf4j-nop as a dependency. Anyone who actually wants an error message everytime can always exclude the nop dependency.

@ignazio1977

This comment has been minimized.

Copy link
Contributor

ignazio1977 commented Apr 27, 2016

It's true that those warnings are annoying. However, adding a binding to OWLAPI dependencies is precisely what SLF4J discourages:
http://www.slf4j.org/codes.html#StaticLoggerBinder

Embedded components such as libraries or frameworks should not declare a dependency on any SLF4J binding but only depend on slf4j-api. When a library declares a compile-time dependency on a SLF4J binding, it imposes that binding on the end-user, thus negating SLF4J's purpose. When you come across an embedded component declaring a compile-time dependency on any SLF4J binding, please take the time to contact the authors of said component/library and kindly ask them to mend their ways.

I wouldn't want our ways to not be on the straight and narrow...

I'm not sure if Maven allows for dependencies with low priority - so that the final user never needs to exclude dependencies in order to replace them with a different binding. I can't find any such mechanism.
Could probably work around this by writing a custom binding which will replicate the search process used by SLF4j (acting as a proxy) but not output any message when none is found. Sounds like a lot of work though.

@phillord

This comment has been minimized.

Copy link
Contributor Author

phillord commented Apr 27, 2016

slf4j's code and their website are both wrong. A system which randomly dumps to standard out by design is not worth using, in my book. However, since it is being used, I think we need a solution which removes the problem. Given that SLF4J is using a maven-dependency-as-a-form-of-configuration approach, fixing this in the same way makes sense. The text above talks about a compile time dependency. Including the nop as a maven time dependency (perhaps as runtime) solves this problem.

In the meantime, I will contact slf4j and "kindly ask them to mend their ways".

@ignazio1977

This comment has been minimized.

Copy link
Contributor

ignazio1977 commented Apr 27, 2016

Technically it's System.err, says the pedant :-)

Wearing the devil's advocate hat for a moment, the amount of config required to use a binding in a client app and silence the warning is the same amount required for a client app to override the default; however introducing a default where none was means that client apps that configured their own binding will have to change or get warnings and loss of logging. I'm a bit meh about that perspective.

Patching sl4j to stop those three lines appearing is too much extra maintenance overhead. However a suppressor binding like the one I described would negate all concerns mentioned here. So that shall happen.

@phillord

This comment has been minimized.

Copy link
Contributor Author

phillord commented Apr 27, 2016

I'd agree, that client apps which want logging will now have to explicitly ask for it. Although, if this does happen; according to the FAQ.

"If more than one binding is present on the class path, SLF4J will emit a warning, listing the location of those bindings"

So, anyone who is explicitly using a slf4j will get a warning about multiple bindings. Given that they are, by definition, using slf4j they, at least, should not be non-plussed about the warning, since they will have heard about slf4j.

Yes, you are, of course correct that the amount of config to include the nop dependency is about the same as that required to exclude it, But, it's different people. Those who want logging have to ask for it, those who do not are untroubled.

A suppressor binding -- I can't see how this helps. The nop dependency is a supressor binding. If you add one, then end-users with their own binding will still find a conflict, and will now need to exclude your suppressor.

I've mailed the slf4j mailing list also, and will let you know how that goes. Ultimately, slf4j is the right place to fix things, not here.

@ignazio1977

This comment has been minimized.

Copy link
Contributor

ignazio1977 commented Apr 27, 2016

What I'm talking about is a binding that will look for other bindings and, finding one, delegate to it. Finding none, will use nop without further messages.

At that point, sl4j thinks there's a binding, so it does not complain, and users without their choice of binding are not bothered by any messages. Whenever they add a binding, they get the logging they expect. No changes required to existing configs.

@phillord

This comment has been minimized.

Copy link
Contributor Author

phillord commented Apr 27, 2016

Sounds good, but too complicated; I suspect it's going to be randomly
dependent on the order on which things load in the classpath.

Ultimately, I think, we should leave this. I'll see whether slf4j will fix
it. If you are not willing (and I can respect why) to pull in nop, then I
think, I'll just have to put up with it.

On Wed, April 27, 2016 12:14 pm, Ignazio Palmisano wrote:

What I'm talking about is a binding that will look for other bindings
and, finding one, delegate to it. Finding none, will use nop without
further messages.

At that point, sl4j thinks there's a binding, so it does not complain,
and users without their choice of binding are not bothered by any
messages. Whenever they add a binding, they get the logging they expect.
No changes required to existing configs.


You are receiving this because you authored the thread.
Reply to this email directly or view it on GitHub:
#516 (comment)

@ignazio1977

This comment has been minimized.

Copy link
Contributor

ignazio1977 commented Apr 27, 2016

There' an interesting trick here:
http://stackoverflow.com/questions/7571506/how-to-suppress-slf4j-warning-about-multiple-bindings

Replace System.err with a filtered version that ignores SLF4J messages - now the only problem is where to put this code so it's executed once and only once :-)

@sesuncedu

This comment has been minimized.

Copy link
Contributor

sesuncedu commented Apr 27, 2016

It is interesting to note that the root cause of the problem in the
referenced stack exchange is... dependencies that include slf4j
implementations.

The error message printed when an application using slf4j (indirectly)
contains a url to a Web page that explains the error and links to the
download page.

It might be possible to publish an artifact "owlapi-with-slf4j-nop-logging"
that had just a dependency on owlapi and a dependency on slf4j-nop, and
applications that wished to not have logging could use that.
On Apr 27, 2016 2:24 PM, "Ignazio Palmisano" notifications@github.com
wrote:

There' an interesting trick here:

http://stackoverflow.com/questions/7571506/how-to-suppress-slf4j-warning-about-multiple-bindings

Replace System.err with a filtered version that ignores SLF4J messages -
now the only problem is where to put this code so it's executed once and
only once :-)


You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub
#516 (comment)

@phillord

This comment has been minimized.

Copy link
Contributor Author

phillord commented Apr 27, 2016

Ignazio Palmisano notifications@github.com writes:

There' an interesting trick here:
http://stackoverflow.com/questions/7571506/how-to-suppress-slf4j-warning-about-multiple-bindings

Replace System.err with a filtered version that ignores SLF4J messages - now
the only problem is where to put this code so it's executed once and only once
:-)

Yes, that's not a bad possibility.

Running it more than once is not a disaster since it is functionally
idempotent. Running many times more than once would be less cool.

I was thinking I could nobble the logging messages from ELK in the same
way, but I've just tried it and am entertaining to find that, actually,
they have gone anyway.

Phil

@phillord

This comment has been minimized.

Copy link
Contributor Author

phillord commented Apr 27, 2016

Simon Spero notifications@github.com writes:

It is interesting to note that the root cause of the problem in the
referenced stack exchange is... dependencies that include slf4j
implementations.

The root course of the problem is slf4j printing messages rather than
logging them. I can see that there is a bootstrap problem here, but
their solution is not a good one. The nop dependency doesn't even
contain the nop-logger -- that's bundled with the API!

Alas, this behaviour occurs even if one of the two bindings is the nop
logger, although AFAICT, the nop binding gets ignored and the noisy
logger gets used.

The error message printed when an application using slf4j (indirectly)
contains a url to a Web page that explains the error and links to the
download page.

Yes, and here we get to the pathological situation. Iff I want slf4j to
be quiet, so that it does not print out all the time during tests or in
interactive use, then their advice is "include the nop dependency".

But, I am building a tool which can (and is) also usable as a library.
And, now their advice is, "tell anyone using a binding to mend their
ways". So, I shouldn't include the nop dependency.

Which means I have to include it as a dev dependency, or may a provided
dependency. Now, my testing will not be hassled, but slf4j-nop will not
be included in the dependency list. Alas, now all downstream projects
(for example, any of the ontologies I build with tawny), will suffer the
same fate; now they will print error messages, and they will have to add
slf4j-nop as a dependency.

This is a lot of effort to go to stop a logging framework from printing
a message telling me that it's not going to print any messages.

So, I will include the slf4j-nop as a dependency, if the OWL API will
not.

It might be possible to publish an artifact "owlapi-with-slf4j-nop-logging"
that had just a dependency on owlapi and a dependency on slf4j-nop,

There is no value to this, to be honest. Firstly, when I get slf4j's
error message, I will google and find "add slf4j-nop" before I find
"owlapi-with-slf4j-nop-logging"; so no one will use it. Second, changing
my owlapi dependency to owlapi-with-slf4j-nop-logging is the same effort
as adding a nop-logging dependency.

and applications that wished to not have logging could use that.

It's not about getting no logging. By default the OWL API does not log
(and nor should it).

The correct solution is, still, I think to include the nop dependency
directly. The faq entry from slf4j telling you not to do this is,
simply, wrong.

Anyone who wants logging can exclude this.

Phil

ps. github removes all the inline quoting. Hope it still makes sense. I am speaking to slf4j, and will update if we get a better solution.

@phillord

This comment has been minimized.

Copy link
Contributor Author

phillord commented Apr 29, 2016

Okay, I have spoken to the SLF4J devs -- the full log is on the user mailing list.

http://news.gmane.org/gmane.comp.java.slf4j.user

The current situation is that, there is no way of avoiding this error message, except by incorporating the nop dependency. They generally argue that libraries should not do this, while applications should not. I am stuck, of course, as tawny is both. They have updated their FAQ, as a result of the discussion.

I will incorporate the nop binding into tawny owl. Personally, I would prefer that you incorporate it into the OWL API -- anyone who wants logging can, of course, exclude the dependency and use another implementation, rather than force downstream users to make a choice in the default case.

Up to you, of course!

@phillord

This comment has been minimized.

Copy link
Contributor Author

phillord commented May 5, 2016

I think we should finalize on this. AFAICT, there are two ways forward -- include slf4j-nop and close the issue, or do not include slf4j-nop and close the ticket!

@ignazio1977

This comment has been minimized.

Copy link
Contributor

ignazio1977 commented May 5, 2016

The other alternative is to write a small utility to silence the output, ensuring it does not become a performance black hole.

You could then use it freely in either library or app behavior of tawny.

ignazio1977 added a commit that referenced this issue May 5, 2016

Fix Noisy print messages from logging framework #516
To fix, call SLF4JSilencer.silence();
@ignazio1977

This comment has been minimized.

Copy link
Contributor

ignazio1977 commented May 5, 2016

To fix, call SLF4JSilencer.silence();

ignazio1977 added a commit that referenced this issue May 5, 2016

Fix Noisy print messages from logging framework #516
To fix, call SLF4JSilencer.silence();
@ignazio1977

This comment has been minimized.

Copy link
Contributor

ignazio1977 commented May 5, 2016

Will be in the next release; in the meantime, you can copy the class in Tawny to use it right now.

@ignazio1977

This comment has been minimized.

Copy link
Contributor

ignazio1977 commented May 5, 2016

Forgot to mention: this class won't wrap System.err more than once. Won't error if a null string is printed in code, and performance is in the order of 10 million strings per millisecond; so, effectively irrelevant.

@phillord

This comment has been minimized.

Copy link
Contributor Author

phillord commented May 5, 2016

@ignazio1977 That's completely crazy. I will for sure use it!

We could count to 3 lines, then restore System.err after that. I may implement this myself actually, and add "LOG4J" -- I get the same issue from log4j, thanks to ELK.

I blogged about it! http://www.russet.org.uk/blog/3112

@phillord

This comment has been minimized.

Copy link
Contributor Author

phillord commented May 5, 2016

Oh, I thought you might be interested in this commit which came out of thinking about this.

phillord/tawny-owl@2025e40

I was irritated with slf4j for not just setting a default, but realised I was doing the same myself. Fixed now.

@ignazio1977

This comment has been minimized.

Copy link
Contributor

ignazio1977 commented May 5, 2016

phillord/tawny-owl@2025e40

Love that JFact is the default, although honestly I would have used something else :-) performance is getting better but it's still not as good as a good number of the others.

@phillord

This comment has been minimized.

Copy link
Contributor Author

phillord commented May 5, 2016

Performance is one thing, but jfact tends to stay in sync with the OWL API for some reason.

Mostly, performance is not a huge issue, although I am curious. I will check it out with some of our large stuff sometime.

I'll close now. Thanks for the fix!

@phillord phillord closed this May 5, 2016

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment