Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[JENKINS-68417] Revert LogRecord tricks #6643

Merged
merged 8 commits into from
Jul 6, 2022
72 changes: 41 additions & 31 deletions core/src/main/java/hudson/util/RingBufferLogHandler.java
Original file line number Diff line number Diff line change
Expand Up @@ -24,42 +24,31 @@

package hudson.util;

import edu.umd.cs.findbugs.annotations.SuppressFBWarnings;
import java.lang.ref.SoftReference;
import hudson.remoting.ProxyException;
import java.util.AbstractList;
import java.util.List;
import java.util.Objects;
import java.util.logging.Formatter;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.LogRecord;
import java.util.logging.SimpleFormatter;
import jenkins.util.JenkinsJVM;

/**
* Log {@link Handler} that stores the log records into a ring buffer.
*
* @author Kohsuke Kawaguchi
*/
@SuppressFBWarnings(
value = "RV_RETURN_VALUE_IGNORED_NO_SIDE_EFFECT",
justification = "to guard against potential future compiler optimizations")
public class RingBufferLogHandler extends Handler {

private static final int DEFAULT_RING_BUFFER_SIZE = Integer.getInteger(RingBufferLogHandler.class.getName() + ".defaultSize", 256);

private static final class LogRecordRef extends SoftReference<LogRecord> {
LogRecordRef(LogRecord referent) {
super(referent);
}
}

static {
// Preload the LogRecordRef class to avoid an ABBA deadlock between agent class loading and logging.
LogRecord r = new LogRecord(Level.INFO, "<preloading>");
// We call Objects.hash() to guard against potential future compiler optimizations.
Objects.hash(new LogRecordRef(r).get());
}
/**
* Just to access {@link Formatter#formatMessage} which is not {@code static} though it could have been.
*/
private static final Formatter dummyFormatter = new SimpleFormatter();
jglick marked this conversation as resolved.
Show resolved Hide resolved

private int start = 0;
private final LogRecordRef[] records;
private final LogRecord[] records;
private int size;

/**
Expand All @@ -73,7 +62,7 @@ public RingBufferLogHandler() {
}

public RingBufferLogHandler(int ringSize) {
records = new LogRecordRef[ringSize];
records = new LogRecord[ringSize];
}

/**
Expand All @@ -86,13 +75,36 @@ public static int getDefaultRingBufferSize() {
}

@Override
public synchronized void publish(LogRecord record) {
int len = records.length;
records[(start + size) % len] = new LogRecordRef(record);
if (size == len) {
start = (start + 1) % len;
} else {
size++;
public void publish(LogRecord record) {
if (record == null) {
return;
}
Comment on lines +70 to +72
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A call to super.isLoggable(record) does this null check, and it also checks whether the LogRecord has an appropriate level and whether it satisfies any filter. In practice, the level check is handled by hudson.logging.LogRecorder.Target#matches and subclasses are unlikely to implement a filter, but calling super.isLoggable(record) here results in a slight deduplication of code and makes this subclass of Handler consistent with the subclasses of Handler provided by the Java Platform, so I think this is worth doing.

Suggested change
if (record == null) {
return;
}
if (!super.isLoggable(record)) {
return;
}

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I will have to double-check, but I think this is what we do not want to do because this would prevent custom fine loggers from getting anything. Regular handlers either print a message to a sink or do not; handlers which collect all messages need to behave differently. https://github.com/jenkinsci/support-core-plugin/blob/7e75fdc7e9af0abe0d7d659a3e6e591c3451288f/src/main/java/com/cloudbees/jenkins/support/SupportLogHandler.java#L128-L135

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This would prevent custom fine loggers from getting anything

I do not see how it could because we never mutate java.util.logging.Handler#logLevel from its default value of ALL in RingBufferLogHandler. Like I wrote earlier, I do not think there is a difference in practice, but I think using the built-in method better adheres to the parent class's extensible design just in case a theoretical subclass of RingBufferLogHandler wanted to use a custom level or filter.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It appears to work. Still, I would rather not do it here because

  • I am not entirely confident it is correct.
  • It is not much related to the rest of the change. (I merely added the null check after noticing that tooMuchRecordsShouldNotCrashHandler was not testing anything.)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

a theoretical subclass of RingBufferLogHandler

I would rather just make it final than consider such possibilities.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would rather just make it final than consider such possibilities.

I am OK with making it final.

if (JenkinsJVM.isJenkinsJVM() && record.getParameters() != null) {
jglick marked this conversation as resolved.
Show resolved Hide resolved
try {
LogRecord clone = new LogRecord(record.getLevel(), dummyFormatter.formatMessage(record));
jglick marked this conversation as resolved.
Show resolved Hide resolved
clone.setLoggerName(record.getLoggerName());
clone.setMillis(record.getMillis());
jglick marked this conversation as resolved.
Show resolved Hide resolved
clone.setSequenceNumber(record.getSequenceNumber());
clone.setSourceClassName(record.getSourceClassName());
clone.setSourceMethodName(record.getSourceMethodName());
clone.setThreadID(record.getThreadID());
Throwable t = record.getThrown();
if (t != null) {
clone.setThrown(new ProxyException(t));
jglick marked this conversation as resolved.
Show resolved Hide resolved
}
record = clone;
} catch (Exception e) {
e.printStackTrace();
jglick marked this conversation as resolved.
Show resolved Hide resolved
}
}
synchronized (this) {
int len = records.length;
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

hide whitespace in diff

records[(start + size) % len] = record;
if (size == len) {
start = (start + 1) % len;
} else {
size++;
}
}
}

Expand All @@ -114,9 +126,7 @@ public List<LogRecord> getView() {
public LogRecord get(int index) {
// flip the order
synchronized (RingBufferLogHandler.this) {
LogRecord r = records[(start + (size - (index + 1))) % records.length].get();
// We cannot just omit collected entries due to the List interface.
return r != null ? r : new LogRecord(Level.OFF, "<discarded>");
return records[(start + (size - (index + 1))) % records.length];
}
}

Expand Down
6 changes: 4 additions & 2 deletions test/src/test/java/hudson/util/RingBufferLogHandlerTest.java
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,8 @@

package hudson.util;

import java.util.logging.Level;
import java.util.logging.LogRecord;
import org.junit.Test;
import org.jvnet.hudson.test.Issue;

Expand All @@ -33,10 +35,10 @@ public class RingBufferLogHandlerTest {
@Issue("JENKINS-9120")
public void tooMuchRecordsShouldNotCrashHandler() {
final RingBufferLogHandler handler = new RingBufferLogHandler();

LogRecord lr = new LogRecord(Level.INFO, "xxx");
for (long i = 0; i < (long) Integer.MAX_VALUE + 300; i++) {
// throws ArrayIndexOutOfBoundsException after int-overflow
handler.publish(null);
handler.publish(lr);
}
}
}
17 changes: 11 additions & 6 deletions test/src/test/java/jenkins/model/JenkinsLogRecordsTest.java
Original file line number Diff line number Diff line change
Expand Up @@ -37,14 +37,19 @@ private static void _logRecordsArePresentOnController(JenkinsRule r) throws Thro
containsInRelativeOrder("Completed initialization", "Started initialization"));
VersionNumber javaVersion = new VersionNumber(System.getProperty("java.specification.version"));
if (javaVersion.isOlderThan(new VersionNumber("9")) || javaVersion.isNewerThanOrEqualTo(new VersionNumber("17"))) { // TODO https://github.com/jenkinsci/jenkins-test-harness/issues/359
LogRecord lr = new LogRecord(Level.INFO, "collect me");
Logger.getLogger(Jenkins.class.getName()).log(lr);
WeakReference<LogRecord> ref = new WeakReference<>(lr);
lr = null;
Object x = new Object() {
@Override
public String toString() {
return "collect me";
}
};
Logger.getLogger(Jenkins.class.getName()).log(Level.INFO, "formatting {0}", x);
WeakReference<Object> ref = new WeakReference<>(x);
x = null;
MemoryAssert.assertGC(ref, true);
assertThat("Records collected",
assertThat("Record parameters formatted before collection",
logRecords.stream().map(LogRecord::getMessage).collect(Collectors.toList()),
hasItem("<discarded>"));
hasItem("formatting collect me"));
jglick marked this conversation as resolved.
Show resolved Hide resolved
}
}
}