Junit5: Introduce custom logging façade on top of JUL
Overview
We are considering to write and use our own custom façade. Something like was done in Spring.
Add more logging statements to the code, especially when it comes to configuration/setup with engines, listeners, test class/method invocations.
Related Issues
- #242
- #602
Deliverables
- [x] Discuss custom logging façade.
- [x] Implement custom logging façade.
- ❌ Make custom logging façade _testable_ -- for example, by allowing tests to _attach_ some sort of listener in order to verify that particular statements were logged at a specific log level.
- to be performed in a later release
- [x] Document custom logging façade (JavaDoc).
sormuras
All 45 comments
I am currently not in favor of introducing a custom logging façade.
I think JUL should continue to suffice for our needs.
sbrannen
on 4 May 2017
Having said that, I _am_ in favor of introducing more logging and/or proper error handling.
sbrannen
on 4 May 2017
Error handling will be addressed in #242.
sbrannen
on 4 May 2017
Providing additional context in error messages will be addressed in #602.
sbrannen
on 4 May 2017
FYI: added _Related Issues_ section to issue description.
sbrannen
on 4 May 2017
Currently slated for 5.0 M5 in order to discuss this topic in a timely manner.
sbrannen
on 4 May 2017
@sormuras: Could you describe the rationale for creating a facade (excuse me if I forego the fancy "c" :wink:)? What would the different backends be?
nipafx
on 4 May 2017
A true _façade_ was not intended, we should stick with JUL as our framework of choice.
Maybe an internal LogUtils class that provides documented, often used and better named methods à la LogUtils.warn(Class, Supplier<String>) and .info(...), .config(...), .debug(...) variants is what I wanted.
sormuras
on 5 May 2017
@sormuras I find this intriguing. With a slim facade like the one you propose (please don't call it LogUtils, though! :wink:) it would be possible to take a different logging route based on configuration or Java version.
In Java 9 in particular, there's redirected platform logging, which allows logging backends to be plugged into the JDK to route messages through them. This would allow JUnit 5 to use a JDK API while still allowing clients to receive the messages through whatever logging framework they prefer. So if someone has a use case for getting JUnit's messages through Logback, that would be possible on Java 9 without JUnit adopting any new dependencies.
While nice in theory, it raises the question why anybody would want to do that. I have to admit, I never had that use case.
nipafx
on 5 May 2017
Just a note since this thread started with Spring 5: That step came out of a special situation with 13 years of history, so our choice of implementing a custom Commons Logging variant happens to be our smoothest way out of this: preserving binary compatibility while having first-class support for Log4J 2, SLF4J and JUL... by default, without custom Maven setup. I wouldn't recommend this to anyone else unless there is also a lot of existing third-party code with Commons Logging references for a particular framework out there...
So for JUnit 5 in particular, I'd also stick with JUL. Test environments are more controlled to begin with, and the most relevant part are assertions which bubble up to the execution environment. Any intermediate logging is really more of a bonus, trying to analyze JUnit extension interferences, that sort of stuff? In any case, server applications are certainly different since even hard failures need to be analyzed through the log, not just passing back an error response to the client but also tracking such occurrences on the server.
jhoeller
on 7 Jul 2017
Thanks for the background information, Jürgen.
As stated above, I'm totally fine with stickting to JUL.
The current 16 usages of the Logger.getLogger(...) pattern are:
This is the basis to build on for more meaningful logging, like Sam mentioned above. Perhaps, we should route the creation and usage of Logger instances through an internal utility class, that a) bundles the logging calls in a single place and b) documents the purpose of each severity level.
sormuras
on 7 Jul 2017
Hi @jhoeller!
Thanks for sharing your insight with regard to Spring's special needs. We'll definitely take those points into consideration.
If we end up creating any kind of logging _facade_ for JUnit, I think it would simply be a wrapper around JUL that provides us a better API than the one in JUL itself. In other words, I don't foresee us aiming for interoperability with multiple logging frameworks.
Cheers,
Sam
sbrannen
on 7 Jul 2017
Perhaps, we should route the creation and usage of Logger instances through an internal utility class, that a) bundles the logging calls in a single place and b) documents the purpose of each severity level.
@sormuras, looks like we're on the same page. 😉
sbrannen
on 7 Jul 2017
In such a utility class / façade, I'd actually like to use _common_ log level names to avoid the confusion caused by the bizarre log level names in JUL. Plus, I'd like to make sure that it's easy to log warnings with an exception, etc.
sbrannen
on 7 Jul 2017
A major drawback of a potential "LogSupport.log(Level, Message)" helper is that this helper method is referred to by the automatic source/location of the log statement. See https://docs.oracle.com/javase/7/docs/api/java/util/logging/LogRecord.html#getSourceMethodName() for details.
sormuras
on 31 Aug 2017
A major drawback of a potential "LogSupport.log(Level, Message)" helper is that this helper method is referred to by the automatic source/location of the log statement.
Hmmmm... will have to investigate the implications of that.
Though... I never thought we would use static methods for logging but rather that we would introduce our own Logger interface and corresponding factory method with an internal implementation that would simply delegate to JUL, much like any other logging framework out there.
sbrannen
on 31 Aug 2017
See the output of this small demo:
import java.util.function.Consumer;
import java.util.logging.Logger;
interface JulDemo {
Logger logger = Logger.getLogger("JULES");
Consumer<String> lambda = logger::info;
Facade facade = new Facade();
class Facade {
void info(String message) {
logger.info(message);
}
}
static void main(String... args) {
logger.info("direct");
lambda.accept("lambda");
facade.info("facade");
}
}
The output using the default JUL setup looks like:
Aug 31, 2017 7:04:42 PM JulDemo main
INFO: direct
Aug 31, 2017 7:04:42 PM JulDemo main
INFO: lambda
Aug 31, 2017 7:04:42 PM JulDemo$Facade info
INFO: facade
Two times, the logging location/origin is class JulDemo and method main. I didn't know, that lambdas are that transparent to the VM here. I expected to see a generated method with some $$ or other magic signs here.
The call behind the facade gets "relocated" to class JulDemo$Facade and method info. Ergo, you lose the information of the true origin.
sormuras
on 31 Aug 2017
...refactored to use "our own Logger interface and corresponding factory method" that delegates to JUL similar to the JulDemo$Facade#info above would hide/lose the following information:
- class
org.junit.platform.launcher.core.ServiceLoaderTestEngineRegistry - method
loadTestEngines()
sormuras
on 31 Aug 2017
That does sound like quite a negative side effect.
However, I'm wondering if it would be possible to _fix_ the issue by populating the sourceClassName and sourceMethodName properties of LogRecord accordingly (e.g., by inspecting the call stack... which would of course be easier with Java 9's StackWalker).
Thoughts?
sbrannen
on 4 Sep 2017
That's indeed a solution to the problem, as taken by the common SLF4J bridges and also by Spring 5: see https://github.com/spring-projects/spring-framework/blob/master/spring-jcl/src/main/java/org/apache/commons/logging/LogFactory.java, specifically LocationResolvingLogRecord. Similar solutions are available for SLF4J and Log4J 2, there simply by specifying the class name of the logging bridge and letting the underlying logger skip such entries in the stacktrace.
jhoeller
on 4 Sep 2017
Hi @jhoeller,
Thanks for chiming in and confirming the feasibility of my assumptions!
I'd _love_ to just copy the required code from Spring's LogFactory but I'm not sure about the legal ramifications due to the two different open source licenses.
Would you be willing to _donate_ the necessary JUL bridging code to JUnit? 😉
sbrannen
on 4 Sep 2017
Just wondering: what would happen if different logging frameworks are available on the classpath? I've seen this in projects with legacy support for older software parts... just to mention.
bechte
on 5 Sep 2017
what would happen if different logging frameworks are available on the classpath?
That's a problem that every project potentially faces, but it's also one that our logging façade would not exacerbate.
Our use of a façade on top of JUL would be akin to using slf4j as a façade on top of JUL.
We will not be introducing a new logging framework. Rather, we will simply be introducing a façade on top of an existing logging framework.
Make sense?
sbrannen
on 5 Sep 2017
FYI: I renamed this issue accordingly.
sbrannen
on 5 Sep 2017
All good and yes it totally makes sense to me either. What I was pointing at is the way the logging framework is detected in the Spring LogFactory and if this might lead to incorrect expectations.
Anyways, for us it would only be one case providing a simplified logging API which I totally agree with. :+1:
bechte
on 5 Sep 2017
One additional thought: Right now, logging is on by default, because JUL logs certain levels to the console unless configured otherwise. I would like to simplify that, i.e. have JUnit's logging disabled by default and only enable it for debugging purposes via a system property. That could also be achieved by such a façade. Thoughts?
marcphilipp
on 5 Sep 2017
Great idea. But I think we still need a certain logging to explain what went wrong. E.g. During discovery or API usage validation. We might include such a property after we have merged a solution for #242.
bechte
on 5 Sep 2017
Proof of concept: _in progress_
sbrannen
on 5 Sep 2017
In order to give us something concrete to look at and discuss, I just introduced the following branch with a _proof of concept_.
https://github.com/junit-team/junit5/tree/issues/834-logging-facade
sbrannen
on 5 Sep 2017
This is the package to look at:
sbrannen
on 5 Sep 2017
And you can see the use of our façade in action here:
sbrannen
on 5 Sep 2017
The log output from the corresponding test looks like this (using log4j as the underlying JUL implementation).
15:26:16.069 [main] WARN org.junit.platform.engine.support.descriptor.DemoClassTestDescriptor - Configuration error: invalid tag syntax in @Tag(" ") declaration on [class org.junit.platform.launcher.TagFilterTests$ClassWithNoTags]. Tag will be ignored.
So, it actually knows that the log statement came from DemoClassTestDescriptor, even without a custom JUL LogRecord in this particular scenario.
sbrannen
on 5 Sep 2017
And this is the log output from the corresponding test when using JUL directly (i.e., JUL as the implementation of the JUL API).
Sep 05, 2017 3:38:53 PM org.junit.platform.commons.logging.LoggerFactory$DelegatingLogger log
WARNING: Configuration error: invalid tag syntax in @Tag(" ") declaration on [class org.junit.platform.launcher.TagFilterTests$ClassWithNoTags]. Tag will be ignored.
So, in this scenario the log statement comes from LoggerFactory$DelegatingLogger instead of from DemoClassTestDescriptor.
sbrannen
on 5 Sep 2017
I wonder what the output looks like if we don't use Log4j. And also how they know about the facade? Fancy. Still like the solution because of its simple and clean interface. Thanks.
Second time of a comment race condition. ;-) so we should add Spring's code for the LogRecord for the JUL API.
Thanks for testing and providing the poc 👍
bechte
on 5 Sep 2017
@marcphilipp,
One additional thought: Right now, logging is on by default, because JUL logs certain levels to the console unless configured otherwise. I would like to simplify that, i.e. have JUnit's logging disabled by default and only enable it for debugging purposes via a system property. That could also be achieved by such a façade. Thoughts?
Well, I'm not sure I'm a fan of turning off logging by default, but.... it would certainly be possible with such a façade.
The check would go in org.junit.platform.commons.logging.LoggerFactory.DelegatingLogger.log(Level, Throwable, Supplier<String>).
sbrannen
on 5 Sep 2017
@sbrannen, of course I'm happy for the Spring 5 logging code to be used (directly or as an inspiration) in JUnit 5. There is prior art here in the logging bridges (e.g. SLF4J-JUL) anyway, so it's a quite common approach at this point.
jhoeller
on 5 Sep 2017
Awesome, @jhoeller.
Thanks so much! 👍
sbrannen
on 5 Sep 2017
Update
I just added support for populating the _source_ class name and method name based on the current call stack.
sbrannen
on 5 Sep 2017
With the above change in place, the following is the _new_ (correct) log output from the corresponding test when using JUL directly (i.e., JUL as the implementation of the JUL API).
Sep 05, 2017 5:51:22 PM org.junit.platform.engine.support.descriptor.DemoClassTestDescriptor lambda$1
WARNING: Configuration error: invalid tag syntax in @Tag(" ") declaration on [class org.junit.platform.launcher.TagFilterTests$ClassWithNoTags]. Tag will be ignored.
The log statement now correctly comes from DemoClassTestDescriptor instead of LoggerFactory$DelegatingLogger as was previously the case.
sbrannen
on 5 Sep 2017
Great! :+1:
bechte
on 5 Sep 2017
@junit-team/junit-lambda I am in favor of using our own custom logging façade for JUL effective immediately.
Rationale: using our façade would avoid the need for "fix up" commits like my last two:
- 3bedaf529efc2f9d0c9d5807f29a492f9f2fcd08
- b8c1ae510d024a96e237c9411c4c0c88fd860584
Since the usage of the façade would only be internal, I don't foresee any negative side effects for end users.
Thoughts?
sbrannen
on 6 Sep 2017
Update
Tentatively slated for 5.0 GA in order to discuss usage of the façade immediately, with further refinements potentially coming in 5.0.x or 5.1.
sbrannen
on 6 Sep 2017
Updated _Deliverables_.
I propose that the task "Make custom logging façade _testable_" could potentially be pushed back until 5.0.x or 5.1.
sbrannen
on 6 Sep 2017
I could live with having it in 5.0. So +1
bechte
on 6 Sep 2017
Resolved in d5c0b1cca585ea7cef809db5377f5ee6b31cf630 in master.
Follow-up work regarding testing will be addressed in #1047.
sbrannen
on 8 Sep 2017
Related issues
borisilic
·
4Comments
kec2
·
3Comments
1vanan
·
4Comments
netzwerg
·
6Comments
ondrejlerch
·
4Comments