spec/integration/logging_spec.rb in freddy-jruby-1.0.0 vs spec/integration/logging_spec.rb in freddy-jruby-1.3.2

@@ -1,44 +1,101 @@
 require 'spec_helper'
+require 'logasm/tracer'
 
-describe 'Logging' do
-  let(:freddy1) { Freddy.build(logger1, config) }
-  let(:freddy2) { Freddy.build(logger2, config) }
+describe 'Logging with Logasm::Tracer' do
+  let(:logger) { ArrayLogger.new }
+  let(:tracer) { Logasm::Tracer.new(logger) }
 
-  let(:logger1) { spy('logger1') }
-  let(:logger2) { spy('logger2') }
+  before { OpenTracing.global_tracer = tracer }
+  after { OpenTracing.global_tracer = nil }
 
-  let(:destination) { random_destination }
-  let(:payload)     { {pay: 'load'} }
+  context 'when receiving an untraced request' do
+    let(:freddy) { Freddy.build(spy, config) }
+    let(:destination) { random_destination }
 
-  after { [freddy1, freddy2].each(&:close) }
-
-  before do
-    freddy1.respond_to destination do |payload, msg_handler|
-      msg_handler.success
+    before do
+      freddy.respond_to(destination) do |payload, msg_handler|
+        sleep 0.1 # emulate some processing
+        msg_handler.success({})
+      end
     end
 
-    freddy2.deliver_with_response(destination, payload) { }
-    default_sleep
-  end
+    after { freddy.close }
 
-  it 'logs all consumed messages' do
-    expect(logger1).to have_received(:info).with(/Listening for requests on \S+/)
-    expect(logger1).to have_received(:debug).with(
-      message: 'Received message',
-      queue: destination,
-      payload: payload,
-      correlation_id: anything
-    )
+    it 'generates a trace' do
+      freddy.deliver_with_response(destination, {})
+
+      expect(logger.calls.map(&:first)).to eq([
+        # Initiator
+        "Span [freddy:request:#{destination}] started",
+        "Span [freddy:request:#{destination}] Publishing request",
+
+        # Service
+        "Span [freddy:respond:#{destination}] started",
+        "Span [freddy:respond:#{destination}] Received message through respond_to",
+        "Span [freddy:respond:#{destination}] Sending response",
+        "Span [freddy:respond:#{destination}] finished",
+
+        # Initiator
+        "Span [freddy:request:#{destination}] finished"
+      ])
+    end
   end
 
-  it 'logs all produced messages' do
-    expect(logger2).to have_received(:debug).with(/Consuming messages on \S+/)
-    expect(logger2).to have_received(:debug).with(
-      message: 'Publishing request',
-      queue: destination,
-      payload: payload,
-      response_queue: anything,
-      correlation_id: anything
-    )
+  context 'when receiving a traced request' do
+    let(:freddy) { Freddy.build(spy, config) }
+    let(:freddy2) { Freddy.build(spy, config) }
+
+    let(:destination) { random_destination }
+    let(:destination2) { random_destination }
+
+    before do
+      freddy.respond_to(destination) do |payload, msg_handler|
+        sleep 0.1 # emulate some processing
+        msg_handler.success({
+          trace_initiator: {},
+          current_receiver: freddy.deliver_with_response(destination2, {})
+        })
+      end
+
+      freddy2.respond_to(destination2) do |payload, msg_handler|
+        sleep 0.1 # emulate some processing
+        msg_handler.success({})
+      end
+    end
+
+    after do
+      freddy.close
+      freddy2.close
+    end
+
+    it 'generates a trace' do
+      freddy.deliver_with_response(destination, {})
+
+      expect(logger.calls.map(&:first)).to eq([
+        # Initiator
+        "Span [freddy:request:#{destination}] started",
+        "Span [freddy:request:#{destination}] Publishing request",
+
+        # Service 1
+        "Span [freddy:respond:#{destination}] started",
+        "Span [freddy:respond:#{destination}] Received message through respond_to",
+        "Span [freddy:request:#{destination2}] started",
+        "Span [freddy:request:#{destination2}] Publishing request",
+
+        # Service 2
+        "Span [freddy:respond:#{destination2}] started",
+        "Span [freddy:respond:#{destination2}] Received message through respond_to",
+        "Span [freddy:respond:#{destination2}] Sending response",
+        "Span [freddy:respond:#{destination2}] finished",
+
+        # Service 1
+        "Span [freddy:request:#{destination2}] finished",
+        "Span [freddy:respond:#{destination}] Sending response",
+        "Span [freddy:respond:#{destination}] finished",
+
+        # Initiator
+        "Span [freddy:request:#{destination}] finished"
+      ])
+    end
   end
 end