+ LogStruct writes only part of very large values, so a huge request body or Hash can't + slow down the thread that writes your logs. Long strings are scrubbed before they're + cut. +
+ +
- LogStruct provides customizable error handling modes to control how errors are processed.
- You probably don't want type-checking errors or internal logging-related errors to
- crash your application, so our default behavior is to log and report those errors without
- crashing. We automatically detect which error reporting service you use (Sentry, Bugsnag,
- Rollbar, etc.). If you use a service that we don't support yet, you can configure a{' '}
+ LogStruct sorts the errors it handles into four groups, each with its own mode (the example
+ below shows all four with their defaults). Type-checking errors and errors inside LogStruct
+ are raised in development and test, so you see them early. In production they don't
+ crash your app: type-checking errors are logged and reported, and LogStruct's own
+ errors are logged. The modes are Ignore, Log, Report{' '}
+ (log and report), LogProduction and ReportProduction (log, or log
+ and report, in production; raise in development and test) and Raise.
+
+ We automatically detect which error reporting service you use (Sentry, Bugsnag, Rollbar, + Honeybadger). If you use a service that we don't support yet, you can configure a{' '} custom error handler. (Or you can send a PR!)
@@ -259,10 +274,10 @@ end`}
- LogStruct integrates with Sorbet to handle type checking errors based on the environment. We
- raise type errors or logging-related errors in test/development so you can catch them early,
- but we only log or report them in production. You can configure a different error handling
- mode to change this behavior.
+ LogStruct sets Sorbet's runtime error handlers, so a type error anywhere in your app or
+ its gems is raised in development and test, and logged and reported in production while your
+ app carries on (error_handling_modes.type_checking_errors). Without LogStruct,
+ Sorbet raises them everywhere.
- LogStruct integrates with Sorbet to handle type checking errors appropriately based on the - environment. We raise any logging-related errors in test/development and log or report - them in production to avoid crashing your application. + LogStruct sets Sorbet's runtime error handlers: type errors are raised in development + and test, and logged and reported in production so they don't crash your app.
RAILS_LOG_TO_STDOUT set, both log to STDOUT only. In development, you can
+ opt‑in to the same JSON to avoid surprises.
RAILS_LOG_TO_STDOUT=1 (many platforms set this by default).
+ LogStruct logs to STDOUT in production whether or not RAILS_LOG_TO_STDOUT is
+ set, so your platform collects the lines from the process's output.
- LogStruct configures Sorbet error handlers to log and report type-checking errors. If you
- already use Sorbet and you want to keep using your own error handlers, set{' '}
- enable_sorbet_error_handlers to false. This will prevent LogStruct
- from overriding your handlers.
+ LogStruct sets Sorbet's runtime error handlers: type errors are raised in development
+ and test, and logged and reported in production. The{' '}
+
+ type_checking_errors mode
+ {' '}
+ changes this. If you already use Sorbet and you want to keep using your own error handlers,
+ set enable_sorbet_error_handlers to false. This will prevent
+ LogStruct from overriding your handlers.
IP spoofing detected. This request has been blocked for security reasons.
" \ - "", - String - ) - - # CSRF error response - CSRF_HTML = T.let( - "Invalid authenticity token. This request has been blocked to prevent cross-site request forgery.
" \ - "", - String - ) - - # Response headers calculated at load time - IP_SPOOF_HEADERS = T.let( - { - "Content-Type" => "text/html", - "Content-Length" => IP_SPOOF_HTML.bytesize.to_s - }.freeze, - T::Hash[String, String] - ) - - CSRF_HEADERS = T.let( - { - "Content-Type" => "text/html", - "Content-Length" => CSRF_HTML.bytesize.to_s - }.freeze, - T::Hash[String, String] - ) - - # HTTP status code for forbidden responses - FORBIDDEN_STATUS = T.let(403, Integer) - - sig { params(app: T.untyped).void } - def initialize(app) - @app = app - end - - sig { params(env: T.untyped).returns(T.untyped) } + # Logs the errors that get past ShowExceptions, or come from the middleware outside it (an IP + # spoofing error from a middleware that reads remote_ip, for example), then raises them again + # for the server to handle as it would without LogStruct + class Middleware < RackMiddleware + sig { override.params(env: T.untyped).returns(T.untyped) } def call(env) - return @app.call(env) unless LogStruct.enabled? - - request = ::ActionDispatch::Request.new(env) - - begin - # Trigger the same spoofing checks that ActionDispatch::RemoteIp performs after - # it is initialized in the middleware stack. We run this manually because we - # execute before that middleware and still want spoofing attacks to surface here. - perform_remote_ip_check!(request) - - @app.call(env) - rescue ::ActionDispatch::RemoteIp::IpSpoofAttackError => ip_spoof_error - # Create a security log for IP spoofing - security_log = Log::Security::IPSpoof.new( - path: env["PATH_INFO"], - http_method: env["REQUEST_METHOD"], - user_agent: env["HTTP_USER_AGENT"], - referer: StringScrubber.without_query(env["HTTP_REFERER"]), - message: ip_spoof_error.message, - client_ip: env["HTTP_CLIENT_IP"], - x_forwarded_for: env["HTTP_X_FORWARDED_FOR"], - timestamp: Time.now - ) - - ::Rails.logger.warn(security_log) - - [FORBIDDEN_STATUS, IP_SPOOF_HEADERS.dup, [IP_SPOOF_HTML]] - rescue => error - if csrf_error?(error) - # Create a security log for CSRF error - security_log = Log::Security::CSRFViolation.new( - path: request.path, - http_method: request.method, - source_ip: request.remote_ip, - user_agent: request.user_agent, - referer: StringScrubber.without_query(request.referer), - message: error.message, - timestamp: Time.now - ) - LogStruct.error(security_log) - - # Report to error reporting service and/or re-raise - context = extract_request_context(env, request) - LogStruct.handle_exception(error, source: Source::Security, context: context) - - # If handle_exception raised an exception then Rails will deal with it (e.g. config.exceptions_app) - # If we are only logging or reporting these security errors, then return a default response - [FORBIDDEN_STATUS, CSRF_HEADERS.dup, [CSRF_HTML]] - else - # Extract request context for error reporting - context = extract_request_context(env, request) - - # Create and log a structured exception with request context - exception_log = Log.from_exception(Source::Rails, error, context) - LogStruct.error(exception_log) - - # Re-raise any standard errors to let Rails or error reporter handle it. - # Rails will also log the request details separately - raise error - end - end - end - - private - - sig { params(request: ::ActionDispatch::Request).void } - def perform_remote_ip_check!(request) - action_dispatch_config = ::Rails.application.config.action_dispatch - check_ip = action_dispatch_config.ip_spoofing_check - return unless check_ip - - proxies = normalized_trusted_proxies(action_dispatch_config.trusted_proxies) - - ::ActionDispatch::RemoteIp::GetIp - .new(request, check_ip, proxies) - .to_s - end - - sig { params(env: T::Hash[String, T.untyped], request: T.nilable(::ActionDispatch::Request)).returns(T::Hash[Symbol, T.untyped]) } - def extract_request_context(env, request = nil) - request ||= ::ActionDispatch::Request.new(env) - { - path: request.path, - method: request.method, - user_agent: request.user_agent, - referer: StringScrubber.without_query(request.referer) - } + @app.call(env) rescue => error - # If we can't extract request context, return minimal info - {error_extracting_context: error.message} - end - - sig { params(error: StandardError).returns(T::Boolean) } - def csrf_error?(error) - error_name = error.class.name - error_name == "ActionController::InvalidAuthenticityToken" || - error_name == "ActionController::InvalidCrossOriginRequest" - end - - sig { params(configured_proxies: T.untyped).returns(T.untyped) } - def normalized_trusted_proxies(configured_proxies) - if configured_proxies.nil? || (configured_proxies.respond_to?(:empty?) && configured_proxies.empty?) - return ::ActionDispatch::RemoteIp::TRUSTED_PROXIES + begin + ErrorLines.log_escaped(::ActionDispatch::Request.new(env), error) + rescue => logging_error + LogStruct.handle_exception(logging_error, source: Source::Internal) end - - return configured_proxies if configured_proxies.respond_to?(:any?) - - raise( - ArgumentError, - <<~EOM - Setting config.action_dispatch.trusted_proxies to a single value isn't - supported. Please set this to an enumerable instead. For - example, instead of: - - config.action_dispatch.trusted_proxies = IPAddr.new("10.0.0.0/8") - - Wrap the value in an Array: - - config.action_dispatch.trusted_proxies = [IPAddr.new("10.0.0.0/8")] - - Note that passing an enumerable will *replace* the default set of trusted proxies. - EOM - ) + raise error end end end diff --git a/lib/log_struct/integrations/rack_middleware.rb b/lib/log_struct/integrations/rack_middleware.rb new file mode 100644 index 00000000..57d0cedc --- /dev/null +++ b/lib/log_struct/integrations/rack_middleware.rb @@ -0,0 +1,23 @@ +# typed: strict +# frozen_string_literal: true + +module LogStruct + module Integrations + # A Rack middleware around the app: subclasses define call, and pass the request on to @app + class RackMiddleware + extend T::Sig + extend T::Helpers + + abstract! + + sig { params(app: T.untyped).void } + def initialize(app) + @app = app + end + + sig { abstract.params(env: T.untyped).returns(T.untyped) } + def call(env) + end + end + end +end diff --git a/lib/log_struct/integrations/request_context/middleware.rb b/lib/log_struct/integrations/request_context/middleware.rb index 76c88f90..0b6cc6fd 100644 --- a/lib/log_struct/integrations/request_context/middleware.rb +++ b/lib/log_struct/integrations/request_context/middleware.rb @@ -1,20 +1,15 @@ # typed: strict # frozen_string_literal: true +require_relative "../rack_middleware" + module LogStruct module Integrations module RequestContext # Middleware that captures request_id and stores it in SemanticLogger's # named_tags so all logs during the request include the request_id. - class Middleware - extend T::Sig - - sig { params(app: T.untyped).void } - def initialize(app) - @app = app - end - - sig { params(env: T.untyped).returns(T.untyped) } + class Middleware < RackMiddleware + sig { override.params(env: T.untyped).returns(T.untyped) } def call(env) request = ::ActionDispatch::Request.new(env) request_id = request.request_id diff --git a/lib/log_struct/integrations/sidekiq/logger.rb b/lib/log_struct/integrations/sidekiq/logger.rb index 166f1190..6ed29f48 100644 --- a/lib/log_struct/integrations/sidekiq/logger.rb +++ b/lib/log_struct/integrations/sidekiq/logger.rb @@ -23,12 +23,15 @@ class Logger < LogStruct::SemanticLogger::Logger # Override log methods to create Sidekiq log structs %i[debug info warn error fatal].each do |level| define_method(level) do |message = nil, payload = nil, &block| - # Ensure message is a String (Sidekiq may pass Hash for config logs) - msg = if message.nil? - block ? block.call.to_s : "" - else - message.to_s + # Hashes, LogStruct log entries and exceptions are logged as they are, so their keys are + # filtered (Sidekiq logs some settings as a Hash) + unless message.nil? || message.is_a?(String) + next super(message, payload, &block) end + # A message with an exception is an error line with both + next super(message, payload, &block) if payload.is_a?(Exception) + + msg = message || (block ? block.call.to_s : "") # Create a Sidekiq log struct with the message log_struct = Log::Sidekiq::Log.new( @@ -39,11 +42,12 @@ class Logger < LogStruct::SemanticLogger::Logger thread_id: Sidekiq.tid, # Log a copy: SemanticLogger may still be serializing the struct on its appender # thread when Sidekiq adds :elapsed to the live context after the job finishes. - context: (::Sidekiq::Context.current || {}).dup + context: (::Sidekiq::Context.current || {}).dup, + additional_data: payload.is_a?(Hash) ? payload : nil ) # Pass the struct to SemanticLogger - super(log_struct, payload, &nil) + super(log_struct, nil, &nil) end end end diff --git a/lib/log_struct/log/active_job.rb b/lib/log_struct/log/active_job.rb index b2233b88..db2bd486 100644 --- a/lib/log_struct/log/active_job.rb +++ b/lib/log_struct/log/active_job.rb @@ -10,6 +10,7 @@ require_relative "active_job/schedule" require_relative "active_job/start" require_relative "active_job/finish" +require_relative "active_job/error" module LogStruct module Log diff --git a/lib/log_struct/log/active_job/error.rb b/lib/log_struct/log/active_job/error.rb new file mode 100644 index 00000000..0b5f97dd --- /dev/null +++ b/lib/log_struct/log/active_job/error.rb @@ -0,0 +1,65 @@ +# typed: strict +# frozen_string_literal: true + +# AUTO-GENERATED: DO NOT EDIT +# Generated by scripts/generate_structs.rb +# Schemas dir: schemas/log_sources/ +# Template: tools/codegen/templates/sorbet/event.rb.erb + +require "log_struct/shared/interfaces/common_fields" +require "log_struct/shared/interfaces/additional_data_field" +require "log_struct/shared/interfaces/request_fields" +require "log_struct/shared/serialize_common" +require "log_struct/shared/merge_additional_data_fields" +require "log_struct/shared/add_request_fields" +require_relative "../../enums/source" +require_relative "../../enums/event" +require_relative "../../enums/level" +require_relative "../../enums/log_field" + +module LogStruct + module Log + class ActiveJob + class Error < T::Struct + extend T::Sig + + # Shared/common fields + const :source, Source::Job, default: Source::Job + const :event, Event, default: Event::Error + const :timestamp, Time, factory: -> { Time.now } + const :level, Level, default: Level::Info + + const :job_id, String + const :job_class, String + const :queue_name, T.nilable(Symbol), default: nil + const :arguments, T.nilable(T::Array[T.untyped]), default: nil + const :executions, T.nilable(Integer), default: nil + const :provider_job_id, T.nilable(String), default: nil + + # Event-specific fields + const :error_class, T.class_of(Exception) + const :message, String + const :backtrace, T.nilable(T::Array[String]), default: nil + + # Serialize shared fields + include LogStruct::Log::Interfaces::CommonFields + include LogStruct::Log::Shared::SerializeCommon + + sig { returns(T::Hash[LogStruct::LogField, T.untyped]) } + def to_h + h = T.let({}, T::Hash[LogStruct::LogField, T.untyped]) + h[LogField::JobId] = job_id + h[LogField::JobClass] = job_class + h[LogField::QueueName] = queue_name unless queue_name.nil? + h[LogField::Arguments] = arguments unless arguments.nil? + h[LogField::Executions] = executions unless executions.nil? + h[LogField::ProviderJobId] = provider_job_id unless provider_job_id.nil? + h[LogField::ErrorClass] = error_class + h[LogField::Message] = message + h[LogField::Backtrace] = backtrace unless backtrace.nil? + h + end + end + end + end +end diff --git a/lib/log_struct/log/error.rb b/lib/log_struct/log/error.rb index 23603912..23896cc0 100644 --- a/lib/log_struct/log/error.rb +++ b/lib/log_struct/log/error.rb @@ -28,9 +28,16 @@ class Error < T::Struct const :timestamp, Time, factory: -> { Time.now } const :level, Level, default: Level::Info + const :path, T.nilable(String), default: nil + const :http_method, T.nilable(String), default: nil + const :source_ip, T.nilable(String), default: nil + const :user_agent, T.nilable(String), default: nil + const :referer, T.nilable(String), default: nil + # Event-specific fields const :error_class, T.class_of(Exception) const :message, String + const :error_message, T.nilable(String), default: nil const :backtrace, T.nilable(T::Array[String]), default: nil # Additional data @@ -38,15 +45,25 @@ class Error < T::Struct const :additional_data, T.nilable(T::Hash[T.any(String, Symbol), T.untyped]), default: nil include LogStruct::Log::Shared::MergeAdditionalDataFields + # Request fields (optional) + include LogStruct::Log::Interfaces::RequestFields + # Serialize shared fields include LogStruct::Log::Interfaces::CommonFields include LogStruct::Log::Shared::SerializeCommon + include LogStruct::Log::Shared::AddRequestFields sig { returns(T::Hash[LogStruct::LogField, T.untyped]) } def to_h h = T.let({}, T::Hash[LogStruct::LogField, T.untyped]) + h[LogField::Path] = path unless path.nil? + h[LogField::HttpMethod] = http_method unless http_method.nil? + h[LogField::SourceIp] = source_ip unless source_ip.nil? + h[LogField::UserAgent] = user_agent unless user_agent.nil? + h[LogField::Referer] = referer unless referer.nil? h[LogField::ErrorClass] = error_class h[LogField::Message] = message + h[LogField::ErrorMessage] = error_message unless error_message.nil? h[LogField::Backtrace] = backtrace unless backtrace.nil? h end diff --git a/lib/log_struct/log/sidekiq/error.rb b/lib/log_struct/log/sidekiq/error.rb index 48f2a904..43e4ba34 100644 --- a/lib/log_struct/log/sidekiq/error.rb +++ b/lib/log_struct/log/sidekiq/error.rb @@ -37,6 +37,11 @@ class Error < T::Struct const :queue_name, T.nilable(String), default: nil const :retry_count, T.nilable(Integer), default: nil + # Additional data + include LogStruct::Log::Interfaces::AdditionalDataField + const :additional_data, T.nilable(T::Hash[T.any(String, Symbol), T.untyped]), default: nil + include LogStruct::Log::Shared::MergeAdditionalDataFields + # Serialize shared fields include LogStruct::Log::Interfaces::CommonFields include LogStruct::Log::Shared::SerializeCommon diff --git a/lib/log_struct/log/sidekiq/log.rb b/lib/log_struct/log/sidekiq/log.rb index d4e34da6..453bb83f 100644 --- a/lib/log_struct/log/sidekiq/log.rb +++ b/lib/log_struct/log/sidekiq/log.rb @@ -35,6 +35,11 @@ class Log < T::Struct const :process_id, T.nilable(Integer), default: nil const :thread_id, T.nilable(T.any(Integer, String)), default: nil + # Additional data + include LogStruct::Log::Interfaces::AdditionalDataField + const :additional_data, T.nilable(T::Hash[T.any(String, Symbol), T.untyped]), default: nil + include LogStruct::Log::Shared::MergeAdditionalDataFields + # Serialize shared fields include LogStruct::Log::Interfaces::CommonFields include LogStruct::Log::Shared::SerializeCommon diff --git a/lib/log_struct/rails_boot_banner_silencer.rb b/lib/log_struct/rails_boot_banner_silencer.rb index a33e8230..4da5740f 100644 --- a/lib/log_struct/rails_boot_banner_silencer.rb +++ b/lib/log_struct/rails_boot_banner_silencer.rb @@ -15,6 +15,9 @@ def self.install! @installed = true return unless ARGV.include?("server") + # Rails' own banner stays when LogStruct is disabled + return unless LogStruct.enabled? + patch! end diff --git a/lib/log_struct/railtie.rb b/lib/log_struct/railtie.rb index ff1abe6b..b0a5b39d 100644 --- a/lib/log_struct/railtie.rb +++ b/lib/log_struct/railtie.rb @@ -54,6 +54,7 @@ class Railtie < ::Rails::Railtie # Emit Puma lifecycle logs when running `rails server` initializer "logstruct.puma_lifecycle", after: "logstruct.configure_logger" do + next unless LogStruct.enabled? is_server = ::LogStruct.server_mode? next unless is_server begin diff --git a/lib/log_struct/semantic_logger/concerns/log_methods.rb b/lib/log_struct/semantic_logger/concerns/log_methods.rb index 0e8752dd..0ffd492b 100644 --- a/lib/log_struct/semantic_logger/concerns/log_methods.rb +++ b/lib/log_struct/semantic_logger/concerns/log_methods.rb @@ -10,83 +10,58 @@ module LogMethods requires_ancestor { LogStruct::SemanticLogger::Logger } # Override log methods to handle LogStruct types and broadcast - sig { params(message: T.untyped, payload: T.untyped, block: T.nilable(T.proc.returns(String))).returns(T::Boolean) } - def debug(message = nil, payload = nil, &block) - instrument_log(message, :debug) - result = if message.is_a?(LogStruct::Log::Interfaces::CommonFields) || message.is_a?(T::Struct) - super(nil, payload: message, &block) - elsif message.is_a?(Hash) - # As the payload itself, so its keys are written at the top level of the line - super(nil, message, &block) - else - super - end + sig { params(message: T.untyped, payload: T.untyped, exception: T.untyped, block: T.nilable(T.proc.returns(String))).returns(T::Boolean) } + def debug(message = nil, payload = nil, exception = nil, &block) + result = super(*semantic_logger_args(:debug, message, payload, exception), &block) broadcast_message(:debug, message, block) result end - sig { params(message: T.untyped, payload: T.untyped, block: T.nilable(T.proc.returns(String))).returns(T::Boolean) } - def info(message = nil, payload = nil, &block) - instrument_log(message, :info) - result = if message.is_a?(LogStruct::Log::Interfaces::CommonFields) || message.is_a?(T::Struct) - super(nil, payload: message, &block) - elsif message.is_a?(Hash) - # As the payload itself, so its keys are written at the top level of the line - super(nil, message, &block) - else - super - end + sig { params(message: T.untyped, payload: T.untyped, exception: T.untyped, block: T.nilable(T.proc.returns(String))).returns(T::Boolean) } + def info(message = nil, payload = nil, exception = nil, &block) + result = super(*semantic_logger_args(:info, message, payload, exception), &block) broadcast_message(:info, message, block) result end - sig { params(message: T.untyped, payload: T.untyped, block: T.nilable(T.proc.returns(String))).returns(T::Boolean) } - def warn(message = nil, payload = nil, &block) - instrument_log(message, :warn) - result = if message.is_a?(LogStruct::Log::Interfaces::CommonFields) || message.is_a?(T::Struct) - super(nil, payload: message, &block) - elsif message.is_a?(Hash) - # As the payload itself, so its keys are written at the top level of the line - super(nil, message, &block) - else - super - end + sig { params(message: T.untyped, payload: T.untyped, exception: T.untyped, block: T.nilable(T.proc.returns(String))).returns(T::Boolean) } + def warn(message = nil, payload = nil, exception = nil, &block) + result = super(*semantic_logger_args(:warn, message, payload, exception), &block) broadcast_message(:warn, message, block) result end - sig { params(message: T.untyped, payload: T.untyped, block: T.nilable(T.proc.returns(String))).returns(T::Boolean) } - def error(message = nil, payload = nil, &block) - instrument_log(message, :error) - result = if message.is_a?(LogStruct::Log::Interfaces::CommonFields) || message.is_a?(T::Struct) - super(nil, payload: message, &block) - elsif message.is_a?(Hash) - # As the payload itself, so its keys are written at the top level of the line - super(nil, message, &block) - else - super - end + sig { params(message: T.untyped, payload: T.untyped, exception: T.untyped, block: T.nilable(T.proc.returns(String))).returns(T::Boolean) } + def error(message = nil, payload = nil, exception = nil, &block) + result = super(*semantic_logger_args(:error, message, payload, exception), &block) broadcast_message(:error, message, block) result end - sig { params(message: T.untyped, payload: T.untyped, block: T.nilable(T.proc.returns(String))).returns(T::Boolean) } - def fatal(message = nil, payload = nil, &block) - instrument_log(message, :fatal) - result = if message.is_a?(LogStruct::Log::Interfaces::CommonFields) || message.is_a?(T::Struct) - super(nil, payload: message, &block) - elsif message.is_a?(Hash) - # As the payload itself, so its keys are written at the top level of the line - super(nil, message, &block) - else - super - end + sig { params(message: T.untyped, payload: T.untyped, exception: T.untyped, block: T.nilable(T.proc.returns(String))).returns(T::Boolean) } + def fatal(message = nil, payload = nil, exception = nil, &block) + result = super(*semantic_logger_args(:fatal, message, payload, exception), &block) broadcast_message(:fatal, message, block) result end private + # SemanticLogger's arguments for a line: a LogStruct entry or struct goes in the payload, and a Hash is the + # payload itself, so its keys are written at the top level of the line. An exception can come second + # (logger.error({id: 1}, error)) or third. + sig { params(level: Symbol, message: T.untyped, payload: T.untyped, exception: T.untyped).returns([T.untyped, T.untyped, T.untyped]) } + def semantic_logger_args(level, message, payload, exception) + instrument_log(message, level) + if message.is_a?(LogStruct::Log::Interfaces::CommonFields) || message.is_a?(T::Struct) + [nil, {payload: message}, nil] + elsif message.is_a?(Hash) + [nil, message, payload.is_a?(Exception) ? payload : exception] + else + [message, payload, exception] + end + end + # Instrument log events for subscribers sig { params(message: T.untyped, level: Symbol).void } def instrument_log(message, level) @@ -95,8 +70,6 @@ def instrument_log(message, level) ::ActiveSupport::Notifications.instrument("log.logstruct", log: message, level: level) end - private - # Other loggers get String messages, and what blocks return, scrubbed like a log line's strings sig { params(level: Symbol, message: T.untyped, block: T.nilable(T.proc.returns(String))).void } def broadcast_message(level, message, block) diff --git a/lib/log_struct/semantic_logger/formatter.rb b/lib/log_struct/semantic_logger/formatter.rb index 596111f6..3cff4a6d 100644 --- a/lib/log_struct/semantic_logger/formatter.rb +++ b/lib/log_struct/semantic_logger/formatter.rb @@ -75,9 +75,12 @@ def call(log, logger) json = if logstruct # Use our formatter to process LogStruct types directly @logstruct_formatter.call(log.level, log.time, log.name, logstruct, **metadata) + elsif log.exception + @logstruct_formatter.call(log.level, log.time, log.name, exception_log(log), **metadata) elsif log.payload.is_a?(Hash) # Process hashes through our formatter - @logstruct_formatter.call(log.level, log.time, log.name, without_reserved_keys(log.payload), **metadata) + payload = with_message(without_reserved_keys(log.payload), log.message) + @logstruct_formatter.call(log.level, log.time, log.name, payload, **metadata) elsif log.payload.is_a?(T::Struct) @logstruct_formatter.call(log.level, log.time, log.name, log.payload, **metadata) else @@ -96,6 +99,36 @@ def call(log, logger) private + # logger.error(exception) and logger.error("Message", exception): an error line with the + # exception's class, message and backtrace. A logged message goes in msg, and the exception's + # message in error_message. A Hash logged with them adds its keys to the line. + sig { params(log: ::SemanticLogger::Log).returns(LogStruct::Log::Error) } + def exception_log(log) + exception = T.let(log.exception, Exception) + message = log.message + logged_message = (message.is_a?(String) && !message.empty?) ? message : nil + payload = log.payload + LogStruct::Log::Error.new( + source: Source::App, + error_class: exception.class, + message: logged_message || exception.message, + error_message: logged_message ? exception.message : nil, + backtrace: exception.backtrace, + additional_data: payload.is_a?(Hash) ? without_reserved_keys(payload) : nil, + timestamp: log.time + ) + end + + # A message logged beside a Hash (logger.info("Saved", id: 1)) goes in msg, unless the Hash + # has its own + sig { params(payload: T::Hash[T.untyped, T.untyped], message: T.untyped).returns(T::Hash[T.untyped, T.untyped]) } + def with_message(payload, message) + return payload unless message.is_a?(String) && !message.empty? + return payload if payload.key?(:msg) || payload.key?("msg") + + {msg: message}.merge(payload) + end + # A logged Hash may set its own src and evt, but the line's timestamp and level come from the logger HASH_RESERVED_KEYS = T.let(%w[ts lvl].freeze, T::Array[String]) diff --git a/lib/log_struct/semantic_logger/reopen_after_fork.rb b/lib/log_struct/semantic_logger/reopen_after_fork.rb new file mode 100644 index 00000000..48a88c5f --- /dev/null +++ b/lib/log_struct/semantic_logger/reopen_after_fork.rb @@ -0,0 +1,40 @@ +# typed: strict +# frozen_string_literal: true + +module LogStruct + module SemanticLogger + # SemanticLogger writes lines from a background thread, and a forked child doesn't get its parent's threads, so + # lines logged in Puma, Unicorn, Passenger or Pitchfork workers, Resque jobs and other forked children were never + # written. Ruby calls Process._fork for every fork, so each child reopens the appenders (a new writer thread). + module ReopenAfterFork + extend T::Sig + + @installed = T.let(false, T::Boolean) + + sig { void } + def self.install! + return if @installed + @installed = true + + Process.singleton_class.prepend(ForkHook) + end + + module ForkHook + extend T::Sig + + sig { returns(Integer) } + def _fork + pid = T.let(super, Integer) + if pid.zero? + begin + ::SemanticLogger.reopen + rescue => e + LogStruct.handle_exception(e, source: LogStruct::Source::Internal, context: {integration: :semantic_logger}) + end + end + pid + end + end + end + end +end diff --git a/lib/log_struct/semantic_logger/setup.rb b/lib/log_struct/semantic_logger/setup.rb index 3c0d737c..f365f8c2 100644 --- a/lib/log_struct/semantic_logger/setup.rb +++ b/lib/log_struct/semantic_logger/setup.rb @@ -5,6 +5,7 @@ require_relative "formatter" require_relative "color_formatter" require_relative "logger" +require_relative "reopen_after_fork" module LogStruct # SemanticLogger Integration @@ -111,6 +112,7 @@ def self.configure_semantic_logger(app) # Add appropriate appenders based on environment add_appenders(app) + ReopenAfterFork.install! # Replace Rails.logger with SemanticLogger replace_rails_logger(app) @@ -176,9 +178,11 @@ def self.add_appenders(app) ) end - # Add file appender if Rails has a log path configured (normal Rails behavior), unless - # RAILS_LOG_TO_STDOUT says to log to STDOUT instead: in a container the file only fills the disk - if app.config.paths["log"].first && ENV["RAILS_LOG_TO_STDOUT"].blank? + # Log to Rails' log file too in development and test (config.local_environments), unless + # RAILS_LOG_TO_STDOUT says not to. Production and other servers log to STDOUT only: nothing + # rotates the file, and in a container it only fills the disk. + local = config.local_environments.include?(Rails.env.to_sym) + if local && app.config.paths["log"].first && ENV["RAILS_LOG_TO_STDOUT"].blank? ::SemanticLogger.add_appender( file_name: app.config.paths["log"].first, formatter: LogStruct::SemanticLogger::Formatter.new, diff --git a/rails_test_app/templates/app/controllers/security_controller.rb b/rails_test_app/templates/app/controllers/security_controller.rb new file mode 100644 index 00000000..07ab82e0 --- /dev/null +++ b/rails_test_app/templates/app/controllers/security_controller.rb @@ -0,0 +1,15 @@ +# typed: true +# frozen_string_literal: true + +class SecurityController < ApplicationController + # The test app is API-only, with no session for protect_from_forgery to check, so this raises the + # error protect_from_forgery raises for a request without a valid token + def submit + raise ActionController::InvalidAuthenticityToken, "Can't verify CSRF token authenticity." + end + + # Reading remote_ip runs Rails' IP spoofing check + def remote_ip + render json: {ip: request.remote_ip} + end +end diff --git a/rails_test_app/templates/config/routes.rb b/rails_test_app/templates/config/routes.rb index 545016e4..da48c635 100644 --- a/rails_test_app/templates/config/routes.rb +++ b/rails_test_app/templates/config/routes.rb @@ -14,6 +14,9 @@ get "/logging/shrine_upload", to: "logging#test_shrine_upload" get "/logging/ams", to: "logging#test_ams_serialization" + post "/security/submit", to: "security#submit" + get "/security/remote_ip", to: "security#remote_ip" + # Healthcheck route get "/health", to: proc { [200, {}, ["OK"]] } end diff --git a/rails_test_app/templates/test/integration/security_errors_test.rb b/rails_test_app/templates/test/integration/security_errors_test.rb new file mode 100644 index 00000000..990f1bd3 --- /dev/null +++ b/rails_test_app/templates/test/integration/security_errors_test.rb @@ -0,0 +1,53 @@ +# typed: true +# frozen_string_literal: true + +require "test_helper" + +class SecurityErrorsTest < ActionDispatch::IntegrationTest + def setup + @io = StringIO.new + ::SemanticLogger.clear_appenders! + ::SemanticLogger.add_appender(io: @io, formatter: LogStruct::SemanticLogger::Formatter.new, async: false) + end + + def test_csrf_errors_are_logged_once_and_rails_responds_as_usual + post "/security/submit", params: {name: "visible"}, headers: {"HTTP_REFERER" => "https://app.example.com/form?token=t1"} + + assert_response :unprocessable_entity + lines = security_lines("csrf_violation") + + assert_equal 1, lines.size, @io.string + assert_equal ["/security/submit", "POST", "https://app.example.com/form"], lines.first.values_at("path", "method", "referer") + end + + def test_ip_spoofing_errors_are_logged_once_where_rails_raises_them + headers = {"HTTP_CLIENT_IP" => "1.1.1.1", "HTTP_X_FORWARDED_FOR" => "2.2.2.2"} + + # Rails' check runs only where remote_ip is read + get "/health", headers: headers + + assert_response :success + assert_empty security_lines("ip_spoof") + + assert_raises(ActionDispatch::RemoteIp::IpSpoofAttackError) do + get "/security/remote_ip", headers: headers + end + lines = security_lines("ip_spoof") + + assert_equal 1, lines.size, @io.string + # The test app scrubs IP addresses + assert_equal ["/security/remote_ip", "[IP]", "[IP]"], lines.first.values_at("path", "client_ip", "x_forwarded_for") + end + + private + + def security_lines(event) + ::SemanticLogger.flush + @io.string.lines.filter_map do |line| + parsed = JSON.parse(line) + parsed if parsed["src"] == "security" && parsed["evt"] == event + rescue JSON::ParserError + nil + end + end +end diff --git a/schemas/log_sources/active_job.yml b/schemas/log_sources/active_job.yml index 07a7a100..2ba03e9a 100644 --- a/schemas/log_sources/active_job.yml +++ b/schemas/log_sources/active_job.yml @@ -39,3 +39,16 @@ events: fields: DurationMs: Float FinishedAt: Time + + # The job raised an exception + Error: + fields: + ErrorClass: + type: 'T.class_of(Exception)' + required: true + Message: + type: String + required: true + Backtrace: + type: 'T::Array[String]' + required: false diff --git a/schemas/log_sources/error.yml b/schemas/log_sources/error.yml index 4193b66a..b8eb904c 100644 --- a/schemas/log_sources/error.yml +++ b/schemas/log_sources/error.yml @@ -4,6 +4,8 @@ consts: # Can be any source source: Source +# The request an error happened in, when there was one +add_request_fields: true additional_data: true events: @@ -11,6 +13,10 @@ events: fields: ErrorClass: 'T.class_of(Exception)' Message: String + # The exception's message, when the line's message is the one logged with it + ErrorMessage: + type: String + required: false Backtrace: type: 'T::Array[String]' required: false diff --git a/schemas/log_sources/sidekiq.yml b/schemas/log_sources/sidekiq.yml index ec684cee..b5f6be9c 100644 --- a/schemas/log_sources/sidekiq.yml +++ b/schemas/log_sources/sidekiq.yml @@ -3,6 +3,9 @@ source: Sidekiq consts: source: Source::Sidekiq +# The keys of a Hash logged beside a message (Sidekiq.logger.info("Synced", order_id: 1)) +additional_data: true + events: Log: default_required: false diff --git a/test/code_examples/configuration_test.rb b/test/code_examples/configuration_test.rb index fb1afd66..e15ed86c 100644 --- a/test/code_examples/configuration_test.rb +++ b/test/code_examples/configuration_test.rb @@ -177,17 +177,40 @@ def test_filter_configuration assert_equal 16, filters.hash_length end + def test_limits_configuration + # ---------------------------------------------------------- + # BEGIN CODE EXAMPLE: limits_configuration + # ---------------------------------------------------------- + LogStruct.configure do |config| + # How much of each logged value is written (the defaults) + config.limits.max_hash_keys = 100 # The rest are counted in _more_keys + config.limits.max_array_items = 10 # Followed by "... and N more items" + config.limits.max_backtrace_lines = 100 # Arrays that look like backtraces + config.limits.max_string_bytes = 32_768 # Longer strings are cut, and say how long they were + end + # ---------------------------------------------------------- + # END CODE EXAMPLE: limits_configuration + # ---------------------------------------------------------- + + assert_equal 100, LogStruct.config.limits.max_hash_keys + assert_equal 32_768, LogStruct.config.limits.max_string_bytes + end + def test_error_handling_modes # ---------------------------------------------------------- # BEGIN CODE EXAMPLE: error_handling_modes # ---------------------------------------------------------- LogStruct.configure do |config| - # Configure error handling modes modes = config.error_handling_modes + # The defaults: + # Sorbet type errors: raised in development and test, logged and reported in production modes.type_checking_errors = LogStruct::ErrorHandlingMode::ReportProduction - modes.logstruct_errors = LogStruct::ErrorHandlingMode::ReportProduction + # Errors inside LogStruct: raised in development and test, logged in production + modes.logstruct_errors = LogStruct::ErrorHandlingMode::LogProduction + # CSRF and IP spoofing errors: logged and reported (Rails still responds as usual) modes.security_errors = LogStruct::ErrorHandlingMode::Report + # Errors LogStruct's integrations pass on, such as a mailer's delivery error: raised modes.standard_errors = LogStruct::ErrorHandlingMode::Raise end # ---------------------------------------------------------- @@ -197,7 +220,7 @@ def test_error_handling_modes # Verify error handling modes are applied assert_equal LogStruct::ErrorHandlingMode::ReportProduction, LogStruct.configuration.error_handling_modes.type_checking_errors - assert_equal LogStruct::ErrorHandlingMode::ReportProduction, + assert_equal LogStruct::ErrorHandlingMode::LogProduction, LogStruct.configuration.error_handling_modes.logstruct_errors assert_equal LogStruct::ErrorHandlingMode::Report, LogStruct.configuration.error_handling_modes.security_errors diff --git a/test/code_examples/exhaustiveness_test.rb b/test/code_examples/exhaustiveness_test.rb index d5e072c1..d5f61d46 100644 --- a/test/code_examples/exhaustiveness_test.rb +++ b/test/code_examples/exhaustiveness_test.rb @@ -34,6 +34,18 @@ def test_filter_configuration_is_exhaustive ) end + def test_limits_configuration_is_exhaustive + block = extract_example_block("limits_configuration") + props = props_from_struct(File.join(ROOT, "lib", "log_struct", "config_struct", "limits.rb")) + + assert_props_present!( + block: block, + props: props, + prefixes: ["config.limits."], + hint: "config.limits.NAME_HERE = ..." + ) + end + def test_error_handling_modes_configuration_is_exhaustive block = extract_example_block("error_handling_modes") props = props_from_struct(File.join(ROOT, "lib", "log_struct", "config_struct", "error_handling_modes.rb")) diff --git a/test/log_struct/error_handling_test.rb b/test/log_struct/error_handling_test.rb index e0e493ed..e0c9bbd0 100644 --- a/test/log_struct/error_handling_test.rb +++ b/test/log_struct/error_handling_test.rb @@ -126,6 +126,22 @@ def test_handle_exception_log_production_logs_in_production assert_equal 1, logged.length end + def test_type_checking_errors_are_logged_and_reported_in_production_by_default + error = TypeError.new("Expected type String, got type Integer") + logged = [] + reported = [] + LogStruct.config.error_reporting_handler = ->(e, _context, source) { reported << [e, source] } + + LogStruct.stub(:is_production?, true) do + LogStruct.stub(:error, ->(log) { logged << log }) do + LogStruct.handle_exception(error, source: LogStruct::Source::TypeChecking) + end + end + + assert_equal 1, logged.length + assert_equal [[error, LogStruct::Source::TypeChecking]], reported + end + def test_handle_exception_report_without_logging LogStruct.config.error_handling_modes.standard_errors = LogStruct::ErrorHandlingMode::Report error = RuntimeError.new("already logged") diff --git a/test/log_struct/formatter_test.rb b/test/log_struct/formatter_test.rb index 04db2234..80b1855a 100644 --- a/test/log_struct/formatter_test.rb +++ b/test/log_struct/formatter_test.rb @@ -484,6 +484,99 @@ def test_prevents_infinite_recursion_when_error_occurs end end + def test_writes_binary_and_invalid_strings_and_keys_as_utf8 + user_agent = (+"Agent \xFF").force_encoding(Encoding::BINARY) + key = (+"k\xFE").force_encoding(Encoding::BINARY) + + log_line = @formatter.call(@severity, @time, @progname, {:msg => "Request", :user_agent => user_agent, key => 1, :note => "caf\xE9"}) + result = JSON.parse(log_line) + + assert_equal "Agent \uFFFD", result["user_agent"] + assert_equal 1, result["k\uFFFD"] + assert_equal "caf\uFFFD", result["note"] + end + + def test_writes_nan_and_infinity_as_strings + result = JSON.parse(@formatter.call(@severity, @time, @progname, {msg: "Ratios", nan: Float::NAN, inf: -Float::INFINITY})) + + assert_equal "NaN", result["nan"] + assert_equal "-Infinity", result["inf"] + end + + def test_cuts_long_strings_after_scrubbing_them + LogStruct.config.limits.max_string_bytes = 100 + # An email address across the cut is scrubbed whole + long = "#{"a" * 90} ada@example.com #{"b" * 200}" + + value = JSON.parse(@formatter.call(@severity, @time, @progname, {msg: "Long", body: long}))["body"] + + assert_operator value.bytesize, :<, 150 + assert_match(/\.\.\. \(cut from #{long.bytesize} bytes\)\z/, value) + assert_not_includes value, "ada@" + assert_includes value, "[EMAIL:" + end + + def test_writes_the_first_keys_of_a_large_hash + LogStruct.config.limits.max_hash_keys = 3 + + result = JSON.parse(@formatter.call(@severity, @time, @progname, {msg: "Big", data: (1..10).to_h { |i| ["k#{i}", i] }})) + + assert_equal({"k1" => 1, "k2" => 2, "k3" => 3, "_more_keys" => 7}, result["data"]) + end + + def test_writes_the_first_lines_of_a_backtrace_like_array + result = JSON.parse(@formatter.call(@severity, @time, @progname, {msg: "Trace", lines: ["a:0"] * 150})) + + assert_equal 101, result["lines"].size + assert_equal "... and 50 more lines", result["lines"].last + end + + def test_logs_exceptions_with_their_class_message_and_backtrace + error = ArgumentError.new("bad input") + error.set_backtrace(["app/models/user.rb:3:in 'save'"]) + + result = JSON.parse(@formatter.call(::Logger::ERROR, @time, @progname, error)) + + assert_equal %w[app error error ArgumentError bad\ input], result.values_at("src", "evt", "lvl", "error_class", "msg") + assert_equal ["app/models/user.rb:3:in 'save'"], result["backtrace"] + end + + def test_writes_a_placeholder_line_when_a_line_cant_be_written + formatter = Class.new(Formatter) do + def generate_json(data) + raise JSON::GeneratorError, "can't write" if data[:msg] == "unwritable" + + super + end + end.new + reported = [] + + log_line = LogStruct.stub(:is_production?, true) do + LogStruct.stub(:handle_exception, ->(error, **) { reported << error.message }) do + formatter.call(@severity, @time, @progname, {msg: "unwritable", job: "SyncJob"}) + end + end + result = JSON.parse(log_line) + + assert_equal ["can't write"], reported + assert_equal "LogStruct couldn't write this line as JSON", result["msg"] + assert_equal %w[app log info JSON::GeneratorError], result.values_at("src", "evt", "lvl", "error_class") + end + + def test_summarizes_objects_whose_as_json_overflows_the_stack + looping = Class.new do + def as_json(*) + raise SystemStackError, "stack level too deep" + end + end.new + + log_line = LogStruct.stub(:is_production?, true) do + @formatter.call(@severity, @time, @progname, {msg: "Loop", value: looping}) + end + + assert_equal "Loop", JSON.parse(log_line)["msg"] + end + private def create_user_class diff --git a/test/log_struct/integrations/active_job/log_subscriber_test.rb b/test/log_struct/integrations/active_job/log_subscriber_test.rb index f5dc6007..105492b6 100644 --- a/test/log_struct/integrations/active_job/log_subscriber_test.rb +++ b/test/log_struct/integrations/active_job/log_subscriber_test.rb @@ -88,7 +88,8 @@ class TestMailer < ::ActionMailer::Base log = parse_first_log(@log_output) - assert_equal %w[job error NotImplementedError], log.values_at("src", "evt", "error_class") + assert_equal ["job", "error", "NotImplementedError", TestActiveJob.name], log.values_at("src", "evt", "error_class", "job_class") + assert_equal "not yet", log["msg"] end test "logs only the mailer, the mail and the delivery method for a mail delivery job" do diff --git a/test/log_struct/integrations/active_model_serializers_test.rb b/test/log_struct/integrations/active_model_serializers_test.rb index c02bdb8e..851b597d 100644 --- a/test/log_struct/integrations/active_model_serializers_test.rb +++ b/test/log_struct/integrations/active_model_serializers_test.rb @@ -14,6 +14,10 @@ class ActiveModelSerializersTest < ActiveSupport::TestCase end teardown do + # Each setup subscribes again + ActiveSupport::Notifications.notifier.listeners_for("render.active_model_serializers").each do |listener| + ActiveSupport::Notifications.unsubscribe(listener) + end if defined?(::ActiveModelSerializers) Object.send(:remove_const, :ActiveModelSerializers) end @@ -59,6 +63,19 @@ def self.name assert_equal "OpenStruct", json["resource_class"] assert_in_delta 0.0, json["duration_ms"], 50.0 end + + test "a problem with the log line doesn't fail the render in production" do + handled = [] + LogStruct.stub(:is_production?, true) do + LogStruct.stub(:info, ->(_log) { raise "formatter broke" }) do + LogStruct.stub(:handle_exception, ->(error, source:, context:) { handled << [error.message, source, context] }) do + assert_equal :rendered, ActiveSupport::Notifications.instrument("render.active_model_serializers") { :rendered } + end + end + end + + assert_equal [["formatter broke", LogStruct::Source::Internal, {integration: :active_model_serializers}]], handled + end end end end diff --git a/test/log_struct/integrations/ahoy_test.rb b/test/log_struct/integrations/ahoy_test.rb index ded80281..cee0b839 100644 --- a/test/log_struct/integrations/ahoy_test.rb +++ b/test/log_struct/integrations/ahoy_test.rb @@ -13,7 +13,7 @@ class AhoyTest < ActiveSupport::TestCase end unless defined?(::Ahoy::Tracker) tracker_class = Class.new do - def track(name, properties = nil, _options = nil) + def track(name, properties = {}, _options = {}) # Return a simple value to verify passthrough [:ok, name, properties] end @@ -58,6 +58,38 @@ def track(name, properties = nil, _options = nil) assert_equal "signup", json["ahoy_event"] assert_kind_of Hash, json["properties"] end + + test "properties that aren't a Hash and Symbol event names are logged without raising" do + logs = [] + + LogStruct.stub(:info, ->(log) { logs << log }) do + assert_equal [:ok, :signup, "not a hash"], ::Ahoy::Tracker.new.track(:signup, "not a hash") + end + + json = logs.fetch(0).as_json + + assert_equal "signup", json["ahoy_event"] + assert_equal({_class: "String"}, json["properties"]) + end + + test "Ahoy gets the arguments as they were given, so its defaults still apply" do + LogStruct.stub(:info, ->(_log) {}) do + assert_equal [:ok, "signup", {}], ::Ahoy::Tracker.new.track("signup") + end + end + + test "a problem with the log line doesn't fail the tracking call in production" do + handled = [] + LogStruct.stub(:is_production?, true) do + LogStruct.stub(:info, ->(_log) { raise "formatter broke" }) do + LogStruct.stub(:handle_exception, ->(error, source:, context:) { handled << [error.message, source, context] }) do + assert_equal [:ok, "signup", {}], ::Ahoy::Tracker.new.track("signup") + end + end + end + + assert_equal [["formatter broke", LogStruct::Source::Internal, {integration: :ahoy}]], handled + end end end end diff --git a/test/log_struct/integrations/dotenv_test.rb b/test/log_struct/integrations/dotenv_test.rb new file mode 100644 index 00000000..91755a2e --- /dev/null +++ b/test/log_struct/integrations/dotenv_test.rb @@ -0,0 +1,32 @@ +# typed: true +# frozen_string_literal: true + +require "test_helper" + +module LogStruct + module Integrations + class DotenvTest < ActiveSupport::TestCase + test "a problem with a Dotenv log line is a LogStruct error, so it doesn't stop the app in production" do + # Subscribe again: other tests replace the notifier + subscribed = Dotenv::STATE.subscribed + listeners = ActiveSupport::Notifications.notifier.listeners_for("load.dotenv") + Dotenv::STATE.subscribed = false + Dotenv.subscribe! + handled = [] + + LogStruct.stub(:handle_exception, ->(error, source:, context:) { handled << [error.class, source, context] }) do + # No env in the payload, so building the line fails + ActiveSupport::Notifications.instrument("load.dotenv", env: nil) + end + + refute_empty handled + assert_equal [[NoMethodError, Source::Internal, {integration: :dotenv}]], handled.uniq + ensure + (ActiveSupport::Notifications.notifier.listeners_for("load.dotenv") - T.must(listeners)).each do |listener| + ActiveSupport::Notifications.unsubscribe(listener) + end + Dotenv::STATE.subscribed = subscribed + end + end + end +end diff --git a/test/log_struct/integrations/good_job/logger_test.rb b/test/log_struct/integrations/good_job/logger_test.rb index 978695a3..04971aed 100644 --- a/test/log_struct/integrations/good_job/logger_test.rb +++ b/test/log_struct/integrations/good_job/logger_test.rb @@ -35,6 +35,20 @@ def with_good_job_current_thread(**accessors) assert_kind_of LogStruct::SemanticLogger::Logger, @logger end + test "logs a message with an exception, as SemanticLogger's loggers take them" do + clear_log_buffer(@io) + error = RuntimeError.new("boom") + + @logger.error("Notifier errored", nil, error) + @logger.error("Notifier errored", error) + ::SemanticLogger.flush + + lines = @io.string.lines.map { |line| JSON.parse(line) } + + assert_equal [%w[Notifier\ errored RuntimeError boom]] * 2, + lines.map { |line| line.values_at("msg", "error_class", "error_message") } + end + test "logs info messages with GoodJob structure" do clear_log_buffer(@io) diff --git a/test/log_struct/integrations/good_job_test.rb b/test/log_struct/integrations/good_job_test.rb index 65053c57..44a96218 100644 --- a/test/log_struct/integrations/good_job_test.rb +++ b/test/log_struct/integrations/good_job_test.rb @@ -78,6 +78,24 @@ class << self end end + test "the app's thread error handler runs even if LogStruct's line fails" do + with_fake_goodjob do |fake| + reported = [] + handled = [] + fake.on_thread_error = ->(exception) { reported << exception.message } + GoodJob.send(:configure_logger) + + GoodJob.stub(:log_thread_error, ->(_exception) { raise "formatter broke" }) do + LogStruct.stub(:handle_exception, ->(error, source:, context:) { handled << [error.message, source, context] }) do + fake._on_thread_error(RuntimeError.new("boom")) + end + end + + assert_equal ["boom"], reported + assert_equal [["formatter broke", LogStruct::Source::Internal, {integration: :good_job}]], handled + end + end + test "a thread error is one structured error line from GoodJob's logger" do io = setup_isolated_logger with_fake_goodjob do |fake| diff --git a/test/log_struct/integrations/host_authorization_test.rb b/test/log_struct/integrations/host_authorization_test.rb new file mode 100644 index 00000000..da4fc971 --- /dev/null +++ b/test/log_struct/integrations/host_authorization_test.rb @@ -0,0 +1,60 @@ +# typed: true +# frozen_string_literal: true + +require "test_helper" +require "rack/mock" + +module LogStruct + module Integrations + class HostAuthorizationTest < ActiveSupport::TestCase + setup do + @saved_host_authorization = Rails.application.config.host_authorization + @env = Rack::MockRequest.env_for("http://blocked.example.com/health") + end + + teardown do + Rails.application.config.host_authorization = @saved_host_authorization + end + + test "the blocked host is logged and the app's own response app responds" do + Rails.application.config.host_authorization = {response_app: ->(_env) { [418, {}, ["the app's page"]] }} + logged = [] + + # Set up twice, as when the integrations are set up again: one line per blocked request + 2.times { HostAuthorization.setup(LogStruct.config) } + response = LogStruct.stub(:warn, ->(log) { logged << log }) do + Rails.application.config.host_authorization[:response_app].call(@env) + end + + assert_equal [418, {}, ["the app's page"]], response + assert_equal ["blocked.example.com"], logged.map(&:blocked_host) + end + + test "without the app's own response app, LogStruct responds with 403" do + Rails.application.config.host_authorization = {} + HostAuthorization.setup(LogStruct.config) + + status, = LogStruct.stub(:warn, ->(_log) {}) do + Rails.application.config.host_authorization[:response_app].call(@env) + end + + assert_equal 403, status + end + + test "a problem with the log line still gets the request its response" do + Rails.application.config.host_authorization = {} + HostAuthorization.setup(LogStruct.config) + handled = [] + + status, = LogStruct.stub(:warn, ->(_log) { raise "formatter broke" }) do + LogStruct.stub(:handle_exception, ->(error, source:, context:) { handled << [error.message, source, context] }) do + Rails.application.config.host_authorization[:response_app].call(@env) + end + end + + assert_equal 403, status + assert_equal [["formatter broke", LogStruct::Source::Internal, {integration: :host_authorization}]], handled + end + end + end +end diff --git a/test/log_struct/integrations/puma_unit_test.rb b/test/log_struct/integrations/puma_unit_test.rb index a65d428e..d546b589 100644 --- a/test/log_struct/integrations/puma_unit_test.rb +++ b/test/log_struct/integrations/puma_unit_test.rb @@ -2,6 +2,7 @@ # frozen_string_literal: true require "test_helper" +require "timeout" class PumaIntegrationUnitTest < Minitest::Test PUMA = LogStruct::Integrations::Puma @@ -16,6 +17,97 @@ def teardown ARGV.replace(@original_argv) end + def test_install_patches_skips_when_puma_is_not_installed + installed = PUMA::STATE[:installed] + PUMA::STATE[:installed] = false + + PUMA.stub(:require, ->(_name) { raise LoadError, "cannot load such file -- puma" }) do + PUMA.install_patches! + end + + refute PUMA::STATE[:installed] + ensure + PUMA::STATE[:installed] = installed + end + + def test_a_problem_in_the_puma_integration_is_a_logstruct_error + handled = [] + error = RuntimeError.new("patch broke") + + LogStruct.stub(:server_mode?, true) do + LogStruct.stub(:handle_exception, ->(e, source:, context: nil) { handled << [e, source, context] }) do + PUMA.handle_integration_error(error) + end + end + + assert_equal [[error, LogStruct::Source::Internal, {integration: :puma}]], handled + end + + def test_puma_lifecycle_initializer_does_nothing_when_logstruct_is_disabled + initializer = LogStruct::Railtie.instance.initializers.find { |i| i.name == "logstruct.puma_lifecycle" } + logged = [] + + LogStruct.stub(:enabled?, false) do + LogStruct.stub(:server_mode?, true) do + LogStruct.stub(:info, ->(log) { logged << log }) do + T.must(initializer).run(Rails.application) + end + end + end + + assert_empty logged + end + + def test_shutdown_trap_logs_then_runs_the_previous_handler + previous_calls = [] + shutdowns = [] + original = Signal.trap("USR2") { |signal_number| previous_calls << signal_number } + + PUMA.stub(:emit_shutdown!, ->(message) { shutdowns << message }) do + PUMA.trap_shutdown_signal("USR2") + Process.kill("USR2", Process.pid) + Timeout.timeout(2) { sleep 0.01 while previous_calls.empty? } + end + + assert_equal ["USR2"], shutdowns + assert_equal [Signal.list.fetch("USR2")], previous_calls + ensure + Signal.trap("USR2", original || "DEFAULT") + end + + # A real signal in a child process: the default action, EXIT and IGNORE can't be stubbed + # (stubbing Signal.trap breaks the debug gem's trap interceptor for later tests) + def test_shutdown_trap_does_what_the_signal_does_by_default + output = in_child_process do |out| + send_signal_after_trapping("DEFAULT", out) + out.write("not stopped") + rescue SignalException => e + out.write("stopped by #{e.signm}") + end + + assert_equal "logged USR2; stopped by SIGUSR2", output + end + + def test_shutdown_trap_exits_when_the_previous_handler_was_exit + output = in_child_process do |out| + send_signal_after_trapping("EXIT", out) + out.write("not stopped") + rescue SystemExit + out.write("exited") + end + + assert_equal "logged USR2; exited", output + end + + def test_shutdown_trap_carries_on_when_the_signal_was_ignored + output = in_child_process do |out| + send_signal_after_trapping("IGNORE", out, wait: 0.2) + out.write("still running") + end + + assert_equal "logged USR2; still running", output + end + def test_process_line_builds_started_log_from_boot_sequence started_logs = [] @@ -129,4 +221,35 @@ def feed_boot_lines lines.each { |line| PUMA.process_line(line) } end + + def send_signal_after_trapping(previous_handler, out, wait: 2) + PUMA.stub(:emit_shutdown!, ->(message) { out.write("logged #{message}; ") }) do + Signal.trap("USR2", previous_handler) + PUMA.trap_shutdown_signal("USR2") + Process.kill("USR2", Process.pid) + sleep wait + end + end + + # Runs the block in a forked child and returns what it wrote. exit! skips the child's at_exit hooks + # (Minitest, SimpleCov). + def in_child_process + reader, writer = IO.pipe + pid = fork do + reader.close + begin + yield writer + rescue Exception => e # rubocop:disable Lint/RescueException + writer.write("#{e.class}: #{e.message}") + ensure + writer.close + exit!(0) + end + end + writer.close + Process.wait(pid) + reader.read + ensure + reader&.close + end end diff --git a/test/log_struct/integrations/rack_error_handler_test.rb b/test/log_struct/integrations/rack_error_handler_test.rb index d92af04d..06c3e58f 100644 --- a/test/log_struct/integrations/rack_error_handler_test.rb +++ b/test/log_struct/integrations/rack_error_handler_test.rb @@ -4,41 +4,42 @@ require "test_helper" class LogStruct::Integrations::RackErrorHandlerTest < Minitest::Test - def setup - @middleware = LogStruct::Integrations::RackErrorHandler::Middleware.new( - ->(_env) { [200, {}, ["ok"]] } - ) - end + ErrorLines = LogStruct::Integrations::RackErrorHandler::ErrorLines - def test_csrf_error_handles_invalid_authenticity_token - defined_auth_token = false - unless ::ActionController.const_defined?(:InvalidAuthenticityToken) - ::ActionController.const_set(:InvalidAuthenticityToken, Class.new(StandardError)) - defined_auth_token = true + def test_csrf_and_ip_spoofing_errors_are_security_errors + csrf_error = Class.new(StandardError) do + def self.name = "ActionController::InvalidAuthenticityToken" end - - error = ::ActionController::InvalidAuthenticityToken.new("csrf") - - assert(@middleware.send(:csrf_error?, error)) - ensure - if defined_auth_token - ::ActionController.send(:remove_const, :InvalidAuthenticityToken) + cross_origin_error = Class.new(StandardError) do + def self.name = "ActionController::InvalidCrossOriginRequest" end + + assert ErrorLines.security_error?(csrf_error.new("csrf")) + assert ErrorLines.security_error?(cross_origin_error.new("csrf")) + assert ErrorLines.security_error?(ActionDispatch::RemoteIp::IpSpoofAttackError.new("spoof")) + refute ErrorLines.security_error?(RuntimeError.new("boom")) end - def test_csrf_error_handles_invalid_cross_origin_request - defined_cross_origin = false - unless ::ActionController.const_defined?(:InvalidCrossOriginRequest) - ::ActionController.const_set(:InvalidCrossOriginRequest, Class.new(StandardError)) - defined_cross_origin = true - end + def test_the_middleware_logs_an_escaped_error_once_and_raises_it_again + io = StringIO.new + logger = Logger.new(io) + logger.formatter = LogStruct::Formatter.new + error = RuntimeError.new("boom") + middleware = LogStruct::Integrations::RackErrorHandler::Middleware.new(->(_env) { raise error }) + env = Rack::MockRequest.env_for("/orders?page=2", "HTTP_REFERER" => "https://app.example.com/reset?token=t1") - error = ::ActionController::InvalidCrossOriginRequest.new("csrf") + LogStruct.stub(:error, ->(line) { logger.error(line) }) do + 2.times do + raised = assert_raises(RuntimeError) { middleware.call(env) } - assert(@middleware.send(:csrf_error?, error)) - ensure - if defined_cross_origin - ::ActionController.send(:remove_const, :InvalidCrossOriginRequest) + assert_same error, raised + end end + + lines = io.string.lines.map { |line| JSON.parse(line) } + + assert_equal 1, lines.size + assert_equal ["rails", "error", "RuntimeError", "boom", "/orders", "GET", "https://app.example.com/reset"], + lines.first.values_at("src", "evt", "error_class", "msg", "path", "method", "referer") end end diff --git a/test/log_struct/integrations/sidekiq_test.rb b/test/log_struct/integrations/sidekiq_test.rb index 1ef9abd9..c9dd873d 100644 --- a/test/log_struct/integrations/sidekiq_test.rb +++ b/test/log_struct/integrations/sidekiq_test.rb @@ -30,6 +30,24 @@ class SidekiqTest < ActiveSupport::TestCase ActiveSupport::Notifications.unsubscribe(subscriber) end + test "Hashes and payloads logged through Sidekiq's logger are filtered, not turned into strings" do + logger = Sidekiq::Logger.new("Sidekiq-Server") + logger.info({event: "settings", password: "hunter2"}) + logger.info("Synced", order_id: 7, api_token: "tok-1") + error = ArgumentError.new("bad") + logger.warn("Retrying", error) + ::SemanticLogger.flush + + lines = @io.string.lines.map { |line| JSON.parse(line) }.last(3) + + assert_not_includes @io.string, "hunter2" + assert_not_includes @io.string, "tok-1" + assert_equal({"_filtered" => {"_class" => "String"}}, lines[0]["password"]) + assert_equal %w[sidekiq Synced], lines[1].values_at("src", "msg") + assert_equal 7, lines[1]["order_id"] + assert_equal %w[error ArgumentError Retrying bad], lines[2].values_at("evt", "error_class", "msg", "error_message") + end + test "lines logged while a job runs include the job's ID and class" do job_hash = {"jid" => "abc123", "class" => "Sidekiq::ActiveJob::Wrapper", "wrapped" => "HardJob"} diff --git a/test/log_struct/rails_boot_banner_silencer_test.rb b/test/log_struct/rails_boot_banner_silencer_test.rb index cb1150ac..348ff7a6 100644 --- a/test/log_struct/rails_boot_banner_silencer_test.rb +++ b/test/log_struct/rails_boot_banner_silencer_test.rb @@ -28,6 +28,16 @@ def test_install_skips_patch_when_not_running_server end end + def test_install_skips_patch_when_logstruct_is_disabled + ARGV.replace(["server"]) + + LogStruct.stub(:enabled?, false) do + SILENCER.stub(:patch!, proc { flunk("patch! should not run when LogStruct is disabled") }) do + SILENCER.install! + end + end + end + def test_patch_handles_missing_rails_gracefully with_kernel_require_raising_load_error do SILENCER.instance_variable_set(:@installed, false) diff --git a/test/log_struct/semantic_logger_test.rb b/test/log_struct/semantic_logger_test.rb index d078d566..ea2e7dc6 100644 --- a/test/log_struct/semantic_logger_test.rb +++ b/test/log_struct/semantic_logger_test.rb @@ -59,6 +59,87 @@ class SemanticLoggerTest < ActiveSupport::TestCase assert_equal({"_filtered" => {"_class" => "String"}}, JSON.parse(T.must(@io.string.lines.last))["req_id"]) end + test "keeps the message logged beside a Hash" do + clear_log_buffer(@io) + @logger.info("Saved", id: 1) + @logger.info("Renamed", msg: "Its own message") + ::SemanticLogger.flush + + lines = @io.string.lines.map { |line| JSON.parse(line) } + + assert_equal [["Saved", 1], ["Its own message", nil]], lines.map { |line| line.values_at("msg", "id") } + end + + test "logs exceptions with their class, message and backtrace" do + error = ArgumentError.new("bad input") + error.set_backtrace(["app/jobs/sync_job.rb:3:in 'perform'"]) + clear_log_buffer(@io) + + @logger.error(error) + @logger.error("Sync failed", error) + @logger.error("Sync failed", {order_id: 7}, error) + @logger.error({order_id: 8}, error) + ::SemanticLogger.flush + + lines = @io.string.lines.map { |line| JSON.parse(line) } + + assert_equal( + [ + ["error", "ArgumentError", "bad input", nil, nil], + ["error", "ArgumentError", "Sync failed", "bad input", nil], + ["error", "ArgumentError", "Sync failed", "bad input", 7], + ["error", "ArgumentError", "bad input", nil, 8] + ], + lines.map { |line| line.values_at("evt", "error_class", "msg", "error_message", "order_id") } + ) + assert_equal ["app/jobs/sync_job.rb:3:in 'perform'"], lines.first["backtrace"] + end + + test "logs only to STDOUT in production" do + ::SemanticLogger.clear_appenders! + Rails.stub(:env, ActiveSupport::EnvironmentInquirer.new("production")) do + LogStruct::SemanticLogger::Setup.add_appenders(Rails.application) + end + + assert_empty(::SemanticLogger.appenders.select { |appender| appender.is_a?(::SemanticLogger::Appender::File) }) + assert_equal 1, ::SemanticLogger.appenders.size + ensure + ::SemanticLogger.clear_appenders! + end + + test "logs to the log file too in test" do + ::SemanticLogger.clear_appenders! + ClimateControl.modify(RAILS_LOG_TO_STDOUT: nil) do + LogStruct::SemanticLogger::Setup.add_appenders(Rails.application) + end + + assert_equal 1, ::SemanticLogger.appenders.count { |appender| appender.is_a?(::SemanticLogger::Appender::File) } + ensure + ::SemanticLogger.clear_appenders! + end + + test "forked processes still write their lines" do + LogStruct::SemanticLogger::ReopenAfterFork.install! + reader, writer = IO.pipe + ::SemanticLogger.clear_appenders! + ::SemanticLogger.add_appender(io: writer, formatter: LogStruct::SemanticLogger::Formatter.new, async: false) + + # SemanticLogger's writer thread isn't copied into the child + pid = fork do + reader.close + @logger.info("from the child") + ::SemanticLogger.flush + exit!(0) + end + Process.wait(pid) + ::SemanticLogger.clear_appenders! + writer.close + + assert_includes reader.read, "from the child" + ensure + reader&.close + end + test "logs plain messages through SemanticLogger" do @logger.info("Test message") ::SemanticLogger.flush