dd-trace-rb icon indicating copy to clipboard operation
dd-trace-rb copied to clipboard

Published 20 hours ago • verified publisher icon DataDog

Sinatra: Tracing differences between 0.54 and 1.0

Open mscrivo opened this issue 2 years ago • 11 comments

Hi there, I'm trying to upgrade our app to use 1.0 and running into some differences in behavior between the old and new versions and am just unsure if I'm doing something wrong, or these are intentional. Here's a before and after trace of the same sinatra request:

before: image

after: image

It no longer seems to be picking up the rack & sinatra services in the same way.

Here's a before and after of our config setup:

before:

Datadog.configure do |c|
  c.tracer.enabled = TRACING_ENABLED

  c.tracer.hostname = <host>
  c.tracer.port = 8126

  c.tracer.partial_flush.enabled = ENABLE_PARTIAL_FLUSH

  c.tracer sampler:
             Datadog::PrioritySampler.new(
               post_sampler:
                 Datadog::Sampling::RuleSampler.new(
                   [
                     Datadog::Sampling::SimpleRule.new(sample_rate: SAMPLE_RATE)
                   ]
                 )
             )

  c.runtime_metrics.enabled = true
end

after:

Datadog.configure do |c|
  c.tracing.enabled = TRACING_ENABLED

  c.agent.host = <host>
  c.agent.port = 8126

  c.tracing.partial_flush.enabled = ENABLE_PARTIAL_FLUSH

  c.tracing.sampler =
    Datadog::Tracing::Sampling::PrioritySampler.new(
      post_sampler:
        Datadog::Tracing::Sampling::RuleSampler.new(
          [
            # Sample all traces at configured SAMPLE_RATE
            Datadog::Tracing::Sampling::SimpleRule.new(sample_rate: SAMPLE_RATE)
          ]
        )
    )

  c.tracing.analytics.enabled = true
  c.runtime_metrics.enabled = true
end

We also have the DD annotations setup on our containers like this:

labels:
  tags.datadoghq.com/env="<env>"
  tags.datadoghq.com/service="web"
  tags.datadoghq.com/version="<commit hash>"

we are also calling: use Datadog::Contrib::Rack::TraceMiddleware in our rack config and register Datadog::Contrib::Sinatra::Tracer in our Sinatra base classes.

What's interesting is that with version 0.54, it seemingly ignored the service annotation on the container and used the services it auto discovered, so in our case "sinatra", but now it's using "web" as defined in the annotation.

Any help you can provide on what's wrong with our setup after moving to 1.0 would be greatly appreciated. It seems the tracing produced with 0.54 was more "correct", so I'm hoping I'm just misconfiguring something in 1.0

mscrivo avatar May 19 '22 21:05 mscrivo

👋 @mscrivo, could try removing register Datadog::Contrib::Sinatra::Tracer and checking if the traces are more legible for your application? I see we still have it documented to manually register the Sinatra integration, but we already register ddtrace into Sinatra at configuration time, thus shouldn't be needed: https://github.com/DataDog/dd-trace-rb/blob/2703f941734253fa864d5d4e29903f86f4085f5a/lib/datadog/tracing/contrib/sinatra/patcher.rb#L61-L62

marcotc avatar May 24 '22 18:05 marcotc

The combination of Rack and Sinatra spans into the same service is expected and desirable here. service_name is meant to reflect the name of the application, not layers within the application. We incorrectly separated spans of the same service into different service names before 1.0, and this addresses that issue.

However, seconding what @marcotc said, I think the real concern is the duplication of Rack spans. That shouldn't happen. I would guess there should only be one Rack span, so I would want to determine why there are multiple now. Is instrumentation injected incorrectly?

A few things might be of interest:

  1. Do the Rack spans all look the same?
  2. What does the stack trace look like once you enter the sinatra.request?
  3. How are you activating instrumentation? (With require 'ddtrace/autoinstrument'?)

That may give us some hints. Beyond that, it would be helpful if we can determine some steps to replicate this on our end. Is it as simple as setting up a Sinatra app? Or is there more setup?

delner avatar May 25 '22 13:05 delner

@marcotc I tried your suggestion of removing the registration of the sinatra middleware, and now I'm not seeing the sinatra.request spans, just sinatra.route ones:

image

Also, seeing this in the logs on startup, not sure if it's relevant or not:

WARN -- ddtrace: [ddtrace] Sinatra integration is misconfigured, reported traces will be missing request metadata such as path and HTTP status code. Did you forget to add register Datadog::Tracing::Contrib::Sinatra::Tracer to your Sinatra::Base subclass? See https://docs.datadoghq.com/tracing/setup_overview/setup/ruby/#sinatra for more details.

important to note that we were seeing that on 0.54 and 1.0 before and after removing the middleware registration.

@delner

  1. They mostly look the same, but the top one has a process-id and runtime-id whereas the other ones don't. The final one also has some extra tags we specifically added, that used to get attached to the sinatra.request span, but are now getting attached to the rack.request span.
  2. I have no sinatra.request now after removing the registration, so I'll have to put that back in and get back to you.
  3. yes, we are using require 'ddtrace/auto_instrument'

mscrivo avatar May 25 '22 13:05 mscrivo

@delner by stack trace, you mean actual code stack trace? does that require profiling to be enabled? because I don't recall ever seeing stack traces for our system except for errors.

mscrivo avatar May 25 '22 14:05 mscrivo

  1. The tags are correct (only top level spans should get process/runtime). Odd that tags ended up on Rack instead of Sinatra. (Maybe because span structure changed?)
  2. If you can print caller from inside that Sinatra request, it should give us an array of stack frames, which is the stack trace. That stack trace should show where and how it entered Rack instrumentation so many times. (Profiling is not required.)
  3. Good to know. Not sure if this is a variable or not, just seems like instrumentation was applied multiple times, incorrectly.

My goal here is to be able to replicate this on our end... if we can do that, we can pull apart the instrumentation behavior and come up with a solid diagnosis and solution.

delner avatar May 25 '22 18:05 delner

here's the stacktrace from inside a sinatra request:

"/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1685:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1685:in `block in compile!'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1071:in `block in process_route'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1069:in `catch'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1069:in `process_route'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1010:in `block in filter!'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1009:in `each'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1009:in `filter!'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1008:in `filter!'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1137:in `block in dispatch!'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1112:in `block in invoke'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1112:in `catch'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1112:in `invoke'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1135:in `dispatch!'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:949:in `block in call!'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1112:in `block in invoke'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1112:in `catch'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1112:in `invoke'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:949:in `call!'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:938:in `call'"
 "/Users/michaelscrivo/affinity/patches/legacy_browser_detection.rb:17:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-2.2.3/lib/rack/null_logger.rb:11:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/show_exceptions.rb:22:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:218:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/ddtrace-1.0.0/lib/datadog/tracing/contrib/rack/middlewares.rb:84:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1992:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1552:in `block in call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1768:in `synchronize'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1552:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-router-0.2.4/lib/sinatra/router.rb:81:in `block in try_route'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-router-0.2.4/lib/sinatra/router.rb:79:in `each'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-router-0.2.4/lib/sinatra/router.rb:79:in `try_route'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-router-0.2.4/lib/sinatra/router.rb:14:in `call'"
 "/Users/michaelscrivo/affinity/patches/legacy_browser_detection.rb:17:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/secure_headers-6.3.3/lib/secure_headers/middleware.rb:11:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-protection-2.2.0/lib/rack/protection/base.rb:50:in `call'"
 "/Users/mchaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-protection-2.2.0/lib/rack/protection/base.rb:50:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-router-0.2.4/lib/sinatra/router.rb:21:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-protection-2.2.0/lib/rack/protection/base.rb:50:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-router-0.2.4/lib/sinatra/router.rb:21:in `call'"
 "/Users/michaelscrivo/affinity/lib/query_tracker.rb:273:in `block in call'"
 "/Users/michaelscrivo/affinity/lib/query_tracker.rb:54:in `track_queries!'"
 "/Users/michaelscrivo/affinity/lib/query_tracker.rb:273:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-parser-0.7.0/lib/rack/parser.rb:24:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-throttle-0.7.0/lib/rack/throttle/limiter.rb:35:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-throttle-0.7.0/lib/rack/throttle/limiter.rb:35:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-throttle-0.7.0/lib/rack/throttle/limiter.rb:35:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:996:in `forward'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1088:in `route_missing'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1037:in `route!'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1033:in `route!'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1140:in `block in dispatch!'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1112:in `block in invoke'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1112:in `catch'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1112:in `invoke'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1135:in `dispatch!'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:949:in `block in call!'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1112:in `block in invoke'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1112:in `catch'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1112:in `invoke'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:949:in `call!'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:938:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-2.2.3/lib/rack/null_logger.rb:11:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/show_exceptions.rb:22:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:218:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/ddtrace-1.0.0/lib/datadog/tracing/contrib/rack/middlewares.rb:84:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1992:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-parser-0.7.0/lib/rack/parser.rb:24:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/request_store-1.5.1/lib/request_store/middleware.rb:19:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-protection-2.2.0/lib/rack/protection/xss_header.rb:18:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-protection-2.2.0/lib/rack/protection/path_traversal.rb:16:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-protection-2.2.0/lib/rack/protection/json_csrf.rb:26:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-protection-2.2.0/lib/rack/protection/base.rb:50:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-protection-2.2.0/lib/rack/protection/frame_options.rb:31:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-2.2.3/lib/rack/null_logger.rb:11:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/show_exceptions.rb:22:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:218:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/ddtrace-1.0.0/lib/datadog/tracing/contrib/rack/middlewares.rb:84:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1992:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/puma-5.6.4/lib/puma/commonlogger.rb:40:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/puma-5.6.4/lib/puma/configuration.rb:252:in `call'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/puma-5.6.4/lib/puma/request.rb:77:in `block in handle_request'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/puma-5.6.4/lib/puma/thread_pool.rb:340:in `with_force_shutdown'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/puma-5.6.4/lib/puma/request.rb:76:in `handle_request'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/puma-5.6.4/lib/puma/server.rb:441:in `process_client'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/puma-5.6.4/lib/puma/thread_pool.rb:147:in `block in spawn_thread'"
 "/Users/michaelscrivo/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/logging-2.3.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'"

mscrivo avatar May 26 '22 13:05 mscrivo

These are the parts that are interesting:

"gems/sinatra-2.2.0/lib/sinatra/base.rb:218:in `call'"
"gems/ddtrace-1.0.0/lib/datadog/tracing/contrib/rack/middlewares.rb:84:in `call'"
"gems/sinatra-2.2.0/lib/sinatra/base.rb:1992:in `call'"
"gems/sinatra-2.2.0/lib/sinatra/base.rb:1552:in `block in call'"
...
"gems/sinatra-2.2.0/lib/sinatra/base.rb:218:in `call'"
"gems/ddtrace-1.0.0/lib/datadog/tracing/contrib/rack/middlewares.rb:84:in `call'"
"gems/sinatra-2.2.0/lib/sinatra/base.rb:1992:in `call'"
"gems/rack-parser-0.7.0/lib/rack/parser.rb:24:in `call'"
...
"gems/sinatra-2.2.0/lib/sinatra/base.rb:218:in `call'"
"gems/ddtrace-1.0.0/lib/datadog/tracing/contrib/rack/middlewares.rb:84:in `call'"
"gems/sinatra-2.2.0/lib/sinatra/base.rb:1992:in `call'"
"gems/puma-5.6.4/lib/puma/commonlogger.rb:40:in `call'"

Clearly the Rack trace middleware is being invoked at least 3 times, whereas it probably should only be invoked once (at the beginning of the Rack stack). We made some changes to our Sinatra instrumentation to support our new AppSec feature, so this is likely related.

I will attempt to recreate this on our end by setting up a new Sinatra app. Can you share your configuration, relevant structure of your Sinatra app? So I can create a replica to more thoroughly debug this? The more code/detail you can provide me, the more accurate the model, the more likely we can solve this. Thanks!

delner avatar May 26 '22 14:05 delner

Sure .. so as you can see, we run the app with Puma, the puma config is pretty standard, it just calls rackup(app.ru) and app.ru looks like this:

# lots of stuff gets loaded here, including the datadog config (which I've shared above)
require_relative '../app'

use Datadog::Contrib::Rack::TraceMiddleware

run Apps::Web.new

Apps::Web looks roughly like this:

module Apps
  class Web < Base
    configure do
      set :protection

      use Rack::Session::Cookie, COOKIE_OPTIONS.dup
      use Rack::Parser
    end

    include Sinatra::ContentFor
    use SecureHttpHeaders::Web
    
    use Sinatra::Router do
      # mount all controllers
    end
  end
end

That sinatra base class looks roughly like this:

  module Apps
    class Base < Sinatra::Base
      use RequestStore::Middleware

      configure do
        set :root, File.expand_path('..', __dir__)
        use Rack::Parser
      end

      register Sinatra::Hashfix
    end
  end

with this exercise, I'm noticing that we call use Rack::Parser twice, so let me try removing one of those and see how things look.

mscrivo avatar May 26 '22 14:05 mscrivo

Removing the extra Rack::Parser seems like it removed one of them maybe? Still doesn't seem to be anywhere near as clean as with 0.54

image

Also upgraded to the just released 1.1.0

mscrivo avatar May 26 '22 15:05 mscrivo

The code you shared will be helpful. Thank you.

Trace shared doesn't look any different than the original?

Looking at the stack trace from before, it looked like the instrumentation was possibly injecting into Sinatra's Wrapper, which is likely wrapping the Rack::Parser. So something (Sinatra instrumentation) is probably injecting our trace middleware too many times. We should be able to make this trace much cleaner.

I wouldn't expect this to be fixed in 1.1.0 yet.

delner avatar May 26 '22 16:05 delner

Any movement on this? We'd really like to upgrade from 0.54

mscrivo avatar Sep 15 '22 14:09 mscrivo

@mscrivo I believe we did some work on this. Let me check in with @TonyCTHsu: he might know.

delner avatar Oct 20 '22 14:10 delner

@mscrivo I believe we did some work on this. Let me check in with @TonyCTHsu: he might know.

Thanks. Still an issue as of 1.5.0

mscrivo avatar Oct 20 '22 17:10 mscrivo

Hi @mscrivo , sorry its been a while.

From what I learned so far is that rack is generating nested spans from Sinatra. Although this is technically correct for Sinatra, the nested spans seem to be a noise and not so useful.

I have a PR I believe could improve the experience by squashing those nested spans (rack.request and sinatra.request). In addition, it simplifies instrumentation registration, no longer need to register tracer. Currently, I am collecting feedback from our Application Security team to see if the changes would break their implementation(sorry for the wait...).

Would you be willing to try out our pre-release gem to confirm whether such approach improves your experience and the flamegraph looks like something you would find useful?

source 'http://gems.datadoghq.com/prerelease-v2' do
  gem 'ddtrace', '1.5.0.feature.sinatra.rack.279536'
end

This would help me understand if I am heading toward to right direction of solving this. Thanks

TonyCTHsu avatar Oct 21 '22 10:10 TonyCTHsu

Thank you @TonyCTHsu .. I can definitely try that out. Will do as soon as I can and let you know how it looks.

mscrivo avatar Oct 21 '22 14:10 mscrivo

@TonyCTHsu had a chance to try this out, it's looking great! pretty much like it did with 0.54, which makes me question whether I deployed my test branch properly ;)

image

Thanks so much for your work on this!

mscrivo avatar Oct 21 '22 19:10 mscrivo

@mscrivo Thanks for the confirmation! I will try to make it in the next release.

TonyCTHsu avatar Oct 26 '22 10:10 TonyCTHsu

👋 @mscrivo 1.6.0 has just released! Give it a try!

TonyCTHsu avatar Nov 15 '22 19:11 TonyCTHsu

looking good so far @TonyCTHsu. Thanks again for all your work on this

mscrivo avatar Nov 16 '22 15:11 mscrivo