Bug: Logging casing affects nested object properties

[sliedig]

Expected Behaviour

Logger should respect the casing of the of the object it logs, irrespective of the POWERTOOLS_LOGGER_CASE configuration. In the following example, the logging attribute logs the Amazon.Lambda.SQSEvents.SQSEvent. In this instance the POWERTOOLS_LOGGER_CASE setting is not defined and defaults to snake case (the current default setting, see docs).

    [Logging(LogEvent = true)]
    [Metrics(CaptureColdStart = true)]
    [Tracing(CaptureMode = TracingCaptureMode.ResponseAndError)]
    public async Task<string> FunctionHandler(SQSEvent sqsEvent, ILambdaContext context)
    {
        // implementation......
    }

The log output should be.

{
  "cold_start": true,
  "xray_trace_id": "1-64f2e834-b9df67f7a705145c59f8092f",
  "function_name": "uni-prop-local-contract-ContractEventHandlerFuncti-PSkd9CKrYlRh",
  "function_version": "$LATEST",
  "function_memory_size": 512,
  "function_arn": "arn:aws:lambda:ap-southeast-2:538510314095:function:uni-prop-local-contract-ContractEventHandlerFuncti-PSkd9CKrYlRh",
  "function_request_id": "12579e8a-9950-5bc2-bb7e-c3e67320b537",
  "timestamp": "2023-09-02T07:45:57.5637679Z",
  "level": "Information",
  "service": "unicorn.contracts",
  "name": "AWS.Lambda.Powertools.Logging.Logger",
  "message": {
    "Records": [
      {
        "MessageId": "17ac62a8-0ae4-4b7c-aeed-c602004a736b",
        "ReceiptHandle": "AQEB9CXbbsl59Im3MAetnLq7NAOSSFCCp/MHFdKf9Ft7u0OctJa6+PDbVSVDV6fdvbyPQ/P2wmXZADZ2W2D0HHId1jZp9xhfY+XDndOSdl5x6rX0g4Iqa4EL1VHP5OzpJoBZ+tZOGkO3cjorTv6LNCeEZlHNPGrIq7SMiATIV9qpirUj/Y3Grb92Hi+UDfk03zZ4B9FvSOXMUVtNnZBNr8BGgrLDHfZpfh1+4yp7Gu+I9uhLwZzlKo4jkx3NZX+LsRgE8Jpq61LUumSkbVWNujnD9WokOlx3GrqD7qNh7byvAfu++gesrNhhhX9Q7pCahcyUkKe0iRCuv+bSczMxD07mrscpRoMcb93DdtJh59jn8rFfuV4GYNSqYHEdVuoBZg6qbN2XF0EiK8EMXThB5UiUmKkMje0TLbGKYor/bP4kfK0=",
        "Body": "{\n\"address\": {\n\"country\": \"USA\",\n\"city\": \"Anytown\",\n\"street\": \"Main Street\",\n\"number\": 222\n},\n\"seller_name\": \"John Doe\",\n\"property_id\": \"usa/anytown/main-street/333\"\n}",
        "Md5OfBody": "95cf13afcccc87caed66de64b2c28f0b",
        "Md5OfMessageAttributes": "b51fb21666798a04bb45833ff6dc08ad",
        "EventSourceArn": "arn:aws:sqs:ap-southeast-2:538510314095:UnicornContractsIngestQueue-Local",
        "EventSource": "aws:sqs",
        "AwsRegion": "ap-southeast-2",
        "Attributes": {
          "ApproximateReceiveCount": "1",
          "AWSTraceHeader": "Root=1-64f2e929-78c8c8f13605d20d170afacd;Parent=3b94c8aa1aee62e6;Sampled=1",
          "SentTimestamp": "1693641001436",
          "SenderId": "AROAX2YNXJJX23OWVT6JY:BackplaneAssumeRoleSession",
          "ApproximateFirstReceiveTimestamp": "1693641001446"
        },
        "MessageAttributes": {
          "HttpMethod": {
            "StringValue": "POST",
            "BinaryValue": null,
            "StringListValues": [],
            "BinaryListValues": [],
            "DataType": "String"
          }
        }
      }
    ]
  },
  "sampling_rate": 0
}

Current Behaviour

By default, if you apply the above example, the output would look like this - everything snake case.

{
  "cold_start": true,
  "xray_trace_id": "1-64f2e834-b9df67f7a705145c59f8092f",
  "function_name": "uni-prop-local-contract-ContractEventHandlerFuncti-PSkd9CKrYlRh",
  "function_version": "$LATEST",
  "function_memory_size": 512,
  "function_arn": "arn:aws:lambda:ap-southeast-2:538510314095:function:uni-prop-local-contract-ContractEventHandlerFuncti-PSkd9CKrYlRh",
  "function_request_id": "12579e8a-9950-5bc2-bb7e-c3e67320b537",
  "timestamp": "2023-09-02T07:45:57.5637679Z",
  "level": "Information",
  "service": "unicorn.contracts",
  "name": "AWS.Lambda.Powertools.Logging.Logger",
  "message": {
    "records": [
      {
        "message_id": "4bdc3703-d801-41a6-8e1a-f2c066692bc7",
        "receipt_handle": "AQEBA6PRPusqsS9CPajNcTosKxsRPPvx70RnB/bQ2vjfjolv2zS5Icic3p2dVJLVig0GmKMg/fLb2piFe2GyJ/ylRFJIDho7r1as5DnQkIFhtpENDuBuNpMrVzw+1//xSJ2BFoNbh6RP50GB7hjcgyYuQ8zcrgceKHctrey9OG5bsyWrgzHFA1IUK9yS7mw1lSyOgizLPL4KScXv+sAeu0M8sZNihRpPR0Tv/8kRoaj40veVEllLcp9sbwt+A0RH+BIWBiLHl6yU51TqpRs99njCKUDXOnpiS9462Myz4mmOhzHRM4BkBY040+WZJ9mpLOaeOrlUFQDcCFw4AIz/HJqo3BpjAVW5UOHqq52dKCRvHmXgfC0IwgG//sepwz0+9etQffIaI9lnGdjQvQbCqdSYRGo80JY48uXZV1Te4MJETYI=",
        "body": "{\n\"address\": {\n\"country\": \"USA\",\n\"city\": \"Anytown\",\n\"street\": \"Main Street\",\n\"number\": 222\n},\n\"seller_name\": \"John Doe\",\n\"property_id\": \"usa/anytown/main-street/333\"\n}",
        "md5_of_body": "95cf13afcccc87caed66de64b2c28f0b",
        "md5_of_message_attributes": "b51fb21666798a04bb45833ff6dc08ad",
        "event_source_arn": "arn:aws:sqs:ap-southeast-2:538510314095:UnicornContractsIngestQueue-Local",
        "event_source": "aws:sqs",
        "aws_region": "ap-southeast-2",
        "attributes": {
          "approximate_receive_count": "1",
          "a_w_s_trace_header": "Root=1-64f2e834-3c0e93736f6ba2b20d753ed1;Parent=71052d679694decd;Sampled=1",
          "sent_timestamp": "1693640756520",
          "sender_id": "AROAX2YNXJJX23OWVT6JY:BackplaneAssumeRoleSession",
          "approximate_first_receive_timestamp": "1693640756527"
        },
        "message_attributes": {
          "http_method": {
            "string_value": "POST",
            "binary_value": null,
            "string_list_values": [],
            "binary_list_values": [],
            "data_type": "String"
          }
        }
      }
    ]
  },
  "sampling_rate": 0
}

Similarly, if you define POWERTOOLS_LOGGER_CASE as camel case, you get:

{
  "coldStart": true,
  "xrayTraceId": "1-64f300a1-3c412c94f3f0f78886a83a0a",
  "functionName": "uni-prop-local-contract-ContractEventHandlerFuncti-PSkd9CKrYlRh",
  "functionVersion": "$LATEST",
  "functionMemorySize": 512,
  "functionArn": "arn:aws:lambda:ap-southeast-2:538510314095:function:uni-prop-local-contract-ContractEventHandlerFuncti-PSkd9CKrYlRh",
  "functionRequestId": "a11d70c2-4eb7-5dec-a145-2daf4c6d124a",
  "timestamp": "2023-09-02T09:30:10.1436179Z",
  "level": "Information",
  "service": "unicorn.contracts",
  "name": "AWS.Lambda.Powertools.Logging.Logger",
  "message": {
    "records": [
      {
        "messageId": "856aa859-d1c7-4121-b408-30a2d9abff10",
        "receiptHandle": "AQEBCR9KN558uxQYXnPjSsOR4fRcPCXSNDXX3l3cMLw+UrG9sFg0LzfYq6shPAXQUkEfRIJjiR7tSyx7psLKINdqaUxACBbJXnSKu7OfH7EsAxq7K2cZ0FN8LBnR6HvQeWxwcR7YSnS8OSaeI3P5D5Q6DwTq6MSxnS4DyG/8WODa4oBsLBfUz9hWLNVFf7aQqE1yXhltpNr2HVKkRRnchivfviYjDL7dMZoBYLuBAH+us+HI18v7PCRvJ7Fwlg4oeLLW6uQd7hREyMBSUVr9st//HSQM7CifsSAmroLqveCIrUEIgRcu0dsShPGwkj6bNrD5K0WYRczZSlkgCb9ZG6HeM0oBh5LQk2Ak+IhAD8urWVXbZruIojm7XMwbTXVI1AZOq/zVvczv9Qb4UB/d9OsiEETSr1Rg2sZoGQIK31Ibqn4=",
        "body": "{\n\"address\": {\n\"country\": \"USA\",\n\"city\": \"Anytown\",\n\"street\": \"Main Street\",\n\"number\": 222\n},\n\"seller_name\": \"John Doe\",\n\"property_id\": \"usa/anytown/main-street/333\"\n}",
        "md5OfBody": "95cf13afcccc87caed66de64b2c28f0b",
        "md5OfMessageAttributes": "b51fb21666798a04bb45833ff6dc08ad",
        "eventSourceArn": "arn:aws:sqs:ap-southeast-2:538510314095:UnicornContractsIngestQueue-Local",
        "eventSource": "aws:sqs",
        "awsRegion": "ap-southeast-2",
        "attributes": {
          "approximateReceiveCount": "1",
          "awsTraceHeader": "Root=1-64f300a0-75746f3e2832451e1720a3d7;Parent=20b56946b0a910a5;Sampled=1",
          "sentTimestamp": "1693647009037",
          "senderId": "AROAX2YNXJJX23OWVT6JY:BackplaneAssumeRoleSession",
          "approximateFirstReceiveTimestamp": "1693647009046"
        },
        "messageAttributes": {
          "httpMethod": {
            "stringValue": "POST",
            "binaryValue": null,
            "stringListValues": [],
            "binaryListValues": [],
            "dataType": "String"
          }
        }
      }
    ]
  },
  "samplingRate": 0
}

In both cases, this is a misrepresentation of the definition of the SQSEvent class.

Code snippet

Already provide above

Possible Solution

Two recommendations:

1. Do not apply key casing conventions to nested objects. Keep the property definition of the original object. Apply casing configuration to top-level keys only. This includes all extra keys, but not the values of the extra keys.

2. Make Pascal case the default casing for all keys. This is the default casing for .NET and should be an opt-out if users want something different, rather than it being an opt in.

Steps to Reproduce

Do nothing. Or change the POWERTOOLS_LOGGER_CASE to CamelCase

Powertools for AWS Lambda (.NET) version

latest

AWS Lambda function runtime

dotnet6

Debugging logs

No response

[hjgraca]

@sliedig update on this, other runtimes are only changing the casing on powertools added properties, so we can do your solution 1 but only for powertools properties.

[hjgraca]

Team decision log

• Apply casing to all first level keys except when advanced logging is enabled
• What is the impact on users querying with custom casing?
• Default casing change to Pascal for Logger v2

[nCubed]

With the proposed update, will the output logging represent example 1 or 2 when the output logging is set to snake_case?

Logging Input

Logger.LogInformation(new
{
    topic = "Requesting new order.",
    uriPart,
    CreateOrderRequest = req,
    RequestJson = http.json,
    client.DefaultRequestHeaders
});

Output Example 1

{
  "cold_start": true,
  "xray_trace_id": "1-64f2e834-b9df67f7a705145c59f8092f",
  "function_name": "my-function",
  "function_version": "$LATEST",
  "function_memory_size": 512,
  "name": "AWS.Lambda.Powertools.Logging.Logger",
  "message": {
    "topic": "Requesting new order.",
    "uriPart": "/foo/bar/orders",
    "CreateOrderRequest": {
      "SourceKey": "3d7432696a88a9ff201b356d5ff4f058",
      "SourceType": "customer"
    },
    "RequestJson": "{ some json }",
    "DefaultRequestHeaders": [
        "key": "value"
    ]
  }
}

Output Example 2

{
  "cold_start": true,
  "xray_trace_id": "1-64f2e834-b9df67f7a705145c59f8092f",
  "function_name": "my-function",
  "function_version": "$LATEST",
  "function_memory_size": 512,
  "name": "AWS.Lambda.Powertools.Logging.Logger",
  "message": {
    "topic": "Requesting new order.",
    "uri_part": "/foo/bar/orders",
    "create_order_request": {
      "source_key": "3d7432696a88a9ff201b356d5ff4f058",
      "source_type": "customer"
    },
    "request_json": "{ some json }",
    "default_request_headers": [
        "key": "value"
    ]
  }
}

[hjgraca]

@nCubed from my understanding, the message will not be affected by the casing defined in Powertools, so it would be as shown in your output example 1.

[nCubed]

@hjgraca - If the output will be like Example 1, then this would be a major breaking change in the current behavior. I would strongly encourage this behavior not be changed by default.

How about allowing consumers to "opt-out" of having the message property being included? This would maintain current behavior and allow consumers to decide if they really want the message property to be excluded.

[hjgraca]

@nCubed thank you for your feedback.
You are 100% correct, this issue is marked as v2 since it has breaking changes.
We don't want to break any existing customers and also this issue is still under discussion about the approach but will be behind a config flag, either "enable_old_behaviour" or "enable_new_behaviour".

PS: in terms of comparison with other runtimes, .NET is the only one that allows for case configuration, which is something that is good and bad, so something to consider here as well to just have all runtimes with the same case. again up for discussion.

[hjgraca]

This is now possible with version 2 of Logging which now supports JsonSerializerOptions

We kept the existing behaviour the same for backwards compatibility.
if you want to prevent the properties to change you will need to set the DictionaryKeyPolicy to null.

builder.Logging.AddPowertoolsLogger(options => 
{
    options.JsonOptions = new JsonSerializerOptions
    {
        DictionaryKeyPolicy = null // Override output casing
    };
});