Stabilized LogFileManager logging and class+method resolution

Signed-off-by: David Matějček <[email protected]>

Author: dmatej

nucleus/glassfish-jul-extension/src/main/java/org/glassfish/main/jul/record/GlassFishLogRecord.java

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022, 2024 Eclipse Foundation and/or its affiliates. All rights reserved.
+ * Copyright (c) 2022, 2025 Contributors to the Eclipse Foundation
  *
  * This program and the accompanying materials are made available under the
  * terms of the Eclipse Public License v. 2.0, which is available at
@@ -54,23 +54,28 @@ public class GlassFishLogRecord extends LogRecord {
      * @param autodetectSource autodetect source class and method
      */
     public GlassFishLogRecord(final Level level, final String message, final boolean autodetectSource) {
-        this(new LogRecord(level, message), autodetectSource);
+        super(level, null);
+        this.threadName = Thread.currentThread().getName();
+        this.record = new LogRecord(level, message);
+        if (autodetectSource) {
+            SourceDetector.detectClassAndMethod(record);
+        } else {
+            // Prevents autodetection done passively by JUL
+            record.setSourceClassName(null);
+            record.setSourceMethodName(null);
+        }
     }
 
 
     /**
      * Wraps the log record.
      *
      * @param record the log record
-     * @param autodetectSource autodetect source class and method
      */
-    public GlassFishLogRecord(final LogRecord record, final boolean autodetectSource) {
+    public GlassFishLogRecord(final LogRecord record) {
         super(record.getLevel(), null);
         this.threadName = Thread.currentThread().getName();
         this.record = record;
-        if (autodetectSource) {
-            SourceDetector.detectClassAndMethod(record);
-        }
     }
 
 
@@ -294,6 +299,7 @@ private static class SourceDetector {
         private static final Set<String> LOGGING_CLASSES = Set.of(
             "org.glassfish.main.jul.GlassFishLogger",
             "org.glassfish.main.jul.GlassFishLoggerWrapper",
+            "org.glassfish.main.jul.rotation.LogFileManager$AsyncLogger",
             // see LogDomains in GlassFish sources
             "com.sun.logging.LogDomainsLogger",
             // remaining classes are in the JDK

nucleus/glassfish-jul-extension/src/main/java/org/glassfish/main/jul/record/MessageResolver.java

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022 Eclipse Foundation and/or its affiliates. All rights reserved.
+ * Copyright (c) 2022, 2025 Contributors to the Eclipse Foundation
  *
  * This program and the accompanying materials are made available under the
  * terms of the Eclipse Public License v. 2.0, which is available at
@@ -85,7 +85,7 @@ private GlassFishLogRecord toGlassFishLogRecord(final LogRecord record) {
         if (GlassFishLogRecord.class.isInstance(record)) {
             return (GlassFishLogRecord) record;
         }
-        return new GlassFishLogRecord(record, false);
+        return new GlassFishLogRecord(record);
     }
 
 

nucleus/glassfish-jul-extension/src/main/java/org/glassfish/main/jul/rotation/LogFileManager.java

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022, 2024 Eclipse Foundation and/or its affiliates. All rights reserved.
+ * Copyright (c) 2022, 2025 Contributors to the Eclipse Foundation
  *
  * This program and the accompanying materials are made available under the
  * terms of the Eclipse Public License v. 2.0, which is available at
@@ -20,19 +20,22 @@
 import java.io.File;
 import java.io.FileOutputStream;
 import java.io.IOException;
-import java.lang.System.Logger;
 import java.nio.charset.Charset;
 import java.nio.file.Files;
 import java.nio.file.StandardCopyOption;
 import java.time.LocalDateTime;
 import java.time.format.DateTimeFormatter;
+import java.util.concurrent.ConcurrentLinkedQueue;
+import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.locks.ReentrantLock;
-import java.util.function.Supplier;
+import java.util.logging.Level;
+import java.util.logging.Logger;
 
+import org.glassfish.main.jul.record.GlassFishLogRecord;
 import org.glassfish.main.jul.tracing.GlassFishLoggingTracer;
 
-import static java.lang.System.Logger.Level.ERROR;
-import static java.lang.System.Logger.Level.INFO;
+import static java.util.logging.Level.INFO;
+import static java.util.logging.Level.SEVERE;
 import static org.glassfish.main.jul.tracing.GlassFishLoggingTracer.trace;
 
 
@@ -49,7 +52,6 @@
  * @author David Matejcek
  */
 public class LogFileManager {
-    private static final Logger LOG = System.getLogger(LogFileManager.class.getName());
 
     private static final DateTimeFormatter SUFFIX_FORMATTER = DateTimeFormatter.ofPattern("yyyy-MM-dd'T'HH-mm-ss");
 
@@ -181,10 +183,9 @@ public void rollIfFileNotEmpty() {
      */
     public void roll() {
         lock.lock();
-        try {
+        try (AsyncLogger logger = new AsyncLogger()) {
             final boolean wasOutputEnabled = isOutputEnabled();
-            logInfoAsync(
-                () -> "Rolling the file " + this.logFile + "; output was originally enabled: " + wasOutputEnabled);
+            logger.logInfo("Rolling the file " + this.logFile + "; output was originally enabled: " + wasOutputEnabled);
             disableOutput();
             File archivedFile = null;
             try {
@@ -193,11 +194,11 @@ public void roll() {
                 }
                 archivedFile = prepareAchivedLogFileTarget();
                 trace(LogFileManager.class, "Archived file: " + archivedFile);
-                moveFile(logFile, archivedFile);
+                moveFile(logFile, archivedFile, logger);
                 forceOSFilesync(logFile);
                 return;
             } catch (Exception e) {
-                logErrorAsync("Error, could not rotate log file " + logFile, e);
+                logger.logError("Error, could not rotate log file " + logFile, e);
             } finally {
                 if (wasOutputEnabled) {
                     enableOutput();
@@ -322,36 +323,23 @@ private void forceOSFilesync(final File file) throws IOException {
     }
 
 
-    private void moveFile(final File logFileToArchive, final File target) throws IOException {
-        logInfoAsync(() -> "Archiving file " + logFileToArchive + " to " + target);
+    private void moveFile(final File logFileToArchive, final File target, final AsyncLogger logger) throws IOException {
+        logger.logInfo("Archiving file " + logFileToArchive + " to " + target);
         try {
             Files.move(logFileToArchive.toPath(), target.toPath(), StandardCopyOption.ATOMIC_MOVE);
         } catch (UnsupportedOperationException | IOException e) {
             // If we don't succeed with file rename which most likely can happen on
             // Windows because of multiple file handles opened. We go through Plan B to
             // copy bytes explicitly to a renamed file.
             // Can happen on some windows file systems - then we try non-atomic version at least.
-            logErrorAsync(String.format(
+            logger.logError(String.format(
                 "File %s could not be renamed to %s atomically, now trying to move it without this request.",
                 logFileToArchive, target), e);
             Files.move(logFileToArchive.toPath(), target.toPath());
         }
     }
 
 
-    /**
-     * This logs in a separate thread to avoid deadlocks. The separate thread can be blocked when
-     * the LogRecordBuffer is full while the LogFileManager is still locked and doesn't process
-     * any records until it finishes rolling the file.
-     * <p>
-     * The count of messages is limited, so we can do this.
-     */
-    private void logInfoAsync(final Supplier<String> message) {
-        trace(getClass(), message);
-        new Thread(() -> LOG.log(INFO, message), "LogFileManager-Async-Info-Logger").start();
-    }
-
-
     /**
      * This logs in a separate thread to avoid deadlocks. The separate thread can be blocked when
      * the LogRecordBuffer is full while the LogFileManager is still locked and doesn't process
@@ -362,8 +350,64 @@ private void logInfoAsync(final Supplier<String> message) {
      * However it is not suitable for all errors - if we cannot write to the file, this would just create
      * another record which could not be written.
      */
-    private void logErrorAsync(final String message, final Exception exception) {
-        GlassFishLoggingTracer.error(getClass(), message, exception);
-        new Thread(() -> LOG.log(ERROR, message, exception), "LogFileManager-Async-Error-Logger").start();
+    private static class AsyncLogger extends Thread implements AutoCloseable {
+
+        private final AtomicBoolean stop;
+        private final ConcurrentLinkedQueue<AsyncLogRecord> queue;
+        private final Logger logger;
+
+        private AsyncLogger() {
+            super("LogFileManagerAsyncLogger");
+            setDaemon(true);
+            this.queue = new ConcurrentLinkedQueue<>();
+            this.stop = new AtomicBoolean();
+            this.logger = Logger.getLogger(LogFileManager.class.getName(), null);
+            start();
+        }
+
+        void logInfo(final String message) {
+            trace(getClass(), message);
+            queue.add(new AsyncLogRecord(INFO, message, null));
+        }
+
+        void logError(final String message, final Exception exception) {
+            GlassFishLoggingTracer.error(getClass(), message, exception);
+            queue.add(new AsyncLogRecord(SEVERE, message, exception));
+        }
+
+        @Override
+        public void close() {
+            this.stop.set(true);
+        }
+
+        @Override
+        public void run() {
+            while(!stop.get()) {
+                drainQueue();
+                Thread.onSpinWait();
+            }
+            drainQueue();
+        }
+
+        private void drainQueue() {
+            while (true) {
+                AsyncLogRecord record = queue.poll();
+                if (record == null) {
+                    break;
+                }
+                logger.log(record);
+            }
+        }
+    }
+
+
+    private static class AsyncLogRecord extends GlassFishLogRecord {
+
+        private static final long serialVersionUID = -8159574547676058852L;
+
+        AsyncLogRecord(Level level, String message, Throwable error) {
+            super(level, message, true);
+            setThrown(error);
+        }
     }
 }

nucleus/glassfish-jul-extension/src/test/java/org/glassfish/main/jul/cfg/LoggingPropertiesTest.java

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022, 2023 Eclipse Foundation and/or its affiliates. All rights reserved.
+ * Copyright (c) 2022, 2025 Contributors to the Eclipse Foundation
  *
  * This program and the accompanying materials are made available under the
  * terms of the Eclipse Public License v. 2.0, which is available at
@@ -38,7 +38,7 @@
  */
 public class LoggingPropertiesTest {
 
-    public static final int PROPERTY_COUNT = 12;
+    public static final int PROPERTY_COUNT = 13;
 
     @Test
     void conversions() throws Exception {

nucleus/glassfish-jul-extension/src/test/java/org/glassfish/main/jul/handler/GlassFishLogHandlerTest.java

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022, 2024 Contributors to the Eclipse Foundation
+ * Copyright (c) 2022, 2025 Contributors to the Eclipse Foundation
  *
  * This program and the accompanying materials are made available under the
  * terms of the Eclipse Public License v. 2.0, which is available at
@@ -157,9 +157,10 @@ public void roll() throws Exception {
             () -> assertTrue(handler.getConfiguration().getLogFile().exists(), "file exists"),
             () -> assertThat("file content", Files.readAllLines(handler.getConfiguration().getLogFile().toPath()),
                 contains(
-                    stringContainsInOrder("INFO", "Rolling the file ", ".log", "output was originally enabled: true"),
-                    stringContainsInOrder("INFO", "Archiving file ", ".log", " to ", ".log_")
-                )
+                    stringContainsInOrder("INFO", "org.glassfish.main.jul.rotation.LogFileManager.roll",
+                        "Rolling the file ", ".log", "output was originally enabled: true"),
+                    stringContainsInOrder("INFO", "org.glassfish.main.jul.rotation.LogFileManager.moveFile",
+                        "Archiving file ", ".log", " to ", ".log_")                )
             )
         );
         handler.publish(new GlassFishLogRecord(Level.SEVERE, "File two, line two", false));

nucleus/glassfish-jul-extension/src/test/java/org/glassfish/main/jul/handler/LoggingPrintStreamTest.java

@@ -98,7 +98,7 @@ public void testPrintStacktrace() throws Exception {
             () -> assertEquals(1L, record.getThreadID()),
             () -> assertEquals(Thread.currentThread().getName(), record.getThreadName()),
             () -> assertSame(exception, record.getThrown()),
-            () -> assertNull(record.getSourceMethodName())
+            () -> assertEquals("testPrintStacktrace", record.getSourceMethodName())
         );
     }
 

nucleus/glassfish-jul-extension/src/test/resources/logging.properties

@@ -5,6 +5,7 @@ java.util.logging.ConsoleHandler.filter=org.glassfish.main.jul.test.TestFilter
 
 org.glassfish.main.jul.handler.GlassFishLogHandler.formatter=org.glassfish.main.jul.formatter.OneLineFormatter
 org.glassfish.main.jul.handler.GlassFishLogHandler.formatter.size.class=1
+org.glassfish.main.jul.handler.GlassFishLogHandler.formatter.printSource=true
 
 .level=FINEST
 org.glassfish.main.jul.GlassFishLogManagerLifeCycleTest.level=FINE