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

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>> MAP_STRING_OBJECT_SUPPLIER = () -> new CopyOnWriteMap<>(() -> new WeakHashMap<>());
     public static final Supplier<Map<String, String>> MAP_STRING_STRING_SUPPLIER = () -> new CopyOnWriteMap<>(() -> new WeakHashMap<>());
 

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()));
+    }
+}

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;
+  }
+}

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<List<LogRecord>> 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<LogRecord> threadLogs = logs.get();
+            if (!threadLogs.isEmpty()) {
+                consoleHandler.publish(summaryLog(threadLogs));
+                for (LogRecord log : threadLogs) {
+                    consoleHandler.publish(log);
+                }
+            }
+        }
+        logs.remove();
+    }
+
+    private static LogRecord summaryLog(List<LogRecord> logs) {
+        LogRecord record = new LogRecord(INFO, "Written %d logs during the test:".formatted(logs.size()));
+        record.setLoggerName(ThreadLocalLogHandler.class.getName());
+        return record;
+    }
+}

src/test/resources/META-INF/services/org.junit.jupiter.api.extension.Extension

@@ -0,0 +1 @@
+net.datafaker.TestSetupExtension

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

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