From c1d19572c6c7a022f3a04d90177cab36d570457f Mon Sep 17 00:00:00 2001 From: Mariusz Hausenplas Date: Tue, 21 Aug 2018 19:02:50 +0200 Subject: [PATCH] Add support for Action Cable Refactor log subscribers & create a new one to support logging of Action Cable events Monkey-patch Action Cable server class to silence default Action Cable logger Monkey-patch Action Cable Channel and Connection classes to support logging subscribe, unsubscribe, connect & disconnect events Update log formatters to support Action Cable log data --- lib/lograge.rb | 43 ++- lib/lograge/formatters/graylog2.rb | 4 +- .../formatters/helpers/method_and_path.rb | 12 + lib/lograge/formatters/logstash.rb | 4 +- lib/lograge/log_subscriber.rb | 121 -------- lib/lograge/log_subscribers/action_cable.rb | 32 +++ .../log_subscribers/action_controller.rb | 73 +++++ lib/lograge/log_subscribers/base.rb | 70 +++++ .../rails_ext/action_cable/channel/base.rb | 30 ++ .../rails_ext/action_cable/connection/base.rb | 42 +++ .../rails_ext/action_cable/server/base.rb | 8 + lib/lograge/silent_logger.rb | 11 + .../helpers/method_and_path_spec.rb | 41 +++ spec/log_subscribers/action_cable_spec.rb | 264 ++++++++++++++++++ .../action_controller_spec.rb} | 6 +- spec/silent_logger_spec.rb | 14 + 16 files changed, 639 insertions(+), 136 deletions(-) create mode 100644 lib/lograge/formatters/helpers/method_and_path.rb delete mode 100644 lib/lograge/log_subscriber.rb create mode 100644 lib/lograge/log_subscribers/action_cable.rb create mode 100644 lib/lograge/log_subscribers/action_controller.rb create mode 100644 lib/lograge/log_subscribers/base.rb create mode 100644 lib/lograge/rails_ext/action_cable/channel/base.rb create mode 100644 lib/lograge/rails_ext/action_cable/connection/base.rb create mode 100644 lib/lograge/rails_ext/action_cable/server/base.rb create mode 100644 lib/lograge/silent_logger.rb create mode 100644 spec/formatters/helpers/method_and_path_spec.rb create mode 100644 spec/log_subscribers/action_cable_spec.rb rename spec/{lograge_logsubscriber_spec.rb => log_subscribers/action_controller_spec.rb} (98%) create mode 100644 spec/silent_logger_spec.rb diff --git a/lib/lograge.rb b/lib/lograge.rb index b7376f5d..5787e11b 100644 --- a/lib/lograge.rb +++ b/lib/lograge.rb @@ -1,4 +1,5 @@ require 'lograge/version' +require 'lograge/formatters/helpers/method_and_path' require 'lograge/formatters/cee' require 'lograge/formatters/json' require 'lograge/formatters/graylog2' @@ -8,11 +9,19 @@ require 'lograge/formatters/logstash' require 'lograge/formatters/ltsv' require 'lograge/formatters/raw' -require 'lograge/log_subscriber' +require 'lograge/log_subscribers/base' +require 'lograge/log_subscribers/action_cable' +require 'lograge/log_subscribers/action_controller' +require 'lograge/silent_logger' require 'lograge/ordered_options' require 'active_support/core_ext/module/attribute_accessors' require 'active_support/core_ext/string/inflections' +if defined?(ActionCable) + require 'lograge/rails_ext/action_cable/channel/base' + require 'lograge/rails_ext/action_cable/connection/base' +end + # rubocop:disable ModuleLength module Lograge module_function @@ -63,10 +72,14 @@ def before_format(data, payload) def ignore_actions(actions) ignore(lambda do |event| params = event.payload - Array(actions).include?("#{params[:controller]}##{params[:action]}") + Array(actions).include?("#{controller_field(params)}##{params[:action]}") end) end + def controller_field(params) + params[:controller] || params[:channel_class] || params[:connection_class] + end + def ignore_tests @ignore_tests ||= [] end @@ -122,6 +135,8 @@ def setup(app) keep_original_rails_log attach_to_action_controller + attach_to_action_cable if defined?(ActionCable) + set_lograge_log_options setup_custom_payload support_deprecated_config # TODO: Remove with version 1.0 @@ -139,24 +154,29 @@ def set_formatter end def attach_to_action_controller - Lograge::RequestLogSubscriber.attach_to :action_controller + Lograge::LogSubscribers::ActionController.attach_to :action_controller + end + + def attach_to_action_cable + Lograge::LogSubscribers::ActionCable.attach_to :action_cable end def setup_custom_payload return unless lograge_config.custom_payload_method.respond_to?(:call) - base_controller_classes = Array(lograge_config.base_controller_class) - base_controller_classes.map! { |klass| klass.try(:constantize) } - if base_controller_classes.empty? - base_controller_classes << ActionController::Base + base_classes = Array(lograge_config.base_controller_class) + base_classes.map! { |klass| klass.try(:constantize) } + if base_classes.empty? + base_classes << ActionController::Base + base_classes << ActionCable::Channel::Base if defined?(ActionCable) end - base_controller_classes.each do |base_controller_class| - extend_base_controller_class(base_controller_class) + base_classes.each do |base_class| + extend_base_class(base_class) end end - def extend_base_controller_class(klass) + def extend_base_class(klass) append_payload_method = klass.instance_method(:append_info_to_payload) custom_payload_method = lograge_config.custom_payload_method @@ -181,6 +201,9 @@ def keep_original_rails_log return if lograge_config.keep_original_rails_log require 'lograge/rails_ext/rack/logger' + + require 'lograge/rails_ext/action_cable/server/base' if defined?(ActionCable) + Lograge.remove_existing_log_subscriptions end diff --git a/lib/lograge/formatters/graylog2.rb b/lib/lograge/formatters/graylog2.rb index d20be24b..341ce4e5 100644 --- a/lib/lograge/formatters/graylog2.rb +++ b/lib/lograge/formatters/graylog2.rb @@ -1,6 +1,8 @@ module Lograge module Formatters class Graylog2 + include Lograge::Formatters::Helpers::MethodAndPath + def call(data) # Cloning because we don't want to mess with the original when mutating keys. data_clone = data.clone @@ -23,7 +25,7 @@ def underscore_prefix(key) end def short_message(data) - "[#{data[:status]}] #{data[:method]} #{data[:path]} (#{data[:controller]}##{data[:action]})" + "[#{data[:status]}]#{method_and_path_string(data)}(#{data[:controller]}##{data[:action]})" end end end diff --git a/lib/lograge/formatters/helpers/method_and_path.rb b/lib/lograge/formatters/helpers/method_and_path.rb new file mode 100644 index 00000000..23a1f709 --- /dev/null +++ b/lib/lograge/formatters/helpers/method_and_path.rb @@ -0,0 +1,12 @@ +module Lograge + module Formatters + module Helpers + module MethodAndPath + def method_and_path_string(data) + method_and_path = [data[:method], data[:path]].compact + method_and_path.any?(&:present?) ? " #{method_and_path.join(' ')} " : ' ' + end + end + end + end +end diff --git a/lib/lograge/formatters/logstash.rb b/lib/lograge/formatters/logstash.rb index 208ce86f..2c3702ed 100644 --- a/lib/lograge/formatters/logstash.rb +++ b/lib/lograge/formatters/logstash.rb @@ -1,11 +1,13 @@ module Lograge module Formatters class Logstash + include Lograge::Formatters::Helpers::MethodAndPath + def call(data) load_dependencies event = LogStash::Event.new(data) - event['message'] = "[#{data[:status]}] #{data[:method]} #{data[:path]} (#{data[:controller]}##{data[:action]})" + event['message'] = "[#{data[:status]}]#{method_and_path_string(data)}(#{data[:controller]}##{data[:action]})" event.to_json end diff --git a/lib/lograge/log_subscriber.rb b/lib/lograge/log_subscriber.rb deleted file mode 100644 index ebb5b702..00000000 --- a/lib/lograge/log_subscriber.rb +++ /dev/null @@ -1,121 +0,0 @@ -require 'json' -require 'action_pack' -require 'active_support/core_ext/class/attribute' -require 'active_support/log_subscriber' -require 'request_store' - -module Lograge - class RequestLogSubscriber < ActiveSupport::LogSubscriber - def process_action(event) - return if Lograge.ignore?(event) - - payload = event.payload - data = extract_request(event, payload) - data = before_format(data, payload) - formatted_message = Lograge.formatter.call(data) - logger.send(Lograge.log_level, formatted_message) - end - - def redirect_to(event) - RequestStore.store[:lograge_location] = event.payload[:location] - end - - def unpermitted_parameters(event) - RequestStore.store[:lograge_unpermitted_params] ||= [] - RequestStore.store[:lograge_unpermitted_params].concat(event.payload[:keys]) - end - - def logger - Lograge.logger.presence || super - end - - private - - def extract_request(event, payload) - data = initial_data(payload) - data.merge!(extract_status(payload)) - data.merge!(extract_runtimes(event, payload)) - data.merge!(extract_location) - data.merge!(extract_unpermitted_params) - data.merge!(custom_options(event)) - end - - def initial_data(payload) - { - method: payload[:method], - path: extract_path(payload), - format: extract_format(payload), - controller: payload[:controller], - action: payload[:action] - } - end - - def extract_path(payload) - path = payload[:path] - strip_query_string(path) - end - - def strip_query_string(path) - index = path.index('?') - index ? path[0, index] : path - end - - if ::ActionPack::VERSION::MAJOR == 3 && ::ActionPack::VERSION::MINOR.zero? - def extract_format(payload) - payload[:formats].first - end - else - def extract_format(payload) - payload[:format] - end - end - - def extract_status(payload) - if (status = payload[:status]) - { status: status.to_i } - elsif (error = payload[:exception]) - exception, message = error - { status: get_error_status_code(exception), error: "#{exception}: #{message}" } - else - { status: 0 } - end - end - - def get_error_status_code(exception) - status = ActionDispatch::ExceptionWrapper.rescue_responses[exception] - Rack::Utils.status_code(status) - end - - def custom_options(event) - options = Lograge.custom_options(event) || {} - options.merge event.payload[:custom_payload] || {} - end - - def before_format(data, payload) - Lograge.before_format(data, payload) - end - - def extract_runtimes(event, payload) - data = { duration: event.duration.to_f.round(2) } - data[:view] = payload[:view_runtime].to_f.round(2) if payload.key?(:view_runtime) - data[:db] = payload[:db_runtime].to_f.round(2) if payload.key?(:db_runtime) - data - end - - def extract_location - location = RequestStore.store[:lograge_location] - return {} unless location - - RequestStore.store[:lograge_location] = nil - { location: strip_query_string(location) } - end - - def extract_unpermitted_params - unpermitted_params = RequestStore.store[:lograge_unpermitted_params] - return {} unless unpermitted_params - - RequestStore.store[:lograge_unpermitted_params] = nil - { unpermitted_params: unpermitted_params } - end - end -end diff --git a/lib/lograge/log_subscribers/action_cable.rb b/lib/lograge/log_subscribers/action_cable.rb new file mode 100644 index 00000000..ebf105f3 --- /dev/null +++ b/lib/lograge/log_subscribers/action_cable.rb @@ -0,0 +1,32 @@ +module Lograge + module LogSubscribers + class ActionCable < Base + %i(perform_action subscribe unsubscribe connect disconnect).each do |method_name| + define_method(method_name) do |event| + process_main_event(event) + end + end + + private + + def initial_data(payload) + { + method: {}, + path: {}, + format: {}, + params: payload[:data], + controller: payload[:channel_class] || payload[:connection_class], + action: payload[:action] + } + end + + def default_status + 200 + end + + def extract_runtimes(event, _payload) + { duration: event.duration.to_f.round(2) } + end + end + end +end diff --git a/lib/lograge/log_subscribers/action_controller.rb b/lib/lograge/log_subscribers/action_controller.rb new file mode 100644 index 00000000..007239bc --- /dev/null +++ b/lib/lograge/log_subscribers/action_controller.rb @@ -0,0 +1,73 @@ +module Lograge + module LogSubscribers + class ActionController < Base + def process_action(event) + process_main_event(event) + end + + def redirect_to(event) + RequestStore.store[:lograge_location] = event.payload[:location] + end + + def unpermitted_parameters(event) + RequestStore.store[:lograge_unpermitted_params] ||= [] + RequestStore.store[:lograge_unpermitted_params].concat(event.payload[:keys]) + end + + private + + def initial_data(payload) + { + method: payload[:method], + path: extract_path(payload), + format: extract_format(payload), + controller: payload[:controller], + action: payload[:action] + } + end + + def extract_path(payload) + path = payload[:path] + strip_query_string(path) + end + + def strip_query_string(path) + index = path.index('?') + index ? path[0, index] : path + end + + if ::ActionPack::VERSION::MAJOR == 3 && ::ActionPack::VERSION::MINOR.zero? + def extract_format(payload) + payload[:formats].first + end + else + def extract_format(payload) + payload[:format] + end + end + + def extract_runtimes(event, payload) + data = { duration: event.duration.to_f.round(2) } + data[:view] = payload[:view_runtime].to_f.round(2) if payload.key?(:view_runtime) + data[:db] = payload[:db_runtime].to_f.round(2) if payload.key?(:db_runtime) + data + end + + def extract_location + location = RequestStore.store[:lograge_location] + return {} unless location + + RequestStore.store[:lograge_location] = nil + { location: strip_query_string(location) } + end + + def extract_unpermitted_params + unpermitted_params = RequestStore.store[:lograge_unpermitted_params] + return {} unless unpermitted_params + + RequestStore.store[:lograge_unpermitted_params] = nil + { unpermitted_params: unpermitted_params } + end + end + end +end diff --git a/lib/lograge/log_subscribers/base.rb b/lib/lograge/log_subscribers/base.rb new file mode 100644 index 00000000..ae62623a --- /dev/null +++ b/lib/lograge/log_subscribers/base.rb @@ -0,0 +1,70 @@ +require 'json' +require 'action_pack' +require 'active_support/core_ext/class/attribute' +require 'active_support/log_subscriber' +require 'request_store' + +module Lograge + module LogSubscribers + class Base < ActiveSupport::LogSubscriber + def logger + Lograge.logger.presence || super + end + + private + + def process_main_event(event) + return if Lograge.ignore?(event) + + payload = event.payload + data = extract_request(event, payload) + data = before_format(data, payload) + formatted_message = Lograge.formatter.call(data) + logger.send(Lograge.log_level, formatted_message) + end + + def extract_request(event, payload) + data = initial_data(payload) + data.merge!(extract_status(payload)) + data.merge!(extract_runtimes(event, payload)) + data.merge!(extract_location) + data.merge!(extract_unpermitted_params) + data.merge!(custom_options(event)) + end + + %i(initial_data extract_status extract_runtimes + extract_location extract_unpermitted_params).each do |method_name| + define_method(method_name) { |*_arg| {} } + end + + def extract_status(payload) + if (status = payload[:status]) + { status: status.to_i } + elsif (error = payload[:exception]) + exception, message = error + { status: get_error_status_code(exception), error: "#{exception}: #{message}" } + else + { status: default_status } + end + end + + def default_status + 0 + end + + def get_error_status_code(exception) + status = ActionDispatch::ExceptionWrapper.rescue_responses[exception] + Rack::Utils.status_code(status) + end + + def custom_options(event) + options = Lograge.custom_options(event) || {} + options.merge event.payload[:custom_payload] || {} + end + + def before_format(data, payload) + Lograge.before_format(data, payload) + end + end + end +end diff --git a/lib/lograge/rails_ext/action_cable/channel/base.rb b/lib/lograge/rails_ext/action_cable/channel/base.rb new file mode 100644 index 00000000..31286629 --- /dev/null +++ b/lib/lograge/rails_ext/action_cable/channel/base.rb @@ -0,0 +1,30 @@ +module ActionCable + module Channel + class Base + def subscribe_to_channel + ActiveSupport::Notifications.instrument('subscribe.action_cable', notification_payload('subscribe')) do + run_callbacks :subscribe do + subscribed + end + + reject_subscription if subscription_rejected? + ensure_confirmation_sent + end + end + + def unsubscribe_from_channel + ActiveSupport::Notifications.instrument('unsubscribe.action_cable', notification_payload('unsubscribe')) do + run_callbacks :unsubscribe do + unsubscribed + end + end + end + + private + + def notification_payload(method_name) + { channel_class: self.class.name, action: method_name } + end + end + end +end diff --git a/lib/lograge/rails_ext/action_cable/connection/base.rb b/lib/lograge/rails_ext/action_cable/connection/base.rb new file mode 100644 index 00000000..8f7c512f --- /dev/null +++ b/lib/lograge/rails_ext/action_cable/connection/base.rb @@ -0,0 +1,42 @@ +module ActionCable + module Connection + class Base + # rubocop:disable Metrics/MethodLength + def handle_open + ActiveSupport::Notifications.instrument('connect.action_cable', notification_payload('connect')) do + begin + @protocol = websocket.protocol + connect if respond_to?(:connect) + subscribe_to_internal_channel + send_welcome_message + + message_buffer.process! + server.add_connection(self) + rescue ActionCable::Connection::Authorization::UnauthorizedError + respond_to_invalid_request + end + end + end + # rubocop:enable Metrics/MethodLength + + def handle_close + ActiveSupport::Notifications.instrument('disconnect.action_cable', notification_payload('disconnect')) do + logger.info finished_request_message if Lograge.lograge_config.keep_original_rails_log + + server.remove_connection(self) + + subscriptions.unsubscribe_from_all + unsubscribe_from_internal_channel + + disconnect if respond_to?(:disconnect) + end + end + + private + + def notification_payload(method_name) + { connection_class: self.class.name, action: method_name, data: request.params } + end + end + end +end diff --git a/lib/lograge/rails_ext/action_cable/server/base.rb b/lib/lograge/rails_ext/action_cable/server/base.rb new file mode 100644 index 00000000..b206b695 --- /dev/null +++ b/lib/lograge/rails_ext/action_cable/server/base.rb @@ -0,0 +1,8 @@ +module ActionCable + module Server + class Base + mattr_accessor :logger + self.logger = Lograge::SilentLogger.new(config.logger) + end + end +end diff --git a/lib/lograge/silent_logger.rb b/lib/lograge/silent_logger.rb new file mode 100644 index 00000000..2d027e13 --- /dev/null +++ b/lib/lograge/silent_logger.rb @@ -0,0 +1,11 @@ +module Lograge + class SilentLogger < SimpleDelegator + def initialize(logger) + super + end + + %i(debug info warn error fatal unknown).each do |method_name| + define_method(method_name) { |*_args| } + end + end +end diff --git a/spec/formatters/helpers/method_and_path_spec.rb b/spec/formatters/helpers/method_and_path_spec.rb new file mode 100644 index 00000000..b5d38590 --- /dev/null +++ b/spec/formatters/helpers/method_and_path_spec.rb @@ -0,0 +1,41 @@ +describe Lograge::Formatters::Helpers::MethodAndPath do + describe '#method_and_path_string' do + let(:instance) do + Object.new.extend(described_class) + end + + let(:method_and_path_string) { instance.method_and_path_string(data) } + + context "when both 'method' and 'path' fields are blank" do + let(:data) { {} } + + it 'returns single space' do + expect(method_and_path_string).to eq(' ') + end + end + + context "when 'method' field is present" do + let(:data) { { method: 'GET' } } + + it "returns 'method' value surrounded with spaces" do + expect(method_and_path_string).to eq(' GET ') + end + end + + context "when 'path' field is present" do + let(:data) { { path: '/foo' } } + + it "returns 'path' value surrounded by spaces" do + expect(method_and_path_string).to eq(' /foo ') + end + end + + context "when both 'method' and path' fields are present" do + let(:data) { { method: 'index', path: '/foo' } } + + it 'returns string surrounded by spaces with both fields separated with a space ' do + expect(method_and_path_string).to eq(' index /foo ') + end + end + end +end diff --git a/spec/log_subscribers/action_cable_spec.rb b/spec/log_subscribers/action_cable_spec.rb new file mode 100644 index 00000000..aa2ad34f --- /dev/null +++ b/spec/log_subscribers/action_cable_spec.rb @@ -0,0 +1,264 @@ +require 'lograge/log_subscribers/action_controller' +require 'active_support/notifications' +require 'active_support/core_ext/string' +require 'logger' +require 'active_record' +require 'rails' + +describe Lograge::LogSubscribers::ActionCable do + let(:log_output) { StringIO.new } + let(:logger) do + Logger.new(log_output).tap { |logger| logger.formatter = ->(_, _, _, msg) { msg } } + end + + let(:subscriber) { Lograge::LogSubscribers::ActionCable.new } + let(:event_params) { { 'foo' => 'bar' } } + + let(:event) do + ActiveSupport::Notifications::Event.new( + 'perform_action.action_cable', + Time.now, + Time.now, + 2, + channel_class: 'ActionCableChannel', + data: event_params, + action: 'pong' + ) + end + + before { Lograge.logger = logger } + + context 'with custom_options configured for cee output' do + before do + Lograge.formatter = ->(data) { "My test: #{data}" } + end + + it 'combines the hash properly for the output' do + Lograge.custom_options = { data: 'value' } + subscriber.perform_action(event) + expect(log_output.string).to match(/^My test: {.*:data=>"value"/) + end + + it 'combines the output of a lambda properly' do + Lograge.custom_options = ->(_event) { { data: 'value' } } + + subscriber.perform_action(event) + expect(log_output.string).to match(/^My test: {.*:data=>"value"/) + end + + it 'works when the method returns nil' do + Lograge.custom_options = ->(_event) { nil } + + subscriber.perform_action(event) + expect(log_output.string).to be_present + end + end + + context 'when processing an action with lograge output' do + before do + Lograge.formatter = Lograge::Formatters::KeyValue.new + end + + it 'includes the controller and action' do + subscriber.perform_action(event) + expect(log_output.string).to include('controller=ActionCableChannel action=pong') + end + + it 'includes the duration' do + subscriber.perform_action(event) + expect(log_output.string).to match(/duration=[\.0-9]{2,4}/) + end + + context 'when an `ActiveRecord::RecordNotFound` is raised' do + let(:exception) { 'ActiveRecord::RecordNotFound' } + + before do + ActionDispatch::ExceptionWrapper.rescue_responses[exception] = :not_found + event.payload[:exception] = [exception, 'Record not found'] + event.payload[:status] = nil + end + + it 'adds a 404 status' do + subscriber.perform_action(event) + expect(log_output.string).to match(/status=404 /) + expect(log_output.string).to match( + /error='ActiveRecord::RecordNotFound: Record not found' / + ) + end + end + + it 'returns a default status when no status or exception is found' do + event.payload[:status] = nil + event.payload[:exception] = nil + subscriber.perform_action(event) + expect(log_output.string).to match(/status=200 /) + end + + it 'does not include a location by default' do + subscriber.perform_action(event) + expect(log_output.string).to_not include('location=') + end + end + + context 'with custom_options configured for lograge output' do + before do + Lograge.formatter = Lograge::Formatters::KeyValue.new + end + + it 'combines the hash properly for the output' do + Lograge.custom_options = { data: 'value' } + subscriber.perform_action(event) + expect(log_output.string).to match(/ data=value/) + end + + it 'combines the output of a lambda properly' do + Lograge.custom_options = ->(_event) { { data: 'value' } } + + subscriber.perform_action(event) + expect(log_output.string).to match(/ data=value/) + end + it 'works when the method returns nil' do + Lograge.custom_options = ->(_event) { nil } + + subscriber.perform_action(event) + expect(log_output.string).to be_present + end + end + + context 'when event payload includes a "custom_payload"' do + before do + Lograge.formatter = Lograge::Formatters::KeyValue.new + end + + it 'incorporates the payload correctly' do + event.payload[:custom_payload] = { data: 'value' } + + subscriber.perform_action(event) + expect(log_output.string).to match(/ data=value/) + end + + it 'works when custom_payload is nil' do + event.payload[:custom_payload] = nil + + subscriber.perform_action(event) + expect(log_output.string).to be_present + end + end + + context 'with before_format configured for lograge output' do + before do + Lograge.formatter = Lograge::Formatters::KeyValue.new + Lograge.before_format = nil + end + + it 'outputs correctly' do + Lograge.before_format = ->(data, payload) { { status: data[:status] }.merge(action: payload[:action]) } + + subscriber.perform_action(event) + + expect(log_output.string).to include('action=pong') + expect(log_output.string).to include('status=200') + end + it 'works if the method returns nil' do + Lograge.before_format = ->(_data, _payload) { nil } + + subscriber.perform_action(event) + expect(log_output.string).to be_present + end + end + + context 'with ignore configured' do + before do + Lograge.ignore_nothing + end + + it 'does not log ignored controller actions given a single ignored action' do + Lograge.ignore_actions 'ActionCableChannel#pong' + subscriber.perform_action(event) + expect(log_output.string).to be_blank + end + + it 'does not log ignored controller actions given a single ignored action after a custom ignore' do + Lograge.ignore(->(_event) { false }) + + Lograge.ignore_actions 'ActionCableChannel#pong' + subscriber.perform_action(event) + expect(log_output.string).to be_blank + end + + it 'logs non-ignored controller actions given a single ignored action' do + Lograge.ignore_actions 'ActionCableChannel#bar' + subscriber.perform_action(event) + expect(log_output.string).to be_present + end + + it 'does not log ignored controller actions given multiple ignored actions' do + Lograge.ignore_actions ['ActionCableChannel#bar', 'ActionCableChannel#pong', 'OtherChannel#foo'] + subscriber.perform_action(event) + expect(log_output.string).to be_blank + end + + it 'logs non-ignored controller actions given multiple ignored actions' do + Lograge.ignore_actions ['ActionCableChannel#bar', 'OtherChannel#foo'] + subscriber.perform_action(event) + expect(log_output.string).to_not be_blank + end + + it 'does not log ignored events' do + Lograge.ignore(->(event) { 'pong' == event.payload[:action] }) + + subscriber.perform_action(event) + expect(log_output.string).to be_blank + end + + it 'logs non-ignored events' do + Lograge.ignore(->(event) { 'foo' == event.payload[:action] }) + + subscriber.perform_action(event) + expect(log_output.string).not_to be_blank + end + + it 'does not choke on nil ignore_actions input' do + Lograge.ignore_actions nil + subscriber.perform_action(event) + expect(log_output.string).not_to be_blank + end + + it 'does not choke on nil ignore input' do + Lograge.ignore nil + subscriber.perform_action(event) + expect(log_output.string).not_to be_blank + end + end + + describe 'other actions' do + %i(subscribe unsubscribe connect disconnect).each do |action_name| + let(:event) do + ActiveSupport::Notifications::Event.new( + "#{action_name}.action_cable", + Time.now, + Time.now, + 2, + channel_class: 'ActionCableChannel', + data: event_params, + action: 'pong' + ) + end + + it 'generates output' do + subscriber.perform_action(event) + expect(log_output.string).to include('controller=ActionCableChannel action=pong') + end + end + end + + it "will fallback to ActiveSupport's logger if one isn't configured" do + Lograge.formatter = Lograge::Formatters::KeyValue.new + Lograge.logger = nil + ActiveSupport::LogSubscriber.logger = logger + + subscriber.perform_action(event) + + expect(log_output.string).to be_present + end +end diff --git a/spec/lograge_logsubscriber_spec.rb b/spec/log_subscribers/action_controller_spec.rb similarity index 98% rename from spec/lograge_logsubscriber_spec.rb rename to spec/log_subscribers/action_controller_spec.rb index 46785110..ea06d300 100644 --- a/spec/lograge_logsubscriber_spec.rb +++ b/spec/log_subscribers/action_controller_spec.rb @@ -1,17 +1,17 @@ -require 'lograge/log_subscriber' +require 'lograge/log_subscribers/action_controller' require 'active_support/notifications' require 'active_support/core_ext/string' require 'logger' require 'active_record' require 'rails' -describe Lograge::RequestLogSubscriber do +describe Lograge::LogSubscribers::ActionController do let(:log_output) { StringIO.new } let(:logger) do Logger.new(log_output).tap { |logger| logger.formatter = ->(_, _, _, msg) { msg } } end - let(:subscriber) { Lograge::RequestLogSubscriber.new } + let(:subscriber) { Lograge::LogSubscribers::ActionController.new } let(:event_params) { { 'foo' => 'bar' } } let(:event) do diff --git a/spec/silent_logger_spec.rb b/spec/silent_logger_spec.rb new file mode 100644 index 00000000..1aac31c4 --- /dev/null +++ b/spec/silent_logger_spec.rb @@ -0,0 +1,14 @@ +require 'logger' + +describe Lograge::SilentLogger do + let(:base_logger) { Logger.new(STDOUT) } + subject(:silent_logger) { described_class.new(base_logger) } + + it "doesn't call base logger on either log method" do + %i(debug info warn error fatal unknown).each do |method_name| + expect(base_logger).not_to receive(method_name) + + silent_logger.public_send(method_name) + end + end +end