Amazon.Lambda.Logging.AspNetCore JSON logger crashes with ArgumentNullException when HttpLogging enabled

[Dreamescaper]

Describe the bug

When AspNetCore HttpLogging is enabled, LambdaLogger crashes with an exception.

Regression Issue

• Select this option if this issue appears to be a regression.

Expected Behavior

LambdaLogger manages to log everything what AspNetCore internals attempt to log.

Current Behavior

Logging fails with ArgumentNullException.

StackTrace:

        "System.AggregateException: An error occurred while writing to logger(s). (Value cannot be null. (Parameter 'key'))",
        "---> System.ArgumentNullException: Value cannot be null. (Parameter 'key')",
        "at System.ThrowHelper.ThrowArgumentNullException(String name)",
        "at System.Collections.Concurrent.ConcurrentDictionary`2.TryGetValue(TKey key, TValue& value)",
        "at Amazon.Lambda.RuntimeSupport.Helpers.Logging.AbstractLogMessageFormatter.ParseProperties(String messageTemplate)",
        "at Amazon.Lambda.RuntimeSupport.Helpers.Logging.JsonLogMessageFormatter.FormatMessage(MessageState state)",
        "at Amazon.Lambda.RuntimeSupport.Helpers.LogLevelLoggerWriter.WrapperTextWriter.FormattedWriteLine(String level, Exception exeception, String messageTemplate, Object[] args)",
        "at Amazon.Lambda.Core.LambdaLogger.Log(LogLevel level, Exception exception, String message, Object[] args)",
        "at Microsoft.Extensions.Logging.LambdaILogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)",
        "at Microsoft.Extensions.Logging.Logger.<Log>g__LoggerLog|14_0[TState](LogLevel logLevel, EventId eventId, ILogger logger, Exception exception, Func`3 formatter, List`1& exceptions, TState& state)",
        "--- End of inner exception stack trace ---",
        "at Microsoft.Extensions.Logging.Logger.ThrowLoggingError(List`1 exceptions)",
        "at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)",
        "at Microsoft.AspNetCore.HttpLogging.HttpLoggingExtensions.RequestLog(ILogger logger, HttpLog requestLog)",
        "at Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware.InvokeInternal(HttpContext context, HttpLoggingOptions options, HttpLoggingAttribute loggingAttribute, HttpLoggingFields loggingFields)",
        "at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.InterfaceMiddlewareBinder.<>c__DisplayClass2_0.<<CreateMiddleware>b__0>d.MoveNext()",
        "--- End of stack trace from previous location ---",
        "at Amazon.Lambda.AspNetCoreServer.AbstractAspNetCoreFunction`2.ProcessRequest(ILambdaContext lambdaContext, Object context, InvokeFeatures features, Boolean rethrowUnhandledError)"

Reproduction Steps

Use the following Program configuration.

var builder = WebApplication.CreateBuilder(args);

builder.Logging.AddLambdaLogger();

builder.Services.AddHttpLogging(_ => { });
builder.Services.AddAWSLambdaHosting(LambdaEventSource.HttpApi);

...

var app = builder.Build();
app.UseHttpLogging();

Attempt to invoke any endpoint.

Additional Information/Context

Seems like LambdaILogger does not handle the case when state has no "{OriginalFormat}" property.
https://github.com/aws/aws-lambda-dotnet/blob/master/Libraries/src/Amazon.Lambda.Logging.AspNetCore/LambdaILogger.cs#L73

HttpLogging, however, uses custom TState object, with custom formatter, it has no {OriginalFormat} property:
https://source.dot.net/#Microsoft.AspNetCore.HttpLogging/HttpLoggingExtensions.cs,c735f435f16b6645

AWS .NET SDK and/or Package version used

Amazon.Lambda.Logging.AspNetCore 4.1.0

Targeted .NET Platform

.NET 8

Operating System and version

AmazonLinux

[Dreamescaper]

For context, here's how this log entry looks with JsonConsole Logger:

{
    "EventId": 1,
    "LogLevel": "Information",
    "Category": "Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware",
    "Message": "Request:\nProtocol: \nMethod: GET\nScheme: https\nPathBase: \nPath: /health\nsec-fetch-mode: [Redacted]\nx-amzn-tls-cipher-suite: [Redacted]\nx-amzn-tls-version: [Redacted]\nx-amzn-trace-id: [Redacted]\naccept-language: *\nx-forwarded-proto: [Redacted]\nhost: ullnvs2xzd3uw2nrnjh24mwjfe0ivdiw.lambda-url.eu-central-1.on.aws\nx-forwarded-port: [Redacted]\nx-forwarded-for: [Redacted]\naccept-encoding: br, gzip, deflate\nuser-agent: node\naccept: */*\nContent-Length: 0",
    "State": {
        "Message": "Request:\nProtocol: \nMethod: GET\nScheme: https\nPathBase: \nPath: /health\nsec-fetch-mode: [Redacted]\nx-amzn-tls-cipher-suite: [Redacted]\nx-amzn-tls-version: [Redacted]\nx-amzn-trace-id: [Redacted]\naccept-language: *\nx-forwarded-proto: [Redacted]\nhost: blalbls2xzd3uw2nrnjh24mwjfe0ivdiw.lambda-url.eu-central-1.on.aws\nx-forwarded-port: [Redacted]\nx-forwarded-for: [Redacted]\naccept-encoding: br, gzip, deflate\nuser-agent: node\naccept: */*\nContent-Length: 0",
        "Protocol": null,
        "Method": "GET",
        "Scheme": "https",
        "PathBase": "",
        "Path": "/health",
        "sec-fetch-mode": "[Redacted]",
        "x-amzn-tls-cipher-suite": "[Redacted]",
        "x-amzn-tls-version": "[Redacted]",
        "x-amzn-trace-id": "[Redacted]",
        "accept-language": "*",
        "x-forwarded-proto": "[Redacted]",
        "host": "blalbls2xzd3uw2nrnjh24mwjfe0ivdiw.lambda-url.eu-central-1.on.aws",
        "x-forwarded-port": "[Redacted]",
        "x-forwarded-for": "[Redacted]",
        "accept-encoding": "br, gzip, deflate",
        "user-agent": "node",
        "accept": "*/*",
        "Content-Length": "0"
    }
}

[GarrettBeatty]

was able to reproduce this error (without running on lambda) by creating the following test

using Amazon.Lambda.AspNetCoreServer.Hosting;
using Amazon.Lambda.RuntimeSupport.Helpers.Logging;
using Amazon.Lambda.RuntimeSupport.Helpers;

Environment.SetEnvironmentVariable("AWS_LAMBDA_LOG_FORMAT", "JSON");

// Test the JsonLogMessageFormatter bug directly
TestJsonFormatterBug();



static void TestJsonFormatterBug()
{
    Console.WriteLine("===========================================");
    Console.WriteLine("Testing JsonLogMessageFormatter bug reproduction...");
    Console.WriteLine("===========================================");
    
    var formatter = new JsonLogMessageFormatter();
    
    // Create MessageState that simulates the HttpLogging bug condition
    var messageState = new MessageState
    {
        MessageTemplate = null,  // This is the bug - missing {OriginalFormat}
        MessageArguments = new object[] { "arg1", "arg2" },  // Non-empty triggers ParseProperties
        Level = LogLevelLoggerWriter.LogLevel.Information,
        TimeStamp = DateTime.UtcNow,
        AwsRequestId = "test-request-id"
    };
    
    Console.WriteLine($"MessageTemplate: {messageState.MessageTemplate ?? "null"}");
    Console.WriteLine($"MessageArguments Length: {messageState.MessageArguments?.Length}");
    Console.WriteLine("Calling JsonLogMessageFormatter.FormatMessage()...");
    
    try 
    {
        // This should crash with ArgumentNullException in ParseProperties
        var result = formatter.FormatMessage(messageState);
        Console.WriteLine("❌ Bug NOT reproduced - no exception thrown");
        Console.WriteLine($"Result: {result}");
    }
    catch (ArgumentNullException ex) when (ex.ParamName == "key")
    {
        Console.WriteLine("✅ BUG REPRODUCED! ArgumentNullException in ParseProperties");
        Console.WriteLine($"Exception: {ex.Message}");
        Console.WriteLine($"Stack trace: {ex.StackTrace}");
    }
    catch (Exception ex)
    {
        Console.WriteLine($"❓ Different exception occurred: {ex.GetType().Name}");
        Console.WriteLine($"Message: {ex.Message}");
        Console.WriteLine($"Stack trace: {ex.StackTrace}");
    }
    
    Console.WriteLine("===========================================");
    Console.WriteLine("Test completed. Starting web application...");
    Console.WriteLine("===========================================");
}

will take a look at the potential fix

[normj]

@Dreamescaper I put out a PR to fix the issue.

If you were curious and my subtle way for pushing our .NET Aspire integration I was able to reproduce this through the ASP.NET Core Bridge using the following Aspire AppHost.

#pragma warning disable CA2252

var builder = DistributedApplication.CreateBuilder(args);

var function = builder.AddAWSLambdaFunction<Projects.AspNetCoreLoggingRepo>("WebApp", lambdaHandler: "AspNetCoreLoggingRepo", options: new Aspire.Hosting.AWS.Lambda.LambdaFunctionOptions
{
    LogFormat = Amazon.Lambda.LogFormat.JSON
});

builder.AddAWSAPIGatewayEmulator("gateway", Aspire.Hosting.AWS.Lambda.APIGatewayType.Rest)
    .WithReference(function, Aspire.Hosting.AWS.Lambda.Method.Any, "/{proxy+}")
    .WithReference(function, Aspire.Hosting.AWS.Lambda.Method.Any, "/");

builder.Build().Run();

[normj]

Version 4.1.1 of Amazon.Lambda.Logging.AspNetCore is out that fixes null pointer issue.

[github-actions]

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.