From e87184f8036a9dc81d50012edf6993ba7741a7f2 Mon Sep 17 00:00:00 2001 From: James Perkins Date: Tue, 25 Jul 2017 11:46:51 -0700 Subject: [PATCH] [LOGMGR-154] Allow logging to the handler to continue even if the file rotation fails. --- pom.xml | 30 +++++++++ .../handlers/PeriodicRotatingFileHandler.java | 2 +- .../PeriodicSizeRotatingFileHandler.java | 14 ++-- .../handlers/SizeRotatingFileHandler.java | 8 +-- .../logmanager/handlers/SuffixRotator.java | 65 +++++++++++++------ .../PeriodicRotatingFileHandlerTests.java | 53 ++++++++++++++- .../PeriodicSizeRotatingFileHandlerTests.java | 37 +++++++++++ .../SizeRotatingFileHandlerTests.java | 43 ++++++++++++ 8 files changed, 213 insertions(+), 39 deletions(-) diff --git a/pom.xml b/pom.xml index c11274d9..50fcfab4 100644 --- a/pom.xml +++ b/pom.xml @@ -47,6 +47,7 @@ 1.0 + 3.0.10 1.0.4 1.5.2.Final 1.2.0.Beta10 @@ -90,6 +91,34 @@ + + + org.jboss.byteman + byteman + ${version.org.byteman} + test + + + + org.jboss.byteman + byteman-submit + ${version.org.byteman} + test + + + + org.jboss.byteman + byteman-install + ${version.org.byteman} + test + + + + org.jboss.byteman + byteman-bmunit + ${version.org.byteman} + test + junit junit @@ -116,6 +145,7 @@ **/SyslogTest.java + true org.jboss.logmanager.LogManager ${project.build.directory}${file.separator}logs${file.separator} diff --git a/src/main/java/org/jboss/logmanager/handlers/PeriodicRotatingFileHandler.java b/src/main/java/org/jboss/logmanager/handlers/PeriodicRotatingFileHandler.java index f4894fb2..b5822c11 100644 --- a/src/main/java/org/jboss/logmanager/handlers/PeriodicRotatingFileHandler.java +++ b/src/main/java/org/jboss/logmanager/handlers/PeriodicRotatingFileHandler.java @@ -194,7 +194,7 @@ private void rollOver() { // first, close the original file (some OSes won't let you move/rename a file that is open) setFile(null); // next, rotate it - suffixRotator.rotate(file.toPath(), nextSuffix); + suffixRotator.rotate(getErrorManager(), file.toPath(), nextSuffix); // start new file setFile(file); } catch (IOException e) { diff --git a/src/main/java/org/jboss/logmanager/handlers/PeriodicSizeRotatingFileHandler.java b/src/main/java/org/jboss/logmanager/handlers/PeriodicSizeRotatingFileHandler.java index 10e93bcf..4e171e9d 100644 --- a/src/main/java/org/jboss/logmanager/handlers/PeriodicSizeRotatingFileHandler.java +++ b/src/main/java/org/jboss/logmanager/handlers/PeriodicSizeRotatingFileHandler.java @@ -151,14 +151,10 @@ public void setFile(final File file) throws FileNotFoundException { synchronized (outputLock) { // Check for a rotate if (rotateOnBoot && maxBackupIndex > 0 && file != null && file.exists() && file.length() > 0L) { - try { - final String suffix = getNextSuffix(); - final SuffixRotator suffixRotator = getSuffixRotator(); - if (suffixRotator != SuffixRotator.EMPTY && suffix != null) { - suffixRotator.rotate(file.toPath(), suffix, maxBackupIndex); - } - } catch (IOException e) { - throw new RuntimeException(e); + final String suffix = getNextSuffix(); + final SuffixRotator suffixRotator = getSuffixRotator(); + if (suffixRotator != SuffixRotator.EMPTY && suffix != null) { + suffixRotator.rotate(getErrorManager(), file.toPath(), suffix, maxBackupIndex); } } super.setFile(file); @@ -229,7 +225,7 @@ protected void preWrite(final ExtLogRecord record) { } // close the old file. setFile(null); - getSuffixRotator().rotate(file.toPath(), getNextSuffix(), maxBackupIndex); + getSuffixRotator().rotate(getErrorManager(), file.toPath(), getNextSuffix(), maxBackupIndex); // start with new file. setFile(file); } catch (IOException e) { diff --git a/src/main/java/org/jboss/logmanager/handlers/SizeRotatingFileHandler.java b/src/main/java/org/jboss/logmanager/handlers/SizeRotatingFileHandler.java index 40fd56f2..8e41b953 100644 --- a/src/main/java/org/jboss/logmanager/handlers/SizeRotatingFileHandler.java +++ b/src/main/java/org/jboss/logmanager/handlers/SizeRotatingFileHandler.java @@ -139,11 +139,7 @@ public void setFile(final File file) throws FileNotFoundException { synchronized (outputLock) { // Check for a rotate if (rotateOnBoot && maxBackupIndex > 0 && file != null && file.exists() && file.length() > 0L) { - try { - suffixRotator.rotate(file.toPath(), maxBackupIndex); - } catch (IOException e) { - throw new RuntimeException(e); - } + suffixRotator.rotate(getErrorManager(), file.toPath(), maxBackupIndex); } super.setFile(file); if (outputStream != null) @@ -246,7 +242,7 @@ protected void preWrite(final ExtLogRecord record) { } // close the old file. setFile(null); - suffixRotator.rotate(file.toPath(), maxBackupIndex); + suffixRotator.rotate(getErrorManager(), file.toPath(), maxBackupIndex); // start with new file. setFile(file); } catch (IOException e) { diff --git a/src/main/java/org/jboss/logmanager/handlers/SuffixRotator.java b/src/main/java/org/jboss/logmanager/handlers/SuffixRotator.java index 5a4a7674..8b45633c 100644 --- a/src/main/java/org/jboss/logmanager/handlers/SuffixRotator.java +++ b/src/main/java/org/jboss/logmanager/handlers/SuffixRotator.java @@ -29,6 +29,7 @@ import java.text.SimpleDateFormat; import java.util.Date; import java.util.Locale; +import java.util.logging.ErrorManager; import java.util.zip.GZIPOutputStream; import java.util.zip.ZipEntry; import java.util.zip.ZipOutputStream; @@ -144,19 +145,29 @@ CompressionType getCompressionType() { * is not being used the file is just moved replacing the target file if it already exists. *

* - * @param source the file to be rotated - * @param suffix the suffix to append to the rotated file. - * - * @throws IOException if an error occurs rotating the file + * @param errorManager the error manager used to report errors to, if {@code null} an {@link IOException} will + * be thrown + * @param source the file to be rotated + * @param suffix the suffix to append to the rotated file. */ - void rotate(final Path source, final String suffix) throws IOException { + void rotate(final ErrorManager errorManager, final Path source, final String suffix) { final Path target = Paths.get(source + suffix + compressionSuffix); if (compressionType == CompressionType.GZIP) { - archiveGzip(source, target); + try { + archiveGzip(source, target); + } 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) { - archiveZip(source, target); + try { + archiveZip(source, target); + } 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 { - Files.move(source, target, StandardCopyOption.REPLACE_EXISTING); + move(errorManager, source, target); } } @@ -168,20 +179,20 @@ void rotate(final Path source, final String suffix) throws IOException { * incremented target. The compression suffix, if required, will be appended to this indexed file name. *

* + * @param errorManager the error manager used to report errors to, if {@code null} an {@link IOException} will + * be thrown * @param source the file to be rotated * @param maxBackupIndex the number of backups to keep - * - * @throws IOException if an error occurs rotating the file */ - void rotate(final Path source, final int maxBackupIndex) throws IOException { + void rotate(final ErrorManager errorManager, final Path source, final int maxBackupIndex) { if (formatter == null) { - rotate(source, "", maxBackupIndex); + rotate(errorManager, source, "", maxBackupIndex); } else { final String suffix; synchronized (formatter) { suffix = formatter.format(new Date()); } - rotate(source, suffix, maxBackupIndex); + rotate(errorManager, source, suffix, maxBackupIndex); } } @@ -192,27 +203,32 @@ void rotate(final Path source, final int maxBackupIndex) throws IOException { * incremented target. The compression suffix, if required, will be appended to this indexed file name. *

* + * @param errorManager the error manager used to report errors to, if {@code null} an {@link IOException} will + * be thrown * @param source the file to be rotated * @param suffix the optional suffix to append to the file before the index and optional compression suffix * @param maxBackupIndex the number of backups to keep - * - * @throws IOException if an error occurs rotating the file */ - void rotate(final Path source, final String suffix, final int maxBackupIndex) throws IOException { + void rotate(final ErrorManager errorManager, final Path source, final String suffix, final int maxBackupIndex) { if (maxBackupIndex > 0) { final String rotationSuffix = (suffix == null ? "" : suffix); final String fileWithSuffix = source.toAbsolutePath() + rotationSuffix; - Files.deleteIfExists(Paths.get(fileWithSuffix + "." + maxBackupIndex + compressionSuffix)); + final Path lastFile = Paths.get(fileWithSuffix + "." + maxBackupIndex + compressionSuffix); + try { + Files.deleteIfExists(lastFile); + } catch (Exception e) { + errorManager.error(String.format("Failed to delete file %s", lastFile), e, ErrorManager.GENERIC_FAILURE); + } for (int i = maxBackupIndex - 1; i >= 1; i--) { final Path src = Paths.get(fileWithSuffix + "." + i + compressionSuffix); if (Files.exists(src)) { final Path target = Paths.get(fileWithSuffix + "." + (i + 1) + compressionSuffix); - Files.move(src, target, StandardCopyOption.REPLACE_EXISTING); + move(errorManager, src, target); } } - rotate(source, rotationSuffix + ".1"); + rotate(errorManager, source, rotationSuffix + ".1"); } else if (suffix != null && !suffix.isEmpty()) { - rotate(source, suffix); + rotate(errorManager, source, suffix); } } @@ -221,6 +237,15 @@ public String toString() { return originalSuffix; } + private void move(final ErrorManager errorManager, final Path src, final Path target) { + try { + Files.move(src, target, StandardCopyOption.REPLACE_EXISTING); + } catch (Exception e) { + // Report the error, but allow the rotation to continue + errorManager.error(String.format("Failed to move file %s to %s.", src, target), e, ErrorManager.GENERIC_FAILURE); + } + } + private static void archiveGzip(final Path source, final Path target) throws IOException { final byte[] buff = new byte[512]; diff --git a/src/test/java/org/jboss/logmanager/handlers/PeriodicRotatingFileHandlerTests.java b/src/test/java/org/jboss/logmanager/handlers/PeriodicRotatingFileHandlerTests.java index 8fa996f4..0c40120b 100644 --- a/src/test/java/org/jboss/logmanager/handlers/PeriodicRotatingFileHandlerTests.java +++ b/src/test/java/org/jboss/logmanager/handlers/PeriodicRotatingFileHandlerTests.java @@ -30,16 +30,20 @@ import java.util.Calendar; import java.util.List; +import org.jboss.byteman.contrib.bmunit.BMRule; +import org.jboss.byteman.contrib.bmunit.BMUnitRunner; import org.jboss.logmanager.ExtLogRecord; import org.jboss.logmanager.Level; import org.junit.After; import org.junit.Assert; import org.junit.Before; import org.junit.Test; +import org.junit.runner.RunWith; /** * @author James R. Perkins */ +@RunWith(BMUnitRunner.class) public class PeriodicRotatingFileHandlerTests extends AbstractHandlerTest { private final static String FILENAME = "periodic-rotating-file-handler.log"; @@ -91,6 +95,50 @@ public void testArchiveRotateZip() throws Exception { testArchiveRotate(".zip"); } + @Test + @BMRule(name = "Test failed rotated", + targetClass = "java.nio.file.Files", + targetMethod = "move", + targetLocation = "AT ENTRY", + condition = "$2.getFileName().toString().matches(\"periodic-rotating-file-handler\\.log\\.\\d+\")", + action = "throw new IOException(\"Fail on purpose\")") + public void testFailedRotate() throws Exception { + final Calendar cal = Calendar.getInstance(); + final Path rotatedFile = BASE_LOG_DIR.toPath().resolve(FILENAME + rotateFormatter.format(cal.getTime())); + final SimpleDateFormat sdf = new SimpleDateFormat("yyyy-MM-dd"); + final int currentDay = cal.get(Calendar.DAY_OF_MONTH); + final int nextDay = currentDay + 1; + + final String currentDate = sdf.format(cal.getTime()); + + // Create a log message to be logged + ExtLogRecord record = createLogRecord(Level.INFO, "Date: %s", currentDate); + handler.publish(record); + + Assert.assertTrue("File '" + logFile + "' does not exist", Files.exists(logFile)); + + // Read the contents of the log file and ensure there's only one line + List lines = Files.readAllLines(logFile, StandardCharsets.UTF_8); + Assert.assertEquals("More than 1 line found", 1, lines.size()); + Assert.assertTrue("Expected the line to contain the date: " + currentDate, lines.get(0).contains(currentDate)); + + // Create a new record, increment the day by one. The file should fail rotating, but the contents of the + // log file should contain the new data + cal.add(Calendar.DAY_OF_MONTH, nextDay); + final String nextDate = sdf.format(cal.getTime()); + record = createLogRecord(Level.INFO, "Date: %s", nextDate); + record.setMillis(cal.getTimeInMillis()); + handler.publish(record); + + // Read the contents of the log file and ensure there's only one line + lines = Files.readAllLines(logFile, StandardCharsets.UTF_8); + Assert.assertEquals("More than 1 line found", 1, lines.size()); + Assert.assertTrue("Expected the line to contain the date: " + nextDate, lines.get(0).contains(nextDate)); + + // The file should not have been rotated + Assert.assertTrue("The rotated file '" + rotatedFile.toString() + "' exists and should not", Files.notExists(rotatedFile)); + } + private void testRotate(final Calendar cal, final Path rotatedFile) throws Exception { final SimpleDateFormat sdf = new SimpleDateFormat("yyyy-MM-dd"); @@ -105,7 +153,7 @@ private void testRotate(final Calendar cal, final Path rotatedFile) throws Excep Assert.assertTrue("File '" + logFile + "' does not exist", Files.exists(logFile)); - // Read the contents of the log file and ensure there's only one line and that like + // Read the contents of the log file and ensure there's only one line List lines = Files.readAllLines(logFile, StandardCharsets.UTF_8); Assert.assertEquals("More than 1 line found", 1, lines.size()); Assert.assertTrue("Expected the line to contain the date: " + currentDate, lines.get(0).contains(currentDate)); @@ -117,9 +165,8 @@ record = createLogRecord(Level.INFO, "Date: %s", nextDate); record.setMillis(cal.getTimeInMillis()); handler.publish(record); - // Read the contents of the log file and ensure there's only one line and that like + // Read the contents of the log file and ensure there's only one line lines = Files.readAllLines(logFile, StandardCharsets.UTF_8); - System.out.println(lines); Assert.assertEquals("More than 1 line found", 1, lines.size()); Assert.assertTrue("Expected the line to contain the date: " + nextDate, lines.get(0).contains(nextDate)); diff --git a/src/test/java/org/jboss/logmanager/handlers/PeriodicSizeRotatingFileHandlerTests.java b/src/test/java/org/jboss/logmanager/handlers/PeriodicSizeRotatingFileHandlerTests.java index 3f4a29f1..2c4159d2 100644 --- a/src/test/java/org/jboss/logmanager/handlers/PeriodicSizeRotatingFileHandlerTests.java +++ b/src/test/java/org/jboss/logmanager/handlers/PeriodicSizeRotatingFileHandlerTests.java @@ -20,6 +20,7 @@ package org.jboss.logmanager.handlers; import java.io.File; +import java.nio.charset.StandardCharsets; import java.nio.file.Files; import java.nio.file.Path; import java.text.SimpleDateFormat; @@ -31,14 +32,18 @@ import java.util.List; import java.util.Map; +import org.jboss.byteman.contrib.bmunit.BMRule; +import org.jboss.byteman.contrib.bmunit.BMUnitRunner; import org.jboss.logmanager.ExtLogRecord; import org.junit.Assert; import org.junit.Ignore; import org.junit.Test; +import org.junit.runner.RunWith; /** * @author James R. Perkins */ +@RunWith(BMUnitRunner.class) public class PeriodicSizeRotatingFileHandlerTests extends AbstractHandlerTest { private final static String FILENAME = "rotating-file-handler.log"; @@ -198,6 +203,38 @@ public void testArchiveRotateSizeOnlyZip() throws Exception { testArchiveRotate(null,".zip"); } + @Test + @BMRule(name = "Test failed rotated", + targetClass = "java.nio.file.Files", + targetMethod = "move", + targetLocation = "AT ENTRY", + condition = "$2.getFileName().toString().equals(\"rotating-file-handler.log.2\")", + action = "throw new IOException(\"Fail on purpose\")") + public void testFailedRotate() throws Exception { + final PeriodicSizeRotatingFileHandler handler = new PeriodicSizeRotatingFileHandler(); + configureHandlerDefaults(handler); + handler.setRotateSize(1024L); + handler.setMaxBackupIndex(5); + handler.setFile(logFile); + + // Allow a few rotates + for (int i = 0; i < 100; i++) { + handler.publish(createLogRecord("Test message: %d", i)); + } + + handler.close(); + + // The log file should exist, as should one rotated file since we fail the rotation on the second rotate + Assert.assertTrue(String.format("Expected log file %s to exist", logFile), logFile.exists()); + final Path rotatedFile = BASE_LOG_DIR.toPath().resolve(FILENAME + ".1"); + Assert.assertTrue(String.format("Expected rotated file %s to exist", rotatedFile), Files.exists(rotatedFile)); + + // The last line of the log file should end with "99" as it should be the last record + final List lines = Files.readAllLines(logFile.toPath(), StandardCharsets.UTF_8); + final String lastLine = lines.get(lines.size() - 1); + Assert.assertTrue("Expected the last line to end with 99: " + lastLine, lastLine.endsWith("99")); + } + private void testArchiveRotate(final String dateSuffix, final String archiveSuffix) throws Exception { final String currentDate = dateSuffix == null ? "" : LocalDate.now().format(DateTimeFormatter.ofPattern(dateSuffix)); PeriodicSizeRotatingFileHandler handler = new PeriodicSizeRotatingFileHandler(); diff --git a/src/test/java/org/jboss/logmanager/handlers/SizeRotatingFileHandlerTests.java b/src/test/java/org/jboss/logmanager/handlers/SizeRotatingFileHandlerTests.java index 035504bf..7358e51e 100644 --- a/src/test/java/org/jboss/logmanager/handlers/SizeRotatingFileHandlerTests.java +++ b/src/test/java/org/jboss/logmanager/handlers/SizeRotatingFileHandlerTests.java @@ -20,17 +20,23 @@ package org.jboss.logmanager.handlers; import java.io.File; +import java.nio.charset.StandardCharsets; import java.nio.file.Files; import java.nio.file.Path; import java.text.SimpleDateFormat; import java.util.Date; +import java.util.List; +import org.jboss.byteman.contrib.bmunit.BMRule; +import org.jboss.byteman.contrib.bmunit.BMUnitRunner; import org.junit.Assert; import org.junit.Test; +import org.junit.runner.RunWith; /** * @author James R. Perkins */ +@RunWith(BMUnitRunner.class) public class SizeRotatingFileHandlerTests extends AbstractHandlerTest { private final static String FILENAME = "rotating-file-handler.log"; @@ -148,6 +154,7 @@ public void testBootRotate() throws Exception { // Clean up files rotatedFile.delete(); } + @Test public void testArchiveRotateGzip() throws Exception { testArchiveRotate(".gz"); @@ -158,6 +165,42 @@ public void testArchiveRotateZip() throws Exception { testArchiveRotate(".zip"); } + /** + * Note we only test a failed rotation on the SizeRotatingFileHandler. The type of the rotation, e.g. periodic vs + * size, shouldn't matter as each uses the same rotation logic in the SuffixRotator. + */ + @Test + @BMRule(name = "Test failed rotated", + targetClass = "java.nio.file.Files", + targetMethod = "move", + targetLocation = "AT ENTRY", + condition = "$2.getFileName().toString().equals(\"rotating-file-handler.log.2\")", + action = "throw new IOException(\"Fail on purpose\")") + public void testFailedRotate() throws Exception { + final SizeRotatingFileHandler handler = new SizeRotatingFileHandler(); + configureHandlerDefaults(handler); + handler.setRotateSize(1024L); + handler.setMaxBackupIndex(5); + handler.setFile(logFile); + + // Allow a few rotates + for (int i = 0; i < 100; i++) { + handler.publish(createLogRecord("Test message: %d", i)); + } + + handler.close(); + + // The log file should exist, as should one rotated file since we fail the rotation on the second rotate + Assert.assertTrue(String.format("Expected log file %s to exist", logFile), logFile.exists()); + final Path rotatedFile = BASE_LOG_DIR.toPath().resolve(FILENAME + ".1"); + Assert.assertTrue(String.format("Expected rotated file %s to exist", rotatedFile), Files.exists(rotatedFile)); + + // The last line of the log file should end with "99" as it should be the last record + final List lines = Files.readAllLines(logFile.toPath(), StandardCharsets.UTF_8); + final String lastLine = lines.get(lines.size() - 1); + Assert.assertTrue("Expected the last line to end with 99: " + lastLine, lastLine.endsWith("99")); + } + private void testArchiveRotate(final String archiveSuffix) throws Exception { final SizeRotatingFileHandler handler = new SizeRotatingFileHandler(); configureHandlerDefaults(handler);