more tests and fixes for log formatting

Author: ndbroadbent

.cspell/project-words.txt

@@ -43,6 +43,7 @@ metaprogramming
 mswin
 nilability
 nilable
+nonblock
 optparse
 parseable
 pentester

Gemfile

@@ -19,6 +19,7 @@ gem "rails", "~> 8.0.2.1", require: false
 gem "bigdecimal"
 gem "drb"  # For ActiveSupport::TestCase
 gem "mutex_m"
+gem "openssl"  # For tapioca SSL certificate verification
 gem "ostruct"  # For Ruby 3.5+ compatibility
 
 # Sorbet is needed for development

Gemfile.lock

@@ -221,6 +221,7 @@ GEM
     nokogiri (1.18.3-x86_64-linux-musl)
       racc (~> 1.4)
     observer (0.1.2)
+    openssl (3.3.2)
     ostruct (0.6.1)
     parallel (1.26.3)
     parser (3.3.7.1)
@@ -467,6 +468,7 @@ DEPENDENCIES
   minitest (~> 5.20)
   minitest-reporters (~> 1.6)
   mutex_m
+  openssl
   ostruct
   rails (~> 8.0.2.1)
   redcarpet

lib/log_struct/monkey_patches/active_support/tagged_logging/formatter.rb

@@ -3,16 +3,19 @@
 
 require "active_support/tagged_logging"
 
-# Monkey-patch ActiveSupport::TaggedLogging::Formatter to support hash inputs
-# This allows us to pass structured data to the logger and have tags incorporated
-# directly into the hash instead of being prepended as strings
+# Monkey-patch ActiveSupport::TaggedLogging::Formatter to work with structured logging.
+#
+# Problem: Rails' TaggedLogging prepends tags as text and converts messages to strings.
+# When we pass a hash to super(), Rails does "#{tags_text}#{msg}" which calls .to_s
+# on the hash, producing Ruby inspect format {message: "..."} instead of valid JSON.
+#
+# Solution: When LogStruct is enabled, we add tags as a hash entry and delegate to
+# LogStruct::Formatter for proper JSON serialization with filtering and standard fields.
 module ActiveSupport
   module TaggedLogging
     extend T::Sig
 
     # Add class-level current_tags method for compatibility with Rails code
-    # that expects to call ActiveSupport::TaggedLogging.current_tags
-    # Use thread-local storage directly like Rails does internally
     sig { returns(T::Array[T.any(String, Symbol)]) }
     def self.current_tags
       Thread.current[:activesupport_tagged_logging_tags] || []
@@ -23,39 +26,33 @@ module FormatterExtension
       extend T::Helpers
       requires_ancestor { ::ActiveSupport::TaggedLogging::Formatter }
 
-      # Override the call method to support hash input/output, and wrap
-      # plain strings in a Hash under a `msg` key.
-      # The data is then passed to our custom log formatter that transforms it
-      # into a JSON string before logging.
-      #
-      # IMPORTANT: This only applies when LogStruct is enabled. When disabled,
-      # we preserve the original Rails logging behavior to avoid wrapping
-      # messages in hashes (which would break default Rails log formatting).
       sig { params(severity: T.any(String, Symbol), time: Time, progname: T.untyped, data: T.untyped).returns(String) }
       def call(severity, time, progname, data)
-        # Skip hash wrapping when LogStruct is disabled to preserve default Rails behavior
+        # Preserve original Rails behavior when LogStruct is disabled
         return super unless ::LogStruct.enabled?
 
-        # Convert data to a hash if it's not already one
-        data = if data.is_a?(Hash)
-          data
-        elsif data.is_a?(::LogStruct::Log::Interfaces::CommonFields)
-          # LogStruct structs have a serialize method that returns a proper hash
-          data.serialize
-        elsif data.is_a?(T::Struct)
-          # Other T::Struct types can be serialized to hash
-          data.serialize
+        # Get current tags
+        tags = T.unsafe(self).respond_to?(:current_tags) ? current_tags : (Thread.current[:activesupport_tagged_logging_tags] || [])
+
+        # Add tags to data as hash entry (not text prefix)
+        data_with_tags = if data.is_a?(Hash)
+          tags.present? ? data.merge(tags: tags) : data
+        elsif data.is_a?(::LogStruct::Log::Interfaces::CommonFields) || (data.is_a?(T::Struct) && data.respond_to?(:serialize))
+          hash = T.unsafe(data).serialize
+          tags.present? ? hash.merge(tags: tags) : hash
         else
-          {message: data.to_s}
+          tags.present? ? {message: data.to_s, tags: tags} : {message: data.to_s}
         end
 
-        # Add current tags to the hash if present
-        # Use thread-local storage directly as fallback if current_tags method doesn't exist
-        tags = T.unsafe(self).respond_to?(:current_tags) ? current_tags : (Thread.current[:activesupport_tagged_logging_tags] || [])
-        data[:tags] = tags if tags.present?
+        # Delegate to LogStruct::Formatter for JSON serialization with filtering
+        logstruct_formatter.call(severity, time, progname, data_with_tags)
+      end
+
+      private
 
-        # Call the original formatter with our enhanced data
-        super
+      sig { returns(::LogStruct::Formatter) }
+      def logstruct_formatter
+        @logstruct_formatter ||= T.let(::LogStruct::Formatter.new, T.nilable(::LogStruct::Formatter))
       end
     end
   end

rails_test_app/templates/test/integration/ams_logging_test.rb

@@ -0,0 +1,79 @@
+# typed: true
+# frozen_string_literal: true
+
+require "test_helper"
+
+# Test that ActiveModelSerializers logs are properly formatted as JSON,
+# NOT as Ruby hash inspect with tag prefixes like:
+#   [active_model_serializers] {message: "Rendered ...", tags: ["active_model_serializers"]}
+class AmsLoggingTest < ActionDispatch::IntegrationTest
+  def setup
+    @log_output = StringIO.new
+    ::SemanticLogger.clear_appenders!
+    ::SemanticLogger.add_appender(io: @log_output, formatter: LogStruct::SemanticLogger::Formatter.new, async: false)
+  end
+
+  # This test reproduces the production bug where AMS logs look like:
+  # [active_model_serializers] {message: "Rendered SubmissionSerializer...", tags: ["active_model_serializers"]}
+  def test_ams_logs_are_not_ruby_hash_inspect_format
+    skip "AMS not available" unless defined?(::ActiveModelSerializers)
+
+    # Trigger an AMS serialization by rendering a serialized response
+    # (Need to add an endpoint that uses AMS)
+    get "/logging/basic"
+
+    ::SemanticLogger.flush
+    @log_output.rewind
+    output = @log_output.read.to_s
+
+    # Capture stdout too since AMS might log there
+    stdout_output = ""
+    original_stdout = $stdout
+    begin
+      stdout_capture = StringIO.new
+      $stdout = stdout_capture
+
+      get "/logging/basic"
+
+      ::SemanticLogger.flush
+      $stdout = original_stdout
+      stdout_capture.rewind
+      stdout_output = stdout_capture.read.to_s
+    ensure
+      $stdout = original_stdout
+    end
+
+    combined_output = output + stdout_output
+
+    # MUST NOT have the broken [tag] {message: ...} format
+    refute_match(/\[active_model_serializers\]\s*\{message:/,
+      combined_output,
+      "AMS logs must NOT be in broken [tag] {message: ...} format")
+
+    # MUST NOT have Ruby hash inspect format
+    refute_match(/\{message:\s*"Rendered/,
+      combined_output,
+      "AMS logs must NOT use Ruby hash inspect format")
+  end
+
+  def test_ams_logs_do_not_pollute_with_default_format
+    skip "AMS not available" unless defined?(::ActiveModelSerializers)
+
+    # Capture both SemanticLogger output and stdout
+    original_stdout = $stdout
+    stdout_capture = StringIO.new
+    $stdout = stdout_capture
+
+    get "/logging/basic"
+
+    ::SemanticLogger.flush
+    $stdout = original_stdout
+    stdout_capture.rewind
+    stdout_output = stdout_capture.read.to_s
+
+    # AMS default logs like "Rendered X with Y (Zms)" should NOT appear in stdout
+    refute_match(/Rendered\s+\S+Serializer\s+with/,
+      stdout_output,
+      "AMS default log format should not appear in stdout")
+  end
+end

rails_test_app/templates/test/integration/request_logging_e2e_test.rb

@@ -0,0 +1,184 @@
+# typed: true
+
+require "test_helper"
+require "open3"
+require "timeout"
+require "net/http"
+
+class RequestLoggingE2eTest < ActiveSupport::TestCase
+  # Test that real HTTP requests through Puma produce valid JSON request logs
+  def test_real_http_request_produces_json_request_log
+    port = 32125
+    env = {
+      "LOGSTRUCT_ENABLED" => "true",
+      "RAILS_ENV" => "test",
+      "RAILS_LOG_TO_STDOUT" => "1"
+    }
+
+    cmd = ["bundle", "exec", "rails", "server", "-p", port.to_s]
+
+    Open3.popen3(env, *cmd) do |_stdin, stdout, stderr, wait_thr|
+      lines = []
+      begin
+        # Wait for server to be ready
+        Timeout.timeout(15) do
+          while (line = stdout.gets)
+            lines << line.strip
+            break if line.include?("Use Ctrl-C to stop") || line.include?("Listening on")
+          end
+        end
+
+        # Make a real HTTP request to a controller action (not proc) to trigger Lograge
+        uri = URI("http://127.0.0.1:#{port}/logging/basic")
+        response = Net::HTTP.get_response(uri)
+
+        assert_equal "200", response.code, "Request should succeed"
+
+        # Give logs time to flush
+        sleep 0.5
+
+        # Collect any additional output non-blocking
+        loop do
+          line = stdout.read_nonblock(4096)
+          lines.concat(line.split("\n").map(&:strip))
+        rescue IO::WaitReadable, EOFError
+          break
+        end
+      rescue Timeout::Error
+        flunk "Server did not start in time. Output: #{lines.join("\n")}\nSTDERR: #{stderr.read}"
+      ensure
+        begin
+          Process.kill("TERM", wait_thr.pid)
+        rescue Errno::ESRCH
+          # already dead
+        end
+
+        # Collect shutdown output
+        begin
+          Timeout.timeout(5) do
+            while (line = stdout.gets)
+              lines << line.strip
+            end
+          end
+        rescue Timeout::Error
+          # ignore
+        end
+      end
+
+      output = lines.join("\n")
+      stderr_output = stderr.read
+
+      # Parse all JSON log lines
+      json_lines = lines.filter_map do |l|
+        JSON.parse(l) if l.strip.start_with?("{")
+      rescue JSON::ParserError
+        nil
+      end
+
+      # Find request logs (Lograge output has evt:"request")
+      request_logs = json_lines.select { |h| h["evt"] == "request" }
+
+      assert_predicate request_logs,
+        :any?,
+        "Expected at least one request log.\nJSON logs: #{json_lines.map(&:inspect).join("\n")}\nAll output: #{output}\nSTDERR: #{stderr_output}"
+
+      request_log = request_logs.first
+
+      # Verify it's valid JSON with proper LogStruct fields
+      assert_equal "rails", request_log["src"], "Source must be 'rails'"
+      assert_equal "request", request_log["evt"], "Event must be 'request'"
+      assert request_log.key?("path"), "Must have 'path' field"
+      assert request_log.key?("status"), "Must have 'status' field"
+      assert request_log.key?("duration_ms"), "Must have 'duration_ms' field"
+
+      # MUST NOT be Ruby hash inspect format
+      request_line = lines.find { |l| l.include?('"evt":"request"') }
+
+      assert request_line, "Should find request log line"
+      refute_match(/\{message:/, request_line, "Request log must NOT be Ruby hash inspect format")
+      refute_match(/\{:message=>/, request_line, "Request log must NOT be Ruby hash rocket format")
+    end
+  end
+
+  # Test that AMS-style tagged logging doesn't produce broken format
+  def test_tagged_logging_does_not_produce_ruby_hash_format
+    port = 32126
+    env = {
+      "LOGSTRUCT_ENABLED" => "true",
+      "RAILS_ENV" => "test",
+      "RAILS_LOG_TO_STDOUT" => "1"
+    }
+
+    cmd = ["bundle", "exec", "rails", "server", "-p", port.to_s]
+
+    Open3.popen3(env, *cmd) do |_stdin, stdout, stderr, wait_thr|
+      lines = []
+      begin
+        # Wait for server to be ready
+        Timeout.timeout(15) do
+          while (line = stdout.gets)
+            lines << line.strip
+            break if line.include?("Use Ctrl-C to stop") || line.include?("Listening on")
+          end
+        end
+
+        # Make a real HTTP request to a controller action to trigger logging
+        uri = URI("http://127.0.0.1:#{port}/logging/basic")
+        Net::HTTP.get_response(uri)
+
+        # Give logs time to flush
+        sleep 0.5
+
+        # Collect any additional output non-blocking
+        loop do
+          line = stdout.read_nonblock(4096)
+          lines.concat(line.split("\n").map(&:strip))
+        rescue IO::WaitReadable, EOFError
+          break
+        end
+      rescue Timeout::Error
+        flunk "Server did not start in time. Output: #{lines.join("\n")}\nSTDERR: #{stderr.read}"
+      ensure
+        begin
+          Process.kill("TERM", wait_thr.pid)
+        rescue Errno::ESRCH
+          # already dead
+        end
+
+        begin
+          Timeout.timeout(5) do
+            while (line = stdout.gets)
+              lines << line.strip
+            end
+          end
+        rescue Timeout::Error
+          # ignore
+        end
+      end
+
+      # NO line should have the broken [tag] {message: ...} format
+      lines.each do |line|
+        refute_match(
+          /\[[\w_]+\]\s*\{message:/,
+          line,
+          "No log line should have broken [tag] {message: ...} format. Line: #{line}"
+        )
+        refute_match(
+          /\{message:.*tags:/,
+          line,
+          "No log line should have {message: ..., tags: ...} Ruby format. Line: #{line}"
+        )
+      end
+
+      # All JSON lines should be valid JSON (not Ruby hash inspect)
+      json_lines = lines.select { |l| l.strip.start_with?("{") }
+      json_lines.each do |line|
+        parsed = JSON.parse(line)
+
+        assert parsed, "Line should be valid JSON: #{line}"
+      rescue JSON::ParserError => e
+        flunk "Line should be valid JSON but got parse error: #{e.message}\nLine: #{line}"
+      end
+    end
+  end
+end