Test compression on logrotate and correct visibility and cleanup unused code.

2 files changed, 94 insertions, 68 deletions

diff --git a/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java b/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java
index 8220f715b92..56af8be722a 100644
--- a/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java
+++ b/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java
@@ -10,11 +10,12 @@ import java.io.FileOutputStream;
 import java.io.IOException;
 import java.io.OutputStream;
 import java.util.ArrayList;
+import java.util.Arrays;
 import java.util.concurrent.ArrayBlockingQueue;
 import java.util.concurrent.TimeUnit;
-import java.util.logging.Formatter;
 import java.util.logging.Level;
 import java.util.logging.LogRecord;
+import java.util.logging.Logger;
 import java.util.logging.StreamHandler;
 import java.util.regex.Matcher;
 import java.util.regex.Pattern;
@@ -31,6 +32,7 @@ import java.util.regex.Pattern;
  */
 public class LogFileHandler extends StreamHandler {
 
+    private final static Logger logger = Logger.getLogger(LogFileHandler.class.getName());
     /** True to use the sequence file name scheme, false (default) to use the date scheme */
     private final boolean useSequenceNameScheme;
     private final boolean compressOnRotation;
@@ -43,12 +45,12 @@ public class LogFileHandler extends StreamHandler {
     private String fileName;
     private String symlinkName = null;
     private ArrayBlockingQueue<LogRecord> logQueue = new ArrayBlockingQueue<>(100000);
-    LogRecord rotateCmd = new LogRecord(Level.SEVERE, "rotateNow");
+    private LogRecord rotateCmd = new LogRecord(Level.SEVERE, "rotateNow");
 
     static private class LogThread extends Thread {
         LogFileHandler logFileHandler;
         long lastFlush = 0;
-        public LogThread(LogFileHandler logFile) {
+        LogThread(LogFileHandler logFile) {
             super("Logger");
             setDaemon(true);
             logFileHandler = logFile;
@@ -90,46 +92,21 @@ public class LogFileHandler extends StreamHandler {
             }
         }
     }
-    LogThread logThread = null;
+    private final LogThread logThread;
 
-    public LogFileHandler() {
+    LogFileHandler() {
         this(AccessLogConfig.FileHandler.RotateScheme.Enum.DATE, false);
     }
 
-    public LogFileHandler(boolean compressOnRotation) {
+    LogFileHandler(boolean compressOnRotation) {
         this(AccessLogConfig.FileHandler.RotateScheme.Enum.DATE, compressOnRotation);
     }
 
-    public LogFileHandler(AccessLogConfig.FileHandler.RotateScheme.Enum rotateScheme) {
-        this(rotateScheme, false);
-    }
-
-    public LogFileHandler(AccessLogConfig.FileHandler.RotateScheme.Enum rotateScheme,
-                          boolean compressOnRotation)
+    LogFileHandler(AccessLogConfig.FileHandler.RotateScheme.Enum rotateScheme, boolean compressOnRotation)
     {
         super();
         this.useSequenceNameScheme = (rotateScheme == AccessLogConfig.FileHandler.RotateScheme.Enum.SEQUENCE);
         this.compressOnRotation = compressOnRotation;
-        init();
-    }
-
-    /**
-     * Constructs a log handler
-     *
-     * @param useSequenceNameScheme True to use the sequence file name scheme, false (default) to use the date scheme
-     */
-    public LogFileHandler(OutputStream out, Formatter formatter, boolean useSequenceNameScheme) {
-        this(out, formatter, useSequenceNameScheme, false);
-    }
-
-    public LogFileHandler(OutputStream out, Formatter formatter, boolean useSequenceNameScheme, boolean compressOnRotation) {
-        super(out, formatter);
-        this.useSequenceNameScheme = useSequenceNameScheme;
-        this.compressOnRotation = compressOnRotation;
-        init();
-    }
-
-    private void init() {
         logThread = new LogThread(this);
         logThread.start();
     }
@@ -167,7 +144,7 @@ public class LogFileHandler extends StreamHandler {
      *
      * @param pattern See LogFormatter for definition
      */
-    public void setFilePattern ( String pattern ) {
+    void setFilePattern ( String pattern ) {
         filePattern = pattern;
     }
 
@@ -177,7 +154,7 @@ public class LogFileHandler extends StreamHandler {
      * @param timesOfDay in millis, from midnight
      *
      */
-    public void setRotationTimes ( long[] timesOfDay ) {
+    void setRotationTimes ( long[] timesOfDay ) {
         rotationTimes = timesOfDay;
     }
 
@@ -185,7 +162,7 @@ public class LogFileHandler extends StreamHandler {
      *
      * @param prescription string form of times, in minutes
      */
-    public void setRotationTimes ( String prescription ) {
+    void setRotationTimes ( String prescription ) {
         setRotationTimes(calcTimesMinutes(prescription));
     }
 
@@ -195,7 +172,7 @@ public class LogFileHandler extends StreamHandler {
      * @param now the specified time; if zero, current time is used.
      * @return the next rotation time
      */
-    public long getNextRotationTime (long now) {
+    long getNextRotationTime (long now) {
         if (now <= 0) {
             now = System.currentTimeMillis();
         }
@@ -214,7 +191,17 @@ public class LogFileHandler extends StreamHandler {
         return next;
     }
 
-    private void checkAndCreateDir(String pathname) throws IOException {
+    void waitDrained() {
+        while(! logQueue.isEmpty()) {
+            try {
+                Thread.sleep(1);
+            } catch (InterruptedException e) {
+            }
+        }
+        super.flush();
+    }
+
+    private void checkAndCreateDir(String pathname) {
       int lastSlash = pathname.lastIndexOf("/");
       if (lastSlash > -1) {
           String pathExcludingFilename = pathname.substring(0, lastSlash);
@@ -228,7 +215,7 @@ public class LogFileHandler extends StreamHandler {
     /**
      * Force file rotation now, independent of schedule.
      */
-    public void rotateNow () {
+    void rotateNow () {
         publish(rotateCmd);
     }
 
@@ -278,12 +265,12 @@ public class LogFileHandler extends StreamHandler {
     }
 
     private void triggerCompression(File oldFile) throws InterruptedException {
+        String oldFileName = oldFile.getPath();
+        String gzippedFileName = oldFileName + ".gz";
+        StringBuilder cmd = new StringBuilder("gzip");
+        cmd.append(" < "). append(oldFileName).append(" > ").append(gzippedFileName);
+        Runtime r = Runtime.getRuntime();
         try {
-            String oldFileName = oldFile.getPath();
-            String gzippedFileName = oldFileName + ".gz";
-            Runtime r = Runtime.getRuntime();
-            StringBuilder cmd = new StringBuilder("gzip");
-            cmd.append(" < "). append(oldFileName).append(" > ").append(gzippedFileName);
             Process p = r.exec(cmd.toString());
             // Detonator pattern: Think of all the fun we can have if gzip isn't what we
             // think it is, if it doesn't return, etc, etc
@@ -294,10 +281,11 @@ public class LogFileHandler extends StreamHandler {
             if (retval == 0) {
                 oldFile.delete();
                 nativeIO.dropFileFromCache(new File(gzippedFileName));
+            } else {
+                logger.warning("Command '" + cmd.toString() + "' + failed with exitcode=" + retval);
             }
-
         } catch (IOException e) {
-            // little we can do...
+            logger.warning("Got '" + e + "' while doing'" + cmd + "'.");
         }
     }
 
@@ -306,14 +294,25 @@ public class LogFileHandler extends StreamHandler {
         if (symlinkName == null) return;
         File f = new File(fileName);
         File f2 = new File(f.getParent(), symlinkName);
+        String canonicalPath;
+        try {
+            canonicalPath = f.getCanonicalPath();
+        } catch (IOException e) {
+            logger.warning("Got '" + e + "' while doing f.getCanonicalPath() on file '" + f.getPath() + "'.");
+            return;
+        }
+        String [] cmd = new String[]{"/bin/ln", "-sf", canonicalPath, f2.getPath()};
         try {
             Runtime r = Runtime.getRuntime();
-            Process p = r.exec(new String[] { "/bin/ln", "-sf", f.getCanonicalPath(), f2.getPath() });
+            Process p = r.exec(cmd);
             // Detonator pattern: Think of all the fun we can have if ln isn't what we
             // think it is, if it doesn't return, etc, etc
-            p.waitFor();
+            int retval = p.waitFor();
+            if (retval != 0) {
+                logger.warning("Command '" + Arrays.toString(cmd) + "' + failed with exitcode=" + retval);
+            }
         } catch (IOException e) {
-            // little we can do...
+            logger.warning("Got '" + e + "' while doing'" + Arrays.toString(cmd) + "'.");
         }
     }
 
@@ -340,24 +339,10 @@ public class LogFileHandler extends StreamHandler {
     }
 
     /**
-     * @return last time file rotation occurred for this output file
-     */
-    public long getLastRotationTime () {
-        return lastRotationTime;
-    }
-
-    /**
-     * @return number of records written to this file since last rotation
-     */
-    public long getNumberRecords () {
-        return numberOfRecords;
-    }
-
-    /**
      * Calculate rotation times array, given times in minutes, as "0 60 ..."
      *
      */
-    public static long[] calcTimesMinutes(String times) {
+    private static long[] calcTimesMinutes(String times) {
         ArrayList<Long> list = new ArrayList<>(50);
         int i = 0;
         boolean etc = false;
@@ -377,7 +362,7 @@ public class LogFileHandler extends StreamHandler {
         int size = list.size();
         long[] longtimes = new long[size];
         for (i = 0; i<size; i++) {
-            longtimes[i] = list.get(i).longValue()   // pick up value in minutes past midnight
+            longtimes[i] = list.get(i)   // pick up value in minutes past midnight
                            * 60000;                          // and multiply to get millis
         }
 
@@ -406,11 +391,11 @@ public class LogFileHandler extends StreamHandler {
     // Support staff :-)
     private static final long lengthOfDayMillis = 24*60*60*1000;  // ? is this close enough ?
 
-    private static final long timeOfDayMillis ( long time ) {
+    private static long timeOfDayMillis ( long time ) {
         return time % lengthOfDayMillis;
     }
 
-    public void setSymlinkName(String symlinkName) {
+    void setSymlinkName(String symlinkName) {
         this.symlinkName = symlinkName;
     }
 
diff --git a/container-accesslogging/src/test/java/com/yahoo/container/logging/test/LogFileHandlerTestCase.java b/container-accesslogging/src/test/java/com/yahoo/container/logging/LogFileHandlerTestCase.java
index 47e98c1f8c5..0330a76951d 100644
--- a/container-accesslogging/src/test/java/com/yahoo/container/logging/test/LogFileHandlerTestCase.java
+++ b/container-accesslogging/src/test/java/com/yahoo/container/logging/LogFileHandlerTestCase.java
@@ -1,11 +1,13 @@
 // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
-package com.yahoo.container.logging.test;
+package com.yahoo.container.logging;
 
-import com.yahoo.container.logging.LogFileHandler;
 import com.yahoo.io.IOUtils;
 import org.junit.Test;
 
 import java.io.File;
+import java.io.FileInputStream;
+import java.io.IOException;
+import java.io.InputStreamReader;
 import java.text.DateFormat;
 import java.text.SimpleDateFormat;
 import java.util.Date;
@@ -13,8 +15,11 @@ import java.util.logging.Formatter;
 import java.util.logging.Level;
 import java.util.logging.LogRecord;
 import java.util.logging.SimpleFormatter;
+import java.util.zip.GZIPInputStream;
 
 import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertFalse;
+import static org.junit.Assert.assertTrue;
 
 /**
  * @author <a href="mailto:travisb@yahoo-inc.com">Bob Travis</a>
@@ -169,4 +174,40 @@ public class LogFileHandlerTestCase {
             deleteOnExit(f2);
     }
 
+    @Test
+    public void testcompression() throws InterruptedException, IOException {
+        IOUtils.recursiveDeleteDir(new File("./testcompression"));
+        LogFileHandler h = new LogFileHandler(true);
+        h.setFilePattern("./testcompression/logfilehandlertest.%Y%m%d%H%M%S%s");
+        h.setFormatter(new Formatter() {
+            public String format(LogRecord r) {
+                DateFormat df = new SimpleDateFormat("yyyy.MM.dd:HH:mm:ss.SSS");
+                String timeStamp = df.format(new Date(r.getMillis()));
+                return ("["+timeStamp+"]" + " " + formatMessage(r) + "\n");
+            }
+        } );
+        for (int i=0; i < 10000; i++) {
+            LogRecord lr = new LogRecord(Level.INFO, "test");
+            h.publish(lr);
+        }
+        String f1 = h.getFileName();
+        assertTrue(f1.startsWith("./testcompression/logfilehandlertest."));
+        File uncompressed = new File(f1);
+        File compressed = new File(f1 + ".gz");
+        h.waitDrained();
+        assertTrue(uncompressed.exists());
+        assertFalse(compressed.exists());
+        String content = IOUtils.readFile(uncompressed);
+        assertEquals(310000, content.length());
+        h.rotateNow();
+        while (uncompressed.exists()) {
+            Thread.sleep(10);
+        }
+        assertTrue(compressed.exists());
+        String unzipped = IOUtils.readAll(new InputStreamReader(new GZIPInputStream(new FileInputStream(compressed))));
+        assertEquals(content, unzipped);
+
+        IOUtils.recursiveDeleteDir(new File("./testcompression"));
+    }
+
 }