Sporadic "Failed to export spans. The request could not be executed. Full error message: Stream was closed"

[famod]

Describe the bug

I'm seeing the following error in the logs every now and then:

SEVERE [io.qua.ope.run.exp.otl.VertxGrpcExporter] (vert.x-eventloop-thread-1) Failed to export spans. The request could not be executed. Full error message: Stream was closed

OTLP sink is a Jaeger container (1.48.0, no collector in between), all apps are running in a docker compose setup.
I can see those errors locally and on our central testing VMs.

I do see plenty of spans in Jaeger though.

I haven't seen this issue before in Quarkus 2.16.

Any hints on where to start looking/debugging?

Expected behavior

No response

Actual behavior

No response

How to Reproduce?

n/a ATM

Output of uname -a or ver

No response

Output of java -version

Java 17

GraalVM version (if different from Java)

No response

Quarkus version or git rev

3.3.1

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

No response

Additional information

I'm also seeing sporadic messages like:

WARN [io.qua.ope.run.QuarkusContextStorage] (executor-thread-143) Context in storage not the expected context, Scope.close was not called correctly

and

ERROR [io.ver.cor.net.imp.ConnectionBase] (vert.x-eventloop-thread-1) NULL

But not everytime are those messages logged together.

[famod]

/cc @brunobat @radcortez

[brunobat]

"Scope.close was not called correctly" It's an issue in the creation of the spans themselves. It would be important to understand which code is responsible for that.
"ERROR [io.ver.cor.net.imp.ConnectionBase] (vert.x-eventloop-thread-1) NULL"... Yeah... The bug you filed for that needs to be closed in order to understand what's going on.
Quarkus 3.3 has a new exporter based on Vert.x because the standard OTLP exporter previously used was based on OkHttp and we don't want that.

"Stream was closed" might mean that we are trying to write/send spans using a stream that was previously closed. That might align with getting an "ERROR [io.ver.cor.net.imp.ConnectionBase] (vert.x-eventloop-thread-1) NULL"

Is this happening when you shutdown the server @famod ?

[famod]

@brunobat no, Jaeger is alive and kicking all the time. There's also no warning or error in its logs.

[brunobat]

@famod I was talking about the Quarkus server instances

[famod]

@brunobat ah, sorry. No, it happens mutliple times during a UI regression test suite execution that runs 45 mins or so (but doesn't cause that much load).

[brunobat]

Umm... This totally smells to a thread being shutdown and then later used to send the last remaining spans.
Would you be able to confirm this or come up with a reproducer?

[famod]

Setting vert.x' ConnectionBase to DEBUG reveals:

[io.ver.cor.net.imp.ConnectionBase] (vert.x-eventloop-thread-5) The connection will be closed due to timeout

Trying to dig deeper...

[famod]

So it turns out that some export requests take longer that the default 10s to be processed by jaeger.
Setting quarkus.otel.exporter.otlp.traces.timeout=30S resolves this issue for me.
Seems like that even with very low local load we export too much, probably due to the jdbc spans and an export factor of 1.0 (100%).

So this is probably a won't fix, but maybe we could print a more actionable message?
I can see that a io.vertx.core.http.HttpClosedException: Stream was closed is caught/handled (only the message is logged though).
What about:

• logging toString() of the exception instead of just the message (which could theoretically be null)
• adding something like "Try increasing quarkus.otel.exporter.otlp.traces.timeout and/or reducing the number of exported items by lowering the sampling rate."

[famod]

Btw, I'm under the impression that VertxGrpcExporter will never use http 2, or am I wrong? (setting 2 didn't improve my timeout issue though)

[brunobat]

Hi @famod. Thanks for the debugging.
I was able to reproduce the issue by killing Jaeger:
SEVERE traceId=, parentId=, spanId=, sampled= [io.qu.op.ru.ex.ot.VertxGrpcExporter] (vert.x-eventloop-thread-1) Failed to export spans. The request could not be executed. Full error message: Stream was closed
This message will show up if either end of the connection abruptly disconnects while transmitting the spans.
Will create a PR...

[famod]

This message will show up if either end of the connection abruptly disconnects while transmitting the spans.

Makes sense. In my case it's vert.x killing it due to timeout.

[jimkont]

Not sure if this is the same issue but I also get a Stream was closed error when I try the new Vertex-based GRPC exporter with version 3.4.2. Unfortunately, I get this only in the production environment and cannot reproduce it locally. Some error logs that I get near that error are the following:

• Failed to export spans. The request could not be executed. Full error message: Cannot create stream 3 greater than Last-Stream-ID 1 from GOAWAY. from "vert.x-eventloop-thread-1"
• Thread Thread[vert.x-eventloop-thread-1,5,main] has been blocked for 3820 ms, time limit is 2000 ms from "vertx-blocked-thread-checker"
• Broken pipe ("io.vertx.core.net.impl.ConnectionBase") from "vert.x-eventloop-thread-1"
• NULL ("io.vertx.core.net.impl.ConnectionBase") from "vert.x-eventloop-thread-1"
• Failed to export spans. The request could not be executed. Full error message: Stream closed before write could take place from "vert.x-eventloop-thread-1"
• Failed to export spans. The request could not be executed. Full error message: Stream was closed from "vert.x-eventloop-thread-1"

sharing in case log 1 or 2 could be causing the stream to close.
In production we are using aws-lambda with snap start enabled, in case this brings some more context

[brunobat]

Thanks @jimkont.
Can you please format it in plain text? We cannot see how many log lines are there.
It looks like you have a Broken pipe... There was a communication problem with the collector, either in transit or the
collector was non responsive.

Because it's a lambda, most likely, the function is being shutdown before while sending the trace... That's unfortunate and should be solved, in the future, by this issue: #29448
We currently use a Batch exporter and for lambdas, a Simple exporter is better.

In the meantime, you need to speedup the flush of the exporter with these properties:

#1 ms
quarkus.otel.bsp.schedule.delay=PT0.001S
quarkus.otel.bsp.max.queue.size=1
quarkus.otel.bsp.max.export.batch.size=1

[jimkont]

I see, looking into the communication problem. wrt the logs, they come from log aggregation tool in json, I could not verify if they come from the same lambda instance as they get executed after the lambda invocation and lose all the context. I get multiple logs of all the lines there.

Thanks for the lambda configuration hints. Would it also help if I place an @PreDestroy hook on the class that handles the requests, inject a spanProcessor: SpanProcessor and run spanProcessor.forceFlush().join(seconds, TimeUnit.SECONDS)?

[brunobat]

We do force the flush but it doesn't seem to be enough for lambda functions:

quarkus/extensions/opentelemetry/runtime/src/main/java/io/quarkus/opentelemetry/OpenTelemetryDestroyer.java

Line 17 in 09cd879

openTelemetrySdk.getSdkTracerProvider().forceFlush();

[luneo7]

We bumped from Quarkus 3.2.x to 3.4.x and we started to get a lot of those logs io.opentelemetry.sdk.internal.ThrottlingLogger doLog Failed to export spans. The request could not be executed. Full error message: Stream was closed and before we weren't getting any error, in our case we export to an AWS OTEL Collector, the collector is running without any error, and it logs no error.

[luneo7]

We are actually seeing this error as well in the OTEL collector side: zapgrpc/zapgrpc.go:195 [core] [Server #1] grpc: Server.processUnaryRPC failed to write status: connection error: desc = "transport is closing" {"grpc_log": true} ... the Vert.x client implementation seems to be handling something different there... since with the OkHTTP client we do not see this error

[brunobat]

@luneo7, this will hopefully help: #36538

[luneo7]

Don’t think that it will help as the PR is handling the shutdown, and those logs are happening during the app execution. Even increasing the timeout, and decreasing the batch size didn’t solve it, it reduced the amount of logs but it is still there, but if with OkHTTP that didn’t happen, something is being handled differently by the Vert.x GRPC client…

[brunobat]

@luneo7 are you able to get a reproducer?

[famod]

While checking something else, I realized that I can reproduce this issue sporadically with the opentelemetry-quickstart:

• mvn clean install (just to make sure it runs in general)
• docker compose up -d (watch out, you'll need #quarkus-quickstarts/1348 for compose to work)
• mvn quarkus:dev
• curl http://localhost:8080/hello a few times (or use something like hey)

[brunobat]

Thanks @famod. I'm also working on a new IT test that produces this error consistently.

[luneo7]

Have been sniffing packets to see if there is any difference between OkHttp and Vert.x... the OkHttp client adds content-length, whereas Vert.x adds grpc-accept-encoding (OkHttp uses only accept-encoding)

OkHttp:

Vert.x:

Besides that didn't find a major difference that would make the connection die, as it happens with Vert.x but doesn't with OkHttp....

One thing that I noted is that OkHttp has a call timeout which is what OTEL uses to set the timeout, and it works by verifying the whole operation... Vert.x on the other hand is setting read timeout with the same value as the OkHttp timeout (tracesConfig.timeout())... just that read timeout is totally different than the call timeout... with vert.x grpc client there is no way to set the whole timeout because we have no access to the RequestOptions.... doesn't matter much since the default timeout in the RequestOptions is 0, which means no timeout...

I've found one issue with the current Vert.x implementation is that we have an streaming response, and in the ClientRequestOnSuccessHandler we do request.send(buffer).onSuccess and the handler there is trying to parse status and other stuff that won't exist at that time, while debugging I've found that GrpcStatus is always null and and statusMessage is null as well... the fix for that would be actually processing the status when the response ends... we need to run the code/message extraction in the responde endhandler the code would look something like:

request.send(buffer).onSuccess(new Handler<>() {
                    @Override
                    public void handle(GrpcClientResponse<Buffer, Buffer> response) {
                        response.endHandler(new Handler<Void>() {
                                    @Override
                                    public void handle(Void event) {
                                        GrpcStatus status = getStatus(response);
                                        if (status == GrpcStatus.OK) {
                                            exporterMetrics.addSuccess(numItems);
                                            result.succeed();
                                            return;
                                        }
                                        String statusMessage = getStatusMessage(response);
                                        if (statusMessage == null) {
                                            exporterMetrics.addSuccess(numItems);
                                            result.succeed();
                                            return;
                                        }

                                        logAppropriateWarning(status, statusMessage);
                                        exporterMetrics.addFailed(numItems);
                                        result.fail();
                                    }
                                })
                                .exceptionHandler(new Handler<Throwable>() {
                                    @Override
                                    public void handle(Throwable t) {
                                        exporterMetrics.addFailed(numItems);
                                        logger.log(
                                                Level.SEVERE,
                                                "Failed to export "
                                                        + type
                                                        + "s. Stream failed. Full error message: "
                                                        + t.getMessage());
                                        result.fail();
                                    }
                                });
                    }

Still don't think that fixing the response parsing will fix the issue... just wanted to share these findings...

In the mean time internally we have made an okhttp exporter extension and we are using that with Quarkus 3.5 overriding (removing) the Vert.x exporter, and not seeing any errors... one thing that I noted that might have brought errors to the default exporter on Quarkus is that the OkHttp version is defaulted to 3.14.9 and okio 1.7.9... and OTEL uses 4.11.0 which brings also a new okio... so there was a version mismatch there... but with our extension we forced the new okhttp version 4.12.0 and okio 3.6.0... with that we had no memory issues nor anything else...

[luneo7]

And here is a stack trace for one of those stream closed:

handle:340, VertxGrpcExporter$ClientRequestOnSuccessHandler$2 (io.quarkus.opentelemetry.runtime.exporter.otlp)
handle:337, VertxGrpcExporter$ClientRequestOnSuccessHandler$2 (io.quarkus.opentelemetry.runtime.exporter.otlp)
onFailure:117, FutureImpl$2 (io.vertx.core.impl.future)
onFailure:268, FutureImpl$ListenerArray (io.vertx.core.impl.future)
emitFailure:75, FutureBase (io.vertx.core.impl.future)
tryFail:230, FutureImpl (io.vertx.core.impl.future)
onFailure:45, Mapping (io.vertx.core.impl.future)
emitFailure:75, FutureBase (io.vertx.core.impl.future)
tryFail:230, FutureImpl (io.vertx.core.impl.future)
tryFail:23, PromiseImpl (io.vertx.core.impl.future)
fail:183, HttpClientRequestBase (io.vertx.core.http.impl)
handleException:178, HttpClientRequestBase (io.vertx.core.http.impl)
handleException:81, HttpClientRequestImpl (io.vertx.core.http.impl)
handle:-1, 1562917048 (io.vertx.core.http.impl.HttpClientRequestImpl$$Lambda$1069)
handleException:542, Http2ClientConnection$StreamImpl (io.vertx.core.http.impl)
handle:-1, 1652996321 (io.vertx.core.http.impl.VertxHttp2Stream$$Lambda$1092)
emit:55, EventLoopContext (io.vertx.core.impl)
emit:297, ContextBase (io.vertx.core.impl)
onException:95, VertxHttp2Stream (io.vertx.core.http.impl)
onStreamClosed:154, Http2ConnectionBase (io.vertx.core.http.impl)
onStreamClosed:188, VertxHttp2ConnectionHandler (io.vertx.core.http.impl)
notifyClosed:357, DefaultHttp2Connection (io.netty.handler.codec.http2)
removeFromActiveStreams:1007, DefaultHttp2Connection$ActiveStreams (io.netty.handler.codec.http2)
deactivate:963, DefaultHttp2Connection$ActiveStreams (io.netty.handler.codec.http2)
close:515, DefaultHttp2Connection$DefaultStream (io.netty.handler.codec.http2)
close:153, DefaultHttp2Connection (io.netty.handler.codec.http2)
channelInactive:217, Http2ConnectionHandler$BaseDecoder (io.netty.handler.codec.http2)
channelInactive:432, Http2ConnectionHandler (io.netty.handler.codec.http2)
channelInactive:149, VertxHttp2ConnectionHandler (io.vertx.core.http.impl)
invokeChannelInactive:305, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelInactive:281, AbstractChannelHandlerContext (io.netty.channel)
fireChannelInactive:274, AbstractChannelHandlerContext (io.netty.channel)
channelInactive:81, ChannelInboundHandlerAdapter (io.netty.channel)
channelInactive:277, IdleStateHandler (io.netty.handler.timeout)
invokeChannelInactive:303, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelInactive:281, AbstractChannelHandlerContext (io.netty.channel)
fireChannelInactive:274, AbstractChannelHandlerContext (io.netty.channel)
channelInactive:1405, DefaultChannelPipeline$HeadContext (io.netty.channel)
invokeChannelInactive:301, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelInactive:281, AbstractChannelHandlerContext (io.netty.channel)
fireChannelInactive:901, DefaultChannelPipeline (io.netty.channel)
run:813, AbstractChannel$AbstractUnsafe$7 (io.netty.channel)
runTask:173, AbstractEventExecutor (io.netty.util.concurrent)
safeExecute:166, AbstractEventExecutor (io.netty.util.concurrent)
runAllTasks:470, SingleThreadEventExecutor (io.netty.util.concurrent)
run:569, NioEventLoop (io.netty.channel.nio)
run:997, SingleThreadEventExecutor$4 (io.netty.util.concurrent)
run:74, ThreadExecutorMap$2 (io.netty.util.internal)
run:30, FastThreadLocalRunnable (io.netty.util.concurrent)
run:829, Thread (java.lang)

The start of the stacktrace is a little off since I've changed the code to debug a little, but didn't change what the code was doing...
So, Netty is firing an event stating that the channel is inactive, and that happens before we receive (finish receiving) the response... the error doesn't seem to be happening to the server as it logs that error stating that transport was closed, so Netty somehow decided that the channel is inactive and killed the connection creating the error in the server, and also the exception in the Quarkus GRPC client... also what proves that it is not the server is that with OkHttp that kind of error doesn't happen.

[brunobat]

Thanks for debugging this @luneo7. Those are great insights.
We decided to remove OkHttp because it depends on Kotlin and we don't provide support for Kotlin based libs, which is the case of OkHttp v4.x+. Same for Wildfly and EAP.
That's the reason of the version mismatch.
We now need to polish the vert.x client...
An interesting exercise should be to test the vert.x client with the http/protobuf protocol, not with grpc. FYI, there are discussions in OTel Java to move the default from grpc to http/protobuf.

[luneo7]

You would not see any error with OkHttp as the retry is handled silently

What I am saying is that on the server side there is no error log with OkHttp, and with Vert.x client there is a server error log in the collector that comes at the same time as the quarkus error log

[luneo7]

One thing that I also noted, is that for OkHTTP, the default max pool size is 5, whereas with vertx we are not setting setHttp2MaxPoolSize, so it defaults to 1 (since DEFAULT_HTTP2_MAX_POOL_SIZE = 1).... dunno if it also has some impact on something...

[geoand]

It shouldn't matter, since we are only making a single (non blocking) call every x secondy

[luneo7]

I think that we can make more than one request at time, since there is batch max export span size, defaults 512, or 5 seconds, so if we have a bunch of requests and they exceed 512 under 5 seconds we are going to have simultaneous calls or at least try to

[brunobat]

@luneo7 is right and we can simulate this to see if it replicates:
These properties should do it:

# default is 512
quarkus.otel.bsp.max.export.batch.size=1 
# default is 30s
quarkus.otel.bsp.export.timeout=1s 
# default is 2048
quarkus.otel.bsp.max.queue.size=1 
# default is 5s
quarkus.otel.bsp.schedule.delay=1s

Based on the defaults, it's totally possible that each 5s you get an export with a large number of elements being split in multiple batch requests and overlapping with the next export slot.
Also both size and delay can trigger exports.
If this is causing it, increasing the quarkus.otel.bsp.schedule.delay and quarkus.otel.bsp.max.queue.size could in theory reduce the number of errors.

[geoand]

When requests are done in a non blocking manner, the queue size does not have the same semantics.

I will however take another look

[geoand]

Moreover quarkus.otel.bsp.max.queue.size is not the same thing as what @luneo7 described above

[geoand]

@cescoffier @vietj what is the reason for DEFAULT_HTTP2_MAX_POOL_SIZE being 1?

[geoand]

The only thing I can think of is (maybe was?) that there is some weird in Netty or Vert.x gRPC handling that occasionally causes a connection issue.
With the introduction of more retries in #38895 that should hopefully go away.

[cescoffier]

@geoand @vietj I don't have the exact reason, but...

It's HTTP/2. Each connection can contain streams (channels) to multiplex on a single connection. So, for a client that connects to a single endpoint (which seems to be the case here), establishing a single connection and using streams makes a lot of sense. Now, if your client needs to connect to multiple endpoints (different hostname:port) when, yes, this property needs to be increased.

If, within a single connection, you reach the maximum number of allowed streams, this is because the server limits that number (for capacity reasons) - so creating a second connection is counterproductive.

[geoand]

Right, I thought of the multiplexing after asking the question :)

[famod]

So I see that the grpc variant has received a robustness enhancement, which is nice.
I could give that a spin, but given that http/protobuf will become the default soon I'm leaning towards http/protobuf.
Are the last thoughts on pool size etc. also relevant for http/protobuf?

Thing is: I gave http/protobuf a try for at least a day and yes, I used the proper port 4318 for that. Request go directly to Jaeger (through some Hashicorp connect sidecars that handle TLS transparently), no separate collector involved.
Timeout was doubled to 20s.
Still, the error pops up every 5-10 minutes with not that much going on except some scheduled jobs.
I also tried gzip compression to no avail.

Would it make sense to log more details? E.g. how many spans were involved?

[brunobat]

So I see that the grpc variant has received a robustness enhancement, which is nice. I could give that a spin, but given that http/protobuf will become the default soon I'm leaning towards http/protobuf. Are the last thoughts on pool size etc. also relevant for http/protobuf?

Yes, the queue size and other properties above are independent from protocol and should also work in http/protobub.

Thing is: I gave http/protobuf a try for at least a day and yes, I used the proper port 4318 for that. Request go directly to Jaeger (through some Hashicorp connect sidecars that handle TLS transparently), no separate collector involved. Timeout was doubled to 20s. Still, the error pops up every 5-10 minutes with not that much going on except some scheduled jobs. I also tried gzip compression to no avail.

Would it make sense to log more details? E.g. how many spans were involved?

That can be added to some of the error messages, yes.

[vietj]

@cescoffier @vietj what is the reason for DEFAULT_HTTP2_MAX_POOL_SIZE being 1?

Clients SHOULD NOT open more than one HTTP/2 connection to a given host and port pair

https://httpwg.org/specs/rfc9113.html#rfc.section.9.1

[geoand]

Thanks!

[geoand]

In light of this, I am going to close this as fixed.
We can surely reopen if the problem reappears