From ba6f3d71947dd2e7277ef961236435be7b629c11 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Mart=C3=ADn?= Date: Fri, 20 Dec 2024 18:33:01 +0100 Subject: [PATCH] Simplify stacktraces of unhandled exceptions in logs --- CHANGELOG.md | 1 + .../urjc/etsii/grafo/util/ExceptionUtil.java | 32 +++++++++++++++++++ .../etsii/grafo/util/ExceptionUtilTest.java | 19 +++++++++-- .../exceptions/DefaultExceptionHandler.java | 15 +++++---- .../orchestrator/DefaultOrchestrator.java | 4 ++- .../java/es/urjc/etsii/grafo/solver/Mork.java | 3 +- 6 files changed, 64 insertions(+), 10 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index cba2f662..3e7783ad 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,7 @@ - (New) Irace plots: generate an HTML report with the results of running the autoconfig procedure. - (New) Two ParetoSet implementations are provided: a simple list based (should be correct, but slow) and a NDTree based implementation (should be fast, but may contain bugs). - (New) ValidationResult: allow accumulating errors. +- (New) When we report an unhandled exception, filter some stackframes that are not relevant to the user code. Full stacktrace still logged at trace level. - (Breaking) Due to changes in how objectives are handled, ReferenceResult methods have been renamed for clarity. - (Fix) Math.random, Collections.shuffle now blocked using AspectJ instead of reflection. --add-opens no longer necessary. - (Fix) Add @JsonIgnore to instance in solution class already exists in getter, but serializer may be configured to use fields instead of methods. diff --git a/common/src/main/java/es/urjc/etsii/grafo/util/ExceptionUtil.java b/common/src/main/java/es/urjc/etsii/grafo/util/ExceptionUtil.java index 8723cbf7..4bf4f8fa 100644 --- a/common/src/main/java/es/urjc/etsii/grafo/util/ExceptionUtil.java +++ b/common/src/main/java/es/urjc/etsii/grafo/util/ExceptionUtil.java @@ -1,6 +1,18 @@ package es.urjc.etsii.grafo.util; +import org.apache.commons.lang3.exception.ExceptionUtils; + public class ExceptionUtil { + + public static String[] filterTerms = new String[]{ + "$AjcClosure", + "org.springframework", + "java.base/java.util.stream", + "org.aspectj.runtime.reflect.JoinPointImpl.proceed", + "_aroundBody0", + "es.urjc.etsii.grafo.aop.TimedAspect." + }; + /** * Get the root cause of an exception * @param e exception to investigate @@ -15,4 +27,24 @@ public static Throwable getRootCause(Throwable e){ } return e; } + + public static String filteredStacktrace(Throwable e){ + var frames = ExceptionUtils.getStackFrames(e); + StringBuilder sb = new StringBuilder(); + for(var frame: frames){ + if(!filterFrame(frame)){ + sb.append(frame).append(System.lineSeparator()); + } + } + return sb.toString(); + } + + private static boolean filterFrame(String frame){ + for(var filter: filterTerms){ + if(frame.contains(filter)){ + return true; + } + } + return false; + } } diff --git a/common/src/test/java/es/urjc/etsii/grafo/util/ExceptionUtilTest.java b/common/src/test/java/es/urjc/etsii/grafo/util/ExceptionUtilTest.java index 41974d22..566d006d 100644 --- a/common/src/test/java/es/urjc/etsii/grafo/util/ExceptionUtilTest.java +++ b/common/src/test/java/es/urjc/etsii/grafo/util/ExceptionUtilTest.java @@ -1,9 +1,11 @@ package es.urjc.etsii.grafo.util; +import org.apache.commons.lang3.exception.ExceptionUtils; import org.junit.jupiter.api.Test; -import static org.junit.jupiter.api.Assertions.assertEquals; -import static org.junit.jupiter.api.Assertions.assertThrows; +import java.util.List; + +import static org.junit.jupiter.api.Assertions.*; public class ExceptionUtilTest { @Test @@ -16,4 +18,17 @@ public void testGetRootCause() { assertEquals(rootCause, ExceptionUtil.getRootCause(new IllegalArgumentException(new IllegalStateException(new RuntimeException(rootCause))))); assertThrows(IllegalArgumentException.class, () -> ExceptionUtil.getRootCause(null)); } + + @Test + public void testFilteresStacktrace(){ + var list = List.of("a,b,c,d,e,f"); + try { + list.stream().sorted().forEach(e -> {throw new IllegalArgumentException();}); + } catch (IllegalArgumentException e){ + var fullStacktrace = ExceptionUtils.getStackTrace(e); + var simplifiedStacktrace = ExceptionUtil.filteredStacktrace(e); + assertTrue(fullStacktrace.contains("java.util.stream")); + assertFalse(simplifiedStacktrace.contains("java.util.stream")); + } + } } diff --git a/core/src/main/java/es/urjc/etsii/grafo/exceptions/DefaultExceptionHandler.java b/core/src/main/java/es/urjc/etsii/grafo/exceptions/DefaultExceptionHandler.java index f543d74c..b75700e4 100644 --- a/core/src/main/java/es/urjc/etsii/grafo/exceptions/DefaultExceptionHandler.java +++ b/core/src/main/java/es/urjc/etsii/grafo/exceptions/DefaultExceptionHandler.java @@ -6,11 +6,13 @@ import es.urjc.etsii.grafo.io.Instance; import es.urjc.etsii.grafo.services.IOManager; import es.urjc.etsii.grafo.solution.Solution; +import es.urjc.etsii.grafo.util.ExceptionUtil; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import java.io.PrintWriter; import java.io.StringWriter; import java.util.Optional; -import java.util.logging.Logger; /** * Default exception handler. @@ -21,7 +23,7 @@ * @param Instance class */ public class DefaultExceptionHandler, I extends Instance> extends ExceptionHandler { - private static final Logger logger = Logger.getLogger(DefaultExceptionHandler.class.getName()); + private static final Logger logger = LoggerFactory.getLogger(DefaultExceptionHandler.class.getName()); private final IOManager io; @@ -36,17 +38,18 @@ public DefaultExceptionHandler(IOManager io) { * Behaviour can be customized or changed by extending the ExceptionHandler class. */ public void handleException(String experimentName, int iteration, Exception e, Optional sOptional, I i, Algorithm algorithm){ - logger.severe(String.format("Error while solving instance %s with algorithm %s, iteration %s, skipping. Exception message: %s", i.getId(), algorithm.toString(), iteration, e.getMessage())); + logger.error("Error while solving instance {} with algorithm {}, iteration {}, skipping. Exception message: {}.", i.getId(), algorithm.toString(), iteration, e.getMessage()); explain(e); String stackTrace = getStackTrace(e); - logger.severe("Stacktrace: " + stackTrace); - sOptional.ifPresent(s -> logger.severe("Last executed movements: " + s.lastExecutesMoves())); + logger.info("Simplified stacktrace: {}", ExceptionUtil.filteredStacktrace(e)); + logger.trace("Full error stacktrace: {}", stackTrace); + sOptional.ifPresent(s -> logger.info("Last executed moves: {}", s.lastExecutesMoves())); io.exportError(experimentName, algorithm, i, e, stackTrace); } private void explain(Throwable e) { if(e instanceof InvalidRandomException){ - logger.severe("The exception InvalidRandomException is generated when a method from the Java API that would break reproducibility is executed. See https://mork-optimization.readthedocs.io/en/latest/quickstart/bestpractices/#customized-random-generator for more information."); + logger.error("The exception InvalidRandomException is generated when a method from the Java API that would break reproducibility is executed. See https://mork-optimization.readthedocs.io/en/latest/quickstart/bestpractices/#customized-random-generator for more information."); } } diff --git a/core/src/main/java/es/urjc/etsii/grafo/orchestrator/DefaultOrchestrator.java b/core/src/main/java/es/urjc/etsii/grafo/orchestrator/DefaultOrchestrator.java index 2ec8908c..bbb81b4e 100644 --- a/core/src/main/java/es/urjc/etsii/grafo/orchestrator/DefaultOrchestrator.java +++ b/core/src/main/java/es/urjc/etsii/grafo/orchestrator/DefaultOrchestrator.java @@ -97,7 +97,9 @@ public void run(String... args) { long startTime = System.nanoTime(); try { executor.startup(); - experiments.values().forEach(this::experimentWrapper); + for(var experiment : experiments.values()){ + experimentWrapper(experiment); + } } finally { executor.shutdown(); long totalExecutionTime = System.nanoTime() - startTime; diff --git a/core/src/main/java/es/urjc/etsii/grafo/solver/Mork.java b/core/src/main/java/es/urjc/etsii/grafo/solver/Mork.java index 2a67a65f..41a81974 100644 --- a/core/src/main/java/es/urjc/etsii/grafo/solver/Mork.java +++ b/core/src/main/java/es/urjc/etsii/grafo/solver/Mork.java @@ -71,7 +71,8 @@ public static , S extends Solution, I extends Instance> } catch (Exception e) { var rootCause = ExceptionUtil.getRootCause(e); log.error("%s: %s".formatted(rootCause.getClass().getSimpleName(), rootCause.getMessage())); - log.info("Unhandled exception: ", e); + log.info("Simplified stacktrace: {}", ExceptionUtil.filteredStacktrace(e)); + log.trace("Full stacktrace: ", e); return false; } }