diff --git a/.github/workflows/main.yml b/.github/workflows/main.yml index 68f6695..01ddc7c 100644 --- a/.github/workflows/main.yml +++ b/.github/workflows/main.yml @@ -18,6 +18,7 @@ jobs: matrix: ruby-version: + - "4.0" - "3" - "3.3" - "3.2" @@ -40,6 +41,8 @@ jobs: - "rails-5.1" - "rails-5.0" exclude: + - gemfile: "rails-edge" + ruby-version: "3.2" - gemfile: "rails-edge" ruby-version: "3.1" - gemfile: "rails-edge" @@ -50,8 +53,6 @@ jobs: ruby-version: "2.6" - gemfile: "rails-edge" ruby-version: "2.5" - - gemfile: "rails-8.1" - ruby-version: "truffleruby" - gemfile: "rails-8.1" ruby-version: "3.1" @@ -63,8 +64,6 @@ jobs: ruby-version: "2.6" - gemfile: "rails-8.1" ruby-version: "2.5" - - gemfile: "rails-8.1" - ruby-version: "truffleruby" - gemfile: "rails-8.0" ruby-version: "3.1" @@ -96,6 +95,8 @@ jobs: - gemfile: "rails-7.0" ruby-version: "2.5" + - gemfile: "rails-5.2" + ruby-version: "4.0" - gemfile: "rails-5.2" ruby-version: "3" - gemfile: "rails-5.2" @@ -109,6 +110,8 @@ jobs: - gemfile: "rails-5.2" ruby-version: "truffleruby" + - gemfile: "rails-5.1" + ruby-version: "4.0" - gemfile: "rails-5.1" ruby-version: "3" - gemfile: "rails-5.1" @@ -122,6 +125,8 @@ jobs: - gemfile: "rails-5.1" ruby-version: "truffleruby" + - gemfile: "rails-5.0" + ruby-version: "4.0" - gemfile: "rails-5.0" ruby-version: "3" - gemfile: "rails-5.0" diff --git a/gemfiles/rails-7.1.gemfile b/gemfiles/rails-7.1.gemfile index 13f0883..83ac20c 100755 --- a/gemfiles/rails-7.1.gemfile +++ b/gemfiles/rails-7.1.gemfile @@ -5,6 +5,8 @@ gem 'sidekiq', '>= 7.3.0', require: false if RUBY_VERSION >= '2.7.0' gem 'logtail' gem 'logtail-rack' +# ActiveSupport passes quirks_mode to JSON.generate until 7.2.4 and 8.1, json 3 no longer accepts it +gem 'json', '< 3' if RUBY_PLATFORM == "java" gem 'mime-types', '2.6.2' diff --git a/gemfiles/rails-7.2.gemfile b/gemfiles/rails-7.2.gemfile index 0a9637b..2a86de7 100644 --- a/gemfiles/rails-7.2.gemfile +++ b/gemfiles/rails-7.2.gemfile @@ -1,6 +1,8 @@ source 'https://rubygems.org' -gem 'rails', '~> 7.2.0' +# 7.2.4 is the first release that works with json 3. Without the floor, Bundler prefers +# minitest 6 over it and settles for Rails 7.2.3. +gem 'rails', '~> 7.2.4' gem 'sidekiq', '>= 7.3.0', require: false gem 'logtail' diff --git a/gemfiles/rails-8.0.gemfile b/gemfiles/rails-8.0.gemfile index 6b3342f..d34482f 100755 --- a/gemfiles/rails-8.0.gemfile +++ b/gemfiles/rails-8.0.gemfile @@ -5,6 +5,7 @@ gem 'sidekiq', '>= 7.3.0', require: false gem 'logtail' gem 'logtail-rack' -gem "sqlite3", ">= 2.0" +# ActiveSupport passes quirks_mode to JSON.generate until 7.2.4 and 8.1, json 3 no longer accepts it +gem 'json', '< 3' gemspec :path => '../' diff --git a/gemfiles/rails-8.1.gemfile b/gemfiles/rails-8.1.gemfile index f9657d3..03b4e39 100755 --- a/gemfiles/rails-8.1.gemfile +++ b/gemfiles/rails-8.1.gemfile @@ -5,6 +5,5 @@ gem 'sidekiq', '>= 7.3.0', require: false gem 'logtail' gem 'logtail-rack' -gem "sqlite3", ">= 2.0" gemspec :path => '../' diff --git a/gemfiles/rails-edge.gemfile b/gemfiles/rails-edge.gemfile index e4caa85..ac2df52 100755 --- a/gemfiles/rails-edge.gemfile +++ b/gemfiles/rails-edge.gemfile @@ -5,7 +5,6 @@ gem 'sidekiq', '>= 7.3.0', require: false if RUBY_VERSION >= '2.7.0' gem 'logtail' gem 'logtail-rack' -gem "sqlite3", ">= 2.0" if RUBY_PLATFORM == "java" gem 'mime-types', '2.6.2' diff --git a/lib/logtail-rails/action_controller/log_subscriber.rb b/lib/logtail-rails/action_controller/log_subscriber.rb index 9f7bf33..55409d7 100755 --- a/lib/logtail-rails/action_controller/log_subscriber.rb +++ b/lib/logtail-rails/action_controller/log_subscriber.rb @@ -18,7 +18,7 @@ def integrate! return true if Logtail::Integrations::Rails::ActiveSupportLogSubscriber.subscribed?(:action_controller, LogtailLogSubscriber) Logtail::Integrations::Rails::ActiveSupportLogSubscriber.unsubscribe!(:action_controller, ::ActionController::LogSubscriber) - LogtailLogSubscriber.attach_to(:action_controller) + Logtail::Integrations::Rails::ActiveSupportLogSubscriber.subscribe!(:action_controller, LogtailLogSubscriber) end end end diff --git a/lib/logtail-rails/action_controller/log_subscriber/logtail_log_subscriber.rb b/lib/logtail-rails/action_controller/log_subscriber/logtail_log_subscriber.rb index 7bcbcd2..a8a7809 100755 --- a/lib/logtail-rails/action_controller/log_subscriber/logtail_log_subscriber.rb +++ b/lib/logtail-rails/action_controller/log_subscriber/logtail_log_subscriber.rb @@ -9,21 +9,42 @@ class LogSubscriber < Integrator # # @private class LogtailLogSubscriber < ::ActionController::LogSubscriber - def start_processing(event) - return true if silence? + if ::ActionController::LogSubscriber < ::ActiveSupport::LogSubscriber + def start_processing(event) + return true if silence? - info do - payload = event.payload - params = payload[:params].except(*INTERNAL_PARAMS) - format = extract_format(payload) - format = format.to_s.upcase if format.is_a?(Symbol) + info do + payload = event.payload + params = payload[:params].except(*INTERNAL_PARAMS) + format = extract_format(payload) + format = format.to_s.upcase if format.is_a?(Symbol) - Events::ControllerCall.new( - controller: payload[:controller], - action: payload[:action], - format: format, - params: params - ) + Events::ControllerCall.new( + controller: payload[:controller], + action: payload[:action], + format: format, + params: params + ) + end + end + else + # Rails 8.2+ feeds this subscriber from Rails.event: the event is a hash whose + # payload already comes without the internal params and with the format upcased. + self.namespace = "action_controller" + + def request_started(event) + return true if silence? + + info do + payload = event[:payload] + + Events::ControllerCall.new( + controller: payload[:controller], + action: payload[:action], + format: payload[:format], + params: payload[:params] + ) + end end end diff --git a/lib/logtail-rails/action_view/log_subscriber.rb b/lib/logtail-rails/action_view/log_subscriber.rb index 5334195..02322b8 100755 --- a/lib/logtail-rails/action_view/log_subscriber.rb +++ b/lib/logtail-rails/action_view/log_subscriber.rb @@ -17,7 +17,7 @@ def integrate! return true if Logtail::Integrations::Rails::ActiveSupportLogSubscriber.subscribed?(:action_view, LogtailLogSubscriber) Logtail::Integrations::Rails::ActiveSupportLogSubscriber.unsubscribe!(:action_view, ::ActionView::LogSubscriber) - LogtailLogSubscriber.attach_to(:action_view) + Logtail::Integrations::Rails::ActiveSupportLogSubscriber.subscribe!(:action_view, LogtailLogSubscriber) end end end diff --git a/lib/logtail-rails/action_view/log_subscriber/logtail_log_subscriber.rb b/lib/logtail-rails/action_view/log_subscriber/logtail_log_subscriber.rb index 72eaf13..7fb451f 100755 --- a/lib/logtail-rails/action_view/log_subscriber/logtail_log_subscriber.rb +++ b/lib/logtail-rails/action_view/log_subscriber/logtail_log_subscriber.rb @@ -7,8 +7,12 @@ class LogSubscriber < Integrator # The intent of this subscriber is to, as transparently as possible, properly # track events that are being logged here. # + # Until Rails 8.1 it extends the default subscriber. Rails 8.2 turned that one into a + # subscriber of Rails.event, which receives the rendering events in debug mode only, so + # there this subscriber listens to the notifications on its own. + # # @private - class LogtailLogSubscriber < ::ActionView::LogSubscriber + class LogtailLogSubscriber < (::ActionView::LogSubscriber < ::ActiveSupport::LogSubscriber ? ::ActionView::LogSubscriber : ::ActiveSupport::LogSubscriber) def render_template(event) return true if silence? @@ -67,15 +71,25 @@ def render_collection(event) end end - def self.attach_to(*) - super + if superclass == ::ActionView::LogSubscriber + def self.attach_to(*) + super + + if ::Rails::VERSION::MAJOR > 7 || ::Rails::VERSION::MAJOR == 7 && ::Rails::VERSION::MINOR >= 1 + # Clean extra listeners subscribed in parent's attach_to method + ::ActiveSupport::Notifications.notifier.listeners_for("render_template.action_view") + .concat(::ActiveSupport::Notifications.notifier.listeners_for("render_layout.action_view")).flatten + .filter { |listener| listener.delegate.class == ::ActionView::LogSubscriber::Start } + .each { |listener| ActiveSupport::Notifications.unsubscribe(listener) } + end + end + else + # The default subscriber used to bring these log levels, the logger and the helpers below + subscribe_log_level :render_partial, :debug + subscribe_log_level :render_collection, :debug - if ::Rails::VERSION::MAJOR > 7 || ::Rails::VERSION::MAJOR == 7 && ::Rails::VERSION::MINOR >= 1 - # Clean extra listeners subscribed in parent's attach_to method - ::ActiveSupport::Notifications.notifier.listeners_for("render_template.action_view") - .concat(::ActiveSupport::Notifications.notifier.listeners_for("render_layout.action_view")).flatten - .filter { |listener| listener.delegate.class == ::ActionView::LogSubscriber::Start } - .each { |listener| ActiveSupport::Notifications.unsubscribe(listener) } + def logger + ::ActionView::Base.logger end end @@ -90,6 +104,35 @@ def log_rendering_start(*args) def silence? ActionView.silence? end + + unless superclass == ::ActionView::LogSubscriber + def from_rails_root(string) + string = string.sub(rails_root, "") + string.sub!(/^app\/views\//, "") + string + end + + def rails_root + @rails_root ||= "#{::Rails.root}/" + end + + def render_count(payload) + if payload[:cache_hits] + "[#{payload[:cache_hits]} / #{payload[:count]} cache hits]" + else + "[#{payload[:count]} times]" + end + end + + def cache_message(payload) + case payload[:cache_hit] + when :hit + "[cache hit]" + when :miss + "[cache miss]" + end + end + end end end end diff --git a/lib/logtail-rails/active_record/log_subscriber.rb b/lib/logtail-rails/active_record/log_subscriber.rb index 8c11be4..a71eb72 100755 --- a/lib/logtail-rails/active_record/log_subscriber.rb +++ b/lib/logtail-rails/active_record/log_subscriber.rb @@ -12,7 +12,7 @@ def integrate! return true if Logtail::Integrations::Rails::ActiveSupportLogSubscriber.subscribed?(:active_record, LogtailLogSubscriber) Logtail::Integrations::Rails::ActiveSupportLogSubscriber.unsubscribe!(:active_record, ::ActiveRecord::LogSubscriber) - LogtailLogSubscriber.attach_to(:active_record) + Logtail::Integrations::Rails::ActiveSupportLogSubscriber.subscribe!(:active_record, LogtailLogSubscriber) end end end diff --git a/lib/logtail-rails/active_record/log_subscriber/logtail_log_subscriber.rb b/lib/logtail-rails/active_record/log_subscriber/logtail_log_subscriber.rb index 6cfe126..ddbcfa9 100755 --- a/lib/logtail-rails/active_record/log_subscriber/logtail_log_subscriber.rb +++ b/lib/logtail-rails/active_record/log_subscriber/logtail_log_subscriber.rb @@ -13,35 +13,88 @@ class LogSubscriber < Integrator # track events that are being logged here. This LogSubscriber will never change # default behavior / log messages. # + # Until Rails 8.1 it extends the default subscriber. Rails 8.2 turned that one into a + # subscriber of Rails.event, which receives the SQL events in debug mode only, so there + # this subscriber listens to the notifications on its own. + # # @private - class LogtailLogSubscriber < ::ActiveRecord::LogSubscriber - def sql(event) - return true if silence? + class LogtailLogSubscriber < (::ActiveRecord::LogSubscriber < ::ActiveSupport::LogSubscriber ? ::ActiveRecord::LogSubscriber : ::ActiveSupport::LogSubscriber) + if superclass == ::ActiveRecord::LogSubscriber + def sql(event) + return true if silence? - r = super(event) + r = super(event) - if @message - payload = event.payload + if @message + payload = event.payload - sql_event = Events::SQLQuery.new( - sql: payload[:sql], - duration_ms: event.duration, - message: @message, - ) + sql_event = Events::SQLQuery.new( + sql: payload[:sql], + duration_ms: event.duration, + message: @message, + ) - logger.debug sql_event + logger.debug sql_event - @message = nil + @message = nil + end + + r end - r - end + private + def debug(message) + @message = message + end + else + require "active_record/structured_event_subscriber" - private - def debug(message) - @message = message + # Rails 8.2 split ActiveRecord::LogSubscriber#sql in two: a subscriber that turns the + # notification into an event for Rails.event, rendering and filtering the binds, and + # a log subscriber that formats the event. Both are used here as they are, without + # Rails.event between them. + class Translation < ::ActiveRecord::StructuredEventSubscriber + attr_reader :payload + + def emit_debug_event(name, payload = nil, caller_depth: 1, **kwargs) + @payload = payload || kwargs + end + end + + class Formatting < ::ActiveRecord::LogSubscriber + attr_reader :message + + private + def debug(message) + @message = message + end + end + + def sql(event) + return true if silence? + + translation = Translation.new + translation.sql(event) + # Schema and explain queries are not reported + return unless translation.payload + + formatting = Formatting.new + formatting.sql({ name: "active_record.sql", payload: translation.payload }) + + logger.debug Events::SQLQuery.new( + sql: event.payload[:sql], + duration_ms: event.duration, + message: formatting.message, + ) + end + subscribe_log_level :sql, :debug + + def logger + ::ActiveRecord::Base.logger + end end + private def silence? ActiveRecord.silence? end diff --git a/lib/logtail-rails/active_support_log_subscriber.rb b/lib/logtail-rails/active_support_log_subscriber.rb index 89e0c5c..0c826c5 100755 --- a/lib/logtail-rails/active_support_log_subscriber.rb +++ b/lib/logtail-rails/active_support_log_subscriber.rb @@ -6,6 +6,12 @@ module ActiveSupportLogSubscriber extend self def find(component, type) + if event_reporter_subscriber?(type) + return ::ActiveSupport.event_reporter.subscribers.map { |entry| entry[:subscriber] }.find do |subscriber| + subscriber.class == type + end + end + ::ActiveSupport::LogSubscriber.log_subscribers.find do |subscriber| subscriber.class == type end @@ -15,9 +21,25 @@ def subscribed?(component, type) !find(component, type).nil? end + def subscribe!(component, type) + if event_reporter_subscriber?(type) + # Like attach_to below, only deliver the events for the methods the subscriber defines itself + events = type.public_instance_methods(false).map { |method| "#{component}.#{method}" } + ::ActiveSupport.event_reporter.subscribe(type.new) { |event| events.include?(event[:name]) } + return + end + + type.attach_to(component) + end + # I don't know why this has to be so complicated, but it is. This code was taken from # lograge :/ def unsubscribe!(component, type) + if event_reporter_subscriber?(type) + ::ActiveSupport.event_reporter.unsubscribe(type) + return + end + if defined?(type.detach_from) type.detach_from(component) return @@ -38,6 +60,12 @@ def unsubscribe!(component, type) end end end + + # Rails 8.2+ feeds the framework log subscribers from Rails.event instead of + # ActiveSupport::Notifications. + def event_reporter_subscriber?(type) + defined?(::ActiveSupport::EventReporter::LogSubscriber) && type < ::ActiveSupport::EventReporter::LogSubscriber + end end end end diff --git a/lib/logtail-rails/event_log_subscriber.rb b/lib/logtail-rails/event_log_subscriber.rb index 8fddee5..f1131ae 100644 --- a/lib/logtail-rails/event_log_subscriber.rb +++ b/lib/logtail-rails/event_log_subscriber.rb @@ -22,6 +22,7 @@ def initialize(logger) # Rails 8.1 event emission method - called when events are emitted def emit(event) return unless self.class.enabled + return if framework_event?(event) # Log the event with all its data to Rails.logger # Create a structured log entry with the event data @@ -42,6 +43,17 @@ def emit(event) private + # Rails 8.2+ routes the framework's own instrumentation (controller calls, SQL queries, + # template renders, ...) through Rails.event as well. The Rails log subscribers, and ours + # replacing them, already log those, so only the application's own events are forwarded. + def framework_event?(event) + return false unless defined?(::ActiveSupport::EventReporter::LogSubscriber) + + ::ActiveSupport::EventReporter::LogSubscriber.descendants.any? do |log_subscriber| + event[:name].start_with?("#{log_subscriber.namespace}.") + end + end + def build_log_message(event) payload = event[:payload] || {} payload_str = payload.map { |key, value| "#{key}=#{value}" }.join(" ") diff --git a/logtail-rails.gemspec b/logtail-rails.gemspec index b9c8c7b..f3faf7f 100644 --- a/logtail-rails.gemspec +++ b/logtail-rails.gemspec @@ -58,7 +58,10 @@ Gem::Specification.new do |spec| spec.add_development_dependency('activerecord-jdbcsqlite3-adapter', '>= 0') elsif rails_version >= 3 && rails_version < 6 spec.add_development_dependency('sqlite3', '1.3.13') - else + elsif rails_version >= 6 && rails_version < 8 spec.add_development_dependency('sqlite3', '~> 1.5.0') + else + # Rails 8 and newer, which is also what rails-edge and the root Gemfile resolve to + spec.add_development_dependency('sqlite3', '>= 2.0') end end diff --git a/spec/logtail-rails/action_view/log_subscriber_spec.rb b/spec/logtail-rails/action_view/log_subscriber_spec.rb index 280cf1b..29d0b5e 100755 --- a/spec/logtail-rails/action_view/log_subscriber_spec.rb +++ b/spec/logtail-rails/action_view/log_subscriber_spec.rb @@ -54,6 +54,26 @@ def method_for_action(action_name) expect(lines[2].strip).to match(/Rendered spec\/support\/rails\/templates\/template.html \(\d+\.\d+ms\)/) expect(lines[2]).to include("\"template_rendered\":{\"name\":\"spec/support/rails/templates/template.html\"") end + + if Rails.respond_to?(:event) + # What config.log_level = :info does when the app boots. Rails 8.2 reports the rendering + # events to Rails.event in debug mode only. + context "with the debug mode of Rails.event turned off" do + around(:each) do |example| + debug_mode = Rails.event.debug_mode? + Rails.event.debug_mode = false + example.run + Rails.event.debug_mode = debug_mode + end + + it "should log a template render event once" do + dispatch_rails_request("/action_view_log_subscriber") + lines = clean_lines(io.string.split("\n")) + expect(lines[2].strip).to match(/Rendered spec\/support\/rails\/templates\/template.html \(\d+\.\d+ms\)/) + expect(lines[2]).to include("\"template_rendered\":{\"name\":\"spec/support/rails/templates/template.html\"") + end + end + end end end end diff --git a/spec/logtail-rails/active_record/log_subscriber_spec.rb b/spec/logtail-rails/active_record/log_subscriber_spec.rb index ba7da80..0b071b3 100755 --- a/spec/logtail-rails/active_record/log_subscriber_spec.rb +++ b/spec/logtail-rails/active_record/log_subscriber_spec.rb @@ -39,6 +39,37 @@ expect(string).to include("\"level\":\"debug\"") expect(string).to include("\"sql_query_executed\":") end + + it "should log the bind values" do + User.where(first_name: "Petr").to_a + expect(io.string).to include('[[\"first_name\", \"Petr\"]]') + end + + if Rails.respond_to?(:event) + # What config.log_level = :info does when the app boots. Rails 8.2 reports the SQL events + # to Rails.event in debug mode only, whatever the level of the logger is. + context "with the debug mode of Rails.event turned off" do + around(:each) do |example| + debug_mode = Rails.event.debug_mode? + Rails.event.debug_mode = false + example.run + Rails.event.debug_mode = debug_mode + end + + it "should log the sql query" do + ActiveRecord::Base.connection.execute("select * from users") + expect(io.string).to include("select * from users") + expect(io.string).to include("duration_ms") + expect(io.string).to include("\"level\":\"debug\"") + expect(io.string).to include("\"sql_query_executed\":") + end + + it "should log the bind values" do + User.where(first_name: "Petr").to_a + expect(io.string).to include('[[\"first_name\", \"Petr\"]]') + end + end + end end end end diff --git a/spec/logtail-rails/event_log_subscriber_spec.rb b/spec/logtail-rails/event_log_subscriber_spec.rb new file mode 100644 index 0000000..38d8017 --- /dev/null +++ b/spec/logtail-rails/event_log_subscriber_spec.rb @@ -0,0 +1,30 @@ +require "spec_helper" + +RSpec.describe Logtail::Integrations::Rails::EventLogSubscriber do + let(:io) { StringIO.new } + let(:logger) { Logtail::Logger.new(io) } + let(:subscriber) { described_class.new(logger) } + + before(:each) do + skip("EventLogSubscriber is only subscribed where Rails.event exists, Rails 8.1 and higher") unless Rails.respond_to?(:event) + end + + around(:each) do |example| + with_rails_logger(logger) { example.run } + end + + it "logs events reported by the application" do + subscriber.emit({ name: "user.created", payload: { id: 1 }, tags: {}, context: {}, source_location: {} }) + + expect(io.string).to include('"message":"[user.created] id=1"') + expect(io.string).to include('"event_name":"user.created"') + end + + it "does not log events the Rails framework already logs" do + skip("Rails 8.2 routes the framework's own events through Rails.event") unless defined?(::ActiveSupport::EventReporter::LogSubscriber) + + subscriber.emit({ name: "active_record.sql", payload: { sql: "select 1" }, tags: {}, context: {}, source_location: {} }) + + expect(io.string).to eq("") + end +end