Can not execute the operation on ended Span opentelemetry-instrumentation-http

[bogdanoliinyk]

What version of OpenTelemetry are you using?

0.18.0

What version of Node are you using?

tested 12 and 14

Please provide the code you used to setup the OpenTelemetry SDK

export class SDK {
    static setup(): void {
        diag.setLogger(new DiagConsoleLogger(), logLevel[config.loggerLevel] || DEFAULT_LOG_LEVEL);

        const provider: NodeTracerProvider = new NodeTracerProvider();
        provider.register();

        registerInstrumentations({
            instrumentations: [
                new HttpInstrumentation(),
                new GrpcInstrumentation()
            ],
            tracerProvider: provider
        });
    }
}

What did you do?

http request call

What did you expect to see?

Span created and closed with all data set

What did you see instead?

Can not execute the operation on ended Span

Additional context

That happens because request close event fired before the response end event.

socketCloseListener might emits close event before readable steam ended.

Due to it, http instrumentation going to close Span

opentelemetry-js/experimental/packages/opentelemetry-instrumentation-http/src/http.ts

Line 344 in 357ec92

this._closeHttpSpan(span);

Response end event will set Span status, that will lead to ended span issue.

opentelemetry-js/experimental/packages/opentelemetry-instrumentation-http/src/http.ts

Line 317 in 357ec92

span.setStatus(status);

It might be tricky to reproduce, as I see it relay on response content size. In most cases, request close event is fired after response end. I was lucky to reproduce it.
There is some logic in a stream implementation.

Possible solution

Request end event might be changed with a close event.

opentelemetry-js/experimental/packages/opentelemetry-instrumentation-http/src/http.ts

Line 307 in 357ec92

response.on('end', () => {

Response close event will be fired after request close by socketCloseListener implementation.
Lines: 389 and 393

Related items

#2126

[dyladan]

Looking at all the events in https://nodejs.org/api/http.html#httprequesturl-options-callback I think close might make sense but would like to get @vmarchaud opinion since he wrote the original version afaik.

[vmarchaud]

I did rewrite the old plugin to the new instrumentation system but i didn't write the original code which i'm pretty sure was ported from opencensus.
From what i read here (https://nodejs.org/api/net.html#event-end), the end event indeed is fired when we can't read anymore from it but it can still be written to. Updating it to close looks fine to me.

EDIT: @bogdandrutu Do you want/have the time to make a PR to fix this ?

PS: thanks for the detailed bug report, really appreciated

[bogdanoliinyk]

Hi guys, is there any news ?
@dyladan @vmarchaud @bogdandrutu

[dyladan]

@vmarchaud pinged the wrong bogdan. I think he meant to ask if you @bogdanoliinyk want to make a PR

[vmarchaud]

I think he meant to ask if you @bogdanoliinyk want to make a PR

Yep, github username suggestions sometimes betray me :)

[github-actions]

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

[github-actions]

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

[github-actions]

This issue was closed because it has been stale for 14 days with no activity.

[SimenB]

I'm hitting this (I think), but I'm unable to consistently reproduce. In our case it happens with the https instrumentation when fetching data from GCS.

Looking at the code I don't really understand why _spanNotEnded does not prevent this from happening, tho. That's only checked for end, not setStatus

[SimenB]

By adding some logging, I can see it's the same response.on('end', () => { call identified in the OP. Using 18.14.1, so still an issue in the latest LTS (at the time of writing)

[dyladan]

I did rewrite the old plugin to the new instrumentation system but i didn't write the original code which i'm pretty sure was ported from opencensus. From what i read here (https://nodejs.org/api/net.html#event-end), the end event indeed is fired when we can't read anymore from it but it can still be written to. Updating it to close looks fine to me.

EDIT: @bogdandrutu Do you want/have the time to make a PR to fix this ?

PS: thanks for the detailed bug report, really appreciated

The docs listed here are for the net socket. Are these events emitted on the request/response from http? They're not listed in https://nodejs.org/api/http.html#httprequesturl-options-callback

nevermind i'm just confusing myself in the maze of docs