Changeset 18549 in josm

Timestamp:

2022-09-06T18:40:21+02:00 (20 months ago)

Author:

taylor.smock

Message:

See #22183: NoClassDefFoundError: Could not initialize class org.openstreetmap.josm.actions.SessionSaveAction

The root cause is a suppressed NPE whose stack trace is not given
in the bug report.

This adds a method to BugReport to add suppressed exceptions to a report.
In the future, if we keep the code long-term, methods in Logging which take
exceptions may assume the exception is suppressed, and add it to the
suppressed exceptions.

Location:

trunk

Files:

• src/org/openstreetmap/josm/gui/progress/swing/ProgressMonitorExecutor.java (modified) (2 diffs)
• src/org/openstreetmap/josm/gui/util/GuiHelper.java (modified) (1 diff)
• src/org/openstreetmap/josm/tools/bugreport/BugReport.java (modified) (4 diffs)
• test/unit/org/openstreetmap/josm/tools/bugreport/BugReportTest.java (modified) (4 diffs)

trunk/src/org/openstreetmap/josm/gui/progress/swing/ProgressMonitorExecutor.java

@@ -11 +11 @@
 import org.openstreetmap.josm.tools.Logging;
 import org.openstreetmap.josm.tools.Utils;
+import org.openstreetmap.josm.tools.bugreport.BugReport;
 
 /**
@@ -59 +60 @@
         if (t != null) {
             Logging.error("Thread {0} raised {1}", Thread.currentThread().getName(), t);
+            BugReport.addSuppressedException(t);
         }
     }

trunk/src/org/openstreetmap/josm/gui/util/GuiHelper.java

@@ -212 +212 @@
     static void handleEDTException(Throwable t) {
         Logging.logWithStackTrace(Logging.LEVEL_ERROR, t, "Exception raised in EDT");
+        BugReport.addSuppressedException(t);
     }
 

trunk/src/org/openstreetmap/josm/tools/bugreport/BugReport.java

@@ -5 +5 @@
 import java.io.Serializable;
 import java.io.StringWriter;
+import java.time.Instant;
+import java.util.ArrayDeque;
+import java.util.Deque;
 import java.util.concurrent.CopyOnWriteArrayList;
 import java.util.function.Predicate;
+
+import org.openstreetmap.josm.tools.Pair;
 
 /**
@@ -40 +45 @@
 public final class BugReport implements Serializable {
     private static final long serialVersionUID = 1L;
+    /** The maximum suppressed exceptions to keep to report */
+    private static final byte MAXIMUM_SUPPRESSED_EXCEPTIONS = 4;
+    /** The list of suppressed exceptions, Pair<time reported, exception> */
+    private static final Deque<Pair<Instant, Throwable>> SUPPRESSED_EXCEPTIONS = new ArrayDeque<>(MAXIMUM_SUPPRESSED_EXCEPTIONS);
 
     private boolean includeStatusReport = true;
@@ -54 +63 @@
         this.exception = e;
         includeAllStackTraces = e.mayHaveConcurrentSource();
+    }
+
+    /**
+     * Add a suppressed exception. Mostly useful for when a chain of exceptions causes an actual bug report.
+     * This should only be used when an exception is raised in {@link org.openstreetmap.josm.gui.util.GuiHelper}
+     * or {@link org.openstreetmap.josm.gui.progress.swing.ProgressMonitorExecutor} at this time.
+     * {@link org.openstreetmap.josm.tools.Logging} may call this in the future, when logging a throwable.
+     * @param t The throwable raised. If {@code null}, we add a new {@code NullPointerException} instead.
+     * @since 18549
+     */
+    public static void addSuppressedException(Throwable t) {
+        SUPPRESSED_EXCEPTIONS.add(new Pair<>(Instant.now(), t != null ? t : new NullPointerException()));
+        // Ensure we don't call pop in more than MAXIMUM_SUPPRESSED_EXCEPTIONS threads. This guard is
+        // here just in case someone doesn't read the javadocs.
+        synchronized (SUPPRESSED_EXCEPTIONS) {
+            // Ensure we aren't keeping exceptions forever
+            while (SUPPRESSED_EXCEPTIONS.size() > MAXIMUM_SUPPRESSED_EXCEPTIONS) {
+                SUPPRESSED_EXCEPTIONS.pop();
+            }
+        }
     }
 
@@ -136 +165 @@
             exception.printReportThreadsTo(out);
         }
+        synchronized (SUPPRESSED_EXCEPTIONS) {
+            if (!SUPPRESSED_EXCEPTIONS.isEmpty()) {
+                out.println("=== ADDITIONAL EXCEPTIONS ===");
+                // Avoid multiple bug reports from reading from the deque at the same time.
+                while (SUPPRESSED_EXCEPTIONS.peek() != null) {
+                    Pair<Instant, Throwable> currentException = SUPPRESSED_EXCEPTIONS.pop();
+                    out.println("==== Exception at " + currentException.a.toEpochMilli() + " ====");
+                    currentException.b.printStackTrace(out);
+                }
+            }
+        }
         return stringWriter.toString().replaceAll("\r", "");
     }

trunk/test/unit/org/openstreetmap/josm/tools/bugreport/BugReportTest.java

@@ -2 +2 @@
 package org.openstreetmap.josm.tools.bugreport;
 
+import static org.junit.jupiter.api.Assertions.assertAll;
+import static org.junit.jupiter.api.Assertions.assertDoesNotThrow;
 import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.junit.jupiter.api.Assertions.assertFalse;
 import static org.junit.jupiter.api.Assertions.assertSame;
 import static org.junit.jupiter.api.Assertions.assertTrue;
@@ -9 +12 @@
 import java.io.PrintWriter;
 import java.io.StringWriter;
-
+import java.lang.reflect.Field;
+import java.util.function.Consumer;
+import java.util.logging.Handler;
+import java.util.regex.Matcher;
+import java.util.regex.Pattern;
+import java.util.stream.Stream;
+
+import org.junit.jupiter.api.AfterAll;
+import org.junit.jupiter.api.BeforeAll;
 import org.junit.jupiter.api.Test;
+import org.junit.jupiter.params.ParameterizedTest;
+import org.junit.jupiter.params.provider.Arguments;
+import org.junit.jupiter.params.provider.MethodSource;
+import org.junit.platform.commons.util.ReflectionUtils;
 import org.openstreetmap.josm.actions.ShowStatusReportAction;
+import org.openstreetmap.josm.gui.MainApplication;
+import org.openstreetmap.josm.gui.util.GuiHelper;
 import org.openstreetmap.josm.testutils.annotations.BasicPreferences;
+import org.openstreetmap.josm.tools.Logging;
 
 /**
@@ -21 +39 @@
 @BasicPreferences
 class BugReportTest {
+    private static Handler[] handlers;
+
+    @AfterAll
+    static void cleanup() {
+        // Clear queue
+        new BugReport(BugReport.intercept(new NullPointerException())).getReportText("");
+        Logging.clearLastErrorAndWarnings();
+        for (Handler handler : handlers) {
+            Logging.getLogger().addHandler(handler);
+        }
+    }
+
+    @BeforeAll
+    static void setup() {
+        handlers = Logging.getLogger().getHandlers();
+        // Avoid console spam
+        for (Handler handler : handlers) {
+            Logging.getLogger().removeHandler(handler);
+        }
+    }
+
     /**
      * Test {@link BugReport#getReportText}
@@ -70 +109 @@
         return BugReport.getCallingMethod(2);
     }
+
+    @Test
+    void testSuppressedExceptionsOrder() {
+        final String methodName = "testSuppressedExceptionsOrder";
+        BugReport.addSuppressedException(new NullPointerException(methodName));
+        BugReport.addSuppressedException(new IllegalStateException(methodName));
+        BugReport bugReport = new BugReport(BugReport.intercept(new IOException(methodName)));
+        final String report = assertDoesNotThrow(() -> bugReport.getReportText(methodName));
+        assertAll(() -> assertTrue(report.contains("NullPointerException")),
+                () -> assertTrue(report.contains("IOException")),
+                () -> assertTrue(report.contains("IllegalStateException")));
+        int ioe = report.indexOf("IOException");
+        int npe = report.indexOf("NullPointerException");
+        int ise = report.indexOf("IllegalStateException");
+        assertAll("Ordering of exceptions is wrong",
+                () -> assertTrue(ioe < npe, "IOException should be reported before NullPointerException"),
+                () -> assertTrue(npe < ise, "NullPointerException should be reported before IllegalStateException"));
+    }
+
+    static Stream<Arguments> testSuppressedExceptions() {
+        return Stream.of(
+                Arguments.of("GuiHelper::runInEDTAndWaitAndReturn",
+                        (Consumer<Runnable>) r -> GuiHelper.runInEDTAndWaitAndReturn(() -> {
+                            r.run();
+                            return null;
+                        })),
+                Arguments.of("GuiHelper::runInEDTAndWait", (Consumer<Runnable>) GuiHelper::runInEDTAndWait),
+                Arguments.of("MainApplication.worker", (Consumer<Runnable>) MainApplication.worker::execute)
+        );
+    }
+
+    @ParameterizedTest
+    @MethodSource
+    void testSuppressedExceptions(String workerName, Consumer<Runnable> worker) {
+        // Throw a npe in the worker. Workers might give us the exception, wrapped or otherwise.
+        try {
+            worker.accept(() -> {
+                throw new NullPointerException();
+            });
+        } catch (Exception e) {
+            // pass. MainApplication.worker can continue throwing the NPE;
+            Logging.trace(e);
+        }
+        // Ensure that the threads are synced
+        assertDoesNotThrow(() -> worker.accept(() -> { /* sync */ }));
+        // Now throw an exception
+        BugReport bugReport = new BugReport(BugReport.intercept(new IOException("testSuppressedExceptions")));
+        String report = bugReport.getReportText(workerName);
+        assertTrue(report.contains("IOException"));
+        assertTrue(report.contains("NullPointerException"));
+    }
+
+    @Test
+    void testSuppressedExceptionsReportedOnce() {
+        // Add the exception
+        BugReport.addSuppressedException(new NullPointerException("testSuppressedExceptionsReportedOnce"));
+        BugReport bugReport = new BugReport(BugReport.intercept(new IOException("testSuppressedExceptionsReportedOnce")));
+        // Get the report which clears the suppressed exceptions
+        String report = bugReport.getReportText("");
+        assertTrue(report.contains("IOException"));
+        assertTrue(report.contains("NullPointerException"));
+
+        BugReport bugReport2 = new BugReport(BugReport.intercept(new IOException("testSuppressedExceptionsReportedOnce")));
+        String report2 = bugReport2.getReportText("");
+        assertTrue(report2.contains("IOException"));
+        assertFalse(report2.contains("NullPointerException"));
+    }
+
+    @Test
+    void testManyExceptions() throws ReflectiveOperationException {
+        Field suppressedExceptions = BugReport.class.getDeclaredField("MAXIMUM_SUPPRESSED_EXCEPTIONS");
+        ReflectionUtils.makeAccessible(suppressedExceptions);
+        final byte expected = suppressedExceptions.getByte(null);
+        final int end = 2 * expected;
+        // Add many suppressed exceptions
+        for (int i = 0; i < end; i++) {
+            BugReport.addSuppressedException(new NullPointerException("NPE: " + i));
+        }
+        BugReport bugReport = new BugReport(BugReport.intercept(new IOException("testManyExceptions")));
+        String report = bugReport.getReportText("");
+        Matcher matcher = Pattern.compile("NPE: (\\d+)").matcher(report);
+        for (int i = end - expected; i < end; ++i) {
+            assertTrue(matcher.find());
+            assertEquals(Integer.toString(i), matcher.group(1));
+        }
+        assertFalse(matcher.find());
+    }
+
+    @Test
+    void testNullException() {
+        // This should add a NPE to the suppressed exceptions
+        assertDoesNotThrow(() -> BugReport.addSuppressedException(null));
+        BugReport bugReport = new BugReport(BugReport.intercept(new IOException("testNullException")));
+        // Getting the report text should not throw an exception.
+        String report = assertDoesNotThrow(() -> bugReport.getReportText(""));
+        assertTrue(report.contains("IOException"));
+        assertTrue(report.contains("NullPointerException"));
+    }
 }