1 files changed, 397 insertions, 0 deletions
diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/LogFileHandler.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/LogFileHandler.java
new file mode 100644
index 00000000000..75e9febc192
--- /dev/null
+++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/LogFileHandler.java
@@ -0,0 +1,397 @@
+// 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;
+
+import com.yahoo.concurrent.ThreadFactoryFactory;
+import com.yahoo.io.NativeIO;
+import com.yahoo.log.LogFileDb;
+import com.yahoo.system.ProcessExecuter;
+import com.yahoo.yolean.Exceptions;
+
+import java.io.File;
+import java.io.FileInputStream;
+import java.io.FileOutputStream;
+import java.io.IOException;
+import java.util.ArrayList;
+import java.util.Arrays;
+import java.util.concurrent.ArrayBlockingQueue;
+import java.util.concurrent.ExecutorService;
+import java.util.concurrent.Executors;
+import java.util.concurrent.TimeUnit;
+import java.util.logging.Level;
+import java.util.logging.LogRecord;
+import java.util.logging.Logger;
+import java.util.logging.StreamHandler;
+import java.util.zip.GZIPOutputStream;
+
+/**
+ * <p>Implements log file naming/rotating logic for container logs.</p>
+ *
+ * <p>Overridden methods: publish</p>
+ *
+ * <p>Added methods: setFilePattern, setRotationTimes, rotateNow (+ few others)</p>
+ *
+ * @author Bob Travis
+ */
+public class LogFileHandler extends StreamHandler {
+
+    private final static Logger logger = Logger.getLogger(LogFileHandler.class.getName());
+    private final boolean compressOnRotation;
+    private long[] rotationTimes = {0}; //default to one log per day, at midnight
+    private String filePattern = "./log.%T";  // default to current directory, ms time stamp
+    private long nextRotationTime = 0;
+    private FileOutputStream currentOutputStream = null;
+    private volatile String fileName;
+    private String symlinkName = null;
+    private ArrayBlockingQueue<LogRecord> logQueue = new ArrayBlockingQueue<>(100000);
+    private LogRecord rotateCmd = new LogRecord(Level.SEVERE, "rotateNow");
+    private ExecutorService executor = Executors.newCachedThreadPool(ThreadFactoryFactory.getDaemonThreadFactory("logfilehandler.compression"));
+    private final NativeIO nativeIO = new NativeIO();
+    private long lastDropPosition = 0;
+
+    static private class LogThread extends Thread {
+        LogFileHandler logFileHandler;
+        long lastFlush = 0;
+        LogThread(LogFileHandler logFile) {
+            super("Logger");
+            setDaemon(true);
+            logFileHandler = logFile;
+        }
+        @Override
+        public void run() {
+            try {
+                storeLogRecords();
+            } catch (InterruptedException e) {
+            } catch (Exception e) {
+                com.yahoo.protect.Process.logAndDie("Failed storing log records", e);
+            }
+
+            logFileHandler.flush();
+        }
+
+        private void storeLogRecords() throws InterruptedException {
+            while (!isInterrupted()) {
+                LogRecord r = logFileHandler.logQueue.poll(100, TimeUnit.MILLISECONDS);
+                if (r != null) {
+                    if (r == logFileHandler.rotateCmd) {
+                        logFileHandler.internalRotateNow();
+                        lastFlush = System.nanoTime();
+                    } else {
+                        logFileHandler.internalPublish(r);
+                    }
+                    flushIfOld(3, TimeUnit.SECONDS);
+                } else {
+                    flushIfOld(100, TimeUnit.MILLISECONDS);
+                }
+            }
+        }
+
+        private void flushIfOld(long age, TimeUnit unit) {
+            long now = System.nanoTime();
+            if (TimeUnit.NANOSECONDS.toMillis(now - lastFlush) > unit.toMillis(age)) {
+                logFileHandler.flush();
+                lastFlush = now;
+            }
+        }
+    }
+    private final LogThread logThread;
+
+    LogFileHandler() {
+        this(false);
+    }
+
+    LogFileHandler(boolean compressOnRotation)
+    {
+        super();
+        this.compressOnRotation = compressOnRotation;
+        logThread = new LogThread(this);
+        logThread.start();
+    }
+
+    /**
+     * Sends logrecord to file, first rotating file if needed.
+     *
+     * @param r logrecord to publish
+     */
+    public void publish(LogRecord r) {
+        try {
+            logQueue.put(r);
+        } catch (InterruptedException e) {
+        }
+    }
+
+    @Override
+    public synchronized void flush() {
+        super.flush();
+        try {
+            if (currentOutputStream != null) {
+                long newPos = currentOutputStream.getChannel().position();
+                if (newPos > lastDropPosition + 102400) {
+                    nativeIO.dropPartialFileFromCache(currentOutputStream.getFD(), lastDropPosition, newPos, true);
+                    lastDropPosition = newPos;
+                }
+            }
+        } catch (IOException e) {
+            logger.warning("Failed dropping from cache : " + Exceptions.toMessageString(e));
+        }
+    }
+
+    private void internalPublish(LogRecord r) {
+        // first check to see if new file needed.
+        // if so, use this.internalRotateNow() to do it
+
+        long now = System.currentTimeMillis();
+        if (nextRotationTime <= 0) {
+            nextRotationTime = getNextRotationTime(now); // lazy initialization
+        }
+        if (now > nextRotationTime || currentOutputStream == null) {
+            internalRotateNow();
+        }
+        super.publish(r);
+    }
+
+    /**
+     * Assign pattern for generating (rotating) file names.
+     *
+     * @param pattern See LogFormatter for definition
+     */
+    void setFilePattern ( String pattern ) {
+        filePattern = pattern;
+    }
+
+    /**
+     * Assign times for rotating output files.
+     *
+     * @param timesOfDay in millis, from midnight
+     *
+     */
+    void setRotationTimes ( long[] timesOfDay ) {
+        rotationTimes = timesOfDay;
+    }
+
+    /** Assign time for rotating output files
+     *
+     * @param prescription string form of times, in minutes
+     */
+    void setRotationTimes ( String prescription ) {
+        setRotationTimes(calcTimesMinutes(prescription));
+    }
+
+    /**
+     * Find next rotation after specified time.
+     *
+     * @param now the specified time; if zero, current time is used.
+     * @return the next rotation time
+     */
+    long getNextRotationTime (long now) {
+        if (now <= 0) {
+            now = System.currentTimeMillis();
+        }
+        long nowTod = timeOfDayMillis(now);
+        long next = 0;
+        for (long rotationTime : rotationTimes) {
+            if (nowTod < rotationTime) {
+                next = rotationTime-nowTod + now;
+                break;
+            }
+        }
+        if (next == 0) { // didn't find one -- use 1st time 'tomorrow'
+            next = rotationTimes[0]+lengthOfDayMillis-nowTod + now;
+        }
+
+        return next;
+    }
+
+    void waitDrained() {
+        while(! logQueue.isEmpty()) {
+            try {
+                Thread.sleep(1);
+            } catch (InterruptedException e) {
+            }
+        }
+        flush();
+    }
+
+    private void checkAndCreateDir(String pathname) {
+      int lastSlash = pathname.lastIndexOf("/");
+      if (lastSlash > -1) {
+          String pathExcludingFilename = pathname.substring(0, lastSlash);
+          File filepath = new File(pathExcludingFilename);
+          if (!filepath.exists()) {
+            filepath.mkdirs();
+          }
+      }
+    }
+
+    /**
+     * Force file rotation now, independent of schedule.
+     */
+    void rotateNow () {
+        publish(rotateCmd);
+    }
+
+    // Throw InterruptedException upwards rather than relying on isInterrupted to stop the thread as
+    // isInterrupted() returns false after interruption in p.waitFor
+    private void internalRotateNow() {
+        // figure out new file name, then
+        // use super.setOutputStream to switch to a new file
+
+        String oldFileName = fileName;
+        long now = System.currentTimeMillis();
+        fileName = LogFormatter.insertDate(filePattern, now);
+        flush();
+        super.close();
+
+        try {
+            checkAndCreateDir(fileName);
+            FileOutputStream os = new FileOutputStream(fileName, true); // append mode, for safety
+            super.setOutputStream(os);
+            currentOutputStream = os;
+            lastDropPosition = 0;
+            LogFileDb.nowLoggingTo(fileName);
+        }
+        catch (IOException e) {
+            throw new RuntimeException("Couldn't open log file '" + fileName + "'", e);
+        }
+
+        createSymlinkToCurrentFile();
+
+        nextRotationTime = 0; //figure it out later (lazy evaluation)
+        if ((oldFileName != null)) {
+            File oldFile = new File(oldFileName);
+            if (oldFile.exists()) {
+                if (compressOnRotation) {
+                    executor.execute(() -> runCompression(oldFile));
+                } else {
+                    nativeIO.dropFileFromCache(oldFile);
+                }
+            }
+        }
+    }
+
+
+    static void runCompression(File oldFile) {
+        File gzippedFile = new File(oldFile.getPath() + ".gz");
+        try (GZIPOutputStream compressor = new GZIPOutputStream(new FileOutputStream(gzippedFile), 0x100000);
+             FileInputStream inputStream = new FileInputStream(oldFile))
+        {
+            byte [] buffer = new byte[0x400000]; // 4M buffer
+
+            long totalBytesRead = 0;
+            NativeIO nativeIO = new NativeIO();
+            for (int read = inputStream.read(buffer); read > 0; read = inputStream.read(buffer)) {
+                compressor.write(buffer, 0, read);
+                nativeIO.dropPartialFileFromCache(inputStream.getFD(), totalBytesRead, read, false);
+                totalBytesRead += read;
+            }
+            compressor.finish();
+            compressor.flush();
+
+            oldFile.delete();
+            nativeIO.dropFileFromCache(gzippedFile);
+        } catch (IOException e) {
+            logger.warning("Got '" + e + "' while compressing '" + oldFile.getPath() + "'.");
+        }
+    }
+
+    /** Name files by date - create a symlink with a constant name to the newest file */
+    private void createSymlinkToCurrentFile() {
+        if (symlinkName == null) return;
+        File f = new File(fileName);
+        File f2 = new File(f.getParent(), symlinkName);
+        String [] cmd = new String[]{"/bin/ln", "-sf", f.getName(), f2.getPath()};
+        try {
+            int retval = new ProcessExecuter().exec(cmd).getFirst();
+            // 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
+            if (retval != 0) {
+                logger.warning("Command '" + Arrays.toString(cmd) + "' + failed with exitcode=" + retval);
+            }
+        } catch (IOException e) {
+            logger.warning("Got '" + e + "' while doing'" + Arrays.toString(cmd) + "'.");
+        }
+    }
+
+    /**
+     * Calculate rotation times array, given times in minutes, as "0 60 ..."
+     *
+     */
+    private static long[] calcTimesMinutes(String times) {
+        ArrayList<Long> list = new ArrayList<>(50);
+        int i = 0;
+        boolean etc = false;
+
+        while (i < times.length()) {
+            if (times.charAt(i) == ' ') { i++; continue; } // skip spaces
+            int j = i; // start of string
+            i = times.indexOf(' ', i);
+            if (i == -1) i = times.length();
+            if (times.charAt(j) == '.' && times.substring(j,i).equals("...")) { // ...
+                etc = true;
+                break;
+            }
+            list.add(Long.valueOf(times.substring(j,i)));
+        }
+
+        int size = list.size();
+        long[] longtimes = new long[size];
+        for (i = 0; i<size; i++) {
+            longtimes[i] = list.get(i)   // pick up value in minutes past midnight
+                           * 60000;                          // and multiply to get millis
+        }
+
+        if (etc) { // fill out rest of day, same as final interval
+            long endOfDay = 24*60*60*1000;
+            long lasttime = longtimes[size-1];
+            long interval = lasttime - longtimes[size-2];
+            long moreneeded = (endOfDay - lasttime)/interval;
+            if (moreneeded > 0) {
+                int newsize = size + (int)moreneeded;
+                long[] temp = new long[newsize];
+                for (i=0; i<size; i++) {
+                    temp[i] = longtimes[i];
+                }
+                while (size < newsize) {
+                    lasttime += interval;
+                    temp[size++] = lasttime;
+                }
+                longtimes = temp;
+            }
+        }
+
+        return longtimes;
+    }
+
+    // Support staff :-)
+    private static final long lengthOfDayMillis = 24*60*60*1000;  // ? is this close enough ?
+
+    private static long timeOfDayMillis ( long time ) {
+        return time % lengthOfDayMillis;
+    }
+
+    void setSymlinkName(String symlinkName) {
+        this.symlinkName = symlinkName;
+    }
+
+    /**
+     * Flushes all queued messages, interrupts the log thread in this and
+     * waits for it to end before returning
+     */
+    public void shutdown() {
+        logThread.interrupt();
+        try {
+            logThread.join();
+            executor.shutdown();
+            executor.awaitTermination(600, TimeUnit.SECONDS);
+        }
+        catch (InterruptedException e) {
+        }
+    }
+
+    /**
+     * Only for unit testing. Do not use.
+     */
+    public String getFileName() {
+        return fileName;
+    }
+
+}