micronaut-core: CompletableFuturePublisher doesn't handle exception from the future supplier what hangs a request
In 1.2.0.
When I send a GraphQL request with invalid data (in my example I’m trying to set “abc” string to UUID field) the request hangs infinitely with the following exception:
See the exception
17:22:47.389 [nioEventLoopGroup-1-2] WARN i.n.u.c.AbstractEventExecutor - A task raised an exception. Task: io.reactivex.internal.schedulers.ExecutorScheduler$ExecutorWorker@429a837d
java.lang.NullPointerException: Actually not, but can't throw other exceptions due to RS
at io.reactivex.Flowable.subscribe(Flowable.java:14927)
at io.reactivex.Flowable.subscribe(Flowable.java:14865)
at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.internal.operators.flowable.FlowableFlatMap.subscribeActual(FlowableFlatMap.java:53)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.Flowable.subscribe(Flowable.java:14865)
at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.Flowable.subscribe(Flowable.java:14868)
at io.micronaut.core.async.publisher.Publishers.lambda$map$2(Publishers.java:133)
at io.micronaut.core.async.publisher.Publishers.lambda$map$2(Publishers.java:133)
at io.reactivex.internal.operators.flowable.FlowableDefer.subscribeActual(FlowableDefer.java:42)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.Flowable.subscribe(Flowable.java:14865)
at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.internal.operators.flowable.FlowableMap.subscribeActual(FlowableMap.java:37)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.Flowable.subscribe(Flowable.java:14865)
at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.internal.operators.flowable.FlowableSwitchIfEmpty.subscribeActual(FlowableSwitchIfEmpty.java:32)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.Flowable.subscribe(Flowable.java:14865)
at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.Flowable.subscribe(Flowable.java:14868)
at io.micronaut.http.context.ServerRequestTracingPublisher.lambda$subscribe$0(ServerRequestTracingPublisher.java:52)
at io.micronaut.http.context.ServerRequestContext.with(ServerRequestContext.java:52)
at io.micronaut.http.context.ServerRequestTracingPublisher.subscribe(ServerRequestTracingPublisher.java:52)
at io.reactivex.internal.operators.flowable.FlowableDefer.subscribeActual(FlowableDefer.java:42)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.Flowable.subscribe(Flowable.java:14865)
at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.Flowable.subscribe(Flowable.java:14865)
at io.reactivex.internal.operators.flowable.FlowableSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FlowableSwitchIfEmpty.java:71)
at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.onComplete(InstrumentedSubscriber.java:112)
at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.drainLoop(FlowableFlatMap.java:426)
at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.drain(FlowableFlatMap.java:366)
at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onComplete(FlowableFlatMap.java:338)
at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.onComplete(InstrumentedSubscriber.java:112)
at io.reactivex.internal.operators.maybe.MaybeToFlowable$MaybeToFlowableSubscriber.onComplete(MaybeToFlowable.java:80)
at io.micronaut.reactive.rxjava2.RxInstrumentedMaybeObserver.onComplete(RxInstrumentedMaybeObserver.java:92)
at io.reactivex.internal.operators.maybe.MaybeDoOnEvent$DoOnEventMaybeObserver.onComplete(MaybeDoOnEvent.java:115)
at io.micronaut.reactive.rxjava2.RxInstrumentedMaybeObserver.onComplete(RxInstrumentedMaybeObserver.java:92)
at io.reactivex.internal.operators.flowable.FlowableElementAtMaybe$ElementAtSubscriber.onComplete(FlowableElementAtMaybe.java:102)
at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.onComplete(InstrumentedSubscriber.java:112)
at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.drainLoop(FlowableFlatMap.java:426)
at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.drain(FlowableFlatMap.java:366)
at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onComplete(FlowableFlatMap.java:338)
at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.onComplete(InstrumentedSubscriber.java:112)
at io.reactivex.internal.operators.flowable.FlowableFromIterable$IteratorSubscription.slowPath(FlowableFromIterable.java:255)
at io.reactivex.internal.operators.flowable.FlowableFromIterable$BaseRangeSubscription.request(FlowableFromIterable.java:124)
at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onSubscribe(FlowableFlatMap.java:117)
at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.onSubscribe(InstrumentedSubscriber.java:75)
at io.reactivex.internal.operators.flowable.FlowableFromIterable.subscribe(FlowableFromIterable.java:69)
at io.reactivex.internal.operators.flowable.FlowableFromIterable.subscribeActual(FlowableFromIterable.java:47)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.Flowable.subscribe(Flowable.java:14865)
at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.internal.operators.flowable.FlowableFlatMap.subscribeActual(FlowableFlatMap.java:53)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.Flowable.subscribe(Flowable.java:14865)
at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.internal.operators.flowable.FlowableElementAtMaybe.subscribeActual(FlowableElementAtMaybe.java:36)
at io.reactivex.Maybe.subscribe(Maybe.java:4290)
at io.micronaut.reactive.rxjava2.RxInstrumentedMaybe.subscribeActual(RxInstrumentedMaybe.java:64)
at io.reactivex.Maybe.subscribe(Maybe.java:4290)
at io.reactivex.internal.operators.maybe.MaybeDoOnEvent.subscribeActual(MaybeDoOnEvent.java:39)
at io.reactivex.Maybe.subscribe(Maybe.java:4290)
at io.micronaut.reactive.rxjava2.RxInstrumentedMaybe.subscribeActual(RxInstrumentedMaybe.java:64)
at io.reactivex.Maybe.subscribe(Maybe.java:4290)
at io.reactivex.internal.operators.maybe.MaybeToFlowable.subscribeActual(MaybeToFlowable.java:45)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.Flowable.subscribe(Flowable.java:14865)
at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.internal.operators.flowable.FlowableFlatMap.subscribeActual(FlowableFlatMap.java:53)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.Flowable.subscribe(Flowable.java:14865)
at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.internal.operators.flowable.FlowableSwitchIfEmpty.subscribeActual(FlowableSwitchIfEmpty.java:32)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.Flowable.subscribe(Flowable.java:14865)
at io.micronaut.reactive.rxjava2.RxInstrumentedFlowable.subscribeActual(RxInstrumentedFlowable.java:68)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
at io.reactivex.Flowable.subscribe(Flowable.java:14865)
at io.reactivex.internal.operators.flowable.FlowableSubscribeOn$SubscribeOnSubscriber.run(FlowableSubscribeOn.java:82)
at io.reactivex.internal.schedulers.ExecutorScheduler$ExecutorWorker$BooleanRunnable.run(ExecutorScheduler.java:288)
at io.reactivex.internal.schedulers.ExecutorScheduler$ExecutorWorker.run(ExecutorScheduler.java:253)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:163)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:416)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:515)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:835)
Caused by: java.lang.IllegalArgumentException: Invalid UUID string: abc
at java.base/java.util.UUID.fromString(UUID.java:215)
at io.leangen.graphql.util.Scalars$1.parseLiteral(Scalars.java:95)
at graphql.validation.ValidationUtil.parseLiteral(ValidationUtil.java:113)
at graphql.validation.ValidationUtil.isValidLiteralValue(ValidationUtil.java:90)
at graphql.validation.ValidationUtil.isValidLiteralValue(ValidationUtil.java:86)
at graphql.validation.rules.ArgumentsOfCorrectType.checkArgument(ArgumentsOfCorrectType.java:23)
at graphql.validation.RulesVisitor.checkArgument(RulesVisitor.java:98)
at graphql.validation.RulesVisitor.enter(RulesVisitor.java:65)
at graphql.validation.LanguageTraversal.traverseImpl(LanguageTraversal.java:33)
at graphql.validation.LanguageTraversal.traverseImpl(LanguageTraversal.java:38)
at graphql.validation.LanguageTraversal.traverseImpl(LanguageTraversal.java:38)
at graphql.validation.LanguageTraversal.traverseImpl(LanguageTraversal.java:38)
at graphql.validation.LanguageTraversal.traverseImpl(LanguageTraversal.java:38)
at graphql.validation.LanguageTraversal.traverse(LanguageTraversal.java:28)
at graphql.validation.Validator.validateDocument(Validator.java:43)
at graphql.GraphQL.validate(GraphQL.java:576)
at graphql.GraphQL.parseAndValidate(GraphQL.java:541)
at graphql.GraphQL.lambda$parseValidateAndExecute$3(GraphQL.java:515)
at graphql.execution.preparsed.NoOpPreparsedDocumentProvider.get(NoOpPreparsedDocumentProvider.java:11)
at graphql.GraphQL.parseValidateAndExecute(GraphQL.java:511)
at graphql.GraphQL.executeAsync(GraphQL.java:495)
at io.micronaut.configuration.graphql.DefaultGraphQLInvocation.lambda$null$0(DefaultGraphQLInvocation.java:69)
at io.micronaut.core.async.publisher.CompletableFuturePublisher$CompletableFutureSubscription.request(CompletableFuturePublisher.java:75)
at io.reactivex.internal.operators.flowable.FlowableFlatMap$InnerSubscriber.onSubscribe(FlowableFlatMap.java:656)
at io.micronaut.core.async.publisher.CompletableFuturePublisher.subscribe(CompletableFuturePublisher.java:48)
at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onNext(FlowableFlatMap.java:163)
at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.lambda$onNext$0(InstrumentedSubscriber.java:80)
at io.micronaut.http.context.ServerRequestContext.with(ServerRequestContext.java:52)
at io.micronaut.http.context.ServerRequestContext.lambda$instrument$0(ServerRequestContext.java:68)
at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.onNext(InstrumentedSubscriber.java:84)
at io.micronaut.core.async.publisher.Publishers$JustPublisher$1.request(Publishers.java:340)
at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onSubscribe(FlowableFlatMap.java:117)
at io.micronaut.reactive.rxjava2.InstrumentedSubscriber.onSubscribe(InstrumentedSubscriber.java:75)
at io.micronaut.core.async.publisher.Publishers$JustPublisher.subscribe(Publishers.java:330)
at io.reactivex.internal.operators.flowable.FlowableFromPublisher.subscribeActual(FlowableFromPublisher.java:29)
at io.reactivex.Flowable.subscribe(Flowable.java:14918)
... 102 common frames omitted
Looking on DefaultGraphQLInvocation from Micronaut:
@Override
public Publisher<ExecutionResult> invoke(GraphQLInvocationData invocationData, HttpRequest httpRequest) {
ExecutionInput executionInput = ExecutionInput.newExecutionInput()
.query(invocationData.getQuery())
.operationName(invocationData.getOperationName())
.variables(invocationData.getVariables())
.build();
return Flowable.fromPublisher(graphQLExecutionInputCustomizer.customize(executionInput, httpRequest))
.flatMap(customizedExecutionInput -> Publishers.fromCompletableFuture(() ->
graphQL.executeAsync(customizedExecutionInput)));
}
The cause seems to be an unhandled exception thrown in CompletableFuturePublisher supplier (() -> graphQL.executeAsync(customizedExecutionInput) code from the example above). When the exception is thrown there, and in GraphQL it can apparently can be thrown there in case of validation/deserialization issues, the request is hung infinitely.
I prepared a testcase here, please review the code from this controller, and try to GET /error:
$ curl -m 5 http://localhost:8080/error
curl: (28) Operation timed out after 5001 milliseconds with 0 bytes received
Request is hung (timeout happens) with the following log:
17:32:24.133 [nioEventLoopGroup-1-4] WARN i.n.u.c.AbstractEventExecutor - A task raised an exception. Task: io.micronaut.http.netty.reactive.HandlerSubscriber$$Lambda$424/128773606@5a93364c
java.lang.IllegalArgumentException: null
at micronaut.general.TestController.lambda$exceptionFlow$1(TestController.java:25)
at io.micronaut.core.async.publisher.CompletableFuturePublisher$CompletableFutureSubscription.request(CompletableFuturePublisher.java:75)
at io.reactivex.internal.subscriptions.SubscriptionHelper.deferredRequest(SubscriptionHelper.java:219)
at io.reactivex.internal.subscribers.StrictSubscriber.request(StrictSubscriber.java:70)
at io.micronaut.http.netty.reactive.HandlerSubscriber.maybeRequestMore(HandlerSubscriber.java:216)
at io.micronaut.http.netty.reactive.HandlerSubscriber.maybeStart(HandlerSubscriber.java:260)
at io.micronaut.http.netty.reactive.HandlerSubscriber.provideSubscription(HandlerSubscriber.java:247)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:163)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:416)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:515)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)
About this issue
- Original URL
- State: closed
- Created 5 years ago
- Comments: 17 (17 by maintainers)
@l0co Micronaut-GraphQL
1.2.1was just released with a fix for this. It should be synced to Maven Central shortly. So you can remove your overwritten / @Replaces classes 😉