diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 4d17062..2255bcb 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -12,36 +12,29 @@ jobs: fail-fast: false matrix: include: - - rails: 5.1 - ruby: 2.5 - - - rails: 5.2 - ruby: 2.5 - - rails: 5.2 - ruby: 2.6 - - rails: 5.2 - ruby: jruby-9.3 - - - rails: "6.0" - ruby: 2.6 - rails: "6.0" - ruby: 2.7 - - rails: "6.0" - ruby: jruby + ruby: "2.7" - rails: "6.1" ruby: "2.7" - rails: "6.1" - ruby: jruby - - - rails: "7.0" ruby: "3.0" + - rails: "6.1" + ruby: "3.1" + - rails: "6.1" + ruby: "3.2" + - rails: "7.0" - ruby: 3.1 - - rails: "7.0" - ruby: 3.2 + ruby: "3.1" - rails: "7.0" - ruby: jruby + ruby: "3.2" + + - rails: "7.1" + ruby: "3.1" + - rails: "7.1.1" + ruby: "3.2" + - rails: "7.1" + ruby: "3.2" env: BUNDLE_GEMFILE: gemfiles/rails_${{ matrix.rails }}.gemfile diff --git a/.gitignore b/.gitignore index 7342460..81e76a9 100644 --- a/.gitignore +++ b/.gitignore @@ -2,6 +2,7 @@ *.log pkg/ test/dummy/tmp/ +test/dummy/db/test.sqlite3-* test/dummy/.sass-cache *.gem /.idea @@ -12,6 +13,5 @@ Gemfile.lock *.sqlite3 .rakeTasks -*.sqlite3 TODO.md diff --git a/.rubocop.yml b/.rubocop.yml index 6c7f1ee..3465c71 100644 --- a/.rubocop.yml +++ b/.rubocop.yml @@ -1,9 +1,10 @@ AllCops: - TargetRubyVersion: 2.4 Exclude: - - '.git/**/*' - - '.github/**/*' - - 'gemfiles/**/*' + - ".git/**/*" + - "docs/**/*" + - "gemfiles/*" + NewCops: enable + TargetRubyVersion: 2.5 # # RuboCop built-in settings. @@ -31,7 +32,7 @@ Layout/HashAlignment: Layout/LineLength: Max: 128 Exclude: - - '**/test/**/*' + - "**/test/**/*" # Match existing layout Layout/SpaceInsideHashLiteralBraces: @@ -44,17 +45,17 @@ Metrics/AbcSize: # Support long block lengths for tests Metrics/BlockLength: Exclude: - - 'test/**/*' - - '**/*/cli.rb' - ExcludedMethods: - - 'aasm' - - 'included' + - "test/**/*" + - "**/*/cli.rb" + AllowedMethods: + - "aasm" + - "included" # Soften limits Metrics/ClassLength: Max: 250 Exclude: - - 'test/**/*' + - "test/**/*" # TODO: Soften Limits for phase 1 only Metrics/CyclomaticComplexity: @@ -77,7 +78,7 @@ Metrics/PerceivedComplexity: # Initialization Vector abbreviation Naming/MethodParameterName: - AllowedNames: ['iv', '_', 'io', 'ap'] + AllowedNames: [ "iv", "_", "io", "ap", "id", "_id" ] # Does not allow Symbols to load Security/YAMLLoad: @@ -85,7 +86,7 @@ Security/YAMLLoad: # Needed for testing DateTime Style/DateTime: - Exclude: ['test/**/*'] + Exclude: [ "test/**/*" ] # TODO: Soften Limits for phase 1 only Style/Documentation: diff --git a/Appraisals b/Appraisals index 75860a2..ce550fc 100644 --- a/Appraisals +++ b/Appraisals @@ -1,33 +1,24 @@ -appraise "rails_5.1" do - gem "rails", "~> 5.1.5" - gem "sqlite3", "~> 1.3.0", platform: :ruby - gem "activerecord-jdbcsqlite3-adapter", "~> 51.0", platform: :jruby -end - -appraise "rails_5.2" do - gem "rails", "~> 5.2.0" - gem "sqlite3", "~> 1.3.0", platform: :ruby - gem "activerecord-jdbcsqlite3-adapter", "~> 52.0", platform: :jruby -end - appraise "rails_6.0" do gem "rails", "~> 6.0.0" - gem "activerecord-jdbcsqlite3-adapter", "~> 60.0", platform: :jruby gem "sqlite3", "~> 1.4.0", platform: :ruby end appraise "rails_6.1" do gem "rails", "~> 6.1.0" - gem "activerecord-jdbcsqlite3-adapter", "~> 61.0", platform: :jruby gem "sqlite3", "~> 1.4.0", platform: :ruby end appraise "rails_7.0" do - # Remove this deprecated gem once the following patch is released - # https://github.com/rails-api/active_model_serializers/pull/2428 - gem "thread_safe", "~> 0.3.6" - gem "rails", "~> 7.0.0" - gem "activerecord-jdbcsqlite3-adapter", "~> 70.0", platform: :jruby + gem "sqlite3", "~> 1.4.0", platform: :ruby +end + +appraise "rails_7.1.1" do + gem "rails", "7.1.1" + gem "sqlite3", "~> 1.4.0", platform: :ruby +end + +appraise "rails_7.1" do + gem "rails", "~> 7.1.0" gem "sqlite3", "~> 1.4.0", platform: :ruby end diff --git a/Gemfile b/Gemfile index b72a386..054e2bf 100644 --- a/Gemfile +++ b/Gemfile @@ -12,7 +12,7 @@ gem "minitest-rails" gem "rake" gem "sprockets", "< 4.0" -gem "rails", "~> 7.0.0" +gem "rails", "~> 7.1.0" gem "sqlite3", "~> 1.4.0", platform: :ruby gem "rubocop" diff --git a/gemfiles/rails_6.0.gemfile b/gemfiles/rails_6.0.gemfile index 2f4d738..29fbc06 100644 --- a/gemfiles/rails_6.0.gemfile +++ b/gemfiles/rails_6.0.gemfile @@ -10,13 +10,8 @@ gem "minitest" gem "minitest-rails" gem "rake" gem "sprockets", "< 4.0" -gem "semantic_logger", github: "reidmorrison/semantic_logger" gem "rails", "~> 6.0.0" gem "sqlite3", "~> 1.4.0", platform: :ruby -gem "activerecord-jdbcsqlite3-adapter", "~> 60.0", platform: :jruby - -group :development do - gem "rubocop" -end +gem "rubocop" gemspec path: "../" diff --git a/gemfiles/rails_6.1.gemfile b/gemfiles/rails_6.1.gemfile index 37c0074..16fc598 100644 --- a/gemfiles/rails_6.1.gemfile +++ b/gemfiles/rails_6.1.gemfile @@ -10,13 +10,8 @@ gem "minitest" gem "minitest-rails" gem "rake" gem "sprockets", "< 4.0" -gem "semantic_logger", github: "reidmorrison/semantic_logger" gem "rails", "~> 6.1.0" gem "sqlite3", "~> 1.4.0", platform: :ruby -gem "activerecord-jdbcsqlite3-adapter", "~> 61.0", platform: :jruby - -group :development do - gem "rubocop" -end +gem "rubocop" gemspec path: "../" diff --git a/gemfiles/rails_7.0.gemfile b/gemfiles/rails_7.0.gemfile index fe819a1..3d38acd 100644 --- a/gemfiles/rails_7.0.gemfile +++ b/gemfiles/rails_7.0.gemfile @@ -10,14 +10,8 @@ gem "minitest" gem "minitest-rails" gem "rake" gem "sprockets", "< 4.0" -gem "semantic_logger", github: "reidmorrison/semantic_logger" gem "rails", "~> 7.0.0" gem "sqlite3", "~> 1.4.0", platform: :ruby -gem "thread_safe", "~> 0.3.6" -gem "activerecord-jdbcsqlite3-adapter", "~> 70.0", platform: :jruby - -group :development do - gem "rubocop" -end +gem "rubocop" gemspec path: "../" diff --git a/gemfiles/rails_5.1.gemfile b/gemfiles/rails_7.1.1.gemfile similarity index 50% rename from gemfiles/rails_5.1.gemfile rename to gemfiles/rails_7.1.1.gemfile index 6001b83..12c543a 100644 --- a/gemfiles/rails_5.1.gemfile +++ b/gemfiles/rails_7.1.1.gemfile @@ -10,13 +10,8 @@ gem "minitest" gem "minitest-rails" gem "rake" gem "sprockets", "< 4.0" -gem "semantic_logger", github: "reidmorrison/semantic_logger" -gem "rails", "~> 5.1.5" -gem "sqlite3", "~> 1.3.0", platform: :ruby -gem "activerecord-jdbcsqlite3-adapter", "~> 51.0", platform: :jruby - -group :development do - gem "rubocop" -end +gem "rails", "7.1.1" +gem "sqlite3", "~> 1.4.0", platform: :ruby +gem "rubocop" gemspec path: "../" diff --git a/gemfiles/rails_5.2.gemfile b/gemfiles/rails_7.1.gemfile similarity index 50% rename from gemfiles/rails_5.2.gemfile rename to gemfiles/rails_7.1.gemfile index 7cdf14a..739d96c 100644 --- a/gemfiles/rails_5.2.gemfile +++ b/gemfiles/rails_7.1.gemfile @@ -10,13 +10,8 @@ gem "minitest" gem "minitest-rails" gem "rake" gem "sprockets", "< 4.0" -gem "semantic_logger", github: "reidmorrison/semantic_logger" -gem "rails", "~> 5.2.0" -gem "sqlite3", "~> 1.3.0", platform: :ruby -gem "activerecord-jdbcsqlite3-adapter", "~> 52.0", platform: :jruby - -group :development do - gem "rubocop" -end +gem "rails", "~> 7.1.0" +gem "sqlite3", "~> 1.4.0", platform: :ruby +gem "rubocop" gemspec path: "../" diff --git a/lib/rails_semantic_logger.rb b/lib/rails_semantic_logger.rb index e930fb2..5943cb1 100644 --- a/lib/rails_semantic_logger.rb +++ b/lib/rails_semantic_logger.rb @@ -6,21 +6,27 @@ module RailsSemanticLogger module ActionController autoload :LogSubscriber, "rails_semantic_logger/action_controller/log_subscriber" end + module ActionMailer autoload :LogSubscriber, "rails_semantic_logger/action_mailer/log_subscriber" end + module ActionView autoload :LogSubscriber, "rails_semantic_logger/action_view/log_subscriber" end + module ActiveJob autoload :LogSubscriber, "rails_semantic_logger/active_job/log_subscriber" end + module ActiveRecord autoload :LogSubscriber, "rails_semantic_logger/active_record/log_subscriber" end + module Rack autoload :Logger, "rails_semantic_logger/rack/logger" end + module DelayedJob autoload :Plugin, "rails_semantic_logger/delayed_job/plugin" end @@ -48,9 +54,11 @@ def self.unattach(subscriber) end def self.subscriber_patterns(subscriber) - subscriber.patterns.respond_to?(:keys) ? - subscriber.patterns.keys : + if subscriber.patterns.respond_to?(:keys) + subscriber.patterns.keys + else subscriber.patterns + end end private_class_method :subscriber_patterns, :unattach @@ -58,4 +66,9 @@ def self.subscriber_patterns(subscriber) require("rails_semantic_logger/extensions/mongoid/config") if defined?(Mongoid) require("rails_semantic_logger/extensions/active_support/logger") if defined?(ActiveSupport::Logger) -require("rails_semantic_logger/extensions/rack/server") if defined?(Rack::Server) +require("rails_semantic_logger/extensions/active_support/log_subscriber") if defined?(ActiveSupport::LogSubscriber) +if defined?(Rackup::Server) + require("rails_semantic_logger/extensions/rackup/server") +elsif defined?(Rack::Server) + require("rails_semantic_logger/extensions/rack/server") +end diff --git a/lib/rails_semantic_logger/action_controller/log_subscriber.rb b/lib/rails_semantic_logger/action_controller/log_subscriber.rb index 4aa26f9..80b9b5f 100644 --- a/lib/rails_semantic_logger/action_controller/log_subscriber.rb +++ b/lib/rails_semantic_logger/action_controller/log_subscriber.rb @@ -14,10 +14,10 @@ def process_action(event) # Unused, but needed for Devise 401 status code monkey patch to still work. ::ActionController::Base.log_process_action(payload) - + params = payload[:params] - if params.kind_of?(Hash) || params.kind_of?(::ActionController::Parameters) + if params.is_a?(Hash) || params.is_a?(::ActionController::Parameters) # According to PR https://github.com/reidmorrison/rails_semantic_logger/pull/37/files # params is not always a Hash. payload[:params] = params.to_unsafe_h unless params.is_a?(Hash) @@ -79,7 +79,9 @@ def redirect_to(event) end def send_data(event) - controller_logger(event).info(message: "Sent data", payload: {file_name: event.payload[:filename]}, duration: event.duration) + controller_logger(event).info(message: "Sent data", + payload: {file_name: event.payload[:filename]}, + duration: event.duration) end def unpermitted_parameters(event) diff --git a/lib/rails_semantic_logger/action_mailer/log_subscriber.rb b/lib/rails_semantic_logger/action_mailer/log_subscriber.rb index 423fb8b..be35b70 100644 --- a/lib/rails_semantic_logger/action_mailer/log_subscriber.rb +++ b/lib/rails_semantic_logger/action_mailer/log_subscriber.rb @@ -9,22 +9,22 @@ def deliver(event) message_id = event.payload[:message_id] duration = event.duration.round(1) if ex - log_with_formatter event: event, log_duration: true, level: :error do |fmt| + log_with_formatter event: event, log_duration: true, level: :error do |_fmt| { - message: "Error delivering mail #{message_id} (#{duration}ms)", + message: "Error delivering mail #{message_id} (#{duration}ms)", exception: ex } end else - message = begin + message = if event.payload[:perform_deliveries] "Delivered mail #{message_id} (#{duration}ms)" else "Skipped delivery of mail #{message_id} as `perform_deliveries` is false" end - end - log_with_formatter event: event, log_duration: true do |fmt| - { message: message } + + log_with_formatter event: event, log_duration: true do |_fmt| + {message: message} end end end @@ -34,8 +34,8 @@ def process(event) mailer = event.payload[:mailer] action = event.payload[:action] duration = event.duration.round(1) - log_with_formatter event: event do |fmt| - { message: "#{mailer}##{action}: processed outbound mail in #{duration}ms" } + log_with_formatter event: event do |_fmt| + {message: "#{mailer}##{action}: processed outbound mail in #{duration}ms"} end end @@ -74,8 +74,6 @@ def date event.payload[:date].to_time.utc elsif event.payload[:date].is_a?(String) Time.parse(date).utc - else - nil end end @@ -92,10 +90,10 @@ def action end def formatted_args - if defined?(mailer.contantize.log_arguments?) && !mailer.contantize.log_arguments? + if defined?(mailer.constantize.log_arguments?) && !mailer.constantize.log_arguments? "" - else - JSON.pretty_generate(event.payload[:args].map { |arg| format(arg) }) if event.payload[:args].present? + elsif event.payload[:args].present? + JSON.pretty_generate(event.payload[:args].map { |arg| format(arg) }) end end diff --git a/lib/rails_semantic_logger/action_view/log_subscriber.rb b/lib/rails_semantic_logger/action_view/log_subscriber.rb index 2b0ade0..9a91577 100644 --- a/lib/rails_semantic_logger/action_view/log_subscriber.rb +++ b/lib/rails_semantic_logger/action_view/log_subscriber.rb @@ -22,7 +22,7 @@ def render_template(event) payload = { template: from_rails_root(event.payload[:identifier]) } - payload[:within] = from_rails_root(event.payload[:layout]) if event.payload[:layout] + payload[:within] = from_rails_root(event.payload[:layout]) if event.payload[:layout] payload[:allocations] = event.allocations if event.respond_to?(:allocations) logger.measure( @@ -39,8 +39,8 @@ def render_partial(event) payload = { partial: from_rails_root(event.payload[:identifier]) } - payload[:within] = from_rails_root(event.payload[:layout]) if event.payload[:layout] - payload[:cache] = event.payload[:cache_hit] unless event.payload[:cache_hit].nil? + payload[:within] = from_rails_root(event.payload[:layout]) if event.payload[:layout] + payload[:cache] = event.payload[:cache_hit] unless event.payload[:cache_hit].nil? payload[:allocations] = event.allocations if event.respond_to?(:allocations) logger.measure( @@ -60,7 +60,7 @@ def render_collection(event) template: from_rails_root(identifier), count: event.payload[:count] } - payload[:cache_hits] = event.payload[:cache_hits] if event.payload[:cache_hits] + payload[:cache_hits] = event.payload[:cache_hits] if event.payload[:cache_hits] payload[:allocations] = event.allocations if event.respond_to?(:allocations) logger.measure( @@ -72,16 +72,61 @@ def render_collection(event) end def start(name, id, payload) - if (name == "render_template.action_view") && should_log? + if ["render_template.action_view", "render_layout.action_view"].include?(name) && should_log? + qualifier = " layout" if name == "render_layout.action_view" payload = {template: from_rails_root(payload[:identifier])} payload[:within] = from_rails_root(payload[:layout]) if payload[:layout] - logger.send(self.class.rendered_log_level, message: "Rendering", payload: payload) + logger.send(self.class.rendered_log_level, message: "Rendering#{qualifier}", payload: payload) end super end + if (Rails::VERSION::MAJOR == 7 && Rails::VERSION::MINOR >= 1) || Rails::VERSION::MAJOR > 7 + class Start + def start(name, _id, payload) + return unless %w[render_template.action_view render_layout.action_view].include?(name) + + qualifier = " layout" if name == "render_layout.action_view" + payload = {template: from_rails_root(payload[:identifier])} + payload[:within] = from_rails_root(payload[:layout]) if payload[:layout] + + logger.debug(message: "Rendering#{qualifier}", payload: payload) + end + + def finish(name, id, payload) + end + + private + + def from_rails_root(string) + string = string.sub(rails_root, "") + string.sub!(VIEWS_PATTERN, "") + string + end + + def rails_root + @root ||= "#{Rails.root}/" + end + + def logger + @logger ||= SemanticLogger["ActionView"] + end + end + + def self.attach_to(*) + ActiveSupport::Notifications.unsubscribe("render_template.action_view") + ActiveSupport::Notifications.unsubscribe("render_layout.action_view") + ActiveSupport::Notifications.subscribe("render_template.action_view", + RailsSemanticLogger::ActionView::LogSubscriber::Start.new) + ActiveSupport::Notifications.subscribe("render_layout.action_view", + RailsSemanticLogger::ActionView::LogSubscriber::Start.new) + + super + end + end + private @logger = SemanticLogger["ActionView"] diff --git a/lib/rails_semantic_logger/active_job/log_subscriber.rb b/lib/rails_semantic_logger/active_job/log_subscriber.rb index c93d334..0f411d2 100644 --- a/lib/rails_semantic_logger/active_job/log_subscriber.rb +++ b/lib/rails_semantic_logger/active_job/log_subscriber.rb @@ -4,14 +4,44 @@ module RailsSemanticLogger module ActiveJob class LogSubscriber < ::ActiveSupport::LogSubscriber def enqueue(event) - log_with_formatter event: event do |fmt| - {message: "Enqueued #{fmt.job_info}"} + ex = event.payload[:exception_object] + + if ex + log_with_formatter level: :error, event: event do |fmt| + { + message: "Failed enqueuing #{fmt.job_info} (#{ex.class} (#{ex.message})", + exception: ex + } + end + elsif event.payload[:aborted] + log_with_formatter level: :info, event: event do |fmt| + {message: "Failed enqueuing #{fmt.job_info}, a before_enqueue callback halted the enqueuing execution."} + end + else + log_with_formatter event: event do |fmt| + {message: "Enqueued #{fmt.job_info}"} + end end end def enqueue_at(event) - log_with_formatter event: event do |fmt| - {message: "Enqueued #{fmt.job_info} at #{fmt.scheduled_at}"} + ex = event.payload[:exception_object] + + if ex + log_with_formatter level: :error, event: event do |fmt| + { + message: "Failed enqueuing #{fmt.job_info} (#{ex.class} (#{ex.message})", + exception: ex + } + end + elsif event.payload[:aborted] + log_with_formatter level: :info, event: event do |fmt| + {message: "Failed enqueuing #{fmt.job_info}, a before_enqueue callback halted the enqueuing execution."} + end + else + log_with_formatter event: event do |fmt| + {message: "Enqueued #{fmt.job_info} at #{fmt.scheduled_at}"} + end end end @@ -26,7 +56,7 @@ def perform(event) if ex log_with_formatter event: event, log_duration: true, level: :error do |fmt| { - message: "Error performing #{fmt.job_info} in #{event.duration.round(2)}ms", + message: "Error performing #{fmt.job_info} in #{event.duration.round(2)}ms", exception: ex } end diff --git a/lib/rails_semantic_logger/active_record/log_subscriber.rb b/lib/rails_semantic_logger/active_record/log_subscriber.rb index c54a334..357303b 100644 --- a/lib/rails_semantic_logger/active_record/log_subscriber.rb +++ b/lib/rails_semantic_logger/active_record/log_subscriber.rb @@ -169,9 +169,7 @@ def render_bind_v5_0_3(attr, value) def render_bind_v6_1(attr, value) case attr when ActiveModel::Attribute - if attr.type.binary? && attr.value - value = "<#{attr.value_for_database.to_s.bytesize} bytes of binary data>" - end + value = "<#{attr.value_for_database.to_s.bytesize} bytes of binary data>" if attr.type.binary? && attr.value when Array attr = attr.first else diff --git a/lib/rails_semantic_logger/engine.rb b/lib/rails_semantic_logger/engine.rb index 42589af..37fe21a 100644 --- a/lib/rails_semantic_logger/engine.rb +++ b/lib/rails_semantic_logger/engine.rb @@ -77,7 +77,7 @@ class Engine < ::Rails::Engine logger = SemanticLogger[Rails] logger.warn( "Rails Error: Unable to access log file. Please ensure that #{path} exists and is chmod 0666. " \ - "The log level has been raised to WARN and the output directed to STDERR until the problem is fixed.", + "The log level has been raised to WARN and the output directed to STDERR until the problem is fixed.", e ) logger @@ -111,14 +111,14 @@ class Engine < ::Rails::Engine if defined?(Sidekiq) if Sidekiq.respond_to?(:logger=) Sidekiq.logger = SemanticLogger[Sidekiq] - elsif Sidekiq::VERSION[0..1] == '7.' + elsif Sidekiq::VERSION[0..1] == "7." method = Sidekiq.server? ? :configure_server : :configure_client Sidekiq.public_send(method) { |cfg| cfg.logger = SemanticLogger[Sidekiq] } end end # Replace the Sidetiq logger - Sidetiq.logger = SemanticLogger[Sidetiq] if defined?(Sidetiq) && Sidetiq.respond_to?(:logger=) + Sidetiq.logger = SemanticLogger[Sidetiq] if defined?(Sidetiq) && Sidetiq.respond_to?(:logger=) # Replace the DelayedJob logger if defined?(Delayed::Worker) @@ -127,7 +127,7 @@ class Engine < ::Rails::Engine end # Replace the Bugsnag logger - Bugsnag.configure { |config| config.logger = SemanticLogger[Bugsnag] } if defined?(Bugsnag) + Bugsnag.configure(false) { |config| config.logger = SemanticLogger[Bugsnag] } if defined?(Bugsnag) # Set the IOStreams PGP logger IOStreams::Pgp.logger = SemanticLogger["IOStreams::Pgp"] if defined?(IOStreams) @@ -138,12 +138,14 @@ class Engine < ::Rails::Engine config = Rails.application.config # Replace the Bugsnag logger - Bugsnag.configure { |bugsnag_config| bugsnag_config.logger = SemanticLogger[Bugsnag] } if defined?(Bugsnag) + Bugsnag.configure(false) { |bugsnag_config| bugsnag_config.logger = SemanticLogger[Bugsnag] } if defined?(Bugsnag) # Rails Patches require("rails_semantic_logger/extensions/action_cable/tagged_logger_proxy") if defined?(::ActionCable) require("rails_semantic_logger/extensions/action_controller/live") if defined?(::ActionController::Live) - require("rails_semantic_logger/extensions/action_dispatch/debug_exceptions") if defined?(::ActionDispatch::DebugExceptions) + if defined?(::ActionDispatch::DebugExceptions) + require("rails_semantic_logger/extensions/action_dispatch/debug_exceptions") + end if defined?(::ActionView::StreamingTemplateRenderer::Body) require("rails_semantic_logger/extensions/action_view/streaming_template_renderer") end diff --git a/lib/rails_semantic_logger/extensions/active_job/logging.rb b/lib/rails_semantic_logger/extensions/active_job/logging.rb index a811a6e..b634223 100644 --- a/lib/rails_semantic_logger/extensions/active_job/logging.rb +++ b/lib/rails_semantic_logger/extensions/active_job/logging.rb @@ -9,7 +9,11 @@ module Logging undef_method :tag_logger def tag_logger(*tags, &block) - logger.tagged(*tags, &block) + if logger.respond_to?(:tagged) + logger.tagged(*tags, &block) + else + yield + end end end end diff --git a/lib/rails_semantic_logger/extensions/active_support/log_subscriber.rb b/lib/rails_semantic_logger/extensions/active_support/log_subscriber.rb new file mode 100644 index 0000000..c6b7566 --- /dev/null +++ b/lib/rails_semantic_logger/extensions/active_support/log_subscriber.rb @@ -0,0 +1,13 @@ +if ActiveSupport::VERSION::STRING == "7.1.1" + require "active_support/log_subscriber" + + module ActiveSupport + class LogSubscriber + # @override Rails 7.1 + def silenced?(event) + native_log_level = @event_levels.fetch(event, ::Logger::Severity::FATAL) + logger.nil? || SemanticLogger::Levels.index(logger.level) > SemanticLogger::Levels.index(native_log_level) + end + end + end +end diff --git a/lib/rails_semantic_logger/extensions/active_support/logger.rb b/lib/rails_semantic_logger/extensions/active_support/logger.rb index 9b30070..d096f51 100644 --- a/lib/rails_semantic_logger/extensions/active_support/logger.rb +++ b/lib/rails_semantic_logger/extensions/active_support/logger.rb @@ -5,14 +5,22 @@ module ActiveSupport class Logger class << self undef :logger_outputs_to? + + # Prevent broadcasting since SemanticLogger already supports multiple loggers + if method_defined?(:broadcast) + undef :broadcast + def broadcast(_logger) + Module.new + end + end end # Prevent Console from trying to merge loggers - def self.logger_outputs_to?(*args) + def self.logger_outputs_to?(*_args) true end - def self.new(*args, **kwargs) + def self.new(*_args, **_kwargs) SemanticLogger[self] end end diff --git a/lib/rails_semantic_logger/extensions/rackup/server.rb b/lib/rails_semantic_logger/extensions/rackup/server.rb new file mode 100644 index 0000000..bcffedc --- /dev/null +++ b/lib/rails_semantic_logger/extensions/rackup/server.rb @@ -0,0 +1,12 @@ +module RailsSemanticLogger + module Rackup + module Server + def daemonize_app + super + SemanticLogger.reopen + end + end + end +end + +Rackup::Server.prepend(RailsSemanticLogger::Rackup::Server) diff --git a/lib/rails_semantic_logger/extensions/rails/server.rb b/lib/rails_semantic_logger/extensions/rails/server.rb index f21323b..9aa79b5 100644 --- a/lib/rails_semantic_logger/extensions/rails/server.rb +++ b/lib/rails_semantic_logger/extensions/rails/server.rb @@ -4,7 +4,7 @@ module Rails class Server private - + undef_method :log_to_stdout if method_defined?(:log_to_stdout) def log_to_stdout wrapped_app # touch the app so the logger is set up diff --git a/lib/rails_semantic_logger/rack/logger.rb b/lib/rails_semantic_logger/rack/logger.rb index 6f90f1a..20dea0e 100644 --- a/lib/rails_semantic_logger/rack/logger.rb +++ b/lib/rails_semantic_logger/rack/logger.rb @@ -37,7 +37,7 @@ def call(env) def call_app(request, env) instrumenter = ActiveSupport::Notifications.instrumenter instrumenter_state = instrumenter.start "request.action_dispatch", request: request - instrumenter_finish = -> () { + instrumenter_finish = lambda { instrumenter.finish_with_state(instrumenter_state, "request.action_dispatch", request: request) } diff --git a/lib/rails_semantic_logger/version.rb b/lib/rails_semantic_logger/version.rb index 3ec7e6a..18f8d38 100644 --- a/lib/rails_semantic_logger/version.rb +++ b/lib/rails_semantic_logger/version.rb @@ -1,3 +1,3 @@ module RailsSemanticLogger - VERSION = "4.12.0".freeze + VERSION = "4.14.0".freeze end diff --git a/rails_semantic_logger.gemspec b/rails_semantic_logger.gemspec index ae38f48..2dcea7b 100644 --- a/rails_semantic_logger.gemspec +++ b/rails_semantic_logger.gemspec @@ -20,7 +20,7 @@ Gem::Specification.new do |s| s.metadata = { "bug_tracker_uri" => "https://github.com/reidmorrison/rails_semantic_logger/issues", "documentation_uri" => "https://logger.rocketjob.io", - "source_code_uri" => "https://github.com/reidmorrison/rails_semantic_logger/tree/#{RailsSemanticLogger::VERSION}", + "source_code_uri" => "https://github.com/reidmorrison/rails_semantic_logger/tree/v#{RailsSemanticLogger::VERSION}", "rubygems_mfa_required" => "true" } end diff --git a/test/action_mailer_test.rb b/test/action_mailer_test.rb index 8349947..760bca6 100644 --- a/test/action_mailer_test.rb +++ b/test/action_mailer_test.rb @@ -2,8 +2,8 @@ class ActionMailerTest < Minitest::Test class MyMailer < ActionMailer::Base - def some_email(to:, from:, subject:) - mail(to: to, from: from, subject: subject, body: "Hello") + def some_email(opts) + mail(to: opts[:to], from: opts[:from], subject: opts[:subject], body: "Hello") end end @@ -14,39 +14,39 @@ def some_email(to:, from:, subject:) end it "sends the email" do - MyMailer.some_email(to: 'test@test.com', from: 'test@test.com', subject: 'test').deliver_now + MyMailer.some_email(to: "test@test.com", from: "test@test.com", subject: "test").deliver_now end it "writes log messages" do messages = semantic_logger_events do - MyMailer.some_email(to: 'test@test.com', from: 'test@test.com', subject: 'test').deliver_now + MyMailer.some_email(to: "test@test.com", from: "test@test.com", subject: "test").deliver_now end assert_equal 2, messages.count, messages assert_semantic_logger_event( messages[0], - level: :info, - name: "ActionMailer::Base", + level: :info, + name: "ActionMailer::Base", message_includes: "ActionMailerTest::MyMailer#some_email: processed outbound mail", payload_includes: { event_name: "process.action_mailer", - mailer: "ActionMailerTest::MyMailer", - action: :some_email, + mailer: "ActionMailerTest::MyMailer", + action: :some_email } ) assert_semantic_logger_event( messages[1], - level: :info, - name: "ActionMailer::Base", + level: :info, + name: "ActionMailer::Base", message_includes: Rails::VERSION::MAJOR >= 6 ? "Delivered mail" : "Skipped delivery", payload_includes: { - event_name: "deliver.action_mailer", - mailer: "ActionMailerTest::MyMailer", + event_name: "deliver.action_mailer", + mailer: "ActionMailerTest::MyMailer", perform_deliveries: Rails::VERSION::MAJOR >= 6 ? true : nil, - subject: "test", - to: ["test@test.com"], - from: ["test@test.com"], + subject: "test", + to: ["test@test.com"], + from: ["test@test.com"] } ) end @@ -65,15 +65,15 @@ def some_email(to:, from:, subject:) let(:payload) do { - mailer: 'MyMailer', - action: :some_email, + mailer: "MyMailer", + action: :some_email } end let(:event_name) { "deliver.action_mailer" } let(:mailer) do - MyMailer.some_email(to: 'test@test.com', from: 'test@test.com', subject: 'test') + MyMailer.some_email(to: "test@test.com", from: "test@test.com", subject: "test") end %i[deliver process].each do |method| diff --git a/test/active_job_test.rb b/test/active_job_test.rb index 3f842bb..2ca6ad2 100644 --- a/test/active_job_test.rb +++ b/test/active_job_test.rb @@ -121,6 +121,144 @@ def id end end + describe "#enqueue with exception object" do + let(:event_name) { "enqueue.active_job" } + + let(:payload) do + { + adapter: ActiveJob::QueueAdapters::InlineAdapter.new, + job: job, + exception_object: ArgumentError.new("error") + } + end + + it "logs message" do + messages = semantic_logger_events do + subscriber.enqueue(event) + end + assert_equal 1, messages.count, messages + + assert_semantic_logger_event( + messages[0], + level: :error, + name: "Rails", + message_includes: "Failed enqueuing ActiveJobTest::MyJob", + payload_includes: { + job_class: "ActiveJobTest::MyJob", + queue: "my_jobs", + event_name: "enqueue.active_job" + } + ) + assert_includes messages[0].payload, :job_id + + exception = messages[0].exception + assert exception.is_a?(ArgumentError) + assert_equal "error", exception.message + end + end + + describe "#enqueue with throwing :abort" do + let(:event_name) { "enqueue.active_job" } + + let(:payload) do + { + adapter: ActiveJob::QueueAdapters::InlineAdapter.new, + job: job, + aborted: true + } + end + + it "logs message" do + messages = semantic_logger_events do + subscriber.enqueue(event) + end + assert_equal 1, messages.count, messages + + assert_semantic_logger_event( + messages[0], + level: :info, + name: "Rails", + message_includes: "Failed enqueuing ActiveJobTest::MyJob", + payload_includes: { + job_class: "ActiveJobTest::MyJob", + queue: "my_jobs", + event_name: "enqueue.active_job" + } + ) + assert_match(/Failed enqueuing .*, a before_enqueue callback halted the enqueuing execution/, messages[0].message) + assert_includes messages[0].payload, :job_id + end + end + + describe "#enqueue_at with exception object" do + let(:event_name) { "enqueue.active_job" } + + let(:payload) do + { + adapter: ActiveJob::QueueAdapters::InlineAdapter.new, + job: job, + exception_object: ArgumentError.new("error") + } + end + + it "logs message" do + messages = semantic_logger_events do + subscriber.enqueue_at(event) + end + assert_equal 1, messages.count, messages + + assert_semantic_logger_event( + messages[0], + level: :error, + name: "Rails", + message_includes: "Failed enqueuing ActiveJobTest::MyJob", + payload_includes: { + job_class: "ActiveJobTest::MyJob", + queue: "my_jobs", + event_name: "enqueue.active_job" + } + ) + assert_includes messages[0].payload, :job_id + + exception = messages[0].exception + assert exception.is_a?(ArgumentError) + assert_equal "error", exception.message + end + end + + describe "#enqueue_at with throwing :abort" do + let(:event_name) { "enqueue.active_job" } + + let(:payload) do + { + adapter: ActiveJob::QueueAdapters::InlineAdapter.new, + job: job, + aborted: true + } + end + + it "logs message" do + messages = semantic_logger_events do + subscriber.enqueue_at(event) + end + assert_equal 1, messages.count, messages + + assert_semantic_logger_event( + messages[0], + level: :info, + name: "Rails", + message_includes: "Failed enqueuing ActiveJobTest::MyJob", + payload_includes: { + job_class: "ActiveJobTest::MyJob", + queue: "my_jobs", + event_name: "enqueue.active_job" + } + ) + assert_match(/Failed enqueuing .*, a before_enqueue callback halted the enqueuing execution/, messages[0].message) + assert_includes messages[0].payload, :job_id + end + end + describe "ActiveJob::Logging::LogSubscriber::EventFormatter" do let(:formatter) do RailsSemanticLogger::ActiveJob::LogSubscriber::EventFormatter.new(event: event, log_duration: true) diff --git a/test/active_record_test.rb b/test/active_record_test.rb index e43a491..0fc3866 100644 --- a/test/active_record_test.rb +++ b/test/active_record_test.rb @@ -3,7 +3,7 @@ class ActiveRecordTest < Minitest::Test describe "ActiveRecord" do # Rails 5 has an extra space - let(:extra_space) { Rails::VERSION::MAJOR >= 6 ? "" : " "} + let(:extra_space) { Rails::VERSION::MAJOR >= 6 ? "" : " " } describe "logs" do it "sql" do @@ -21,7 +21,7 @@ class ActiveRecordTest < Minitest::Test message: "Sample Load", payload_includes: { sql: expected_sql, - binds: { limit: 1 } + binds: {limit: 1} } ) assert_instance_of Integer, messages[0].payload[:allocations] if Rails.version.to_i >= 6 @@ -42,7 +42,7 @@ class ActiveRecordTest < Minitest::Test message: "Sample Load", payload_includes: { sql: expected_sql, - binds: { name: "foo", limit: 1 } + binds: {name: "foo", limit: 1} } ) assert_instance_of Integer, messages[0].payload[:allocations] if Rails.version.to_i >= 6 @@ -54,7 +54,7 @@ class ActiveRecordTest < Minitest::Test message: "Sample Load", payload_includes: { sql: expected_sql, - binds: { name: "foo", limit: 1 }, + binds: {name: "foo", limit: 1}, cached: true } ) @@ -81,7 +81,7 @@ class ActiveRecordTest < Minitest::Test message: "Sample Load", payload_includes: { sql: expected_sql, - binds: { name: "Jack", limit: 1 } + binds: {name: "Jack", limit: 1} } ) assert_instance_of Integer, messages[0].payload[:allocations] if Rails.version.to_i >= 6 @@ -96,7 +96,6 @@ class ActiveRecordTest < Minitest::Test Sample.where(age: 2..21).first end assert_equal 1, messages.count, messages - ap messages assert_semantic_logger_event( messages[0], @@ -105,7 +104,7 @@ class ActiveRecordTest < Minitest::Test message: "Sample Load", payload_includes: { sql: expected_sql, - binds: { age: [2, 21], limit: 1 } + binds: {age: [2, 21], limit: 1} } ) assert_instance_of Integer, messages[0].payload[:allocations] if Rails.version.to_i >= 6 @@ -128,7 +127,7 @@ class ActiveRecordTest < Minitest::Test message: "Sample Load", payload_includes: { sql: expected_sql, - binds: { age: [2, 3], limit: 1 } + binds: {age: [2, 3], limit: 1} } ) end diff --git a/test/controllers/articles_controller_test.rb b/test/controllers/articles_controller_test.rb index c79ccb5..f6ed780 100644 --- a/test/controllers/articles_controller_test.rb +++ b/test/controllers/articles_controller_test.rb @@ -2,7 +2,7 @@ class ArticlesControllerTest < ActionDispatch::IntegrationTest describe ArticlesController do - let(:params) { { article: { text: "Text1", title: "Title1" } } } + let(:params) { {article: {text: "Text1", title: "Title1"}} } describe "#new" do it "shows new article" do diff --git a/test/controllers/dashboard_controller_test.rb b/test/controllers/dashboard_controller_test.rb index f68e69d..b9bea58 100644 --- a/test/controllers/dashboard_controller_test.rb +++ b/test/controllers/dashboard_controller_test.rb @@ -58,7 +58,7 @@ class DashboardControllerTest < ActionDispatch::IntegrationTest end payload = PayloadCollector.last - assert_equal payload[:params], { "controller" => "dashboard", "action" => "show" } + assert_equal payload[:params], {"controller" => "dashboard", "action" => "show"} end end end diff --git a/test/dummy/config.ru b/test/dummy/config.ru index 08dd501..9d6e524 100644 --- a/test/dummy/config.ru +++ b/test/dummy/config.ru @@ -1,4 +1,4 @@ # This file is used by Rack-based servers to start the application. -require ::File.expand_path("../config/environment", __FILE__) +require File.expand_path("config/environment", __dir__) run Dummy::Application diff --git a/test/dummy/config/application.rb b/test/dummy/config/application.rb index 260d4e7..15d2e1b 100644 --- a/test/dummy/config/application.rb +++ b/test/dummy/config/application.rb @@ -7,7 +7,7 @@ module Dummy class Application < Rails::Application # Configure sensitive parameters which will be filtered from the log file. - config.filter_parameters += [:password] + config.filter_parameters += [:password] config.active_record.sqlite3.represent_boolean_as_integer = true if config.active_record.sqlite3 # Settings in config/environments/* take precedence over those specified here. @@ -30,6 +30,6 @@ class Application < Rails::Application config.semantic_logger.backtrace_level = :trace # Test out Amazing Print - config.rails_semantic_logger.ap_options = { multiline: false, ruby19_syntax: true } + config.rails_semantic_logger.ap_options = {multiline: false, ruby19_syntax: true} end end diff --git a/test/test_helper.rb b/test/test_helper.rb index 91495b7..cac6b76 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -16,4 +16,4 @@ # Add Semantic Logger helpers for Minitest Minitest::Test.include SemanticLogger::Test::Minitest -::ActionMailer::Base.delivery_method = :test +ActionMailer::Base.delivery_method = :test