diff --git a/core/src/main/java/hudson/slaves/SlaveComputer.java b/core/src/main/java/hudson/slaves/SlaveComputer.java index cc1f5cdaa99ac1a5c7c16dbaa6fb92a77e14646b..c6d1c56019592002dc291a8ce31f11780591b987 100644 --- a/core/src/main/java/hudson/slaves/SlaveComputer.java +++ b/core/src/main/java/hudson/slaves/SlaveComputer.java @@ -1020,12 +1020,12 @@ public class SlaveComputer extends Computer { public Void call() { SLAVE_LOG_HANDLER = new RingBufferLogHandler(ringBufferSize) { - Formatter dummy = new SimpleFormatter(); + ThreadLocal dummy = ThreadLocal.withInitial(() -> new SimpleFormatter()); @Override - public synchronized void publish(LogRecord record) { + public /* not synchronized */ void publish(LogRecord record) { // see LogRecord.writeObject for dangers of serializing non-String/null parameters if (record.getMessage() != null && record.getParameters() != null && Stream.of(record.getParameters()).anyMatch(p -> p != null && !(p instanceof String))) { - record.setMessage(dummy.formatMessage(record)); + record.setMessage(dummy.get().formatMessage(record)); record.setParameters(null); } super.publish(record); diff --git a/core/src/main/java/hudson/util/RobustReflectionConverter.java b/core/src/main/java/hudson/util/RobustReflectionConverter.java index 976d1755f757cf89d7b1ccb87c710bc6c03ccf14..9b07e31886401f66ca8921b90155c9731a69b864 100644 --- a/core/src/main/java/hudson/util/RobustReflectionConverter.java +++ b/core/src/main/java/hudson/util/RobustReflectionConverter.java @@ -53,6 +53,8 @@ import java.util.Set; import java.util.concurrent.locks.ReadWriteLock; import java.util.concurrent.locks.ReentrantReadWriteLock; import static java.util.logging.Level.FINE; + +import java.util.logging.Level; import java.util.logging.Logger; import edu.umd.cs.findbugs.annotations.NonNull; import net.jcip.annotations.GuardedBy; @@ -365,7 +367,23 @@ public class RobustReflectionConverter implements Converter { // Report any class/field errors in Saveable objects if (context.get("ReadError") != null && context.get("Saveable") == result) { - OldDataMonitor.report((Saveable)result, (ArrayList)context.get("ReadError")); + // Avoid any error in OldDataMonitor to be catastrophic. See JENKINS-62231 and JENKINS-59582 + // The root cause is the OldDataMonitor extension is not ready before a plugin triggers an error, for + // example when trying to load a field that was created by a new version and you downgrade to the previous + // one. + try { + OldDataMonitor.report((Saveable) result, (ArrayList) context.get("ReadError")); + } catch (Throwable t) { + // it should be already reported, but we report with INFO just in case + StringBuilder message = new StringBuilder("There was a problem reporting unmarshalling field errors"); + Level level = Level.WARNING; + if (t instanceof IllegalStateException && t.getMessage().contains("Expected 1 instance of " + OldDataMonitor.class.getName())) { + message.append(". Make sure this code is executed after InitMilestone.EXTENSIONS_AUGMENTED stage, for example in Plugin#postInitialize instead of Plugin#start"); + level = Level.INFO; // it was reported when getting the singleton for OldDataMonitor + } + // it should be already reported, but we report with INFO just in case + LOGGER.log(level, message.toString(), t); + } context.put("ReadError", null); } return result; diff --git a/core/src/main/java/jenkins/telemetry/impl/java11/MissingClassEvents.java b/core/src/main/java/jenkins/telemetry/impl/java11/MissingClassEvents.java index 2b7b2737e1d759ea857ebac860cb793c1ff83ae4..59d7ba6e47f1550b4ee6205bc3fd404a402e876a 100644 --- a/core/src/main/java/jenkins/telemetry/impl/java11/MissingClassEvents.java +++ b/core/src/main/java/jenkins/telemetry/impl/java11/MissingClassEvents.java @@ -42,10 +42,16 @@ public class MissingClassEvents { /* package */ static /* final */ int MAX_EVENTS_PER_SEND = 100; /** - * List of events, one per stack trace. + * List of events, one per stack trace, to send to Telemetry. Only the first {@code #MAX_EVENTS_PER_SEND} are sent. */ private ConcurrentHashMap, MissingClassEvent> events = new ConcurrentHashMap<>(MAX_EVENTS_PER_SEND); + /** + * List of all events registered on this execution, to avoid printing an event more than once in the log. This map + * is not limited. On every Jenkins restart is cleaned because it's not persisted, so the CNFE is printed again. The + * key is the class name not found to quickly look for it on every CNFE thrown. + */ + private ConcurrentHashMap eventsOnThisExecution = new ConcurrentHashMap<>(MAX_EVENTS_PER_SEND); /** * Add a new exception to the store. If the same exception already exists, it increases the occurrences. If we * already get the maximum number of exceptions, it doesn't add any value. @@ -60,19 +66,19 @@ public class MissingClassEvents { // We need the key (the stack trace) to be a list and unmodifiable List key = Collections.unmodifiableList(Arrays.asList(t.getStackTrace())); + + final MissingClassEvent newEvent = new MissingClassEvent(name, t); events.compute(key, (stackTraceElements, missingClassEvent) -> { if (missingClassEvent == null) { // It's a new element, the size will increase if (events.size() < MAX_EVENTS_PER_SEND) { // Create the new value - MissingClassEvent newEvent = new MissingClassEvent(name, t); occurrences.set(1); return newEvent; } else { return null; } - } else { // We update the occurrences and the last time it happened occurrences.set(missingClassEvent.getOccurrences()); @@ -82,6 +88,12 @@ public class MissingClassEvents { } }); + // We add the event to the list of already printed events. We used the name of the missing class instead of the + // full stack trace as a key to avoid filling the log with CNFE talking about the same class even though the + // stack traces are different. Worse scenario, if we don't put the exception on the IGNORED_PLACES correctly, + // the administrator will see the message again and we will be able to add the new one to the IGNORED_PLACES. + // In addition, the event is also sent to telemetry. + eventsOnThisExecution.putIfAbsent(name, newEvent); return occurrences.get(); } @@ -98,6 +110,21 @@ public class MissingClassEvents { return currentEvents; } + /** + * Returns true if the class name was already registered previously, during the current execution of this Jenkins + * instance. + * @param className the class name to check + * @return true if it was already registered + */ + public boolean alreadyRegistered(@NonNull String className) { + return eventsOnThisExecution.containsKey(className); + } + + // To clean on every test execution + void clearEventsOnThisExecution() { + eventsOnThisExecution.clear(); + } + @Override public String toString() { return "MissingClassEvents{" + diff --git a/core/src/main/java/jenkins/telemetry/impl/java11/MissingClassTelemetry.java b/core/src/main/java/jenkins/telemetry/impl/java11/MissingClassTelemetry.java index c962ca2b9893e5939d521f4cf021194a26707467..6b0a8145e003735a332090e6f6a16523bb2d053c 100644 --- a/core/src/main/java/jenkins/telemetry/impl/java11/MissingClassTelemetry.java +++ b/core/src/main/java/jenkins/telemetry/impl/java11/MissingClassTelemetry.java @@ -107,7 +107,9 @@ public class MissingClassTelemetry extends Telemetry { {"org.codehaus.groovy.control.ClassNodeResolver", "tryAsLoaderClassOrScript"}, {"org.kohsuke.stapler.RequestImpl$TypePair", "convertJSON"}, {"net.bull.javamelody.FilterContext", "isMojarraAvailable"}, // JENKINS-60725 - {"hudson.remoting.RemoteClassLoader$ClassLoaderProxy", "fetch3"} // JENKINS-61521 + {"hudson.remoting.RemoteClassLoader$ClassLoaderProxy", "fetch3"}, // JENKINS-61521 + //Don't add "java.base/" before sun.reflect.generics.factory.CoreReflectionFactory + {"sun.reflect.generics.factory.CoreReflectionFactory", "makeNamedType"}, // JENKINS-61920 }; @@ -239,13 +241,18 @@ public class MissingClassTelemetry extends Telemetry { // We call the methods in this order because if the missing class is not java related, we don't loop over the // stack trace to look if it's not thrown from an ignored place avoiding an impact on performance. if (isFromMovedPackage(name) && !calledFromIgnoredPlace(e)) { - events.put(name, e); - if (LOGGER.isLoggable(Level.WARNING)) + if (LOGGER.isLoggable(Level.WARNING) && !wasAlreadyReported(name)) { LOGGER.log(Level.WARNING, "Added a missed class for missing class telemetry. Class: " + name, e); + } + events.put(name, e); } } } + private static boolean wasAlreadyReported(@NonNull String className) { + return events.alreadyRegistered(className); + } + /** * Determine if the exception specified was thrown from an ignored place * @param throwable The exception thrown diff --git a/core/src/main/resources/hudson/PluginManager/_table.js b/core/src/main/resources/hudson/PluginManager/_table.js index c0ec3c151148377080d8a95f85c5c0e19f01aaf8..cfd9eb1980e94e0f5315927ba79098b1926b4f51 100644 --- a/core/src/main/resources/hudson/PluginManager/_table.js +++ b/core/src/main/resources/hudson/PluginManager/_table.js @@ -11,7 +11,7 @@ function checkPluginsWithoutWarnings() { Behaviour.specify("#filter-box", '_table', 0, function(e) { function applyFilter() { var filter = e.value.toLowerCase().trim(); - var filterParts = filter.split(/ +/).filter (word => word.length > 0); + var filterParts = filter.split(/ +/).filter (function(word) { return word.length > 0; }); var items = document.getElementsBySelector("TR.plugin"); var anyVisible = false; for (var i=0; i, MissingClassEvent> eventsGathered = MissingClassTelemetry.getEvents().getEventsAndClean(); - // Only one class miss gathered with two occurrences + // Only one class miss gathered assertEquals(1, eventsGathered.size()); + + // 2 log entries + assertEquals("Two missing class should be printed out in the log", 2, logging.getRecords().stream().filter(r -> r.getMessage().contains(NON_EXISTING_CLASS) || + r.getMessage().contains("sun.java.MySecondNonExistentJavaClass")).count()); } finally { MissingClassEvents.MAX_EVENTS_PER_SEND = maxEventsBefore; } @@ -91,12 +99,12 @@ public class MissingClassTelemetryFasterTest { Assume.assumeTrue("The telemetry should be enabled", MissingClassTelemetry.enabled()); try { - cl.loadClass("sun.java.MyNonExistentClass"); + cl.loadClass(NON_EXISTING_CLASS); } catch (ClassNotFoundException ignored) { } try { - cl.loadClass("sun.java.MyNonExistentJavaClass"); + cl.loadClass(NON_EXISTING_CLASS); } catch (ClassNotFoundException ignored) { } @@ -108,6 +116,10 @@ public class MissingClassTelemetryFasterTest { assertEquals(2, eventsGathered.size()); assertEquals(1, eventsGathered.values().iterator().next().getOccurrences()); assertEquals(1, eventsGathered.values().iterator().next().getOccurrences()); + + // The stack trace of these CNFE are different but we only look at class names when printing on logs, so + // just one log entry + assertEquals("Single missing class should be printed out in the log", 1, logging.getRecords().stream().filter(r -> r.getMessage().contains(NON_EXISTING_CLASS)).count()); } /** @@ -120,7 +132,7 @@ public class MissingClassTelemetryFasterTest { for (int i = 0; i < 2; i++) { try { //Exceptions thrown at the same line, with the same stack trace become occurrences of just one event - cl.loadClass("sun.java.MyNonExistentJavaClass"); + cl.loadClass(NON_EXISTING_CLASS); } catch (ClassNotFoundException ignored) { } } @@ -132,6 +144,9 @@ public class MissingClassTelemetryFasterTest { // Only one class miss gathered with two occurrences assertEquals(1, eventsGathered.size()); assertEquals(2, eventsGathered.values().iterator().next().getOccurrences()); + + // The class name and also the stack trace of these CNFEs are the same, so 1 log event + assertEquals("Just one missing class should be printed out in the log", 1, logging.getRecords().stream().filter(r -> r.getMessage().contains(NON_EXISTING_CLASS)).count()); } /** @@ -152,31 +167,42 @@ public class MissingClassTelemetryFasterTest { // No events gathered assertEquals(0, eventsGathered.size()); + + // No log + assertEquals("No log if the class is not a java one", 0, logging.getRecords().stream().filter(r -> r.getMessage().contains(NON_EXISTING_CLASS)).count()); } /** - * Only a max number of events is gathered. In this test, just one wit two occurrences + * Only a max number of events is gathered. In this test, just one with two occurrences */ @Test public void maxEventsLimitedSameStackTrace() { Assume.assumeTrue("The telemetry should be enabled", MissingClassTelemetry.enabled()); + // Backup to restore at the end of the test + int maxEventsBefore = MissingClassEvents.MAX_EVENTS_PER_SEND; MissingClassEvents.MAX_EVENTS_PER_SEND = 1; - for (int i = 0; i < 2; i++) { - try { - //Exceptions thrown at the same line, with the same stack trace become occurrences of just one event - cl.loadClass("sun.java.MyNonExistentJavaClass"); - } catch (ClassNotFoundException ignored) { + try { + for (int i = 0; i < 2; i++) { + try { + //Exceptions thrown at the same line, with the same stack trace become occurrences of just one event + cl.loadClass(NON_EXISTING_CLASS); + } catch (ClassNotFoundException ignored) { + } } - } - - // Get the events gathered - MissingClassEvents events = MissingClassTelemetry.getEvents(); - ConcurrentHashMap, MissingClassEvent> eventsGathered = events.getEventsAndClean(); + + // Get the events gathered + MissingClassEvents events = MissingClassTelemetry.getEvents(); + ConcurrentHashMap, MissingClassEvent> eventsGathered = events.getEventsAndClean(); + + // Only one event gathered + assertEquals(1, eventsGathered.size()); + assertEquals(2, eventsGathered.values().iterator().next().getOccurrences()); - // Only one event gathered - assertEquals(1, eventsGathered.size()); - assertEquals(2, eventsGathered.values().iterator().next().getOccurrences()); + assertEquals("One event should be logged", 1, logging.getRecords().stream().filter(r -> r.getMessage().contains(NON_EXISTING_CLASS)).count()); + } finally { + MissingClassEvents.MAX_EVENTS_PER_SEND = maxEventsBefore; + } } /** @@ -186,27 +212,37 @@ public class MissingClassTelemetryFasterTest { public void maxEventsLimitedDifferentStackTrace() { Assume.assumeTrue("The telemetry should be enabled", MissingClassTelemetry.enabled()); + // Backup to restore at the end of the test + int maxEventsBefore = MissingClassEvents.MAX_EVENTS_PER_SEND; MissingClassEvents.MAX_EVENTS_PER_SEND = 1; try { - cl.loadClass("sun.java.MyNonExistentClassGathered"); - } catch (ClassNotFoundException ignored) { - } + try { + cl.loadClass("sun.java.MyNonExistentClassGathered"); + } catch (ClassNotFoundException ignored) { + } + + try { + cl.loadClass("sun.java.MyNonExistentJavaClassNotGathered"); + } catch (ClassNotFoundException ignored) { + } + + // Get the events gathered + MissingClassEvents events = MissingClassTelemetry.getEvents(); + ConcurrentHashMap, MissingClassEvent> eventsGathered = events.getEventsAndClean(); + + // Only one event gathered + assertEquals(1, eventsGathered.size()); + assertEquals(1, eventsGathered.values().iterator().next().getOccurrences()); + assertThat(eventsGathered.values().iterator().next().getStackTrace(), containsString("MyNonExistentClassGathered")); + assertThat(eventsGathered.values().iterator().next().getStackTrace(), not(containsString("MyNonExistentJavaClassNotGathered"))); - try { - cl.loadClass("sun.java.MyNonExistentJavaClassNotGathered"); - } catch (ClassNotFoundException ignored) { + // Log has nothing to do with the limit for the sending. We print both because they have different class names + assertEquals("Two CNFE should be logged", 2, logging.getRecords().stream().filter(r -> r.getMessage().contains("MyNonExistentClassGathered") || + r.getMessage().contains("MyNonExistentJavaClassNotGathered")).count()); + } finally { + MissingClassEvents.MAX_EVENTS_PER_SEND = maxEventsBefore; } - - // Get the events gathered - MissingClassEvents events = MissingClassTelemetry.getEvents(); - ConcurrentHashMap, MissingClassEvent> eventsGathered = events.getEventsAndClean(); - - // Only one event gathered - assertEquals(1, eventsGathered.size()); - assertEquals(1, eventsGathered.values().iterator().next().getOccurrences()); - assertThat(eventsGathered.values().iterator().next().getStackTrace(), containsString("MyNonExistentClassGathered")); - assertThat(eventsGathered.values().iterator().next().getStackTrace(), not(containsString("MyNonExistentJavaClassNotGathered"))); } /** @@ -217,8 +253,6 @@ public class MissingClassTelemetryFasterTest { public void cyclesNotReachedBecauseCNFEReported() { Assume.assumeTrue("The telemetry should be enabled", MissingClassTelemetry.enabled()); - logging.record(MissingClassTelemetry.class, Logger.getLogger(MissingClassTelemetry.class.getName()).getLevel()).capture(5); - try { /* parent -> child -> cnfe @@ -228,7 +262,7 @@ public class MissingClassTelemetryFasterTest { found here */ - ClassNotFoundException cnfe = new ClassNotFoundException("sun.java.MyNonExistentClassGathered"); + ClassNotFoundException cnfe = new ClassNotFoundException(NON_EXISTING_CLASS); Exception child = new Exception("child", cnfe); Exception parent = new Exception("parent", child); // parent -> caused by -> child child.addSuppressed(parent); @@ -260,10 +294,8 @@ public class MissingClassTelemetryFasterTest { public void cnfeFoundAfterCycle() { Assume.assumeTrue("The telemetry should be enabled", MissingClassTelemetry.enabled()); - logging.record(MissingClassTelemetry.class, Logger.getLogger(MissingClassTelemetry.class.getName()).getLevel()).capture(5); - try { - ClassNotFoundException cnfe = new ClassNotFoundException("sun.java.MyNonExistentClassGathered"); + ClassNotFoundException cnfe = new ClassNotFoundException(NON_EXISTING_CLASS); /* parent -> child @@ -302,8 +334,6 @@ public class MissingClassTelemetryFasterTest { public void cnfeAfterCNFENotJava11AndCycle() { Assume.assumeTrue("The telemetry should be enabled", MissingClassTelemetry.enabled()); - logging.record(MissingClassTelemetry.class, Logger.getLogger(MissingClassTelemetry.class.getName()).getLevel()).capture(5); - try { ClassNotFoundException cnfe = new ClassNotFoundException("sun.java.MyNonExistentClassGathered"); ClassNotFoundException cnfeNonJava11 = new ClassNotFoundException("MyNonExistentClassGathered"); @@ -352,5 +382,7 @@ public class MissingClassTelemetryFasterTest { // No events gathered assertEquals(0, eventsGathered.size()); + + assertEquals("No log if telemetry disabled", 0, logging.getRecords().stream().count()); } }