Modular Sinatra not handling resource names correctly

[tomasv]

Hey,

We have a couple of Sinatra apps that split logic into Sinatra subapps like described in "Using Sinatra as Middleware" in Sinatra README.

The issue is that the subapps that are mounted into the main Sinatra app generate spans with less information and most importantly without the query path information.

I built a simple app to demonstrate the issue:

require 'bundler/inline'

gemfile(true) do
  gem 'sinatra', '2.0.8.1'
  gem 'ddtrace', '0.31.0'
end

require 'sinatra/base'
require 'ddtrace'

Datadog.configure do |c|
  c.tracer enabled: true, debug: true
  c.use :sinatra
end

class SubApp < Sinatra::Base
  get '/subapp' do
    'im a subapp!'
  end
end

class App < Sinatra::Base
  register Datadog::Contrib::Sinatra::Tracer
  use SubApp

  get '/app' do
    'im an app!'
  end

  run!
end

(this can be placed into app.rb and run with ruby app.rb)

Then GET'ing /app and /subapp yields such spans:

 Name: sinatra.request
Span ID: 993493109027999176
Parent ID: 0
Trace ID: 8546903515006022516
Type: web
Service: sinatra
Resource: GET /app
Error: 0
Start: 1578580744393947904
End: 1578580744394780928
Duration: 833000
Allocations: 345
Tags: [
   http.url => /app,
   http.method => GET,
   sinatra.route.path => /app,
   http.response.headers.content_type => text/html;charset=utf-8]
Metrics: [
   system.pid => 54966.0,
   http.status_code => 200.0,
   _sampling_priority_v1 => 1.0]]

 Name: sinatra.request
Span ID: 5146783070146725872
Parent ID: 0
Trace ID: 3033401100074248247
Type: web
Service: sinatra
Resource: sinatra.request
Error: 0
Start: 1578580741950976000
End: 1578580741954078976
Duration: 3103000
Allocations: 5754
Tags: [
   http.response.headers.content_type => text/html;charset=utf-8]
Metrics: [
   system.pid => 54966.0,
   _sampling_priority_v1 => 1.0]]

As you can see GET /subapp span does not have proper tags and resource name.

Expected behaviour: mounted Sinatra apps get the same detailed spans as the top-level Sinatra app. This case also works correctly with NewRelic.

Thanks

[tomasv]

I forgot to mention one extra detail that might help:

Putting register Datadog::Contrib::Sinatra::Tracer into each Sinatra app almost fixes this, but then each web request logs as many spans as there are register calls with only some of the spans being correctly filled out.

[delner]

Okay, thanks for the report @tomasv! We'll try replicate this from what you provided and follow up.

[ZimbiX]

This is a duplicate of https://github.com/DataDog/dd-trace-rb/issues/486, but with a better title.

@jpaulgs and I at GreenSync had submitted a PR over a year and a half ago that would have fixed this problem, but sadly, it was not merged (iirc, due to an at-the-time upcoming significant refactor of ddtrace).

In mid-December 2019, we moved from using our by-that-time ancient fork of the gem with our fix, to the mainline gem (for access to new features). We wanted to find a way to do that without monkeypatching ddtrace, and so came up with this:

lib/dex/core/api/dex_dd_trace.rb:

require 'ddtrace/contrib/rack/middlewares'
require 'ddtrace/contrib/sinatra/ext'

module Dex
  module Core
    module API
      module DexDDTrace
        def self.registered(app)
          app.after do
            preferred_resource = proc do |sinatra_span|
              if /(GET|PUT|PATH|HEAD|POST)\s$/.match?(sinatra_span.resource)
                sinatra_span.resource + sinatra_span.get_tag('http.url')
              else
                sinatra_span.resource
              end
            end

            rack_span = env[Datadog::Contrib::Rack::TraceMiddleware::RACK_REQUEST_SPAN]
            sinatra_span = env[Datadog::Contrib::Sinatra::Ext::RACK_ENV_REQUEST_SPAN]
            rack_span.resource ||= preferred_resource.call(sinatra_span)
          end
        end
      end
    end
  end
end

Sinatra.send(:register, Dex::Core::API::DexDDTrace)

In config.ru - close to the top, before any other middleware:

if app_context.apm_config.enabled
  require 'sequel' # required for ddtrace to properly patch sequel since it doesn't require sequel itself
  require 'ddtrace'
  require 'ddtrace/contrib/sinatra/tracer'

  Datadog.configure do |c|
    c.tracer(
      hostname: app_context.apm_config.agent_host,
      port: app_context.apm_config.agent_port,
      env: app_context.apm_config.env,
    )
    service_name = 'dex-core'
    c.use :rack, service_name: service_name, request_queuing: true, distributed_tracing: true
    c.use :sinatra, service_name: service_name, resource_script_names: true
    c.use :sequel
  end

  use Datadog::Contrib::Rack::TraceMiddleware

  require 'dex/core/api/dex_dd_trace'
end

Writing specs for all this was rather difficult. When we enable ddtrace in our config then parse config.ru, it patches classes - which then affects the rest of our test suite. My solution involved spawning a subprocess of RSpec for this spec to isolate its runtime.

spec/isolate.rb:

# frozen_string_literal: true

module IsolateSpec
  def self.isolate(spec_file)
    isolated = !Object.constants.include?(:Dex)
    unless isolated
      RSpec.describe 'Isolated spec' do
        it 'passes all its specs' do
          command = [$PROGRAM_NAME, spec_file].join ' '
          require 'open3'
          stdout, _stderr, status = Open3.capture3(command)
          expect(stdout).to include(' 0 failures')
          expect(status).to eq(0)
        end
      end
    end
    isolated
  end
end

spec/dex/core/ddtrace_spec.rb:

require 'isolate'
isolated = IsolateSpec.isolate(__FILE__)
return unless isolated

require 'ddtrace/span'
require 'ddtrace/tracer'
require 'rack/test'
require 'rspec'
require 'timeout'

ENV['RACK_ENV'] = 'test'

RSpec.describe 'Datadog APM', controller: true do # rubocop:disable RSpec/DescribeClass
  include Rack::Test::Methods

  describe 'resources that show up in APM' do
    let(:app) { Rack::Builder.parse_file('config.ru').first }
    let(:spans) { [] }

    before do
      @dd_apm_enabled_orig = ENV['DD_APM_ENABLED']
      ENV['DD_APM_ENABLED'] = 'true'
      Datadog::Logger.log = Logger.new(nil)

      allow_any_instance_of(Datadog::Span).to receive(:finish).and_wrap_original do |method, *args| # rubocop:disable RSpec/AnyInstance
        method.call(*args).tap do |span|
          spans << span.to_hash
        end
      end
    end

    after { ENV['DD_APM_ENABLED'] = @dd_apm_enabled_orig } # rubocop:disable RSpec/InstanceVariable

    def find_root_span
      spans.find { |span| span[:type] == 'web' && span[:parent_id] == 0 }
    end

    shared_examples 'a http request' do |resource, method|
      context "shows #{resource}" do
        let(:root_span) { find_root_span }

        it 'includes a HTTP root span' do
          expect(spans).to include(hash_including(type: 'web', parent_id: 0))
        end

        it 'records the resource on the root span' do
          expect(root_span[:resource]).to eq(resource)
        end

        it 'records the http method' do
          expect(root_span[:meta]['http.method']).to eq(method)
        end

        it 'records the url' do
          expect(root_span[:meta]['http.url']).to eq(request_path)
        end
      end
    end

    def expect_route_to_be_handled_by_a_controller
      error = 'The requested URL did not match a controller route'
      if last_response.status == 404
        expect(last_response.body).to include('"code":"NotFound"'), error
      else
        expect([200, 201, 400]).to include(last_response.status), error # rubocop:disable RSpec/ExpectActual
      end
    end

    context 'when Rack::Builder `map` route is prepended to the Sinatra route' do
      let(:request_path) { '/.well-known/jwks.json' }

      before do
        get request_path
      end

      it 'is a handled route' do
        expect_route_to_be_handled_by_a_controller
      end

      include_examples 'a http request',
                       'GET /.well-known/jwks.json',
                       'GET'
    end
  end
end

Sorry for the code dump - we're looking at a way to upstream/gem-ify this or turn it into a proper fix, but I thought I'd contribute this info now in case it helps =)

[delner]

@ZimbiX thanks for sharing this! Fixing this for Sinatra is something high on my list, but we could use a little help. The quickest way to get this in the mainline would be to update #486 or open an an equivalent PR that has the changes you need.

Apparently that older PR fell through the cracks, but once updated, I'm more than happy to give you a fresh review and help get it merged.

[marcotc]

Thank you for the detailed report @tomasv and @ZimbiX, we've just merged #1015 adding full support for modular Sinatra apps.

We'll update this GH issue when the release is out with this feature.

[marcotc]

v0.35.0 has been released with full support for Sinatra modular apps.

I'll close this issue, but please let us know if there's any further feedback!

[tomasv]

@marcotc great news, but a new issue in 0.35.0 is blocking us from testing this out: https://github.com/DataDog/dd-trace-rb/issues/1021