16

UPDATE: The latest version of Intellij IDEA implements exactly what I'm looking for. The question is how to implement this outside of the IDE (so I can to dump async stack traces to log files), ideally without the use of an instrumenting agent.


Ever since I converted my application from a synchronous to asynchronous model I am having problems debugging failures.

When I use synchronous APIs, I always find my classes in exception stacktraces so I know where to begin looking if something goes wrong. With asynchronous APIs, I am getting stacktraces that do not reference my classes nor indicate what request triggered the failure.

I'll give you a concrete example, but I'm interested in a general solution to this kind of problem.

Concrete example

I make an HTTP request using Jersey:

new Client().target("http://test.com/").request().rx().get(JsonNode.class);

where rx() indicates that the request should take place asynchronously, returning a CompletionStage<JsonNode> instead of a JsonNode directly. If this call fails, I get this stacktrace:

javax.ws.rs.ForbiddenException: HTTP 403 Authentication Failed
    at org.glassfish.jersey.client.JerseyInvocation.convertToException(JerseyInvocation.java:1083)
    at org.glassfish.jersey.client.JerseyInvocation.translate(JerseyInvocation.java:883)
    at org.glassfish.jersey.client.JerseyInvocation.lambda$invoke$1(JerseyInvocation.java:767)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:316)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:298)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:229)
    at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:414)
    at org.glassfish.jersey.client.JerseyInvocation.invoke(JerseyInvocation.java:765)
    at org.glassfish.jersey.client.JerseyInvocation$Builder.method(JerseyInvocation.java:456)
    at org.glassfish.jersey.client.JerseyCompletionStageRxInvoker.lambda$method$1(JerseyCompletionStageRxInvoker.java:70)
    at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590)

Notice:

  • The stacktrace does not reference user code.
  • The exception message does not contain contextual information about the HTTP request that triggered the error (HTTP method, URI, etc).

As a result, I have no way of tracking the exception back to its source.

Why this is happening

If you dig under the hood, you will discover that Jersey is invoking:

CompletableFuture.supplyAsync(() -> getSyncInvoker().method(name, entity, responseType))

for rx() invocations. Because the supplier is constructed by Jersey, there is no reference back to user code.

What I've tried

I tried filing a bug report against Jetty for an unrelated async example, and was subsequently turned down on security grounds.

Instead, I've been adding contextual information as follows:

makeHttpRequest().exceptionally(e ->
{
    throw new RuntimeException(e);
});

Meaning, I am manually adding exceptionally() after every single HTTP request in my code. Any exceptions thrown by Jersey are wrapped in a secondary exception that references my code. The resulting stacktrace looks like this:

java.lang.RuntimeException: javax.ws.rs.ForbiddenException: HTTP 403 Authentication Failed
    at my.user.code.Testcase.lambda$null$1(Testcase.java:25)
    at java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:870)
    ... 6 common frames omitted
Caused by: javax.ws.rs.ForbiddenException: HTTP 403 Authentication Failed
    at org.glassfish.jersey.client.JerseyInvocation.convertToException(JerseyInvocation.java:1083)
    at org.glassfish.jersey.client.JerseyInvocation.translate(JerseyInvocation.java:883)
    at org.glassfish.jersey.client.JerseyInvocation.lambda$invoke$1(JerseyInvocation.java:767)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:316)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:298)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:229)
    at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:414)
    at org.glassfish.jersey.client.JerseyInvocation.invoke(JerseyInvocation.java:765)
    at org.glassfish.jersey.client.JerseyInvocation$Builder.method(JerseyInvocation.java:456)
    at org.glassfish.jersey.client.JerseyCompletionStageRxInvoker.lambda$method$1(JerseyCompletionStageRxInvoker.java:70)
    at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590)
    ... 3 common frames omitted

I don't like this approach because it is error prone and decreases the readability of the code. If I mistakenly omit this for some HTTP request I will end up with a vague stacktrace and spend a lot time tracking it down.

Further, if I want to hide this trick behind a utility class then I have to instantiate an exception outside of a CompletionStage; otherwise, the utility class will show up in the stacktrace instead of the actual call site. Instantiating an exception outside of a CompletionStage is extremely expensive because this code runs even if no exception is ever thrown by the async call.

My question

Is there a robust, easy-to-maintain approach to add contextual information to asynchronous calls?

Alternatively, is there an efficient approach to track stacktraces back to their source without this contextual information?

Gili
  • 86,244
  • 97
  • 390
  • 689
  • good question as usual, I've listed a presentation on async where they say that the hardest thing is debugging and getting the exceptions when needed... – Eugene Mar 14 '18 at 12:12
  • Spring's RestTemplate has method setErrorHandler(ResponseErrorHandler), and that ResponseErrorHandler receives http response. I think Jersey has something similar, at least google request "Jersey error handling" gives many web references. – Alexei Kaigorodov Mar 14 '18 at 21:25
  • @AlexeiKaigorodov As I explained near the top of my question, I am looking for a general solution. The concrete example I gave was meant as a specific example of the more general problem. Besides, I don't think the error handler has a way of knowing the call-site when an exception is thrown asynchronously. – Gili Mar 16 '18 at 16:04
  • it is supposed that in in the chain of `CompletableFuture`s and `CompletionStage`s information of errors is returned to async caller. This is a convention. If it is not, then some stage misbehaves and just drops it, which is an error. Since Jersey maintainers reject your bug report, you have to find this place yourself. Then you can fix it and file a pull request. – Alexei Kaigorodov Mar 16 '18 at 19:32

2 Answers2

6

Seeing as this question has not received any answers in almost a month, I'm going to post the best solution I've found to date:

DebugCompletableFuture.java:

/**
 * A {@link CompletableFuture} that eases debugging.
 *
 * @param <T> the type of value returned by the future
 */
public final class DebugCompletableFuture<T> extends CompletableFuture<T>
{
    private static RunMode RUN_MODE = RunMode.DEBUG;
    private static final Set<String> CLASS_PREFIXES_TO_REMOVE = ImmutableSet.of(DebugCompletableFuture.class.getName(),
        CompletableFuture.class.getName(), ThreadPoolExecutor.class.getName());
    private static final Set<Class<? extends Throwable>> EXCEPTIONS_TO_UNWRAP = ImmutableSet.of(AsynchronousException.class,
        CompletionException.class, ExecutionException.class);
    private final CompletableFuture<T> delegate;
    private final AsynchronousException asyncStacktrace;

    /**
     * @param delegate the stage to delegate to
     * @throws NullPointerException if any of the arguments are null
     */
    private DebugCompletableFuture(CompletableFuture<T> delegate)
    {
        requireThat("delegate", delegate).isNotNull();
        this.delegate = delegate;
        this.asyncStacktrace = new AsynchronousException();
        delegate.whenComplete((value, exception) ->
        {
            if (exception == null)
            {
                super.complete(value);
                return;
            }
            exception = Exceptions.unwrap(exception, EXCEPTIONS_TO_UNWRAP);
            asyncStacktrace.initCause(exception);
            filterStacktrace(asyncStacktrace, element ->
            {
                String className = element.getClassName();
                for (String prefix : CLASS_PREFIXES_TO_REMOVE)
                    if (className.startsWith(prefix))
                        return true;
                return false;
            });
            Set<String> newMethods = getMethodsInStacktrace(asyncStacktrace);
            if (!newMethods.isEmpty())
            {
                Set<String> oldMethods = getMethodsInStacktrace(exception);
                newMethods.removeAll(oldMethods);
                if (!newMethods.isEmpty())
                {
                    // The async stacktrace introduces something new
                    super.completeExceptionally(asyncStacktrace);
                    return;
                }
            }
            super.completeExceptionally(exception);
        });
    }

    /**
     * @param exception an exception
     * @return the methods referenced by the stacktrace
     * @throws NullPointerException if {@code exception} is null
     */
    private Set<String> getMethodsInStacktrace(Throwable exception)
    {
        requireThat("exception", exception).isNotNull();
        Set<String> result = new HashSet<>();
        for (StackTraceElement element : exception.getStackTrace())
            result.add(element.getClassName() + "." + element.getMethodName());
        for (Throwable suppressed : exception.getSuppressed())
            result.addAll(getMethodsInStacktrace(suppressed));
        return result;
    }

    /**
     * @param <T2>     the type returned by the delegate
     * @param delegate the stage to delegate to
     * @return if {@code RUN_MODE == DEBUG} returns an instance that wraps {@code delegate}; otherwise, returns {@code delegate}
     * unchanged
     * @throws NullPointerException if any of the arguments are null
     */
    public static <T2> CompletableFuture<T2> wrap(CompletableFuture<T2> delegate)
    {
        if (RUN_MODE != RunMode.DEBUG)
            return delegate;
        return new DebugCompletableFuture<>(delegate);
    }

    /**
     * Removes stack trace elements that match a filter. The exception and its descendants are processed recursively.
     * <p>
     * This method can be used to remove lines that hold little value for the end user (such as the implementation of utility functions).
     *
     * @param exception     the exception to process
     * @param elementFilter returns true if the current stack trace element should be removed
     */
    private void filterStacktrace(Throwable exception, Predicate<StackTraceElement> elementFilter)
    {
        Throwable cause = exception.getCause();
        if (cause != null)
            filterStacktrace(cause, elementFilter);
        for (Throwable suppressed : exception.getSuppressed())
            filterStacktrace(suppressed, elementFilter);
        StackTraceElement[] elements = exception.getStackTrace();
        List<StackTraceElement> keep = new ArrayList<>(elements.length);
        for (StackTraceElement element : elements)
        {
            if (!elementFilter.test(element))
                keep.add(element);
        }
        exception.setStackTrace(keep.toArray(new StackTraceElement[0]));
    }

    @Override
    public <U> CompletableFuture<U> thenApply(Function<? super T, ? extends U> fn)
    {
        return wrap(super.thenApply(fn));
    }

    @Override
    public <U> CompletableFuture<U> thenApplyAsync(Function<? super T, ? extends U> fn)
    {
        return wrap(super.thenApplyAsync(fn));
    }

    @Override
    public <U> CompletableFuture<U> thenApplyAsync(Function<? super T, ? extends U> fn, Executor executor)
    {
        return wrap(super.thenApplyAsync(fn, executor));
    }

    @Override
    public CompletableFuture<Void> thenAccept(Consumer<? super T> action)
    {
        return wrap(super.thenAccept(action));
    }

    @Override
    public CompletableFuture<Void> thenAcceptAsync(Consumer<? super T> action)
    {
        return wrap(super.thenAcceptAsync(action));
    }

    @Override
    public CompletableFuture<Void> thenAcceptAsync(Consumer<? super T> action, Executor executor)
    {
        return wrap(super.thenAcceptAsync(action, executor));
    }

    @Override
    public CompletableFuture<Void> thenRun(Runnable action)
    {
        return wrap(super.thenRun(action));
    }

    @Override
    public CompletableFuture<Void> thenRunAsync(Runnable action)
    {
        return wrap(super.thenRunAsync(action));
    }

    @Override
    public CompletableFuture<Void> thenRunAsync(Runnable action, Executor executor)
    {
        return wrap(super.thenRunAsync(action, executor));
    }

    @Override
    public <U, V> CompletableFuture<V> thenCombine(CompletionStage<? extends U> other,
                                                   BiFunction<? super T, ? super U, ? extends V> fn)
    {
        return wrap(super.thenCombine(other, fn));
    }

    @Override
    public <U, V> CompletableFuture<V> thenCombineAsync(CompletionStage<? extends U> other,
                                                        BiFunction<? super T, ? super U, ? extends V> fn)
    {
        return wrap(super.thenCombineAsync(other, fn));
    }

    @Override
    public <U, V> CompletableFuture<V> thenCombineAsync(CompletionStage<? extends U> other,
                                                        BiFunction<? super T, ? super U, ? extends V> fn,
                                                        Executor executor)
    {
        return wrap(super.thenCombineAsync(other, fn, executor));
    }

    @Override
    public <U> CompletableFuture<Void> thenAcceptBoth(CompletionStage<? extends U> other,
                                                      BiConsumer<? super T, ? super U> action)
    {
        return wrap(super.thenAcceptBoth(other, action));
    }

    @Override
    public <U> CompletableFuture<Void> thenAcceptBothAsync(CompletionStage<? extends U> other,
                                                           BiConsumer<? super T, ? super U> action)
    {
        return wrap(super.thenAcceptBothAsync(other, action));
    }

    @Override
    public <U> CompletableFuture<Void> thenAcceptBothAsync(CompletionStage<? extends U> other,
                                                           BiConsumer<? super T, ? super U> action,
                                                           Executor executor)
    {
        return wrap(super.thenAcceptBothAsync(other, action, executor));
    }

    @Override
    public CompletableFuture<Void> runAfterBoth(CompletionStage<?> other, Runnable action)
    {
        return wrap(super.runAfterBoth(other, action));
    }

    @Override
    public CompletableFuture<Void> runAfterBothAsync(CompletionStage<?> other, Runnable action)
    {
        return wrap(super.runAfterBothAsync(other, action));
    }

    @Override
    public CompletableFuture<Void> runAfterBothAsync(CompletionStage<?> other, Runnable action, Executor executor)
    {
        return wrap(super.runAfterBothAsync(other, action, executor));
    }

    @Override
    public <U> CompletableFuture<U> applyToEither(CompletionStage<? extends T> other, Function<? super T, U> fn)
    {
        return wrap(super.applyToEither(other, fn));
    }

    @Override
    public <U> CompletableFuture<U> applyToEitherAsync(CompletionStage<? extends T> other, Function<? super T, U> fn)
    {
        return wrap(super.applyToEitherAsync(other, fn));
    }

    @Override
    public <U> CompletableFuture<U> applyToEitherAsync(CompletionStage<? extends T> other, Function<? super T, U> fn,
                                                       Executor executor)
    {
        return wrap(super.applyToEitherAsync(other, fn, executor));
    }

    @Override
    public CompletableFuture<Void> acceptEither(CompletionStage<? extends T> other, Consumer<? super T> action)
    {
        return wrap(super.acceptEither(other, action));
    }

    @Override
    public CompletableFuture<Void> acceptEitherAsync(CompletionStage<? extends T> other, Consumer<? super T> action)
    {
        return wrap(super.acceptEitherAsync(other, action));
    }

    @Override
    public CompletableFuture<Void> acceptEitherAsync(CompletionStage<? extends T> other, Consumer<? super T> action,
                                                     Executor executor)
    {
        return wrap(super.acceptEitherAsync(other, action, executor));
    }

    @Override
    public CompletableFuture<Void> runAfterEither(CompletionStage<?> other, Runnable action)
    {
        return wrap(super.runAfterEither(other, action));
    }

    @Override
    public CompletableFuture<Void> runAfterEitherAsync(CompletionStage<?> other, Runnable action)
    {
        return wrap(super.runAfterEitherAsync(other, action));
    }

    @Override
    public CompletableFuture<Void> runAfterEitherAsync(CompletionStage<?> other, Runnable action, Executor executor)
    {
        return wrap(super.runAfterEitherAsync(other, action, executor));
    }

    @Override
    public <U> CompletableFuture<U> thenCompose(Function<? super T, ? extends CompletionStage<U>> fn)
    {
        return wrap(super.thenCompose(fn));
    }

    @Override
    public <U> CompletableFuture<U> thenComposeAsync(Function<? super T, ? extends CompletionStage<U>> fn)
    {
        return wrap(super.thenComposeAsync(fn));
    }

    @Override
    public <U> CompletableFuture<U> thenComposeAsync(Function<? super T, ? extends CompletionStage<U>> fn,
                                                     Executor executor)
    {
        return wrap(super.thenComposeAsync(fn, executor));
    }

    @Override
    public CompletableFuture<T> exceptionally(Function<Throwable, ? extends T> fn)
    {
        return wrap(super.exceptionally(fn));
    }

    @Override
    public CompletableFuture<T> whenComplete(BiConsumer<? super T, ? super Throwable> action)
    {
        return wrap(super.whenComplete(action));
    }

    @Override
    public CompletableFuture<T> whenCompleteAsync(BiConsumer<? super T, ? super Throwable> action)
    {
        return wrap(super.whenCompleteAsync(action));
    }

    @Override
    public CompletableFuture<T> whenCompleteAsync(BiConsumer<? super T, ? super Throwable> action,
                                                  Executor executor)
    {
        return wrap(super.whenCompleteAsync(action, executor));
    }

    @Override
    public <U> CompletableFuture<U> handle(BiFunction<? super T, Throwable, ? extends U> fn)
    {
        return wrap(super.handle(fn));
    }

    @Override
    public <U> CompletableFuture<U> handleAsync(BiFunction<? super T, Throwable, ? extends U> fn)
    {
        return wrap(super.handleAsync(fn));
    }

    @Override
    public <U> CompletableFuture<U> handleAsync(BiFunction<? super T, Throwable, ? extends U> fn,
                                                Executor executor)
    {
        return wrap(super.handleAsync(fn, executor));
    }

    @Override
    public boolean complete(T value)
    {
        return delegate.complete(value);
    }

    @Override
    public boolean completeExceptionally(Throwable ex)
    {
        return delegate.completeExceptionally(ex);
    }
}

RunMode.java:

/**
 * Operational modes.
 */
public enum RunMode
{
    /**
     * Optimized for debugging problems (extra runtime checks, logging of the program state).
     */
    DEBUG,
    /**
     * Optimized for maximum performance.
     */
    RELEASE
}

AsynchronousException.java

/**
 * Thrown when an asynchronous operation fails. The stacktrace indicates who triggered the operation.
 */
public final class AsynchronousException extends RuntimeException
{
    private static final long serialVersionUID = 0L;

    public AsynchronousException()
    {
    }
}

Usage:

DebugCompletableFuture.wrap(CompletableFuture.supplyAsync(this::expensiveOperation));

Upside: you'll get relatively clean asynchronous stack traces.

Downside: Constructing a new AsynchronousException every time a future is created is extremely expensive. Specifically, if you're generating a lot of futures, this generates a lot of garbage on the heap and the GC overhead becomes noticeable.

I am still hopeful that someone will come up with a better-performing approach.

Gili
  • 86,244
  • 97
  • 390
  • 689
  • 1
    In similar cases, I have used [`addSuppressed()`](https://docs.oracle.com/javase/8/docs/api/java/lang/Throwable.html#addSuppressed-java.lang.Throwable-) to store context information, so that your original exception is kept but you see a `Suppressed:` in the stacktrace. This avoids having to handle the `AsynchrounousException` in your code. Ideally you'd implement it in the executor so that you don't have to put it everywhere. BTW, doesn't [the JVM omit the stacktrace](https://stackoverflow.com/q/2411487/525036) of your `AsynchronousException` quite quickly with this solution? – Didier L Apr 11 '18 at 09:29
  • @DidierL It seems I learn something new every day :) I never heard of JVMs optimizing-away stacktraces until today. Thank you for that. I also like your idea of moving this code into `ExecutorService.submit()`. I will update this answer with that approach once I get a chance. – Gili Apr 15 '18 at 07:48
  • 1
    @DidierL It turns out that it isn't possible to implement this in the executor as you suggested. `CompletableFuture` invokes `Executor.execute(Runnable)` and catches all exceptions inside the `Runnable` that it supplies. The executor never sees any exceptions so it cannot add the desired context. – Gili May 01 '18 at 17:44
  • Ah, yes, that makes sense I guess… It seems there is room for improvements in the `CompletableFuture` API… – Didier L May 01 '18 at 18:24
  • Nice idea -- this was what I was hoping wouldn't be necessary but it's good that you did the work to find this out! – Bill Burdick Apr 15 '19 at 15:52
0

This is probably due to the JVM update when it finds that the stack is exhausted of emitting the same log so it starts to omit it.

And the solution is using -XX:-OmitStackTraceInFastThrow flag to prevent JVM from optimizing built-in exceptions stack trace.

  • Good try, but no. This issue has nothing to do with throwing the same exception over and over again. It will occur for any asynchronous task you spawn. – Gili Mar 22 '20 at 20:51