Logs not showing up with SAM local - async issue?

[rmmeans]

I have been trying to use the lambda-logging library and I noticed something very odd - when running my lambda's using SAM local - the logs were not showing up at all - but when ran on AWS as a real lambda, they did show up.

What bothered me even more though is a bit hard to describe. Only the SLF4J impl seems to fail. Given I have the following in my handler:

    lambdaLogger.log("using the lambda logger y'all...")
    System.err.println("A standard error output...")
    logger.error("Using SLF4J - first call")
    logger.error("Using SLF4j - second call")

On SAM Local I receive the following (note the ordering of events and that SLF4J is missing)

START RequestId: b280dc8f-2a62-4131-b023-802fdf4222e8 Version: $LATEST
using the lambda logger y'all...A standard error output...
END RequestId: b280dc8f-2a62-4131-b023-802fdf4222e8
REPORT RequestId: b280dc8f-2a62-4131-b023-802fdf4222e8  Duration: 902.05 ms     Billed Duration: 1000 ms        Memory Size: 3008 MB    Max Memory Used: 3 MB

On AWS I receive the following, this time with SLF4J logs being printed (note the ordering of events -the SLF4J's calls are AFTER the END RequestId) and the two different log statements got grouped into a single one. I thought they should have been two unique events since they were two individual calls to logger.error?

Seeing how the SLF4J calls only show up when running on AWS is odd but when also seeing them appear out of order makes me wonder if SLF4J is doing some sort of queuing under the covers even though I don't believe the ConsoleAppender is an async appender. What I'm wondering if is this is causing a dangerous race condition...the logs didn't actually get written out to the STDOUT synchronously with where the logs were told to print in the code before continuing to the next statement in the code.... just by chance, the real lambda is still getting them written before the function container is paused / killed whereas when using SAM local the function container is killed before they are written which is why I am not seeing them. Does that sound plausible?

Finally - I am just wondering y'alls opinion going forward now that AWS has a log4j2 appender (https://github.com/aws/aws-lambda-java-libs/tree/master/aws-lambda-java-log4j2) whereas it was just an old 1.x appender when y'all first wrote this library (I believe that's what I understood from y'alls blog post). I also found it interesting that in their log4j2 impl they just call out to the lambda logger: https://github.com/aws/aws-lambda-java-libs/blob/master/aws-lambda-java-log4j2/src/main/java/com/amazonaws/services/lambda/runtime/log4j2/LambdaAppender.java#L74 I saw y'alls note in the README about possibly needing to make this SLF4J impl call out to the lambdalogger directly: https://github.com/symphoniacloud/lambda-monitoring/blob/master/lambda-logging/README.md#todo .. do you think that is necessary to get around the issues above? ^^

[rmmeans]

Just thought I would give an update here incase anyone else sees this.

I was able to successfully use aws-lambda-java-log4j2 with version 1.1.0 from amazon. I then used the log4j-slf4j-impl library so that log4j2 is only used as the logging framework for slf4j. This allowed me to use SLF4J api in my libraries and libraries from others that depend on the SLF4J API while having logs route through the recommended and provided AWS logging framework.

Upon doing this, all of my logs are now back in the correct execution order with where the process was at during execution of the Lambda and it is working with SAM local the same it does on AWS lambda.

I'm not sure what the logback appender is doing in what I referenced above as to why it does not appear to be immediately flushing to the output stream for stdout - this is not an issue with SLF4J but with logback as the logging framework and the appender being used it would appear.

[johnchapin]

Thanks for the detailed report - that's a really interesting finding. We're not doing anything particularly wild with logback, so it's definitely unexpected.

I do think it's worth trying to call out to LambdaLogger directly - if you'd like to take a swing at a PR for a new appender I'm happy to review it.

[johnchapin]

@rmmeans - try this again with version 1.0.3 (just released, may take a few hours to hit Maven Central). The lack of a trailing newline was causing some havoc, both in test output and in CloudWatch logs.