Bug: Service property no longer uses the LoggingAttribute.Service name when the environment variable is provided

[nCubed]

Expected Behaviour

The root level service property of the logging output should be prioritized in this order:

1. LoggingAttribute.Service property value
2. POWERTOOLS_SERVICE_NAME environment variable

Current Behaviour

The root level service property of the logging output no longer prioritizes and uses the service name provided prior to the first log call.

Code snippet

// Each log entry is the value of the Root level service property when written to CloudWatch

// v1.5.1 behavior
Logger.LogInformation("Service: service_undefined");

Environment.SetEnvironmentVariable("POWERTOOLS_SERVICE_NAME", "Environment Service", EnvironmentVariableTarget.Process);

Logger.LogInformation("Service: Environment Service");

await LambdaBootstrapBuilder.Create((Func<string, ILambdaContext, Task<string>>)Handler, new DefaultLambdaJsonSerializer())
        .Build()
        .RunAsync();

[Logging(Service = "Attribute Service")]
async Task<string> Handler(string input, ILambdaContext context)
{
    Logger.LogInformation("Service: Attribute Service");

    return await Task.FromResult(input);
}


// v1.6.2 behavior - example 1
Logger.LogInformation("Service: service_undefined");

Environment.SetEnvironmentVariable("POWERTOOLS_SERVICE_NAME", "Environment Service", EnvironmentVariableTarget.Process);

Logger.LogInformation("Service: service_undefined");

await LambdaBootstrapBuilder.Create((Func<string, ILambdaContext, Task<string>>)Handler, new DefaultLambdaJsonSerializer())
        .Build()
        .RunAsync();

[Logging(Service = "Attribute Service")]
async Task<string> Handler(string input, ILambdaContext context)
{
    Logger.LogInformation("Service: service_undefined");

    return await Task.FromResult(input);
}


// v1.6.2 behavior - example 2
Environment.SetEnvironmentVariable("POWERTOOLS_SERVICE_NAME", "Environment Service", EnvironmentVariableTarget.Process);

Logger.LogInformation("Service: Environment Service");

await LambdaBootstrapBuilder.Create((Func<string, ILambdaContext, Task<string>>)Handler, new DefaultLambdaJsonSerializer())
        .Build()
        .RunAsync();

[Logging(Service = "Attribute Service")]
async Task<string> Handler(string input, ILambdaContext context)
{
    Logger.LogInformation("Service: Environment Service");

    return await Task.FromResult(input);
}


// v1.6.2 behavior - example 3
await LambdaBootstrapBuilder.Create((Func<string, ILambdaContext, Task<string>>)Handler, new DefaultLambdaJsonSerializer())
        .Build()
        .RunAsync();

[Logging(Service = "Attribute Service")]
async Task<string> Handler(string input, ILambdaContext context)
{
    Logger.LogInformation("Service: Attribute Service");

    return await Task.FromResult(input);
}

Possible Solution

Rollback to the v1.5.1 behavior.

Steps to Reproduce

Code snippet above provides all the steps to reproduce.

Powertools for AWS Lambda (.NET) version

1.6.2

AWS Lambda function runtime

dotnet8

Debugging logs

[hjgraca]

Hi @nCubed thanks for opening another issue, really appreciate taking the time to improve Powertools.
I am planning to release a fix for the second example next Tuesday (our release day).

As for your first example, the behaviour on version 1.5.1 is not correct.

Essentially in the first instantiation of Logging, the values present in the environment variables will be set and cached here so setting environment variables after this point wont change the properties.
This caching happens so you are not always calling the env variables and to be honest env variables are set and read on startup and stay immutable during execution

// This is the first instantiation of Logging, the values present in the environment variables will be set and cached here
// so setting environment variables after this point wont change the properties. 
// This caching happens so you are not always calling the env variables and to be honest env variables are set and read on startup and stay immutable during execution

Logger.LogInformation("Service: service_undefined");

Environment.SetEnvironmentVariable("POWERTOOLS_SERVICE_NAME", "Environment Service", EnvironmentVariableTarget.Process);

Logger.LogInformation("Service: service_undefined"); // this is correct. Logging will not query env again

await LambdaBootstrapBuilder.Create((Func<string, ILambdaContext, Task<string>>)Handler, new DefaultLambdaJsonSerializer())
        .Build()
        .RunAsync();

[Logging(Service = "Attribute Service")]
async Task<string> Handler(string input, ILambdaContext context)
{
    Logger.LogInformation("Service: service_undefined"); // This is not correct - should override the service with the one from the decorator

    return await Task.FromResult(input);
}

[nCubed]

As for your first example, the behaviour on version 1.5.1 is not correct.

Understood; however, that is the behavior of 1.5.1. We used 1.5.1 in production for a year and used that exact configuration where our start up prior to hitting the handler method used an env var to set the service. Once it hit the handler, the attribute set the service.

For whatever change you make, could you please provide some clearer documentation about the prioritization?

[hjgraca]

From you description that is the fix I am doing (example 2). If you there is a value on the env variable before the Logging is called it will use that value, but if there is a service defined in the handler, when calling Logging inside the handler and from there on, it will use the value set in the handler.

The wrong behaviour I was mentioning is related to calling Logging before there is an env variable set, this will cause the env variable to have a service_undefined and the Logging will log that, even if you add another env variable it will get the same service_undefined because it is now cached. But when it enters the handler with a service defined it will override by that service value.
Does that make sense?

[hjgraca]

For whatever change you make, could you please provide some clearer documentation about the prioritization?

Will do, I will add a specific section for the service pioritization.
The priority will be the same as LogLevel (which is already documented). Highest priority Service set in Handler and then Environment variable.

[nCubed]

From you description that is the fix I am doing (example 2). If you there is a value on the env variable before the Logging is called it will use that value, but if there is a service defined in the handler, when calling Logging inside the handler and from there on, it will use the value set in the handler.

This is the expected behavior, IMO.

[hjgraca]

Correct, that is the fix I am going to do and that is the expected behaviour.

The first example is the one that I was talking about that is currently correct behaviour. It should not change if the Logger is called before the env variable, it will stay service_undefined. (only changes when it gets override by the handler decorator)

Logger.LogInformation("Service: service_undefined");

Environment.SetEnvironmentVariable("POWERTOOLS_SERVICE_NAME", "Environment Service", EnvironmentVariableTarget.Process);

Logger.LogInformation("Service: service_undefined"); // this is correct. Logging will not query env again

[hjgraca]

Release 1.19

[hjgraca]

release Logging v1.6.4