Logging Concluded
My last blogpost was on logging (n.d.) with the SLF4J library, its inclusion in the OWL API, and its impact on Tawny-OWL. It raised quite a response, not least because it suggested that people ignore the advice of the authors of the library.
Perhaps, unsurprisingly, the general feeling was against my position — something that I expected given that this had already happened on the SLF4J mailing list. Now, of course, it does have to be said that there is a significant sampling bias here: anyone on the mailing list, or who reads and responds to a post about a logging API, is likely to be interested in logging rather than a passive user (or non-user) of such a library. None the less, I think it is worth reflecting on the reasons for the comments.
Of course, I am aware, that as many people pointed out, the problem is not huge (a three line error message) and my solution is messy. Well, I agree, the solution is messy, but it is the only method that SLF4J has support for. There are alternatives; for example, this commit from the OWL API provides another solution. I have not decided yet whether this is the right way to go or not.
Several people complained that including the nop dependency will silently turn off all logging. Actually, this is not true: in applications which have logging already, including a nop dependency, will trigger an error message; whether logging is turned off or not is hard to determine — it depends on the classpath ordering. I am, however, clearly making life harder for those who want logging on. Specifically, I am requiring that instead of using:
["uk.org.russet/tawny-owl "1.5.0"]
It will require this:
["uk.org.russet/tawny-owl "1.5.0" :exclusions ["org.slf4/slf4f-nop"]]
(or the equivalent for maven). So, harder, but not much harder.
The other two main suggestions are that I split my code into library and application, even though this is artificial (the “application” would currently contain no code). But this approach would require most of my downstream dependencies to also be split into two for the same reason; it was even suggested that the Clojure REPL or Leiningen that should do the work, and that they should be split into two. Introducing such complexity for a logging API is surely not good engineering.
Finally, there were many suggestions that I leave the decision to the “end user”. But, as I have said, while I like allowing the “end user” to have a choice, I do not believe in imposing it on them. Choose a default where it is at all possible and do not sit on the fence.
During this process, though, I have thought a lot about logging, and I have come to the conclusion that the core of the problem is that logging is heavily overloaded. Quite a few people were frankly amazed that I would not want to see logging, asserting that most people would want to see it.
Now, I use a web server, and use its logs all the time. Logs are critical for many reasons, and many tools like webalyser or fail2ban work over them. I would never want to turn these off. But, here, though, the logging is effectily a part of the application: apache logs are part of the adminstration user interface, as well as forming an ad hoc API to downstream tools; part of the plumbing in git parlance. Why would you want to switch this off? I would not.
In this case, though, if logging is part of the application, why on earth are people so keen on libraries logging — the application should not be deciding the location of the logs only, but also how and what is logged. Libraries should just not be logging at all; they should be taking callbacks, returning values and leaving the outcome of this to the application.
What about “error messages” though? Surely libraries can produce these? The OWL API (which is the library that makes use of SLF4J) is an example of this. Most of the logging message are errors: for example, this situation:
if (loadCount.get() != importsLoadCount.get()) {
LOGGER.warn(
"Runtime Warning: Parsers should load imported ontologies using the makeImportLoadRequest method.");
}
which is effectively a form of active documentation or this:
try {
return optional(new XZInputStream(new BufferedInputStream(new FileInputStream(file))));
} catch (IOException e) {
LOGGER.error("File cannot be found or opened", e);
failedOnStreams.set(true);
return emptyOptional();
}
which is sort of an error but one that has actually been dealt with. These are mostly debugging statements that the authors think they may use again. That’s fine and an entirely reasonable use of a logging framework. Equally, and I feel entirely reasonably, I want this off by default.
The “error message” from SLF4J that started me down this path falls into the same category. It is not an error, or it would throw an exception (as it used to do in the past). It is a debugging statement that is there for a normal condition that the authors are, nonetheless, not entirely happy about. There are two reasonable defaults (be noisy, or be silent), and they do not know which to choose.
My previous trip into the field of logging was twenty years ago, when I
wrote a fun Emacs packages for putting System.out.println
statements
into the code (then taking them out again); as one person said of me, I
“simply lack the knowledge” of logging frameworks to comment. I am happy
to accept that this is entirely correct. Despite this my conclusions are
simple. I remain convinced that SLF4J should have the courage of its
convictions; if there is an error, signal an error, otherwise remain
silent. Until it does this, adding the nop dependency remains the right
way forward for me. Take my advice with a distinct pinch of salt,
certainly. At the same time, think how many people have been
irritated by that error
message and not taken the time to comment. If you are worried about
these people, then using the nop dependency may be the right way forward
for you to.
And there I shall leave the discussion and comment no more.