Error on sinatra tracing after upgrading to 0.52

[mscrivo]

After upgrading from 0.51 to 0.52, we immediately started getting a slew of these errors:

NoMethodError: undefined method `[]' for nil:NilClass (Most recent call first)
File /home/affinity/vendor/bundle/ruby/3.0.0/gems/ddtrace-0.52.0/lib/ddtrace/contrib/sinatra/env.rb line 13 in datadog_span
File /home/affinity/vendor/bundle/ruby/3.0.0/gems/ddtrace-0.52.0/lib/ddtrace/contrib/sinatra/tracer.rb line 122 in block in route_eval
File /home/affinity/vendor/bundle/ruby/3.0.0/gems/ddtrace-0.52.0/lib/ddtrace/tracer.rb line 283 in trace
File /home/affinity/vendor/bundle/ruby/3.0.0/gems/ddtrace-0.52.0/lib/ddtrace/contrib/sinatra/tracer.rb line 105 in route_eval

Still looking into the codepaths and whether we missed updating something that was deprecated, but thought I'd raise it early.

[ivoanjo]

Hey @mscrivo, thanks a lot for the report!

This looks like a regression from #1628, which shipped in 0.52.0 -- confirming your observation that this issue did not happen on 0.51.1.

From the code path being followed, it looks like you're using a modular sinatra app, e.g. one that subclasses Sinatra::Base.

I have a suspicion about where the issue may be coming from. Could you doublecheck if you're registering the Datadog::Contrib::Sinatra::Tracer middleware in Sinatra as shown in the dd-trace-rb documentation?

It should look something like this

class App < Sinatra::Base
  register Datadog::Contrib::Sinatra::Tracer # <--- the middleware

  get '/' do
    'Hello world!'
  end
end

If you're not, you're actually missing out on a few tracing features; here's how my example test app behaves with the trace middleware:

...and here's how it looks without the middleware:

Notice the missing path, process id and status code reporting.

The difference between 0.51.1 and 0.52.0 is that 0.51.1 did not break when the middleware was missing (both of those screenshots were taken using 0.51.1), whereas in 0.52.0 the configuration without middleware breaks for me with exactly the same stack trace as you reported.

I'll start working on a PR to restore the previous behavior, but if your issue is indeed the missing middleware, my suggestion is to add it, since that's how you get the best out of the sinatra integration anyway.

[mscrivo]

Hi @ivoanjo, thanks for the very detailed response!

I checked and it turns out that we are registering the rack middleware but not the sinatra one. So I see process_id, runtime_id etc on the rack spans, but no the sinatra ones. We do have both a sinatra route and request span though. I can definitely try registering the Sinatra middleware and see if that fixes it.

[ivoanjo]

Let me know if adding the middleware solves it for you!

Indeed in my screenshots above I was using sinatra directly, without the rack integration; As you pointed out, using the rack integration with sinatra does restore some of the metadata that would otherwise be missing.

In the meanwhile I've opened a PR with a fix in #1644 that restores the previous behavior of not breaking whenever the sinatra request span is missing.

[mscrivo]

That does seem to have done the trick. Though, now I am seeing 3 levels of sinatra spans, whereas before we only had 2 request & route:

Is this normal?

[mscrivo]

Ah we might have 2 sinatra.request spans because we were manually creating our own middleware before 🤦🏼

[mscrivo]

This is starting to make more sense now, we didn't register the sinatra middleware because we basically had setup our own to do some extra things:

def self.registered(app)
  app.helpers Tracing::Helpers

  app.before do
    TraceResource.set_resource!(matched_route)

    next unless Datadog.tracer.enabled

    @span =
      Datadog.tracer.trace(
        'sinatra.request',
        service: Datadog.configuration[:sinatra][:service_name],
        span_type: Datadog::Ext::HTTP::TEMPLATE,
      )

    @span.set_tag(Datadog::Ext::HTTP::URL, matched_route)
    @span.set_tag(Datadog::Ext::HTTP::METHOD, request.request_method)
  end

  app.after do
    TraceResource.set_resource!(nil)

    next unless Datadog.tracer.enabled

    @span.resource = "#{request.request_method} #{matched_route}"
    @span.set_tag(Datadog::Ext::HTTP::STATUS_CODE, response.status)
    @span.set_error(env['sinatra.error']) if response.server_error?

    finish_time = Time.now.utc
    duration = finish_time - @span.start_time

    # Reject 98% of uninteresting traces
    if ENDPOINTS_TO_REJECT.include?(matched_route) && Random.rand(100) < 97
      @span.context.sampling_priority = Datadog::Ext::Priority::USER_REJECT
    end

    # Always sample long requests.
    if duration > Affinity::Monitoring::Tracing::ALWAYS_SAMPLE_THRESHOLD
      @span.context.sampling_priority = Datadog::Ext::Priority::USER_KEEP
    end

    @span.finish(finish_time)
  end
end

[ivoanjo]

Interesting, thanks for sharing! The middleware does provide most of that functionality, so enabling it on top of your custom setup would be quite redundant. If you do prefer to keep using the custom setup without the middleware, my fix in #1644 restores the previous behavior.

[mscrivo]

Interesting, thanks for sharing! The middleware does provide most of that functionality, so enabling it on top of your custom setup would be quite redundant. If you do prefer to keep using the custom setup without the middleware, my fix in #1644 restores the previous behavior.

yeah that's my thought as well .. I'm going to try removing it and using the middleware instead.

[mscrivo]

Using the DD middleware solved the issue.