Sinatra instrumentation does not add caught exceptions to the span

[ahayworth]

Description of the bug

The Sinatra auto-instrumentation does not record exceptions as error logs on the span, despite using our in_span helper. This is because Sinatra does not necessarily barf on exceptions unless configured to do so - much like Rails, it catches those exceptions and returns an appropriate HTTP status code but it does not throw the exception. Thus, in_span never has anything to rescue. This feels like a bug to me, but I'm not sure.

Share details about your runtime

Operating system details: Darwin janeway.local 21.5.0 Darwin Kernel Version 21.5.0: Tue Apr 26 21:08:29 PDT 2022; root:xnu-8020.121.3~4/RELEASE_ARM64_T8101 arm64
RUBY_ENGINE: ruby
RUBY_VERSION: 3.1.2
RUBY_DESCRIPTION: ruby 3.1.2p20 (2022-04-12 revision 4491bb740a) [arm64-darwin21]

Share a simplified reproduction if possible

You could trivially reproduce this by adding a raise "boom" into any of the examples we ship. The logged span from one such experiment looks like:

#<struct OpenTelemetry::SDK::Trace::SpanData
 name="GET /thing/:id",
 kind=:server,
 status=#<OpenTelemetry::Trace::Status:0x0000000104ae8eb8 @code=2, @description="">,
 parent_span_id="\x00\x00\x00\x00\x00\x00\x00\x00",
 total_recorded_attributes=4,
 total_recorded_events=0,
 total_recorded_links=0,
 start_timestamp=1655760015092533000,
 end_timestamp=1655760015092967000,
 attributes={"http.method"=>"GET", "http.url"=>"/thing/12345", "http.status_code"=>500, "http.route"=>"/thing/:id"},
 links=nil,
 events=nil,
 resource=
  #<OpenTelemetry::SDK::Resources::Resource:0x0000000104677050
   @attributes=
    {"service.name"=>"unknown_service",
     "process.pid"=>25942,
     "process.command"=>"./server.rb",
     "process.runtime.name"=>"ruby",
     "process.runtime.version"=>"3.1.2",
     "process.runtime.description"=>"ruby 3.1.2p20 (2022-04-12 revision 4491bb740a) [arm64-darwin21]",
     "telemetry.sdk.name"=>"opentelemetry",
     "telemetry.sdk.language"=>"ruby",
     "telemetry.sdk.version"=>"1.1.0"}>,
 instrumentation_library=#<struct OpenTelemetry::SDK::InstrumentationLibrary name="OpenTelemetry::Instrumentation::Sinatra", version="0.20.0">,
 span_id="\x8D\x8D\xCA\t\xAB\x15\xE7i",
 trace_id="\x9E\xA7MA\xA1#\xCBz\x01\x15c\x0E\xC0\xC2\xC4\x92",
 trace_flags=#<OpenTelemetry::Trace::TraceFlags:0x0000000100c49e78 @flags=1>,
 tracestate=#<OpenTelemetry::Trace::Tracestate:0x0000000100c52ca8 @hash={}>>

(Note that while the span status seems correct, there are no log events that would record the error onto the span).

cc open-telemetry/opentelemetry-demo#158

[ahayworth]

I think we could fix this pretty easily here: https://github.com/open-telemetry/opentelemetry-ruby-contrib/blob/main/instrumentation/sinatra/lib/opentelemetry/instrumentation/sinatra/middlewares/tracer_middleware.rb#L46

Something very easy like this (but adapted for the actual internals of the instrumentation) would do it: OpenTelemetry::Trace.current_span.record_exception(env['sinatra.error'])

[ahayworth]

From the SIG - we should actually test this behavior on #54 first, because we suspect the Rack instrumentation actually does the right thing already.

[ahayworth]

After #54 merged, I can confirm that we do not record the exception onto any spans. Rack seems to expect that env['rack.errors'] is actually a StringIO-like object that can be puts to, which complicates this a bit further.

We could try to figure out the exact way that dd-trace-rb is doing it today, although my initial experiments proved unsuccessful: https://github.com/DataDog/dd-trace-rb/blob/master/lib/datadog/tracing/contrib/rack/middlewares.rb

Other options include hijacking env['rack.errors'] to something we control and recording low-fidelity exceptions as span events, or doing this separately for each instrumentation.

Thoughts?