diff --git a/.gitignore b/.gitignore index ba13ae8..98c7e59 100644 --- a/.gitignore +++ b/.gitignore @@ -15,3 +15,4 @@ Gemfile.lock .ruby-version # containerized test runner clone .test-runner/ +.idea/ diff --git a/Dockerfile.rie b/Dockerfile.rie index 021150f..671b9b8 100644 --- a/Dockerfile.rie +++ b/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}/ diff --git a/aws_lambda_ric.gemspec b/aws_lambda_ric.gemspec index 67e3799..04b32f9 100644 --- a/aws_lambda_ric.gemspec +++ b/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' diff --git a/lib/aws_lambda_ric.rb b/lib/aws_lambda_ric.rb index 418ad3d..7415a3c 100755 --- a/lib/aws_lambda_ric.rb +++ b/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 diff --git a/lib/aws_lambda_ric/lambda_log_formatter.rb b/lib/aws_lambda_ric/lambda_log_formatter.rb index c9fa62c..ac00ae6 100644 --- a/lib/aws_lambda_ric/lambda_log_formatter.rb +++ b/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 = '%s, [%s #%d] %5s %s -- %s: %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 diff --git a/lib/aws_lambda_ric/lambda_logger.rb b/lib/aws_lambda_ric/lambda_logger.rb index 8d98e37..70a71bf 100644 --- a/lib/aws_lambda_ric/lambda_logger.rb +++ b/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 diff --git a/lib/aws_lambda_ric/logger_patch.rb b/lib/aws_lambda_ric/logger_patch.rb index f872d37..81e6f35 100644 --- a/lib/aws_lambda_ric/logger_patch.rb +++ b/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 diff --git a/test/unit/lambda_log_formatter_test.rb b/test/unit/lambda_log_formatter_test.rb index 777b92f..bf9e5d0 100644 --- a/test/unit/lambda_log_formatter_test.rb +++ b/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 \ No newline at end of file +end diff --git a/test/unit/lambda_logger_test.rb b/test/unit/lambda_logger_test.rb new file mode 100644 index 0000000..efff343 --- /dev/null +++ b/test/unit/lambda_logger_test.rb @@ -0,0 +1,64 @@ +# frozen_string_literal: true + +require 'json' +require 'stringio' +require 'minitest/autorun' + +module AwsLambdaRIC + class TelemetryLogger + class << self + attr_accessor :telemetry_log_sink + end + end +end + +require_relative '../../lib/aws_lambda_ric/lambda_logger' + +class LambdaLoggerTest < Minitest::Test + FakeException = Struct.new(:payload) do + def to_lambda_response + payload + end + end + + def setup + @original_stdout = $stdout + @stdout = StringIO.new + $stdout = @stdout + AwsLambdaRIC::TelemetryLogger.telemetry_log_sink = nil + end + + def teardown + $stdout = @original_stdout + AwsLambdaRIC::TelemetryLogger.telemetry_log_sink = nil + end + + def test_logs_single_line_json_without_telemetry_sink + exception = FakeException.new({ + errorMessage: 'undefined method', + errorType: 'Function', + stackTrace: ['a', 'b'] + }) + + LambdaLogger.log_error(exception: exception, message: 'Critical exception from handler') + + assert_equal <<~OUTPUT, @stdout.string + Critical exception from handler + {"errorMessage":"undefined method","errorType":"Function","stackTrace":["a","b"]} + OUTPUT + end + + def test_logs_pretty_json_with_telemetry_sink + AwsLambdaRIC::TelemetryLogger.telemetry_log_sink = Object.new + exception = FakeException.new({ + errorMessage: 'undefined method', + errorType: 'Function', + stackTrace: ['a', 'b'] + }) + + LambdaLogger.log_error(exception: exception, message: 'Critical exception from handler') + + expected_json = JSON.pretty_unparse(exception.to_lambda_response) + assert_equal "Critical exception from handler\n#{expected_json}\n", @stdout.string + end +end diff --git a/test/unit/logger_patch_test.rb b/test/unit/logger_patch_test.rb new file mode 100644 index 0000000..15ed336 --- /dev/null +++ b/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 diff --git a/test/unit/xray_cause_test.rb b/test/unit/xray_cause_test.rb index 1e2fafb..c66abf9 100644 --- a/test/unit/xray_cause_test.rb +++ b/test/unit/xray_cause_test.rb @@ -25,7 +25,7 @@ def test_xray_cause assert_true under_test.instance_variable_get(:@cause)[:exceptions][0][:stack].count.positive? assert_equal __FILE__, under_test.instance_variable_get(:@cause)[:exceptions][0][:stack][0][:path] assert_kind_of Integer, under_test.instance_variable_get(:@cause)[:exceptions][0][:stack][0][:line] - assert_equal __method__.to_s, under_test.instance_variable_get(:@cause)[:exceptions][0][:stack][0][:label] + assert_includes under_test.instance_variable_get(:@cause)[:exceptions][0][:stack][0][:label], __method__.to_s end def test_stack_depth_maximum