Log-Meldungen während der Ausführung von Tests können verwirrend sein, insbesondere wenn Error-Level Meldungen mit Stacktraces ausgegeben werden, die im Rahmen des Tests vollkommen ok sind. Mit einem eigenen Filter für Log4j2 habe ich eine Möglichkeit gefunden, die Log-Meldungen während der Ausführung eines Blocks stummzuschalten.
Das Handling von Logmeldungen erscheint meist trivial, ist es aber nicht. Wenn eine Exception passiert, sollte diese in jedem Fall in den Logmeldungen auftauchen, normalerweise im Loglevel Error. An der Stelle, wo die Exception aufgefangen und behandelt wird, sollte sie auch geloggt werden. Schreibt man nun einen Testcase, der die Stelle testet, in der eine Exception passiert und behandelt wird, dann landet die Ausgabe der Exception im Logfile. Auch wenn ein Test nicht fehlschlägt, ist es für den Entwickler durchaus irritierend, wenn im Logfile Error-Level Meldungen mit Stacktraces auftauchen.
Würde man nun in der Loggingkonfiguration das Loggen für alle Testcases oder die Testklasse abschalten, würde man Error-Meldungen aus anderen Stellen und unerwarteten Fehlern nicht mehr sehen.
Log4j2 erlaubt es, auf einfache Weise Filter zu schreiben, die in das Logging-Geschehen eingreifen können.
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.Logger;
import org.apache.logging.log4j.core.config.plugins.Plugin;
import org.apache.logging.log4j.core.config.plugins.PluginAttribute;
import org.apache.logging.log4j.core.config.plugins.PluginFactory;
import org.apache.logging.log4j.core.filter.AbstractFilter;
import org.apache.logging.log4j.message.Message;
/**
* Log4j Filter zum "Muten" der Logs, wenn in einem Testcase eine Exception erwartet wird.<br>
* Anwendung:<br>
* <pre>
* log.info("TEST UNMUTED 1");
* LoggingMuteFilter.muted(() -> {
* log.info("TEST MUTED 1");
* log.info("TEST MUTED 2");
* log.error("TEST MUTED 3");
* log.fatal("TEST MUTED 4");
* });
* log.info("TEST UNMUTED 2");
* </pre>
*
* @author Serhat Cinar
*/
@Plugin(name = "LoggingMuteFilter", category = "Core", elementType = "filter", printObject = true)
public class LoggingMuteFilter extends AbstractFilter {
private static ThreadLocal<Boolean> MUTED = ThreadLocal.withInitial(() -> Boolean.FALSE);
private LoggingMuteFilter(Result onMatch, Result onMismatch) {
super(onMatch, onMismatch);
}
public Result filter(Logger logger, Level level, Marker marker, String msg, Object[] params) {
return filter();
}
public Result filter(Logger logger, Level level, Marker marker, Object msg, Throwable t) {
return filter();
}
public Result filter(Logger logger, Level level, Marker marker, Message msg, Throwable t) {
return filter();
}
@Override
public Result filter(LogEvent event) {
return filter();
}
private Result filter() {
return MUTED.get() ? onMismatch : onMatch;
}
@PluginFactory
public static LoggingMuteFilter createFilter(@PluginAttribute(value = "onMatch", defaultString = "NEUTRAL") Result onMatch,
@PluginAttribute(value = "onMismatch", defaultString = "DENY") Result onMismatch) {
return new LoggingMuteFilter(onMatch, onMismatch);
}
public static void muted(Runnable runnable) {
MUTED.set(Boolean.TRUE);
try {
runnable.run();
} finally {
MUTED.set(Boolean.FALSE);
}
}
}
Ich verwende den ThreadLocal MUTED, um zu speichern, ob das Logging stummgeschaltet werden soll.
Dies wird also pro Thread separat verwaltet, damit sich parallel ausgeführte Tests nicht gegenseitig stören.
Um in einem Codeblock das Logging zu deaktivieren, wird die Methode muted aufgerufen, die einen Runnable entgegennimmt.
log.info("TEST UNMUTED 1");
LoggingMuteFilter.muted(() -> {
log.info("TEST MUTED 1");
log.info("TEST MUTED 2");
log.error("TEST MUTED 3");
log.fatal("TEST MUTED 4");
});
log.info("TEST UNMUTED 2");
Im obigen Beispiel wird das Logging für die Meldungen TEST MUTED 1, TEST MUTED 2, TEST MUTED 3 und TEST MUTED 4 deaktiviert,
die Log-Ausgabe enthält damit nur noch folgendes:
TEST UNMUTED 1
TEST UNMUTED 2
Der Filter wird in der Loggingkonfiguration wie folgt eingebunden:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="INFO">
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="%d %-5p %l - %m%n" />
<LoggingMuteFilter />
</Console>
</Appenders>
<Loggers>
<Root level="INFO">
<AppenderRef ref="Console" />
</Root>
</Loggers>
</Configuration>