Dd-trace-rb: Add an option to error if an internal integration is the root span

[tjwp]

We recently had an issue with one of our Rails applications after upgrading to v0.35.2 from v0.34.2. After the upgrade we stopped seeing any APM data for the application. There is some oddness in the initialization of that application, so we _thought_ we'd fixed the ddtrace configuration and redeployed the application.

Although we thought we were getting all the trace data for the application, we later found out that one of the integrations (graphql) was no longer creating spans that were nesting with our other spans from the service. They were reported completely separately.

What would be a good way to detect these kinds of configuration issues? One thought that I had was to add a setting named-like allow_root_span to integrations to specify whether they should always be nested under another span. This might default to true, but for "internal" integrations like activerecord, postgres, graphql, etc within a Rails application I would configure them with allow_root_span=false. And if allow_root_span=false and an attempt is made to start a span as the root span, then raise an error.

The benefit here would be quickly catching that the distributed tracing is broken. As it was we generated a couple of days of data where we were unable to trace all the way through the application.

[delner]

Hmmmm, this might require a bit more thought on our end. @tjwp Just so I understand the full context of what happened, can you explain how the trace structure changed to cause this to happen?

My first instinct says this shouldn't have happened when upgrading between those two versions, unless we communicated specifically that we were making some significant change to how instrumentation functions. There might be something in the GraphQL instrumentation that needs to be fixed that was overlooked in the last release (most of that instrumentation doesn't exist in this repo, but in GraphQL itself, so its possible we missed something.)

Primarily, I think it'd be best that we prevent this kind of unwanted change in behavior/bug(?) from happening in the first place, as prevention is better than a cure.

Secondarily, as a matter of detecting this kind of problem, what code quality control measures we build and where we build them is important. I don't want users to be encumbered with the responsibility of adding safety checks if this is something we can adequately control for out-of-the-box in ddtrace. I think if I can learn a bit more about the nature of how this problem manifested, it might tell us a lot about what and where we change:

• Is this a product of a bug which ddtrace produced? Maybe we need to consider adding coverage to the ddtrace CI test suite.
• Is this "intended behavior" but a configuration issue within the domain of the user's application? Maybe we should provide mechanisms to unit/integration test traces in their own CI test suite, or validate configuration settings.
• Maybe allow_root_span? Maybe something else entirely?

While we investigate this and learn more about out, for what it's worth, you might be able to build some detection mechanism for this specific case today using the processing pipeline. Presumably you could use it to check traces to see if an unexpected span ends up at the root of a trace, and if it does, log a warning, metric or whatever alert you see fit.

[tjwp]

@delner Thank you for the detailed response! I will look into the processing pipeline.

I will also attempt to gather more information about what went wrong and report back.

[tjwp]

@delner I did some more digging into this. I think your instinct may be correct that this is specifically related to the GraphQL instrumentation.

I wasn't entirely sure what to look at but I'll describe what I focused on.

v0.34.2

Everything was working for us with this version. Datadog.tracer is the same as the tracer used in by the GraphQL instrumentation:

> Datadog.tracer.object_id
=> 47093656444080
> Marketplace::Schema.plugins[1][1][:tracer].object_id
=> 47093656444080

> Datadog.tracer.writer.transport.apis["v0.4"].adapter
=> #<Datadog::Transport::HTTP::Adapters::Net:0x000055a9b1670ba0 @hostname="datadog-trace.kube-system", @port=8126, @timeout=1>

Marketplace::Schema is one of our the instrumented GraphQL schemas. One tracer is used and the configuration looks correct.

v0.35.1

With this version, I think we hit https://github.com/DataDog/dd-trace-rb/issues/1032 so we were not seeing any traces reported where we'd expect.

> Datadog.tracer.object_id
=> 47389317176080
> Marketplace::Schema.plugins[1][1][:tracer].object_id
=> 47389315492840

> Datadog.tracer.writer.transport.apis["v0.4"].adapter
=> #<Datadog::Transport::HTTP::Adapters::Net:0x000056335ed1f460 @hostname="datadog-trace.kube-system", @port=8126, @timeout=1>
> Marketplace::Schema.plugins[1][1][:tracer].writer.transport.apis["v0.4"].adapter
=> #<Datadog::Transport::HTTP::Adapters::Net:0x000056335ea1d1e0 @hostname="127.0.0.1", @port=8126, @timeout=1>

Different tracers are being used, and the GraphQL instrumentation is no longer picking up the configuration for our agent hostname.

There were no changes in how we configure the application.

v0.35.2

> Datadog.tracer.object_id
=> 47243898595320
> Datadog.configuration[:graphql][:tracer].object_id
=> 47243898595320
> Marketplace::Schema.plugins[1][1][:tracer].object_id
=> 47243897380040

> Datadog.tracer.writer.transport.apis["v0.4"].adapter
=> #<Datadog::Transport::HTTP::Adapters::Net:0x000055efa797b200 @hostname="datadog-trace.kube-system", @port=8126, @timeout=1>

> Marketplace::Schema.plugins[1][1][:tracer].writer.transport.apis["v0.4"].adapter
=> #<Datadog::Transport::HTTP::Adapters::Net:0x000055efa7712a18 @hostname="127.0.0.1", @port=8126, @timeout=1>

Results here look similar to v0.35.1, though tracing for the rest of the application was working again. Here I captured that the tracer configured for the GraphQL integration is not the tracer used by the integration. Also, that tracer for the integration is not picking up the correct configuration.

v0.35.2 other configurations

I played around with some changes in application configuration (moving the configuration of the GraphQL integration to a Rails after_initialize block or configuring in an after_initialize with Datadog.tracer).

Using after_initialize did allow the GraphQL instrumentation to pick up the correct hostname, but it continued to use a separate tracer from the rest of the application.

I'm guessing that the use of the separate tracer instance by the GraphQL instrumentation is the reason that the GraphQL spans are not connected to the rest of the trace.

[marcotc]

Thank you @tjwp for such a detailed write up! Super helpful!

I tried to get a different Schema.plugins[1][1][:tracer] from Datadog.tracer but couldn't do it: all my attempts turn out having the same tracer instance.

I found out that we don't have tests for the manual GraphQL instrumentation so I suspected that was our culprit. I wrote tests for this case but I still can't get the tracer to mismatch: https://github.com/DataDog/dd-trace-rb/pull/1052

Could you provide us your relevant ddtrace configuration (Datadog.configure) and a basic version of your schema definition so we can try to reproduced it on our side?

[delner]

I'm guessing that the use of the separate tracer instance by the GraphQL instrumentation is the reason that the GraphQL spans are not connected to the rest of the trace.

@tjwp It's almost certainly really bad that you're getting multiple tracer instances like that, and has been a recent issue with integrations starting with 0.35.0. I think if we focus on fixing that first, we'll have decent odds at fixing the problem.

[tjwp]

Could you provide us your relevant ddtrace configuration (Datadog.configure) and a basic version of your schema definition so we can try to reproduced it on our side?

@marcotc Here comes another info dump!

We have a gem that standardizes the configuration in various services. Here's a slightly simplified version of the Railtie:

module EzcaterAPM
  class Railtie < ::Rails::Railtie
    DEFAULT_SAMPLE_RATE = 0.05

    initializer "ezcater_apm.datadog" do
      if ::Rails.env.production? || ::Rails.env.staging?
        Datadog.configure do |config|
          service_name = ENV["KUBE_APPLICATION"]
          tags = { } # omit to make this example shorter :)

          config.tracer hostname: "datadog-trace.kube-system",
                        env: ENV["KUBE_ENVIRONMENT"],
                        tags: tags

          ((::Rails.configuration.x.ddtrace.integrations.presence || []) | [:rake]).each do |integration|
            add_integration(integration, config, service_name)
          end

          if defined?(::Sidekiq)
            # The redis integration auto-patches but this ensures the name is set based on the service.
            add_integration(:redis, config, service_name, analytics_enabled: false)
            add_integration(:sidekiq, config, service_name,
                            tag_args: true,
                            client_service_name: "#{service_name}-sidekiq-client")
          end

          add_integration(:racecar, config, service_name) if defined?(::Racecar)
          add_integration(:excon, config, service_name) if defined?(::Excon)
          add_integration(:elasticsearch, config, service_name) if defined?(::Elasticsearch::Transport)
          add_integration(:rest_client, config, service_name) if defined?(::RestClient)

          if defined?(::Faraday)
            add_integration(:faraday, config, service_name)
            require "ezcater_apm/faraday_connection_options"
          end

          config.use :rails,
                     service_name: service_name,
                     analytics_enabled: true,
                     analytics_sample_rate: DEFAULT_SAMPLE_RATE

          Datadog.configuration[:active_record][:orm_service_name] = "#{service_name}-active_record"
          Datadog.configuration[:active_record][:analytics_enabled] = true
          Datadog.configuration[:active_record][:analytics_sample_rate] = DEFAULT_SAMPLE_RATE
          Datadog.configuration[:rack][:request_queuing] = true
          Datadog.configuration[:rack][:web_service_name] = "#{service_name}-web-server"
        end
      end
    end

    def add_integration(integration, config, service_name, options = {})
      config.use integration,
                 {
                   analytics_enabled: true,
                   analytics_sample_rate: DEFAULT_SAMPLE_RATE,
                   service_name: "#{service_name}-#{integration}",
                 }.merge!(options)
    end
  end
end

You'll notice that we don't configure the GraphQL integration here. That is because it requires the schemas. So we do that in an initializer in Rails services:

if Rails.env.production? || Rails.env.staging?
  Datadog.configure do |config|
    config.use :graphql,
               analytics_enabled: true,
               analytics_sample_rate: 0.05,
               service_name: "#{ENV['KUBE_APPLICATION']}-graphql",
               schemas: [Admin::Schema, Management::Schema, Marketplace::Schema]
  end
end

I've ensured that this initializer runs after the initializer from the Railtie above, but we still have the issue. In one of my experiments I also passed tracer: Datadog.tracer as an option for the GraphQL integration, but that did not fix the issue. You could see the shared tracer in Datadog.configuration[:graphql][:tracer] but the plugin in the schema class still had a separate tracer instance.

I'm skipping including the GraphQL schema here because we are seeing the same issue in multiple Rails services that have GraphQL APIs and upgraded to v0.35.2. They are all configured in a similar way and none use the "manual" configuration within the schema class.

Hope that helps!

[tjwp]

I tested with v0.36.0 this morning and it has fixed the issue that we had with v0.35.2 where the GraphQL tracer was getting a separate tracer instance.

v0.36.0 did create a new issue for us. We do some patching of Faraday (code below) and with v0.36.0 we got an error that Datadog::Contrib::Faraday::Middleware was a missing constant. It was an easy fix to require that file, and we probably should have already, but I thought I'd point it out.

For reference the patch:

# See https://github.com/lostisland/faraday/issues/946#issuecomment-500607890
module FaradayConnectionOptions
  Middleware = ::Datadog::Contrib::Faraday::Middleware

  def self.prepend_middleware(builder)
    builder.insert(0, Middleware) if builder.handlers.none? { |h| h.klass == Middleware }
  end

  def new_builder(block)
    super.tap do |builder|
      FaradayConnectionOptions.prepend_middleware(builder)
    end
  end
end

FaradayConnectionOptions.prepend_middleware(::Faraday.default_connection.builder)

::Faraday::ConnectionOptions.prepend(FaradayConnectionOptions)

Some of this may no longer be necessary, but it was updated recently because we found that requests using the default connection were not patched.

Feel free to close this issue. I'll keep looking into the processing pipeline to catch other issues in the future, and do additional processing on traces.

[delner]

@tjwp Glad to hear the GraphQL issue is resolved; this likely has to do with us now lazy-patching integrations in 0.36.0 (#1037) such that it doesn't eagerly initialize the tracer that causes the issue.

Looks like a side effect of that is it also lazy loads require 'ddtrace/contrib/faraday/middleware' hence the error you're seeing in your patch.

Going to close this then, since it seems like everything is resolved. Please feel free to let us know if you have any other issues.

[marcotc]

Hey @tjwp, I found a gap in our auto instrumentation for Faraday: https://github.com/DataDog/dd-trace-rb/pull/1057
Let me know if you are using the Faraday default connection (e.g. Faraday.get(...)), which this PR would solve.
If you are actually creating new connection objects (e.g. Faraday.new), then we can open a new issue to track this lack of auto instrumentation, as I wasn't able to reproduce it for that case:

require 'ddtrace'
require 'faraday'

Datadog.configure do |c|
  c.diagnostics.debug = true
  c.use :faraday
end

Faraday.new('http://sushi.com').get('/nigiri/sake.json')

properly creates traces (simplified output from the snippet above):

 Name: faraday.request
Span ID: 7643919869515405881
Parent ID: 0
Trace ID: 4404742773229749146
Type: http
Service: faraday
Resource: GET
Tags: [
   http.url => /nigiri/sake.json,
   http.method => GET,
   out.host => sushi.com,
   http.status_code => 301]

[tjwp]

@marcotc Thanks, we do have some use of the default connection. We worked around the issue with the patch that I shared above (https://github.com/DataDog/dd-trace-rb/issues/1048#issuecomment-635304269) where we directly prepend the middleware for the default connection.

For the other use cases (Faraday.new and Faraday.new + block), I don't think we have an issue anymore but we have had the patch in place for a while, it does not conflict with the auto-instrumentation, and I haven't had a chance to test removing it.

[tjwp]

An update on v0.36.0: I reverted back to v0.34.2 again for our main application. Though v0.36.0 fixed the issue with GraphQL that we'd had with v0.35.x, the spans for Faraday and Redis were disconnected. Spans were still being reported for those integrations but disconnected from the rest of the service, so I'm guessing they were getting their own tracer instance.