Introduce custom logging façade on top of JUL

[sormuras]

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

• Introduce error handling mechanism for validation and discovery errors #242
• Provide additional context in error messages #602

Deliverables

• Discuss custom logging façade.
• 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
• Document custom logging façade (JavaDoc).

[sbrannen]

I am currently not in favor of introducing a custom logging façade.

I think JUL should continue to suffice for our needs.

[sbrannen]

Having said that, I am in favor of introducing more logging and/or proper error handling.

[sbrannen]

Error handling will be addressed in #242.

[sbrannen]

Providing additional context in error messages will be addressed in #602.

[sbrannen]

FYI: added Related Issues section to issue description.

[sbrannen]

Currently slated for 5.0 M5 in order to discuss this topic in a timely manner.

[nipafx]

@sormuras: Could you describe the rationale for creating a facade (excuse me if I forego the fancy "c" 😉)? What would the different backends be?

[sormuras]

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.

[nipafx]

@sormuras I find this intriguing. With a slim facade like the one you propose (please don't call it LogUtils, though! 😉) 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.

[jhoeller]

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.

[sormuras]

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.

[sbrannen]

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]

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. 😉

[bechte]

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 👍

[sbrannen]

@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>).

[jhoeller]

@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.

[sbrannen]

Awesome, @jhoeller.

Thanks so much! 👍

[sbrannen]

Update

I just added support for populating the source class name and method name based on the current call stack.

junit5/junit-platform-commons/src/main/java/org/junit/platform/commons/logging/LoggerFactory.java

Lines 108 to 134 in b6a998c

	private LogRecord createLogRecord(Level level, Throwable t, Supplier<String> messageSupplier) {
	StackTraceElement[] stack = new Throwable().getStackTrace();
	String sourceClassName = null;
	String sourceMethodName = null;
	boolean found = false;
	for (StackTraceElement element : stack) {
	String className = element.getClassName();
	if (FQCN.equals(className)) {
	found = true;
	}
	else if (found) {
	sourceClassName = className;
	sourceMethodName = element.getMethodName();
	break;
	}
	}
	LogRecord logRecord = new LogRecord(level, nullSafeGet(messageSupplier));
	logRecord.setLoggerName(this.name);
	logRecord.setThrown(t);
	logRecord.setSourceClassName(sourceClassName);
	logRecord.setSourceMethodName(sourceMethodName);
	logRecord.setResourceBundleName(this.julLogger.getResourceBundleName());
	logRecord.setResourceBundle(this.julLogger.getResourceBundle());
	return logRecord;
	}

[sbrannen]

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.

[bechte]

Great! 👍

[sbrannen]

@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:

• 3bedaf5
• b8c1ae5

Since the usage of the façade would only be internal, I don't foresee any negative side effects for end users.

Thoughts?

[sbrannen]

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]

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.

[bechte]

I could live with having it in 5.0. So +1

[sbrannen]

Resolved in d5c0b1c in master.

Follow-up work regarding testing will be addressed in #1047.