diff --git a/core/src/main/java/hudson/model/AsyncAperiodicWork.java b/core/src/main/java/hudson/model/AsyncAperiodicWork.java index 9111e5fd474d5536879c86180272737fe26aa67c..8587f925c361e010ed118e2a1b9f663f9965faf1 100644 --- a/core/src/main/java/hudson/model/AsyncAperiodicWork.java +++ b/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,48 @@ 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.651 + */ + private static final 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.651 + */ + private static final 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.651 + */ + 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.651 + */ + private final long logRotateSize; + /** + * The last time the log files were rotated. On start-up this will be {@link Long#MIN_VALUE} to ensure that the + * logs are always rotated every time Jenkins starts up to make it easier to correlate events with the main log. + * + * @since 1.651 + */ + private long lastRotateMillis = Long.MIN_VALUE; + /** * Name of the work. */ public final String name; @@ -50,6 +90,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,16 +102,18 @@ 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(), "{0} thread is still running. Execution aborted.", name); return; } thread = new Thread(new Runnable() { public void run() { - logger.log(Level.INFO, "Started "+name); + logger.log(getNormalLoggingLevel(), "Started {0}", name); long startTime = System.currentTimeMillis(); + long stopTime; StreamTaskListener l = createListener(); try { + l.getLogger().printf("Started at %tc%n", new Date(startTime)); ACL.impersonate(ACL.SYSTEM); execute(l); @@ -77,11 +122,16 @@ public abstract class AsyncAperiodicWork extends AperiodicWork { } catch (InterruptedException e) { e.printStackTrace(l.fatalError("aborted")); } finally { - l.closeQuietly(); + stopTime = System.currentTimeMillis(); + try { + l.getLogger().printf("Finished at %tc. %dms%n", new Date(stopTime), stopTime - startTime); + } finally { + l.closeQuietly(); + } } - logger.log(Level.INFO, "Finished "+name+". "+ - (System.currentTimeMillis()-startTime)+" ms"); + logger.log(getNormalLoggingLevel(), "Finished {0}. {1,number} ms", + new Object[]{name, stopTime - startTime}); } },name+" thread"); thread.start(); @@ -91,8 +141,54 @@ public abstract class AsyncAperiodicWork extends AperiodicWork { } protected StreamTaskListener createListener() { + File f = getLogFile(); + if (!f.getParentFile().isDirectory()) { + if (!f.getParentFile().mkdirs()) { + logger.log(getErrorLoggingLevel(), "Could not create directory {0}", f.getParentFile()); + } + } + if (f.isFile()) { + if ((lastRotateMillis + logRotateMillis < System.currentTimeMillis()) + || (logRotateSize > 0 && f.length() > logRotateSize)) { + lastRotateMillis = System.currentTimeMillis(); + File prev = null; + for (int i = 5; i >= 0; i--) { + File curr = i == 0 ? f : new File(f.getParentFile(), f.getName() + "." + i); + if (curr.isFile()) { + if (prev != null && !prev.exists()) { + if (!curr.renameTo(prev)) { + logger.log(getErrorLoggingLevel(), "Could not rotate log files {0} to {1}", + new Object[]{curr, prev}); + } + } else { + if (!curr.delete()) { + logger.log(getErrorLoggingLevel(), "Could not delete log file {0} to enable rotation", + curr); + } + } + } + prev = curr; + } + } + } else { + lastRotateMillis = System.currentTimeMillis(); + // migrate old log files the first time we start-up + File oldFile = new File(Jenkins.getActiveInstance().getRootDir(), f.getName()); + if (oldFile.isFile()) { + File newFile = new File(f.getParentFile(), f.getName() + ".1"); + if (!newFile.isFile()) { + // if there has never been rotation then this is the first time + if (oldFile.renameTo(newFile)) { + logger.log(getNormalLoggingLevel(), "Moved {0} to {1}", new Object[]{oldFile, newFile}); + } else { + logger.log(getErrorLoggingLevel(), "Could not move {0} to {1}", + new Object[]{oldFile, newFile}); + } + } + } + } try { - return new StreamTaskListener(getLogFile()); + return new StreamTaskListener(f, true, null); } catch (IOException e) { throw new Error(e); } @@ -102,7 +198,37 @@ public abstract class AsyncAperiodicWork extends AperiodicWork { * Determines the log file that records the result of this task. */ protected File getLogFile() { - return new File(Jenkins.getInstance().getRootDir(),name+".log"); + return new File(Jenkins.getActiveInstance().getRootDir(),"logs/tasks/"+name+".log"); + } + + /** + * Returns the logging level at which normal messages are displayed. + * + * @return The logging level. + * @since 1.651 + */ + 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.651 + */ + protected Level getSlowLoggingLevel() { + return getNormalLoggingLevel(); + } + + /** + * Returns the logging level at which error messages are displayed. + * + * @return The logging level. + * @since 1.651 + */ + protected Level getErrorLoggingLevel() { + return Level.SEVERE; } /** diff --git a/core/src/main/java/hudson/model/AsyncPeriodicWork.java b/core/src/main/java/hudson/model/AsyncPeriodicWork.java index 9444887b5b1c262818920df69006021e291e5559..392f90abcb7d2ab06c2ebdcac2df18bd8b1cc9ad 100644 --- a/core/src/main/java/hudson/model/AsyncPeriodicWork.java +++ b/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,46 @@ 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.651 + */ + private static final 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.651 + */ + private static final 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.651 + */ + 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.651 + */ + private final long logRotateSize; + /** + * The last time the log files were rotated. On start-up this will be {@link Long#MIN_VALUE} to ensure that the + * logs are always rotated every time Jenkins starts up to make it easier to correlate events with the main log. + * + * @since 1.651 + */ + private long lastRotateMillis = Long.MIN_VALUE; /** * Human readable name of the work. */ @@ -29,6 +70,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); } /** @@ -45,9 +89,11 @@ public abstract class AsyncPeriodicWork extends PeriodicWork { public void run() { logger.log(getNormalLoggingLevel(), "Started {0}", name); long startTime = System.currentTimeMillis(); + long stopTime; StreamTaskListener l = createListener(); try { + l.getLogger().printf("Started at %tc%n", new Date(startTime)); ACL.impersonate(ACL.SYSTEM); execute(l); @@ -56,11 +102,16 @@ public abstract class AsyncPeriodicWork extends PeriodicWork { } catch (InterruptedException e) { e.printStackTrace(l.fatalError("aborted")); } finally { - l.closeQuietly(); + stopTime = System.currentTimeMillis(); + try { + l.getLogger().printf("Finished at %tc. %dms%n", new Date(stopTime), stopTime - startTime); + } finally { + l.closeQuietly(); + } } logger.log(getNormalLoggingLevel(), "Finished {0}. {1,number} ms", - new Object[]{name, (System.currentTimeMillis()-startTime)}); + new Object[]{name, stopTime - startTime}); } },name+" thread"); thread.start(); @@ -73,8 +124,54 @@ public abstract class AsyncPeriodicWork extends PeriodicWork { } protected StreamTaskListener createListener() { + File f = getLogFile(); + if (!f.getParentFile().isDirectory()) { + if (!f.getParentFile().mkdirs()) { + logger.log(getErrorLoggingLevel(), "Could not create directory {0}", f.getParentFile()); + } + } + if (f.isFile()) { + if ((lastRotateMillis + logRotateMillis < System.currentTimeMillis()) + || (logRotateSize > 0 && f.length() > logRotateSize)) { + lastRotateMillis = System.currentTimeMillis(); + File prev = null; + for (int i = 5; i >= 0; i--) { + File curr = i == 0 ? f : new File(f.getParentFile(), f.getName() + "." + i); + if (curr.isFile()) { + if (prev != null && !prev.exists()) { + if (!curr.renameTo(prev)) { + logger.log(getErrorLoggingLevel(), "Could not rotate log files {0} to {1}", + new Object[]{curr, prev}); + } + } else { + if (!curr.delete()) { + logger.log(getErrorLoggingLevel(), "Could not delete log file {0} to enable rotation", + curr); + } + } + } + prev = curr; + } + } + } else { + lastRotateMillis = System.currentTimeMillis(); + // migrate old log files the first time we start-up + File oldFile = new File(Jenkins.getActiveInstance().getRootDir(), f.getName()); + if (oldFile.isFile()) { + File newFile = new File(f.getParentFile(), f.getName() + ".1"); + if (!newFile.isFile()) { + // if there has never been rotation then this is the first time + if (oldFile.renameTo(newFile)) { + logger.log(getNormalLoggingLevel(), "Moved {0} to {1}", new Object[]{oldFile, newFile}); + } else { + logger.log(getErrorLoggingLevel(), "Could not move {0} to {1}", + new Object[]{oldFile, newFile}); + } + } + } + } try { - return new StreamTaskListener(getLogFile()); + return new StreamTaskListener(f, true, null); } catch (IOException e) { throw new Error(e); } @@ -84,7 +181,7 @@ public abstract class AsyncPeriodicWork extends PeriodicWork { * Determines the log file that records the result of this task. */ protected File getLogFile() { - return new File(Jenkins.getInstance().getRootDir(),name+".log"); + return new File(Jenkins.getActiveInstance().getRootDir(),"logs/tasks/"+name+".log"); } /** diff --git a/core/src/main/java/hudson/util/StreamTaskListener.java b/core/src/main/java/hudson/util/StreamTaskListener.java index 4d6aea568d74bce91f31172e5150c0a866ebb2b6..5e4a294fb06069d87ed9987a0f6ef738b242235c 100644 --- a/core/src/main/java/hudson/util/StreamTaskListener.java +++ b/core/src/main/java/hudson/util/StreamTaskListener.java @@ -28,8 +28,6 @@ import hudson.console.ConsoleNote; import hudson.console.HudsonExceptionNote; import hudson.model.TaskListener; import hudson.remoting.RemoteOutputStream; -import org.kohsuke.stapler.framework.io.WriterOutputStream; - import java.io.Closeable; import java.io.File; import java.io.FileOutputStream; @@ -46,6 +44,7 @@ import java.io.Writer; import java.nio.charset.Charset; import java.util.logging.Level; import java.util.logging.Logger; +import org.kohsuke.stapler.framework.io.WriterOutputStream; /** * {@link TaskListener} that generates output into a single stream. @@ -98,6 +97,22 @@ public class StreamTaskListener extends AbstractTaskListener implements Serializ this(new FileOutputStream(out),charset); } + /** + * Constructs a {@link StreamTaskListener} that sends the output to a specified file. + * + * @param out the file. + * @param append if {@code true}, then output will be written to the end of the file rather than the beginning. + * @param charset if non-{@code null} then the charset to use when writing. + * @throws IOException if the file could not be opened. + * @since 1.651 + */ + 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)); }