Solving the Java Aws Lambda logging problem

via maven, docker, GraalVM and sfl4j-simple-lambda

Note

This story is the following of my previous one Let’s compile your Aws Lambda in Java, I am building on it so it could be the place to start if you don’t know about GraalVM native-image or need more info on the Aws Lambda Execution Environment…

Introduction

Logs are crucial in production environment and also during development but the task is not easy even in full java, even following official recommendations from AWS.

Also, as we know it is theoretically possible to compile and execute a Java Lambda to native (see Let’s compile your Aws Lambda in Java) to benefit from a short cold-time, we need to know if this solution is production ready. One of the minimum requirement for that is to be able to log correctly from our native code.

My purpose here is to propose a solution for solving the logging requirement both for your standard Java Lambda but also for your compiled version.

Logging requirements

R1: Use a modern logging framework

We need the possibility to log using different Log levels (INFO, DEBUG, WARN, ERROR…) and to be able to configure which one is active.

R2: Be able to easily find something in the logs

Logs are going naturally to AWS Cloudwatch. We expect one call to log will result to one Cloudwatch Event/Entry.

R3: Be able to get logs also from the libraries we use

In particular, we need to be able to get logs from the Java Aws Sdk v2.

R4: Be able to identify several Log entries as coming from same Business Transaction

As every call to Lambda has a unique AWSRequestId, it could be very useful to add this id to every log entry, to identify them as coming as the same business transaction.

R5: Finding a solution that is native-image compatible.

Using a complex logging framework is a real challenge when trying to compile. Our solution must be compatible for the Java or the Custom Lambda Runtime Environment.

The problems

• Aws Lambda Execution environment is providing us a Context object having a method getLogger() giving a LambdaLogger whose methods doesn’t have any concept of Log Levels…

• Aws recommendation for Logging from Java with slf4j and log4j2 was not suitable for native compilation nor even working for me for plain java. (see aws documentation).
• It is a known issue that sometimes your call to LambdaLogger.log() is creating several Log entries for each line of a multi-line log. See this question in stackoverflow.
• The AWS Context Object is giving access to the AWSRequestId, but adding it manually to every log entry is no-go option.

Investigating on the multi-line logging problem

It took me several days to find the origin of the problem.

There are 2 parts:

• The Java Lambda Environment classloading issue
• The Custom Lambda Environment issues

The Java Lambda Environment classloading issue

After deploying your deployment package, the Java Lambda Execution environment is loading your code inside a custom classloader whose parent is the System Classloader:

This code extract is coming from the Java Runtime Interface Client (Java RIE).

Notice the call to setupRuntimeLogger(lambdaLogger) line 8:

This code is setting the private static field logger with the good LambdaLogger instance. In fact, this is the default value of this field:

Where you can see the default implementation is just writing to System.out without even a terminating newline!

The solution proposed by AWS is to include the dependency com.amazonaws:aws-lambda-java-log4j2:1.2.0

which include a Log4j Appender which retrieve the good LambdaLogger instance from the LambdaRuntime:

You will have then to use this appender from your log4j2.xml configuration file to make usage of the good LambdaLogger.

At the condition that you will not add your own jar of aws-lambda-java-core (which provide the class LambdaRuntime) from your deployment package, to make sure the CustomerClassloader will delegate to its parent when loading LambdaLogger to retrieve the class hacked by the Lambda Execution Environment containing the good logger.

One way to do it, is to include the dependency in scope provided like this:

When done properly, the multi-line logs are ok…

The Custom Lambda Environment issues

When compiling your lambda for use in the Custom Lambda Execution Environment, you need to include the Lambda RIE in your compilation.

So in that case, you need to include the full dependency:

The other issue is that in that case, the LambdaLogger provided will behave differently interpreting every new line in a multi-line comment as a separate Log entry! So we come back to the multi-line log problem.

My Complete Solution

As the solution provided by AWS is not suitable for native-compilation. I tried to provide my own solution based on Slf4j with logback, or log4j2 or slf4j-simple but without success because of native compilation problems or because it was not solving the multi-line logging problem.

So I decided to provide a new solution, a simple one, without reinventing the wheel so I created the open source project slf4j-simple-lambda on github. It is a fork of slf4j-simple provided by slf4j but with taking in mind the lambda execution environment.

These are the features:

• fork from slf4j-simple
• Allow logging from your code via slf4j
• Allow logging from AWS Sdk via log4j-over-slf4j
• graalVM native-image friendly
• Support for AWSRequestId
• Allow env properties with underscore instead of point to be compatible with AWS lambda env property naming rules

Setup your dependencies

log4j-api and log4j-over-slf4j are necessary to get logs produced by the Aws Java sdk 2 using log4j-api as frontend.

Notice: remove the scope provided when compiling your lambda for the Custom Execution Environment.

Add a configuration file simplelogger.properties as a classpath acccessible resource (for example, putting it in src/main/resources) :

Everything is working out of the box by default, using the INFO log Level but feel free to customize for your needs…

As simple as that 😅…

A proof of a complete solution ? see next section!

A complete Example with Logs

This example is using dynamodb, and slf4j-simple-lambda for both:

• The Java Execution Environment
• The Custom Execution Environment

You can find everything on github, where the project is called hello-lambda-custom-with-logs.

The Java Execution Environment

Simply run this:

mvn package

You will find a file in target/ folder:

hello-lambda-custom-with-logs-1.0-SNAPSHOT-deployment_package.zip

This is the lambda deployment package you need to use (with Java 11).

For the handler, specify:

example.App::sayHello 

Testing it will intentionally generate an error to verify the logs:

And yes, these events occurred at 4:24…

The Custom Execution Environment

First run:

mvn validate

This is generating a Dockerfile for your project (generic in case you want to use the project as a template for your own needs) in target/ folder.

Then run:

docker build -f target/Dockerfile -t hello-lambda:latest .

where you can change the tag evidently…

Then:

docker cp $(docker create hello-lambda:latest):/function.zip .

is extracting the function.zip to the current folder, this is the deployment package for your Custom Execution Environment!

Just use the same handler:

Test it, you will get:

As expected…

Conclusion

I let you discover the code of the project for understanding how I did it.

It was a long journey but I hope meaningful… Hope you appreciate the effort ;-). Any Clap will be welcome.