Merge pull request #11 from salemove/logging

Add logging support

.rubocop.yml

@@ -9,6 +9,12 @@ Style/IfUnlessModifier:
 RSpec/NestedGroups:
   Max: 4
 
+RSpec/ExampleLength:
+  Enabled: no
+
+RSpec/MultipleExpectations:
+  Enabled: no
+
 Metrics/BlockLength:
   Enabled: no
 

lib/zipkin/collector.rb

@@ -1,5 +1,8 @@
 require 'thread'
 
+require_relative './collector/timestamp'
+require_relative './collector/log_annotations'
+
 module Zipkin
   class Collector
     def initialize(local_endpoint)
@@ -12,8 +15,8 @@ def retrieve
     end
 
     def send_span(span, end_time)
-      finish_ts = (end_time.to_f * 1_000_000).to_i
-      start_ts = (span.start_time.to_f * 1_000_000).to_i
+      finish_ts = Timestamp.create(end_time)
+      start_ts = Timestamp.create(span.start_time)
       duration = finish_ts - start_ts
       is_server = %w[server consumer].include?(span.tags['span.kind'] || 'server')
 
@@ -24,7 +27,7 @@ def send_span(span, end_time)
         name: span.operation_name,
         timestamp: start_ts,
         duration: duration,
-        annotations: [
+        annotations: LogAnnotations.build(span, @local_endpoint) + [
           {
             timestamp: start_ts,
             value: is_server ? 'sr' : 'cs',

lib/zipkin/collector/log_annotations.rb

@@ -0,0 +1,26 @@
+module Zipkin
+  class Collector
+    module LogAnnotations
+      def self.build(span, endpoint)
+        span.logs.map do |log|
+          {
+            timestamp: Timestamp.create(log.fetch(:timestamp)),
+            value: format_log_value(log),
+            endpoint: endpoint
+          }
+        end
+      end
+
+      def self.format_log_value(log)
+        if log.keys == %i[event timestamp]
+          log.fetch(:event)
+        else
+          log
+            .reject { |key, _value| key == :timestamp }
+            .map { |key, value| "#{key}=#{value}" }
+            .join(' ')
+        end
+      end
+    end
+  end
+end

lib/zipkin/collector/timestamp.rb

@@ -0,0 +1,9 @@
+module Zipkin
+  class Collector
+    module Timestamp
+      def self.create(time)
+        (time.to_f * 1_000_000).to_i
+      end
+    end
+  end
+end

lib/zipkin/span.rb

@@ -2,7 +2,7 @@ module Zipkin
   class Span
     attr_accessor :operation_name
 
-    attr_reader :context, :start_time, :tags
+    attr_reader :context, :start_time, :tags, :logs
 
     # Creates a new {Span}
     #
@@ -17,6 +17,7 @@ def initialize(context, operation_name, collector, start_time: Time.now, tags: {
       @collector = collector
       @start_time = start_time
       @tags = tags
+      @logs = []
     end
 
     # Set a tag value on this span
@@ -47,21 +48,18 @@ def get_baggage_item(key)
 
     # Add a log entry to this span
     #
-    # @param event [String] event name for the log
-    # @param timestamp [Time] time of the log
-    # @param fields [Hash] Additional information to log
-    #
     # @deprecated Use {#log_kv} instead.
-    def log(event: nil, timestamp: Time.now, **fields)
+    def log(*args)
       warn 'Span#log is deprecated. Please use Span#log_kv instead.'
-      nil
+      log_kv(*args)
     end
 
     # Add a log entry to this span
     #
     # @param timestamp [Time] time of the log
     # @param fields [Hash] Additional information to log
     def log_kv(timestamp: Time.now, **fields)
+      @logs << fields.merge(timestamp: timestamp)
       nil
     end
 

script/create_trace

@@ -33,6 +33,8 @@ downstream_span = tracer2.start_span(
   child_of: inner_span,
   tags: { 'span.kind' => 'server' }
 )
+downstream_span.log_kv(event: 'custom-event')
+downstream_span.log_kv(foo: 'bar', baz: 'buz')
 sleep 0.5
 downstream_span.finish
 

spec/zipkin/collector/log_annotations_spec.rb

@@ -0,0 +1,29 @@
+require 'spec_helper'
+
+RSpec.describe Zipkin::Collector::LogAnnotations do
+  let(:span) { Zipkin::Span.new(nil, 'operation_name', nil) }
+  let(:endpoint) { 'local-endpoint' }
+
+  context 'when log includes only event and timestamp' do
+    it 'uses event as the annotation value' do
+      message = 'some message'
+      span.log_kv(event: message)
+      expect(described_class.build(span, endpoint)).to include(
+        timestamp: instance_of(Integer),
+        value: message,
+        endpoint: endpoint
+      )
+    end
+  end
+
+  context 'when log includes multiple fields' do
+    it 'converts fields into string form' do
+      span.log_kv(foo: 'bar', baz: 'buz')
+      expect(described_class.build(span, endpoint)).to include(
+        timestamp: instance_of(Integer),
+        value: 'foo=bar baz=buz',
+        endpoint: endpoint
+      )
+    end
+  end
+end

spec/zipkin/span_spec.rb

@@ -4,8 +4,26 @@
   describe '#log_kv' do
     let(:span) { described_class.new(nil, 'operation_name', nil) }
 
-    it 'return nil' do
+    it 'returns nil' do
       expect(span.log_kv(key: 'value')).to be_nil
     end
+
+    it 'adds log to span' do
+      log = { key1: 'value1', key2: 'value2' }
+      span.log_kv(log)
+
+      expect(span.logs.count).to eq(1)
+      expect(span.logs[0]).to include(
+        log.merge(timestamp: instance_of(Time))
+      )
+    end
+
+    it 'adds log to span with specific timestamp' do
+      log = { key1: 'value1', key2: 'value2', timestamp: Time.now }
+      span.log_kv(log)
+
+      expect(span.logs.count).to eq(1)
+      expect(span.logs[0]).to eq(log)
+    end
   end
 end