Merge pull request #25 from instana/issue_25

For custom traces, the gem should report using the SDK API for spans

lib/instana/agent.rb

@@ -397,7 +397,7 @@ def make_host_agent_request(req)
       Net::HTTP.start(req.uri.hostname, req.uri.port, :open_timeout => 1, :read_timeout => 1) do |http|
         response = http.request(req)
       end
-      ::Instana.logger.agent_comm "#{req.method} Req -> -body-: #{req.uri} -> -#{req.body}- Resp -> body:#{response} -> -#{response.body}-"
+      ::Instana.logger.agent_comm "#{req.method}->#{req.uri} body:(#{req.body}) Response:#{response} body:(#{response.body})"
       response
     rescue Errno::ECONNREFUSED
       return nil

lib/instana/tracing/span.rb

@@ -33,5 +33,9 @@ def key?(k)
     def raw
       @data
     end
+
+    def custom?
+      @data[:n] == :sdk
+    end
   end
 end

lib/instana/tracing/trace.rb

@@ -1,5 +1,7 @@
 module Instana
   class Trace
+    REGISTERED_SPANS = [ :rack, :'net-http' ]
+
     # @return [Integer] the ID for this trace
     attr_reader :id
 
@@ -31,14 +33,20 @@ def initialize(name, kvs = {}, incoming_context = {})
       # This is a new trace so open the first span with the proper
       # root span IDs.
       @current_span = Span.new({
-        :s => @id,      # Span ID
-        :n => name,     # Span name
-        :ts => ts_now,  # Timestamp
-        :ta => :ruby,   # Agent
-        :data => kvs,   # Data
+        :s => @id,         # Span ID
+        :ts => ts_now,     # Timestamp
+        :ta => :ruby,      # Agent
         :f => { :e => ::Instana.agent.report_pid, :h => ::Instana.agent.agent_uuid } # Entity Source
       })
 
+      # Check for custom tracing
+      if !REGISTERED_SPANS.include?(name.to_sym)
+        configure_custom_span(name, kvs)
+      else
+        @current_span[:n]    = name.to_sym
+        @current_span[:data] = kvs
+      end
+
       # Handle potential incoming context
       if incoming_context.empty?
         # No incoming context. Set trace ID the same
@@ -65,23 +73,38 @@ def new_span(name, kvs)
         :s => generate_id,          # Span ID
         :t => @id,                  # Trace ID (same as :s for root span)
         :p => @current_span[:s],    # Parent ID
-        :n => name,                 # Span name
         :ts => ts_now,              # Timestamp
         :ta => :ruby,               # Agent
-        :data => kvs,               # Data
         :f => { :e => Process.pid, :h => :agent_id } # Entity Source
       })
+
       new_span.parent = @current_span
       @spans.add(new_span)
       @current_span = new_span
+
+      # Check for custom tracing
+      if !REGISTERED_SPANS.include?(name.to_sym)
+        configure_custom_span(name, kvs)
+      else
+        @current_span[:n]    = name.to_sym
+        @current_span[:data] = kvs
+      end
     end
 
     # Add KVs to the current span
     #
     # @param kvs [Hash] list of key values to be reported in the span
     #
     def add_info(kvs)
-      @current_span[:data].merge!(kvs)
+      if @current_span.custom?
+        if @current_span[:data][:sdk].key?(:custom)
+          @current_span[:data][:sdk][:custom].merge!(kvs)
+        else
+          @current_span[:data][:sdk][:custom] = kvs
+        end
+      else
+        @current_span[:data].merge!(kvs)
+      end
     end
 
     # Log an error into the current span
@@ -90,6 +113,24 @@ def add_info(kvs)
     #
     def add_error(e)
       @current_span[:error] = true
+
+      if @current_span.key?(:ec)
+        @current_span[:ec] = @current_span[:ec] + 1
+      else
+        @current_span[:ec] = 1
+      end
+
+      #if e.backtrace && e.backtrace.is_a?(Array)
+      #  @current_span[:stack] = []
+      #  e.backtrace.each do |x|
+      #    file, line, method = x.split(':')
+      #    @current_span[:stack] << {
+      #      :f => file,
+      #      :n => line
+      #      #:m => method
+      #    }
+      #  end
+      #end
     end
 
     # Close out the current span and set the parent as
@@ -133,7 +174,9 @@ def valid?
     def has_error?
       @spans.each do |s|
         if s.key?(:error)
-          return s[:error]
+          if s[:error] == true
+            return true
+          end
         end
       end
       false
@@ -150,6 +193,26 @@ def current_span_id
 
     private
 
+    # Configure @current_span to be a custom span per the
+    # SDK generic span type.
+    #
+    def configure_custom_span(name, kvs = {})
+      @current_span[:n] = :sdk
+      @current_span[:data] = { :sdk => { :name => name.to_sym } }
+      @current_span[:data][:sdk][:type] = kvs.key?(:type) ? kvs[:type] : :local
+
+      if kvs.key?(:arguments)
+        @current_span[:data][:sdk][:arguments] = kvs[:arguments]
+      end
+
+      if kvs.key?(:return)
+        @current_span[:data][:sdk][:return] = kvs[:return]
+      end
+      @current_span[:data][:sdk][:custom] = kvs unless kvs.empty?
+      #@current_span[:data][:sdk][:custom][:tags] = {}
+      #@current_span[:data][:sdk][:custom][:logs] = {}
+    end
+
     # Get the current time in milliseconds
     #
     # @return [Integer] the current time in milliseconds

test/instrumentation/net-http_test.rb

@@ -29,7 +29,7 @@ def test_basic_get
     second_span = spans[1]
 
     # Span name validation
-    assert_equal 'net-http-test', first_span[:n]
+    assert_equal :sdk, first_span[:n]
     assert_equal :'net-http', second_span[:n]
 
     # first_span is the parent of second_span

test/tracing/custom_test.rb

@@ -0,0 +1,146 @@
+require 'test_helper'
+
+class CustomTracingTest < Minitest::Test
+  def test_custom_tracing
+    ::Instana.processor.clear!
+
+    assert_equal false, ::Instana.tracer.tracing?
+    # Start tracing
+    ::Instana.tracer.log_start_or_continue(:custom_trace, {:one => 1})
+    assert_equal true, ::Instana.tracer.tracing?
+    ::Instana.tracer.log_info({:info_logged => 1})
+    # End tracing
+    ::Instana.tracer.log_end(:rack, {:close_one => 1})
+    assert_equal false, ::Instana.tracer.tracing?
+
+    traces = ::Instana.processor.queued_traces
+    assert_equal 1, traces.count
+    t = traces.first
+    assert_equal 1, t.spans.size
+    assert t.valid?
+
+    first_span = t.spans.first
+    assert_equal :sdk, first_span[:n]
+
+    assert first_span.key?(:data)
+    assert first_span[:data].key?(:sdk)
+    assert first_span[:data][:sdk].key?(:custom)
+    assert_equal :custom_trace, first_span[:data][:sdk][:name]
+    assert_equal 1, first_span[:data][:sdk][:custom][:one]
+    assert_equal :ruby, first_span[:ta]
+
+    assert first_span.key?(:f)
+    assert first_span[:f].key?(:e)
+    assert first_span[:f].key?(:h)
+    assert_equal ::Instana.agent.agent_uuid, first_span[:f][:h]
+  end
+
+  def test_custom_tracing_with_args
+    ::Instana.processor.clear!
+
+    assert_equal false, ::Instana.tracer.tracing?
+
+    # Start tracing
+    ::Instana.tracer.log_start_or_continue(:rack, :on_trace_start => 1)
+    assert_equal true, ::Instana.tracer.tracing?
+
+    kvs = {}
+    kvs[:on_entry_kv] = 1
+    kvs[:arguments] = [[1,2,3], "test_arg", :ok]
+    kvs[:return] = true
+
+    ::Instana.tracer.log_entry(:custom_span, kvs)
+    ::Instana.tracer.log_info({:on_info_kv => 1})
+    ::Instana.tracer.log_exit(:custom_span, :on_exit_kv => 1)
+
+    # End tracing
+    ::Instana.tracer.log_end(:rack, {:on_trace_end => 1})
+    assert_equal false, ::Instana.tracer.tracing?
+
+    traces = ::Instana.processor.queued_traces
+    assert_equal 1, traces.count
+    t = traces.first
+    assert_equal 2, t.spans.size
+    assert t.valid?
+
+    first_span, second_span = t.spans.to_a
+
+    assert_equal :rack, first_span[:n]
+    assert first_span.key?(:data)
+    assert first_span[:data].key?(:on_trace_start)
+    assert_equal 1, first_span[:data][:on_trace_start]
+    assert first_span[:data].key?(:on_trace_end)
+    assert_equal 1, first_span[:data][:on_trace_end]
+
+    assert_equal :sdk, second_span[:n]
+    assert second_span.key?(:data)
+    assert second_span[:data].key?(:sdk)
+    assert second_span[:data][:sdk].key?(:custom)
+    assert :custom_span, second_span[:data][:sdk][:name]
+    assert :unknown, second_span[:data][:sdk][:type]
+    assert [[1, 2, 3], "test_arg", :ok], second_span[:data][:sdk][:arguments]
+    assert true, second_span[:data][:sdk][:return]
+    assert_equal 1, second_span[:data][:sdk][:custom][:on_entry_kv]
+    assert_equal 1, second_span[:data][:sdk][:custom][:on_info_kv]
+    assert_equal 1, second_span[:data][:sdk][:custom][:on_exit_kv]
+  end
+
+  def test_custom_tracing_with_error
+    ::Instana.processor.clear!
+
+    assert_equal false, ::Instana.tracer.tracing?
+
+    # Start tracing
+    ::Instana.tracer.log_start_or_continue(:rack, :on_trace_start => 1)
+    assert_equal true, ::Instana.tracer.tracing?
+
+    begin
+      kvs = {}
+      kvs[:on_entry_kv] = 1
+      kvs[:arguments] = [[1,2,3], "test_arg", :ok]
+      kvs[:return] = true
+
+      ::Instana.tracer.log_entry(:custom_span, kvs)
+      raise "custom tracing error.  This is only a test"
+      ::Instana.tracer.log_info({:on_info_kv => 1})
+    rescue => e
+      ::Instana.tracer.log_error(e)
+    ensure
+      ::Instana.tracer.log_exit(:custom_span, :on_exit_kv => 1)
+    end
+    ::Instana.tracer.log_end(:rack, {:on_trace_end => 1})
+    assert_equal false, ::Instana.tracer.tracing?
+
+    traces = ::Instana.processor.queued_traces
+    assert_equal 1, traces.count
+    t = traces.first
+    assert_equal 2, t.spans.size
+    assert t.valid?
+
+    first_span, second_span = t.spans.to_a
+
+    assert_equal :rack, first_span[:n]
+    assert first_span.key?(:data)
+    assert first_span[:data].key?(:on_trace_start)
+    assert_equal 1, first_span[:data][:on_trace_start]
+    assert first_span[:data].key?(:on_trace_end)
+    assert_equal 1, first_span[:data][:on_trace_end]
+
+    assert_equal :sdk, second_span[:n]
+    assert second_span.key?(:data)
+    assert second_span[:data].key?(:sdk)
+    assert second_span[:data][:sdk].key?(:custom)
+    assert :custom_span, second_span[:data][:sdk][:name]
+    assert :unknown, second_span[:data][:sdk][:type]
+    assert [[1, 2, 3], "test_arg", :ok], second_span[:data][:sdk][:arguments]
+    assert true, second_span[:data][:sdk][:return]
+    assert_equal 1, second_span[:data][:sdk][:custom][:on_entry_kv]
+    assert !second_span[:data][:sdk][:custom].key?(:on_info_kv)
+    assert_equal 1, second_span[:data][:sdk][:custom][:on_exit_kv]
+
+    # Check the error
+    assert_equal true, second_span[:error]
+    assert_equal 1, second_span[:ec]
+  end
+
+end

test/tracing/trace_test.rb

@@ -23,8 +23,18 @@ def test_max_value_of_generated_id
 
     # Max is the maximum value for a Java signed long
     max_value = 9223372036854775807
-    100.times do
+    1000.times do
       assert t.send(:generate_id) <= max_value
     end
   end
+
+  def test_min_value_of_generated_id
+    t = ::Instana::Trace.new(:test_id)
+
+    # Max is the maximum value for a Java signed long
+    max_value = -9223372036854775808
+    1000.times do
+      assert t.send(:generate_id) >= max_value
+    end
+  end
 end