powertools-lambda-dotnet icon indicating copy to clipboard operation
powertools-lambda-dotnet copied to clipboard

Bug: Logger not threadsafe across multiple parallel test classes

Open samrobley opened this issue 8 months ago • 2 comments

Expected Behaviour

Run until failure completes without failure

Current Behaviour

Random failures after anywhere from 1 to 10 test runs

    Message: 
System.AggregateException : One or more errors occurred. (An item with the same key has already been added. Key: ColdStart)
---- System.ArgumentException : An item with the same key has already been added. Key: ColdStart

    Stack Trace: 
Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
Task`1.GetResultCore(Boolean waitCompletionNotification)
UnitTest2.Test2() line 24
RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)
----- Inner Stack Trace -----
Dictionary`2.TryInsert(TKey key, TValue value, InsertionBehavior behavior)
Dictionary`2.Add(TKey key, TValue value)
Logger.AppendKey(String key, Object value)
LoggingAspectHandler.OnEntry(AspectEventArgs eventArgs)
MethodAspectAttribute.WrapAsync[T](Func`2 target, Object[] args, AspectEventArgs eventArgs)

Code snippet

using Amazon.Lambda.CloudWatchEvents;
using Amazon.Lambda.CloudWatchEvents.S3Events;
using Amazon.Lambda.Core;
using Amazon.Lambda.TestUtilities;
using AWS.Lambda.Powertools.Logging;
using FluentAssertions;
using Xunit;

namespace TestProject1;

public class Function
{
    public Function()
    {
    }

    [Logging(Service = "TestExample")]
    // cloudwatch s3 eventbridge event
    public async Task<bool> Invoke(CloudWatchEvent<S3ObjectCreate> cloudWatchEvent, ILambdaContext context)
    {
        Logger.LogInformation("Processing S3 event");
        return true;
    }
}

public class UnitTest1
{
    [Fact]
    public void Test1()
    {
        // Arrange
        Function function = new Function();
        CloudWatchEvent<S3ObjectCreate> cloudWatchEvent = new CloudWatchEvent<S3ObjectCreate>();
        var context = new TestLambdaContext();

        // Act
        var response = function.Invoke(cloudWatchEvent, context);

        // Assert
        response.Result.Should().BeTrue();
    }
}

public class UnitTest2
{
    [Fact]
    public void Test2()
    {
        // Arrange
        Function function = new Function();
        CloudWatchEvent<S3ObjectCreate> cloudWatchEvent = new CloudWatchEvent<S3ObjectCreate>();
        var context = new TestLambdaContext();

        // Act
        var response = function.Invoke(cloudWatchEvent, context);

        // Assert
        response.Result.Should().BeTrue();
    }
}

Possible Solution

Noted a similar issue cropped up with the Python lambda powertools append keys: [https://github.com/aws-powertools/powertools-lambda-python/issues/2040]

Steps to Reproduce

This is re-producible with the code snippet above.

The workaround is to decorate the classes with: [Collection("Sequential")]

Powertools for AWS Lambda (.NET) version

latest

AWS Lambda function runtime

dotnet6

Debugging logs

Message: 
System.AggregateException : One or more errors occurred. (An item with the same key has already been added. Key: ColdStart)
---- System.ArgumentException : An item with the same key has already been added. Key: ColdStart

    Stack Trace: 
Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
Task`1.GetResultCore(Boolean waitCompletionNotification)
UnitTest2.Test2() line 59
RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)
----- Inner Stack Trace -----
Dictionary`2.TryInsert(TKey key, TValue value, InsertionBehavior behavior)
Dictionary`2.Add(TKey key, TValue value)
Logger.AppendKey(String key, Object value)
LoggingAspectHandler.OnEntry(AspectEventArgs eventArgs)
MethodAspectAttribute.WrapAsync[T](Func`2 target, Object[] args, AspectEventArgs eventArgs)

samrobley avatar Jun 19 '24 02:06 samrobley