The quarkus-amazon-lambda extension doesn't respect JSON log output for unhandled exceptions

StFS commented 2 years ago

Describe the bug

In a Quarkus project configured with the quarkus-amazon-lambda and quarkus-logging-json extensions, one would expect all logging (with the exception of the AWS CloudWatch START, END and REPORT lines) would be output as JSON.

This is in fact the case when running such a project in the Quarkus Dev server, all log lines, including log lines for unhandled exceptions thrown out of the handler method, are logged as JSON lines. So an unhandled exception produces a single JSON line in the output in the Quarkus Dev server that is logged out on the ERROR level and includes the exception stack trace within the JSON package.

However, when this same lambda is run with the prod profile, things change. This seems to result in the standard CloudWatch lines (START, END and REPORT) being output by the lambda when it's invoked but it also has the undesirable side effect that any unhandled exceptions thrown out of the handler method are logged out as plain text instead of being wrapped in a JSON message.

Expected behavior

Unhandled exceptions thrown out of the Lambda handler method should be logged out as JSON, even when running in prod mode.

Actual behavior

Unhandled exceptions thrown out of the Lambda handler method are logged out in plain text when running in prod mode.

Example:

{"timestamp":"2022-07-19T14:11:16.739Z","sequence":9,"loggerClassName":"org.slf4j.impl.Slf4jLogger","loggerName":"org.acme.lambda.GreetingLambda","level":"INFO","message":"This line will be logged as JSON","threadName":"main","threadId":1,"mdc":{},"ndc":"","hostName":"a2c9acd8176a","processName":"lambdainternal.AWSLambda","processId":15}
This exception will not be logged as JSON: java.lang.RuntimeException
java.lang.RuntimeException: This exception will not be logged as JSON
    at org.acme.lambda.GreetingLambda.handleRequest(GreetingLambda.java:17)
    at org.acme.lambda.GreetingLambda.handleRequest(GreetingLambda.java:9)
    at io.quarkus.amazon.lambda.runtime.AmazonLambdaRecorder.handle(AmazonLambdaRecorder.java:85)
    at io.quarkus.amazon.lambda.runtime.QuarkusStreamHandler.handleRequest(QuarkusStreamHandler.java:58)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.base/java.lang.reflect.Method.invoke(Unknown Source)

END RequestId: 55971e9e-7ca0-4707-86ff-1971accb79e3
REPORT RequestId: 55971e9e-7ca0-4707-86ff-1971accb79e3  Init Duration: 1.00 ms  Duration: 1605.74 ms    Billed Duration: 1606 ms    Memory Size: 3008 MB    Max Memory Used: 3008 MB

How to Reproduce?

Reproducer project: https://github.com/StFS/lambda-json-logging

Follow the instructions in the README there to reproduce this.

The very short version is:

Check out the project: git clone git@github.com:StFS/lambda-json-logging.git && cd lambda-json-logging
Run ./mvnw package
Run docker build -t mytag .
Run docker run -p 8080:8080 mytag
In a separate CLI, run curl -XPOST "http://localhost:8080/2015-03-31/functions/function/invocations" -d '{"name":"error"}'

This will result in an exception being thrown in the Lambda handler method and the exception being logged out in plain text.

Output of `uname -a` or `ver`

No response

Output of `java -version`

openjdk version "11.0.14.1" 2022-02-08 LTS OpenJDK Runtime Environment Corretto-11.0.14.10.1 (build 11.0.14.1+10-LTS) OpenJDK 64-Bit Server VM Corretto-11.0.14.10.1 (build 11.0.14.1+10-LTS, mixed mode, sharing)

GraalVM version (if different from Java)

N/A

Quarkus version or git rev

2.10.2.Final

Build tool (ie. output of `mvnw --version` or `gradlew --version`)

Apache Maven 3.8.4 (9b656c72d54e5bacbed989b64718c159fe39b537) Maven home: /Users/stefan.freyr.stefansson/.m2/wrapper/dists/apache-maven-3.8.4-bin/52ccbt68d252mdldqsfsn03jlf/apache-maven-3.8.4 Java version: 17.0.3.1, vendor: Oracle Corporation, runtime: /Library/Java/JavaVirtualMachines/jdk-17.0.3.1.jdk/Contents/Home Default locale: en_IS, platform encoding: UTF-8 OS name: "mac os x", version: "12.4", arch: "x86_64", family: "mac"

Additional information

No response

quarkus-bot[bot] commented 2 years ago

/cc @matejvasek, @patriot1burke

StFS commented 2 years ago

@matejvasek @patriot1burke

Nothing has happened with this issue since I reported it. That's fully understandable but I wanted to ask a question.

Can you explain what mechanism is causing this to happen? What part of the system is logging out these unhandled exceptions?

A colleague of mine had a similar problem where parts of the logging were being output in plain text and he was able to fix that by adding a dependency on commons-logging-jboss-logging. Somehow, that triggered the logging logic of some library that was being used behind the scenes to pick up some config that told it to use JSON output format.

My question is whether you can think of anything similar to that I could try for this? I've already tried adding commons-logging-jboss-logging which did not seem to work in the example I provided for this issue. Are there any other logging library dependencies or configs that you could think of it being worth trying to see if it might impact this behaviour?

patriot1burke commented 2 years ago

The exception is being propagated to the AWS Lambda runtime and outputted there, thus outside the scope and control of Quarkus. I don't know how to override lambda logging.

patriot1burke commented 2 years ago

I guess we could catch the exception in our StreamHandler, log it via Quarkus logger, and return an error response.

StFS commented 2 years ago

@patriot1burke thanks for the response. I'd really like to see that be done because as you say, there doesn't seem to be a way to configure the logging of the AWS Lambda runtime in any easy way.

einarjohnson commented 1 year ago

I am facing the exact same problem on my end where exceptions get logged out to stdout (and thus Cloudwatch) on a non-json format. Any ideas how I could get around this?

quarkusio / quarkus