Add structured JSON logging support

.gitignore

@@ -15,3 +15,4 @@ Gemfile.lock
 .ruby-version
 # containerized test runner clone
 .test-runner/
+.idea/

Dockerfile.rie

@@ -1,4 +1,4 @@
-FROM public.ecr.aws/lambda/ruby:3.3
+FROM public.ecr.aws/lambda/ruby:3.4
 
 # Copy source code and build gem in container
 COPY . ${LAMBDA_TASK_ROOT}/

aws_lambda_ric.gemspec

@@ -32,7 +32,7 @@ Gem::Specification.new do |spec|
   spec.require_paths         = ['lib']
 
   spec.add_runtime_dependency "logger", ">= 1.4", "< 2.0"
-  spec.add_development_dependency 'bundler', '~> 2.0'
+  spec.add_development_dependency 'bundler', '>= 2.0'
   spec.add_development_dependency 'minitest', '~> 5.0'
   spec.add_development_dependency 'rake', '~> 13.0'
   spec.add_development_dependency 'activesupport', '~> 6.0.1'

lib/aws_lambda_ric.rb

@@ -131,10 +131,44 @@ 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, :kernel_puts_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
+
+      def mutate_kernel_puts
+        return if kernel_puts_patch_applied
+
+        Kernel.module_eval do
+          define_method(:puts) do |*args|
+            msg = args.flatten.map { |a| a.to_s }.join("\n")
+            msg = msg.encode('UTF-8', invalid: :replace, undef: :replace)
+            msg += "\n" unless msg.end_with?("\n")
+
+            telemetry_sink = AwsLambdaRIC::TelemetryLogger.telemetry_log_sink
+            if telemetry_sink.nil?
+              $stdout.write(msg)
+            else
+              telemetry_sink.write(msg)
+            end
+
+            nil
+          end
+          module_function :puts
+          private :puts
+        end
+
+        self.kernel_puts_patch_applied = true
       end
     end
 
@@ -144,43 +178,25 @@ def initialize(telemetry_log_fd)
       AwsLambdaRIC::TelemetryLogger.telemetry_log_fd_file.sync = true
 
       AwsLambdaRIC::TelemetryLogger.telemetry_log_sink = TelemetryLogSink.new(file: AwsLambdaRIC::TelemetryLogger.telemetry_log_fd_file)
-
-      mutate_std_logger
-      mutate_kernel_puts
+      AwsLambdaRIC::TelemetryLogger.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
-    end
+      return unless ENV.key?(ENV_VAR_TELEMETRY_LOG_FD)
 
-    def mutate_kernel_puts
-      Kernel.module_eval do
-        def puts(*arg)
-          msg = arg.flatten.collect { |a| a.to_s.encode('UTF-8') }.join("\n")
-          if msg[-1] != "\n"
-            msg += "\n"
-          end
-          AwsLambdaRIC::TelemetryLogger.telemetry_log_sink.write(msg)
-          return nil
-        end
-      end
+      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
-
   # 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')}\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/lambda_logger.rb

@@ -1,10 +1,24 @@
 # frozen_string_literal: true
 
+require 'json'
+
 class LambdaLogger
   class << self
     def log_error(exception:, message: nil)
       puts message if message
-      puts JSON.pretty_unparse(exception.to_lambda_response)
+      puts formatted_error(exception)
+    end
+
+    private
+
+    def formatted_error(exception)
+      error_response = exception.to_lambda_response
+
+      if AwsLambdaRIC::TelemetryLogger.telemetry_log_sink.nil?
+        JSON.generate(error_response)
+      else
+        JSON.pretty_unparse(error_response)
+      end
     end
   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