Skip to content

Commit

Permalink
Fixes #25349 Ensure order of logged messages, fix a few flaky tests
Browse files Browse the repository at this point in the history
  • Loading branch information
@OndroMih
OndroMih committed Feb 5, 2025
1 parent bf6d3ce commit d0a0c4c
Show file tree
Hide file tree
Showing 3 changed files with 36 additions and 33 deletions.
41 changes: 18 additions & 23 deletions ...glassfish-jul-extension/src/main/java/org/glassfish/main/jul/rotation/LogFileManager.java
View file
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
/*
* Copyright (c) 2022, 2024 Eclipse Foundation and/or its affiliates. All rights reserved.
* Copyright (c) 2022, 2025 Eclipse Foundation and/or its affiliates. All rights reserved.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License v. 2.0, which is available at
Expand All @@ -13,7 +13,6 @@
*
* SPDX-License-Identifier: EPL-2.0 OR GPL-2.0 WITH Classpath-exception-2.0
*/

package org.glassfish.main.jul.rotation;

import java.io.BufferedOutputStream;
Expand All @@ -26,6 +25,10 @@
import java.nio.file.StandardCopyOption;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.LinkedBlockingQueue;
import java.util.concurrent.ThreadPoolExecutor;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.ReentrantLock;
import java.util.function.Supplier;

Expand All @@ -35,7 +38,6 @@
import static java.lang.System.Logger.Level.INFO;
import static org.glassfish.main.jul.tracing.GlassFishLoggingTracer.trace;


/**
* Manages the logging file, it's rotations, packing of rolled log file, etc.
* <p>
Expand All @@ -49,6 +51,7 @@
* @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");
Expand All @@ -61,6 +64,13 @@ public class LogFileManager {

private MeteredFileWriter writer;

private final ExecutorService sequentialExecutor = createSequentialExecutor();

private static ExecutorService createSequentialExecutor() {
final ThreadPoolExecutor executor = new ThreadPoolExecutor(1, 1, 100, TimeUnit.MILLISECONDS, new LinkedBlockingQueue<>());
executor.allowCoreThreadTimeOut(true);
return executor;
}

/**
* Creates the manager and initializes it with given parameters. It only creates the manager but
Expand All @@ -76,15 +86,14 @@ public class LogFileManager {
* crosses this value, old files will be permanently deleted.
*/
public LogFileManager(final File logFile, Charset fileEncoding, //
final long maxFileSize, final boolean compressOldLogFiles, final int maxCountOfOldLogFiles //
final long maxFileSize, final boolean compressOldLogFiles, final int maxCountOfOldLogFiles //
) {
this.logFile = logFile;
this.fileEncoding = fileEncoding;
this.maxFileSize = maxFileSize;
this.archiver = new LogFileArchiver(logFile, compressOldLogFiles, maxCountOfOldLogFiles);
}


/**
* Writes the text to the log file.
*
Expand All @@ -107,7 +116,6 @@ public void write(String text) throws IllegalStateException {
}
}


/**
* Flushed the file writer and if the file is too large, rolls the file.
*/
Expand All @@ -127,7 +135,6 @@ public void flush() {
}
}


/**
* @return the size of the logFile in bytes. The value is obtained from the outputstream, only
* if the output stream is closed, this method will check the file system.
Expand All @@ -141,7 +148,6 @@ public long getFileSize() {
}
}


/**
* Calls {@link #roll()} if the file is bigger than limit given in constructor.
*/
Expand All @@ -156,7 +162,6 @@ public void rollIfFileTooBig() {
}
}


/**
* Calls {@link #roll()} if the file is not empty.
*/
Expand All @@ -171,7 +176,6 @@ public void rollIfFileNotEmpty() {
}
}


/**
* Rolls the file regardless of it's size and if it is currently used for output.
* <p>
Expand Down Expand Up @@ -211,7 +215,6 @@ public void roll() {
}
}


/**
* @return true if the handler owning this instance can write to the outputstream.
*/
Expand All @@ -224,7 +227,6 @@ public boolean isOutputEnabled() {
}
}


/**
* Creates the file, initializes the MeteredStream and calls the stream setter given in
* constructor.
Expand Down Expand Up @@ -258,7 +260,6 @@ public void enableOutput() {
}
}


/**
* Calls the close method given in constructor, then closes the output stream.
* <p>
Expand All @@ -283,7 +284,6 @@ public void disableOutput() {
}
}


private boolean isRollFileSizeLimitReached() {
if (this.maxFileSize <= 0) {
return false;
Expand All @@ -292,7 +292,6 @@ private boolean isRollFileSizeLimitReached() {
return fileSize >= this.maxFileSize;
}


private File prepareAchivedLogFileTarget() {
final String archivedFileNameBase = logFile.getName() + "_" + SUFFIX_FORMATTER.format(LocalDateTime.now());
int counter = 1;
Expand All @@ -309,7 +308,6 @@ private File prepareAchivedLogFileTarget() {
}
}


/**
* Make sure that server.log contents are flushed out to start from a clean file again after
* the rename...
Expand All @@ -321,7 +319,6 @@ private void forceOSFilesync(final File file) throws IOException {
new FileOutputStream(file).close();
}


private void moveFile(final File logFileToArchive, final File target) throws IOException {
logInfoAsync(() -> "Archiving file " + logFileToArchive + " to " + target);
try {
Expand All @@ -332,13 +329,12 @@ private void moveFile(final File logFileToArchive, final File target) throws IOE
// 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(
"File %s could not be renamed to %s atomically, now trying to move it without this request.",
logFileToArchive, target), e);
"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
Expand All @@ -348,10 +344,9 @@ private void moveFile(final File logFileToArchive, final File target) throws IOE
*/
private void logInfoAsync(final Supplier<String> message) {
trace(getClass(), message);
new Thread(() -> LOG.log(INFO, message), "LogFileManager-Async-Info-Logger").start();
sequentialExecutor.submit(()-> LOG.log(INFO, message), "LogFileManager-Async-Info-Logger");
}


/**
* 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
Expand All @@ -364,6 +359,6 @@ private void logInfoAsync(final Supplier<String> message) {
*/
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();
sequentialExecutor.submit(() -> LOG.log(ERROR, message, exception), "LogFileManager-Async-Error-Logger");
}
}
8 changes: 6 additions & 2 deletions ...-jul-extension/src/test/java/org/glassfish/main/jul/GlassFishLogManagerLifeCycleTest.java
View file
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
/*
* Copyright (c) 2022, 2024 Eclipse Foundation and/or its affiliates. All rights reserved.
* Copyright (c) 2022, 2025 Eclipse Foundation and/or its affiliates. All rights reserved.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License v. 2.0, which is available at
Expand All @@ -18,6 +18,8 @@

import java.util.List;
import java.util.concurrent.CompletableFuture;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicBoolean;
import java.util.logging.Level;
Expand Down Expand Up @@ -71,6 +73,7 @@ public class GlassFishLogManagerLifeCycleTest {
private static GlassFishLogManagerConfiguration originalCfg;
private static boolean originalLevelResolution;
private static CompletableFuture<Void> process;
private ExecutorService sequentialExecutor = Executors.newSingleThreadExecutor();

@BeforeAll
public static void backupConfiguration() {
Expand Down Expand Up @@ -133,6 +136,7 @@ public void startReconfiguration() throws Exception {
() -> assertEquals(GlassFishLoggingStatus.CONFIGURING, MANAGER.getLoggingStatus()),
() -> assertNull(COLLECTOR.pop(), "COLLECTOR should be empty after reconfiguration started"));
doLog(Level.INFO, "Log after reconfiguration started", 0);
Thread.sleep(10L);
assertNull(COLLECTOR.pop(), "COLLECTOR should be empty after reconfiguration started even if we log again");
}

Expand Down Expand Up @@ -269,7 +273,7 @@ private void reconfigureToBlockingHandler() {
* @throws Exception
*/
private void doLog(final Level level, final String message, final int sleepMillis) throws Exception {
new Thread(() -> LOG.log(level, message)).start();
sequentialExecutor.submit(() -> LOG.log(level, message));
if (sleepMillis > 0) {
Thread.sleep(sleepMillis);
}
Expand Down
20 changes: 12 additions & 8 deletions ...h-jul-extension/src/test/java/org/glassfish/main/jul/handler/GlassFishLogHandlerTest.java
View file
Original file line number Diff line number Diff line change
@@ -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
Expand All @@ -18,6 +18,7 @@

import java.io.File;
import java.nio.file.Files;
import java.util.List;
import java.util.logging.Level;
import java.util.logging.LogManager;
import java.util.logging.Logger;
Expand Down Expand Up @@ -134,12 +135,14 @@ public void enableStandardStreamsLoggers(TestInfo testInfo) throws Exception {
public void roll() throws Exception {
assertTrue(handler.isReady(), "handler.ready");
handler.publish(new GlassFishLogRecord(Level.SEVERE, "File one, record one", false));
final File logFile = handler.getConfiguration().getLogFile();
// pump is now to play
Thread.sleep(MILLIS_FOR_PUMP);
final List<String> fileLines1 = Files.readAllLines(logFile.toPath());
assertAll(
() -> assertTrue(handler.isReady(), "handler.ready"),
() -> assertTrue(handler.getConfiguration().getLogFile().exists(), "file one exists"),
() -> assertThat("file content", Files.readAllLines(handler.getConfiguration().getLogFile().toPath()),
() -> assertTrue(logFile.exists(), "file one exists"),
() -> assertThat("file content, filename=" + logFile + ", content=" + fileLines1 , fileLines1,
contains(
stringContainsInOrder("INFO", "main", "Tommy, can you hear me?"),
stringContainsInOrder("INFO", "main", "Some info message"),
Expand All @@ -152,10 +155,11 @@ public void roll() throws Exception {
handler.roll();
// There will be an asynchronous thread.
Thread.sleep(10L);
final List<String> fileLines2 = Files.readAllLines(logFile.toPath());
assertAll(
() -> assertTrue(handler.isReady(), "handler.ready"),
() -> assertTrue(handler.getConfiguration().getLogFile().exists(), "file exists"),
() -> assertThat("file content", Files.readAllLines(handler.getConfiguration().getLogFile().toPath()),
() -> assertTrue(logFile.exists(), "file exists"),
() -> assertThat("file content, filename=" + logFile + ", content=" + fileLines2 , fileLines2,
contains(
stringContainsInOrder("INFO", "Rolling the file ", ".log", "output was originally enabled: true"),
stringContainsInOrder("INFO", "Archiving file ", ".log", " to ", ".log_")
Expand All @@ -164,10 +168,11 @@ public void roll() throws Exception {
);
handler.publish(new GlassFishLogRecord(Level.SEVERE, "File two, line two", false));
Thread.sleep(MILLIS_FOR_PUMP);
final List<String> fileLines3 = Files.readAllLines(logFile.toPath());
assertAll(
() -> assertTrue(handler.isReady(), "handler.ready"),
() -> assertTrue(handler.getConfiguration().getLogFile().exists(), "file exists"),
() -> assertThat("file content", Files.readAllLines(handler.getConfiguration().getLogFile().toPath()),
() -> assertTrue(logFile.exists(), "file exists"),
() -> assertThat("file content, filename=" + logFile + ", content=" + fileLines3 , fileLines3,
contains(
stringContainsInOrder("INFO", "Rolling the file ", ".log", "output was originally enabled: true"),
stringContainsInOrder("INFO", "Archiving file ", ".log", " to ", ".log_"),
Expand All @@ -177,7 +182,6 @@ public void roll() throws Exception {
);
}


@Test
@Order(50)
public void disabledlogStandardStreams() throws Exception {
Expand Down

0 comments on commit d0a0c4c

Please sign in to comment.