Skip to content

Commit

Permalink
Merge pull request #2047 from stephenc/jenkins-33068
Browse files Browse the repository at this point in the history 
[JENKINS-33068] AsyncPeriodicWork/AsyncAperiodicWork log files rotation
  • Loading branch information
@stephenc
stephenc committed Feb 25, 2016
2 parents b5db997 + 9cf4a80 commit c6b2d01
Show file tree
Hide file tree
Showing 3 changed files with 257 additions and 19 deletions.
148 changes: 137 additions & 11 deletions core/src/main/java/hudson/model/AsyncAperiodicWork.java
View file
Expand Up @@ -25,11 +25,11 @@

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;

/**
Expand All @@ -40,8 +40,48 @@
* @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;
Expand All @@ -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);
}

/**
Expand All @@ -59,16 +102,18 @@ protected AsyncAperiodicWork(String name) {
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);
Expand All @@ -77,11 +122,16 @@ public void run() {
} 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();
Expand All @@ -91,8 +141,54 @@ public void run() {
}

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);
}
Expand All @@ -102,7 +198,37 @@ protected StreamTaskListener createListener() {
* 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;
}

/**
Expand Down
109 changes: 103 additions & 6 deletions core/src/main/java/hudson/model/AsyncPeriodicWork.java
View file
Expand Up @@ -2,12 +2,13 @@

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.
Expand All @@ -20,6 +21,46 @@
* @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.
*/
Expand All @@ -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);
}

/**
Expand All @@ -45,9 +89,11 @@ public final void doRun() {
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);
Expand All @@ -56,11 +102,16 @@ public void run() {
} 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();
Expand All @@ -73,8 +124,54 @@ public void run() {
}

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);
}
Expand All @@ -84,7 +181,7 @@ protected StreamTaskListener createListener() {
* 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");
}

/**
Expand Down

0 comments on commit c6b2d01

Please sign in to comment.