Support structured JSON logging for errors

[bensie]

AWS released advanced logging controls for Lambda.

On the whole, it works great with the slog package in Go 1.21 on the provided.2023 runtime for logging from Go functions. However, aws-lambda-go handles the logging of function errors, which are written in their own format that was decided on long before AWS released structured logging options.

When JSON logging is enabled on a function, any unstructured log entry will be automatically reshaped to JSON and will set the log level to INFO. Function errors handled by aws-lambda-go have this problem, which means that the only way to see function errors in the logs is to set the application log level to INFO.

Here's the complete code that demonstrates the following.

In the CloudFormation for a function, we'll set the LoggingConfig and (for now) we'll set ApplicationLogLevel to INFO.

    LoggingConfig:
      ApplicationLogLevel: INFO
      LogFormat: JSON
      SystemLogLevel: INFO

Given the following code, we expect the usual Lambda system log entries, plus an application-generated info message, warn message, error message, and the panic log entry.

package main

import (
	"context"
	"fmt"
	"log/slog"
	"os"

	"github.com/aws/aws-lambda-go/lambda"
	"github.com/aws/aws-lambda-go/lambdacontext"
)

func main() {
	lambda.StartHandlerFunc(handlerWithLambdaLogging(handler))
}

func handler(ctx context.Context, event any) (any, error) {
	slog.DebugContext(ctx, "debug message", "event", event)
	slog.InfoContext(ctx, "info message", "event", event)
	slog.WarnContext(ctx, "warn message", "event", event)
	slog.ErrorContext(ctx, "error message", "event", event)

	a := []string{"hey"}
	fmt.Println(a[1]) // panic

	return nil, nil
}

func handlerWithLambdaLogging[E, R any](handler func(context.Context, E) (R, error)) func(context.Context, E) (R, error) {
	var level slog.Level
	switch os.Getenv("AWS_LAMBDA_LOG_LEVEL") {
	case "DEBUG":
		level = slog.LevelDebug
	case "INFO":
		level = slog.LevelInfo
	case "WARN":
		level = slog.LevelWarn
	case "ERROR":
		level = slog.LevelError
	default:
		level = slog.LevelInfo
	}

	return func(ctx context.Context, event E) (R, error) {
		lc, _ := lambdacontext.FromContext(ctx)
		logHandler := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: level})).With("requestId", lc.AwsRequestID)
		slog.SetDefault(logHandler)

		return handler(ctx, event)
	}
}

This works as expected, but notice that the level for the errors are INFO.

Now we'll update the LoggingConfig to set the application log level to ERROR (and we'll set the system level to warn to quiet things down).

    LoggingConfig:
      ApplicationLogLevel: ERROR
      LogFormat: JSON
      SystemLogLevel: WARN

Re-run the function and take a look at the CloudWatch Logs. Since the error output logging is getting shoved into INFO level, it's not shown at all. We know that the function errored from the platform-level log, but won't be able to see what happened.

In addition to the AWS_LAMBDA_LOG_LEVEL env var demonstrated above, Lambda now also exposes AWS_LAMBDA_LOG_FORMAT, which could be used here in aws-lambda-go to determine whether or not to write the log entry with a predefined JSON structure without being a breaking change to this library.

In summary, it'd be great to be able to use ERROR level logging in Lambda applications and be able to see errors from aws-lambda-go. Thank you!

[bmoffatt]

Need to play with it a bit! :)

• Implementation: Not sure if a special log writer needs to be implemented to make Lambda recognize the levels, or if there's magic that makes it work out of the box parsing standard out. Ref Java: https://github.com/aws/aws-lambda-java-libs/blob/main/aws-lambda-java-runtime-interface-client/src/main/java/com/amazonaws/services/lambda/runtime/api/client/logging/FramedTelemetryLogSink.java
• Design: Not sure if the current built in log.Println and log.Fatal should match the AWS_LAMBDA_LOG_LEVEL (end thus always be present), or have their level defaulted to INFO, and be configurable via like StartWithOptions(..., lambda.WithLogLevel(...))
• Design: Ditto for AWS_LAMBDA_LOG_FORMAT. Leaning towards lambda.WithLogFormat(...) for backwards compat sake. And then there's ensuring that whatever the JSON format for errors looks like is consistent with the other runtimes

[bensie]

Thanks for taking a peek!

Not sure if a special log writer needs to be implemented to make Lambda recognize the levels

Nothing special is required - as long as level is a top-level JSON key in an entry from standard out, it will omit logs based on the function's AWS_LAMBDA_LOG_LEVEL setting. So you can (technically) spew all kinds of debug logging that just won't make it to CloudWatch Logs if you're set to error level. In app logs that can get expensive though if you're debug logging massive structs as JSON or whatever, so in my code above I'm passing the AWS_LAMBDA_LOG_LEVEL to slog, which is smart about bailing early before calling MarshalJSON on log args.

Not sure if the current built in log.Println and log.Fatal should match

I'm not sure about that either. It's really only an issue if those calls are / can be expensive, but I didn't see it doing anything substantial except for panic recovery and trace info, which is exactly what I'm hoping to get here.

And then there's ensuring that whatever the JSON format for errors looks like is consistent with the other runtimes

There's a doc - scroll to the "JSON format for application logs" section - they detail how the shape looks in the managed runtimes (don't even get me started on time vs timestamp being different between the platform and application logs, come on!). There's also a "Application log-level filtering with custom runtimes" section on that same page I can't link directly to with the ENV var stuff.