Handling of an error through a long chain of completions leads to StackOverflowError

[guss77]

Version

5.0.7

Context

I often get these errors in my server logs:

ip-172-24-16-229 API.Core [6377]: [vert.x-eventloop-thread-2] ERROR io.vertx.core.impl.ContextImpl - Unhandled exception
ip-172-24-16-229 API.Core [6377]: java.lang.StackOverflowError
ip-172-24-16-229 API.Core [6377]: #011at java.base/java.io.BufferedOutputStream.growIfNeeded(BufferedOutputStream.java:138)
ip-172-24-16-229 API.Core [6377]: #011at java.base/java.io.BufferedOutputStream.implWrite(BufferedOutputStream.java:220)
ip-172-24-16-229 API.Core [6377]: #011at java.base/java.io.BufferedOutputStream.write(BufferedOutputStream.java:200)
ip-172-24-16-229 API.Core [6377]: #011at java.base/java.io.PrintStream.implWrite(PrintStream.java:643)
ip-172-24-16-229 API.Core [6377]: #011at java.base/java.io.PrintStream.write(PrintStream.java:623)
ip-172-24-16-229 API.Core [6377]: #011at java.base/sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:309)
ip-172-24-16-229 API.Core [6377]: #011at java.base/sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:405)
ip-172-24-16-229 API.Core [6377]: #011at java.base/sun.nio.cs.StreamEncoder.lockedFlushBuffer(StreamEncoder.java:123)
ip-172-24-16-229 API.Core [6377]: #011at java.base/sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:110)
ip-172-24-16-229 API.Core [6377]: #011at java.base/java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:192)
ip-172-24-16-229 API.Core [6377]: #011at java.base/java.io.PrintStream.implWriteln(PrintStream.java:849)
ip-172-24-16-229 API.Core [6377]: #011at java.base/java.io.PrintStream.writeln(PrintStream.java:826)
ip-172-24-16-229 API.Core [6377]: #011at java.base/java.io.PrintStream.println(PrintStream.java:1191)
ip-172-24-16-229 API.Core [6377]: #011at java.base/java.lang.Throwable$WrappedPrintStream.println(Throwable.java:785)
ip-172-24-16-229 API.Core [6377]: #011at java.base/java.lang.Throwable.lockedPrintStackTrace(Throwable.java:684)
ip-172-24-16-229 API.Core [6377]: #011at java.base/java.lang.Throwable.printStackTrace(Throwable.java:668)
ip-172-24-16-229 API.Core [6377]: #011at java.base/java.lang.Throwable.printStackTrace(Throwable.java:660)
ip-172-24-16-229 API.Core [6377]: #011at org.slf4j.simple.SimpleLogger.writeThrowable(SimpleLogger.java:270)
ip-172-24-16-229 API.Core [6377]: #011at org.slf4j.simple.SimpleLogger.write(SimpleLogger.java:262)
ip-172-24-16-229 API.Core [6377]: #011at org.slf4j.simple.SimpleLogger.innerHandleNormalizedLoggingCall(SimpleLogger.java:439)
ip-172-24-16-229 API.Core [6377]: #011at org.slf4j.simple.SimpleLogger.handleNormalizedLoggingCall(SimpleLogger.java:377)
ip-172-24-16-229 API.Core [6377]: #011at org.slf4j.helpers.AbstractLogger.handle_0ArgsCall(AbstractLogger.java:382)
ip-172-24-16-229 API.Core [6377]: #011at org.slf4j.helpers.AbstractLogger.error(AbstractLogger.java:347)
ip-172-24-16-229 API.Core [6377]: #011at io.vertx.core.logging.SLF4JLogDelegate.error(SLF4JLogDelegate.java:69)
ip-172-24-16-229 API.Core [6377]: #011at io.vertx.core.internal.logging.LoggerAdapter.error(LoggerAdapter.java:100)
ip-172-24-16-229 API.Core [6377]: #011at io.vertx.core.impl.ContextImpl.reportException(ContextImpl.java:181)
ip-172-24-16-229 API.Core [6377]: #011at io.vertx.core.impl.future.FutureBase.emitResult(FutureBase.java:71)
ip-172-24-16-229 API.Core [6377]: #011at io.vertx.core.impl.future.FutureImpl.completeInternal(FutureImpl.java:163)
ip-172-24-16-229 API.Core [6377]: #011at io.vertx.core.impl.future.FutureBase.emitResult(FutureBase.java:68)
ip-172-24-16-229 API.Core [6377]: #011at io.vertx.core.impl.future.FutureImpl.completeInternal(FutureImpl.java:163)
ip-172-24-16-229 API.Core [6377]: #011at io.vertx.core.impl.future.FutureBase.emitResult(FutureBase.java:68)
ip-172-24-16-229 API.Core [6377]: #011at io.vertx.core.impl.future.FutureImpl.completeInternal(FutureImpl.java:163)
...
[last two lines repeat ~1000 times]

I cannot isolate the actual cause because the stack trace implicates none of my LOCs - probably because the beginning of the trace is cut off.

This only appears to happen related to a ContextImpl.reportException() call, so this is likely caused by my code returning a FailedFuture somewhere from a deep completion chain. Still - if there was a way to avoid a chain of future compositions triggering a stack overflow - that would be best.

BTW - looking at emitResult(FutureBase.java:68) - it calls listener.compelete(), an implementation of which isn't listed in the stack trace. This probably means that the listener being completed is created by a function reference in either Transformation.java:44 or Composition.java:48 (my money is on the latter).

If there's a workaround that I can employ in my code - for example, this completion chain is probably generated by iterating many times through an internal HTTP processing mapper, which I can modify - maybe by somehow delegating the completion to a new stack (new thread / new event loop invocation), please let me know.

Steps to reproduce

Sorry, no reproducer ATM.

Do you have a reproducer?

No response

[tsegismont]

Hi @guss77

This only appears to happen related to a ContextImpl.reportException() call, so this is likely caused by my code returning a FailedFuture somewhere from a deep completion chain

In fact, reportException is invoked because of the StackOverflowError. It doesn't necessarily indicate that a failed future is involved.

This kind of problems often happen when iterating over a long list and composing futures. Do you have this in your code?

I think Hibernate Reactive uses async trampoline for that kind of use cases: https://github.com/IBM/java-async-util/blob/master/asyncutil/src/main/java/com/ibm/asyncutil/iteration/AsyncTrampoline.java

[guss77]

Thank you for the answer. I don't believe we have code similar to what the AsyncTrampoline docs discuss - but its a pretty big project (>500 REST routes) which wasn't written exclusively by me - so I'm not actually sure.

I am sure, though, that this is failure handling and not a successful series of computarions that just happen to run out of stack:

1. the part of the stack that we see in the trace - that is partial but still includes ~500 completions - does not show any of my code. This sounds like a series of .compose() or .map() that are skipped in order because there's a failure propagating.
2. The path through FutureImpl.java:163 (Vert.x 5.0.7) is either handling a successful result of null, or failure handling. We do have a bit of Void completions, but going through that path repeatedly sounds more like a failure.
3. It happens occasionally to rarely - if this was a successful processing I'd expect to see it happening a lot more often.

In case this is indeed a failure propagating, from what I understood of the AsyncTrampoline workflow, it won't actually help because it doesn't trampoline failures. Please correct me if I'm wrong.

Lastly - the AsyncTrampoline is very Java CompletableFuture and doing nasty lowlish level things to it, and I'm completely out of my depth figuring how to translate that to Vert.x Future. If you can throw a bone at me of a hint how to go about do implementing something like that for Vert.x, you will have my gratitude.

[tsegismont]

Thank you for the answer. I don't believe we have code similar to what the AsyncTrampoline docs discuss - but its a pretty big project (>500 REST routes) which wasn't written exclusively by me - so I'm not actually sure.

I am sure, though, that this is failure handling and not a successful series of computarions that just happen to run out of stack:

1. the part of the stack that we see in the trace - that is partial but still includes ~500 completions - does not show any of my code. This sounds like a series of .compose() or .map() that are skipped in order because there's a failure propagating.

If a long chain of futures is created, and eventually completed, you could see such a stack

3. The path through FutureImpl.java:163 (Vert.x 5.0.7) is either handling a successful result of null, or failure handling. We do have a bit of Void completions, but going through that path repeatedly sounds more like a failure.

My understanding is that this path is handling emission of a result for a future that was not completed so far. It could be a null, non null, or failure.

5. It happens occasionally to rarely - if this was a successful processing I'd expect to see it happening a lot more often.> > In case this is indeed a failure propagating, from what I understood of the AsyncTrampoline workflow, it won't actually help because it doesn't trampoline failures. Please correct me if I'm wrong.

I believe it could happen occasionally if, during the construction of the chain of futures, completions already happen.

Lastly - the AsyncTrampoline is very Java CompletableFuture and doing nasty lowlish level things to it, and I'm completely out of my depth figuring how to translate that to Vert.x Future. If you can throw a bone at me of a hint how to go about do implementing something like that for Vert.x, you will have my gratitude.

You can convert a Vert.x Future to/from a CompletionStage, and then reuse AsyncTrampoline