[JENKINS-33068] AsyncPeriodicWork/AsyncAperiodicWork log files should be...

[JENKINS-33068] AsyncPeriodicWork/AsyncAperiodicWork log files should be appended and rotated not overwritten each execution

core/src/main/java/hudson/model/AsyncAperiodicWork.java

@@ -25,11 +25,11 @@ package hudson.model;
 
 import hudson.security.ACL;
 import hudson.util.StreamTaskListener;
-
 import java.io.File;
 import java.io.IOException;
+import java.util.Date;
+import java.util.concurrent.TimeUnit;
 import java.util.logging.Level;
-
 import jenkins.model.Jenkins;
 
 /**
@@ -40,8 +40,46 @@ import jenkins.model.Jenkins;
  * @since 1.410
  */
 public abstract class AsyncAperiodicWork extends AperiodicWork {
-	
-	/**
+    /**
+     * The default number of minutes after which to try and rotate the log file used by {@link #createListener()}.
+     * This value is controlled by the system property {@code hudson.model.AsyncAperiodicWork.logRotateMinutes}.
+     * Each individual AsyncAperiodicWork can also have a per-extension override using the system property
+     * based on their fully qualified class name with {@code .logRotateMinutes} appended.
+     *
+     * @since 1.650
+     */
+    private static Long LOG_ROTATE_MINUTES = Long.getLong(AsyncAperiodicWork.class.getName() + ".logRotateMinutes",
+            TimeUnit.DAYS.toMinutes(1));
+    /**
+     * The default file size after which to try and rotate the log file used by {@link #createListener()}.
+     * A value of {@code -1L} disables rotation based on file size.
+     * This value is controlled by the system property {@code hudson.model.AsyncAperiodicWork.logRotateSize}.
+     * Each individual AsyncAperiodicWork can also have a per-extension override using the system property
+     * based on their fully qualified class name with {@code .logRotateSize} appended.
+     *
+     * @since 1.650
+     */
+    private static Long LOG_ROTATE_SIZE = Long.getLong(AsyncAperiodicWork.class.getName() + ".logRotateSize", -1L);
+    /**
+     * The number of milliseconds (since startup or previous rotation) after which to try and rotate the log file.
+     *
+     * @since 1.650
+     */
+    private final long logRotateMillis;
+    /**
+     * {@code -1L} disabled file size based log rotation, otherwise when starting an {@link #execute(TaskListener)},
+     * if the log file size is above this number of bytes then the log file will be rotated beforehand.
+     *
+     * @since 1.650
+     */
+    private final long logRotateSize;
+    /**
+     * The last time the log files were rotated.
+     *
+     * @since 1.650
+     */
+    private Long lastRotateMillis;
+    /**
      * Name of the work.
      */
     public final String name;
@@ -50,6 +88,9 @@ public abstract class AsyncAperiodicWork extends AperiodicWork {
 
     protected AsyncAperiodicWork(String name) {
         this.name = name;
+        this.logRotateMillis = TimeUnit.MINUTES.toMillis(
+                Long.getLong(getClass().getName()+".logRotateMinutes", LOG_ROTATE_MINUTES));
+        this.logRotateSize = Long.getLong(getClass().getName() +".logRotateSize", LOG_ROTATE_SIZE);
     }
 
     /**
@@ -59,19 +100,25 @@ public abstract class AsyncAperiodicWork extends AperiodicWork {
     public final void doAperiodicRun() {
         try {
             if(thread!=null && thread.isAlive()) {
-                logger.log(Level.INFO, name+" thread is still running. Execution aborted.");
+                logger.log(getSlowLoggingLevel(), name+" thread is still running. Execution aborted.");
                 return;
             }
             thread = new Thread(new Runnable() {
                 public void run() {
-                    logger.log(Level.INFO, "Started "+name);
+                    logger.log(getNormalLoggingLevel(), "Started "+name);
                     long startTime = System.currentTimeMillis();
 
                     StreamTaskListener l = createListener();
                     try {
+                        l.getLogger().printf("Started at %tc%n", new Date(startTime));
                         ACL.impersonate(ACL.SYSTEM);
 
-                        execute(l);
+                        try {
+                            execute(l);
+                        } finally {
+                            long stopTime = System.currentTimeMillis();
+                            l.getLogger().printf("Finished at %tc. %dms%n", new Date(stopTime), stopTime - startTime);
+                        }
                     } catch (IOException e) {
                         e.printStackTrace(l.fatalError(e.getMessage()));
                     } catch (InterruptedException e) {
@@ -80,8 +127,8 @@ public abstract class AsyncAperiodicWork extends AperiodicWork {
                         l.closeQuietly();
                     }
 
-                    logger.log(Level.INFO, "Finished "+name+". "+
-                        (System.currentTimeMillis()-startTime)+" ms");
+                    logger.log(getNormalLoggingLevel(), "Finished {0}. {1,number} ms",
+                            new Object[]{name, System.currentTimeMillis() - startTime});
                 }
             },name+" thread");
             thread.start(); 
@@ -91,8 +138,34 @@ public abstract class AsyncAperiodicWork extends AperiodicWork {
     }
 
     protected StreamTaskListener createListener() {
+        File f = getLogFile();
+        if (f.isFile()) {
+            if ((lastRotateMillis == null)
+                    || (lastRotateMillis + logRotateMillis < System.currentTimeMillis())
+                    || (logRotateSize > 0 && f.length() > logRotateSize)) {
+                lastRotateMillis = System.currentTimeMillis();
+                File p = null;
+                for (int i = 5; i >= 0; i--) {
+                    File o = i == 0 ? f : new File(f.getParentFile(), f.getName() + "." + i);
+                    if (o.isFile()) {
+                        if (p != null && !p.exists()) {
+                            if (!o.renameTo(p)) {
+                                logger.log(getErrorLoggingLevel(), "Could not rotate log files {0} to {1}",
+                                        new Object[]{o, p});
+                            }
+                        } else {
+                            if (!o.delete()) {
+                                logger.log(getErrorLoggingLevel(), "Could not delete log files {0} to enable rotation",
+                                        o);
+                            }
+                        }
+                        p = o;
+                    }
+                }
+            }
+        }
         try {
-            return new StreamTaskListener(getLogFile());
+            return new StreamTaskListener(f, true, null);
         } catch (IOException e) {
             throw new Error(e);
         }
@@ -105,6 +178,36 @@ public abstract class AsyncAperiodicWork extends AperiodicWork {
         return new File(Jenkins.getInstance().getRootDir(),name+".log");
     }
 
+    /**
+     * Returns the logging level at which normal messages are displayed.
+     *
+     * @return The logging level.
+     * @since 1.650
+     */
+    protected Level getNormalLoggingLevel() {
+        return Level.INFO;
+    }
+
+    /**
+     * Returns the logging level at which previous task still executing messages is displayed.
+     *
+     * @return The logging level.
+     * @since 1.650
+     */
+    protected Level getSlowLoggingLevel() {
+        return getNormalLoggingLevel();
+    }
+
+    /**
+     * Returns the logging level at which error messages are displayed.
+     *
+     * @return The logging level.
+     * @since 1.650
+     */
+    protected Level getErrorLoggingLevel() {
+        return Level.SEVERE;
+    }
+
     /**
      * Executes the task.
      *

core/src/main/java/hudson/model/AsyncPeriodicWork.java

@@ -2,12 +2,13 @@ package hudson.model;
 
 import hudson.security.ACL;
 import hudson.util.StreamTaskListener;
-import jenkins.model.Jenkins;
-
 import java.io.File;
 import java.io.IOException;
+import java.util.Date;
+import java.util.concurrent.TimeUnit;
 import java.util.logging.Level;
 import java.util.logging.LogRecord;
+import jenkins.model.Jenkins;
 
 /**
  * {@link PeriodicWork} that takes a long time to run.
@@ -20,6 +21,45 @@ import java.util.logging.LogRecord;
  * @author Kohsuke Kawaguchi
  */
 public abstract class AsyncPeriodicWork extends PeriodicWork {
+    /**
+     * The default number of minutes after which to try and rotate the log file used by {@link #createListener()}.
+     * This value is controlled by the system property {@code hudson.model.AsyncPeriodicWork.logRotateMinutes}.
+     * Each individual AsyncPeriodicWork can also have a per-extension override using the system property
+     * based on their fully qualified class name with {@code .logRotateMinutes} appended.
+     *
+     * @since 1.650
+     */
+    private static Long LOG_ROTATE_MINUTES = Long.getLong(AsyncPeriodicWork.class.getName() + ".logRotateMinutes",
+            TimeUnit.DAYS.toMinutes(1));
+    /**
+     * The default file size after which to try and rotate the log file used by {@link #createListener()}.
+     * A value of {@code -1L} disables rotation based on file size.
+     * This value is controlled by the system property {@code hudson.model.AsyncPeriodicWork.logRotateSize}.
+     * Each individual AsyncPeriodicWork can also have a per-extension override using the system property
+     * based on their fully qualified class name with {@code .logRotateSize} appended.
+     *
+     * @since 1.650
+     */
+    private static Long LOG_ROTATE_SIZE = Long.getLong(AsyncPeriodicWork.class.getName() + ".logRotateSize", -1L);
+    /**
+     * The number of milliseconds (since startup or previous rotation) after which to try and rotate the log file.
+     *
+     * @since 1.650
+     */
+    private final long logRotateMillis;
+    /**
+     * {@code -1L} disabled file size based log rotation, otherwise when starting an {@link #execute(TaskListener)},
+     * if the log file size is above this number of bytes then the log file will be rotated beforehand.
+     *
+     * @since 1.650
+     */
+    private final long logRotateSize;
+    /**
+     * The last time the log files were rotated.
+     *
+     * @since 1.650
+     */
+    private Long lastRotateMillis;
     /**
      * Human readable name of the work.
      */
@@ -29,6 +69,9 @@ public abstract class AsyncPeriodicWork extends PeriodicWork {
 
     protected AsyncPeriodicWork(String name) {
         this.name = name;
+        this.logRotateMillis = TimeUnit.MINUTES.toMillis(
+                Long.getLong(getClass().getName() + ".logRotateMinutes", LOG_ROTATE_MINUTES));
+        this.logRotateSize = Long.getLong(getClass().getName() + ".logRotateSize", LOG_ROTATE_SIZE);
     }
 
     /**
@@ -48,9 +91,15 @@ public abstract class AsyncPeriodicWork extends PeriodicWork {
 
                     StreamTaskListener l = createListener();
                     try {
+                        l.getLogger().printf("Started at %tc%n", new Date(startTime));
                         ACL.impersonate(ACL.SYSTEM);
 
-                        execute(l);
+                        try {
+                            execute(l);
+                        } finally {
+                            long stopTime = System.currentTimeMillis();
+                            l.getLogger().printf("Finished at %tc. %dms%n", new Date(stopTime), stopTime - startTime);
+                        }
                     } catch (IOException e) {
                         e.printStackTrace(l.fatalError(e.getMessage()));
                     } catch (InterruptedException e) {
@@ -60,7 +109,7 @@ public abstract class AsyncPeriodicWork extends PeriodicWork {
                     }
 
                     logger.log(getNormalLoggingLevel(), "Finished {0}. {1,number} ms",
-                            new Object[]{name, (System.currentTimeMillis()-startTime)});
+                            new Object[]{name, System.currentTimeMillis() - startTime});
                 }
             },name+" thread");
             thread.start();
@@ -73,8 +122,34 @@ public abstract class AsyncPeriodicWork extends PeriodicWork {
     }
 
     protected StreamTaskListener createListener() {
+        File f = getLogFile();
+        if (f.isFile()) {
+            if ((lastRotateMillis == null)
+                    || (lastRotateMillis + logRotateMillis < System.currentTimeMillis())
+                    || (logRotateSize > 0 && f.length() > logRotateSize)) {
+                lastRotateMillis = System.currentTimeMillis();
+                File p = null;
+                for (int i = 5; i >= 0; i--) {
+                    File o = i == 0 ? f : new File(f.getParentFile(), f.getName() + "." + i);
+                    if (o.isFile()) {
+                        if (p != null && !p.exists()) {
+                            if (!o.renameTo(p)) {
+                                logger.log(getErrorLoggingLevel(), "Could not rotate log files {0} to {1}",
+                                        new Object[]{o, p});
+                            }
+                        } else {
+                            if (!o.delete()) {
+                                logger.log(getErrorLoggingLevel(), "Could not delete log files {0} to enable rotation",
+                                        o);
+                            }
+                        }
+                        p = o;
+                    }
+                }
+            }
+        }
         try {
-            return new StreamTaskListener(getLogFile());
+            return new StreamTaskListener(f, true, null);
         } catch (IOException e) {
             throw new Error(e);
         }

core/src/main/java/hudson/util/StreamTaskListener.java

@@ -98,6 +98,13 @@ public class StreamTaskListener extends AbstractTaskListener implements Serializ
         this(new FileOutputStream(out),charset);
     }
 
+    public StreamTaskListener(File out, boolean append, Charset charset) throws IOException {
+        // don't do buffering so that what's written to the listener
+        // gets reflected to the file immediately, which can then be
+        // served to the browser immediately
+        this(new FileOutputStream(out, append),charset);
+    }
+
     public StreamTaskListener(Writer w) throws IOException {
         this(new WriterOutputStream(w));
     }