diff --git a/.cspell/project-words.txt b/.cspell/project-words.txt index 38120f9c..2d777d04 100644 --- a/.cspell/project-words.txt +++ b/.cspell/project-words.txt @@ -77,3 +77,4 @@ vercel wordlists xorshift yardoc +tsort diff --git a/lib/log_struct/concerns/configuration.rb b/lib/log_struct/concerns/configuration.rb index 586af7d2..7e611b8d 100644 --- a/lib/log_struct/concerns/configuration.rb +++ b/lib/log_struct/concerns/configuration.rb @@ -61,15 +61,32 @@ def set_enabled_from_rails_env! # 3. Otherwise, leave as config.enabled (defaults to true) # Then check if LOGSTRUCT_ENABLED env var is set - config.enabled = if ENV["LOGSTRUCT_ENABLED"] - %w[true t yes y 1].include?(ENV["LOGSTRUCT_ENABLED"]&.strip&.downcase) - else + env_var_enabled = enabled_from_env_var + config.enabled = if env_var_enabled.nil? is_console = console_process? is_server = server_process? ci_build? in_enabled_env = config.enabled_environments.include?(::Rails.env.to_sym) in_enabled_env && !is_console && (is_server || ::Rails.env.test?) + else + env_var_enabled + end + + # apply_initializer_settings! compares the settings with these + @enabled_from_rails_env = T.let(config.enabled, T.nilable(T::Boolean)) + @enabled_environments_from_rails_env = T.let(config.enabled_environments.dup, T.nilable(T::Array[Symbol])) + end + + # After config/initializers run: LOGSTRUCT_ENABLED takes precedence, then `config.enabled` + # if an initializer changed it, then `config.enabled_environments` if an initializer changed that + sig { void } + def apply_initializer_settings! + env_var_enabled = enabled_from_env_var + if !env_var_enabled.nil? + config.enabled = env_var_enabled + elsif config.enabled == @enabled_from_rails_env && config.enabled_environments != @enabled_environments_from_rails_env + set_enabled_from_rails_env! end end @@ -115,6 +132,14 @@ def merge_rails_filter_parameters! private + sig { returns(T.nilable(T::Boolean)) } + def enabled_from_env_var + value = ENV["LOGSTRUCT_ENABLED"] + return nil if value.nil? + + %w[true t yes y 1].include?(value.strip.downcase) + end + sig { returns(T::Boolean) } def console_process? return true if defined?(::Rails::Console) diff --git a/lib/log_struct/integrations.rb b/lib/log_struct/integrations.rb index 934e5c62..96b41875 100644 --- a/lib/log_struct/integrations.rb +++ b/lib/log_struct/integrations.rb @@ -33,8 +33,8 @@ def self.setup_initializers(railtie) LogStruct::Integrations::Dotenv.intercept_logger_setter! end - # Decide which set of boot logs to emit after user initializers - railtie.initializer "logstruct.resolve_boot_logs", after: :load_config_initializers do + # Decide which set of boot logs to emit once `enabled` is final + railtie.initializer "logstruct.resolve_boot_logs", after: "logstruct.setup" do LogStruct::Integrations::Dotenv.resolve_boot_logs! end end diff --git a/lib/log_struct/integrations/active_model_serializers.rb b/lib/log_struct/integrations/active_model_serializers.rb index e19020f2..b79e858b 100644 --- a/lib/log_struct/integrations/active_model_serializers.rb +++ b/lib/log_struct/integrations/active_model_serializers.rb @@ -17,6 +17,11 @@ def self.setup(config) # Only activate if AMS appears to be present return nil unless defined?(::ActiveModelSerializers) + # AMS logs each render as a line of text too + if defined?(::ActiveModelSerializers::Logging::LogSubscriber) + ::ActiveModelSerializers::Logging::LogSubscriber.detach_from(:active_model_serializers) + end + # Subscribe to common AMS notification names; keep broad but specific pattern = /\.active_model_serializers\z/ diff --git a/lib/log_struct/integrations/good_job.rb b/lib/log_struct/integrations/good_job.rb index 1f4dbf3d..93e595a9 100644 --- a/lib/log_struct/integrations/good_job.rb +++ b/lib/log_struct/integrations/good_job.rb @@ -65,22 +65,29 @@ def self.setup(config) true end + @thread_error_handler = T.let(nil, T.nilable(T.proc.params(exception: StandardError).void)) + # Configure GoodJob to use LogStruct's structured logger sig { void } def self.configure_logger return unless defined?(::GoodJob) - # Use direct reference to avoid const_get - GoodJob is guaranteed to be defined here - goodjob_module = T.unsafe(GoodJob) + # Not GoodJob, which here is this module + goodjob_module = ::GoodJob # Replace GoodJob.logger with our structured logger if GoodJob is available if goodjob_module.respond_to?(:logger=) goodjob_module.logger = LogStruct::Integrations::GoodJob::Logger.new("GoodJob") end - # Configure error handling for thread errors if GoodJob supports it + # Log thread errors, after calling the handler the app set (GoodJob's README sets one + # to report them to an error tracker). Setting up again keeps the one handler. if goodjob_module.respond_to?(:on_thread_error=) - goodjob_module.on_thread_error = ->(exception) do + app_handler = goodjob_module.on_thread_error + return if app_handler&.equal?(@thread_error_handler) + + @thread_error_handler = ->(exception) do + app_handler&.call(exception) log_entry = LogStruct::Log::GoodJob::Error.new( error_class: exception.class.name, error_message: exception.message, @@ -90,6 +97,7 @@ def self.configure_logger ) goodjob_module.logger.error(log_entry) end + goodjob_module.on_thread_error = @thread_error_handler end end diff --git a/lib/log_struct/integrations/puma.rb b/lib/log_struct/integrations/puma.rb index ba01106b..1ab27e6a 100644 --- a/lib/log_struct/integrations/puma.rb +++ b/lib/log_struct/integrations/puma.rb @@ -103,6 +103,9 @@ def install_patches! if puma_mod&.const_defined?(:LogWriter) T.unsafe(::Object.const_get("Puma::LogWriter")).prepend(LogWriterPatch) end + if puma_mod&.const_defined?(:ErrorLogger) + T.unsafe(::Object.const_get("Puma::ErrorLogger")).prepend(ErrorLoggerPatch) + end if puma_mod&.const_defined?(:Events) ev = T.unsafe(::Object.const_get("Puma::Events")) ev.prepend(EventsPatch) @@ -379,6 +382,33 @@ def info(msg) end end + # Puma::ErrorLogger writes request errors (an exception the app didn't handle, a malformed + # request, an SSL error) as plain text to STDERR, with the request's query string. Log them + # as structured lines, with the method and path but not the query string, which LogStruct + # can't filter there. + module ErrorLoggerPatch + extend T::Sig + + sig { params(options: T::Hash[Symbol, T.untyped]).returns(T.untyped) } + def info(options = {}) + error = options[:error] + # Log::Error only takes a StandardError + return super unless error.is_a?(StandardError) + + env = options[:req]&.env + details = { + context: options[:text], + method: env&.dig("REQUEST_METHOD"), + path: env && (env["REQUEST_PATH"] || env["PATH_INFO"]) + }.compact + ::LogStruct.error(::LogStruct::Log.from_exception(::LogStruct::Source::Puma, error, details)) + nil + rescue => e + ::LogStruct::Integrations::Puma.handle_integration_error(e) + super + end + end + # Patch Puma::Events as a fallback for some versions where Events handles output module EventsPatch extend T::Sig diff --git a/lib/log_struct/integrations/shrine.rb b/lib/log_struct/integrations/shrine.rb index be8b8dad..6f157197 100644 --- a/lib/log_struct/integrations/shrine.rb +++ b/lib/log_struct/integrations/shrine.rb @@ -88,71 +88,33 @@ def self.setup(config) ::SemanticLogger[::Shrine].info(log_data) end) - # Check if instrumentation plugin is already loaded - # If so, we need to replace the existing subscribers, not add duplicates - if instrumentation_already_configured? - replace_existing_subscribers(shrine_log_subscriber) - else - # First time setup - configure the instrumentation plugin - ::Shrine.plugin :instrumentation, - events: SHRINE_EVENTS, - log_subscriber: shrine_log_subscriber + # Load the instrumentation plugin without Shrine's default log subscriber, which logs + # each event as a line of text (a no-op if the app has loaded it already). Shrine + # ignores a subscriber that's already subscribed. + ::Shrine.plugin :instrumentation, log_subscriber: nil + SHRINE_EVENTS.each do |event_name| + T.unsafe(::Shrine).subscribe(event_name, &shrine_log_subscriber) end - true - end - - sig { returns(T::Boolean) } - def self.instrumentation_already_configured? - return false unless defined?(::Shrine) - - opts = T.unsafe(::Shrine).opts - return false unless opts.is_a?(Hash) + # The app may load the plugin with the default log subscriber too, before or after this + ::Shrine::Plugins::Instrumentation::LogSubscriber.singleton_class.prepend(SkipLoggedEvents) - instrumentation_opts = opts[:instrumentation] - return false unless instrumentation_opts.is_a?(Hash) + # Other plugins' log subscribers and Shrine's warnings write text to Shrine.logger + ::Shrine.logger = ::SemanticLogger[::Shrine] - subscribers = instrumentation_opts[:subscribers] - return false unless subscribers.is_a?(Hash) - - !subscribers.empty? + true end - sig { params(new_subscriber: T.untyped).void } - def self.replace_existing_subscribers(new_subscriber) - opts = T.unsafe(::Shrine).opts - instrumentation_opts = opts[:instrumentation] - subscribers = instrumentation_opts[:subscribers] + # Prepended to Shrine's default instrumentation log subscriber, so it doesn't log the + # events that LogStruct logs + module SkipLoggedEvents + extend T::Sig - # Clear all existing subscribers and add our new one - SHRINE_EVENTS.each do |event_name| - # Clear existing subscribers for this event - subscribers[event_name] = [] if subscribers[event_name] - - # Add our subscriber - subscribers[event_name] ||= [] - subscribers[event_name] << new_subscriber - - # Also re-subscribe via ActiveSupport::Notifications - # Shrine uses "shrine.#{event_name}" as the notification name - notification_name = "shrine.#{event_name}" - - # Unsubscribe existing listeners for this event - # ActiveSupport::Notifications stores subscriptions, we need to find and remove them - notifier = ::ActiveSupport::Notifications.notifier - if notifier.respond_to?(:listeners_for) - # Rails 7.0+ uses listeners_for - listeners = notifier.listeners_for(notification_name) - listeners.each do |listener| - ::ActiveSupport::Notifications.unsubscribe(listener) - end - end + sig { params(event: T.untyped).returns(T.untyped) } + def call(event) + return if SHRINE_EVENTS.include?(event.name) - # Subscribe our new subscriber - ::ActiveSupport::Notifications.subscribe(notification_name) do |*args| - event = ::ActiveSupport::Notifications::Event.new(*args) - new_subscriber.call(event) - end + super end end end diff --git a/lib/log_struct/integrations/sidekiq.rb b/lib/log_struct/integrations/sidekiq.rb index fbc72bb6..30a1a4e6 100644 --- a/lib/log_struct/integrations/sidekiq.rb +++ b/lib/log_struct/integrations/sidekiq.rb @@ -18,6 +18,8 @@ module Sidekiq extend T::Sig extend IntegrationInterface + @original_logger = T.let(nil, T.untyped) + # Set up Sidekiq structured logging sig { override.params(config: LogStruct::Configuration).returns(T.nilable(T::Boolean)) } def self.setup(config) @@ -25,10 +27,9 @@ def self.setup(config) return nil unless config.enabled return nil unless config.integrations.enable_sidekiq - # Configure Sidekiq server (worker) to use our logger - ::Sidekiq.configure_server do |sidekiq_config| - sidekiq_config.logger = LogStruct::Integrations::Sidekiq::Logger.new("Sidekiq-Server") + configure_logger + ::Sidekiq.configure_server do |sidekiq_config| # First in the chain, so lines logged by other middleware include the job too sidekiq_config.server_middleware do |chain| chain.prepend LogStruct::Integrations::Sidekiq::JobContextMiddleware @@ -37,14 +38,41 @@ def self.setup(config) replace_default_error_handler(sidekiq_config) end - # Configure Sidekiq client (Rails app) to use our logger - ::Sidekiq.configure_client do |sidekiq_config| - sidekiq_config.logger = LogStruct::Integrations::Sidekiq::Logger.new("Sidekiq-Client") - end - true end + # Use LogStruct's logger for Sidekiq's own lines. The Railtie calls this as soon as it replaces + # Rails.logger, before config/initializers run, because an initializer that configures Sidekiq + # (connecting to Redis, setting up a fetcher) logs with Sidekiq's logger straight away. + sig { void } + def self.configure_logger + return unless defined?(::Sidekiq) + + current = sidekiq_logger_config.logger + return if current.is_a?(LogStruct::Integrations::Sidekiq::Logger) + + @original_logger = current + name = ::Sidekiq.server? ? "Sidekiq-Server" : "Sidekiq-Client" + sidekiq_logger_config.logger = LogStruct::Integrations::Sidekiq::Logger.new(name) + end + + # Put Sidekiq's own logger back, when an initializer turned LogStruct or this integration off + # after configure_logger ran + sig { void } + def self.restore_logger + return unless defined?(::Sidekiq) + return if @original_logger.nil? + + sidekiq_logger_config.logger = @original_logger + @original_logger = nil + end + + # Sidekiq 7 keeps the logger on its default configuration, Sidekiq 6 on the module + sig { returns(T.untyped) } + def self.sidekiq_logger_config + ::Sidekiq.respond_to?(:default_configuration) ? ::Sidekiq.default_configuration : ::Sidekiq + end + # Sidekiq's default error handler logs three lines for each failed job: the job (with its # arguments) as a JSON string, the error, and the backtrace. Log one structured line instead, # without the arguments, which LogStruct can't filter inside a JSON string. @@ -92,7 +120,7 @@ def self.log_job_error(error, context) T.proc.params(error: Exception, context: T::Hash[T.untyped, T.untyped], config: T.untyped).void ) - private_class_method :replace_default_error_handler, :log_job_error + private_class_method :sidekiq_logger_config, :replace_default_error_handler, :log_job_error end end end diff --git a/lib/log_struct/railtie.rb b/lib/log_struct/railtie.rb index 95697650..ff1abe6b 100644 --- a/lib/log_struct/railtie.rb +++ b/lib/log_struct/railtie.rb @@ -10,31 +10,43 @@ module LogStruct # Railtie to integrate with Rails class Railtie < ::Rails::Railtie - # Configure early, right after logger initialization + # Replace the logger as soon as Rails creates it, so boot-time logs and anything that keeps + # a reference to Rails.logger use LogStruct's logger initializer "logstruct.configure_logger", after: :initialize_logger do |app| next unless LogStruct.enabled? # Use SemanticLogger for powerful logging features LogStruct::SemanticLogger::Setup.configure_semantic_logger(app) + + # Initializers that configure Sidekiq log with its logger while config/initializers run + Integrations::Sidekiq.configure_logger if LogStruct.config.integrations.enable_sidekiq end - # Setup all integrations after logger setup is complete - initializer "logstruct.setup", before: :build_middleware_stack do |app| + # Set up integrations after config/initializers, so that the settings in + # config/initializers/logstruct.rb and filter_parameters added by other initializers apply + initializer "logstruct.setup", after: :load_config_initializers, before: :build_middleware_stack do |app| + # An initializer may have changed `enabled` or `enabled_environments` after the logger was + # (or wasn't) replaced + LogStruct.apply_initializer_settings! + if LogStruct.enabled? + LogStruct::SemanticLogger::Setup.configure_semantic_logger(app) unless LogStruct::SemanticLogger::Setup.configured? + elsif LogStruct::SemanticLogger::Setup.configured? + LogStruct::SemanticLogger::Setup.restore_rails_logger(app) + end + unless LogStruct.enabled? && LogStruct.config.integrations.enable_sidekiq + Integrations::Sidekiq.restore_logger + end + next unless LogStruct.enabled? # Merge Rails filter parameters into our filters LogStruct.merge_rails_filter_parameters! - # Set up non-middleware integrations first Integrations.setup_integrations(stage: :non_middleware) - - # Note: Host allowances are managed by the test app itself. end - # Setup middleware integrations during Rails configuration (before middleware stack is built) - # Must be done in the Railtie class body, not in an initializer - initializer "logstruct.configure_middleware", before: :build_middleware_stack do |app| - # This runs before middleware stack is frozen, so we can configure it + # Add middleware before the middleware stack is built + initializer "logstruct.configure_middleware", after: "logstruct.setup", before: :build_middleware_stack do |app| next unless LogStruct.enabled? Integrations.setup_integrations(stage: :middleware) @@ -53,10 +65,6 @@ class Railtie < ::Rails::Railtie process_id: Process.pid, listening_addresses: port ? ["tcp://127.0.0.1:#{port}"] : nil ) - begin - warn("[logstruct] puma lifecycle init") - rescue - end LogStruct.info(started) at_exit do diff --git a/lib/log_struct/semantic_logger/setup.rb b/lib/log_struct/semantic_logger/setup.rb index d1edfeca..bb3164dc 100644 --- a/lib/log_struct/semantic_logger/setup.rb +++ b/lib/log_struct/semantic_logger/setup.rb @@ -62,6 +62,23 @@ module SemanticLogger module Setup extend T::Sig + # Load hooks for the framework components whose loggers LogStruct replaces + COMPONENT_LOAD_HOOKS = T.let( + %i[active_record action_controller action_mailer active_job action_view action_cable].freeze, + T::Array[Symbol] + ) + + # The logger LogStruct installed, and the loggers it replaced + @logger = T.let(nil, T.nilable(LogStruct::SemanticLogger::Logger)) + @original_rails_logger = T.let(nil, T.untyped) + @original_log_subscriber_logger = T.let(nil, T.untyped) + @original_app_logger = T.let(nil, T.untyped) + + sig { returns(T::Boolean) } + def self.configured? + !@logger.nil? + end + # Configures SemanticLogger as the primary logging engine for the Rails application # # This method replaces Rails' default logger with SemanticLogger, providing: @@ -217,6 +234,10 @@ def self.determine_filter def self.replace_rails_logger(app) # Create new SemanticLogger instance logger = LogStruct::SemanticLogger::Logger.new("Rails") + @logger = logger + @original_rails_logger = Rails.logger + @original_log_subscriber_logger = ActiveSupport::LogSubscriber.logger + @original_app_logger = app.config.logger # Replace Rails.logger Rails.logger = logger @@ -231,16 +252,36 @@ def self.replace_rails_logger(app) # classes: loading them this early would apply their on_load hooks before the app's # initializers run, e.g. ActiveRecord would copy an empty filter_parameters into # filter_attributes. - ActiveSupport.on_load(:active_record) { T.unsafe(self).logger = logger } - ActiveSupport.on_load(:action_controller) { T.unsafe(self).logger = logger } - ActiveSupport.on_load(:action_mailer) { T.unsafe(self).logger = logger } - ActiveSupport.on_load(:active_job) { T.unsafe(self).logger = logger } - ActiveSupport.on_load(:action_view) { T.unsafe(self).logger = logger } - ActiveSupport.on_load(:action_cable) { T.unsafe(self).logger = logger } + COMPONENT_LOAD_HOOKS.each do |hook| + ActiveSupport.on_load(hook) { T.unsafe(self).logger = logger } + end # Store reference in app config app.config.logger = logger end + + # Puts back the loggers that replace_rails_logger replaced. Used when an initializer + # disables LogStruct after the logger was replaced at boot. + sig { params(app: T.untyped).void } + def self.restore_rails_logger(app) + logger = @logger + return unless logger + + original_logger = @original_rails_logger + Rails.logger = original_logger + ActiveSupport::LogSubscriber.logger = @original_log_subscriber_logger + app.config.logger = @original_app_logger + + # These hooks run after the ones that installed LogStruct's logger, including for + # components that are already loaded + COMPONENT_LOAD_HOOKS.each do |hook| + ActiveSupport.on_load(hook) do + T.unsafe(self).logger = original_logger if T.unsafe(self).logger.equal?(logger) + end + end + + @logger = nil + end end end end diff --git a/rails_test_app/templates/config/initializers/logstruct.rb b/rails_test_app/templates/config/initializers/logstruct.rb index 53d2ad1b..b33a2ed5 100644 --- a/rails_test_app/templates/config/initializers/logstruct.rb +++ b/rails_test_app/templates/config/initializers/logstruct.rb @@ -7,6 +7,14 @@ # Specify which environments to enable in config.enabled_environments = [:development, :test, :production] + # Lets BootLogsIntegrationTest check that `enabled` and `enabled_environments` set here are honored + if ENV.key?("LOGSTRUCT_TEST_INITIALIZER_ENABLED") + config.enabled = ENV["LOGSTRUCT_TEST_INITIALIZER_ENABLED"] == "true" + end + if ENV.key?("LOGSTRUCT_TEST_INITIALIZER_ENVIRONMENTS") + config.enabled_environments = ENV.fetch("LOGSTRUCT_TEST_INITIALIZER_ENVIRONMENTS").split(",").map(&:to_sym) + end + # Specify which environments are considered local/development config.local_environments = [:development, :test] diff --git a/rails_test_app/templates/test/integration/ams_logging_test.rb b/rails_test_app/templates/test/integration/ams_logging_test.rb index 60f049f7..3159c71a 100644 --- a/rails_test_app/templates/test/integration/ams_logging_test.rb +++ b/rails_test_app/templates/test/integration/ams_logging_test.rb @@ -59,22 +59,19 @@ def test_ams_logs_are_not_ruby_hash_inspect_format def test_ams_logs_do_not_pollute_with_default_format raise "AMS not available" unless defined?(::ActiveModelSerializers) - # Capture both SemanticLogger output and stdout - original_stdout = $stdout - stdout_capture = StringIO.new - $stdout = stdout_capture + # AMS's own log subscriber writes "Rendered UserSerializer with ... (0.1ms)" to this logger + ams_log = StringIO.new + original_logger = ActiveModelSerializers.logger + ActiveModelSerializers.logger = ActiveSupport::TaggedLogging.new(Logger.new(ams_log)) - get "/logging/basic" + get "/logging/ams" ::SemanticLogger.flush - $stdout = original_stdout - stdout_capture.rewind - stdout_output = stdout_capture.read.to_s - - # AMS default logs like "Rendered X with Y (Zms)" should NOT appear in stdout - refute_match(/Rendered\s+\S+Serializer\s+with/, - stdout_output, - "AMS default log format should not appear in stdout") + + assert_includes @log_output.string, '"msg":"ams.render"' + refute_match(/Rendered\s+\S+\s+with/, ams_log.string, "AMS default log lines should not be logged") + ensure + ActiveModelSerializers.logger = original_logger end def test_ams_logs_adapter_class_name_not_serialized_output diff --git a/rails_test_app/templates/test/integration/boot_logs_integration_test.rb b/rails_test_app/templates/test/integration/boot_logs_integration_test.rb index ef0e8939..64d6fee0 100644 --- a/rails_test_app/templates/test/integration/boot_logs_integration_test.rb +++ b/rails_test_app/templates/test/integration/boot_logs_integration_test.rb @@ -58,8 +58,66 @@ def test_rails_runner_emits_original_dotenv_logs_when_disabled assert dotenv_lines.any? { |l| l.include?("Loaded ") }, "Expected a 'Loaded ...' line" end + def test_initializer_can_disable_logstruct_after_the_logger_was_replaced + result = runner_loggers( + "RAILS_ENV" => "test", + "LOGSTRUCT_ENABLED" => nil, + "LOGSTRUCT_TEST_INITIALIZER_ENABLED" => "false" + ) + + assert_equal "false", result[:enabled] + refute_match(/LogStruct/, result[:rails_logger]) + refute_match(/LogStruct/, result[:active_record_logger]) + end + + def test_initializer_can_enable_logstruct + result = runner_loggers( + "RAILS_ENV" => "development", + "LOGSTRUCT_ENABLED" => nil, + "LOGSTRUCT_TEST_INITIALIZER_ENABLED" => "true" + ) + + assert_equal "true", result[:enabled] + assert_equal "LogStruct::SemanticLogger::Logger", result[:rails_logger] + assert_equal "LogStruct::SemanticLogger::Logger", result[:active_record_logger] + end + + def test_initializer_can_change_enabled_environments + result = runner_loggers( + "RAILS_ENV" => "test", + "LOGSTRUCT_ENABLED" => nil, + "LOGSTRUCT_TEST_INITIALIZER_ENVIRONMENTS" => "production" + ) + + assert_equal "false", result[:enabled] + refute_match(/LogStruct/, result[:rails_logger]) + end + + def test_logstruct_enabled_env_var_overrides_the_initializer + result = runner_loggers( + "RAILS_ENV" => "development", + "LOGSTRUCT_ENABLED" => "false", + "LOGSTRUCT_TEST_INITIALIZER_ENABLED" => "true" + ) + + assert_equal "false", result[:enabled] + refute_match(/LogStruct/, result[:rails_logger]) + end + private + def runner_loggers(env) + script = 'puts "LOGGERS #{LogStruct.enabled?} #{Rails.logger.class} #{ActiveRecord::Base.logger.class}"' + stdout_str, stderr_str, status = Open3.capture3(env, "bundle", "exec", "rails", "runner", script) + + assert_predicate status, :success?, "rails runner failed: #{stderr_str}" + line = stdout_str.lines.find { |l| l.start_with?("LOGGERS ") } + + assert line, "Expected a LOGGERS line in:\n#{stdout_str}" + _, enabled, rails_logger, active_record_logger = T.must(line).split + {enabled: enabled, rails_logger: rails_logger, active_record_logger: active_record_logger} + end + def runner_output_lines(env) cmd = ["bundle", "exec", "rails", "runner", "puts LogStruct.enabled?"] stdout_str, stderr_str, status = Open3.capture3(env, *cmd) diff --git a/rails_test_app/templates/test/integration/filter_parameters_test.rb b/rails_test_app/templates/test/integration/filter_parameters_test.rb index 294d6308..378b3bc5 100644 --- a/rails_test_app/templates/test/integration/filter_parameters_test.rb +++ b/rails_test_app/templates/test/integration/filter_parameters_test.rb @@ -16,6 +16,19 @@ def test_rails_keeps_its_filter_parameters assert_equal "[FILTERED]", filter.filter("password" => "hunter2")["password"] end + def test_logstruct_filters_keys_from_initializers_the_way_rails_does + # :otp and :crypt come from config/initializers/filter_parameter_logging.rb, not LogStruct's + # defaults, and Rails matches them anywhere in a key + Rails.logger.info(msg: "Signed in", otp_attempt: "135790", encrypted_note: "hunter2") + + ::SemanticLogger.flush + output = @log_output.string + + assert_includes output, "Signed in" + assert_not_includes output, "135790" + assert_not_includes output, "hunter2" + end + def test_active_record_filter_attributes_still_filter assert_includes ActiveRecord::Base.filter_attributes, :passw end diff --git a/rails_test_app/templates/test/integration/shrine_logging_test.rb b/rails_test_app/templates/test/integration/shrine_logging_test.rb index 33dbb78d..15683cc1 100644 --- a/rails_test_app/templates/test/integration/shrine_logging_test.rb +++ b/rails_test_app/templates/test/integration/shrine_logging_test.rb @@ -134,31 +134,28 @@ def test_shrine_logs_are_json_not_ruby_inspect end end - def test_shrine_default_log_format_is_suppressed - # Capture STDOUT to check for Shrine's default log format - # Shrine's default format looks like: "Upload (0ms) – {storage: :store, ...}" - original_stdout = $stdout - stdout_capture = StringIO.new - $stdout = stdout_capture + def test_shrine_default_log_subscriber_does_not_log_events + # config/initializers/shrine.rb loads the instrumentation plugin with Shrine's default + # log subscriber, which writes lines like "Upload (0ms) – {storage: :store, ...}" + shrine_log = StringIO.new + original_logger = Shrine.logger + Shrine.logger = Logger.new(shrine_log) get "/logging/shrine_upload" assert_response :success + refute_match(/(Upload|Metadata|Open|Download|Exists|Delete) \(\d+ms\) –/, shrine_log.string) + ensure + Shrine.logger = original_logger + end + + def test_shrine_logger_writes_json + Shrine.warn("test warning") ::SemanticLogger.flush - $stdout = original_stdout - stdout_capture.rewind - stdout_output = stdout_capture.read.to_s - - # Shrine's default log format should NOT appear - refute_match(/Upload \(\d+ms\) – \{/, - stdout_output, - "Shrine's default log format should not appear in stdout") - refute_match(/Metadata \(\d+ms\) – \{/, - stdout_output, - "Shrine's default metadata format should not appear in stdout") - refute_match(/Open \(\d+ms\) – \{/, - stdout_output, - "Shrine's default open format should not appear in stdout") + line = @log_output.string.lines.find { |l| l.include?("test warning") } + + assert line, "Expected the Shrine warning in the LogStruct output:\n#{@log_output.string}" + assert_equal "SHRINE WARNING: test warning", JSON.parse(line)["msg"] end end diff --git a/sorbet/rbi/shims/good_job.rbi b/sorbet/rbi/shims/good_job.rbi new file mode 100644 index 00000000..67195a4f --- /dev/null +++ b/sorbet/rbi/shims/good_job.rbi @@ -0,0 +1,19 @@ +# typed: true + +# GoodJob isn't installed for development (it needs PostgreSQL), so Tapioca has no RBI for it. +# These are the settings the GoodJob integration changes. +module GoodJob + class << self + sig { returns(T.untyped) } + def logger; end + + sig { params(logger: T.untyped).void } + def logger=(logger); end + + sig { returns(T.nilable(T.proc.params(exception: StandardError).void)) } + def on_thread_error; end + + sig { params(handler: T.nilable(T.proc.params(exception: StandardError).void)).void } + def on_thread_error=(handler); end + end +end diff --git a/sorbet/rbi/shims/shrine.rbi b/sorbet/rbi/shims/shrine.rbi new file mode 100644 index 00000000..36a30ae0 --- /dev/null +++ b/sorbet/rbi/shims/shrine.rbi @@ -0,0 +1,8 @@ +# typed: true + +# Shrine loads its plugins on demand, so Tapioca doesn't generate RBIs for them +module Shrine::Plugins::Instrumentation + class LogSubscriber + def self.call(event); end + end +end diff --git a/test/log_struct/configuration_test.rb b/test/log_struct/configuration_test.rb index 8fb2eb9e..df215913 100644 --- a/test/log_struct/configuration_test.rb +++ b/test/log_struct/configuration_test.rb @@ -105,6 +105,49 @@ def test_enabled_env_var_takes_precedence_over_environment end end + def test_enabled_environments_set_in_an_initializer_apply + ClimateControl.modify LOGSTRUCT_ENABLED: nil do + Rails.stub(:env, ActiveSupport::StringInquirer.new("test")) do + LogStruct.config.enabled_environments = [:test, :production] + LogStruct.set_enabled_from_rails_env! + + LogStruct.config.enabled_environments = [:production] + LogStruct.apply_initializer_settings! + + refute LogStruct.config.enabled + end + end + end + + def test_enabled_set_in_an_initializer_wins_over_enabled_environments + ClimateControl.modify LOGSTRUCT_ENABLED: nil do + Rails.stub(:env, ActiveSupport::StringInquirer.new("test")) do + LogStruct.config.enabled_environments = [:production] + LogStruct.set_enabled_from_rails_env! + + LogStruct.config.enabled = true + LogStruct.config.enabled_environments = [:staging] + LogStruct.apply_initializer_settings! + + assert LogStruct.config.enabled + end + end + end + + def test_logstruct_enabled_wins_over_settings_from_an_initializer + ClimateControl.modify LOGSTRUCT_ENABLED: "true" do + Rails.stub(:env, ActiveSupport::StringInquirer.new("test")) do + LogStruct.set_enabled_from_rails_env! + + LogStruct.config.enabled = false + LogStruct.config.enabled_environments = [:production] + LogStruct.apply_initializer_settings! + + assert LogStruct.config.enabled + end + end + end + def test_merge_rails_filter_parameters_matches_keys_the_way_rails_does filter_params = [:passw, "Card_Number", :_key] diff --git a/test/log_struct/integrations/good_job_test.rb b/test/log_struct/integrations/good_job_test.rb index 2525f194..26495169 100644 --- a/test/log_struct/integrations/good_job_test.rb +++ b/test/log_struct/integrations/good_job_test.rb @@ -2,6 +2,7 @@ # frozen_string_literal: true require "test_helper" +require "log_struct/integrations/good_job/logger" module LogStruct module Integrations @@ -56,6 +57,25 @@ class GoodJobTest < ActiveSupport::TestCase assert_includes GoodJob.private_methods, :configure_logger end + test "replaces GoodJob's logger and logs thread errors after the app's own handler" do + with_fake_goodjob do |fake| + reported = [] + fake.on_thread_error = ->(exception) { reported << exception.message } + + GoodJob.send(:configure_logger) + GoodJob.send(:configure_logger) + + assert_instance_of GoodJob::Logger, fake.logger + logged = [] + fake.logger.stub(:error, ->(entry) { logged << entry.error_message }) do + fake.on_thread_error.call(RuntimeError.new("boom")) + end + + assert_equal ["boom"], reported + assert_equal ["boom"], logged + end + end + test "subscribe_to_notifications method exists and is private" do assert_includes GoodJob.private_methods, :subscribe_to_notifications end @@ -80,6 +100,19 @@ class GoodJobTest < ActiveSupport::TestCase private + # Stands in for the GoodJob gem, which isn't installed for the tests + def with_fake_goodjob + fake = Module.new do + class << self + attr_accessor :logger, :on_thread_error + end + end + Object.const_set(:GoodJob, fake) + yield fake + ensure + Object.send(:remove_const, :GoodJob) + end + def skip_if_goodjob_defined if defined?(::GoodJob) skip "GoodJob is defined in test environment - cannot test undefined behavior" diff --git a/test/log_struct/integrations/puma_unit_test.rb b/test/log_struct/integrations/puma_unit_test.rb index e83881e1..b0101c25 100644 --- a/test/log_struct/integrations/puma_unit_test.rb +++ b/test/log_struct/integrations/puma_unit_test.rb @@ -65,6 +65,37 @@ def test_process_line_returns_false_for_unhandled_input refute PUMA.process_line("unrecognized line") end + # Stands in for Puma::ErrorLogger, which writes "