Merge branch 'master' of https://github.com/DataDog/dd-trace-rb into …

…sequel-instrumentation-fail-for-sql-expression

lib/ddtrace/buffer.rb

@@ -18,30 +18,32 @@ def initialize
     end
 
     def measure_accept(trace)
-      @buffer_spans += trace.length
       @buffer_accepted += 1
       @buffer_accepted_lengths += trace.length
+
+      @buffer_spans += trace.length
     rescue StandardError => e
       Datadog.logger.debug("Failed to measure queue accept. Cause: #{e.message} Source: #{e.backtrace.first}")
     end
 
     def measure_drop(trace)
       @buffer_dropped += 1
+
       @buffer_spans -= trace.length
-      @buffer_accepted_lengths -= trace.length
     rescue StandardError => e
       Datadog.logger.debug("Failed to measure queue drop. Cause: #{e.message} Source: #{e.backtrace.first}")
     end
 
     def measure_pop(traces)
-      # Accepted
+      # Accepted, cumulative totals
       Datadog.health_metrics.queue_accepted(@buffer_accepted)
       Datadog.health_metrics.queue_accepted_lengths(@buffer_accepted_lengths)
 
-      # Dropped
+      # Dropped, cumulative totals
       Datadog.health_metrics.queue_dropped(@buffer_dropped)
+      # TODO: are we missing a +queue_dropped_lengths+ metric?
 
-      # Queue gauges
+      # Queue gauges, current values
       Datadog.health_metrics.queue_max_length(@max_size)
       Datadog.health_metrics.queue_spans(@buffer_spans)
       Datadog.health_metrics.queue_length(traces.length)

lib/ddtrace/configuration/settings.rb

@@ -96,7 +96,6 @@ class Settings
 
       settings :logger do
         option :instance do |o|
-          o.setter { |value, old_value| value.is_a?(::Logger) ? value : old_value }
           o.on_set { |value| set_option(:level, value.level) unless value.nil? }
         end
 

lib/ddtrace/runtime/metrics.rb

@@ -1,3 +1,4 @@
+require 'ddtrace/ext/integration'
 require 'ddtrace/ext/runtime'
 
 require 'ddtrace/metrics'
@@ -25,8 +26,11 @@ def associate_with_span(span)
         # Register service as associated with metrics
         register_service(span.service) unless span.service.nil?
 
-        # Tag span with language and runtime ID for association with metrics
-        span.set_tag(Ext::Runtime::TAG_LANG, Runtime::Identity.lang)
+        # Tag span with language and runtime ID for association with metrics.
+        # We only tag spans that performed internal application work.
+        unless span.get_tag(Datadog::Ext::Integration::TAG_PEER_SERVICE)
+          span.set_tag(Ext::Runtime::TAG_LANG, Runtime::Identity.lang)
+        end
       end
 
       # Associate service with runtime metrics

lib/ddtrace/span.rb

@@ -346,8 +346,8 @@ def to_json(*args)
 
     # Return a human readable version of the span
     def pretty_print(q)
-      start_time = (start_time.to_f * 1e9).to_i rescue '-'
-      end_time = (end_time.to_f * 1e9).to_i rescue '-'
+      start_time = (self.start_time.to_f * 1e9).to_i
+      end_time = (self.end_time.to_f * 1e9).to_i
       q.group 0 do
         q.breakable
         q.text "Name: #{@name}\n"
@@ -360,7 +360,7 @@ def pretty_print(q)
         q.text "Error: #{@status}\n"
         q.text "Start: #{start_time}\n"
         q.text "End: #{end_time}\n"
-        q.text "Duration: #{duration.to_f}\n"
+        q.text "Duration: #{duration.to_f if finished?}\n"
         q.text "Allocations: #{allocations}\n"
         q.group(2, 'Tags: [', "]\n") do
           q.breakable

spec/ddtrace/buffer_spec.rb

@@ -65,19 +65,21 @@ def measure_trace_size(trace)
         expect(output.length).to eq(max_size)
         expect(output).to include(traces.last)
 
+        accepted_spans = traces.inject(0) { |sum, t| sum + t.length }
+
         # A trace will be dropped at random, except the trace
         # that triggered the overflow.
         dropped_traces = traces.reject { |t| output.include?(t) }
 
         expected_traces = traces - dropped_traces
-        expected_spans = expected_traces.inject(0) { |sum, t| sum + t.length }
+        net_spans = expected_traces.inject(0) { |sum, t| sum + t.length }
 
         # Calling #pop produces metrics:
         # Accept events for every #push, and one drop event for overflow
         expect(health_metrics).to have_received(:queue_accepted)
           .with(traces.length)
         expect(health_metrics).to have_received(:queue_accepted_lengths)
-          .with(expected_spans)
+          .with(accepted_spans)
 
         expect(health_metrics).to have_received(:queue_dropped)
           .with(dropped_traces.length)
@@ -86,7 +88,7 @@ def measure_trace_size(trace)
         expect(health_metrics).to have_received(:queue_max_length)
           .with(max_size)
         expect(health_metrics).to have_received(:queue_spans)
-          .with(expected_spans)
+          .with(net_spans)
         expect(health_metrics).to have_received(:queue_length)
           .with(max_size)
       end

spec/ddtrace/configuration/settings_spec.rb

@@ -301,7 +301,14 @@
     end
 
     describe '#instance=' do
-      let(:logger) { Datadog::Logger.new(STDOUT) }
+      let(:logger) do
+        double(:logger,
+               debug: true,
+               info: true,
+               warn: true,
+               error: true,
+               level: true)
+      end
 
       it 'updates the #instance setting' do
         expect { settings.logger.instance = logger }

spec/ddtrace/contrib/rack/configuration_spec.rb

@@ -77,8 +77,7 @@
         expect(queue_span.span_type).to eq('proxy')
         expect(queue_span.service).to eq(Datadog.configuration[:rack][:web_service_name])
         expect(queue_span.start_time.to_i).to eq(queue_time)
-        # Queue span gets tagged for runtime metrics because its a local root span.
-        # TODO: It probably shouldn't get tagged like this in the future; it's not part of the runtime.
+        expect(queue_span.get_tag(Datadog::Ext::Runtime::TAG_LANG)).to be_nil
 
         expect(rack_span.name).to eq('rack.request')
         expect(rack_span.span_type).to eq('web')

spec/ddtrace/contrib/support/tracer_helpers.rb

@@ -50,24 +50,32 @@ def clear_spans!
     RSpec.configure do |config|
       # Capture spans from the global tracer
       config.before(:each) do
-        clear_spans!
+        Datadog.shutdown!
 
-        # The mutex must be eagerly initialized to prevent race conditions on lazy initialization
-        write_lock = Mutex.new
-        allow_any_instance_of(Datadog::Tracer).to receive(:write) do |tracer, trace|
-          tracer.instance_exec do
-            write_lock.synchronize do
-              @spans ||= []
-              @spans << trace
+        # DEV `*_any_instance_of` has concurrency issues when running with parallelism (e.g. JRuby).
+        # DEV Single object `allow` and `expect` work as intended with parallelism.
+        allow(Datadog::Tracer).to receive(:new).and_wrap_original do |method, *args, &block|
+          instance = method.call(*args, &block)
+
+          # The mutex must be eagerly initialized to prevent race conditions on lazy initialization
+          write_lock = Mutex.new
+          allow(instance).to receive(:write) do |trace|
+            instance.instance_exec do
+              write_lock.synchronize do
+                @spans ||= []
+                @spans << trace
+              end
             end
           end
+
+          instance
         end
       end
     end
 
     # Useful for integration testing.
     def use_real_tracer!
-      allow_any_instance_of(Datadog::Tracer).to receive(:write).and_call_original
+      allow(Datadog::Tracer).to receive(:new).and_call_original
     end
   end
 end

spec/ddtrace/runtime/metrics_spec.rb

@@ -24,21 +24,31 @@
 
   describe '#associate_with_span' do
     subject(:associate_with_span) { runtime_metrics.associate_with_span(span) }
-    let(:span) { instance_double(Datadog::Span, service: service) }
+    let(:span) { Datadog::Span.new(nil, 'dummy', service: service) }
     let(:service) { 'parser' }
 
     context 'when enabled' do
       before do
         runtime_metrics.enabled = true
 
-        expect(span).to receive(:set_tag)
-          .with(Datadog::Ext::Runtime::TAG_LANG, Datadog::Runtime::Identity.lang)
-
         associate_with_span
       end
 
-      it 'registers the span\'s service' do
-        expect(runtime_metrics.default_metric_options[:tags]).to include("service:#{service}")
+      context 'with internal span' do
+        it 'registers the span\'s service' do
+          expect(runtime_metrics.default_metric_options[:tags]).to include("service:#{service}")
+          expect(span.get_tag(Datadog::Ext::Runtime::TAG_LANG)).to eq(Datadog::Runtime::Identity.lang)
+        end
+      end
+
+      context 'with external resource span' do
+        let(:span) do
+          super().tap { |s| s.set_tag(Datadog::Ext::Integration::TAG_PEER_SERVICE, 'peer-service-name') }
+        end
+
+        it "doesn't tag as an internal language span" do
+          expect(span.get_tag(Datadog::Ext::Runtime::TAG_LANG)).to be nil
+        end
       end
     end
 

spec/ddtrace/span_spec.rb

@@ -649,4 +649,12 @@
       is_expected.to eq(Hash[span.to_hash.map { |k, v| [k.to_s, v] }])
     end
   end
+
+  describe '#pretty_print' do
+    subject(:pretty_print) { PP.pp(span) }
+
+    it 'output without errors' do
+      expect { pretty_print }.to output.to_stdout
+    end
+  end
 end