Add parameterized logging support to ILambdaLogger

[dhhoang]

Issue #, if available: #1268

Description of changes: This PR adds supports for parameterized logging to ILambdaLogger interface. High-level design details are described in the issue mentioned above. Here I will mainly discuss implementation. This PR has a couple of // TODO sections which refers to areas where more inputs might be needed. All new changes are written for NET6_0_OR_GREATER target.

• LambdaLoggerExtensions class: exposes helper methods to make parameterized logging easier for users. This class also includes logic to process logging actions as described below.
• FormattedMessageEntry type: Encapsulates the values passed from log methods. This type initiates MessageFormatter class (with caching), which is responsible for parsing the the log format and returning the fully-formed message with MessageFormatter.Format().
• Another format Json is added to WrapperTextWriter. When this format is specified by user the output will be written as json.
• I also added the FormattedWriteEntry methods which handles all logs that are written using ILambdaLogger.LogEntry(). This method and FormattedWriteLine will handle all formats (default, unformatted, json) but the main difference is that FormattedWriteEntry will be able to output State and Exception passed by the user.

Testing: Existing tests passed. I added a net6.0 target to Amazon.Lambda.RuntimeSupport.UnitTests.csproj which might break an existing build set-up because now this test project will run against 2 target frameworks. Please let me know if there's any work needed to address this.
The new tests added are:

• LambdaLoggerExtensionsTests.cs: Tests the log syntax parsing/formatting behavior of the LambdaLoggerExtensions class.
• LogLevelLoggerWriterTest.cs: Tests the output behavior of ConsoleLoggerWriter for different types for log formats.
• Testing in Lambda environment: The following handler code

public void Handler(ILambdaContext lambdaContext)
{
    lambdaContext.Logger.Debug("this debug message shoud not appear");
    lambdaContext.Logger.Info("this should appear, parameter p1: {p1}, p2: {p2}, p3: {p3}", "demo message", true, DateTime.Now);
    try
    {
        int.Parse("invalid number");
    }
    catch (Exception ex)
    {
        lambdaContext.Logger.Error(ex, "error log should include exception");
    }
}

produces the following logs in Lambda's CloudWatch for Default format

and for Json format:

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

[normj]

Unfortunately you can not use Amazon.Lambda.Core.LogLevel inside Amazon.Lambda.RuntimeSupport. The Lambda function being executed is responsible for bringing in the version of Amazon.Lambda.Core and the function could be bring in an older version of Amazon.Lambda.Core that does not Amazon.Lambda.Core.LogLevel defined. In that scenario deploy Lambda functions would get type not found exception if this code got deploy to Lambda.

That is why this class takes in log level as a string converts the string to Amazon.Lambda.RuntimeSupport version of LogLevel.

[dhhoang]

Ok, so I've changed all the levels to be string, which will be parsed with Enum.TryParse when the log is written (same thing the existing logger is doing).

[normj]

We don't generally use InternalsVisibleToAttribute in our libraries because in our CI builds the assemblies get strong named which changes what value goes here. Our strong naming process is not something I like but for historical reasons it is where we are.

Our practice is for types that we want to treat as internal we put them in a namespace with the Internal suffix. Like Amazon.Lambda.Core.Internal.

[dhhoang]

I've removed this and re-worked the unit tests for LambdaLoggerExtensions. Now it will only test public methods. One downside is that we lost the test case for caching behavior of MessageFormatter instances since that class is internal.

I'm okay with not having that test case but if it's needed maybe the CI build can be changed to include am MSBuild property like <IsTest>true<IsTest> and the InternalsVisibleToAttribute can become conditional?

[normj]

Because of the disconnect to how Amazon.Lambda.RuntimeSupport and Amazon.Lambda.Core are deployed you have to provide a default implementation to this method.

If you look at how the LogInformation method was written it had a default implementation to the Log method that took in the log level as a string to avoid a dependency on the LogLevel type. Then the Log method has a default implementation to LogLine. In RuntimeSupport it implements only the Log method taking the string log level. So RuntimeSupport doesn't use the LogLevel type. That way if Amazon.Lambda.Core is deployed newer then RuntimeSupport it will still work forwarding to LogLine. If RuntimeSupport is newer then Amazon.Lambda.Core then function won't call any new methods and since you are relying on just the string representation of LogLevel it doesn't matter that the older Core didn't have LogLevel.

[dhhoang]

I've changed this to void LogEntry<TEntry>(string level, TEntry entry) => Log(level, entry.ToString());.

[normj]

Going to be another one of those challenging parts where you can't have RuntimeSupport use a new type on Lambda Core. Probably have to do something where the message entry also implement the IDictionary interface or something.

[dhhoang]

To work around this I've changed the implementation of FormattedMessageEntry. It is a IReadOnlyList<KeyValuePair<string, object>> with the first entry (index 0) being ["{Exception}"] = <log_exception>. The rest of the entries in that list are log name-value parameters. The log writer will recognize this magic string and renders the exception and state. This is the only way I can think of to avoid introducing new types in Amazon.Lambda.Core.

[dhhoang]

Based on feedbacks I've made the followings major changes:

• LogEntry now takes a string level and defaults to Log(string, string):

void LogEntry<TEntry>(string level, TEntry entry) => Log(level, entry.ToString());

• Public type IMessageEntry in Core is removed. Internal type FormattedMessageEntry now implements IReadOnlyList<KeyValuePair<string, object>> which has the first item being the log's attached exception.
• ConsoleLoggerWriter recognizes the IReadOnlyList<KeyValuePair<string, object>> implementation and write the logs accordingly.

[kaushik19]

This is one of the most awaiting feature, which will reduce multiple lines of code.

[Simonl9l]

Curious questions to what one would not just use https://learn.microsoft.com/en-us/dotnet/core/extensions/logger-message-generator ?

[dhhoang]

Curious questions to what one would not just use https://learn.microsoft.com/en-us/dotnet/core/extensions/logger-message-generator ?

Because we want to avoid introducing additional dependencies to Core as much as possible.

[Simonl9l]

@dhhoang I think you miss my point. Logging is an implementation detail and a separation of concerns than the core of the Lambda runtime.

At least outside of the Raw Lambda approach (i.e. when using Annotations or Minimal API .AddAWSLambdaHosting), why add conflation of scope to the Core when you can just as easily hook the Lambda login directly into the .Net logging with .AddLambdaLogger() as it stands today - one can then follow the instruction for the logger message generator that 1) handles your parameterized logging needs and 2) is code generated so it's efficient ?

I'd even suggest that the use cases for implementing Raw Lambda vs. using Annotation or Minimal API must be very small at this point.

if you are using Annotation Lambda:

public void ConfigureServices(IServiceCollection services)
{
     
    services
        .AddLogging(logging =>
        {
            logging.AddLambdaLogger();
            logging.SetMinimumLevel(LogLevel.Debug);
         });
        ....
}

If in Minimal API:

 public static async Task Main(string[] args)
    {
        var builder = WebApplication.CreateBuilder(args);
   
        builder.Services
            .AddAWSLambdaHosting(LambdaEventSource.RestApi)
            .AddDefaultAWSOptions(builder.Configuration.GetAWSOptions())
            .AddLogging(logging =>
            {
                logging.AddLambdaLogger();
            });

        var app = builder.Build();

        app.MapGet("/", () => "Welcome to running ASP.NET Core Minimal API on AWS Lambda");
      
        await app.RunAsync();
    }

You can then use partial classes or what ever to either DI the ILogger<MyClass> logger into the service/controller etc or pass the ILogger<MyCalss> around as needed and insert it as the first parameter in you well defined [LoggerMessage] generated functions per the docs as linked.

@normj - is this an approach you advocate too?

[TobbenTM]

@dhhoang @normj is this PR and related issues abandoned?

I was working on my own changes to the Amazon.Lambda.Logging.AspNetCore package to just serialize the state of ILogger<> logs and append it as a component being logged to console like the docs describe: https://docs.aws.amazon.com/lambda/latest/operatorguide/parse-logs.html
Compare here if interested: master...TobbenTM:aws-lambda-dotnet:structured-logging, it's not really tested in practice yet.

But I think this PR contains a more core change, which would also make my changes quite a bit simpler, wondering if we're getting structured logging from .Net lambdas at all any time soon?

[normj]

Closing because this work has been incorporated into this PR #1588. Thanks @dhhoang for implementing a lot the structured logging feature that I could easily lift into the new PR.