From 5680fcebe03396643172fbc00d1876c3597a3a00 Mon Sep 17 00:00:00 2001 From: Andrei Solntsev Date: Sun, 21 Jul 2024 18:08:48 +0300 Subject: [PATCH] #1306 setup FINE logging in tests * by default, FINE logs are NOT written to console, BUT * if some test failed, all its FINE logs are written to console. Thus we can investigate flaky tests. --- .../datafaker/service/FakeValuesService.java | 2 +- src/test/java/net/datafaker/LogFormatter.java | 21 +++++ .../net/datafaker/TestSetupExtension.java | 80 +++++++++++++++++++ .../net/datafaker/ThreadLocalLogHandler.java | 58 ++++++++++++++ .../org.junit.jupiter.api.extension.Extension | 1 + src/test/resources/junit-platform.properties | 1 + src/test/resources/logging.properties | 7 ++ 7 files changed, 169 insertions(+), 1 deletion(-) create mode 100644 src/test/java/net/datafaker/LogFormatter.java create mode 100644 src/test/java/net/datafaker/TestSetupExtension.java create mode 100644 src/test/java/net/datafaker/ThreadLocalLogHandler.java create mode 100644 src/test/resources/META-INF/services/org.junit.jupiter.api.extension.Extension create mode 100644 src/test/resources/logging.properties diff --git a/src/main/java/net/datafaker/service/FakeValuesService.java b/src/main/java/net/datafaker/service/FakeValuesService.java index ec40cc449..1b16d6416 100644 --- a/src/main/java/net/datafaker/service/FakeValuesService.java +++ b/src/main/java/net/datafaker/service/FakeValuesService.java @@ -52,7 +52,7 @@ public class FakeValuesService { private static final char[] DIGITS = "0123456789".toCharArray(); private static final String[] EMPTY_ARRAY = new String[0]; - private static final Logger LOG = Logger.getLogger("faker"); + private static final Logger LOG = Logger.getLogger(FakeValuesService.class.getName()); public static final Supplier> MAP_STRING_OBJECT_SUPPLIER = () -> new CopyOnWriteMap<>(() -> new WeakHashMap<>()); public static final Supplier> MAP_STRING_STRING_SUPPLIER = () -> new CopyOnWriteMap<>(() -> new WeakHashMap<>()); diff --git a/src/test/java/net/datafaker/LogFormatter.java b/src/test/java/net/datafaker/LogFormatter.java new file mode 100644 index 000000000..2bae07837 --- /dev/null +++ b/src/test/java/net/datafaker/LogFormatter.java @@ -0,0 +1,21 @@ +package net.datafaker; + +import java.time.format.DateTimeFormatter; +import java.util.logging.LogRecord; +import java.util.logging.SimpleFormatter; + +import static java.lang.Thread.currentThread; +import static java.time.ZoneId.systemDefault; + +public class LogFormatter extends SimpleFormatter { + private static final DateTimeFormatter dt = DateTimeFormatter.ofPattern("HH:mm:ss.SSSSSS"); + + @Override + public String format(LogRecord record) { + return "[%s] %s %s".formatted(currentThread().getName(), time(record), super.format(record)); + } + + private static String time(LogRecord record) { + return dt.format(record.getInstant().atZone(systemDefault())); + } +} diff --git a/src/test/java/net/datafaker/TestSetupExtension.java b/src/test/java/net/datafaker/TestSetupExtension.java new file mode 100644 index 000000000..ce0efb5ec --- /dev/null +++ b/src/test/java/net/datafaker/TestSetupExtension.java @@ -0,0 +1,80 @@ +package net.datafaker; + +import org.junit.jupiter.api.extension.AfterAllCallback; +import org.junit.jupiter.api.extension.AfterEachCallback; +import org.junit.jupiter.api.extension.BeforeAllCallback; +import org.junit.jupiter.api.extension.BeforeEachCallback; +import org.junit.jupiter.api.extension.ExtensionContext; +import org.opentest4j.TestAbortedException; + +import java.io.File; +import java.io.IOException; +import java.net.URISyntaxException; +import java.util.TimeZone; +import java.util.concurrent.atomic.AtomicLong; +import java.util.logging.Logger; + +import static java.util.logging.LogManager.getLogManager; + +public class TestSetupExtension implements BeforeAllCallback, AfterAllCallback, BeforeEachCallback, AfterEachCallback { + private static final AtomicLong counter = new AtomicLong(1000); + private static final ExtensionContext.Namespace namespace = ExtensionContext.Namespace.create(TestSetupExtension.class); + + @Override + public void beforeAll(ExtensionContext context) throws IOException, URISyntaxException { + String loggingConfig = new File(getClass().getResource("/logging.properties").toURI()).getAbsolutePath(); + System.setProperty("java.util.logging.config.file", loggingConfig); + getLogManager().readConfiguration(); + + Logger.getLogger(context.getDisplayName()).info(() -> "Starting tests (%s)".formatted(memory())); + } + + @Override + public void afterAll(ExtensionContext context) { + Logger.getLogger(context.getDisplayName()).info(() -> "Finished tests - %s (%s)".formatted(verdict(context), memory())); + } + + @Override + public void beforeEach(ExtensionContext context) { + TimeZone.setDefault(TimeZone.getTimeZone("Asia/Kaohsiung")); + long testId = counter.incrementAndGet(); + context.getStore(namespace).put("test-id", testId); + context.getStore(namespace).put("original-thread-name", Thread.currentThread().getName()); + + Thread.currentThread().setName("%s.%s#%d#".formatted(context.getRequiredTestClass().getSimpleName(), context.getRequiredTestMethod().getName(), testId)); + + Logger.getLogger(context.getRequiredTestClass().getName()).info(() -> "starting %s (%s)...".formatted(context.getDisplayName(), memory())); + ThreadLocalLogHandler.start(); + } + + @Override + public void afterEach(ExtensionContext context) { + ThreadLocalLogHandler.finish(context.getExecutionException().isPresent()); + + Logger.getLogger(context.getRequiredTestClass().getName()) + .info(() -> "finished %s - %s (%s)".formatted(context.getDisplayName(), verdict(context), memory())); + + String originalThreadName = context.getStore(namespace).remove("original-thread-name", String.class); + Thread.currentThread().setName(originalThreadName); + context.getStore(namespace).remove("test-id"); + TimeZone.setDefault(TimeZone.getTimeZone("Asia/Kaohsiung")); + } + + private String verdict(ExtensionContext context) { + return context.getExecutionException().isPresent() ? + (context.getExecutionException().get() instanceof TestAbortedException ? "skipped" : "NOK") : + "OK"; + } + + private String memory() { + long freeMemory = Runtime.getRuntime().freeMemory(); + long maxMemory = Runtime.getRuntime().maxMemory(); + long totalMemory = Runtime.getRuntime().totalMemory(); + long usedMemory = totalMemory - freeMemory; + return "memory used:" + mb(usedMemory) + ", free:" + mb(freeMemory) + ", total:" + mb(totalMemory) + ", max:" + mb(maxMemory); + } + + private long mb(long bytes) { + return bytes / 1024 / 1024; + } +} diff --git a/src/test/java/net/datafaker/ThreadLocalLogHandler.java b/src/test/java/net/datafaker/ThreadLocalLogHandler.java new file mode 100644 index 000000000..333e82bdd --- /dev/null +++ b/src/test/java/net/datafaker/ThreadLocalLogHandler.java @@ -0,0 +1,58 @@ +package net.datafaker; + +import java.util.ArrayList; +import java.util.List; +import java.util.logging.ConsoleHandler; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogRecord; + +import static java.util.logging.Level.INFO; + +public class ThreadLocalLogHandler extends Handler { + private static final ThreadLocal> logs = new ThreadLocal<>(); + private static final ConsoleHandler consoleHandler = new ConsoleHandler(); + + static { + consoleHandler.setLevel(Level.FINE); + } + + @Override + public void publish(LogRecord record) { + if (logs.get() != null) { + logs.get().add(record); + } + } + + @Override + public void flush() { + } + + @Override + public void close() throws SecurityException { + logs.remove(); + } + + static void start() { + logs.set(new ArrayList<>()); + } + + static void finish(boolean writeLogs) { + if (writeLogs) { + List threadLogs = logs.get(); + if (!threadLogs.isEmpty()) { + consoleHandler.publish(summaryLog(threadLogs)); + for (LogRecord log : threadLogs) { + consoleHandler.publish(log); + } + } + } + logs.remove(); + } + + private static LogRecord summaryLog(List logs) { + LogRecord record = new LogRecord(INFO, "Written %d logs during the test:".formatted(logs.size())); + record.setLoggerName(ThreadLocalLogHandler.class.getName()); + return record; + } +} diff --git a/src/test/resources/META-INF/services/org.junit.jupiter.api.extension.Extension b/src/test/resources/META-INF/services/org.junit.jupiter.api.extension.Extension new file mode 100644 index 000000000..58ae7a6ca --- /dev/null +++ b/src/test/resources/META-INF/services/org.junit.jupiter.api.extension.Extension @@ -0,0 +1 @@ +net.datafaker.TestSetupExtension diff --git a/src/test/resources/junit-platform.properties b/src/test/resources/junit-platform.properties index dd6225018..335162567 100644 --- a/src/test/resources/junit-platform.properties +++ b/src/test/resources/junit-platform.properties @@ -1,2 +1,3 @@ junit.jupiter.execution.parallel.enabled=true junit.jupiter.execution.parallel.mode.default=concurrent +junit.jupiter.extensions.autodetection.enabled=true diff --git a/src/test/resources/logging.properties b/src/test/resources/logging.properties new file mode 100644 index 000000000..5078142dc --- /dev/null +++ b/src/test/resources/logging.properties @@ -0,0 +1,7 @@ +handlers=java.util.logging.ConsoleHandler,net.datafaker.ThreadLocalLogHandler + +.level=FINE +java.util.logging.ConsoleHandler.level=INFO +java.util.logging.ConsoleHandler.formatter=net.datafaker.LogFormatter +net.datafaker.ThreadLocalLogHandler.level=FINE +java.util.logging.SimpleFormatter.format=%4$s [%3$s] %5$s%n