Merge pull request #5 from skirushkin/feature/better-as-notification-log

Implement better ActiveSupport notification span logging.

Gemfile.lock

@@ -1,7 +1,7 @@
 PATH
   remote: .
   specs:
-    jcw (0.1.2)
+    jcw (0.1.3)
       activesupport (>= 5.0)
       httprb-opentracing (~> 0.4.0)
       jaeger-client (~> 1.1.0)
@@ -74,12 +74,12 @@ GEM
     method_source (1.0.0)
     mini_portile2 (2.6.1)
     minitest (5.14.4)
-    nokogiri (1.12.3)
+    nokogiri (1.12.5)
       mini_portile2 (~> 2.6.1)
       racc (~> 1.4)
-    nokogiri (1.12.3-x86_64-darwin)
+    nokogiri (1.12.5-x86_64-darwin)
       racc (~> 1.4)
-    nokogiri (1.12.3-x86_64-linux)
+    nokogiri (1.12.5-x86_64-linux)
       racc (~> 1.4)
     opentracing (0.5.0)
     parallel (1.20.1)
@@ -164,7 +164,7 @@ GEM
     simplecov-lcov (0.8.0)
     simplecov_json_formatter (0.1.3)
     thor (1.1.0)
-    thrift (0.14.2)
+    thrift (0.15.0)
     tzinfo (2.0.4)
       concurrent-ruby (~> 1.0)
     unf (0.1.4)

README.md

@@ -25,7 +25,7 @@ gem install jcw
 ```
 
 ```ruby
-require 'jcw' 
+require 'jcw'
 ```
 
 ## Usage
@@ -68,17 +68,20 @@ Rails.application.middleware.use(JCW::RackTracer)
 # Not recommended for UDP sender, because default max packet size is 65,000 bytes.
 Rails.application.config.tap do |config|
   config.middleware.use(
-  ::JCW::RackTracer,
-  on_finish_span:
-    -> (span) { ::JCW::JaegerLogger.current.logs.each { |log| span.log_kv(**log) } },
+    JCW::RackTracer,
+    on_finish_span: lambda do |span|
+      JCW::Logger.current.logs.each { |log| span.log_kv(**log) }
+      JCW::Logger.current.clear # Do not forget to avoid memory leaks
+    end,
   )
-  config.logger.extend(::JCW::JaegerLoggerExtension)
+
+  config.logger.extend(JCW::LoggerExtension)
 end
 ```
 - `config.subscribe_to` - not recommended for UDP sender, because default max packet size is 65,000 bytes.
 
 ### Contributing
- 
+
  - Fork it ( https://github.com/Cado-Labs/jcw )
  - Create your feature branch (`git checkout -b feature/my-new-feature`)
  - Commit your changes (`git commit -am '[feature_context] Add some feature'`)

lib/jcw/init.rb

@@ -41,11 +41,10 @@ def tcp_reporter
       end
 
       def activate_subscribers
-        subscribers = config.subscribe_to
-        return if subscribers.blank?
+        events = config.subscribe_to
+        return if events.blank?
 
-        Tracing.register_subscribers(subscribers)
-        Tracing.subscribe_tracing_events
+        events.each { |event| JCW::Subscriber.subscribe_to_event!(event) }
       end
 
       def init_http_tracer

lib/jcw/subscriber.rb

@@ -1,26 +1,31 @@
 # frozen_string_literal: true
 
 module JCW
-  class Subscriber
-    class << self
-      def subscribe_to_event!(event_name)
-        ActiveSupport::Notifications.subscribe(event_name) do |*args|
-          (span = OpenTracing.scope_manager.active&.span) or next
-          event = ActiveSupport::Notifications::Event.new(*args)
-          span.log_kv(context: span_context(event))
-        end
+  module Subscriber
+    extend self
+
+    IGNORED_PAYLOAD_KEYS = %i[request response headers exception exception_object].freeze
+
+    def subscribe_to_event!(event)
+      ActiveSupport::Notifications.subscribe(event) do |name, _start, _finish, _uid, payload|
+        add(name, payload)
       end
+    end
 
-      private
+    def add(name, payload)
+      # skip Rails internal events
+      return if name.start_with?("!")
 
-      def span_context(event)
-        {
-          name: event.name,
-          time: event.time,
-          payload: event.payload.to_s,
-          transaction_id: event.transaction_id,
-        }.as_json
+      span = OpenTracing.scope_manager.active&.span
+      return if span.blank?
+
+      if payload.is_a?(Hash)
+        # we should only mutate the copy of the payload
+        payload = payload.dup
+        IGNORED_PAYLOAD_KEYS.each { |key| payload.delete(key) if payload.key?(key) }
       end
+
+      span.log_kv(message: name, context: JSON.dump(payload))
     end
   end
 end

lib/jcw/version.rb

@@ -1,5 +1,5 @@
 # frozen_string_literal: true
 
 module JCW
-  VERSION = "0.1.2"
+  VERSION = "0.1.3"
 end

lib/jcw/wrapper.rb

@@ -17,7 +17,6 @@ def configure
   end
 end
 
-require_relative "tracing"
 require_relative "init"
 require_relative "subscriber"
 require_relative "http_tracer"

spec/jcw_spec.rb

@@ -17,7 +17,7 @@ def set_jaeger
 
   let(:enabled) { true }
   let(:connection) { { protocol: :udp, host: "127.0.0.1", port: 6831 } }
-  let(:subscribe_to) { %w[process_action.action_controller start_processing.action_controller] }
+  let(:subscribe_to) { [/.*/] }
 
   specify "set OpenTracing.global_tracer" do
     set_jaeger
@@ -26,48 +26,39 @@ def set_jaeger
 
   context "ActiveSupport::Notifications subscribers" do
     context "send fake message to subscribers" do
-      let(:start_args) { %w[start_processing.action_controller arg1 arg2 arg3 arg4] }
-      let(:procces_args) { %w[process_action.action_controller arg1 arg2 arg3 arg4] }
-      let(:start_event) { ActiveSupport::Notifications::Event.new(*start_args) }
-      let(:process_event) { ActiveSupport::Notifications::Event.new(*procces_args) }
+      let(:args) { [Time.now, Time.now, SecureRandom.hex] }
+      let(:data) { { request: "REQUEST", key: "value" } }
+      let(:start_args) { ["start_processing.action_controller", *args, nil] }
+      let(:process_args) { ["process_action.action_controller", *args, data] }
+      let(:deprecation_args) { ["!deprecation.rails", *args, nil] }
 
       before { set_jaeger }
 
       specify "with span and log created" do
-        allow(ActiveSupport::Notifications::Event).to receive(:new).and_return(start_event)
-        allow(ActiveSupport::Notifications::Event).to receive(:new).and_return(process_event)
-
         OpenTracing.start_active_span(self.class.name) do
           ActiveSupport::Notifications.publish(*start_args)
-          ActiveSupport::Notifications.publish(*procces_args)
+          ActiveSupport::Notifications.publish(*process_args)
+          ActiveSupport::Notifications.publish(*deprecation_args)
         end
       end
 
       specify "without span and log not created" do
-        expect(ActiveSupport::Notifications::Event).not_to receive(:new)
-        expect(ActiveSupport::Notifications::Event).not_to receive(:new)
-
         ActiveSupport::Notifications.publish(*start_args)
-        ActiveSupport::Notifications.publish(*procces_args)
+        ActiveSupport::Notifications.publish(*process_args)
+        ActiveSupport::Notifications.publish(*deprecation_args)
       end
     end
 
     specify "set subscribers" do
-      expect(ActiveSupport::Notifications).to receive(:subscribe)
-                                                  .with("process_action.action_controller")
-      expect(ActiveSupport::Notifications).to receive(:subscribe)
-                                                  .with("start_processing.action_controller")
+      expect(ActiveSupport::Notifications).to receive(:subscribe).with(/.*/)
       set_jaeger
     end
 
     context "when subscribe_to is blank" do
       let(:subscribe_to) { [] }
 
       specify "subscribers not set" do
-        expect(ActiveSupport::Notifications).not_to receive(:subscribe)
-                                                        .with("process_action.action_controller")
-        expect(ActiveSupport::Notifications).not_to receive(:subscribe)
-                                                        .with("start_processing.action_controller")
+        expect(ActiveSupport::Notifications).not_to receive(:subscribe).with(/.*/)
         set_jaeger
       end
     end
@@ -120,8 +111,7 @@ def set_jaeger
         }
         config.enabled = true
         config.flush_interval = 10
-        config.subscribe_to =
-          %w[process_action.action_controller start_processing.action_controller]
+        config.subscribe_to = [/.*/]
         config.tags = {
           hostname: "custom-hostname",
           custom_tag: "custom-tag-value",