Merge pull request #126 from jamezp/LOGMGR-154

[LOGMGR-154] Allow logging to the handler to continue even if the fil…

pom.xml

@@ -47,6 +47,7 @@
     <properties>
         <!-- Dependency versions -->
         <version.javax.json>1.0</version.javax.json>
+        <version.org.byteman>3.0.10</version.org.byteman>
         <version.org.glassfish.javax.json>1.0.4</version.org.glassfish.javax.json>
         <version.org.jboss.modules.jboss-modules>1.5.2.Final</version.org.jboss.modules.jboss-modules>
         <version.org.wildfly.common.wildfly-common>1.2.0.Beta10</version.org.wildfly.common.wildfly-common>
@@ -90,6 +91,34 @@
         </dependency>
 
         <!-- test dependencies -->
+
+        <dependency>
+            <groupId>org.jboss.byteman</groupId>
+            <artifactId>byteman</artifactId>
+            <version>${version.org.byteman}</version>
+            <scope>test</scope>
+        </dependency>
+
+        <dependency>
+            <groupId>org.jboss.byteman</groupId>
+            <artifactId>byteman-submit</artifactId>
+            <version>${version.org.byteman}</version>
+            <scope>test</scope>
+        </dependency>
+
+        <dependency>
+            <groupId>org.jboss.byteman</groupId>
+            <artifactId>byteman-install</artifactId>
+            <version>${version.org.byteman}</version>
+            <scope>test</scope>
+        </dependency>
+
+        <dependency>
+            <groupId>org.jboss.byteman</groupId>
+            <artifactId>byteman-bmunit</artifactId>
+            <version>${version.org.byteman}</version>
+            <scope>test</scope>
+        </dependency>
         <dependency>
             <groupId>junit</groupId>
             <artifactId>junit</artifactId>
@@ -116,6 +145,7 @@
                         <exclude>**/SyslogTest.java</exclude>
                     </excludes>
                     <systemPropertyVariables>
+                        <jdk.attach.allowAttachSelf>true</jdk.attach.allowAttachSelf>
                         <java.util.logging.manager>org.jboss.logmanager.LogManager</java.util.logging.manager>
                         <test.log.dir>${project.build.directory}${file.separator}logs${file.separator}</test.log.dir>
                     </systemPropertyVariables>

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

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

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

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.
      * </p>
      *
-     * @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.
      * </p>
      *
+     * @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.
      * </p>
      *
+     * @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];

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 <a href="mailto:jperkins@redhat.com">James R. Perkins</a>
  */
+@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<String> 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<String> 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));
 

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 <a href="mailto:jperkins@redhat.com">James R. Perkins</a>
  */
+@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<String> 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();