Simplify stacktraces of unhandled exceptions in logs

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.

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;
+    }
 }

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"));
+        }
+    }
 }

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 <I> Instance class
  */
 public class DefaultExceptionHandler<S extends Solution<S,I>, I extends Instance> extends ExceptionHandler<S,I> {
-    private static final Logger logger = Logger.getLogger(DefaultExceptionHandler.class.getName());
+    private static final Logger logger = LoggerFactory.getLogger(DefaultExceptionHandler.class.getName());
 
     private final IOManager<S,I> io;
 
@@ -36,17 +38,18 @@ public DefaultExceptionHandler(IOManager<S, I> io) {
      * Behaviour can be customized or changed by extending the ExceptionHandler class.
      */
     public void handleException(String experimentName, int iteration, Exception e, Optional<S> sOptional, I i, Algorithm<S,I> 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.");
         }
     }
 

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;

core/src/main/java/es/urjc/etsii/grafo/solver/Mork.java

@@ -71,7 +71,8 @@ public static <M extends Move<S,I>, S extends Solution<S,I>, 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;
         }
     }