From 68eb7c33480bf7a39c68eacd4ebfe065bbfe9a6b Mon Sep 17 00:00:00 2001 From: Henning Baldersheim Date: Wed, 10 Oct 2018 13:30:44 +0200 Subject: Test compression on logrotate and correct visibility and cleanup unused code. --- .../yahoo/container/logging/LogFileHandler.java | 117 +++++------ .../container/logging/LogFileHandlerTestCase.java | 213 +++++++++++++++++++++ .../logging/test/LogFileHandlerTestCase.java | 172 ----------------- 3 files changed, 264 insertions(+), 238 deletions(-) create mode 100644 container-accesslogging/src/test/java/com/yahoo/container/logging/LogFileHandlerTestCase.java delete mode 100644 container-accesslogging/src/test/java/com/yahoo/container/logging/test/LogFileHandlerTestCase.java (limited to 'container-accesslogging') 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 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) + "'."); } } @@ -339,25 +338,11 @@ public class LogFileHandler extends StreamHandler { file.renameTo(newFn); } - /** - * @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 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; iBob Travis + */ +// TODO: Make these tests wait until the right things happen rather than waiting for a predetermined time +// These tests take too long, and are not cleaning up properly. See how this should be done in YApacheLogTestCase +public class LogFileHandlerTestCase { + + /** + * The scenario + */ + @Test + public void testIt() { + LogFileHandler h = new LogFileHandler(); + h.setFilePattern("./logfilehandlertest.%Y%m%d%H%M%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"); + } + } ); + long now = System.currentTimeMillis(); + long millisPerDay = 60*60*24*1000; + long tomorrowDays = (now / millisPerDay) +1; + long tomorrowMillis = tomorrowDays * millisPerDay; + assertEquals (tomorrowMillis, h.getNextRotationTime(now)); + long[] rTimes = {1000, 2000, 10000}; + h.setRotationTimes(rTimes); + assertEquals (tomorrowMillis+1000, h.getNextRotationTime(tomorrowMillis)); + assertEquals (tomorrowMillis+10000, h.getNextRotationTime(tomorrowMillis+3000)); + boolean okToWrite = false; // don't want regular unit tests to create tiles.... + if (okToWrite) { + LogRecord lr = new LogRecord(Level.INFO, "test"); + h.publish(lr); + h.publish(new LogRecord(Level.INFO, "another test")); + h.rotateNow(); + h.publish(lr); + h.flush(); + } + } + + private boolean delete(String fileOrDir) { + File file = new File(fileOrDir); + return file.delete(); + } + + private void deleteOnExit(String fileOrDir) { + new File(fileOrDir).deleteOnExit(); + } + + private static void deleteRecursive(String directory) { + IOUtils.recursiveDeleteDir(new File(directory)); + } + + @Test + public void testSimpleLogging() { + String logFilePattern = "./testLogFileG1.txt"; + + //create logfilehandler + LogFileHandler h = new LogFileHandler(); + h.setFilePattern(logFilePattern); + h.setFormatter(new SimpleFormatter()); + h.setRotationTimes("0 5 ..."); + + //write log + LogRecord lr = new LogRecord(Level.INFO, "testDeleteFileFirst1"); + h.publish(lr); + h.flush(); + + new File(logFilePattern).deleteOnExit(); + } + + @Test + public void testDeleteFileDuringLogging() { + String logFilePattern = "./testLogFileG2.txt"; + + //create logfilehandler + LogFileHandler h = new LogFileHandler(); + h.setFilePattern(logFilePattern); + h.setFormatter(new SimpleFormatter()); + h.setRotationTimes("0 5 ..."); + + //write log + LogRecord lr = new LogRecord(Level.INFO, "testDeleteFileDuringLogging1"); + h.publish(lr); + h.flush(); + + //delete log file + delete(logFilePattern); + + //write log again + lr = new LogRecord(Level.INFO, "testDeleteFileDuringLogging2"); + h.publish(lr); + h.flush(); + + new File(logFilePattern).deleteOnExit(); + } + + @Test + public void testSymlink() { + LogFileHandler h = new LogFileHandler(); + h.setFilePattern("./testlogforsymlinkchecking/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"); + } + } ); + h.setSymlinkName("symlink"); + LogRecord lr = new LogRecord(Level.INFO, "test"); + h.publish(lr); + String f1 = h.getFileName(); + String f2 = null; + try { + while (f1 == null) { + Thread.sleep(1); + f1 = h.getFileName(); + } + h.rotateNow(); + Thread.sleep(1); + f2 = h.getFileName(); + while (f1.equals(f2)) { + Thread.sleep(1); + f2 = h.getFileName(); + } + lr = new LogRecord(Level.INFO, "string which is way longer than the word test"); + h.publish(lr); + Thread.sleep(1000); + File f = new File(f1); + long first = f.length(); + f = new File(f2); + long second = f.length(); + final long secondLength = 72; + for (int n = 0; n < 20 && second != secondLength; ++n) { + Thread.sleep(1000); + second = f.length(); + } + f = new File("./testlogforsymlinkchecking", "symlink"); + long link = f.length(); + assertEquals(secondLength, link); + assertEquals(31, first); + assertEquals(secondLength, second); + } catch (InterruptedException e) { + // just let the test pass + } + deleteOnExit("./testlogforsymlinkchecking"); + deleteOnExit("./testlogforsymlinkchecking/symlink"); + deleteOnExit(f1); + if (f2 != null) + 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")); + } + +} 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/test/LogFileHandlerTestCase.java deleted file mode 100644 index 47e98c1f8c5..00000000000 --- a/container-accesslogging/src/test/java/com/yahoo/container/logging/test/LogFileHandlerTestCase.java +++ /dev/null @@ -1,172 +0,0 @@ -// 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; - -import com.yahoo.container.logging.LogFileHandler; -import com.yahoo.io.IOUtils; -import org.junit.Test; - -import java.io.File; -import java.text.DateFormat; -import java.text.SimpleDateFormat; -import java.util.Date; -import java.util.logging.Formatter; -import java.util.logging.Level; -import java.util.logging.LogRecord; -import java.util.logging.SimpleFormatter; - -import static org.junit.Assert.assertEquals; - -/** - * @author Bob Travis - */ -// TODO: Make these tests wait until the right things happen rather than waiting for a predetermined time -// These tests take too long, and are not cleaning up properly. See how this should be done in YApacheLogTestCase -public class LogFileHandlerTestCase { - - /** - * The scenario - */ - @Test - public void testIt() { - LogFileHandler h = new LogFileHandler(); - h.setFilePattern("./logfilehandlertest.%Y%m%d%H%M%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"); - } - } ); - long now = System.currentTimeMillis(); - long millisPerDay = 60*60*24*1000; - long tomorrowDays = (now / millisPerDay) +1; - long tomorrowMillis = tomorrowDays * millisPerDay; - assertEquals (tomorrowMillis, h.getNextRotationTime(now)); - long[] rTimes = {1000, 2000, 10000}; - h.setRotationTimes(rTimes); - assertEquals (tomorrowMillis+1000, h.getNextRotationTime(tomorrowMillis)); - assertEquals (tomorrowMillis+10000, h.getNextRotationTime(tomorrowMillis+3000)); - boolean okToWrite = false; // don't want regular unit tests to create tiles.... - if (okToWrite) { - LogRecord lr = new LogRecord(Level.INFO, "test"); - h.publish(lr); - h.publish(new LogRecord(Level.INFO, "another test")); - h.rotateNow(); - h.publish(lr); - h.flush(); - } - } - - private boolean delete(String fileOrDir) { - File file = new File(fileOrDir); - return file.delete(); - } - - private void deleteOnExit(String fileOrDir) { - new File(fileOrDir).deleteOnExit(); - } - - private static void deleteRecursive(String directory) { - IOUtils.recursiveDeleteDir(new File(directory)); - } - - @Test - public void testSimpleLogging() { - String logFilePattern = "./testLogFileG1.txt"; - - //create logfilehandler - LogFileHandler h = new LogFileHandler(); - h.setFilePattern(logFilePattern); - h.setFormatter(new SimpleFormatter()); - h.setRotationTimes("0 5 ..."); - - //write log - LogRecord lr = new LogRecord(Level.INFO, "testDeleteFileFirst1"); - h.publish(lr); - h.flush(); - - new File(logFilePattern).deleteOnExit(); - } - - @Test - public void testDeleteFileDuringLogging() { - String logFilePattern = "./testLogFileG2.txt"; - - //create logfilehandler - LogFileHandler h = new LogFileHandler(); - h.setFilePattern(logFilePattern); - h.setFormatter(new SimpleFormatter()); - h.setRotationTimes("0 5 ..."); - - //write log - LogRecord lr = new LogRecord(Level.INFO, "testDeleteFileDuringLogging1"); - h.publish(lr); - h.flush(); - - //delete log file - delete(logFilePattern); - - //write log again - lr = new LogRecord(Level.INFO, "testDeleteFileDuringLogging2"); - h.publish(lr); - h.flush(); - - new File(logFilePattern).deleteOnExit(); - } - - @Test - public void testSymlink() { - LogFileHandler h = new LogFileHandler(); - h.setFilePattern("./testlogforsymlinkchecking/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"); - } - } ); - h.setSymlinkName("symlink"); - LogRecord lr = new LogRecord(Level.INFO, "test"); - h.publish(lr); - String f1 = h.getFileName(); - String f2 = null; - try { - while (f1 == null) { - Thread.sleep(1); - f1 = h.getFileName(); - } - h.rotateNow(); - Thread.sleep(1); - f2 = h.getFileName(); - while (f1.equals(f2)) { - Thread.sleep(1); - f2 = h.getFileName(); - } - lr = new LogRecord(Level.INFO, "string which is way longer than the word test"); - h.publish(lr); - Thread.sleep(1000); - File f = new File(f1); - long first = f.length(); - f = new File(f2); - long second = f.length(); - final long secondLength = 72; - for (int n = 0; n < 20 && second != secondLength; ++n) { - Thread.sleep(1000); - second = f.length(); - } - f = new File("./testlogforsymlinkchecking", "symlink"); - long link = f.length(); - assertEquals(secondLength, link); - assertEquals(31, first); - assertEquals(secondLength, second); - } catch (InterruptedException e) { - // just let the test pass - } - deleteOnExit("./testlogforsymlinkchecking"); - deleteOnExit("./testlogforsymlinkchecking/symlink"); - deleteOnExit(f1); - if (f2 != null) - deleteOnExit(f2); - } - -} -- cgit v1.2.3