feat(instrumentation-http): add diag debug on http request events

[Asafb26]

Which problem is this PR solving?

In my case, we got some Can not execute the operation on ended Span warnings pointed to outgoing request spans, which I suspect are triggered on response.end event, followed by request.close event which ended the span before. a debug log at this point will be beneficial to understand this behavior.

Short description of the changes

Adds a debug log on a request state change

[Asafb26]

it can be outgoingRequest on response error() but then we probably need to change this line https://github.com/open-telemetry/opentelemetry-js/blob/main/packages/opentelemetry-instrumentation-http/src/http.ts#L314

[codecov]

Codecov Report

Merging #2126 (3ed4e23) into main (feea516) will increase coverage by 0.78%.
The diff coverage is n/a.

❗ Current head 3ed4e23 differs from pull request most recent head 915da21. Consider uploading reports for the commit 915da21 to get more accurate results

@@            Coverage Diff             @@
##             main    #2126      +/-   ##
==========================================
+ Coverage   92.85%   93.64%   +0.78%     
==========================================
  Files         120       55      -65     
  Lines        4031     1762    -2269     
  Branches      853      363     -490     
==========================================
- Hits         3743     1650    -2093     
+ Misses        288      112     -176     

Impacted Files	Coverage Δ
...s/opentelemetry-core/src/platform/node/sdk-info.ts	0.00% <0.00%> (-100.00%)	⬇️
...pentelemetry-core/src/platform/node/performance.ts	0.00% <0.00%> (-100.00%)	⬇️
...emetry-api-metrics/src/platform/node/globalThis.ts	0.00% <0.00%> (-100.00%)	⬇️
...ckages/opentelemetry-exporter-zipkin/src/zipkin.ts	84.48% <0.00%> (-15.52%)	⬇️
...-sdk-trace-base/src/export/InMemorySpanExporter.ts
...pentelemetry-sdk-metrics-base/src/CounterMetric.ts
...strumentation/src/platform/node/instrumentation.ts
...ckages/opentelemetry-sdk-metrics-base/src/Utils.ts
...ges/opentelemetry-exporter-jaeger/src/transform.ts
...elemetry-sdk-trace-base/src/BasicTracerProvider.ts
... and 92 more

[vmarchaud]

Not really sure this is the correct way to tackle the problem, its make more sense to me to trace the Can not execute the operation on ended Span message with the stacktrace so it can be fixed without having to enabling logging, WDYT ?

[Asafb26]

@vmarchaud indeed, but this log does not provide any stack trace and even if I could fetch the stack trace at that point it probably too late (the span is already ended, the log is just a side effect for the real problem)

BTW - we found how to solve it, but yet not the root cause of this issue - the warnings disappeared after we set keepAlive: true in Axios config, not sure if its Axios bug or something related to the HTTP instrumentation

[vmarchaud]

indeed, but this log does not provide any stack trace and even if I could fetch the stack trace at that point it probably too late (the span is already ended, the log is just a side effect for the real problem)

I was suggesting to add the stackrace for this log (https://github.com/open-telemetry/opentelemetry-js/blob/main/packages/opentelemetry-tracing/src/Span.ts#L229) instead, with this you should be know which functions triggered the second end call on the span

[Asafb26]

this would be great, but yet I don't think that adding a stacktrace would point me to the issue, the issue is the first call of span. end and not the second call.
The second span.end triggered from response end callback (which is the expected call).
The first span.end triggered somewhere else - maybe from request close callback - and not set the span.status correctly.
A stacktrace may show us the point which the second end invoked, but not for the first call.

[obecny]

just a friendly ping on this, to prevent it from being stalled
imho I don't see a problem adding more debug information, just suggested to add yet the error itself, besides that lgtm, @vmarchaud whats your take on this ?

[vmarchaud]

whats your take on this ?

I mean i don't have any issue with adding debug statement to debug an otel behavior but i just wanted to avoid adding debug log to debug http lifecyle in itself.
I'm fine with the PR after the change you suggested

[dyladan]

I am not going to block this, but adding debug logs for the underlying lifecycle of the http request seems a little odd to me. I can see the issue though if you end a span twice, you don't know there is an error until the second call to end() but you want the stacktrace from the first call. Maybe there would be some value in adding a developer mode to the SDK which saves the stacktrace when a span is ended and prints it when the span is ended again? Obviously outside the scope of this PR though.

[dyladan]

I will ✅ when you resolve @obecny's suggestion

[dyladan]

Are you going to address @obecny suggestion here? IMO you should either accept the change or make a case why it shouldn't be accepted. The PR will not be merged until conversations are resolved.