From 875b15d3f1546fdf5a3525d146db563d46f0dc45 Mon Sep 17 00:00:00 2001 From: ash Date: Mon, 4 Oct 2021 17:08:27 +0300 Subject: [PATCH 1/7] Add better AS notification span logging. --- Gemfile.lock | 4 ++-- README.md | 15 +++++++++------ lib/jcw/init.rb | 7 +++---- lib/jcw/subscriber.rb | 35 +++++++++++++++++++---------------- lib/jcw/tracing.rb | 17 ----------------- lib/jcw/version.rb | 2 +- lib/jcw/wrapper.rb | 1 - 7 files changed, 34 insertions(+), 47 deletions(-) delete mode 100644 lib/jcw/tracing.rb diff --git a/Gemfile.lock b/Gemfile.lock index 5d2d454..b9c586b 100644 --- a/Gemfile.lock +++ b/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) @@ -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) diff --git a/README.md b/README.md index 903a7a8..747a8ea 100644 --- a/README.md +++ b/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'`) diff --git a/lib/jcw/init.rb b/lib/jcw/init.rb index 8095489..21d1f29 100644 --- a/lib/jcw/init.rb +++ b/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 diff --git a/lib/jcw/subscriber.rb b/lib/jcw/subscriber.rb index 41c66f3..73ace93 100644 --- a/lib/jcw/subscriber.rb +++ b/lib/jcw/subscriber.rb @@ -1,26 +1,29 @@ # 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_DATA_TYPES = %i[request response headers exception exception_object].freeze + + def subscribe_to_event!(event) + ActiveSupport::Notifications.subscribe(event) do |name, started, finished, unique_id, data| + add(name, started, finished, unique_id, data) end + end - private + def add(name, _started, _finished, _unique_id, data) + # skip Rails internal events + return if name.start_with?("!") + return if (span = OpenTracing.scope_manager.active&.span).blank? - def span_context(event) - { - name: event.name, - time: event.time, - payload: event.payload.to_s, - transaction_id: event.transaction_id, - }.as_json + if data.is_a?(Hash) + # we should only mutate the copy of the data + data = data.dup + IGNORED_DATA_TYPES.each { |key| data.delete(key) if data.key?(key) } # cleanup data end + + span.log_kv(message: name, context: JSON.dump(data)) end end end diff --git a/lib/jcw/tracing.rb b/lib/jcw/tracing.rb deleted file mode 100644 index dc8c5ec..0000000 --- a/lib/jcw/tracing.rb +++ /dev/null @@ -1,17 +0,0 @@ -# frozen_string_literal: true - -module JCW - module Tracing - class << self - attr_reader :subscribers - - def register_subscribers(subscribers) - @subscribers = subscribers - end - - def subscribe_tracing_events - subscribers.each { |subscriber| Subscriber.subscribe_to_event!(subscriber) } - end - end - end -end diff --git a/lib/jcw/version.rb b/lib/jcw/version.rb index f388230..53a85e5 100644 --- a/lib/jcw/version.rb +++ b/lib/jcw/version.rb @@ -1,5 +1,5 @@ # frozen_string_literal: true module JCW - VERSION = "0.1.2" + VERSION = "0.1.3" end diff --git a/lib/jcw/wrapper.rb b/lib/jcw/wrapper.rb index 2af3e77..e51440c 100644 --- a/lib/jcw/wrapper.rb +++ b/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" From 5745acce69f7bf25bd24b4da430251a65183efc7 Mon Sep 17 00:00:00 2001 From: ash Date: Mon, 4 Oct 2021 17:10:31 +0300 Subject: [PATCH 2/7] Bump nokogiri. --- Gemfile.lock | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/Gemfile.lock b/Gemfile.lock index b9c586b..8235a04 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -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) From 9e50881e1a29474f2d3b5d285c470cb9328476e0 Mon Sep 17 00:00:00 2001 From: ash Date: Mon, 4 Oct 2021 17:24:12 +0300 Subject: [PATCH 3/7] Better readability. --- lib/jcw/subscriber.rb | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/lib/jcw/subscriber.rb b/lib/jcw/subscriber.rb index 73ace93..60970ec 100644 --- a/lib/jcw/subscriber.rb +++ b/lib/jcw/subscriber.rb @@ -15,7 +15,9 @@ def subscribe_to_event!(event) def add(name, _started, _finished, _unique_id, data) # skip Rails internal events return if name.start_with?("!") - return if (span = OpenTracing.scope_manager.active&.span).blank? + + span = OpenTracing.scope_manager.active&.span + return if span.blank? if data.is_a?(Hash) # we should only mutate the copy of the data From 02d49883bb71f144b60a02ba24863a094a2828a6 Mon Sep 17 00:00:00 2001 From: ash Date: Mon, 4 Oct 2021 17:28:16 +0300 Subject: [PATCH 4/7] Fix constant naming. --- lib/jcw/subscriber.rb | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/jcw/subscriber.rb b/lib/jcw/subscriber.rb index 60970ec..ef2d88a 100644 --- a/lib/jcw/subscriber.rb +++ b/lib/jcw/subscriber.rb @@ -4,7 +4,7 @@ module JCW module Subscriber extend self - IGNORED_DATA_TYPES = %i[request response headers exception exception_object].freeze + IGNORED_DATA_KEYS = %i[request response headers exception exception_object].freeze def subscribe_to_event!(event) ActiveSupport::Notifications.subscribe(event) do |name, started, finished, unique_id, data| @@ -22,7 +22,7 @@ def add(name, _started, _finished, _unique_id, data) if data.is_a?(Hash) # we should only mutate the copy of the data data = data.dup - IGNORED_DATA_TYPES.each { |key| data.delete(key) if data.key?(key) } # cleanup data + IGNORED_DATA_KEYS.each { |key| data.delete(key) if data.key?(key) } # cleanup data end span.log_kv(message: name, context: JSON.dump(data)) From aaef58daba2ac18409dea3174ff9b00591eeca51 Mon Sep 17 00:00:00 2001 From: ash Date: Mon, 4 Oct 2021 22:19:20 +0300 Subject: [PATCH 5/7] Fix specs for common use. --- spec/jcw_spec.rb | 40 +++++++++++++++++----------------------- 1 file changed, 17 insertions(+), 23 deletions(-) diff --git a/spec/jcw_spec.rb b/spec/jcw_spec.rb index 29be373..9daf8fd 100644 --- a/spec/jcw_spec.rb +++ b/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,37 +26,32 @@ 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 @@ -64,10 +59,10 @@ def set_jaeger 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("process_action.action_controller") + expect(ActiveSupport::Notifications).not_to \ + receive(:subscribe).with("start_processing.action_controller") set_jaeger end end @@ -120,8 +115,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", From 64314348a6fef2ab32ec359bdce48891b1e2cc88 Mon Sep 17 00:00:00 2001 From: ash Date: Mon, 4 Oct 2021 22:21:01 +0300 Subject: [PATCH 6/7] Fix specs for common use 2. --- spec/jcw_spec.rb | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/spec/jcw_spec.rb b/spec/jcw_spec.rb index 9daf8fd..43f81e4 100644 --- a/spec/jcw_spec.rb +++ b/spec/jcw_spec.rb @@ -51,7 +51,6 @@ def set_jaeger specify "set subscribers" do expect(ActiveSupport::Notifications).to receive(:subscribe).with(/.*/) - set_jaeger end @@ -59,10 +58,7 @@ def set_jaeger 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 From 3376a1947d95f4eea107438366f1d20bdfcad596 Mon Sep 17 00:00:00 2001 From: ash Date: Mon, 4 Oct 2021 22:34:51 +0300 Subject: [PATCH 7/7] Better naming in AS style. --- lib/jcw/subscriber.rb | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/lib/jcw/subscriber.rb b/lib/jcw/subscriber.rb index ef2d88a..ed18748 100644 --- a/lib/jcw/subscriber.rb +++ b/lib/jcw/subscriber.rb @@ -4,28 +4,28 @@ module JCW module Subscriber extend self - IGNORED_DATA_KEYS = %i[request response headers exception exception_object].freeze + IGNORED_PAYLOAD_KEYS = %i[request response headers exception exception_object].freeze def subscribe_to_event!(event) - ActiveSupport::Notifications.subscribe(event) do |name, started, finished, unique_id, data| - add(name, started, finished, unique_id, data) + ActiveSupport::Notifications.subscribe(event) do |name, _start, _finish, _uid, payload| + add(name, payload) end end - def add(name, _started, _finished, _unique_id, data) + def add(name, payload) # skip Rails internal events return if name.start_with?("!") span = OpenTracing.scope_manager.active&.span return if span.blank? - if data.is_a?(Hash) - # we should only mutate the copy of the data - data = data.dup - IGNORED_DATA_KEYS.each { |key| data.delete(key) if data.key?(key) } # cleanup data + 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(data)) + span.log_kv(message: name, context: JSON.dump(payload)) end end end