otel_tracer_noop:with_span/5 doesn't restore context properly

[DenysGonchar]

description:

otel_tracer_noop:with_span/5 doesn't restore context properly

here is a code snippet that demonstrates the problem:

require OpenTelemetry.Tracer, as: Tracer

ctx = Tracer.with_span :parent_span1 do
  OpenTelemetry.Ctx.get_current()
end |> IO.inspect(label: "parent_span1 context"); :ok

OpenTelemetry.set_default_tracer({:otel_tracer_noop, []})

Tracer.with_span :parent_span2 do
  OpenTelemetry.Ctx.get_current() |> IO.inspect(label: "parent_span2 context")
  Tracer.with_span ctx, :nested_span, %{} do
    OpenTelemetry.Ctx.get_current() |> IO.inspect(label: "nested_span context")
  end
  OpenTelemetry.Ctx.get_current() |> IO.inspect(label: "restored parent_span2 context")
end; :ok

and the output is:

parent_span1 context: %{
  {:otel_tracer, :span_ctx} => {:span_ctx,
   226093672235243343240248130524572830431, 14684213315684633963, 1,
   {:tracestate, []}, true, false, true,
   {:otel_span_ets, #Function<2.55784961/1 in :otel_tracer_server.on_end/1>}}
}

parent_span2 context: %{
  {:otel_tracer, :span_ctx} => {:span_ctx, 0, 0, 0, {:tracestate, []}, false,
   false, false, :undefined}
}
nested_span context: %{
  {:otel_tracer, :span_ctx} => {:span_ctx,
   226093672235243343240248130524572830431, 14684213315684633963, 1,
   {:tracestate, []}, true, false, true,
   {:otel_span_ets, #Function<2.55784961/1 in :otel_tracer_server.on_end/1>}}
}
restored parent_span2 context: %{
  {:otel_tracer, :span_ctx} => {:span_ctx,
   226093672235243343240248130524572830431, 14684213315684633963, 1,
   {:tracestate, []}, true, false, true,
   {:otel_span_ets, #Function<2.55784961/1 in :otel_tracer_server.on_end/1>}}
}

expected behaviour:

the context is properly restored after execution of otel_trace:with_span/5

proposed changes:

with_span(Ctx, Tracer, SpanName, Opts, Fun) ->
    SpanCtx = start_span(Ctx, Tracer, SpanName, Opts),
    Ctx1 = otel_tracer:set_current_span(Ctx, SpanCtx),
    Token = otel_ctx:attach(Ctx1),
    try
        Fun(SpanCtx)
    after
        otel_ctx:detach(Token)
    end.

[tsloughter]

@DenysGonchar did you try this change? I'm actually not seeing what is different from the current code in your suggestion?

[DenysGonchar]

sorry for the delay. here is the current implementation:

with_span(Ctx, Tracer, SpanName, Opts, Fun) ->
    SpanCtx = start_span(Ctx, Tracer, SpanName, Opts),
    Ctx1 = otel_tracer:set_current_span(Ctx, SpanCtx),
    otel_ctx:attach(Ctx1),
    try
        Fun(SpanCtx)
    after
        otel_ctx:attach(Ctx)
    end.

note that the random external context is attached in the after block, instead of restoring the context from the token returned by otel_ctx:attach(Ctx1)

[DenysGonchar]

actually, otel_tracer_default does the same thing.

with_span(Ctx, Tracer, SpanName, Opts, Fun) ->
    SpanCtx = start_span(Ctx, Tracer, SpanName, Opts),
    Ctx1 = otel_tracer:set_current_span(Ctx, SpanCtx),
    Token = otel_ctx:attach(Ctx1),
    try
        Fun(SpanCtx)
    after
        %% passing SpanCtx directly ensures that this `end_span' ends the span started
        %% in this function. If spans in `Fun()' were started and not finished properly
        %% they will be abandoned and it be up to the `otel_span_sweeper' to eventually remove them.
        _ = otel_span_ets:end_span(SpanCtx),
        otel_ctx:detach(Token)
    end.

and it also contains one more important thing - otel_span_ets:end_span(SpanCtx) in the after block. it also must be added in otel_tracer_noop:with_span/5

[bryannaegele]

The behavior you're pointing out is the correct one. The original ctx is taken in, a span is started and ended (new context) and then the original is reattached.

[DenysGonchar]

the behaviour is correct in the otel_tracer_default module, but broken in the otel_tracer_noop

[tsloughter]

Could you send a PR?