Skip to content

Add structured JSON logging support #58

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
anzheyazzz wants to merge 1 commit into
base: main
Choose a base branch
from
Open

Add structured JSON logging support #58

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
40 changes: 24 additions & 16 deletions lib/aws_lambda_ric.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand All @@ -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)
Expand All @@ -180,7 +189,6 @@ def puts(*arg)
end
end
end

# Represents a single Lambda Invocation Request
class LambdaInvocationRequest

Expand Down
61 changes: 59 additions & 2 deletions lib/aws_lambda_ric/lambda_log_formatter.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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)
Copy link
Copy Markdown

@trivenay trivenay Apr 8, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

JSON.generate raises JSON::GeneratorError when the message contains invalid UTF-8 bytes:

formatter = JsonLogFormatter.new
formatter.call("INFO", Time.now, nil, "Hello \xFF\xFE World")
# => JSON::GeneratorError: source sequence is illegal/malformed utf-8

This could crash the Lambda if user code logs binary data or strings with encoding issues.

Why this is Ruby-specific (not needed in let's say Python):

Ruby strings are byte buffers with an encoding tag — you can have a string tagged as UTF-8 that contains invalid bytes. The error only surfaces at JSON.generate.

Python3 for example validates encoding at string creation time (bytes.decode()). By the time a message reaches the logger, it's guaranteed to be valid Unicode or it already crashed in user code. In Ruby, invalid bytes can slip through and crash in our code.

# Ruby allows this
s = "Hello \xFF\xFE"
s.encoding        # => UTF-8
s.valid_encoding? # => false (but it exists!)

Suggested fix:

def message_for(msg)
  result = msg.is_a?(Exception) ? msg.message : msg2str(msg)
  result.encode('UTF-8', invalid: :replace, undef: :replace)
end

With fix:

formatter.call("INFO", Time.now, nil, "Hello \xFF\xFE World")
# => {"level":"INFO","message":"Hello �� World"}

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
60 changes: 49 additions & 11 deletions lib/aws_lambda_ric/logger_patch.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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
94 changes: 91 additions & 3 deletions test/unit/lambda_log_formatter_test.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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
Expand All @@ -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
Loading
Loading