[LOGMGR-338] When archiving files, do it asynchronously. This allows …

…logging to continue while the file is compressed. https://issues.redhat.com/browse/LOGMGR-338 Signed-off-by: James R. Perkins <[email protected]>
jboss-logging · Jan 18, 2024 · abd0a9e · abd0a9e
1 parent 6862916
commit abd0a9e
Show file tree

Hide file tree

Showing 7 changed files with 147 additions and 18 deletions.
diff --git a/.github/workflows/maven.yml b/.github/workflows/maven.yml
@@ -36,7 +36,7 @@ jobs:
               17
               21
       - name: Build and Test
-        run: mvn -B clean verify "-Djava11.home=${{env.JAVA_HOME_11_X64}}" "-Djava17.home=${{env.JAVA_HOME_17_X64}}"
+        run: mvn -B clean verify "-Djava11.home=${{env.JAVA_HOME_11_X64}}" "-Djava17.home=${{env.JAVA_HOME_17_X64}}" "-Dorg.jboss.test.timeout=60"
       - uses: actions/upload-artifact@v4
         if: failure()
         with:

diff --git a/pom.xml b/pom.xml
@@ -240,6 +240,7 @@
                         <org.jboss.test.address>${org.jboss.test.address}</org.jboss.test.address>
                         <org.jboss.test.port>${org.jboss.test.port}</org.jboss.test.port>
                         <org.jboss.test.alt.port>${org.jboss.test.alt.port}</org.jboss.test.alt.port>
+                        <org.jboss.test.timeout>10</org.jboss.test.timeout>
 
                         <config.dir>${project.build.testOutputDirectory}${file.separator}configs</config.dir>
                     </systemPropertyVariables>

diff --git a/src/main/java/org/jboss/logmanager/handlers/SuffixRotator.java b/src/main/java/org/jboss/logmanager/handlers/SuffixRotator.java
@@ -34,6 +34,9 @@
 import java.text.SimpleDateFormat;
 import java.util.Date;
 import java.util.Locale;
+import java.util.concurrent.CompletableFuture;
+import java.util.concurrent.CompletionStage;
+import java.util.function.Supplier;
 import java.util.logging.ErrorManager;
 import java.util.zip.GZIPOutputStream;
 import java.util.zip.ZipEntry;
@@ -46,6 +49,8 @@
  */
 class SuffixRotator {
 
+    private static final int MAX_FAILED = 100;
+
     /**
      * The compression type for the rotation
      */
@@ -160,20 +165,18 @@ CompressionType getCompressionType() {
      */
     void rotate(final ErrorManager errorManager, final Path source, final String suffix) {
         final Path target = Paths.get(source + suffix + compressionSuffix);
-        if (compressionType == CompressionType.GZIP) {
-            try {
-                archiveGzip(source, target);
-                // Delete the file after it's archived to behave like a file move or rename
-                deleteFile(source);
-            } catch (Exception e) {
-                errorManager.error(String.format("Failed to compress %s to %s. Compressed file may be left on the " +
-                        "filesystem corrupted.", source, target), e, ErrorManager.WRITE_FAILURE);
-            }
-        } else if (compressionType == CompressionType.ZIP) {
+        if (compressionType == CompressionType.GZIP || compressionType == CompressionType.ZIP) {
             try {
-                archiveZip(source, target);
-                // Delete the file after it's archived to behave like a file move or rename
-                deleteFile(source);
+                archive(errorManager, source, target)
+                        .whenComplete((file, error) -> {
+                            if (error != null) {
+                                final Exception e = (error instanceof Exception) ? (Exception) error : new Exception(error);
+                                errorManager.error(
+                                        String.format("Failed to archive file %s. Log file should be available at %s.", source,
+                                                file),
+                                        e, ErrorManager.WRITE_FAILURE);
+                            }
+                        });
             } catch (Exception e) {
                 errorManager.error(String.format("Failed to compress %s to %s. Compressed file may be left on the " +
                         "filesystem corrupted.", source, target), e, ErrorManager.WRITE_FAILURE);
@@ -263,8 +266,63 @@ private void move(final ErrorManager errorManager, final Path src, final Path ta
         }
     }
 
+    private CompletionStage<Path> archive(final ErrorManager errorManager, final Path source, final Path target)
+            throws IOException {
+        // Copy the file to a temporary file
+        final Path temp = Files.createTempFile(source.getFileName().toString(), ".tmp");
+        Files.move(source, temp, StandardCopyOption.REPLACE_EXISTING);
+        // Create the callable for the move
+        final Supplier<Path> task = () -> {
+            try {
+                if (compressionType == CompressionType.GZIP) {
+                    archiveGzip(temp, target);
+                } else if (compressionType == CompressionType.ZIP) {
+                    archiveZip(source.getFileName(), temp, target);
+                } else {
+                    // This should never happen, but in case an error occurs elsewhere, we can't lose logs.
+                    errorManager.error(
+                            String.format("Invalid compression type %s. File preserved at %s.", compressionType, temp), null,
+                            ErrorManager.WRITE_FAILURE);
+                }
+                return target;
+            } catch (Exception e) {
+                // Determine the new target file name
+                final Path dir = source.getParent();
+                Path failedTarget;
+                if (dir == null) {
+                    failedTarget = Path.of(source.getFileName().toString() + ".failed");
+                } else {
+                    failedTarget = dir.resolve(source.getFileName().toString() + ".failed");
+                }
+                final Path root = failedTarget;
+                int index = 0;
+                while (Files.exists(failedTarget)) {
+                    if (dir == null) {
+                        failedTarget = Path.of(root.getFileName().toString() + ++index);
+                    } else {
+                        failedTarget = dir.resolve(root.getFileName().toString() + ++index);
+                    }
+                    if (index >= MAX_FAILED) {
+                        errorManager.error(String.format("The maximum number of failed attempts, %d, as been reached. " +
+                                "No more attempts will be made to rotate the file.", MAX_FAILED), null,
+                                ErrorManager.WRITE_FAILURE);
+                        return temp;
+                    }
+                }
+                try {
+                    return Files.move(temp, failedTarget);
+                } catch (IOException ioe) {
+                    errorManager.error(String.format("Failed to move file %s back to %s.", temp, failedTarget), ioe,
+                            ErrorManager.WRITE_FAILURE);
+                    return temp;
+                }
+            }
+        };
+        return CompletableFuture.supplyAsync(task);
+    }
+
     private void archiveGzip(final Path source, final Path target) throws IOException {
-        final byte[] buff = new byte[512];
+        final byte[] buff = new byte[2048];
         try (final GZIPOutputStream out = new GZIPOutputStream(newOutputStream(target), true)) {
             try (final InputStream in = newInputStream(source)) {
                 int len;
@@ -276,10 +334,10 @@ private void archiveGzip(final Path source, final Path target) throws IOExceptio
         }
     }
 
-    private void archiveZip(final Path source, final Path target) throws IOException {
-        final byte[] buff = new byte[512];
+    private void archiveZip(final Path fileName, final Path source, final Path target) throws IOException {
+        final byte[] buff = new byte[2048];
         try (final ZipOutputStream out = new ZipOutputStream(newOutputStream(target), StandardCharsets.UTF_8)) {
-            final ZipEntry entry = new ZipEntry(source.getFileName().toString());
+            final ZipEntry entry = new ZipEntry(fileName.toString());
             out.putNextEntry(entry);
             try (final InputStream in = newInputStream(source)) {
                 int len;

diff --git a/src/test/java/org/jboss/logmanager/handlers/AbstractHandlerTest.java b/src/test/java/org/jboss/logmanager/handlers/AbstractHandlerTest.java
@@ -33,6 +33,10 @@
 import java.util.Collection;
 import java.util.Collections;
 import java.util.List;
+import java.util.Set;
+import java.util.concurrent.ConcurrentSkipListSet;
+import java.util.concurrent.TimeUnit;
+import java.util.stream.Stream;
 import java.util.zip.GZIPInputStream;
 
 import org.jboss.logmanager.ExtHandler;
@@ -46,10 +50,13 @@
  * @author <a href="mailto:[email protected]">James R. Perkins</a>
  */
 public class AbstractHandlerTest {
+
+    private static final long TIMEOUT;
     static final File BASE_LOG_DIR;
 
     static {
         BASE_LOG_DIR = new File(System.getProperty("log.dir"));
+        TIMEOUT = Long.parseLong(System.getProperty("org.jboss.test.timeout", "10"));
     }
 
     final static PatternFormatter FORMATTER = new PatternFormatter("%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n");
@@ -124,6 +131,53 @@ protected ExtLogRecord createLogRecord(final org.jboss.logmanager.Level level, f
         return new ExtLogRecord(level, String.format(format, args), getClass().getName());
     }
 
+    /**
+     * Waits for all files to be rotated before exiting.
+     *
+     * @param archiveSuffix the type of the archive
+     * @param expectedFiles the files which need to exist
+     *
+     * @throws InterruptedException if an error occurs while waiting
+     */
+    @SuppressWarnings("SameParameterValue")
+    static void waitForRotation(final String archiveSuffix, final Path... expectedFiles) throws InterruptedException {
+        final Set<Path> files = new ConcurrentSkipListSet<>(Set.of(expectedFiles));
+        final long millis = TIMEOUT * 1000L;
+        final Thread task = new Thread(() -> {
+            long t = millis;
+            while (t > 0) {
+                files.removeIf(f -> {
+                    try {
+                        if (Files.exists(f)) {
+                            // Attempt to read the archive, if it ends in an error then we assume the write is not complete
+                            if (".gz".equalsIgnoreCase(archiveSuffix)) {
+                                readAllLinesFromGzip(f);
+                                return true;
+                            }
+                            return isValidZip(f);
+                        }
+                    } catch (Throwable ignore) {
+                        ignore.printStackTrace();
+                    }
+                    return false;
+                });
+                if (files.isEmpty()) {
+                    break;
+                }
+                try {
+                    TimeUnit.MILLISECONDS.sleep(200L);
+                } catch (InterruptedException ignore) {
+                }
+                t -= 200L;
+            }
+        });
+        task.start();
+        task.join();
+        if (!files.isEmpty()) {
+            Assertions.fail(String.format("Failed to find all files within %d seconds. Missing files: %s", TIMEOUT, files));
+        }
+    }
+
     /**
      * Validates that at least one line of the GZIP'd file contains the expected text.
      *
@@ -229,4 +283,17 @@ private static Collection<String> readAllLinesFromGzip(final Path path) throws I
         }
         return lines;
     }
+
+    private static boolean isValidZip(final Path path) {
+        try (
+                final FileSystem zipFs = FileSystems.newFileSystem(URI.create("jar:" + path.toUri().toASCIIString()),
+                        Collections.singletonMap("create", "true"))) {
+            // Simply walk the file stream and assume if there are any entries, the ZIP is fully written
+            try (Stream<Path> files = Files.list(zipFs.getPath("/"))) {
+                return files.findAny().isPresent();
+            }
+        } catch (IOException e) {
+            return false;
+        }
+    }
 }
diff --git a/src/test/java/org/jboss/logmanager/handlers/PeriodicRotatingFileHandlerTests.java b/src/test/java/org/jboss/logmanager/handlers/PeriodicRotatingFileHandlerTests.java
@@ -212,6 +212,7 @@ record = createLogRecord(Level.INFO, "Date: %s", thirdDay);
         final Path logDir = BASE_LOG_DIR.toPath();
         final Path rotated1 = logDir.resolve(FILENAME + firstDateSuffix + archiveSuffix);
         final Path rotated2 = logDir.resolve(FILENAME + secondDateSuffix + archiveSuffix);
+        waitForRotation(archiveSuffix, rotated1, rotated2);
         Assertions.assertTrue(Files.exists(logFile), () -> "Missing file " + logFile);
         Assertions.assertTrue(Files.exists(rotated1), () -> "Missing rotated file " + rotated1);
         Assertions.assertTrue(Files.exists(rotated2), () -> "Missing rotated file " + rotated2);

diff --git a/src/test/java/org/jboss/logmanager/handlers/PeriodicSizeRotatingFileHandlerTests.java b/src/test/java/org/jboss/logmanager/handlers/PeriodicSizeRotatingFileHandlerTests.java
@@ -260,6 +260,7 @@ private void testArchiveRotate(final String dateSuffix, final String archiveSuff
         final Path logDir = BASE_LOG_DIR.toPath();
         final Path path1 = logDir.resolve(FILENAME + currentDate + ".1" + archiveSuffix);
         final Path path2 = logDir.resolve(FILENAME + currentDate + ".2" + archiveSuffix);
+        waitForRotation(archiveSuffix, path1, path2);
         Assertions.assertTrue(logFile.exists());
         Assertions.assertTrue(Files.exists(path1));
         Assertions.assertTrue(Files.exists(path2));

diff --git a/src/test/java/org/jboss/logmanager/handlers/SizeRotatingFileHandlerTests.java b/src/test/java/org/jboss/logmanager/handlers/SizeRotatingFileHandlerTests.java
@@ -259,6 +259,7 @@ private void testArchiveRotate(final String archiveSuffix, final boolean rotateO
         final Path logDir = BASE_LOG_DIR.toPath();
         final Path path1 = logDir.resolve(FILENAME + ".1" + archiveSuffix);
         final Path path2 = logDir.resolve(FILENAME + ".2" + archiveSuffix);
+        waitForRotation(archiveSuffix, path1, path2);
         Assertions.assertTrue(logFile.exists());
         Assertions.assertTrue(Files.exists(path1));
         Assertions.assertTrue(Files.exists(path2));