From f76a9d0a8773e70b4dcede3f4e120f2d0879a537 Mon Sep 17 00:00:00 2001 From: Michal Granec Date: Mon, 29 Apr 2019 23:12:46 +0200 Subject: [PATCH 1/4] update test tracer to be in line with new opentracer api --- lib/test/scope.rb | 42 ++++++++++ lib/test/scope_manager.rb | 49 ++++++++++++ lib/test/scope_manager/scope_stack.rb | 37 +++++++++ lib/test/span.rb | 23 +++--- lib/test/span_context.rb | 8 ++ lib/test/tracer.rb | 111 ++++++++++++++++++++++---- spec/spec_helper.rb | 1 + spec/test/scope_spec.rb | 20 +++++ spec/test/span_spec.rb | 24 +++++- spec/test/tracer_spec.rb | 42 ++++++++++ test-tracer.gemspec | 2 + 11 files changed, 331 insertions(+), 28 deletions(-) create mode 100644 lib/test/scope.rb create mode 100644 lib/test/scope_manager.rb create mode 100644 lib/test/scope_manager/scope_stack.rb create mode 100644 spec/test/scope_spec.rb diff --git a/lib/test/scope.rb b/lib/test/scope.rb new file mode 100644 index 0000000..e1e6307 --- /dev/null +++ b/lib/test/scope.rb @@ -0,0 +1,42 @@ +# frozen_string_literal: true + +module Test + # Scope represents an OpenTracing Scope + # + # See http://www.opentracing.io for more information. + class Scope + def initialize(span, scope_stack, finish_on_close:) + @span = span + @scope_stack = scope_stack + @finish_on_close = finish_on_close + @closed = false + end + + # Return the Span scoped by this Scope + # + # @return [Span] + attr_reader :span + + def closed? + @closed + end + + # Close scope + # + # Mark the end of the active period for the current thread and Scope, + # updating the ScopeManager#active in the process. + def close + raise "Tried to close already closed span: #{inspect}" if @closed + @closed = true + + @span.finish if @finish_on_close + removed_scope = @scope_stack.pop + + if removed_scope != self # rubocop:disable Style/GuardClause + raise 'Removed non-active scope, ' \ + "removed: #{removed_scope.inspect}, "\ + "expected: #{inspect}" + end + end + end +end diff --git a/lib/test/scope_manager.rb b/lib/test/scope_manager.rb new file mode 100644 index 0000000..b9faf9b --- /dev/null +++ b/lib/test/scope_manager.rb @@ -0,0 +1,49 @@ +# frozen_string_literal: true + +require_relative 'scope_manager/scope_stack' + +module Test + # ScopeManager represents an OpenTracing ScopeManager + # + # See http://www.opentracing.io for more information. + # + # The ScopeManager interface abstracts both the activation of Span instances + # via ScopeManager#activate and access to an active Span/Scope via + # ScopeManager#active + class ScopeManager + def initialize + @scope_stack = ScopeStack.new + end + + # Make a span instance active + # + # @param span [Span] the Span that should become active + # @param finish_on_close [Boolean] whether the Span should automatically be + # finished when Scope#close is called + # @return [Scope] instance to control the end of the active period for the + # Span. It is a programming error to neglect to call Scope#close on the + # returned instance. + def activate(span, finish_on_close: true) + return active if active && active.span == span + scope = Scope.new(span, @scope_stack, finish_on_close: finish_on_close) + @scope_stack.push(scope) + scope + end + + # Return active scope + # + # If there is a non-null Scope, its wrapped Span becomes an implicit parent + # (as Reference#CHILD_OF) of any newly-created Span at + # Tracer#start_active_span or Tracer#start_span time. + # + # @return [Scope] the currently active Scope which can be used to access the + # currently active Span. + def active + @scope_stack.peek + end + + def stack + @scope_stack.stack + end + end +end diff --git a/lib/test/scope_manager/scope_stack.rb b/lib/test/scope_manager/scope_stack.rb new file mode 100644 index 0000000..10a57e5 --- /dev/null +++ b/lib/test/scope_manager/scope_stack.rb @@ -0,0 +1,37 @@ +# frozen_string_literal: true + +module Test + class ScopeManager + # @api private + class ScopeStack + def initialize + # Generate a random identifier to use as the Thread.current key. This is + # needed so that it would be possible to create multiple tracers in one + # thread (mostly useful for testing purposes) + @scope_identifier = IdProvider.generate + end + + def push(scope) + store << scope + end + + def pop + store.pop + end + + def peek + store.last + end + + def stack + Thread.current[@scope_identifier] + end + + private + + def store + Thread.current[@scope_identifier] ||= [] + end + end + end +end \ No newline at end of file diff --git a/lib/test/span.rb b/lib/test/span.rb index 831bed2..cc38fc8 100644 --- a/lib/test/span.rb +++ b/lib/test/span.rb @@ -2,13 +2,13 @@ module Test class Span < OpenTracing::Span class SpanAlreadyFinished < StandardError; end - class LogEntry < Struct.new(:event, :timestamp, :fields); end + class LogEntry < Struct.new(:timestamp, :fields); end include TypeCheck - attr_reader :tracer, :operation_name, :start_time, :end_time, :tags, :logs + attr_reader :tracer, :operation_name, :start_time, :end_time, :tags, :logs, :references - def initialize(tracer:, context:, operation_name:, start_time: Time.now, tags: nil) + def initialize(tracer:, context:, operation_name:, start_time: Time.now, references: [], tags: nil) Type! tracer, ::Test::Tracer Type! context, ::Test::SpanContext Type! operation_name, String @@ -20,6 +20,7 @@ def initialize(tracer:, context:, operation_name:, start_time: Time.now, tags: n @operation_name = operation_name @tags = tags || {} @logs = [] + @references = references @start_time = start_time @end_time = nil @in_progress = true @@ -59,21 +60,25 @@ def set_baggage_item(key, value) Type! value, String, NilClass ensure_in_progress! - @context.baggage[key] = value.to_s + @context.set_baggage_item(key, value) self end def get_baggage_item(key) Type! key, String - @context.baggage[key] + @context.get_baggage_item(key) end - def log(event: nil, timestamp: Time.now, **fields) - Type! event, String, NilClass - Type! timestamp, Time + def log(**args) + Type! args, Hash, NilClass ensure_in_progress! + log_kv(**args) + end - @logs << LogEntry.new(event, timestamp, fields) + def log_kv(timestamp: Time.now, **fields) + Type! timestamp, Time + ensure_in_progress! + @logs << LogEntry.new(timestamp, fields) end def finish(end_time: Time.now) diff --git a/lib/test/span_context.rb b/lib/test/span_context.rb index f86af02..313fb05 100644 --- a/lib/test/span_context.rb +++ b/lib/test/span_context.rb @@ -32,6 +32,14 @@ def initialize(trace_id:, span_id:, parent_span_id: nil, baggage: {}) @baggage = baggage end + def set_baggage_item(key, value) + @baggage[key.to_s] = value.to_s + end + + def get_baggage_item(key) + @baggage[key.to_s] + end + def to_s "SpanContext(trace_id=#{trace_id}, span_id=#{span_id}, parent_span_id=#{parent_span_id}, baggage=#{baggage})" end diff --git a/lib/test/tracer.rb b/lib/test/tracer.rb index 22cad85..4c78faf 100644 --- a/lib/test/tracer.rb +++ b/lib/test/tracer.rb @@ -3,6 +3,8 @@ require 'test/type_check' require 'test/id_provider' require 'test/span_context' +require 'test/scope_manager' +require 'test/scope' require 'test/span' require 'test/propagation' require 'test/wrapped' @@ -12,6 +14,7 @@ class Tracer < OpenTracing::Tracer include TypeCheck attr_reader :spans, :finished_spans + attr_reader :scope_manager attr_reader :injectors, :extractors attr_accessor :wrapped_span_extractor @@ -19,7 +22,6 @@ class Tracer < OpenTracing::Tracer attr_accessor :logger - def initialize(logger: nil) @logger = logger @@ -35,6 +37,7 @@ def initialize(logger: nil) default_extractor = Wrapped::DefaultExtractor.new @wrapped_span_extractor = default_extractor @wrapped_span_context_extractor = default_extractor + @scope_manager = ScopeManager.new end def register_injector(format, injector) @@ -59,23 +62,70 @@ def register_codec(format, codec) self end - # OT complaiant - def start_span(operation_name, child_of: nil, references: nil, start_time: Time.now, tags: nil) - child_of = extract_span(child_of) || extract_span_context(child_of) + # OT compliant + def start_active_span(operation_name, + child_of: nil, + references: nil, + start_time: Time.now, + tags: {}, + ignore_active_scope: false, + finish_on_close: true, + **) + span = start_span( + operation_name, + child_of: child_of, + references: references, + start_time: start_time, + tags: tags, + ignore_active_scope: ignore_active_scope + ) + scope = @scope_manager.activate(span, finish_on_close: finish_on_close) + + if block_given? + begin + yield scope + ensure + scope.close + end + else + scope + end + end - parent_context = child_of && child_of.respond_to?(:context) ? child_of.context : child_of - new_context = parent_context ? ::Test::SpanContext.child_of(parent_context) : ::Test::SpanContext.root + # OT compliant + def start_span(operation_name, + child_of: nil, + references: nil, + start_time: Time.now, + tags: nil, + ignore_active_scope: false, + **) + + new_context = prepare_span_context( + child_of: child_of, + references: references, + ignore_active_scope: ignore_active_scope + ) new_span = Span.new(tracer: self, operation_name: operation_name, context: new_context, start_time: start_time, + references: references, tags: tags) @spans << new_span - new_span + if block_given? + begin + yield(new_span) + ensure + new_span.finish + end + else + new_span + end end - # OT complaiant + # OT compliant def inject(span_context, format, carrier) NotNull! format span_context = extract_span_context(span_context) @@ -90,7 +140,7 @@ def inject(span_context, format, carrier) end end - # OT complaiant + # OT compliant def extract(format, carrier) NotNull! format NotNull! carrier @@ -110,17 +160,46 @@ def clear self end - private + private + + def prepare_span_context(child_of:, references:, ignore_active_scope:) + context = + context_from_child_of(child_of) || + context_from_references(references) || + context_from_active_scope(ignore_active_scope) + + context = extract_span_context(context) + if context + ::Test::SpanContext.child_of(context) + else + ::Test::SpanContext.root + end + end + + def context_from_child_of(child_of) + return nil unless child_of + child_of.respond_to?(:context) ? child_of.context : child_of + end + + def context_from_references(references) + return nil if !references || references.none? + + # Prefer CHILD_OF reference if present + ref = references.detect do |reference| + reference.type == OpenTracing::Reference::CHILD_OF + end + (ref || references[0]).context + end + def log(severity, message) logger.log(severity, message) if logger end - def extract_span(span) - if Type?(span, ::Test::Span, NilClass) - span - else - wrapped_span_extractor.extract(span) if wrapped_span_extractor - end + def context_from_active_scope(ignore_active_scope) + return if ignore_active_scope + + active_scope = @scope_manager.active + active_scope.span.context if active_scope end def extract_span_context(span_context) diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index 8bea20b..914197b 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -1,6 +1,7 @@ require "bundler/setup" require "test-tracer" require "support/wrapping_tracer" +require 'pry' RSpec.configure do |config| # Enable flags like --only-failures and --next-failure diff --git a/spec/test/scope_spec.rb b/spec/test/scope_spec.rb new file mode 100644 index 0000000..a9cf718 --- /dev/null +++ b/spec/test/scope_spec.rb @@ -0,0 +1,20 @@ +require "spec_helper" + +RSpec.describe Test::Scope do + describe :attributes do + let(:span_context) { Test::SpanContext.root } + let(:operation_name) { "span_name" } + let(:tracer) { Test::Tracer.new } + let(:span) { Test::Span.new(tracer: tracer, context: span_context, operation_name: operation_name) } + let(:scope) do + Test::Scope.new(span, span_context, finish_on_close: true) + end + + it "returns proper for closed" do + expect(scope).to be + end + end + + describe :root do + end +end diff --git a/spec/test/span_spec.rb b/spec/test/span_spec.rb index 2fc1d40..411374f 100644 --- a/spec/test/span_spec.rb +++ b/spec/test/span_spec.rb @@ -131,14 +131,32 @@ end it "fills up log entries attributes properly" do + event_name = "event" time = Time.now - span.log(event: "event", timestamp: time, additional: :info) + span.log(event: event_name, timestamp: time, additional: :info) log = span.logs.last expect(log).to be_instance_of(Test::Span::LogEntry) - expect(log.event).to eq("event") + expect(log.fields[:event]).to eq(event_name) expect(log.timestamp).to eq(time) - expect(log.fields).to eq(additional: :info) + expect(log.fields).to eq(additional: :info, event: event_name) + end + end + + describe :log_kv do + it "creates new log entry" do + span.log_kv + expect(span.logs.size).to eq(1) + end + + it "fills up log entries attributes properly" do + time = Time.now + span.log_kv(timestamp: time, additional: :info, something: :else) + log = span.logs.last + + expect(log).to be_instance_of(Test::Span::LogEntry) + expect(log.timestamp).to eq(time) + expect(log.fields).to eq(additional: :info, :something=>:else) end end diff --git a/spec/test/tracer_spec.rb b/spec/test/tracer_spec.rb index 7156b61..83005e7 100644 --- a/spec/test/tracer_spec.rb +++ b/spec/test/tracer_spec.rb @@ -38,6 +38,15 @@ end end + it 'works corretly with passed in block' do + value = tracer.start_span("test") do |span| + expect(span).to be_instance_of(Test::Span) + 'expected_value' + end + + expect(value).to eq('expected_value') + end + describe "context propagation" do it "creates new root context when no parent context passed" do expect(tracer.start_span("root").context.parent_span_id).to eq(nil) @@ -67,6 +76,16 @@ expect(tracer.spans.size).to eq(1) expect(tracer.spans.first).to eq(span) end + + it 'adds newely started span to spans collection with block' do + span = tracer.start_span("span") do |span| + span + end + + expect(tracer.spans.size).to eq(1) + expect(tracer.finished_spans.size).to eq(1) + expect(tracer.spans.first).to eq(span) + end end describe :finished_spans do @@ -87,6 +106,29 @@ end end + # describe :start_active_span do + # let(:tracer) { Test::Tracer.new } + + # it "returns instance of Scope" do + # expect(tracer.start_active_span("test")).to be_instance_of(Test::Scope) + # end + + # describe "operation_name propagation" do + # it "sets operation_name on newly created span" do + # expect(tracer.start_active_span("test").operation_name).to eq("test") + # end + # end + + # describe "tags propagation" do + # it "sets tags on newly created span" do + # tags = { 'span.kind' => 'client' } + # expect(tracer.start_active_span("test", tags: tags).tags).to eq(tags) + # end + # end + + + # end + describe :inject do let(:tracer) { Test::Tracer.new } let(:span) { tracer.start_span("root") } diff --git a/test-tracer.gemspec b/test-tracer.gemspec index af4051e..c3ce16d 100644 --- a/test-tracer.gemspec +++ b/test-tracer.gemspec @@ -24,7 +24,9 @@ Gem::Specification.new do |spec| spec.add_dependency 'opentracing', '~> 0.3.1' + spec.add_development_dependency "bundler", "~> 1.15" + spec.add_development_dependency "pry-byebug" spec.add_development_dependency "rake", "~> 10.0" spec.add_development_dependency "rspec", "~> 3.0" end From 129c1da046164ffec36a1c8e8bc80dcfc56f9dcc Mon Sep 17 00:00:00 2001 From: Michal Granec Date: Wed, 1 May 2019 11:06:33 +0200 Subject: [PATCH 2/4] add some more rspec tests --- lib/test/scope.rb | 3 +- lib/test/scope_manager.rb | 6 +- lib/test/scope_manager/scope_stack.rb | 4 +- lib/test/span.rb | 1 + lib/test/tracer.rb | 13 +- spec/spec_helper.rb | 15 +- spec/test/scope_manager_spec.rb | 57 ++++++ spec/test/scope_spec.rb | 64 +++++- spec/test/span_spec.rb | 22 +- spec/test/tracer_spec.rb | 276 +++++++++++++++++++++++--- test-tracer.gemspec | 2 - 11 files changed, 407 insertions(+), 56 deletions(-) create mode 100644 spec/test/scope_manager_spec.rb diff --git a/lib/test/scope.rb b/lib/test/scope.rb index e1e6307..5391db1 100644 --- a/lib/test/scope.rb +++ b/lib/test/scope.rb @@ -15,7 +15,7 @@ def initialize(span, scope_stack, finish_on_close:) # Return the Span scoped by this Scope # # @return [Span] - attr_reader :span + attr_reader :span, :finish_on_close, :scope_stack def closed? @closed @@ -37,6 +37,7 @@ def close "removed: #{removed_scope.inspect}, "\ "expected: #{inspect}" end + removed_scope end end end diff --git a/lib/test/scope_manager.rb b/lib/test/scope_manager.rb index b9faf9b..47b66ec 100644 --- a/lib/test/scope_manager.rb +++ b/lib/test/scope_manager.rb @@ -11,6 +11,8 @@ module Test # via ScopeManager#activate and access to an active Span/Scope via # ScopeManager#active class ScopeManager + attr_reader :scope_stack + def initialize @scope_stack = ScopeStack.new end @@ -41,9 +43,5 @@ def activate(span, finish_on_close: true) def active @scope_stack.peek end - - def stack - @scope_stack.stack - end end end diff --git a/lib/test/scope_manager/scope_stack.rb b/lib/test/scope_manager/scope_stack.rb index 10a57e5..4161b16 100644 --- a/lib/test/scope_manager/scope_stack.rb +++ b/lib/test/scope_manager/scope_stack.rb @@ -24,7 +24,7 @@ def peek end def stack - Thread.current[@scope_identifier] + Thread.current[@scope_identifier].dup end private @@ -34,4 +34,4 @@ def store end end end -end \ No newline at end of file +end diff --git a/lib/test/span.rb b/lib/test/span.rb index cc38fc8..0225d07 100644 --- a/lib/test/span.rb +++ b/lib/test/span.rb @@ -14,6 +14,7 @@ def initialize(tracer:, context:, operation_name:, start_time: Time.now, referen Type! operation_name, String Type! start_time, Time Type! tags, Hash, NilClass + Type! references, Array, NilClass @tracer = tracer @context = context diff --git a/lib/test/tracer.rb b/lib/test/tracer.rb index 4c78faf..e60fe27 100644 --- a/lib/test/tracer.rb +++ b/lib/test/tracer.rb @@ -125,10 +125,17 @@ def start_span(operation_name, end end + # OT compliant + # active_span method it is implemented in OpenTracing tracer + # def active_span + # scope = scope_manager.active + # scope.span if scope + # end + # OT compliant def inject(span_context, format, carrier) NotNull! format - span_context = extract_span_context(span_context) + span_context = extract_wrapped_span_context(span_context) return unless carrier @@ -168,7 +175,7 @@ def prepare_span_context(child_of:, references:, ignore_active_scope:) context_from_references(references) || context_from_active_scope(ignore_active_scope) - context = extract_span_context(context) + context = extract_wrapped_span_context(context) if context ::Test::SpanContext.child_of(context) else @@ -202,7 +209,7 @@ def context_from_active_scope(ignore_active_scope) active_scope.span.context if active_scope end - def extract_span_context(span_context) + def extract_wrapped_span_context(span_context) if Type?(span_context, ::Test::SpanContext, NilClass) span_context else diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index 914197b..fe57b8c 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -1,7 +1,6 @@ require "bundler/setup" require "test-tracer" require "support/wrapping_tracer" -require 'pry' RSpec.configure do |config| # Enable flags like --only-failures and --next-failure @@ -13,4 +12,18 @@ config.expect_with :rspec do |c| c.syntax = :expect end + + def build_span_context(opts = {}) + Test::SpanContext.new({ + trace_id: Test::IdProvider.generate, + span_id: Test::IdProvider.generate + }.merge(opts)) + end + + def build_span(tracer, opts = {}) + span_context = opts.delete(:span_context) || build_span_context + operation_name = opts.delete(:operation_name) || 'operation-name' + + Test::Span.new(tracer: tracer, context: span_context, operation_name: operation_name, **opts) + end end diff --git a/spec/test/scope_manager_spec.rb b/spec/test/scope_manager_spec.rb new file mode 100644 index 0000000..3696dd6 --- /dev/null +++ b/spec/test/scope_manager_spec.rb @@ -0,0 +1,57 @@ +# frozen_string_literal: true + +require 'spec_helper' + +RSpec.describe Test::ScopeManager do + let(:scope_manager) { Test::ScopeManager.new } + let(:tracer) { Test::Tracer.new } + let(:span) { build_span(tracer) } + + describe :activate do + it 'returns scope' do + scope = scope_manager.activate(span) + expect(scope).to be_instance_of(Test::Scope) + end + + it 'propagates finish_on_close to scope' do + scope = scope_manager.activate(span, finish_on_close: false).close + expect(scope.closed?).to be_truthy + expect(scope.span.finished?).to be_falsey + end + + it 'returns the same scope if it is active one' do + scope = scope_manager.activate(span) + the_same_scope = scope_manager.activate(span) + expect(scope_manager.scope_stack.stack.size).to eq(1) + expect(scope).to eq(the_same_scope) + end + end + + describe :active do + let(:last_span) { build_span(tracer) } + + it 'returns last activated element' do + scope_manager.activate(span) + last_scope = scope_manager.activate(last_span) + expect(scope_manager.active).to eq(last_scope) + expect(scope_manager.active.span).to eq(last_span) + end + + it 'doesn\'t remove active scope' do + last_scope = scope_manager.activate(span) + expect(scope_manager.active).to eq(last_scope) + expect(scope_manager.active).to eq(last_scope) + end + end + + describe :stack do + it 'allows to inspect whole scope stack' do + spans = Array.new(5) { |i| build_span(tracer, operation_name: "test_span_#{i}" )} + spans.each do |span| + scope_manager.activate(span) + end + expect(scope_manager.scope_stack.stack.first.span.operation_name).to eq(spans.first.operation_name) + expect(scope_manager.scope_stack.stack.map { |scope| scope.span.operation_name }).to eq(spans.map(&:operation_name)) + end + end +end diff --git a/spec/test/scope_spec.rb b/spec/test/scope_spec.rb index a9cf718..8fd2f81 100644 --- a/spec/test/scope_spec.rb +++ b/spec/test/scope_spec.rb @@ -1,20 +1,64 @@ -require "spec_helper" +# frozen_string_literal: true + +require 'spec_helper' RSpec.describe Test::Scope do + let(:operation_name) { 'span_name' } + let(:tracer) { Test::Tracer.new } + let(:scope_stack) { Test::ScopeManager::ScopeStack.new } + let(:span) { build_span(tracer) } + describe :attributes do - let(:span_context) { Test::SpanContext.root } - let(:operation_name) { "span_name" } - let(:tracer) { Test::Tracer.new } - let(:span) { Test::Span.new(tracer: tracer, context: span_context, operation_name: operation_name) } - let(:scope) do - Test::Scope.new(span, span_context, finish_on_close: true) + let(:scope) { Test::Scope.new(span, scope_stack, finish_on_close: true) } + + it 'returns proper value for closed' do + expect(scope.closed?).to be_falsey end - it "returns proper for closed" do - expect(scope).to be + it 'returns proper value for span' do + expect(scope.span).to eq(span) end end - describe :root do + describe :close do + let(:scope) { Test::Scope.new(span, scope_stack, finish_on_close: finish_on_close) } + let(:finish_on_close) { true } + + before(:each) do + scope_stack.push(scope) + end + + it 'throws error if some other scope is currently active' do + another_span = build_span(tracer) + another_scope = Test::Scope.new(another_span, scope_stack, finish_on_close: true) + scope_stack.push(another_scope) + + expect { scope.close }.to raise_error(RuntimeError, /non-active/) + end + + it 'removes self from scope stack' do + expect(scope.scope_stack.stack).to eq([scope]) + scope.close + expect(scope.scope_stack.stack).to eq([]) + end + + context 'finished on close is true' do + let(:finish_on_close) { true } + it 'closes the scope with span' do + scope.close + expect(scope.closed?).to be_truthy + expect(scope.span.finished?).to be_truthy + end + end + + context 'finished on close is false' do + let(:finish_on_close) { false } + + it 'closes the scope and keeps the span opened' do + scope.close + expect(scope.closed?).to be_truthy + expect(scope.span.in_progress?).to be_truthy + end + end end end diff --git a/spec/test/span_spec.rb b/spec/test/span_spec.rb index 411374f..551d4c6 100644 --- a/spec/test/span_spec.rb +++ b/spec/test/span_spec.rb @@ -4,7 +4,7 @@ let(:tracer) { Test::Tracer.new } let(:span_context) { Test::SpanContext.root } let(:operation_name) { "span_name" } - let(:span) { Test::Span.new(tracer: tracer, context: span_context, operation_name: operation_name) } + let(:span) { build_span(tracer, operation_name: operation_name, span_context: span_context) } describe :initialize do describe :in_progress? do @@ -32,6 +32,22 @@ expect(Test::Span.new(tracer: tracer, context: span_context, operation_name: operation_name, start_time: time).start_time).to eq(time) end end + + describe :references do + it "returns references from initialization" do + open_tracing_references = Array.new(3) { OpenTracing::Reference.child_of(build_span_context) } + + span = Test::Span.new( + tracer: tracer, + context: span_context, + operation_name: operation_name, + references: open_tracing_references + ) + expect(span.references).to be_instance_of(Array) + expect(span.references.first).to be_instance_of(OpenTracing::Reference) + expect(span.references).to eq(open_tracing_references) + end + end end describe "OT spec" do @@ -89,7 +105,7 @@ it "sets a baggage on context" do span.set_baggage_item("key", "value") - expect(span.context.baggage["key"]).to eq("value") + expect(span.context.get_baggage_item("key")).to eq("value") end it "allows string only keys" do @@ -156,7 +172,7 @@ expect(log).to be_instance_of(Test::Span::LogEntry) expect(log.timestamp).to eq(time) - expect(log.fields).to eq(additional: :info, :something=>:else) + expect(log.fields).to eq(additional: :info, something: :else) end end diff --git a/spec/test/tracer_spec.rb b/spec/test/tracer_spec.rb index 83005e7..da79f8a 100644 --- a/spec/test/tracer_spec.rb +++ b/spec/test/tracer_spec.rb @@ -9,6 +9,21 @@ it "has no finished spans" do expect(Test::Tracer.new.finished_spans).to be_empty end + + it 'has ready scope manager with empty scope stack' do + tracer = Test::Tracer.new + expect(tracer.scope_manager).to be_instance_of(Test::ScopeManager) + expect(tracer.scope_manager.active).to be_nil + end + end + + describe 'active_span' do + it 'returns correct scope' do + tracer = Test::Tracer.new + span = tracer.start_span("span") + tracer.scope_manager.activate(span) + expect(tracer.active_span).to eq(span) + end end describe :start_span do @@ -39,12 +54,23 @@ end it 'works corretly with passed in block' do - value = tracer.start_span("test") do |span| + return_value = 'expected_value' + block_value = tracer.start_span("test") do |span| expect(span).to be_instance_of(Test::Span) - 'expected_value' + return_value end + expect(block_value).to eq(return_value) + end - expect(value).to eq('expected_value') + describe "references propagation" do + it "sets references on newly created span" do + parent_context = build_span_context + reference = OpenTracing::Reference.child_of(parent_context) + span = tracer.start_span("test_span", references: [reference]) + expect(span.references.size).to eq(1) + expect(span.context.parent_span_id).to eq(parent_context.span_id) + expect(span.references.first.context).to eq(parent_context) + end end describe "context propagation" do @@ -67,6 +93,36 @@ expect(child_span.context.trace_id).to eq(root_span_context.trace_id) expect(child_span.context.parent_span_id).to eq(root_span_context.span_id) end + + describe 'active scope propagation' do + context 'no active span is present' do + it "creates separate root parants if there is no parent and no active span" do + root_span = tracer.start_span("root") + another_root_span = tracer.start_span("another_root") + + expect(root_span.context.parent_span_id).to be_nil + expect(another_root_span.context.parent_span_id).to be_nil + end + end + + context 'active span is present' do + let(:root_span) { build_span(tracer, operation_name: "root") } + + before(:each) do + tracer.scope_manager.activate(root_span) + end + + it "creates span and sets its parent span to active span" do + span = tracer.start_span("test_span") + expect(span.context.parent_span_id).to eq(root_span.context.span_id) + end + + it "ignore active span if specified by ignore_active_scope" do + span = tracer.start_span("test_span", ignore_active_scope: true) + expect(span.context.parent_span_id).to be_nil + end + end + end end describe :spans do @@ -76,16 +132,6 @@ expect(tracer.spans.size).to eq(1) expect(tracer.spans.first).to eq(span) end - - it 'adds newely started span to spans collection with block' do - span = tracer.start_span("span") do |span| - span - end - - expect(tracer.spans.size).to eq(1) - expect(tracer.finished_spans.size).to eq(1) - expect(tracer.spans.first).to eq(span) - end end describe :finished_spans do @@ -96,6 +142,13 @@ end context "on span finish" do + it 'automatically finish span if start_span received block' do + returned_span = tracer.start_span("span") { |span| span } + + expect(tracer.finished_spans.size).to eq(1) + expect(tracer.finished_spans.first).to eq(returned_span) + end + it "adds finished span to finished_spans collection" do span = tracer.start_span("span").finish @@ -104,30 +157,193 @@ end end end + + describe 'scope_manager scope stack' do + it "start_span doesn't add to scope stack" do + tracer.start_span("span") + expect(tracer.scope_manager).to be_instance_of(Test::ScopeManager) + expect(tracer.scope_manager.scope_stack.stack).to eq([]) + expect(tracer.scope_manager.active).to be_nil + end + end end - # describe :start_active_span do - # let(:tracer) { Test::Tracer.new } + describe :start_active_span do + let(:tracer) { Test::Tracer.new } + + it "returns instance of Scope" do + expect(tracer.start_active_span('root')).to be_instance_of(Test::Scope) + end + + describe "operation_name propagation" do + it "sets operation_name on newly created span" do + expect(tracer.start_active_span("test").span.operation_name).to eq("test") + end + end + + describe "tags propagation" do + it "sets tags on newly created span" do + tags = { 'span.kind' => 'client' } + expect(tracer.start_active_span("test", tags: tags).span.tags).to eq(tags) + end + end + + describe "start_time propagation" do + it "sets start_time on newly created span" do + time = Time.now - 60 + expect(tracer.start_active_span("test", start_time: time).span.start_time).to eq(time) + end + end + + it 'works corretly with passed in block' do + return_value = 'expected_value' + block_value = tracer.start_active_span("test") do |scope| + expect(scope).to be_instance_of(Test::Scope) + return_value + end + expect(block_value).to eq(return_value) + end + + describe 'scope_manager scope stack' do + it "adds to scope stack" do + scope = tracer.start_active_span('test') + expect(scope.closed?).to be_falsey + expect(tracer.scope_manager.scope_stack.stack).to eq([scope]) + expect(tracer.active_span).to eq(scope.span) + end + + it 'adds and removes active scope to scope stack for brief moment if start_active_span received block' do + returned_scope = tracer.start_active_span('test') do |scope| + expect(tracer.active_span).to eq(scope.span) + expect(scope.closed?).to be_falsey + scope + end + + expect(returned_scope.closed?).to be_truthy + expect(tracer.active_span).to be_nil + end + + it 'nests correctly' do + tracer.start_active_span('parent_span') do |parent_scope| + expect(tracer.active_span).to eq(parent_scope.span) + tracer.start_active_span('child_span') do |child_scope| + expect(tracer.active_span).to eq(child_scope.span) + expect(tracer.scope_manager.scope_stack.stack).to eq([parent_scope, child_scope]) + expect(child_scope.span.context.parent_span_id).to eq(parent_scope.span.context.span_id) + end + end + end + end + + describe "references propagation" do + it "sets references on newly created span" do + parent_context = build_span_context + reference = OpenTracing::Reference.child_of(parent_context) + scope = tracer.start_active_span("test_span", references: [reference]) + expect(scope.span.references.size).to eq(1) + expect(scope.span.context.parent_span_id).to eq(parent_context.span_id) + expect(scope.span.references.first.context).to eq(parent_context) + end + end + + describe 'finish_on_close propagation' do + it 'sets finish_on_close in new scope' do + expect(tracer.start_active_span("test_span", finish_on_close: false).finish_on_close).to be_falsey + end + end + + describe "context propagation" do + it "creates new root context when no parent context passed" do + expect(tracer.start_active_span("root").span.context.parent_span_id).to be_nil + end + + it "propagates parent context when parent span passed" do + root_scope = tracer.start_active_span("root") + child_scope = tracer.start_active_span("child", child_of: root_scope.span) + + expect(child_scope.span.context.trace_id).to eq(root_scope.span.context.trace_id) + expect(child_scope.span.context.parent_span_id).to eq(root_scope.span.context.span_id) + end + + it "propagates parent context when parent span context passed" do + root_scope = tracer.start_active_span("root") + child_scope = tracer.start_active_span("child", child_of: root_scope.span.context) + + expect(child_scope.span.context.trace_id).to eq(root_scope.span.context.trace_id) + expect(child_scope.span.context.parent_span_id).to eq(root_scope.span.context.span_id) + end + + describe 'active scope propagation' do + context 'no active span is present' do + it "creates separete root parants if there is no parent and no active span" do + scope = tracer.start_active_span("child") + expect(scope.span.context.parent_span_id).to be_nil + expect(tracer.active_span).to eq(scope.span) + end + end + + context 'active span is present' do + it "creates span and sets its parent span to active span" do + parent_scope = tracer.start_active_span('root') + child_scope = tracer.start_active_span("child") + expect(child_scope.span.context.parent_span_id).to eq(parent_scope.span.context.span_id) + end + + it "ignore active span if specified by ignore_active_scope" do + tracer.start_active_span('root') + child_scope = tracer.start_active_span("child", ignore_active_scope: true) + expect(child_scope.span.context.parent_span_id).to be_nil + end + end + end + end + + describe :spans do + let(:scope_stack) { tracer.scope_manager.scope_stack } + + it "adds newely started span to spans collection" do + span = tracer.start_active_span("test_span").span + + expect(tracer.spans.size).to eq(1) + expect(tracer.spans.first).to eq(span) + expect(scope_stack.stack.size).to eq(1) + expect(scope_stack.stack.first.span).to eq(span) + end + end + + describe :finished_spans do + let(:scope_stack) { tracer.scope_manager.scope_stack } - # it "returns instance of Scope" do - # expect(tracer.start_active_span("test")).to be_instance_of(Test::Scope) - # end + it "doesn\'t add newely started active span to finished_spans collection" do + span = tracer.start_active_span("span").span - # describe "operation_name propagation" do - # it "sets operation_name on newly created span" do - # expect(tracer.start_active_span("test").operation_name).to eq("test") - # end - # end + expect(scope_stack.stack.size).to eq(1) + expect(scope_stack.stack.first.span).to eq(span) + expect(tracer.finished_spans).to be_empty + end - # describe "tags propagation" do - # it "sets tags on newly created span" do - # tags = { 'span.kind' => 'client' } - # expect(tracer.start_active_span("test", tags: tags).tags).to eq(tags) - # end - # end + context "on span finish" do + it "automatically finish span if start_active_span received block" do + span = tracer.start_active_span("span") do |scope| + scope.span + end + + expect(scope_stack.stack.size).to eq(0) + expect(tracer.active_span).to be_nil + expect(tracer.finished_spans.size).to eq(1) + expect(tracer.finished_spans.first).to eq(span) + end + it "adds finished span to finished_spans collection" do + scope = tracer.start_active_span("span").close - # end + expect(tracer.active_span).to be_nil + expect(tracer.finished_spans.size).to eq(1) + expect(tracer.finished_spans.first).to eq(scope.span) + end + end + end + end describe :inject do let(:tracer) { Test::Tracer.new } diff --git a/test-tracer.gemspec b/test-tracer.gemspec index c3ce16d..af4051e 100644 --- a/test-tracer.gemspec +++ b/test-tracer.gemspec @@ -24,9 +24,7 @@ Gem::Specification.new do |spec| spec.add_dependency 'opentracing', '~> 0.3.1' - spec.add_development_dependency "bundler", "~> 1.15" - spec.add_development_dependency "pry-byebug" spec.add_development_dependency "rake", "~> 10.0" spec.add_development_dependency "rspec", "~> 3.0" end From a9cd012a794c6fb682c859e63c0ada2aed2f5337 Mon Sep 17 00:00:00 2001 From: Michal Granec Date: Thu, 2 May 2019 01:34:45 +0200 Subject: [PATCH 3/4] add some basic info to readme --- README.md | 29 ++++++++++++++++++++++------- lib/test/scope.rb | 1 + lib/test/scope_manager.rb | 2 ++ 3 files changed, 25 insertions(+), 7 deletions(-) diff --git a/README.md b/README.md index 64d0a88..fb0c1b7 100644 --- a/README.md +++ b/README.md @@ -77,10 +77,11 @@ In addition to OT compatible methods `Test::Span` provides the following methods 1. `tracer` returns the tracer the span was created by. 1. `in_progress?`, `started?`, `finished?` informs whether the span is in progress, or it's finished. -2. `start_time` returns when the span was started. -2. `end_time` returns when the span was finished, or nil if still in progress. -2. `tags` returns the span's tags. -2. `logs` returns the span's logs, an array of `Test::Span::LogEntry`s. +1. `start_time` returns when the span was started. +1. `end_time` returns when the span was finished, or nil if still in progress. +1. `tags` returns the span's tags. +1. `references` returns SpanContext references to corrent span (either as child_of or followes_from and extracted from OpenTracing::Reference) +1. `logs` returns the span's logs, an array of `Test::Span::LogEntry`s. The modification operations e.g. `operation_name=`, `set_tag`, `set_baggage_item` on a span are not allowed after it's finished. It throws `Test::Span::SpanAlreadyFinished` exception. The same with `finish`. The span can be finished only once. @@ -96,7 +97,7 @@ describe "Test::Span examples" do let(:span) { tracer.start_span("operation name", tags: {'component' => 'ActiveRecord'}) } it "is in progress" do - expect(span.in_progress?).to eq(true) + expect(span.in_progress?).to eq(true) end it "does have the proper name" do @@ -113,7 +114,7 @@ describe "Test::Span examples" do end context "when an event was logged" do - let(:span) do + let(:span) do current_span = tracer.start_span("operation name") current_span.log(event: "exceptional message", severity: Logger::ERROR, pid: $1) current_span @@ -162,7 +163,7 @@ describe "Test::SpanContext examples" do let(:tracer) { Test::Tracer.new } context "when a new span was started as child of root" do - let(:root_context) { tracer.start_span("root span").context } + let(:root_context) { tracer.start_span("root span").context } let(:child_context) { tracer.start_span("child span", child_of: root_context).context } it "all have the same trace_id" do @@ -176,6 +177,20 @@ describe "Test::SpanContext examples" do end ``` +## Test::ScopeManager + +ScopeManager is fully implemented by the tracer, and is also inspired by inspired by [Jaeger](http://jaeger.readthedocs.io/en/latest/). In addition to OT compatible methods `Test::ScopeManager` provides the following methods: + +1. `scope_stack` returns the stack of all scope currently, which are not closed. + +## Test::Scope + +Scope is implemented by the tracer, and is returned from `tracer#start_active_span` and `ScopeManager#activate` It is inspired by [Jaeger](http://jaeger.readthedocs.io/en/latest/). In addition to OT compatible methods `Test::Scope` provides the following methods: + +1. `finish_on_close` informs whether the scope's span should be finished on scope closing. +1. `scope_stack` returns reference to scope manager scope stack +1. `closed?` informs whether the scope has already been closed + ## Development After checking out the repo, run `bin/setup` to install dependencies. Then, run `rake spec` to run the tests. You can also run `bin/console` for an interactive prompt that will allow you to experiment. diff --git a/lib/test/scope.rb b/lib/test/scope.rb index 5391db1..9021e46 100644 --- a/lib/test/scope.rb +++ b/lib/test/scope.rb @@ -21,6 +21,7 @@ def closed? @closed end + # OT complient # Close scope # # Mark the end of the active period for the current thread and Scope, diff --git a/lib/test/scope_manager.rb b/lib/test/scope_manager.rb index 47b66ec..af91120 100644 --- a/lib/test/scope_manager.rb +++ b/lib/test/scope_manager.rb @@ -17,6 +17,7 @@ def initialize @scope_stack = ScopeStack.new end + # OT compliant # Make a span instance active # # @param span [Span] the Span that should become active @@ -32,6 +33,7 @@ def activate(span, finish_on_close: true) scope end + # OT compliant # Return active scope # # If there is a non-null Scope, its wrapped Span becomes an implicit parent From ecb41addfff91e9355879d676c8a0b153cace966 Mon Sep 17 00:00:00 2001 From: Michal Granec Date: Thu, 2 May 2019 01:50:33 +0200 Subject: [PATCH 4/4] update opentracing dependency --- test-tracer.gemspec | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test-tracer.gemspec b/test-tracer.gemspec index af4051e..bb4fcc4 100644 --- a/test-tracer.gemspec +++ b/test-tracer.gemspec @@ -22,7 +22,7 @@ Gem::Specification.new do |spec| spec.executables = spec.files.grep(%r{^exe/}) { |f| File.basename(f) } spec.require_paths = ["lib"] - spec.add_dependency 'opentracing', '~> 0.3.1' + spec.add_dependency 'opentracing', '~> 0.5.0' spec.add_development_dependency "bundler", "~> 1.15" spec.add_development_dependency "rake", "~> 10.0"