LAMBDA_NET_SERIALIZER_DEBUG not working JSON log format

[martincostello]

Describe the bug

I've been trying to diagnose an issue I'm getting with trying to use JSON polymorphism with .NET 9 and AoT in a Lambda function, and in the process it seems that LAMBDA_NET_SERIALIZER_DEBUG doesn't work when a Lambda function is configured to log as JSON instead of text.

My guess would be that CloudWatch is expecting the Console.WriteLine() calls to be in a certain format, and then when they aren't silently drops them.

Regression Issue

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

Expected Behavior

Output when LAMBDA_NET_SERIALIZER_DEBUG=true appears in CloudWatch logs.

Current Behavior

Output is missing from CloudWatch logs.

Reproduction Steps

Set LAMBDA_NET_SERIALIZER_DEBUG=true for a C# Lambda function that is configured to use JSON logs.

Possible Solution

Detect that JSON logging is configured and output to the console in a manner that does not got broken by the JSON content of the payloads being logged.

Additional Information/Context

No response

AWS .NET SDK and/or Package version used

Amazon.Lambda.RuntimeSupport 1.11.0

Targeted .NET Platform

.NET 9

Operating System and version

Amazon Linux 2023

[normj]

From my testing I see the debug log messages showing up in the log message with JSON as the log format with and without AOT. The messages come out as info log messages, what is the log level set for the functions.

9/12/2024 11:46:41 PM	{"timestamp":"2024-09-13T06:46:41.673Z","level":"Information","requestId":"51d04207-ef17-4198-8728-a0eae21069b0","traceId":"Root=1-66e3dfd1-029870525ed473b817cb38e3;Parent=63df23911fe7d599;Sampled=0;Lineage=1:c17fdfdf:0","message":"Lambda Deserialize Amazon.Lambda.APIGatewayEvents.APIGatewayHttpApiV2ProxyRequest: {\u0022version\u0022:\u00222.0\u0022,\u0022routeKey\u0022:\u0022ANY /{proxy\u002B}\u0022,\u0022rawPath\u0022:\u0022/favicon.ico\u0022,\u0022rawQueryString\u0022:\u0022\u0022,\u0022headers\u0022:{\u0022accept\u0022:\u0022image/avif,image/webp,image/apng,image/svg\u002Bxml,image/*,*/*;q=0.8\u0022,\u0022accept-encoding\u0022:\u0022gzip, deflate, br, zstd\u0022,\u0022accept-language\u0022:\u0022en-US,en;q=0.9\u0022,\u0022content-length\u0022:\u00220\u0022,\u0022host\u0022:\u0022sn9fj139i8.execute-api.us-west-2.amazonaws.com\u0022,\u0022priority\u0022:\u0022u=1, i\u0022,\u0022referer\u0022:\u0022https://sn9fj139i8.execute-api.us-west-2.amazonaws.com/\u0022,\u0022sec-ch-ua\u0022:\u0022\\\u0022Chromium\\\u0022;v=\\\u0022128\\\u0022, \\\u0022Not;A=Brand\\\u0022;v=\\\u002224\\\u0022, \\\u0022Google Chrome\\\u0022;v=\\\u0022128\\\u0022\u0022,\u0022sec-ch-ua-mobile\u0022:\u0022?0\u0022,\u0022sec-ch-ua-platform\u0022:\u0022\\\u0022Windows\\\u0022\u0022,\u0022sec-fetch-dest\u0022:\u0022image\u0022,\u0022sec-fetch-mode\u0022:\u0022no-cors\u0022,\u0022sec-fetch-site\u0022:\u0022same-origin\u0022,\u0022user-agent\u0022:\u0022Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36\u0022,\u0022x-amzn-trace-id\u0022:\u0022Root=1-66e3dfd1-6e0fbda451792655447cc145\u0022,\u0022x-forwarded-for\u0022:\u002250.35.61.49\u0022,\u0022x-forwarded-port\u0022:\u0022443\u0022,\u0022x-forwarded-proto\u0022:\u0022https\u0022},\u0022requestContext\u0022:{\u0022accountId\u0022:\u0022626492997873\u0022,\u0022apiId\u0022:\u0022sn9fj139i8\u0022,\u0022domainName\u0022:\u0022sn9fj139i8.execute-api.us-west-2.amazonaws.com\u0022,\u0022domainPrefix\u0022:\u0022sn9fj139i8\u0022,\u0022http\u0022:{\u0022method\u0022:\u0022GET\u0022,\u0022path\u0022:\u0022/favicon.ico\u0022,\u0022protocol\u0022:\u0022HTTP/1.1\u0022,\u0022sourceIp\u0022:\u002250.35.61.49\u0022,\u0022userAgent\u0022:\u0022Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36\u0022},\u0022requestId\u0022:\u0022eB_oziNXvHcEMGw=\u0022,\u0022routeKey\u0022:\u0022ANY /{proxy\u002B}\u0022,\u0022stage\u0022:\u0022$default\u0022,\u0022time\u0022:\u002213/Sep/2024:06:46:41 \u002B0000\u0022,\u0022timeEpoch\u0022:1726210001648},\u0022pathParameters\u0022:{\u0022proxy\u0022:\u0022favicon.ico\u0022},\u0022isBase64Encoded\u0022:false}"}

...

9/12/2024 11:46:41 PM	{"timestamp":"2024-09-13T06:46:41.673Z","level":"Information","requestId":"51d04207-ef17-4198-8728-a0eae21069b0","traceId":"Root=1-66e3dfd1-029870525ed473b817cb38e3;Parent=63df23911fe7d599;Sampled=0;Lineage=1:c17fdfdf:0","message":"Lambda Serialize Amazon.Lambda.APIGatewayEvents.APIGatewayHttpApiV2ProxyResponse: {\u0022statusCode\u0022:200,\u0022headers\u0022:{\u0022Content-Type\u0022:\u0022text/plain\u0022},\u0022body\u0022:\u0022Hello World\u0022,\u0022isBase64Encoded\u0022:false}"}

[martincostello]

Hmm. I'll have another look today, but didn't seem to be getting anything until I switched back to Text. I tried turning things up as far as Trace too.

[martincostello]

what is the log level set for the functions.

Just doing some more testing now, but these are my default settings:

[martincostello]

Yeah, sorry, this was down to me forgetting I'd reworked my Lambda deployment setup.

It used to be that I didn't set the environment variables on deployment. I changed this at some point in the last year (I think it was for the SSL_CERT_FILE=/tmp/noop changes) so that each re-deploy sets the environment variables. This meant that during my debug cycle for the issue I was having, my manual setting of LAMBDA_NET_SERIALIZER_DEBUG=true got unset and I didn't notice amidst the weirdness I was trying to debug 😅 (dotnet/runtime#107740 if you're interested).

It's also possible I missed it amongst the platform-level events (the ones that have time):

[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.