Bug: Log messages not being output as structured content

[j-d-ha]

Expected Behaviour

When using the logger, the output should be just a JSON object containing the log message information. It should NOT have other info added to the front of the output before the JSON log message, such as a timestamp, trace ID, and log level.

As an example, this is what I would expect the log output to be:

Current Behaviour

I am working with an executable assembly lambda and noticed some issues with logging. Here is my current setup:

• Executable assembly lambda with top-level statements
• Using HostApplicationBuilder with Powertools logger registered as singleton
• Handler method on DI-registered service with injected logger
• Service with handler is pulled from DI container and passed to LambdaBootstrapBuilder.Create() on startup

As part of my lambda setup, I am pulling the logger from the DI container after building the Host, and I am logging a startup message, which is properly formatted. Here is an example:

When I invoke the lambda, the log message that the handler logs is getting improperly formatted. Rather than being only a JSON object, it's getting prefixed with timestamp, trace ID, and log level, just like I would expect if I had used Console.WriteLine() to output something.

I ran some different tests and found the following:

• If I don't pull out the logger from the DI container and log during startup, I don't see this issue.
• If I switch the log type from Text to JSON, the message that's getting logged out is escaped JSON:

Happy to provide any other info needed and run other tests!

Code snippet

using Amazon.Lambda.Core;
using Amazon.Lambda.RuntimeSupport;
using Amazon.Lambda.Serialization.SystemTextJson;
using AWS.Lambda.Powertools.Logging;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;

var builder = Host.CreateApplicationBuilder();

builder.Services.AddSingleton<Service>();

builder.Services.AddSingleton<ILogger>(_ =>
    LoggerFactory
        .Create(options =>
            options.AddPowertoolsLogger(config => config.Service = "top-level-function-demo")
        )
        .CreatePowertoolsLogger()
);

var host = builder.Build();

var service = host.Services.GetRequiredService<Service>();

// comment out bellow to get expected behavior
var logger = host.Services.GetRequiredService<ILogger>();
logger.LogInformation("Starting lambda");

await LambdaBootstrapBuilder
    .Create(service.Handler, new DefaultLambdaJsonSerializer())
    .Build()
    .RunAsync();

public class Service
{
    private readonly ILogger _logger;

    public Service(ILogger logger)
    {
        _logger = logger;
    }

    public string Handler(ILambdaContext context)
    {
        var myMessage = new MyMessage("hello there!");
        _logger.LogInformation("This is a test message {@MyMessage}", myMessage);

        return "Hello world!";
    }

    private record MyMessage(string text);
}

Possible Solution

I believe this issue is related to the issue here.

Steps to Reproduce

• Deploy the code added above as a lambda.
• Invoke the lambda.
• Check CloudWatch logs.
• Comment out the code pulling the logger out of the DI container and logging on startup and redeploy the lambda.
• Invoke the lambda.
• Check cloud watch logs and messages should look as expected.

Powertools for AWS Lambda (.NET) version

AWS.Lambda.Powertools.Logging 2.0.0

AWS Lambda function runtime

dotnet8

Debugging logs

[boring-cyborg]

Thanks for opening your first issue here! We'll come back to you as soon as we can.
In the meantime, check out the #dotnet channel on our Powertools for AWS Lambda Discord: Invite link

[hjgraca]

Hi @j-d-ha thanks for opening the issue, I will look into this today

[j-d-ha]

I had a chance to try and debug this, and I think the issue might be that ConsoleWrapper.OverrideLambdaLogger() Needs to be called at least once during the first function invocation as well as once if logging during startup. In the current code here, it looks like ConsoleWrapper.OverrideLambdaLogger() can only ever be called on the first log call. I wonder if we could set a flag to determine if the log call is coming from the handler during the first invocation (cold start) and, if so, call ConsoleWrapper.OverrideLambdaLogger() again?

[hjgraca]

Hi @j-d-ha thanks for your investigation, and you are absolutely correct, the issue is on this line https://github.com/aws-powertools/powertools-lambda-dotnet/blob/develop/libraries/src/AWS.Lambda.Powertools.Common/Core/ConsoleWrapper.cs#L75 we only override once to avoid overriding again but with DI and eager loading outside the handler that will not work.

I have a fix that will push today, but can only release next Tuesday.

If you want to fix this today you can change the bootstrap to force and prevent lambda default logger to override your logger

await LambdaBootstrapBuilder
    .Create((context) =>
    {
        Console.SetOut(new StreamWriter(Console.OpenStandardOutput()) { AutoFlush = true });
        return service.Handler(context);
        
    }, new DefaultLambdaJsonSerializer())
    .Build()
    .RunAsync();

Let me know if that works for you.

[j-d-ha]

Awesome, I just tried this and it worked as expected! Thank you!

One other question that might be related to this (or my not, and if so, I am happy to create a new issue), I noticed in the API docs for AddPowertoolsLogger, it mentioned that it can be registered using the code below. Is this still supported in v2? I tried it while troubleshooting the other issue and ran into errors indicating that ILogger could not be found to be injected.

builder.Logging.AddPowertoolsLogger(options => 
{
    options.MinimumLogLevel = LogLevel.Information;
    options.LoggerOutputCase = LoggerOutputCase.PascalCase;
    options.IncludeLogLevel = true;
});

[hjgraca]

Awesome, I just tried this and it worked as expected! Thank you!

One other question that might be related to this (or my not, and if so, I am happy to create a new issue), I noticed in the API docs for AddPowertoolsLogger, it mentioned that it can be registered using the code below. Is this still supported in v2? I tried it while troubleshooting the other issue and ran into errors indicating that ILogger could not be found to be injected.

builder.Logging.AddPowertoolsLogger(options =>
{
options.MinimumLogLevel = LogLevel.Information;
options.LoggerOutputCase = LoggerOutputCase.PascalCase;
options.IncludeLogLevel = true;
});

@j-d-ha
Again good catch, I will add the missing code in the method

If you want to use it now just need to add

builder.Services.TryAddSingleton<ILogger>(provider =>
    provider.GetRequiredService<ILoggerFactory>().CreatePowertoolsLogger());

before the builder.Logging.AddPowertoolsLogger

builder.Services.TryAddSingleton<ILogger>(provider =>
    provider.GetRequiredService<ILoggerFactory>().CreatePowertoolsLogger());

builder.Logging.AddPowertoolsLogger(config =>
{
    config.Service = "TestService";
    config.LoggerOutputCase = LoggerOutputCase.PascalCase;
});

This will be fixed and released next Tuesday :)

If you have the time I would appreciate if you can create a new issue if not I will do it.
Thank you so much for reporting this.

[j-d-ha]

Awesome! Thank you! I will go ahead and create another issue as soon as I have a second.