search

quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.56k stars 2.62k forks source link

OTEL + `quarkus.http.test-timeout` -> NullPointerException: Cannot invoke "io.vertx.core.spi.observability.HttpResponse.headers()" because "httpResponse" is null #42578

Closed famod closed 2 weeks ago

famod commented 4 weeks ago

Describe the bug

Setting quarkus.http.test-timeout to a low value so that a rest assured request times out results in a NPE in OTEL code.

Expected behavior

No NPE, just a timeout.

Actual behavior

WARN  [io.net.cha.AbstractChannelHandlerContext] (vert.x-eventloop-thread-1) An exception 'java.lang.NullPointerException: Cannot invoke "io.vertx.core.spi.observability.HttpResponse.headers()" because "httpResponse" is null' [enable DEBUG level for full stacktrace] was thrown by a user handler's exceptionCaught() method while handling the following exception:: java.lang.NullPointerException: Cannot invoke "io.vertx.core.spi.observability.HttpResponse.headers()" because "httpResponse" is null
    at io.quarkus.opentelemetry.runtime.tracing.intrumentation.vertx.HttpInstrumenterVertxTracer$AdditionalServerAttributesExtractor.onEnd(HttpInstrumenterVertxTracer.java:301)
    at io.quarkus.opentelemetry.runtime.tracing.intrumentation.vertx.HttpInstrumenterVertxTracer$AdditionalServerAttributesExtractor.onEnd(HttpInstrumenterVertxTracer.java:278)
    at io.opentelemetry.instrumentation.api.instrumenter.Instrumenter.doEnd(Instrumenter.java:227)
    at io.opentelemetry.instrumentation.api.instrumenter.Instrumenter.end(Instrumenter.java:144)
    at io.quarkus.opentelemetry.runtime.tracing.intrumentation.vertx.InstrumenterVertxTracer.sendResponse(InstrumenterVertxTracer.java:72)
    at io.quarkus.opentelemetry.runtime.tracing.intrumentation.vertx.HttpInstrumenterVertxTracer.sendResponse(HttpInstrumenterVertxTracer.java:105)
    at io.quarkus.opentelemetry.runtime.tracing.intrumentation.vertx.HttpInstrumenterVertxTracer.sendResponse(HttpInstrumenterVertxTracer.java:50)
    at io.quarkus.opentelemetry.runtime.tracing.intrumentation.vertx.OpenTelemetryVertxTracer.sendResponse(OpenTelemetryVertxTracer.java:47)
    at io.quarkus.opentelemetry.runtime.tracing.intrumentation.vertx.OpenTelemetryVertxTracer.sendResponse(OpenTelemetryVertxTracer.java:16)
    at io.quarkus.opentelemetry.runtime.tracing.intrumentation.vertx.OpenTelemetryVertxTracingFactory$VertxDelegator.sendResponse(OpenTelemetryVertxTracingFactory.java:78)
    at io.vertx.core.http.impl.Http1xServerRequest.reportRequestReset(Http1xServerRequest.java:700)
    at io.vertx.core.http.impl.Http1xServerRequest.handleException(Http1xServerRequest.java:678)
    at io.vertx.core.http.impl.Http1xServerConnection.lambda$handleClosed$7(Http1xServerConnection.java:501)
    at io.vertx.core.impl.ContextImpl.execute(ContextImpl.java:313)
    at io.vertx.core.impl.DuplicatedContext.execute(DuplicatedContext.java:159)
    at io.vertx.core.impl.ContextInternal.execute(ContextInternal.java:216)
    at io.vertx.core.http.impl.Http1xServerConnection.handleClosed(Http1xServerConnection.java:500)
    at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:143)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
    at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
    at io.netty.handler.timeout.IdleStateHandler.channelInactive(IdleStateHandler.java:280)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
    at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:412)
    at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:377)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1402)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:301)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
    at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:900)
    at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:811)
    at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:566)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994)
    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:1583)

How to Reproduce?

q_otel-assured.zip

Output of uname -a or ver

No response

Output of java -version

No response

Quarkus version or git rev

3.13.2

Build tool (ie. output of mvnw --version or gradlew --version)

Maven 3.9.8

Additional information

There is another exception that looks like "noise" too:

2024-08-15 22:44:18,764 ERROR [io.ver.ext.web.RoutingContext] (executor-thread-1) Unhandled exception in router [Error Occurred After Shutdown]: java.util.concurrent.RejectedExecutionException: event executor terminated
    at io.netty.util.concurrent.SingleThreadEventExecutor.reject(SingleThreadEventExecutor.java:931)
    at io.netty.util.concurrent.SingleThreadEventExecutor.offerTask(SingleThreadEventExecutor.java:350)
    at io.netty.util.concurrent.SingleThreadEventExecutor.addTask(SingleThreadEventExecutor.java:343)
    at io.netty.util.concurrent.SingleThreadEventExecutor.execute(SingleThreadEventExecutor.java:833)
    at io.netty.util.concurrent.SingleThreadEventExecutor.execute0(SingleThreadEventExecutor.java:824)
    at io.netty.util.concurrent.SingleThreadEventExecutor.execute(SingleThreadEventExecutor.java:814)
    at io.vertx.core.net.impl.ConnectionBase.queueForWrite(ConnectionBase.java:238)
    at io.vertx.core.net.impl.ConnectionBase.writeToChannel(ConnectionBase.java:228)
    at io.vertx.core.net.impl.ConnectionBase.writeToChannel(ConnectionBase.java:218)
    at io.vertx.core.net.impl.ConnectionBase.writeToChannel(ConnectionBase.java:214)
    at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:437)
    at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:411)
    at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:390)
    at io.quarkus.vertx.http.runtime.QuarkusErrorHandler.writeResponse(QuarkusErrorHandler.java:206)
    at io.quarkus.vertx.http.runtime.QuarkusErrorHandler.jsonResponse(QuarkusErrorHandler.java:192)
    at io.quarkus.vertx.http.runtime.QuarkusErrorHandler.handle(QuarkusErrorHandler.java:166)
    at io.quarkus.vertx.http.runtime.QuarkusErrorHandler.handle(QuarkusErrorHandler.java:31)
    at io.vertx.ext.web.impl.RouteState.handleFailure(RouteState.java:1291)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:174)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
    at io.quarkus.resteasy.reactive.server.runtime.ResteasyReactiveRecorder$7.handle(ResteasyReactiveRecorder.java:237)
    at io.quarkus.resteasy.reactive.server.runtime.ResteasyReactiveRecorder$7.handle(ResteasyReactiveRecorder.java:196)
    at io.vertx.ext.web.impl.RouteState.handleFailure(RouteState.java:1291)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:174)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
    at io.quarkus.resteasy.reactive.server.runtime.observability.ObservabilityIntegrationRecorder$1.handle(ObservabilityIntegrationRecorder.java:39)
    at io.quarkus.resteasy.reactive.server.runtime.observability.ObservabilityIntegrationRecorder$1.handle(ObservabilityIntegrationRecorder.java:29)
    at io.vertx.ext.web.impl.RouteState.handleFailure(RouteState.java:1291)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:174)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
    at io.vertx.ext.web.impl.RoutingContextImpl.doFail(RoutingContextImpl.java:557)
    at io.vertx.ext.web.impl.RoutingContextImpl.fail(RoutingContextImpl.java:196)
    at io.vertx.ext.web.impl.RoutingContextImpl.fail(RoutingContextImpl.java:185)
    at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.handleUnrecoverableError(QuarkusResteasyReactiveRequestContext.java:65)
    at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.handleException(AbstractResteasyReactiveContext.java:329)
    at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:175)
    at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:635)
    at org.jboss.threads.EnhancedQueueExecutor$Task.doRunWith(EnhancedQueueExecutor.java:2516)
    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2495)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1521)
    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:11)
    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:11)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:1583)
famod commented 4 weeks ago

/cc @brunobat

brunobat commented 3 weeks ago

The response being null is a new one... I would bet the second exception triggers the OTel error. There is a request, but it fails to be processed and is null when OTel runs... @cescoffier Should this be addresses by the vertx part of the stack?

cescoffier commented 3 weeks ago

Not sure I understand the whole picture. The exception means that Vertx cannot write the response because the event loop is shutdown (which only happens when the application terminates).

The request has been processed 'successfully' as there is a http status to be written (that's the write that fails).

For Otel, I'm. It sure what should be done in this case.

brunobat commented 3 weeks ago

If it's shutting down, and only happens on tests, do we even want to create a span? If no response was written, the only meaningful span result would be a 500 error.

famod commented 3 weeks ago

FWIW, I just had the same NPE warning on dev mode reload due to java file change. (while testing Quarkus 3.13.3 if that matters)

Edit: Ugh...now multiple times. Btw, I used to be seeing different exceptions on reload: #29646

famod commented 6 days ago

So after the NPE fix (thanks!), I'm still getting this long "event executor terminated" exception trace.

I don't think it has anything to do with OTEL because it also pops up when I pass -Dquarkus.otel.enabled=false to the test execution.

I should probably create another issue?

brunobat commented 3 days ago

Not sure @famod. The issue relies on the fact that the execution is aborted and you cannot use certain resources anymore.