Merge pull request #58 from aws/anzhey/structured-logging

Adding structured JSON logging support

Author: anzheyazzz

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,69 @@
 # 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 = sanitize_utf8(progname) unless progname.nil?
+    payload[:logger] = logger_name unless logger_name.nil? || logger_name.empty?
+
+    if msg.is_a?(Exception)
+      payload[:errorType] = msg.class.to_s
+      payload[:errorMessage] = sanitize_utf8(msg.message)
+      payload[:stackTrace] = Array(msg.backtrace).map { |line| sanitize_utf8(line) }
+      location = location_for(msg)
+      payload[:location] = location unless location.nil?
+    end
+
+    "#{JSON.generate(payload.compact)}\n"
+  end
+
+  private
+
+  def message_for(msg)
+    result = msg.is_a?(Exception) ? msg.message : msg2str(msg)
+    sanitize_utf8(result)
+  end
+
+  def location_for(exception)
+    first_backtrace_line = exception.backtrace&.first
+    return nil if first_backtrace_line.nil?
+
+    sanitized_line = sanitize_utf8(first_backtrace_line)
+    matched = sanitized_line.match(/\A(?<file>.+):(?<line>\d+):in [`'](?<method>.+)'\z/)
+    return "#{matched[:file]}:#{matched[:method]}:#{matched[:line]}" if matched
+
+    sanitized_line
+  end
+
+  def sanitize_utf8(value)
+    value.to_s.encode('UTF-8', invalid: :replace, undef: :replace, replace: '�')
   end
 end

lib/aws_lambda_ric/logger_patch.rb

@@ -1,19 +1,57 @@
 # 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!
+
+  # shift_size default to 1 megabyte, matching Ruby Logger's default log rotation size.
+  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,93 @@ 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_formats_location_from_backtrace_line
+    $_global_aws_request_id = 'request-id-location'
+    formatter = JsonLogFormatter.new
+    exception = RuntimeError.new('something went wrong')
+    exception.set_backtrace(["/var/task/lambda_function.rb:6:in 'Object#lambda_handler'"])
+
+    output = formatter.call('ERROR', Time.utc(2026, 2, 23, 16, 29, 1), nil, exception)
+    parsed = JSON.parse(output)
+
+    assert_equal '/var/task/lambda_function.rb:Object#lambda_handler:6', parsed['location']
+  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
+
+  def test_sanitizes_invalid_utf8_in_message
+    $_global_aws_request_id = 'request-id-4'
+    formatter = JsonLogFormatter.new
+    invalid_message = [72, 101, 108, 108, 111, 32, 255, 254, 32, 87, 111, 114, 108, 100].pack('C*').force_encoding('UTF-8')
+
+    output = formatter.call('INFO', Time.utc(2026, 2, 23, 16, 29, 1), nil, invalid_message)
+    parsed = JSON.parse(output)
+
+    assert_equal 'Hello �� World', parsed['message']
+  end
+
+  def test_sanitizes_invalid_utf8_in_exception_fields
+    $_global_aws_request_id = 'request-id-5'
+    formatter = JsonLogFormatter.new
+    invalid_message = [66, 111, 111, 109, 32, 255, 254].pack('C*').force_encoding('UTF-8')
+    invalid_backtrace = "/var/task/lambda_function.rb:6:in 'Object#lambda_hand" + [255].pack('C*').force_encoding('UTF-8') + "ler'"
+    exception = RuntimeError.new(invalid_message)
+    exception.set_backtrace([invalid_backtrace])
+
+    output = formatter.call('ERROR', Time.utc(2026, 2, 23, 16, 29, 1), nil, exception)
+    parsed = JSON.parse(output)
+
+    assert_equal 'Boom ��', parsed['message']
+    assert_equal 'Boom ��', parsed['errorMessage']
+    assert_equal ["/var/task/lambda_function.rb:6:in 'Object#lambda_hand�ler'"], parsed['stackTrace']
+    assert_equal "/var/task/lambda_function.rb:Object#lambda_hand�ler:6", parsed['location']
   end
-end
+end