From 1807f427fa3f6e9a12c2828240ee256d08e8ca23 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Sat, 17 Oct 2026 14:34:17 +1300 Subject: [PATCH 01/10] Never drop a line: invalid UTF-8, huge values, exceptions and messages - Strings and Hash keys are written as valid UTF-8. Puma passes headers as binary strings, so a byte like \xFF in a User-Agent stopped the whole line from being written as JSON, and SemanticLogger dropped it: anyone could hide their request line, and the IP spoofing and CSRF lines. Bytes that aren't valid UTF-8 become U+FFFD. NaN and Infinity are written as strings. - A line that still can't be written as JSON is replaced by one that says so, with the error's class, and the error is handled like LogStruct's own. - New config.limits: Hashes write their first 100 keys (and _more_keys), backtrace-like Arrays their first 100 lines (an Array of "a:0" strings was written whole), other Arrays 10 items, and strings are cut at 32 KB after they're scrubbed. One huge value no longer holds up the thread that writes every line. - logger.error(exception) wrote an empty line, and the message logged beside a Hash (logger.info("Saved", id: 1)) was dropped. Exceptions are now error lines with their class, message and backtrace; a message logged with one goes in msg and the exception's in the new error_message field. The log methods take SemanticLogger's exception argument (error(msg, payload, e)), which raised an ArgumentError. - A SystemStackError from an object's as_json is summarized like other errors instead of escaping the formatter. --- .cspell/project-words.txt | 3 + docs/app/docs/configuration/page.tsx | 9 ++ lib/log_struct/config_struct/limits.rb | 28 ++++ lib/log_struct/configuration.rb | 2 + lib/log_struct/formatter.rb | 134 +++++++++++++++--- .../integrations/good_job/logger.rb | 9 +- lib/log_struct/log/error.rb | 2 + .../semantic_logger/concerns/log_methods.rb | 87 ++++-------- lib/log_struct/semantic_logger/formatter.rb | 35 ++++- schemas/log_sources/error.yml | 4 + test/code_examples/configuration_test.rb | 19 +++ test/code_examples/exhaustiveness_test.rb | 12 ++ test/log_struct/formatter_test.rb | 93 ++++++++++++ .../integrations/good_job/logger_test.rb | 14 ++ test/log_struct/semantic_logger_test.rb | 36 +++++ 15 files changed, 406 insertions(+), 81 deletions(-) create mode 100644 lib/log_struct/config_struct/limits.rb diff --git a/.cspell/project-words.txt b/.cspell/project-words.txt index 30a254e5..6cbd0c49 100644 --- a/.cspell/project-words.txt +++ b/.cspell/project-words.txt @@ -83,3 +83,6 @@ otps crypted jwts Luhn +byteslice +unwritable +FFFD diff --git a/docs/app/docs/configuration/page.tsx b/docs/app/docs/configuration/page.tsx index cf0446de..a8ea3a71 100644 --- a/docs/app/docs/configuration/page.tsx +++ b/docs/app/docs/configuration/page.tsx @@ -175,6 +175,15 @@ end`} docs for more information. + Limits +

+ 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. +

+ + + Error Handling Configuration diff --git a/lib/log_struct/config_struct/limits.rb b/lib/log_struct/config_struct/limits.rb new file mode 100644 index 00000000..f74f38e2 --- /dev/null +++ b/lib/log_struct/config_struct/limits.rb @@ -0,0 +1,28 @@ +# typed: strict +# frozen_string_literal: true + +module LogStruct + module ConfigStruct + # How much of each logged value LogStruct writes. The limits keep a huge value (a request body, + # a large Hash) from slowing down the thread that writes the logs. + class Limits < T::Struct + include Sorbet::SerializeSymbolKeys + + # The most keys written from a Hash. The rest are counted in _more_keys. + # Default: 100 + prop :max_hash_keys, Integer, default: 100 + + # The most items written from an Array, followed by "... and N more items" + # Default: 10 + prop :max_array_items, Integer, default: 10 + + # The most lines written from an Array that looks like a backtrace + # Default: 100 + prop :max_backtrace_lines, Integer, default: 100 + + # Strings longer than this many bytes are cut, and say how long they were + # Default: 32768 (32 KB) + prop :max_string_bytes, Integer, default: 32_768 + end + end +end diff --git a/lib/log_struct/configuration.rb b/lib/log_struct/configuration.rb index 915a3d65..93dd7059 100644 --- a/lib/log_struct/configuration.rb +++ b/lib/log_struct/configuration.rb @@ -5,6 +5,7 @@ require_relative "config_struct/error_handling_modes" require_relative "config_struct/integrations" require_relative "config_struct/filters" +require_relative "config_struct/limits" module LogStruct # Core configuration class that provides a type-safe API @@ -35,6 +36,7 @@ class Configuration < T::Struct const :integrations, ConfigStruct::Integrations, factory: -> { ConfigStruct::Integrations.new } const :filters, ConfigStruct::Filters, factory: -> { ConfigStruct::Filters.new } + const :limits, ConfigStruct::Limits, factory: -> { ConfigStruct::Limits.new } # Custom log scrubbing handler for any additional string scrubbing # Default: nil diff --git a/lib/log_struct/formatter.rb b/lib/log_struct/formatter.rb index 43dde82c..0748d73b 100644 --- a/lib/log_struct/formatter.rb +++ b/lib/log_struct/formatter.rb @@ -114,11 +114,14 @@ def process_values(arg, recursion_depth: 0, ancestors: {}.compare_by_identity, p when Source, Event arg.serialize when String - scrub_string(arg) + scrub_limited_string(valid_utf8(arg)) when Time arg.iso8601(3) when Symbol StringScrubber.scrub_name(arg) + when Float + # JSON has no NaN or Infinity + arg.finite? ? arg : arg.to_s when Numeric, TrueClass, FalseClass, NilClass arg else @@ -126,7 +129,9 @@ def process_values(arg, recursion_depth: 0, ancestors: {}.compare_by_identity, p # to_json would write process_values(arg.as_json, recursion_depth: recursion_depth + 1, ancestors: ancestors, path: path, root: root) end - rescue => e + rescue SystemStackError, StandardError => e + # A SystemStackError comes from an object whose as_json refers back to itself + e = RuntimeError.new("#{e.class}: #{e.message}") unless e.is_a?(StandardError) # Report error through LogStruct's framework context = { processor_method: "process_values", @@ -152,7 +157,14 @@ def process_hash(hash, recursion_depth:, ancestors:, path: nil, root: nil) # Rails gives filter blocks the request's parameters with indifferent access line_root = (path && recursion_depth == 0) ? with_indifferent_access(hash) : nil - hash.each do |key, value| + max_keys = LogStruct.config.limits.max_hash_keys + hash.each_with_index do |(key, value), index| + if index >= max_keys + result[:_more_keys] = hash.size - max_keys + break + end + + key = valid_utf8_key(key) logstruct_field = recursion_depth == 0 && LOG_FIELD_KEYS.include?(key) key_path = path && [*path, key.to_s] # A top-level key's root is the line; the keys below it get the top-level field's value @@ -174,6 +186,54 @@ def process_hash(hash, recursion_depth:, ancestors:, path: nil, root: nil) result end + # The string as valid UTF-8. JSON can't hold other bytes: Puma passes headers as binary + # strings, and a byte like \xFF in a User-Agent would stop the whole line from being written. + # Bytes that aren't valid UTF-8 become U+FFFD. + sig { params(string: String).returns(String) } + def valid_utf8(string) + return string if string.ascii_only? || (string.encoding == Encoding::UTF_8 && string.valid_encoding?) + + utf8 = if string.encoding == Encoding::BINARY || string.encoding == Encoding::US_ASCII + string.dup.force_encoding(Encoding::UTF_8) + else + begin + string.encode(Encoding::UTF_8) + rescue EncodingError + string.dup.force_encoding(Encoding::UTF_8) + end + end + utf8.valid_encoding? ? utf8 : utf8.scrub + end + + # A String or Symbol key as valid UTF-8 (symbolize_keys makes Symbols of binary String keys) + sig { params(key: T.untyped).returns(T.untyped) } + def valid_utf8_key(key) + case key + when String + valid_utf8(key) + when Symbol + name = key.name + fixed = valid_utf8(name) + fixed.equal?(name) ? key : fixed.to_sym + else + key + end + end + + # The scrubbers see a little more than a cut string keeps, so data at the cut is scrubbed whole + SCRUB_MARGIN_BYTES = 256 + + # A string scrubbed, and cut to limits.max_string_bytes + sig { params(string: String).returns(String) } + def scrub_limited_string(string) + max_bytes = LogStruct.config.limits.max_string_bytes + return scrub_string(string) if string.bytesize <= max_bytes + + scrubbed = scrub_string(T.must(string.byteslice(0, max_bytes + SCRUB_MARGIN_BYTES)).scrub("")) + kept = T.must(scrubbed.byteslice(0, max_bytes)).scrub("") + "#{kept}... (cut from #{string.bytesize} bytes)" + end + sig { params(value: T.untyped).returns(T.untyped) } def with_indifferent_access(value) value.is_a?(Hash) ? ActiveSupport::HashWithIndifferentAccess.new(value) : value @@ -240,6 +300,10 @@ def log_value_to_hash(log_value, time:) # Use hash as is and convert string keys to symbols symbolize_keys(log_value) + when Exception + # logger.error(exception): its class, message and backtrace + Log.from_exception(Source::App, log_value, {}, time).serialize + else # Create a Plain log with the message as a string and serialize it with symbol keys # log_value can be literally anything: Integer, Float, Boolean, NilClass, etc. @@ -314,7 +378,35 @@ def call(severity, time, progname, log_value, request_id: nil, context: nil) data[:lvl] = level_enum # Set level from severity parameter add_metadata(data, progname: progname, request_id: request_id || Thread.current[:logstruct_request_id], context: context) - generate_json(data) + begin + generate_json(data) + rescue SystemStackError, StandardError => e + unwritable_line_json(data, e) + end + end + + # A line that can't be written as JSON is replaced by one that says so, instead of being lost + sig { params(data: T::Hash[T.untyped, T.untyped], error: Exception).returns(String) } + def unwritable_line_json(data, error) + level = data[:lvl] + line = { + src: enum_or_string(data[:src]) || Source::Internal.serialize, + evt: enum_or_string(data[:evt]) || Event::Error.serialize, + ts: data[:ts].is_a?(String) ? data[:ts] : Time.now.iso8601(3), + lvl: level.is_a?(Level) ? level.serialize : Level::Error.serialize, + msg: "LogStruct couldn't write this line as JSON", + error_class: error.class.name + } + unless Thread.current[:logstruct_reporting_unwritable_line] + begin + Thread.current[:logstruct_reporting_unwritable_line] = true + reported = error.is_a?(StandardError) ? error : RuntimeError.new("#{error.class}: #{error.message}") + LogStruct.handle_exception(reported, source: Source::Internal, context: {src: line[:src], evt: line[:evt]}) + ensure + Thread.current[:logstruct_reporting_unwritable_line] = nil + end + end + "#{::JSON.generate(line)}\n" end # The program name, request ID and job context, filtered and scrubbed like the rest of the line: @@ -346,6 +438,15 @@ def add_metadata(data, progname:, request_id:, context:) data[:ctx] = line_context.is_a?(Hash) ? job_context.merge(line_context) : (line_context || job_context) end + sig { params(value: T.untyped).returns(T.nilable(String)) } + def enum_or_string(value) + if value.is_a?(Source) || value.is_a?(Event) + value.serialize.to_s + elsif value.is_a?(String) + value + end + end + # Output as JSON with a newline. We mock this method in tests so we can # inspect the data right before it gets turned into a JSON string. sig { params(data: T::Hash[T.untyped, T.untyped]).returns(String) } @@ -366,22 +467,17 @@ def generate_json(data) def process_array(array, recursion_depth:, ancestors:, path: nil, root: nil) return [] if array.empty? - if looks_like_backtrace_array?(array) - array.map { |value| process_values(value, recursion_depth: recursion_depth + 1, ancestors: ancestors, path: path, root: root) } - else - processed = [] - array.each_with_index do |value, index| - break if index >= 10 - - processed << process_values(value, recursion_depth: recursion_depth + 1, ancestors: ancestors, path: path, root: root) - end - - if array.size > 10 - processed << "... and #{array.size - 10} more items" - end - - processed + limits = LogStruct.config.limits + backtrace = looks_like_backtrace_array?(array) + max_items = backtrace ? limits.max_backtrace_lines : limits.max_array_items + processed = array.first(max_items).map do |value| + process_values(value, recursion_depth: recursion_depth + 1, ancestors: ancestors, path: path, root: root) end + if array.size > max_items + processed << "... and #{array.size - max_items} more #{backtrace ? "lines" : "items"}" + end + + processed end # Check if an array looks like a backtrace (array of strings with file:line pattern) diff --git a/lib/log_struct/integrations/good_job/logger.rb b/lib/log_struct/integrations/good_job/logger.rb index b13a43b7..42ec9971 100644 --- a/lib/log_struct/integrations/good_job/logger.rb +++ b/lib/log_struct/integrations/good_job/logger.rb @@ -26,10 +26,11 @@ class Logger < LogStruct::SemanticLogger::Logger # Override log methods to create GoodJob-specific log structs %i[debug info warn error fatal].each do |level| - define_method(level) do |message = nil, payload = nil, &block| - # LogStruct log entries and Hashes (like the thread error handler's) are logged as they are - unless message.nil? || message.is_a?(String) - next super(message, payload, &block) + define_method(level) do |message = nil, payload = nil, exception = nil, &block| + # LogStruct log entries and Hashes (like the thread error handler's) are logged as they are, and a + # message with an exception is an error line with both + if !(message.nil? || message.is_a?(String)) || exception || payload.is_a?(Exception) + next super(message, payload, exception, &block) end job_context = Logger.current_job_context diff --git a/lib/log_struct/log/error.rb b/lib/log_struct/log/error.rb index 23603912..4c3c6f1a 100644 --- a/lib/log_struct/log/error.rb +++ b/lib/log_struct/log/error.rb @@ -31,6 +31,7 @@ class Error < T::Struct # 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 @@ -47,6 +48,7 @@ def to_h h = T.let({}, T::Hash[LogStruct::LogField, T.untyped]) 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/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/schemas/log_sources/error.yml b/schemas/log_sources/error.yml index 4193b66a..7ee348d7 100644 --- a/schemas/log_sources/error.yml +++ b/schemas/log_sources/error.yml @@ -11,6 +11,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/test/code_examples/configuration_test.rb b/test/code_examples/configuration_test.rb index fb1afd66..bf40a2c4 100644 --- a/test/code_examples/configuration_test.rb +++ b/test/code_examples/configuration_test.rb @@ -177,6 +177,25 @@ 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 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/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/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/semantic_logger_test.rb b/test/log_struct/semantic_logger_test.rb index d078d566..3e2eafc2 100644 --- a/test/log_struct/semantic_logger_test.rb +++ b/test/log_struct/semantic_logger_test.rb @@ -59,6 +59,42 @@ 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 plain messages through SemanticLogger" do @logger.info("Test message") ::SemanticLogger.flush From 1e14d778e54e8d88aa8d1b5a5f2c3210f6e25e48 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Sat, 17 Oct 2026 14:35:30 +1300 Subject: [PATCH 02/10] Log Hashes and payloads given to Sidekiq's logger as structured data Sidekiq.logger turned a logged Hash into a String before LogStruct saw it, so its keys weren't filtered ({password: "hunter2"} was logged as it was), and dropped the Hash logged beside a message. Hashes, LogStruct entries and exceptions now take the structured path, as with GoodJob's logger; a Hash beside a message adds its keys to the Sidekiq line, and a message with an exception is an error line with both. --- lib/log_struct/integrations/sidekiq/logger.rb | 18 +++++++++++------- lib/log_struct/log/sidekiq/error.rb | 5 +++++ lib/log_struct/log/sidekiq/log.rb | 5 +++++ schemas/log_sources/sidekiq.yml | 3 +++ test/log_struct/integrations/sidekiq_test.rb | 18 ++++++++++++++++++ 5 files changed, 42 insertions(+), 7 deletions(-) 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/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/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/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"} From e0902e0e530090cd95bcfa6afab18ecc1d16d050 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Sat, 17 Oct 2026 14:43:19 +1300 Subject: [PATCH 03/10] Log CSRF and IP spoofing errors where Rails raises them - CSRF lines never appeared: the middleware sat outside ShowExceptions, which turns InvalidAuthenticityToken into a 422 before any middleware outside it sees the error. LogStruct now registers a DebugExceptions interceptor, which Rails calls with every error from the app in every environment, and logs CSRF and IP spoofing errors there. They're handled in the security_errors mode (reported by default; the IP spoofing line was never reported), and Rails responds as it would without LogStruct. - The IP spoofing check ran on every request and answered 403 app-wide, ignoring the proxies set on RemoteIp. Rails only raises where remote_ip is read, and that's where the error is logged now. - The middleware still logs errors that get past ShowExceptions (or come from the middleware outside it), each once, and raises them again. - Error lines have typed request fields (path, method, source_ip, user_agent, referer), and ActiveJob errors are a typed Log::ActiveJob::Error, instead of known fields in additional_data. - Removed integrations/rack.rb, which nothing loaded and which required a file that doesn't exist. --- README.md | 2 +- .../integrations/active_job/log_subscriber.rb | 10 +- lib/log_struct/integrations/rack.rb | 31 --- .../integrations/rack_error_handler.rb | 16 +- .../rack_error_handler/error_lines.rb | 118 +++++++++++ .../rack_error_handler/middleware.rb | 183 ++---------------- .../integrations/rack_middleware.rb | 23 +++ .../request_context/middleware.rb | 13 +- lib/log_struct/log/active_job.rb | 1 + lib/log_struct/log/active_job/error.rb | 65 +++++++ lib/log_struct/log/error.rb | 15 ++ .../app/controllers/security_controller.rb | 15 ++ rails_test_app/templates/config/routes.rb | 3 + .../test/integration/security_errors_test.rb | 53 +++++ schemas/log_sources/active_job.yml | 13 ++ schemas/log_sources/error.yml | 2 + .../active_job/log_subscriber_test.rb | 3 +- .../integrations/rack_error_handler_test.rb | 57 +++--- 18 files changed, 376 insertions(+), 247 deletions(-) delete mode 100644 lib/log_struct/integrations/rack.rb create mode 100644 lib/log_struct/integrations/rack_error_handler/error_lines.rb create mode 100644 lib/log_struct/integrations/rack_middleware.rb create mode 100644 lib/log_struct/log/active_job/error.rb create mode 100644 rails_test_app/templates/app/controllers/security_controller.rb create mode 100644 rails_test_app/templates/test/integration/security_errors_test.rb diff --git a/README.md b/README.md index b7c7902c..a681560a 100644 --- a/README.md +++ b/README.md @@ -53,7 +53,7 @@ Once initialized (and enabled), the gem automatically includes its modules into - `ActionMailer::Base` includes error handling and event logging modules - We configure `Lograge` for request logging - Lograge request logs include request metadata (request_id, source_ip, user_agent, referer without its query string, host, content_type, accept) and custom fields from `lograge_custom_options` -- A Rack middleware is inserted to catch and log errors, including security violations (IP spoofing, CSRF, blocked hosts, etc.) +- CSRF and IP spoofing errors are logged as security lines and reported (`error_handling_modes.security_errors`), and Rails still responds to them as usual (422 for a CSRF error). A Rack middleware logs errors that get past Rails' ShowExceptions. Blocked hosts are logged by the host authorization integration. - Structured logging is set up for ActiveJob, Sidekiq, Shrine, etc. - LogStruct also filters the keys in Rails' `config.filter_parameters`, matched the way Rails matches them (`:passw` filters `user_password`, `"card.number"` filters a nested key by its path, and filter blocks get the parameters), so the same keys are filtered in every log line. Rails' own list is left in place, so `request.filtered_parameters`, `ActiveRecord::Base.filter_attributes` and other Rails features keep filtering, and values Rails has already replaced are logged as `[FILTERED]`. Configure extra sensitive keys via `LogStruct.config.filters`. - When `RAILS_LOG_TO_STDOUT` is set, we log to STDOUT only. Otherwise, we log to STDOUT by default without adding a file appender to avoid duplicate logs. diff --git a/lib/log_struct/integrations/active_job/log_subscriber.rb b/lib/log_struct/integrations/active_job/log_subscriber.rb index d5369f52..1ac33b98 100644 --- a/lib/log_struct/integrations/active_job/log_subscriber.rb +++ b/lib/log_struct/integrations/active_job/log_subscriber.rb @@ -103,10 +103,12 @@ def logged_arguments(job) # perform_now lets any Exception through, not only StandardErrors sig { params(exception: Exception, job: ::ActiveJob::Base, _event: ::ActiveSupport::Notifications::Event).void } def log_exception(exception, job, _event) - base_fields = build_base_fields(job) - job_context = base_fields.to_kwargs - - log_data = Log.from_exception(Source::Job, exception, job_context) + log_data = Log::ActiveJob::Error.new( + **build_base_fields(job).to_kwargs, + error_class: exception.class, + message: exception.message, + backtrace: exception.backtrace + ) logger.error(log_data) # So a backend that reports the same exception (GoodJob's on_thread_error) doesn't log it again diff --git a/lib/log_struct/integrations/rack.rb b/lib/log_struct/integrations/rack.rb deleted file mode 100644 index d0c7ab85..00000000 --- a/lib/log_struct/integrations/rack.rb +++ /dev/null @@ -1,31 +0,0 @@ -# typed: strict -# frozen_string_literal: true - -require "rack" -require "action_dispatch/middleware/show_exceptions" -require_relative "rack/error_handling_middleware" -require_relative "rack_setup" - -module LogStruct - module Integrations - # Rack middleware integration for structured logging - module Rack - extend T::Sig - extend IntegrationInterface - - # Set up Rack middleware for structured error logging - sig { override.params(config: LogStruct::Configuration).returns(T.nilable(T::Boolean)) } - def self.setup(config) - return nil unless RackSetup.enabled?(config) - - # Add structured logging middleware for security violations and errors - # Need to insert after ShowExceptions to catch IP spoofing errors - RackSetup.insert_after( - ::ActionDispatch::ShowExceptions, - Integrations::RackErrorHandler::Middleware - ) - true - end - end - end -end diff --git a/lib/log_struct/integrations/rack_error_handler.rb b/lib/log_struct/integrations/rack_error_handler.rb index 250710ca..6c0fe041 100644 --- a/lib/log_struct/integrations/rack_error_handler.rb +++ b/lib/log_struct/integrations/rack_error_handler.rb @@ -2,7 +2,7 @@ # frozen_string_literal: true require "rack" -require "action_dispatch/middleware/show_exceptions" +require "action_dispatch/middleware/debug_exceptions" require_relative "rack_error_handler/middleware" require_relative "rack_setup" @@ -13,17 +13,25 @@ module RackErrorHandler extend T::Sig extend IntegrationInterface - # Set up Rack middleware for structured error logging + @interceptor_registered = T.let(false, T::Boolean) + + # Set up structured lines for CSRF and IP spoofing errors, and for errors that get past + # ShowExceptions sig { override.params(config: LogStruct::Configuration).returns(T.nilable(T::Boolean)) } def self.setup(config) return nil unless RackSetup.enabled?(config) - # Add structured logging middleware for security violations and errors - # Need to insert before RemoteIp to catch IP spoofing errors it raises + # Errors from the middleware outside ShowExceptions, and any that get past it RackSetup.insert_before( ::ActionDispatch::RemoteIp, Integrations::RackErrorHandler::Middleware ) + # DebugExceptions calls its interceptors with each error from the app (in every environment), + # before ShowExceptions turns it into Rails' usual response: 422 for a CSRF error + unless @interceptor_registered + ::ActionDispatch::DebugExceptions.register_interceptor(ErrorLines.method(:intercept)) + @interceptor_registered = true + end true end diff --git a/lib/log_struct/integrations/rack_error_handler/error_lines.rb b/lib/log_struct/integrations/rack_error_handler/error_lines.rb new file mode 100644 index 00000000..72920324 --- /dev/null +++ b/lib/log_struct/integrations/rack_error_handler/error_lines.rb @@ -0,0 +1,118 @@ +# typed: strict +# frozen_string_literal: true + +module LogStruct + module Integrations + module RackErrorHandler + # The structured lines for errors raised while Rails handles a request. Each error is logged once: + # security errors from the app by DebugExceptions' interceptor, anything else that gets past + # ShowExceptions by the middleware. Rails still turns each error into its usual response. + module ErrorLines + extend T::Sig + + CSRF_ERROR_NAMES = T.let( + ["ActionController::InvalidAuthenticityToken", "ActionController::InvalidCrossOriginRequest"].freeze, + T::Array[String] + ) + + # For DebugExceptions.register_interceptor: CSRF and IP spoofing errors from the app, which + # ShowExceptions would otherwise turn into a response before any middleware saw them. + # Other errors are left to Rails' own logging and error reporting. + sig { params(request: ::ActionDispatch::Request, error: Exception).void } + def self.intercept(request, error) + return unless LogStruct.enabled? + return unless security_error?(error) + return if LoggedErrors.logged?(error) + + log_security_error(request, error) + end + + # An error that got past ShowExceptions (or came from a middleware outside it) + sig { params(request: ::ActionDispatch::Request, error: StandardError).void } + def self.log_escaped(request, error) + return unless LogStruct.enabled? + return if LoggedErrors.logged?(error) + return log_security_error(request, error) if security_error?(error) + + LoggedErrors.mark(error) + LogStruct.error( + Log::Error.new( + source: Source::Rails, + error_class: error.class, + message: error.message, + backtrace: error.backtrace, + path: request.path, + http_method: request.method, + source_ip: source_ip(request), + user_agent: request.user_agent, + referer: StringScrubber.without_query(request.referer) + ) + ) + end + + # A security line, and the error handled in the security_errors mode (reported by default) + sig { params(request: ::ActionDispatch::Request, error: Exception).void } + def self.log_security_error(request, error) + LoggedErrors.mark(error) + if ip_spoof_error?(error) + LogStruct.warn( + Log::Security::IPSpoof.new( + path: request.path, + http_method: request.method, + user_agent: request.user_agent, + referer: StringScrubber.without_query(request.referer), + message: error.message, + source_ip: request.ip, + client_ip: request.get_header("HTTP_CLIENT_IP"), + x_forwarded_for: request.x_forwarded_for, + timestamp: Time.now + ) + ) + else + LogStruct.error( + Log::Security::CSRFViolation.new( + path: request.path, + http_method: request.method, + source_ip: source_ip(request), + user_agent: request.user_agent, + referer: StringScrubber.without_query(request.referer), + message: error.message, + timestamp: Time.now + ) + ) + end + reported = error.is_a?(StandardError) ? error : RuntimeError.new(error.message) + LogStruct.handle_exception(reported, source: Source::Security, context: request_context(request), log: false) + end + + sig { params(request: ::ActionDispatch::Request).returns(T::Hash[Symbol, T.untyped]) } + def self.request_context(request) + { + path: request.path, + method: request.method, + user_agent: request.user_agent, + referer: StringScrubber.without_query(request.referer) + } + end + + # The client's IP, as Rails works it out, or the connection's when Rails finds a spoofed one + sig { params(request: ::ActionDispatch::Request).returns(T.nilable(String)) } + def self.source_ip(request) + request.remote_ip + rescue ::ActionDispatch::RemoteIp::IpSpoofAttackError + request.ip + end + + sig { params(error: Exception).returns(T::Boolean) } + def self.security_error?(error) + ip_spoof_error?(error) || CSRF_ERROR_NAMES.include?(error.class.name) + end + + sig { params(error: Exception).returns(T::Boolean) } + def self.ip_spoof_error?(error) + error.is_a?(::ActionDispatch::RemoteIp::IpSpoofAttackError) + end + end + end + end +end diff --git a/lib/log_struct/integrations/rack_error_handler/middleware.rb b/lib/log_struct/integrations/rack_error_handler/middleware.rb index 25ca6743..054dc82b 100644 --- a/lib/log_struct/integrations/rack_error_handler/middleware.rb +++ b/lib/log_struct/integrations/rack_error_handler/middleware.rb @@ -1,181 +1,26 @@ # typed: strict # frozen_string_literal: true +require_relative "../rack_middleware" +require_relative "error_lines" + module LogStruct module Integrations module RackErrorHandler - # Custom middleware to enhance Rails error logging with JSON format and request details - class Middleware - extend T::Sig - - # IP Spoofing error response - IP_SPOOF_HTML = T.let( - "IP Spoofing Detected" \ - "

Forbidden

" \ - "

IP spoofing detected. This request has been blocked for security reasons.

" \ - "", - String - ) - - # CSRF error response - CSRF_HTML = T.let( - "CSRF Error" \ - "

Forbidden

" \ - "

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/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 4c3c6f1a..23896cc0 100644 --- a/lib/log_struct/log/error.rb +++ b/lib/log_struct/log/error.rb @@ -28,6 +28,12 @@ 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 @@ -39,13 +45,22 @@ 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? 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 7ee348d7..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: 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/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 From 20520e8ef493c78280f93a7d5ace3c8ef5b0bd74 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Sat, 17 Oct 2026 14:44:56 +1300 Subject: [PATCH 04/10] Log to STDOUT only in production Production added a log/production.log file appender unless RAILS_LOG_TO_STDOUT was set, overriding an app's config.logger = STDOUT. Nothing rotated the file, and the README said LogStruct adds no file appender. Environments outside config.local_environments now log to STDOUT only; development keeps STDOUT and the log file, and test the log file. --- README.md | 4 ++-- docs/app/docs/logging/page.tsx | 11 +++++++---- lib/log_struct/semantic_logger/setup.rb | 8 +++++--- test/log_struct/semantic_logger_test.rb | 23 +++++++++++++++++++++++ 4 files changed, 37 insertions(+), 9 deletions(-) diff --git a/README.md b/README.md index a681560a..45e35c48 100644 --- a/README.md +++ b/README.md @@ -1,6 +1,6 @@ # LogStruct -Adds secure JSON structured logging to any Rails app (>= 7.1). Simply add the gem to your Gemfile and add an initializer to configure it. By default, your Rails app prints JSON logs to STDOUT (or to the configured destination when `RAILS_LOG_TO_STDOUT` is set). They're easy to search and filter, you can turn them into metrics and alerts, and they're great for building dashboards in CloudWatch, Grafana, or Datadog. +Adds secure JSON structured logging to any Rails app (>= 7.1). Simply add the gem to your Gemfile and add an initializer to configure it. In production, your Rails app prints JSON logs to STDOUT. They're easy to search and filter, you can turn them into metrics and alerts, and they're great for building dashboards in CloudWatch, Grafana, or Datadog. We support all your other favorite gems too, like Sidekiq, Sentry, and Shrine. (And if not, please open a PR!) @@ -56,7 +56,7 @@ Once initialized (and enabled), the gem automatically includes its modules into - CSRF and IP spoofing errors are logged as security lines and reported (`error_handling_modes.security_errors`), and Rails still responds to them as usual (422 for a CSRF error). A Rack middleware logs errors that get past Rails' ShowExceptions. Blocked hosts are logged by the host authorization integration. - Structured logging is set up for ActiveJob, Sidekiq, Shrine, etc. - LogStruct also filters the keys in Rails' `config.filter_parameters`, matched the way Rails matches them (`:passw` filters `user_password`, `"card.number"` filters a nested key by its path, and filter blocks get the parameters), so the same keys are filtered in every log line. Rails' own list is left in place, so `request.filtered_parameters`, `ActiveRecord::Base.filter_attributes` and other Rails features keep filtering, and values Rails has already replaced are logged as `[FILTERED]`. Configure extra sensitive keys via `LogStruct.config.filters`. -- When `RAILS_LOG_TO_STDOUT` is set, we log to STDOUT only. Otherwise, we log to STDOUT by default without adding a file appender to avoid duplicate logs. +- In production (and any environment that isn't in `config.local_environments`), we log to STDOUT only, with no log file to rotate or fill the disk. In development we log to STDOUT and Rails' log file, and in test to the log file only. With `RAILS_LOG_TO_STDOUT` set, both log to STDOUT only. ### Default behavior by process type diff --git a/docs/app/docs/logging/page.tsx b/docs/app/docs/logging/page.tsx index 9544fbaf..f6a06a9d 100644 --- a/docs/app/docs/logging/page.tsx +++ b/docs/app/docs/logging/page.tsx @@ -37,9 +37,11 @@ export default function LoggingDocsPage() { logs go to STDOUT.
  • - LogStruct: when enabled, replaces the logger with SemanticLogger and emits JSON to - STDOUT in test/production by default. In development, you can opt‑in to the same JSON to - avoid surprises. + LogStruct: when enabled, replaces the logger with SemanticLogger and emits JSON. In + production it logs to STDOUT only, with no log file. In development it logs to STDOUT and + Rails' log file, and in test to the log file only. With{' '} + RAILS_LOG_TO_STDOUT set, both log to STDOUT only. In development, you can + opt‑in to the same JSON to avoid surprises.
    • @@ -74,7 +76,8 @@ config.logger = ActiveSupport::TaggedLogging.new(logger)`}
    • - Ensure 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.
    • Keep LogStruct enabled in production (default) to emit structured JSON for all diff --git a/lib/log_struct/semantic_logger/setup.rb b/lib/log_struct/semantic_logger/setup.rb index 3c0d737c..91f20a5f 100644 --- a/lib/log_struct/semantic_logger/setup.rb +++ b/lib/log_struct/semantic_logger/setup.rb @@ -176,9 +176,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/test/log_struct/semantic_logger_test.rb b/test/log_struct/semantic_logger_test.rb index 3e2eafc2..35b18059 100644 --- a/test/log_struct/semantic_logger_test.rb +++ b/test/log_struct/semantic_logger_test.rb @@ -95,6 +95,29 @@ class SemanticLoggerTest < ActiveSupport::TestCase 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 "logs plain messages through SemanticLogger" do @logger.info("Test message") ::SemanticLogger.flush From 8055441f48bf38074ae3a31cdbf83d73e011654f Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Sat, 17 Oct 2026 14:52:40 +1300 Subject: [PATCH 05/10] Skip Puma when it isn't installed or LogStruct is disabled, and keep Puma's signal handlers - With "server" in ARGV and no Puma, requiring LogStruct raised LoadError and the app didn't boot. - The Puma patches, the boot banner replacement and the puma_lifecycle initializer now check LogStruct.enabled?. - The TERM/INT traps log the shutdown and then run the handler they replaced (or the signal's default action). --- .cspell/project-words.txt | 2 + lib/log_struct.rb | 5 +- lib/log_struct/integrations/puma.rb | 37 +++++- lib/log_struct/rails_boot_banner_silencer.rb | 3 + lib/log_struct/railtie.rb | 1 + .../log_struct/integrations/puma_unit_test.rb | 110 ++++++++++++++++++ .../rails_boot_banner_silencer_test.rb | 10 ++ 7 files changed, 162 insertions(+), 6 deletions(-) diff --git a/.cspell/project-words.txt b/.cspell/project-words.txt index 6cbd0c49..98a0a50e 100644 --- a/.cspell/project-words.txt +++ b/.cspell/project-words.txt @@ -86,3 +86,5 @@ Luhn byteslice unwritable FFFD +signm +SIGUSR diff --git a/lib/log_struct.rb b/lib/log_struct.rb index 39079282..477c6de6 100644 --- a/lib/log_struct.rb +++ b/lib/log_struct.rb @@ -55,8 +55,9 @@ def self.server_mode=(value) LogStruct::RailsBootBannerSilencer.install! # Patch Puma immediately for server runs so we can convert its lifecycle - # messages into structured logs reliably. - if ARGV.include?("server") + # messages into structured logs reliably. Not when LogStruct is disabled, and not + # when Puma isn't installed (install_patches! skips it). + if LogStruct.enabled? && ARGV.include?("server") begin require "log_struct/integrations/puma" LogStruct::Integrations::Puma.install_patches! diff --git a/lib/log_struct/integrations/puma.rb b/lib/log_struct/integrations/puma.rb index 76ff8b3f..678a2553 100644 --- a/lib/log_struct/integrations/puma.rb +++ b/lib/log_struct/integrations/puma.rb @@ -13,6 +13,7 @@ module Puma boot_emitted: false, shutdown_emitted: false, handler_pending_started: false, + signals_trapped: false, start_info: { mode: nil, puma_version: nil, @@ -67,8 +68,9 @@ def setup(config) handle_integration_error(e) end begin - %w[TERM INT].each do |sig| - Signal.trap(sig) { emit_shutdown!(sig) } + unless STATE[:signals_trapped] + STATE[:signals_trapped] = true + %w[TERM INT].each { |signal| trap_shutdown_signal(signal) } end rescue => e handle_integration_error(e) @@ -95,8 +97,10 @@ def install_patches! begin begin require "puma" - rescue => e - handle_integration_error(e) + rescue LoadError + # Puma isn't installed (another server, or a command with "server" in its arguments) + STATE[:installed] = false + return end puma_mod = ::Object.const_defined?(:Puma) ? ::Object.const_get(:Puma) : nil # rubocop:disable Sorbet/ConstantsFromStrings # rubocop:disable Sorbet/ConstantsFromStrings @@ -316,6 +320,31 @@ def emit_started! # Only use LogStruct; SemanticLogger routes to STDOUT in test end + # Logs the shutdown when the signal arrives, then runs the handler that was there before + # (Puma's, which stops the server gracefully), or does what the signal does by default + sig { params(signal: String).void } + def trap_shutdown_signal(signal) + previous = T.let(nil, T.untyped) + previous = Signal.trap(signal) do |signal_number| + emit_shutdown!(signal) + run_previous_signal_handler(previous, signal, signal_number) + end + end + + sig { params(previous: T.untyped, signal: String, signal_number: T.untyped).void } + def run_previous_signal_handler(previous, signal, signal_number) + if previous.respond_to?(:call) + (previous.respond_to?(:arity) && previous.arity == 0) ? previous.call : previous.call(signal_number) + elsif previous == "EXIT" + Kernel.exit + elsif previous.nil? || previous == "DEFAULT" || previous == "SYSTEM_DEFAULT" + # Put back the default and send the signal again, so the process ends as it would have + Signal.trap(signal, previous || "DEFAULT") + Process.kill(signal, Process.pid) + end + # "IGNORE": nothing more to do + end + sig { params(_message: String).void } def emit_shutdown!(_message) return if STATE[:shutdown_emitted] 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/test/log_struct/integrations/puma_unit_test.rb b/test/log_struct/integrations/puma_unit_test.rb index a65d428e..908b54ad 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,84 @@ 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_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 +208,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/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) From 0bda8e0f67bb80709977e3a0f2a13b73bd0b1d6a Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Sat, 17 Oct 2026 14:54:52 +1300 Subject: [PATCH 06/10] Log and report Sorbet type errors in production by default type_checking_errors now defaults to ReportProduction: raised in development and test, logged and reported in production. With LogProduction they were only logged, so type errors in an app and its gems went unreported. The docs said "log and report"; they now describe each error group's default. --- docs/app/docs/configuration/page.tsx | 24 ++++++++++++------- docs/app/docs/integrations/page.tsx | 5 ++-- docs/app/docs/sorbet-types/page.tsx | 13 ++++++---- .../config_struct/error_handling_modes.rb | 4 +++- test/code_examples/configuration_test.rb | 10 +++++--- test/log_struct/error_handling_test.rb | 16 +++++++++++++ 6 files changed, 52 insertions(+), 20 deletions(-) diff --git a/docs/app/docs/configuration/page.tsx b/docs/app/docs/configuration/page.tsx index a8ea3a71..e94f62b9 100644 --- a/docs/app/docs/configuration/page.tsx +++ b/docs/app/docs/configuration/page.tsx @@ -188,11 +188,17 @@ end`} Error Handling Configuration

      - 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!)

      @@ -268,10 +274,10 @@ end`} Sorbet Integration

      - 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.

      diff --git a/docs/app/docs/integrations/page.tsx b/docs/app/docs/integrations/page.tsx index 1319f2b7..6024a1c0 100644 --- a/docs/app/docs/integrations/page.tsx +++ b/docs/app/docs/integrations/page.tsx @@ -77,9 +77,8 @@ export default function IntegrationsPage() {
      Sorbet Integration

      - 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.

      Error Handling for Type Errors

      - 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.

      diff --git a/lib/log_struct/config_struct/error_handling_modes.rb b/lib/log_struct/config_struct/error_handling_modes.rb index 5212ac04..8ad761a0 100644 --- a/lib/log_struct/config_struct/error_handling_modes.rb +++ b/lib/log_struct/config_struct/error_handling_modes.rb @@ -16,7 +16,9 @@ class ErrorHandlingModes < T::Struct # - Raise - Always raise the error # Configurable error handling categories - prop :type_checking_errors, ErrorHandlingMode, default: ErrorHandlingMode::LogProduction + # Sorbet type errors in your app and its gems: logged and reported in production, so they don't pass unseen + prop :type_checking_errors, ErrorHandlingMode, default: ErrorHandlingMode::ReportProduction + # LogStruct's own errors prop :logstruct_errors, ErrorHandlingMode, default: ErrorHandlingMode::LogProduction prop :security_errors, ErrorHandlingMode, default: ErrorHandlingMode::Report prop :standard_errors, ErrorHandlingMode, default: ErrorHandlingMode::Raise diff --git a/test/code_examples/configuration_test.rb b/test/code_examples/configuration_test.rb index bf40a2c4..e15ed86c 100644 --- a/test/code_examples/configuration_test.rb +++ b/test/code_examples/configuration_test.rb @@ -201,12 +201,16 @@ 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 # ---------------------------------------------------------- @@ -216,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/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") From a2423205c3c170442dc31ac059ad73137bb8c1db Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Sat, 17 Oct 2026 14:58:42 +1300 Subject: [PATCH 07/10] Never fail the app's work because an integration's own log line failed - Ahoy: the tracking wrapper takes Ahoy's arguments as given (so Ahoy's default properties still apply), logs Symbol event names and non-Hash properties (from the browser) without raising, and reports its own failures as LogStruct errors. Before, a String of properties raised a type error and, in production, failed the request. - ActiveModelSerializers, Dotenv and Puma: a failure building their log line is a LogStruct error (logstruct_errors: logged in production, raised in development and test), not one of the app's (standard_errors, raised everywhere), so it can't fail a render, stop the app booting or break Puma in production. --- lib/log_struct.rb | 2 +- .../integrations/active_model_serializers.rb | 3 +- lib/log_struct/integrations/ahoy.rb | 32 +++++++++------- lib/log_struct/integrations/dotenv.rb | 38 +++++++------------ lib/log_struct/integrations/puma.rb | 3 +- .../active_model_serializers_test.rb | 17 +++++++++ test/log_struct/integrations/ahoy_test.rb | 34 ++++++++++++++++- test/log_struct/integrations/dotenv_test.rb | 32 ++++++++++++++++ .../log_struct/integrations/puma_unit_test.rb | 13 +++++++ 9 files changed, 132 insertions(+), 42 deletions(-) create mode 100644 test/log_struct/integrations/dotenv_test.rb diff --git a/lib/log_struct.rb b/lib/log_struct.rb index 477c6de6..5da2cb71 100644 --- a/lib/log_struct.rb +++ b/lib/log_struct.rb @@ -67,7 +67,7 @@ def self.server_mode=(value) if defined?(::Rails) && ::Rails.respond_to?(:env) && ::Rails.env.test? raise e else - LogStruct.handle_exception(e, source: LogStruct::Source::Puma) + LogStruct.handle_exception(e, source: LogStruct::Source::Internal, context: {integration: :puma}) end end end diff --git a/lib/log_struct/integrations/active_model_serializers.rb b/lib/log_struct/integrations/active_model_serializers.rb index b79e858b..25d99f9c 100644 --- a/lib/log_struct/integrations/active_model_serializers.rb +++ b/lib/log_struct/integrations/active_model_serializers.rb @@ -44,7 +44,8 @@ def self.setup(config) ) ) rescue => e - LogStruct.handle_exception(e, source: LogStruct::Source::Rails, context: {integration: :active_model_serializers}) + # A problem with the log line is LogStruct's own, and never fails the render in production + LogStruct.handle_exception(e, source: LogStruct::Source::Internal, context: {integration: :active_model_serializers}) end true diff --git a/lib/log_struct/integrations/ahoy.rb b/lib/log_struct/integrations/ahoy.rb index 24b5f2fe..d52c2787 100644 --- a/lib/log_struct/integrations/ahoy.rb +++ b/lib/log_struct/integrations/ahoy.rb @@ -16,28 +16,21 @@ def self.setup(config) mod = Module.new do extend T::Sig - sig { params(name: T.untyped, properties: T.nilable(T::Hash[T.untyped, T.untyped]), options: T.untyped).returns(T.untyped) } - def track(name, properties = nil, options = {}) + # Takes whatever Ahoy's track takes and passes it on as given, so Ahoy's defaults still apply + sig { params(name: T.untyped, args: T.untyped).returns(T.untyped) } + def track(name, *args) result = super begin - # Emit a lightweight structured log about the analytics event - data = { - ahoy_event: T.let(name, T.untyped) - } - data[:properties] = properties if properties LogStruct.info( LogStruct::Log::Ahoy.new( message: "ahoy.track", - ahoy_event: T.must(T.let(name, T.nilable(String))), - properties: T.let( - properties && properties.transform_keys { |k| k.to_sym }, - T.nilable(T::Hash[Symbol, T.untyped]) - ) + ahoy_event: name.to_s, + properties: Integrations::Ahoy.properties_for_log(args.first) ) ) rescue => e - # Never raise from logging; rely on global error handling policies - LogStruct.handle_exception(e, source: LogStruct::Source::App, context: {integration: :ahoy}) + # A problem with the log line is LogStruct's, and never fails the app's tracking call in production + LogStruct.handle_exception(e, source: LogStruct::Source::Internal, context: {integration: :ahoy}) end result end @@ -48,6 +41,17 @@ def track(name, properties = nil, options = {}) true end + + # Event properties can come from the browser, so they can be anything; a non-Hash is logged as its class + sig { params(properties: T.untyped).returns(T.nilable(T::Hash[Symbol, T.untyped])) } + def self.properties_for_log(properties) + properties = properties.to_unsafe_h if properties.respond_to?(:to_unsafe_h) + case properties + when nil then nil + when Hash then properties.to_h { |key, value| [key.to_s.to_sym, value] } + else {_class: properties.class.name} + end + end end end end diff --git a/lib/log_struct/integrations/dotenv.rb b/lib/log_struct/integrations/dotenv.rb index c7b35b81..73c6fedd 100644 --- a/lib/log_struct/integrations/dotenv.rb +++ b/lib/log_struct/integrations/dotenv.rb @@ -48,6 +48,12 @@ def relative_env_path(env) end end + # A problem with a Dotenv log line is LogStruct's own: raised in development and test, logged in production + sig { params(error: StandardError).void } + def handle_log_error(error) + LogStruct.handle_exception(error, source: LogStruct::Source::Internal, context: {integration: :dotenv}) + end + sig { void } def subscribe! # Guard against double subscription @@ -66,11 +72,7 @@ def subscribe! ts = event.time ? Time.at(event.time) : Time.now LogStruct.info(Log::Dotenv::Load.new(file: file, timestamp: ts)) rescue => e - if defined?(::Rails) && ::Rails.respond_to?(:env) && ::Rails.env == "test" - raise - else - LogStruct.handle_exception(e, source: LogStruct::Source::Dotenv) - end + handle_log_error(e) end instrumenter.subscribe("update.dotenv") do |*args| @@ -82,11 +84,7 @@ def subscribe! ts = event.time ? Time.at(event.time) : Time.now LogStruct.debug(Log::Dotenv::Update.new(vars: vars, timestamp: ts)) rescue => e - if defined?(::Rails) && ::Rails.respond_to?(:env) && ::Rails.env == "test" - raise - else - LogStruct.handle_exception(e, source: LogStruct::Source::Dotenv) - end + handle_log_error(e) end instrumenter.subscribe("save.dotenv") do |*args| @@ -95,11 +93,7 @@ def subscribe! ts = event.time ? Time.at(event.time) : Time.now LogStruct.info(Log::Dotenv::Save.new(snapshot: true, timestamp: ts)) rescue => e - if defined?(::Rails) && ::Rails.respond_to?(:env) && ::Rails.env == "test" - raise - else - LogStruct.handle_exception(e, source: LogStruct::Source::Dotenv) - end + handle_log_error(e) end instrumenter.subscribe("restore.dotenv") do |*args| @@ -111,11 +105,7 @@ def subscribe! ts = event.time ? Time.at(event.time) : Time.now LogStruct.info(Log::Dotenv::Restore.new(vars: vars, timestamp: ts)) rescue => e - if defined?(::Rails) && ::Rails.respond_to?(:env) && ::Rails.env == "test" - raise - else - LogStruct.handle_exception(e, source: LogStruct::Source::Dotenv) - end + handle_log_error(e) end STATE.subscribed = true @@ -143,7 +133,7 @@ def self.setup_boot ts = event.time ? Time.at(event.time) : Time.now LogStruct::BootBuffer.add(Log::Dotenv::Load.new(file: file, timestamp: ts)) rescue => e - LogStruct.handle_exception(e, source: LogStruct::Source::Dotenv) + handle_log_error(e) end instrumenter.subscribe("update.dotenv") do |*args| @@ -153,7 +143,7 @@ def self.setup_boot ts = event.time ? Time.at(event.time) : Time.now LogStruct::BootBuffer.add(Log::Dotenv::Update.new(vars: vars, timestamp: ts)) rescue => e - LogStruct.handle_exception(e, source: LogStruct::Source::Dotenv) + handle_log_error(e) end instrumenter.subscribe("save.dotenv") do |*args| @@ -161,7 +151,7 @@ def self.setup_boot ts = event.time ? Time.at(event.time) : Time.now LogStruct::BootBuffer.add(Log::Dotenv::Save.new(snapshot: true, timestamp: ts)) rescue => e - LogStruct.handle_exception(e, source: LogStruct::Source::Dotenv) + handle_log_error(e) end instrumenter.subscribe("restore.dotenv") do |*args| @@ -171,7 +161,7 @@ def self.setup_boot ts = event.time ? Time.at(event.time) : Time.now LogStruct::BootBuffer.add(Log::Dotenv::Restore.new(vars: vars, timestamp: ts)) rescue => e - LogStruct.handle_exception(e, source: LogStruct::Source::Dotenv) + handle_log_error(e) end @@boot_subscribed = true diff --git a/lib/log_struct/integrations/puma.rb b/lib/log_struct/integrations/puma.rb index 678a2553..de0ee0bf 100644 --- a/lib/log_struct/integrations/puma.rb +++ b/lib/log_struct/integrations/puma.rb @@ -148,7 +148,8 @@ def handle_integration_error(e) if defined?(::Rails) && ::Rails.respond_to?(:env) && ::Rails.env.test? && !server_mode raise e else - LogStruct.handle_exception(e, source: Source::Puma) + # LogStruct's own error: logged in production, so Puma keeps running + LogStruct.handle_exception(e, source: Source::Internal, context: {integration: :puma}) end end 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/puma_unit_test.rb b/test/log_struct/integrations/puma_unit_test.rb index 908b54ad..d546b589 100644 --- a/test/log_struct/integrations/puma_unit_test.rb +++ b/test/log_struct/integrations/puma_unit_test.rb @@ -30,6 +30,19 @@ def test_install_patches_skips_when_puma_is_not_installed 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 = [] From c637d22caa746b9196d9c4830f7ec6a1cf2366c4 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Sat, 17 Oct 2026 15:03:37 +1300 Subject: [PATCH 08/10] Reopen SemanticLogger's appenders in every forked process SemanticLogger writes from a background thread, which a forked child doesn't get, so lines logged in Unicorn, Passenger and Pitchfork workers, Resque jobs and other forked children were never written. A Process._fork hook reopens the appenders in each child. It replaces the Puma cluster worker patch, which covered only Puma. --- lib/log_struct/integrations/puma.rb | 21 ---------- .../semantic_logger/reopen_after_fork.rb | 40 +++++++++++++++++++ lib/log_struct/semantic_logger/setup.rb | 2 + test/log_struct/semantic_logger_test.rb | 22 ++++++++++ 4 files changed, 64 insertions(+), 21 deletions(-) create mode 100644 lib/log_struct/semantic_logger/reopen_after_fork.rb diff --git a/lib/log_struct/integrations/puma.rb b/lib/log_struct/integrations/puma.rb index de0ee0bf..750cbe19 100644 --- a/lib/log_struct/integrations/puma.rb +++ b/lib/log_struct/integrations/puma.rb @@ -114,13 +114,6 @@ def install_patches! ev = ::Object.const_get("Puma::Events") ev.prepend(EventsPatch) end - if puma_mod&.const_defined?(:Cluster) - cluster_mod = T.cast(puma_mod.const_get(:Cluster), Module) - if cluster_mod.const_defined?(:Worker) - worker_class = T.cast(cluster_mod.const_get(:Worker), T::Class[T.anything]) - worker_class.prepend(ClusterWorkerPatch) - end - end # Patch Rack::Handler::Puma.run to emit lifecycle logs using options if ::Object.const_defined?(:Rack) rack_mod = ::Object.const_get(:Rack) @@ -451,20 +444,6 @@ def log(str) end end - module ClusterWorkerPatch - extend T::Sig - - sig { returns(T.untyped) } - def run - begin - ::SemanticLogger.reopen - rescue => e - ::LogStruct::Integrations::Puma.handle_integration_error(e) - end - super - end - end - # Hook Rack::Handler::Puma.run to emit structured started/shutdown module RackHandlerPatch extend T::Sig 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 91f20a5f..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) diff --git a/test/log_struct/semantic_logger_test.rb b/test/log_struct/semantic_logger_test.rb index 35b18059..ea2e7dc6 100644 --- a/test/log_struct/semantic_logger_test.rb +++ b/test/log_struct/semantic_logger_test.rb @@ -118,6 +118,28 @@ class SemanticLoggerTest < ActiveSupport::TestCase ::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 From 3c7da39733980366b4af4b83b654aaefcab236ef Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Sat, 17 Oct 2026 15:04:32 +1300 Subject: [PATCH 09/10] Run the app's GoodJob thread error handler even if LogStruct's line fails --- lib/log_struct/integrations/good_job.rb | 4 ++++ test/log_struct/integrations/good_job_test.rb | 18 ++++++++++++++++++ 2 files changed, 22 insertions(+) diff --git a/lib/log_struct/integrations/good_job.rb b/lib/log_struct/integrations/good_job.rb index 57d88de6..4568c9f9 100644 --- a/lib/log_struct/integrations/good_job.rb +++ b/lib/log_struct/integrations/good_job.rb @@ -92,6 +92,10 @@ module LogThreadErrors sig { params(exception: Exception).void } def _on_thread_error(exception) LogStruct::Integrations::GoodJob.log_thread_error(exception) + rescue => e + LogStruct.handle_exception(e, source: LogStruct::Source::Internal, context: {integration: :good_job}) + ensure + # The app's handler runs even if LogStruct's line failed super end end 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| From f24a3fc4636139b38be60a5f8ca966e011ad048f Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Sat, 17 Oct 2026 15:05:40 +1300 Subject: [PATCH 10/10] Respond to blocked hosts with the app's own response_app The host authorization integration replaced an app's response_app with its own. It now logs the blocked host and then calls the app's response_app if there is one (LogStruct's 403 page otherwise), and a failure building the line doesn't stop the response. --- .../integrations/host_authorization.rb | 63 +++++++++++++------ .../integrations/host_authorization_test.rb | 60 ++++++++++++++++++ 2 files changed, 104 insertions(+), 19 deletions(-) create mode 100644 test/log_struct/integrations/host_authorization_test.rb diff --git a/lib/log_struct/integrations/host_authorization.rb b/lib/log_struct/integrations/host_authorization.rb index d4e38aef..a24cfdae 100644 --- a/lib/log_struct/integrations/host_authorization.rb +++ b/lib/log_struct/integrations/host_authorization.rb @@ -35,8 +35,50 @@ def self.setup(config) return nil unless config.enabled return nil unless config.integrations.enable_host_authorization - # Define the response app as a separate variable to fix block alignment - response_app = lambda do |env| + # Merge our response_app into existing host_authorization config to preserve excludes + existing = Rails.application.config.host_authorization + unless existing.is_a?(Hash) + existing = {} + end + existing = existing.dup + app_response_app = existing[:response_app] + # Set up once: don't wrap our own response app again + app_response_app = app_response_app.app_response_app if app_response_app.is_a?(ResponseApp) + existing[:response_app] = ResponseApp.new(app_response_app) + Rails.application.config.host_authorization = existing + + true + end + + # Logs the blocked host, then responds with the app's own response_app if it set one + class ResponseApp + extend T::Sig + + sig { returns(T.untyped) } + attr_reader :app_response_app + + sig { params(app_response_app: T.untyped).void } + def initialize(app_response_app) + @app_response_app = app_response_app + end + + sig { params(env: T::Hash[String, T.untyped]).returns(T.untyped) } + def call(env) + begin + log_blocked_host(env) + rescue => e + LogStruct.handle_exception(e, source: LogStruct::Source::Internal, context: {integration: :host_authorization}) + end + return @app_response_app.call(env) if @app_response_app + + # Dup the headers so they can be modified by downstream middleware + [FORBIDDEN_STATUS, RESPONSE_HEADERS.dup, [RESPONSE_HTML]] + end + + private + + sig { params(env: T::Hash[String, T.untyped]).void } + def log_blocked_host(env) request = ::ActionDispatch::Request.new(env) # Include the blocked hosts app configuration in the log entry # This can be helpful later when reviewing logs. @@ -54,7 +96,6 @@ def self.setup(config) allow_ip_hosts_value = blocked_hosts.allow_ip_hosts end - # Create structured log entry for blocked host log_entry = LogStruct::Log::Security::BlockedHost.new( message: "Blocked host detected: #{request.host}", blocked_host: request.host, @@ -68,24 +109,8 @@ def self.setup(config) allow_ip_hosts: allow_ip_hosts_value ) - # Log the blocked host LogStruct.warn(log_entry) - - # Use pre-defined headers and response if we are only logging or reporting - # Dup the headers so they can be modified by downstream middleware - [FORBIDDEN_STATUS, RESPONSE_HEADERS.dup, [RESPONSE_HTML]] end - - # Merge our response_app into existing host_authorization config to preserve excludes - existing = Rails.application.config.host_authorization - unless existing.is_a?(Hash) - existing = {} - end - existing = existing.dup - existing[:response_app] = response_app - Rails.application.config.host_authorization = existing - - true end end end 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