Update Tracer#in_span to finish the Span

[elskwid]

Overview

Updates Tracer#in_span to call Span#finish at the end of the block and adds API tests for Tracer.

Details

While creating some examples based on the DataDog auto-instrumentation work I noticed that the Tracer#in_span implementation wasn't finishing the span as expected. I looked into the Python implementation and saw the call the end(). This adds the call to #finish and adds tests to both the API and SDK.

The tests are going through some slight acrobatics to verify things are working as expected. Please let me know if there are better ways to do this given the implementation(s).

I added tests for the existing API Tracer implementation before updating #in_span to make sure the changes wouldn't cause us trouble in other methods.

Thoughts

• I like that the Python API makes the call to finish/end optional. If we're interested in that I can open a new PR for that functionality. @fbogsany mentioned we may want to do this.
• It's usually bad form to add methods just to ease testing but you can see that I had to poke at the internals a bit to figure out if a span has ended. Any reason not to add Span#ended??

[fbogsany]

I like that the Python API makes the call to finish/end optional. If we're interested in that I can open a new PR for that functionality. @fbogsany mentioned we may want to do this.

I'm going to walk back my 'like' for this. This is a convenience API that now wraps 3 things that a client can already do with the API:

1. start a new span
2. make it active
3. finish it
   Optionally removing one of the 3 doesn't really bring enough value to justify the complication to the method signature. Compare:

span = nil
result = OpenTelemetry.tracer.in_span('do-the-thing', finish: false) do |new_span|
  span = new_span
  compute_the_thing
end
...
span.finish

with:

span = OpenTelemetry.tracer.start_span('do-the-thing')
result = OpenTelemetry.tracer.with_span(span) { compute_the_thing }
...
span.finish

I'd argue the latter is cleaner, easier to understand, and easier to use.

[elskwid]

I like that the Python API makes the call to finish/end optional. If we're interested in that I can open a new PR for that functionality. @fbogsany mentioned we may want to do this.

I'm going to walk back my 'like' for this. This is a convenience API that now wraps 3 things that a client can already do with the API:

1. start a new span

2. make it active

3. finish it
   Optionally removing one of the 3 doesn't really bring enough value to justify the complication to the method signature. Compare:

span = nil
result = OpenTelemetry.tracer.in_span('do-the-thing', finish: false) do |new_span|
  span = new_span
  compute_the_thing
end
...
span.finish

with:

span = OpenTelemetry.tracer.start_span('do-the-thing')
result = OpenTelemetry.tracer.with_span(span) { compute_the_thing }
...
span.finish

I'd argue the latter is cleaner, easier to understand, and easier to use.

@fbogsany Totally agree with this. Looking closer, the Python folks have added the optional flag to Tracer.use_span which appears to map to our Tracer#with_span. It wasn't clear to me that the method would accept a Span. (The API uses span: "Span" while the SDK uses span: trace_api.Span). Maybe this changes our opinion of the usefulness...

Keep #in_span signature the way it is.

OpenTelemetry.tracer.in_span('do-the-thing') do |new_span|
  compute_the_thing
end

#with_span using default finish of false:

span = OpenTelemetry.tracer.start_span('do-the-thing')
result = OpenTelemetry.tracer.with_span(span) { compute_the_thing }
# ...
span.finish

#with_span using finish == true:

span = OpenTelemetry.tracer.start_span('do-the-thing')
result = OpenTelemetry.tracer.with_span(span, finish: true) { compute_the_thing }

Since #in_span uses #with_span it can default to finish: true, and that might also fix up the problem of returning the value from the with_span block.

[fbogsany]

I think it is worth laying out the common use-cases of each method:

• start_root_span is used when explicitly starting a new trace. This is not common for typical HTTP services, but can be used in a background (e.g. Resque or Sidekiq) job, and may also be used for services that form a boundary between 3rd-party and 1st-party systems (where we may not want to continue a trace started by another business entity). The common pattern is something like:

def foo
  span = tracer.start_root_span('foo')
  ... # maybe tracer.with_span(span) at some point
ensure
  span.finish
end

• start_span provides the most flexibility. It is typically used when a caller wishes to precisely manage the lifetime of the span, the span parent, and also wishes to manage its "activation" via with_span (or not, as the case may be). Typical patterns include:

def foo(parent_span)
  span = tracer.start_span('foo', with_parent: parent_span)
  ... # maybe tracer.with_span(span) at some point
ensure
  span.finish
end

def foo
  span = tracer.start_span('foo') # implicit parent span from current context
  Thread.new(span) do |span|
    ... # maybe tracer.with_span(span) at some point
  ensure
    span.finish
  end
end

• with_span simply activates and deactivates the span w.r.t. the current context. The primary value here is making the "current span" available through a call chain that does not propagate the span via an explicit parameter. Examples include pretty much any Ruby framework at present, which obviously do not anticipate the existence of OpenTelemetry. Example:

def leaf_method
  span = start_span('leaf') # implicit parent span from current context
  do_the_thing
ensure
  span.finish
end

def framework_method
  leaf_method
end

def service_method
  wire_context = tracer.http_text_format.extract(headers) { |headers, key| headers[key] } # what a horrible API, in retrospect
  span = tracer.start_span('service', with_parent_context: wire_context)
  result = tracer.with_span(span) { framework_method }
  format_result(result)
ensure
  span.finish
end

• in_span is a convenience method for a common use-case, especially in manual instrumentation (the moral equivalent of StatsD.measure('my-metric') { ... } or manual timing code & logging). The most common use-case outside of auto-instrumentation is wrapping a block of code in a span, where the author shouldn't have to think about propagation (where her span's parent comes from, which spans her span parents). E.g.:

def my_wonderful_but_maybe_slow_method
  tracer.in_span('my_wonderful_but_maybe_slow_method') do
    sleep(30)
    do_something
  end
end

• current_span is most often used when a new piece of information is discovered at a random point in the code and we want to add it as an attribute or event to the current span (effectively add a metric/dimension or a log), without really caring about what that span is. E.g.

def i_just_figured_it_out!
  tracer.current_span['answer'] = 42
end

From this perspective, I don't think with_span should do optional-double-duty of finishing the span. Its sole purpose is to propagate the span across API boundaries ("in process context propagation"). Most leaf methods (e.g. when instrumenting calls to Redis, memcached, MySQL, etc.) should use explicit span creation and finish.

[elskwid]

@fbogsany I believe I have addressed all your feedback. This is rebased on master and ready to go. Thank you again for the thorough review and all the help. I've opened issue #123 to update the documentation with your Tracer method explanations above.

🙇

[fbogsany]

This behaviour is wrong. Or maybe it isn't. It's definitely up for discussion, with the Named Tracers change. The SDK does not behave in this way, and I don't think the API's "no-op" implementation should either. Specifically, the new Span should share the parent span's trace ID, but should have a different span ID.

opentelemetry-ruby/api/lib/opentelemetry/trace/tracer.rb

Lines 48 to 50 in 3b52ae0

	span_context = with_parent&.context || with_parent_context || current_span.context
	if span_context.valid?
	Span.new(span_context: span_context)

vs.

opentelemetry-ruby/sdk/lib/opentelemetry/sdk/trace/tracer.rb

Line 102 in 3b52ae0

OpenTelemetry::Trace::Span.new(span_context: OpenTelemetry::Trace::SpanContext.new(trace_id: trace_id))

[fbogsany]

Let's stick with the current behaviour for now. This matches the Java implementation of DefaultSpan. There's some related debate in open-telemetry/opentelemetry-specification#208

[fbogsany]

LGTM. Some things will need to move after #122 lands, but we can deal with that then.

[mwear]

It looks like #122 has landed, and this is conflicted. What do we need to do to move this forward?

[elskwid]

@mwear I will make the moves on Friday and see if I can get it over the line.

[elskwid]

@fbogsany I've addressed all the suggestions/issues you raised with the exception of changing the behavior you mentioned in this comment.

@mwear this has been rebased and the Minitest deprecations have also been addressed.

I believe it's good to go.

[mwear]

Thanks for this and the test cases ✨ @elskwid.