Add structured JSON logging support

lib/aws_lambda_ric.rb

@@ -131,10 +131,19 @@ class TelemetryLogger
     ENV_VAR_TELEMETRY_LOG_FD = '_LAMBDA_TELEMETRY_LOG_FD'
 
     class << self
-      attr_accessor :telemetry_log_fd_file, :telemetry_log_sink
-
+      attr_accessor :telemetry_log_fd_file, :telemetry_log_sink, :logger_patch_applied
       def close
         telemetry_log_fd_file&.close
+        self.telemetry_log_fd_file = nil
+      end
+
+      def mutate_std_logger
+        return if logger_patch_applied
+
+        Logger.class_eval do
+          prepend LoggerPatch
+        end
+        self.logger_patch_applied = true
       end
     end
 
@@ -145,28 +154,28 @@ def initialize(telemetry_log_fd)
 
       AwsLambdaRIC::TelemetryLogger.telemetry_log_sink = TelemetryLogSink.new(file: AwsLambdaRIC::TelemetryLogger.telemetry_log_fd_file)
 
-      mutate_std_logger
       mutate_kernel_puts
+
     rescue Errno::ENOENT, Errno::EBADF
-      # If File.open() fails, then the mutation won't happen and the default behaviour (print to stdout) will prevail
+      AwsLambdaRIC::TelemetryLogger.telemetry_log_fd_file = nil
+      AwsLambdaRIC::TelemetryLogger.telemetry_log_sink = nil
     end
 
     def self.from_env()
-      if ENV.key?(ENV_VAR_TELEMETRY_LOG_FD)
-        fd = ENV.fetch(AwsLambdaRIC::TelemetryLogger::ENV_VAR_TELEMETRY_LOG_FD)
-        ENV.delete(AwsLambdaRIC::TelemetryLogger::ENV_VAR_TELEMETRY_LOG_FD)
-        AwsLambdaRIC::TelemetryLogger.new(fd)
-      end
-    end
 
-    private
+      LoggerPatch.refresh_runtime_config!
+      mutate_std_logger
+      AwsLambdaRIC::TelemetryLogger.telemetry_log_sink = nil
 
-    def mutate_std_logger
-      Logger.class_eval do
-        prepend LoggerPatch
-      end
+      return unless ENV.key?(ENV_VAR_TELEMETRY_LOG_FD)
+
+      fd = ENV.fetch(AwsLambdaRIC::TelemetryLogger::ENV_VAR_TELEMETRY_LOG_FD)
+      ENV.delete(AwsLambdaRIC::TelemetryLogger::ENV_VAR_TELEMETRY_LOG_FD)
+      AwsLambdaRIC::TelemetryLogger.new(fd)
     end
 
+    private
+
     def mutate_kernel_puts
       Kernel.module_eval do
         def puts(*arg)
@@ -180,7 +189,6 @@ def puts(*arg)
       end
     end
   end
-
   # Represents a single Lambda Invocation Request
   class LambdaInvocationRequest
 

lib/aws_lambda_ric/lambda_log_formatter.rb

@@ -1,12 +1,65 @@
 # frozen_string_literal: true
 
+require 'json'
 require 'logger'
 
 class LogFormatter < Logger::Formatter
   FORMAT = '%<sev>s, [%<datetime>s #%<process>d] %<severity>5s %<request_id>s -- %<progname>s: %<msg>s'
 
   def call(severity, time, progname, msg)
-    (FORMAT % {sev: severity[0..0], datetime: format_datetime(time), process: $$, severity: severity,
-               request_id: $_global_aws_request_id, progname: progname, msg: msg2str(msg)}).encode!('UTF-8')
+    formatted = FORMAT % {
+      sev: severity[0..0],
+      datetime: format_datetime(time),
+      process: $$,
+      severity: severity,
+      request_id: $_global_aws_request_id,
+      progname: progname,
+      msg: msg2str(msg)
+    }
+    "#{formatted.encode('UTF-8', invalid: :replace, undef: :replace, replace: '�')}\n"
+  end
+end
+
+class JsonLogFormatter < Logger::Formatter
+  DATETIME_FORMAT = '%Y-%m-%dT%H:%M:%S.%6NZ'
+
+  def call(severity, time, progname, msg)
+    payload = {
+      timestamp: time.utc.strftime(DATETIME_FORMAT),
+      level: severity,
+      message: message_for(msg),
+      requestId: $_global_aws_request_id
+    }
+
+    logger_name = progname.to_s
+    payload[:logger] = logger_name unless logger_name.empty?
+
+    if msg.is_a?(Exception)
+      payload[:errorType] = msg.class.to_s
+      payload[:errorMessage] = msg.message
+      payload[:stackTrace] = msg.backtrace || []
+      location = location_for(msg)
+      payload[:location] = location unless location.nil?
+    end
+
+    "#{JSON.generate(payload.compact)}\n"
+  end
+
+  private
+
+  def message_for(msg)
+    return msg.message if msg.is_a?(Exception)
+
+    msg2str(msg)
+  end
+
+  def location_for(exception)
+    first_backtrace_line = exception.backtrace&.first
+    return nil if first_backtrace_line.nil?
+
+    matched = first_backtrace_line.match(/\A(.+):(\d+):in [`'](.+)'\z/)
+    return "#{matched[1]}:#{matched[3]}:#{matched[2]}" if matched
+
+    first_backtrace_line
   end
 end

lib/aws_lambda_ric/logger_patch.rb

@@ -1,19 +1,56 @@
 # Copyright 2019 Amazon.com, Inc. or its affiliates. All Rights Reserved.
 
+# frozen_string_literal: true
+
+require 'logger'
+require_relative 'lambda_log_formatter'
+
 module LoggerPatch
-  def initialize(logdev, shift_age = 0, shift_size = 1048576, level: 'debug',
-                 progname: nil, formatter: nil, datetime_format: nil,
-                 binmode: false, shift_period_suffix: '%Y%m%d')
-    logdev_lambda_override = logdev
-    formatter_override = formatter
-    # use unpatched constructor if logdev is a filename or an IO Object other than $stdout or $stderr
+  LOG_LEVEL_MAP = {
+    'TRACE' => Logger::DEBUG,
+    'DEBUG' => Logger::DEBUG,
+    'INFO' => Logger::INFO,
+    'WARN' => Logger::WARN,
+    'ERROR' => Logger::ERROR,
+    'FATAL' => Logger::FATAL
+  }.freeze
+
+  class << self
+    attr_reader :aws_lambda_log_format, :aws_lambda_log_level
+
+    def refresh_runtime_config!
+      @aws_lambda_log_format = ENV.fetch('AWS_LAMBDA_LOG_FORMAT', '').upcase
+      env_level = ENV.fetch('AWS_LAMBDA_LOG_LEVEL', nil)
+      @aws_lambda_log_level = LOG_LEVEL_MAP[env_level&.upcase]
+    end
+
+    def json_format?
+      @aws_lambda_log_format == 'JSON'
+    end
+  end
+
+  refresh_runtime_config!
+
+  def initialize(logdev, shift_age = 0, shift_size = 1_048_576, **kwargs)
+    level_was_provided = kwargs.key?(:level)
+    kwargs = {
+      level: Logger::DEBUG,
+      progname: nil,
+      formatter: nil,
+      datetime_format: nil,
+      binmode: false,
+      shift_period_suffix: '%Y%m%d'
+    }.merge(kwargs)
+
+    logdev_override = logdev
+
     if !logdev || logdev == $stdout || logdev == $stderr
-      logdev_lambda_override = AwsLambdaRIC::TelemetryLogger.telemetry_log_sink
-      formatter_override = formatter_override || LogFormatter.new
+      telemetry_sink = AwsLambdaRIC::TelemetryLogger.telemetry_log_sink
+      logdev_override = telemetry_sink || logdev
+      kwargs[:formatter] ||= LoggerPatch.json_format? ? JsonLogFormatter.new : LogFormatter.new
+      kwargs[:level] = LoggerPatch.aws_lambda_log_level if !level_was_provided && LoggerPatch.aws_lambda_log_level
     end
 
-    super(logdev_lambda_override, shift_age, shift_size, level: level, progname: progname,
-                                    formatter: formatter_override, datetime_format: datetime_format,
-                                    binmode: binmode, shift_period_suffix: shift_period_suffix)
+    super(logdev_override, shift_age, shift_size, **kwargs)
   end
 end

test/unit/lambda_log_formatter_test.rb

@@ -1,12 +1,13 @@
 # frozen_string_literal: true
 
 require_relative '../../lib/aws_lambda_ric/lambda_log_formatter'
+require 'json'
 require 'logger'
 require 'securerandom'
+require 'time'
 require 'minitest/autorun'
 
 class LambdaLogFormatterTest < Minitest::Test
-
   def test_formatter
     $_global_aws_request_id = SecureRandom.uuid
     time = Time.now
@@ -16,6 +17,53 @@ def test_formatter
 
     actual = under_test.call('INFO', time, progname, msg)
 
-    assert_equal "I, [#{time.strftime("%Y-%m-%dT%H:%M:%S.%6N")} ##{$$}]  INFO #{$_global_aws_request_id} -- #{progname}: #{msg}", actual
+    assert_equal "I, [#{time.strftime("%Y-%m-%dT%H:%M:%S.%6N")} ##{$$}]  INFO #{$_global_aws_request_id} -- #{progname}: #{msg}\n", actual
+  end
+end
+
+class JsonLogFormatterTest < Minitest::Test
+  def test_formats_standard_log_message
+    $_global_aws_request_id = 'request-id-1'
+    formatter = JsonLogFormatter.new
+
+    output = formatter.call('INFO', Time.utc(2026, 2, 23, 16, 29, 1), 'app', 'hello')
+    parsed = JSON.parse(output)
+
+    assert_equal '2026-02-23T16:29:01.000000Z', parsed['timestamp']
+    assert_equal 'INFO', parsed['level']
+    assert_equal 'hello', parsed['message']
+    assert_equal 'request-id-1', parsed['requestId']
+    assert_equal 'app', parsed['logger']
+  end
+
+  def test_formats_exception_fields
+    $_global_aws_request_id = 'request-id-2'
+    formatter = JsonLogFormatter.new
+
+    begin
+      raise RuntimeError, 'something went wrong'
+    rescue RuntimeError => e
+      output = formatter.call('ERROR', Time.utc(2026, 2, 23, 16, 29, 1), nil, e)
+      parsed = JSON.parse(output)
+
+      assert_equal 'ERROR', parsed['level']
+      assert_equal 'something went wrong', parsed['message']
+      assert_equal 'RuntimeError', parsed['errorType']
+      assert_equal 'something went wrong', parsed['errorMessage']
+      assert_kind_of Array, parsed['stackTrace']
+      refute_empty parsed['stackTrace']
+      assert_match(/.+:.+:\d+/, parsed['location'])
+      refute parsed.key?('logger')
+    end
+  end
+
+  def test_coerces_non_string_progname
+    $_global_aws_request_id = 'request-id-3'
+    formatter = JsonLogFormatter.new
+
+    output = formatter.call('INFO', Time.utc(2026, 2, 23, 16, 29, 1), 123, 'hello')
+    parsed = JSON.parse(output)
+
+    assert_equal '123', parsed['logger']
   end
-end
+end

test/unit/logger_patch_test.rb

@@ -0,0 +1,94 @@
+# frozen_string_literal: true
+
+require_relative '../../lib/aws_lambda_ric/logger_patch'
+require 'logger'
+require 'stringio'
+require 'minitest/autorun'
+
+module AwsLambdaRIC
+  class TelemetryLogger
+    class << self
+      attr_accessor :telemetry_log_sink
+    end
+  end
+end
+
+class LoggerPatchTest < Minitest::Test
+  def setup
+    @original_log_format = ENV['AWS_LAMBDA_LOG_FORMAT']
+    @original_log_level = ENV['AWS_LAMBDA_LOG_LEVEL']
+    AwsLambdaRIC::TelemetryLogger.telemetry_log_sink = nil
+
+    @patched_class = Class.new do
+      prepend LoggerPatch
+      attr_reader :super_args, :super_kwargs
+
+      def initialize(*args, **kwargs)
+        @super_args = args
+        @super_kwargs = kwargs
+      end
+    end
+  end
+
+  def teardown
+    ENV['AWS_LAMBDA_LOG_FORMAT'] = @original_log_format
+    ENV['AWS_LAMBDA_LOG_LEVEL'] = @original_log_level
+  end
+
+  def test_uses_text_formatter_for_stdout_by_default
+    ENV['AWS_LAMBDA_LOG_FORMAT'] = 'TEXT'
+    ENV.delete('AWS_LAMBDA_LOG_LEVEL')
+    LoggerPatch.refresh_runtime_config!
+
+    instance = @patched_class.new($stdout)
+
+    assert_same $stdout, instance.super_args[0]
+    assert_instance_of LogFormatter, instance.super_kwargs[:formatter]
+    assert_equal Logger::DEBUG, instance.super_kwargs[:level]
+  end
+
+  def test_uses_json_formatter_when_requested
+    ENV['AWS_LAMBDA_LOG_FORMAT'] = 'json'
+    ENV.delete('AWS_LAMBDA_LOG_LEVEL')
+    LoggerPatch.refresh_runtime_config!
+
+    instance = @patched_class.new($stdout)
+
+    assert_instance_of JsonLogFormatter, instance.super_kwargs[:formatter]
+  end
+
+  def test_maps_trace_level_to_debug
+    ENV['AWS_LAMBDA_LOG_FORMAT'] = 'JSON'
+    ENV['AWS_LAMBDA_LOG_LEVEL'] = 'trace'
+    LoggerPatch.refresh_runtime_config!
+
+    instance = @patched_class.new($stdout)
+
+    assert_equal Logger::DEBUG, instance.super_kwargs[:level]
+  end
+
+  def test_does_not_override_explicit_formatter_or_level
+    custom_formatter = Logger::Formatter.new
+    ENV['AWS_LAMBDA_LOG_FORMAT'] = 'JSON'
+    ENV['AWS_LAMBDA_LOG_LEVEL'] = 'ERROR'
+    LoggerPatch.refresh_runtime_config!
+
+    instance = @patched_class.new($stdout, formatter: custom_formatter, level: Logger::WARN)
+
+    assert_same custom_formatter, instance.super_kwargs[:formatter]
+    assert_equal Logger::WARN, instance.super_kwargs[:level]
+  end
+
+  def test_keeps_custom_logdev_unmodified
+    io = StringIO.new
+    ENV['AWS_LAMBDA_LOG_FORMAT'] = 'JSON'
+    ENV['AWS_LAMBDA_LOG_LEVEL'] = 'ERROR'
+    LoggerPatch.refresh_runtime_config!
+
+    instance = @patched_class.new(io)
+
+    assert_same io, instance.super_args[0]
+    assert_nil instance.super_kwargs[:formatter]
+    assert_equal Logger::DEBUG, instance.super_kwargs[:level]
+  end
+end