aws-lambda-dotnet
aws-lambda-dotnet copied to clipboard
aws
AspNetCoreServer default logging causes double-writes
Description
The default logging provided by Amazon.Lambda.AspNetCoreServer will cause double entries in CloudWatch. I would expect to see each log entry only once.
Reproduction Steps
Create an ASP.NET Core-based Lambda function using Amazon.Lambda.AspNetCoreServer, with minimal customization, and call it in a way that generates some log output. Observe that messages are logged twice.
Logs
Difficult to copy-and-paste out of CloudWatch, hopefully this screenshot illustrates the problem:
Environment
- Build Version: Amazon.Lambda.AspNetCoreServer v6.1.0
- OS Info: Amazon Linux (I assume? just using the default Lambda runtime)
- Build Environment: GitLab pipeline
- Targeted .NET Platform: netcoreapp3.1
Resolution
- [ ] :wave: I can/would-like-to implement a fix for this problem myself
I'd have to deal with my legal team to be able to contribute a solution, but it's probably safe for me to point to the problem. The AspNetCoreServer HostBuilderExtensions code (around line 39) adds loggers, but does not clear existing ones. Since AbstractAspNetCoreFunction calls CreateDefaultBuilder first, the console logger will always be present as part of the .NET defaults.
This is a :bug: bug-report
Hi @qidydl,
Thanks for posting the issue. Although the reproduction steps appear to be simple, would it be possible for you to share the sample code solution for reproduction?
Thanks, Ashish
@ashishdhingra I think I would need approval from our legal team to be able to share code publicly, but basically any ASP.NET Core application will do, including the example from dotnet new webapi. You can see from the screenshot that even default Microsoft logs will reproduce the problem, so there isn't any custom code required.
Hi @qidydl,
Good afternoon.
Could you please check if this is still an issue? I created ASP.NET Core Serverless Web App and added the following logging in Index page:
using Microsoft.AspNetCore.Mvc.RazorPages;
namespace TestServerlessDoubleLogWrite.Pages;
public class IndexModel : PageModel
{
private readonly ILogger<IndexModel> _logger;
public IndexModel(ILogger<IndexModel> logger)
{
_logger = logger;
}
public void OnGet()
{
_logger.LogInformation("Index page visited at {DT}",
DateTime.UtcNow.ToLongTimeString());
}
}
It did not generate duplicate logs:
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| timestamp | message |
|---------------|--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| 1665007564693 | 2022-10-05T22:06:04.686Z [Warning] Microsoft.AspNetCore.DataProtection.Repositories.EphemeralXmlRepository: Using an in-memory repository. Keys will not be persisted to storage. |
| 1665007564693 | 2022-10-05T22:06:04.693Z [Warning] Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager: Neither user profile nor HKLM registry available. Using an ephemeral key repository. Protected data will be unavailable when application exits. |
| 1665007564700 | 2022-10-05T22:06:04.700Z [Information] Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager: Creating key {c295ad7c-f51e-41fa-af20-1d327fca18a9} with creation date 2022-10-05 22:06:04Z, activation date 2022-10-05 22:06:04Z, and expiration date 2023-01-03 22:06:04Z. |
| 1665007564717 | 2022-10-05T22:06:04.717Z [Warning] Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager: No XML encryptor configured. Key {c295ad7c-f51e-41fa-af20-1d327fca18a9} may be persisted to storage in unencrypted form. |
| 1665007564803 | 2022-10-05T22:06:04.803Z [Information] Microsoft.Hosting.Lifetime: Application started. Press Ctrl+C to shut down. |
| 1665007564803 | 2022-10-05T22:06:04.803Z [Information] Microsoft.Hosting.Lifetime: Hosting environment: Production |
| 1665007564803 | 2022-10-05T22:06:04.803Z [Information] Microsoft.Hosting.Lifetime: Content root path: /var/task |
| 1665007564883 | START RequestId: e0b15dd2-da7b-457c-bed9-6c2c2171f18b Version: $LATEST |
| 1665007565057 | 2022-10-05T22:06:05.057Z e0b15dd2-da7b-457c-bed9-6c2c2171f18b [Information] Microsoft.AspNetCore.Hosting.Diagnostics: Request starting GET https://lp0wwv91g8.execute-api.us-east-2.amazonaws.com/Prod/ - 0 |
| 1665007565120 | 2022-10-05T22:06:05.120Z e0b15dd2-da7b-457c-bed9-6c2c2171f18b [Information] Microsoft.AspNetCore.Routing.EndpointMiddleware: Executing endpoint '/Index' |
| 1665007565177 | 2022-10-05T22:06:05.177Z e0b15dd2-da7b-457c-bed9-6c2c2171f18b [Information] Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker: Route matched with {page = "/Index"}. Executing page /Index |
| 1665007565199 | 2022-10-05T22:06:05.199Z e0b15dd2-da7b-457c-bed9-6c2c2171f18b [Information] Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker: Executing handler method TestServerlessDoubleLogWrite.Pages.IndexModel.OnGet - ModelState is Valid |
| 1665007565200 | 2022-10-05T22:06:05.200Z e0b15dd2-da7b-457c-bed9-6c2c2171f18b [Information] TestServerlessDoubleLogWrite.Pages.IndexModel: Index page visited at 10:06:05 PM |
| 1665007565200 | 2022-10-05T22:06:05.200Z e0b15dd2-da7b-457c-bed9-6c2c2171f18b [Information] Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker: Executed handler method OnGet, returned result . |
| 1665007565201 | 2022-10-05T22:06:05.201Z e0b15dd2-da7b-457c-bed9-6c2c2171f18b [Information] Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker: Executing an implicit handler method - ModelState is Valid |
| 1665007565201 | 2022-10-05T22:06:05.201Z e0b15dd2-da7b-457c-bed9-6c2c2171f18b [Information] Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker: Executed an implicit handler method, returned result Microsoft.AspNetCore.Mvc.RazorPages.PageResult. |
| 1665007565484 | 2022-10-05T22:06:05.484Z e0b15dd2-da7b-457c-bed9-6c2c2171f18b [Information] Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker: Executed page /Index in 304.4905ms |
| 1665007565484 | 2022-10-05T22:06:05.484Z e0b15dd2-da7b-457c-bed9-6c2c2171f18b [Information] Microsoft.AspNetCore.Routing.EndpointMiddleware: Executed endpoint '/Index' |
| 1665007565559 | 2022-10-05T22:06:05.559Z e0b15dd2-da7b-457c-bed9-6c2c2171f18b [Information] Microsoft.AspNetCore.Hosting.Diagnostics: Request finished GET https://lp0wwv91g8.execute-api.us-east-2.amazonaws.com/Prod/ - 0 - 200 - text/html;+charset=utf-8 519.2519ms |
| 1665007565599 | END RequestId: e0b15dd2-da7b-457c-bed9-6c2c2171f18b |
| 1665007565599 | REPORT RequestId: e0b15dd2-da7b-457c-bed9-6c2c2171f18b Duration: 715.66 ms Billed Duration: 716 ms Memory Size: 512 MB Max Memory Used: 102 MB Init Duration: 440.76 ms |
| 1665007565744 | START RequestId: 1f530b0e-86b2-4669-b69b-b5edb5b27849 Version: $LATEST |
| 1665007565745 | 2022-10-05T22:06:05.745Z 1f530b0e-86b2-4669-b69b-b5edb5b27849 [Information] Microsoft.AspNetCore.Hosting.Diagnostics: Request starting GET https://lp0wwv91g8.execute-api.us-east-2.amazonaws.com/Prod/css/site.min.css?v=kHvJwvVAK1eJLN4w8xygUR3nbvlLmRwi5yr-OuAO90E - 0 |
| 1665007565750 | 2022-10-05T22:06:05.750Z 1f530b0e-86b2-4669-b69b-b5edb5b27849 [Information] Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware: Sending file. Request path: '/css/site.min.css'. Physical path: '/var/task/wwwroot/css/site.min.css' |
| 1665007565750 | 2022-10-05T22:06:05.750Z 1f530b0e-86b2-4669-b69b-b5edb5b27849 [Information] Microsoft.AspNetCore.Hosting.Diagnostics: Request finished GET https://lp0wwv91g8.execute-api.us-east-2.amazonaws.com/Prod/css/site.min.css?v=kHvJwvVAK1eJLN4w8xygUR3nbvlLmRwi5yr-OuAO90E - 0 - 200 282 text/css 4.8531ms |
| 1665007565778 | END RequestId: 1f530b0e-86b2-4669-b69b-b5edb5b27849 |
| 1665007565778 | REPORT RequestId: 1f530b0e-86b2-4669-b69b-b5edb5b27849 Duration: 33.89 ms Billed Duration: 34 ms Memory Size: 512 MB Max Memory Used: 103 MB |
| 1665007565885 | START RequestId: c70c7866-2758-4f25-9bff-dd6b5ea5705a Version: $LATEST |
| 1665007565886 | 2022-10-05T22:06:05.886Z c70c7866-2758-4f25-9bff-dd6b5ea5705a [Information] Microsoft.AspNetCore.Hosting.Diagnostics: Request starting GET https://lp0wwv91g8.execute-api.us-east-2.amazonaws.com/Prod/js/site.min.js?v=47DEQpj8HBSa-_TImW-5JCeuQeRkm5NMpJWZG3hSuFU - 0 |
| 1665007565886 | 2022-10-05T22:06:05.886Z c70c7866-2758-4f25-9bff-dd6b5ea5705a [Information] Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware: Sending file. Request path: '/js/site.min.js'. Physical path: '/var/task/wwwroot/js/site.min.js' |
| 1665007565886 | 2022-10-05T22:06:05.886Z c70c7866-2758-4f25-9bff-dd6b5ea5705a [Information] Microsoft.AspNetCore.Hosting.Diagnostics: Request finished GET https://lp0wwv91g8.execute-api.us-east-2.amazonaws.com/Prod/js/site.min.js?v=47DEQpj8HBSa-_TImW-5JCeuQeRkm5NMpJWZG3hSuFU - 0 - 200 0 application/javascript 0.4259ms |
| 1665007565887 | END RequestId: c70c7866-2758-4f25-9bff-dd6b5ea5705a |
| 1665007565887 | REPORT RequestId: c70c7866-2758-4f25-9bff-dd6b5ea5705a Duration: 2.28 ms Billed Duration: 3 ms Memory Size: 512 MB Max Memory Used: 103 MB |
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Package used: Amazon.Lambda.AspNetCoreServer version 7.2.0
Target Framework: .NET 6.0
If this is still an issue with the latest version, please share the sample code solution for reproduction.
Thanks, Ashish
@ashishdhingra it looks like it was fixed by @normj in PR #1017, so I believe this issue can be closed now.
⚠️COMMENT VISIBILITY WARNING⚠️
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.
![github-actions[bot] avatar](https://avatars.githubusercontent.com/in/15368?v=4 "Published by a pub.dev verified publisher"){kind=small}