Aspnetcore: Logs at INFO, should be DEBUG level

[WhatFreshHellIsThis]

asp.net 2.0 is logging items at INFO level which it should not. It should be DEBUG or even TRACE.
Many developers are asking how to turn off the built in logging due to the excessive nature of it at such a high level.

Here is an example log:
2018-01-11 12:31:43.6913|INFO|Microsoft.AspNetCore.Hosting.Internal.WebHost|Request starting HTTP/1.1 GET http://[::]:5068/
2018-01-11 12:31:44.3189|INFO|Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Executing action method XXXX.api.Controllers.ApiMetaController.Index (XXXXX) with arguments ((null)) - ModelState is Valid

On a busy site in production the log is going to be absolutely swamped with every request. Are those "INFO" level items of information? I believe they are DEBUG or TRACE level.

[Eilon]

@WhatFreshHellIsThis we do periodically tweak the log levels of certain log entries based on what we think is more/less useful at certain levels. We try to limit "INFO"-level logs to less than ~10 or so per request, and of course as you get more detailed, you get a lot more log messages.

I recommend checking out the docs on Logging Filtering to see how to control certain log messages: https://docs.microsoft.com/en-us/aspnet/core/fundamentals/logging/?tabs=aspnetcore2x#log-filtering

I'm not sure we can ever arrive at a perfect balance of levels because the usefulness of each log entry will vary depending on what someone is looking for.

cc @rynowak @kichalla

[WhatFreshHellIsThis]

Hello, I'm not sure this has been thought through at the level of a production app in the real world:

By setting the default at "Info" for what is really trace or debug level stuff you have taken away the usefulness of the application developer using INFO for their own purposes.

We can't just willy nilly use WARN or ERROR or FATAL levels if we are to stick to accepted practices and for many items DEBUG or TRACE are far too low for them so INFO is the most appropriate level for common application logging in production (i.e. "Server started", "configuration changed" etc etc).

But the log is absolutely filled with Microsoft log items for every single request at INFO level instead, burying these important items that the application developer requires and wants the user to see.

INFO is far too high a level for logging every visit to a web application and it hurts developers who use asp.net core in production with any sizable visitor base.

This isn't a subjective thing that depends on "what someone is looking for" it's a real world necessity and objectively it needs to be set lower.

I'm not alone in thinking this, the NLOG documentation for example here https://github.com/NLog/NLog.Web/wiki/Getting-started-with-ASP.NET-Core-2
specifically has an example on filtering OUT Microsoft.* messages due to this issue and if you do a search online many developers are asking how to filter OUT those messages.

It's not an appropriate level to log such low level activity and it hampers developers writing real world applications.

[Eilon]

@WhatFreshHellIsThis the filtering can be done both by Log Level and by Category Names. If the Microsoft.* messages at the INFO level are too much, we recommend filtering those out so that you see only INFO level messages from non-Microsoft components, but see all "severe" logs from all components (warning, error, etc.).

When we first started logging things we had only 1 or 2 messages at the INFO level, which amounted to something like "Request XYZ is starting" and "Request XYZ has ended," and that was generally seen as too little. So we added some more INFO-level logs such that each "major component" of the system that actually did something during the request would say something meaningful about the request, such as Static Files reporting a file was accessed, MVC reporting that a Controller Action was called, and so forth.

As I mentioned earlier, I don't think that striking a perfect balance is possible here, but if you have specific log messages that you feel are almost never useful, we will consider adjusting them to new log levels.

cc @anurse as well.

[WhatFreshHellIsThis]

@Eilon I understand your point of view, thank you for taking the time.

That being said I don't think you understand the issue here at all. I'm not saying there is a problem with logging that kind of information, I'm saying it's at the wrong level. It's not following accepted practices when you look at it in the context of an entire released in production application and it's diluting and essentially taking away from the developer the only level (INFO) that is most appropriate for common application level logging.

It may seem appropriate when you look at an asp.net core project from a development and learning perspective, but when you get into a large production application it just doesn't make sense to log all that, Imagine a popular site with hundreds of thousands of users, do you really want all the important application information log buried in all those hits that are essentially meaningless unless you are troubleshooting a tricky issue?

In the mean time I and others are forced to completely take over control of logging in my application and so I'm filtering out Microsoft.* at INFO and lower level and only enabling them if a user selects DEBUG level or lower in my own method for setting log level.

I hope some more people come forward and chime in on this, I don't think I'm alone judging by what I found searching online for a solution to this problem and I think this is something that is just simply wrong, but I guess time will tell.

[Eilon]

@WhatFreshHellIsThis indeed, I'd like to keep this issue open for some time to see what the general feelings out there are. As I mentioned, we do periodically tweak the log levels based on both user feedback and our own internal "gut feeling." Sometimes we go too far; sometimes not far enough.

[cwe1ss]

+1. Info logs are too noisy. Setting the level for Microsoft.* to Warning is always one of the first things I do.

[aspnet-hello]

We periodically close 'discussion' issues that have not been updated in a long period of time.

We apologize if this causes any inconvenience. We ask that if you are still encountering an issue, please log a new issue with updated information and we will investigate.

[WhatFreshHellIsThis]

Too soon, please keep this open, it's a nuisance and needs to be fixed.

[Eilon]

@WhatFreshHellIsThis this issue was closed because there wasn't a consensus on what work should be done and whether it would be worth the change.