Skip to content

Commit f152901

Browse files
committed
feat: Add structured JSON logging support
Add JsonLogFormatter for JSON-formatted log output controlled by AWS_LAMBDA_LOG_FORMAT and AWS_LAMBDA_LOG_LEVEL environment variables. Refactor TelemetryLogger initialization to apply Logger patch and runtime config before telemetry fd setup. - Add JsonLogFormatter with timestamp, level, message, requestId, and exception fields (errorType, errorMessage, stackTrace, location) - Update LoggerPatch to select formatter and log level based on env vars - Fix LogFormatter to append newline for consistency - Fix backtrace regex to handle both Ruby < 3.4 and 3.4+ formats - Upgrade Dockerfile.rie base image to Ruby 3.4 - Relax bundler development dependency to >= 2.0
1 parent 6108f92 commit f152901

10 files changed

Lines changed: 376 additions & 49 deletions

.gitignore

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -15,3 +15,4 @@ Gemfile.lock
1515
.ruby-version
1616
# containerized test runner clone
1717
.test-runner/
18+
.idea/

Dockerfile.rie

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
FROM public.ecr.aws/lambda/ruby:3.3
1+
FROM public.ecr.aws/lambda/ruby:3.4
22

33
# Copy source code and build gem in container
44
COPY . ${LAMBDA_TASK_ROOT}/

aws_lambda_ric.gemspec

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -32,7 +32,7 @@ Gem::Specification.new do |spec|
3232
spec.require_paths = ['lib']
3333

3434
spec.add_runtime_dependency "logger", ">= 1.4", "< 2.0"
35-
spec.add_development_dependency 'bundler', '~> 2.0'
35+
spec.add_development_dependency 'bundler', '>= 2.0'
3636
spec.add_development_dependency 'minitest', '~> 5.0'
3737
spec.add_development_dependency 'rake', '~> 13.0'
3838
spec.add_development_dependency 'activesupport', '~> 6.0.1'

lib/aws_lambda_ric.rb

Lines changed: 46 additions & 30 deletions
Original file line numberDiff line numberDiff line change
@@ -131,10 +131,44 @@ class TelemetryLogger
131131
ENV_VAR_TELEMETRY_LOG_FD = '_LAMBDA_TELEMETRY_LOG_FD'
132132

133133
class << self
134-
attr_accessor :telemetry_log_fd_file, :telemetry_log_sink
135-
134+
attr_accessor :telemetry_log_fd_file, :telemetry_log_sink, :logger_patch_applied, :kernel_puts_patch_applied
136135
def close
137136
telemetry_log_fd_file&.close
137+
self.telemetry_log_fd_file = nil
138+
end
139+
140+
def mutate_std_logger
141+
return if logger_patch_applied
142+
143+
Logger.class_eval do
144+
prepend LoggerPatch
145+
end
146+
self.logger_patch_applied = true
147+
end
148+
149+
def mutate_kernel_puts
150+
return if kernel_puts_patch_applied
151+
152+
Kernel.module_eval do
153+
define_method(:puts) do |*args|
154+
msg = args.flatten.map { |a| a.to_s }.join("\n")
155+
msg = msg.encode('UTF-8', invalid: :replace, undef: :replace)
156+
msg += "\n" unless msg.end_with?("\n")
157+
158+
telemetry_sink = AwsLambdaRIC::TelemetryLogger.telemetry_log_sink
159+
if telemetry_sink.nil?
160+
$stdout.write(msg)
161+
else
162+
telemetry_sink.write(msg)
163+
end
164+
165+
nil
166+
end
167+
module_function :puts
168+
private :puts
169+
end
170+
171+
self.kernel_puts_patch_applied = true
138172
end
139173
end
140174

@@ -144,43 +178,25 @@ def initialize(telemetry_log_fd)
144178
AwsLambdaRIC::TelemetryLogger.telemetry_log_fd_file.sync = true
145179

146180
AwsLambdaRIC::TelemetryLogger.telemetry_log_sink = TelemetryLogSink.new(file: AwsLambdaRIC::TelemetryLogger.telemetry_log_fd_file)
147-
148-
mutate_std_logger
149-
mutate_kernel_puts
181+
AwsLambdaRIC::TelemetryLogger.mutate_kernel_puts
150182
rescue Errno::ENOENT, Errno::EBADF
151-
# If File.open() fails, then the mutation won't happen and the default behaviour (print to stdout) will prevail
183+
AwsLambdaRIC::TelemetryLogger.telemetry_log_fd_file = nil
184+
AwsLambdaRIC::TelemetryLogger.telemetry_log_sink = nil
152185
end
153186

154187
def self.from_env()
155-
if ENV.key?(ENV_VAR_TELEMETRY_LOG_FD)
156-
fd = ENV.fetch(AwsLambdaRIC::TelemetryLogger::ENV_VAR_TELEMETRY_LOG_FD)
157-
ENV.delete(AwsLambdaRIC::TelemetryLogger::ENV_VAR_TELEMETRY_LOG_FD)
158-
AwsLambdaRIC::TelemetryLogger.new(fd)
159-
end
160-
end
161188

162-
private
189+
LoggerPatch.refresh_runtime_config!
190+
mutate_std_logger
191+
AwsLambdaRIC::TelemetryLogger.telemetry_log_sink = nil
163192

164-
def mutate_std_logger
165-
Logger.class_eval do
166-
prepend LoggerPatch
167-
end
168-
end
193+
return unless ENV.key?(ENV_VAR_TELEMETRY_LOG_FD)
169194

170-
def mutate_kernel_puts
171-
Kernel.module_eval do
172-
def puts(*arg)
173-
msg = arg.flatten.collect { |a| a.to_s.encode('UTF-8') }.join("\n")
174-
if msg[-1] != "\n"
175-
msg += "\n"
176-
end
177-
AwsLambdaRIC::TelemetryLogger.telemetry_log_sink.write(msg)
178-
return nil
179-
end
180-
end
195+
fd = ENV.fetch(AwsLambdaRIC::TelemetryLogger::ENV_VAR_TELEMETRY_LOG_FD)
196+
ENV.delete(AwsLambdaRIC::TelemetryLogger::ENV_VAR_TELEMETRY_LOG_FD)
197+
AwsLambdaRIC::TelemetryLogger.new(fd)
181198
end
182199
end
183-
184200
# Represents a single Lambda Invocation Request
185201
class LambdaInvocationRequest
186202

Lines changed: 55 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,12 +1,65 @@
11
# frozen_string_literal: true
22

3+
require 'json'
34
require 'logger'
45

56
class LogFormatter < Logger::Formatter
67
FORMAT = '%<sev>s, [%<datetime>s #%<process>d] %<severity>5s %<request_id>s -- %<progname>s: %<msg>s'
78

89
def call(severity, time, progname, msg)
9-
(FORMAT % {sev: severity[0..0], datetime: format_datetime(time), process: $$, severity: severity,
10-
request_id: $_global_aws_request_id, progname: progname, msg: msg2str(msg)}).encode!('UTF-8')
10+
formatted = FORMAT % {
11+
sev: severity[0..0],
12+
datetime: format_datetime(time),
13+
process: $$,
14+
severity: severity,
15+
request_id: $_global_aws_request_id,
16+
progname: progname,
17+
msg: msg2str(msg)
18+
}
19+
"#{formatted.encode('UTF-8')}\n"
20+
end
21+
end
22+
23+
class JsonLogFormatter < Logger::Formatter
24+
DATETIME_FORMAT = '%Y-%m-%dT%H:%M:%S.%6NZ'
25+
26+
def call(severity, time, progname, msg)
27+
payload = {
28+
timestamp: time.utc.strftime(DATETIME_FORMAT),
29+
level: severity,
30+
message: message_for(msg),
31+
requestId: $_global_aws_request_id
32+
}
33+
34+
logger_name = progname.to_s
35+
payload[:logger] = logger_name unless logger_name.empty?
36+
37+
if msg.is_a?(Exception)
38+
payload[:errorType] = msg.class.to_s
39+
payload[:errorMessage] = msg.message
40+
payload[:stackTrace] = msg.backtrace || []
41+
location = location_for(msg)
42+
payload[:location] = location unless location.nil?
43+
end
44+
45+
"#{JSON.generate(payload.compact)}\n"
46+
end
47+
48+
private
49+
50+
def message_for(msg)
51+
return msg.message if msg.is_a?(Exception)
52+
53+
msg2str(msg)
54+
end
55+
56+
def location_for(exception)
57+
first_backtrace_line = exception.backtrace&.first
58+
return nil if first_backtrace_line.nil?
59+
60+
matched = first_backtrace_line.match(/\A(.+):(\d+):in [`'](.+)'\z/)
61+
return "#{matched[1]}:#{matched[3]}:#{matched[2]}" if matched
62+
63+
first_backtrace_line
1164
end
1265
end
Lines changed: 15 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,10 +1,24 @@
11
# frozen_string_literal: true
22

3+
require 'json'
4+
35
class LambdaLogger
46
class << self
57
def log_error(exception:, message: nil)
68
puts message if message
7-
puts JSON.pretty_unparse(exception.to_lambda_response)
9+
puts formatted_error(exception)
10+
end
11+
12+
private
13+
14+
def formatted_error(exception)
15+
error_response = exception.to_lambda_response
16+
17+
if AwsLambdaRIC::TelemetryLogger.telemetry_log_sink.nil?
18+
JSON.generate(error_response)
19+
else
20+
JSON.pretty_unparse(error_response)
21+
end
822
end
923
end
1024
end

lib/aws_lambda_ric/logger_patch.rb

Lines changed: 48 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -1,19 +1,56 @@
11
# Copyright 2019 Amazon.com, Inc. or its affiliates. All Rights Reserved.
22

3+
# frozen_string_literal: true
4+
5+
require 'logger'
6+
require_relative 'lambda_log_formatter'
7+
38
module LoggerPatch
4-
def initialize(logdev, shift_age = 0, shift_size = 1048576, level: 'debug',
5-
progname: nil, formatter: nil, datetime_format: nil,
6-
binmode: false, shift_period_suffix: '%Y%m%d')
7-
logdev_lambda_override = logdev
8-
formatter_override = formatter
9-
# use unpatched constructor if logdev is a filename or an IO Object other than $stdout or $stderr
9+
LOG_LEVEL_MAP = {
10+
'TRACE' => Logger::DEBUG,
11+
'DEBUG' => Logger::DEBUG,
12+
'INFO' => Logger::INFO,
13+
'WARN' => Logger::WARN,
14+
'ERROR' => Logger::ERROR,
15+
'FATAL' => Logger::FATAL
16+
}.freeze
17+
18+
class << self
19+
attr_reader :aws_lambda_log_format, :aws_lambda_log_level
20+
21+
def refresh_runtime_config!
22+
@aws_lambda_log_format = ENV.fetch('AWS_LAMBDA_LOG_FORMAT', '').upcase
23+
env_level = ENV.fetch('AWS_LAMBDA_LOG_LEVEL', nil)
24+
@aws_lambda_log_level = LOG_LEVEL_MAP[env_level&.upcase]
25+
end
26+
27+
def json_format?
28+
@aws_lambda_log_format == 'JSON'
29+
end
30+
end
31+
32+
refresh_runtime_config!
33+
34+
def initialize(logdev, shift_age = 0, shift_size = 1_048_576, **kwargs)
35+
level_was_provided = kwargs.key?(:level)
36+
kwargs = {
37+
level: Logger::DEBUG,
38+
progname: nil,
39+
formatter: nil,
40+
datetime_format: nil,
41+
binmode: false,
42+
shift_period_suffix: '%Y%m%d'
43+
}.merge(kwargs)
44+
45+
logdev_override = logdev
46+
1047
if !logdev || logdev == $stdout || logdev == $stderr
11-
logdev_lambda_override = AwsLambdaRIC::TelemetryLogger.telemetry_log_sink
12-
formatter_override = formatter_override || LogFormatter.new
48+
telemetry_sink = AwsLambdaRIC::TelemetryLogger.telemetry_log_sink
49+
logdev_override = telemetry_sink || logdev
50+
kwargs[:formatter] ||= LoggerPatch.json_format? ? JsonLogFormatter.new : LogFormatter.new
51+
kwargs[:level] = LoggerPatch.aws_lambda_log_level if !level_was_provided && LoggerPatch.aws_lambda_log_level
1352
end
1453

15-
super(logdev_lambda_override, shift_age, shift_size, level: level, progname: progname,
16-
formatter: formatter_override, datetime_format: datetime_format,
17-
binmode: binmode, shift_period_suffix: shift_period_suffix)
54+
super(logdev_override, shift_age, shift_size, **kwargs)
1855
end
1956
end
Lines changed: 51 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,12 +1,13 @@
11
# frozen_string_literal: true
22

33
require_relative '../../lib/aws_lambda_ric/lambda_log_formatter'
4+
require 'json'
45
require 'logger'
56
require 'securerandom'
7+
require 'time'
68
require 'minitest/autorun'
79

810
class LambdaLogFormatterTest < Minitest::Test
9-
1011
def test_formatter
1112
$_global_aws_request_id = SecureRandom.uuid
1213
time = Time.now
@@ -16,6 +17,53 @@ def test_formatter
1617

1718
actual = under_test.call('INFO', time, progname, msg)
1819

19-
assert_equal "I, [#{time.strftime("%Y-%m-%dT%H:%M:%S.%6N")} ##{$$}] INFO #{$_global_aws_request_id} -- #{progname}: #{msg}", actual
20+
assert_equal "I, [#{time.strftime("%Y-%m-%dT%H:%M:%S.%6N")} ##{$$}] INFO #{$_global_aws_request_id} -- #{progname}: #{msg}\n", actual
21+
end
22+
end
23+
24+
class JsonLogFormatterTest < Minitest::Test
25+
def test_formats_standard_log_message
26+
$_global_aws_request_id = 'request-id-1'
27+
formatter = JsonLogFormatter.new
28+
29+
output = formatter.call('INFO', Time.utc(2026, 2, 23, 16, 29, 1), 'app', 'hello')
30+
parsed = JSON.parse(output)
31+
32+
assert_equal '2026-02-23T16:29:01.000000Z', parsed['timestamp']
33+
assert_equal 'INFO', parsed['level']
34+
assert_equal 'hello', parsed['message']
35+
assert_equal 'request-id-1', parsed['requestId']
36+
assert_equal 'app', parsed['logger']
37+
end
38+
39+
def test_formats_exception_fields
40+
$_global_aws_request_id = 'request-id-2'
41+
formatter = JsonLogFormatter.new
42+
43+
begin
44+
raise RuntimeError, 'something went wrong'
45+
rescue RuntimeError => e
46+
output = formatter.call('ERROR', Time.utc(2026, 2, 23, 16, 29, 1), nil, e)
47+
parsed = JSON.parse(output)
48+
49+
assert_equal 'ERROR', parsed['level']
50+
assert_equal 'something went wrong', parsed['message']
51+
assert_equal 'RuntimeError', parsed['errorType']
52+
assert_equal 'something went wrong', parsed['errorMessage']
53+
assert_kind_of Array, parsed['stackTrace']
54+
refute_empty parsed['stackTrace']
55+
assert_match(/.+:.+:\d+/, parsed['location'])
56+
refute parsed.key?('logger')
57+
end
58+
end
59+
60+
def test_coerces_non_string_progname
61+
$_global_aws_request_id = 'request-id-3'
62+
formatter = JsonLogFormatter.new
63+
64+
output = formatter.call('INFO', Time.utc(2026, 2, 23, 16, 29, 1), 123, 'hello')
65+
parsed = JSON.parse(output)
66+
67+
assert_equal '123', parsed['logger']
2068
end
21-
end
69+
end

0 commit comments

Comments
 (0)