[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 <jperkins@redhat.com>

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>

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;

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:jperkins@redhat.com">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;
+ }
+ }
 }

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);

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));

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));