7

So in an ASPNETCORE 2.0 project, I added a logging provider (serilog) to the logging factory along with a console sink. It works great, however I noticed that all the framework request pipelines (like http request response) are logging every little detail as INFO.

[17:37:26 INF] Request starting HTTP/1.1 GET http://localhost:5000/test/health
[17:37:26 INF] Executing action method DAS.Gateways.Command.Api.Controllers.TestController.HealthCheck (DAS.Gateways.Command.Api) with arguments (null) - ModelState is Valid
[17:37:26 INF] Health check called.
[17:37:27 INF] Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
[17:37:27 INF] Executed action DAS.Gateways.Command.Api.Controllers.TestController.HealthCheck (DAS.Gateways.Command.Api) in 203.8825ms
[17:37:27 INF] Request finished in 343.9801ms 200 application/json; charset=utf-8
[17:38:07 INF] Request starting HTTP/1.1 GET http://localhost:5000/test/health
[17:38:07 INF] Executing action method DAS.Gateways.Command.Api.Controllers.TestController.HealthCheck (DAS.Gateways.Command.Api) with arguments (null) - ModelState is Valid
[17:38:07 INF] Health check called.
[17:38:07 INF] Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
[17:38:07 INF] Executed action DAS.Gateways.Command.Api.Controllers.TestController.HealthCheck (DAS.Gateways.Command.Api) in 53.5876ms
[17:38:07 INF] Request finished in 60.2195ms 200 application/json; charset=utf-8

Info is the minimum log level we use for production logging and we have a Loggly sink that has a 1GB/day limit so I feel like MVC logging all request information as INFO is a bit obnoxious and I'd like to lower it to DEBUG. To be clear, I don't want to raise my logging level to prevent INFO from reaching the sink, I want .Net to lower it's logging level from INFO to DEBUG.

Is this possible and how?

Vadim Ovchinnikov
  • 13,327
  • 5
  • 62
  • 90
Sinaesthetic
  • 11,426
  • 28
  • 107
  • 176

3 Answers3

9

You need to use log filtering.

You can specify a minimum log level for a specific provider and category or for all providers or all categories. Any logs below the minimum level aren't passed to that provider, so they don't get displayed or stored.

Filter rules may be defined via configuration or in code. Example of how it may look in code:

    // using Serilog.Extensions.Logging;

    public static IWebHost BuildWebHost(string[] args) =>
        WebHost.CreateDefaultBuilder(args)
            .ConfigureLogging(logging => 
            {
                logging.AddFilter<SerilogLoggerProvider>("Microsoft", LogLevel.Warning);
            }
            .UseStartup<Startup>()
            .Build();

Note, that AddFilter in this case applies only to Serilog log provider as we specify a provider type. If you want to define a filter for all providers, use:

logging.AddFilter("Microsoft", LogLevel.Warning);

Set
  • 47,577
  • 22
  • 132
  • 150
  • 1
    So doesn't this just mean I won't see any of these logs? That's not what I was asking for. I want to change the level of the logs themselves, not what makes it to the sink. I guess this at least solves the overlogging problem. So +1 from me regardless. – Sinaesthetic Aug 23 '17 at 18:07
1

One possible solution is to create your own ILoggerProvider and ILogger implementations that act as a shim for the underlying provider and then have your ILogger.Log() method make the actual decision to log based on the logger's category name and then modify the log level.

In my case, I assumed that all ASP.NET Core applications have logger category names that start with "Microsoft.AspNetCore" and then I change the log level from Information to Debug for these events, something like:

public class MyLogger : ILogger
{
    private string  categoryName;
    private ILogger baseLogger;

    public MyLogger(string categoryName, ILogger baseLogger)
    {
        this.categoryName = categoryName;
        this.baseLogger   = baseLogger;
    }

    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
    {
        if (logLevel == LogLevel.Information 
           && categoryName.StartsWith("Microsoft.AspNetCore"))
        {
            logLevel = LogLevel.Debug;
        }

        baseLogger.Log(logLevel, eventId, state, exception, formatter);
    }
}

This is a bit of a hack but it effectively converts ASP.NET events logged as INFORMATION to DEBUG events, so they won't fill up your logs when you don't need them, but you then you can always set your log level to DEBUG to show them.

UPDATE:

The Startup.cs file below demonstrates how to wire this up:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Options;
using Microsoft.Extensions.Logging.Console;
using Microsoft.Extensions.Logging.Debug;

namespace WebApplication1
{
    public class LoggerProviderShim : ILoggerProvider
    {
        private ILoggerProvider baseLoggerProvider;

        public LoggerProviderShim(ILoggerProvider baseLoggerProvider)
        {
            this.baseLoggerProvider = baseLoggerProvider;
        }

        public ILogger CreateLogger(string categoryName)
        {
            return new LoggerShim(baseLoggerProvider.CreateLogger(categoryName), categoryName);
        }

        public void Dispose()
        {
            baseLoggerProvider.Dispose();
        }
    }

    public class LoggerShim : ILogger
    {
        private ILogger     baseLogger;
        private bool        treatInfoAsDebug;

        public LoggerShim(ILogger baseLogger, string categoryName)
        {
            this.baseLogger       = baseLogger;
            this.treatInfoAsDebug = categoryName != null && categoryName.StartsWith("Microsoft.AspNetCore.");
        }

        public IDisposable BeginScope<TState>(TState state)
        {
            return baseLogger.BeginScope(state);
        }

        public bool IsEnabled(LogLevel logLevel)
        {
            return baseLogger.IsEnabled(logLevel);
        }

        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
        {
            if (treatInfoAsDebug && logLevel == LogLevel.Information)
            {
                logLevel = LogLevel.Debug;
            }

            baseLogger.Log(logLevel, eventId, state, exception, formatter);
        }
    }

    public class Startup
    {
        public Startup(IConfiguration configuration)
        {
            Configuration = configuration;
        }

        public IConfiguration Configuration { get; }

        public void ConfigureServices(IServiceCollection services)
        {
            services.AddMvc();
        }

        public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
        {
            var debugLogProvider = new DebugLoggerProvider();

            loggerFactory.AddProvider(debugLogProvider);
            //loggerFactory.AddProvider(new LoggerProviderShim(debugLogProvider));

            app.UseMvc();
        }
    }
}

I've added the LoggerProviderShim and LoggerShim classes at the top of the file. LoggerProviderShim is intended to wrap a specific logger provider implementation. For this example I'm wrapping a DebugLoggerProvider. LoggerShim is used the wrap loggers returned by the wrapped (aka real) logger provider.

The idea here is that instead of adding real ILoggerProvider to the logger factory in Startup.Configure(), you'll wrap the real provider in a LoggerProviderShim and then add the shim to the logger factory.

LoggerProviderShim works by obtaining a real ILogger from the real logger provider and then wrapping that in a LoggerShim and then returning the shim. The LoggerShim constructor examines the created logger category name to decide whether it should log INFORMATION events as DEBUG. In this case, we're doing this for events that look like they're coming from an ASP.NET CORE component by looking for logger category names that come from ASP (e.g. that are prefixed by "Microsoft.AspNetCore."

The logger shim's Log() method then changes INFORMATION loglevel to DEBUG for these loggers before calling the underlying real logger.

You can see this in action by including this code in a simple WebAPI project:

  1. Make sure the log levels in appsettings.json are set to Debug.
  2. Run the application and hit the controller endpoint a few times.
  3. In the Visual Studio DEBUG output panel, note the ASP.NET events logged as INFORMATION.
  4. Stop the app and in the Startup.Configure() method, comment out the first AddProvider() call and uncomment the second one and test the application again.
  5. Now note that the ASP.NET events are logged as DEBUG. The shims transformed the event level.

You'll need to specifically wrap any of the logging providers you care about. In this example, I wrapped the DebugLogProvider. You'd need to do the same for the Application Insights or any others separately (did I already mention that this is a bit of a hack :)

Jeff Lill
  • 11
  • 3
  • Which ILogger is that? Microsoft.Extensions.Logging.ILogger? It would also help to see how you're plugging this in. I'm pretty new to the new logging framework. – Sinaesthetic Aug 24 '17 at 22:25
0

All the information level logs about http request and response can be turned off by setting the "MinimumLevel" in LoggerConfiguration for "Microsoft" as those logs are from "Microsoft.AspNetCore" . This can be done in code as below

Log.Logger = new LoggerConfiguration()
            .ReadFrom.Configuration(Configuration)
            .MinimumLevel.Override("Microsoft",LogEventLevel.Warning)
            .CreateLogger();

This can also be done through configuration in appsettings.json file as below

"Serilog": {
"MinimumLevel": {
  "Default": "Debug",
  "Override": {
    "Microsoft": "Warning"
  }
},
"WriteTo": [
  {
    "Name": "Async",
    "Args": {
      "configure": [
        {
          "Name": "Console",
          "Args": {
            "outputTemplate": "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] {Message:lj}{NewLine}{Exception}"
          }
        },
        {
          "Name": "File",
          "Args": {
            "path": "Logs/log.txt",
            "outputTemplate": "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] {Message:lj}{NewLine}{Exception}",
            //"fileSizeLimitBytes": "1073741824",
            //"buffered": false,
            //"shared": false,
            "rollingInterval": "Minute"
            //"rollOnFileSizeLimit": false,
            //"retainedFileCountLimit": 31
          }
        }
      ]
    }
  }
]

}

Siva Chamarthi
  • 585
  • 5
  • 9