3

What do I have

I had set an AspectJ joint point for some specific methods in order to be able to measure their execution time. I never intercept anything in the code flow (so we can call this a "read-only" type of weaved code). The corresponding code looks like:

@Around("execution (* my.package.myclass..*(..)) && @annotation(my.another.package.Monitored)")
public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
    Object returnObject = null;
    long startTime = System.currentTimeMillis();
    try {
        returnObject = joinPoint.proceed();
    } catch (Throwable throwable) {
        System.out.println("Intercepted exception " + throwable.getClass().getName() + ": " + throwable.getMessage());
        throw throwable; //<---- this does the jail-breaking
    } finally {
        long endTime = System.currentTimeMillis();
        long elapsedTime = endTime - startTime;
        MethodSignature signature = (MethodSignature) joinPoint.getSignature();
        Method method = signature.getMethod();
        Monitored annotation = method.getAnnotation(Monitored.class);
        //do some more logic as logging etc.
    }
    return returnObject;
}

Also in the application code itself I have stuff like:

try {
    //this is a monitored call:
    my.package.myclass.doStuff();
} catch (Throwable anyException) {
    //log stuff
    //& return default non-null entity
}

Which means I gracefully handle any possible exception at that layer and disallow it to be thrown to the upper layers.

What went wrong

If there is no exceptions thrown by the application code, there are no issues and all the logic works fine - time is measured, logged and tracked. But if there is an exception thrown by the application it escapes the application handler which I posted above and is thrown to the upper layers.

In the debugger I see that it is done by the line which throws throwable from my aspected handler. And this is something I do not understand. Obviously, if I remove throwing an exception from there it becomes even worse since now the entity will be null and the whole application flow would be broken

Question

How to properly deal with exception so to log them happened together with conducting all measuring business and do not allow them to jail-break?

Alma Do
  • 37,009
  • 9
  • 76
  • 105
  • I just set up a little test project with this scenario you describe here, and the exception doesn't escape the application level exception handler for me. Are you, by any chance, using Spring with your project? – Nándor Előd Fekete Jun 17 '16 at 13:29
  • @NándorElődFekete no, I do not use it – Alma Do Jun 17 '16 at 13:29
  • Is your project any different in what you describe here? Because for me, it works as it should. – Nándor Előd Fekete Jun 17 '16 at 13:31
  • @NándorElődFekete there is one thing I did not mentioned here (not sure if it's relevant): I use run-time weaving since I use jar-loading. And the exception is thrown from within loaded class, so it is using different class-loader (not same which defines aspected class or the class which serves as a jail for exceptions) – Alma Do Jun 17 '16 at 13:33
  • It depends. Classloading issues can create very strange behavior. You could end up with two different versions of the same class. Are you catching `Throwable` specifically in your AspectJ and application-level exception handlers? Or some other, application defined exception class? – Nándor Előd Fekete Jun 17 '16 at 13:37
  • I actually **end up** with different versions of same class (it's intended behavior) - but all the dependency tree for any of such classes is strictly independent from one another (so it's not possible to reference same stuff from different class versions). And no - I do not have any interception of exceptions within AspectJ, it's not intended at all. I do not want to change the flow of the application anyhow by that. – Alma Do Jun 17 '16 at 13:41
  • Well, in your aspect, you're catching and rethrowing `Throwable`. Is it `Throwable` that you catch there, or some custom exception class you're catching there? What I'm trying to find out, that, maybe you got two different versions of the exception class you're catching (be it `Throwable` or some other custom exception class). So it might be that you throw `Throwable` and you're catching `Throwable`, but they might be different class instances, so you the handler won't catch an exception of a different version of that type. – Nándor Előd Fekete Jun 17 '16 at 13:48
  • Maybe the underlying issue is just classloading and might be completely unrelated to the measuring aspect (from the code of the aspect, it shouldn't change the exception type since it rethrows it). – Nándor Előd Fekete Jun 17 '16 at 13:49
  • I'm not sure how that could be possible. The exception I catch in the jail-class is `java.lang.Throwable`. I assume any exception that is thrown will fit as a sub-type of that disregarding dynamic class-loading. – Alma Do Jun 17 '16 at 13:55
  • Since your problem doesn't manifest itself in a normal classloading environment (I know this, because I tried it), so my best guess for the issue is that it's classloading related. – Nándor Előd Fekete Jun 17 '16 at 14:04

1 Answers1

1

Just as for Nándor it works for me when trying to replicate your situation, even with LTW. Here is a stand-alone example:

Java driver application:

package de.scrum_master.app;

public class Application {
    public static void main(String[] args) {
        try {
            new Application().doSomething();
        }
        catch (Throwable t) {
            System.out.println("Caught & handled exception: " + t);
        }
    }

    public void doSomething() throws InterruptedException {
        Thread.sleep(100);
        throw new RuntimeException("Oops!");
    }
}

Aspect:

package de.scrum_master.aspect;

import java.lang.reflect.Method;

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.reflect.MethodSignature;

@Aspect
public class RuntimeLogger {
    @Around("execution(!static * *(..))")
    public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
        Object returnObject = null;
        long startTime = System.currentTimeMillis();
        try {
            returnObject = joinPoint.proceed();
        } catch (Throwable throwable) {
            System.out.println("Intercepted exception " + throwable.getClass().getName() + ": " + throwable.getMessage());
            throw throwable; //<---- this does the jail-breaking
        } finally {
            long endTime = System.currentTimeMillis();
            long elapsedTime = endTime - startTime;
            MethodSignature signature = (MethodSignature) joinPoint.getSignature();
            Method method = signature.getMethod();
            System.out.println(elapsedTime + " " + method);
        }
        return returnObject;
    }
}

Console log:

Intercepted exception java.lang.RuntimeException: Oops!
100 public void de.scrum_master.app.Application.doSomething() throws java.lang.InterruptedException
Caught & handled exception: java.lang.RuntimeException: Oops!

Here on StackOverflow a while ago someone was asking for a way to generate some kind of uncatchable "Chuck Norris exception" and I created one for him here using AspectJ. So, just guessing, do you maybe have another aspect or advice anywhere in your code which (re-)throws the exception in question fron a before() : handler() advice? For instance, if you add this to your aspect:

@Before("handler(*) && args(t)")
public void enforceThrow(Throwable t) throws Throwable {
    System.out.println("Let's see if we can break the jail...");
    throw t;
}

Then the console log turns into:

Let's see if we can break the jail...
100 public void de.scrum_master.app.Application.doSomething() throws java.lang.InterruptedException
Let's see if we can break the jail...
Exception in thread "main" java.lang.RuntimeException: Oops!
    at de.scrum_master.app.Application.doSomething_aroundBody0(Application.java:15)
    at de.scrum_master.app.Application$AjcClosure1.run(Application.java:1)
    at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:149)
    at de.scrum_master.aspect.RuntimeLogger.logExecutionTime(RuntimeLogger.aj:18)
    at de.scrum_master.app.Application.doSomething(Application.java:14)
    at de.scrum_master.app.Application.main(Application.java:6)

This is pretty much similar to the effect you are describing.

Community
  • 1
  • 1
kriegaex
  • 63,017
  • 15
  • 111
  • 202
  • Thanks, but I have only one aspected class and only one handler. I will try to prepare minimal viable demo project (since the one I'm working on is an enterprise-licenced one) – Alma Do Jun 20 '16 at 07:35
  • Then there is something you did not tell us. Unless you provide an [SSCCE](http://sscce.org/) reproducing the problem, nobody will be able to help you. – kriegaex Jun 26 '16 at 06:30
  • You are a StackOverflow user with high reputation. I wonder why you have never followed up my answer into which I put quiote some effort. I would really like to (help you) find out what went wrong. – kriegaex Jan 24 '17 at 10:47
  • Because "high-reputation" doesn't directly translate to "high knowledge"? I've followed that - but unfortunately as you may notice from my activity on SO - I barely have time due to my work load :) Btw, eventually it was fixed by putting another exception handler. And I honestly already forgot about the case, thanks for reminding. If I have time - I'll try to reproduce the issue with the code you've provided. _P.S: I was getting far more votes for some answers to where I put little efforts (literally docs link + some brief talks) while for some where I was spending days - I got 2..3 votes._ – Alma Do Jan 24 '17 at 11:23
  • I know what you mean. Speaking of high workload, I have been a freelance consultant (Scrum coach) for 10+ years and do SO just for fun. I stopped making money with software development in the year 2000. But I do know that you do not get 28k reputation in 3.5 years, answering almost 800 questions, if you do not spend a lot of time here. ;-) No offense meant, I admire that. – kriegaex Jan 24 '17 at 11:46