ILambdaLogger.LogLine(...) behaviour changed between .Net 5 and .Net 6

[El-Gor-do]

Description

In .Net 5, ILambdaLogger.LogLine("hello world") would be logged to CloudWatch Logs exactly as

hello world

After changing my Lambda project's TargetFramework from net5.0 to net6.0, the same call to ILambdaLogger.LogLine is logged to CloudWatch Logs as "{timestamp}\t{requestId}\t{level}\t{message}"

2021-11-14T21:32:01.022Z	8247f3ba-2335-4b12-bf19-e379605ba146	info	hello world

In my real Lambda project, my message is a json string which I subsequently deserialise. With the new behaviour in .Net 6, the message is no longer valid json because of the extra tab-delimited fields in each message.

Reproduction Steps

In a custom runtime Lambda, set the function handler to this

public static DateTime FunctionHandler(ILambdaContext context)
{
    context.Logger.LogLine("hello world");
    return DateTime.UtcNow;
}

Deploy this Lambda using TargetFramework net5.0 then invoke the function and check the CloudWatch Logs output. The log event's message will be "hello world". Deploy the Lambda again using TargetFramework net6.0 then invoke the function again and check the CloudWatch Logs output again. The log event's message will have tab-delimited fields followed by "hello world".

Environment

• Build Version: Amazon.Lambda.Core 2.1.0
• OS Info: AmazonLinux2
• Build Environment: docker
• Targeted .NET Platform: net5.0 and net6.0

Resolution

I would like the .Net 6 behaviour to return to the previous .Net 5 behaviour where the log event's message is exactly as I passed to ILambdaLogger.LogLine(...)

This is a 🐛 bug-report

[ashishdhingra]

Reproducible. While we cannot use Visual Studio 2019 for .NET 6 targets, AWS extensions for .NET CLI could be used to deploy the updated project with target as net6.0.

[El-Gor-do]

The change in behaviour appears to be due to changing the IConsoleLoggerWriter implementation from SimpleLoggerWriter to LogLevelLoggerWriter.

aws-lambda-dotnet/Libraries/src/Amazon.Lambda.RuntimeSupport/Helpers/ConsoleLoggerWriter.cs

Line 203 in 70d6a97

internal void FormattedWriteLine(string level, string message)

[normj]

The change was done on purpose because getting request id in the logging statement like other Lambda runtimes was a highly requested feature. I understand your use case of wanting to pass in a JSON string to logline. If we had an environment variable that allowed you to opt in the old behavior would that work for you?

[El-Gor-do]

My current workaround when reading back log messages is to split on \t then deserialise the last field. Having an environment variable to revert to the previous logging behaviour would work for me.

[plaisted]

Are there any plans to integrate the requestId feature into the Microsoft.Extensions.Logging based lambda logger (Amazon.Lambda.Logging.AspNetCore)?

I'm currently using a modified Microsoft.Extensions.Logging.Console based formatter to accomplish this but would be nice to have some sort of built in functionality.

[ashishdhingra]

@El-Gor-do Amazon.Lambda.RuntimeSupport 1.5.0 adds support for environment variable AWS_LAMBDA_HANDLER_LOG_FORMAT with allowed values: Default and Unformatted. This helps users that prefer the pre .NET 6 logging format which didn't added time, request id and log level into each message. Those users can set the environment variable to Unformatted and the log message will be written just as the user sent the message into the log api. Please test the changes at your end to verify that it works for your scenario and let us know if this issue could be closed.

[El-Gor-do]

I have tested Amazon.Lamda.RuntimeSupport 1.5.0 with AWS_LAMBDA_HANDLER_LOG_FORMAT=Unformatted. The CloudWatch Logs message contains an additional trailing newline character whereas the previous .Net 5 behaviour wrote the message exactly as passed without appending a newline character. For my use case this doesn't matter but it might be an issue for other users.

[martincostello]

Just found this issue. Not urgent, but would it be possible to have this exposed programmatically?

We have an internal framework which builds on top of this library we use in a number of different Lambda solutions, where this library is referenced transitively. We also use JSON-formatted logging.

To apply this fix, as well as updating our framework library, this also needs us to apply the environment variable in each lambda project. It would be easier to roll out the fix centrally if our base library could just set the level to Unformatted itself.

[ashishdhingra]

Just found this issue. Not urgent, but would it be possible to have this exposed programmatically?

We have an internal framework which builds on top of this library we use in a number of different Lambda solutions, where this library is referenced transitively. We also use JSON-formatted logging.

To apply this fix, as well as updating our framework library, this also needs us to apply the environment variable in each lambda project. It would be easier to roll out the fix centrally if our base library could just set the level to Unformatted itself.

@martincostello Please raise a new feature request mentioning all the details about your use case.

[martincostello]

@ashishdhingra I've raised #1000.

[ashishdhingra]

Closing this issue since the changes have been implemented and for programmatic behavior a new feature request is created.

[github-actions]

⚠️COMMENT VISIBILITY WARNING⚠️

Comments on closed issues are hard for our team to see.
If you need more assistance, please either tag a team member or open a new issue that references this one.
If you wish to keep having a conversation with other community members under this issue feel free to do so.