CODEWITHSUNDEEP
asp.net-core-webapiserilog
sinsedrix
sinsedrix

Reputation: 4775

Serilog missing exception in generic logger

In a controller method, the generic logger doesn't seem to have the defined enrichers.

Here is the controller:

public class TestController : Controller
{
  ILogger _logger;

  public TestController(ILogger<TestController> logger)
  {
    _logger = logger;
  }

  public IActionResult action()
  {
    try
    {
      throw new NullReferenceException();
    }
    catch(Exception e)
    {
      Serilog.Log.Error(ex, "action KO");
      _logger.LogError("action KO", ex); 
    }
  }
}

The appsettings.json:

{
  "Serilog": {
    "MinimumLevel": {
      "Default": "Debug",
    },
    "WriteTo": [
      {
        "Name": "Console"
      },
      {
        "Name": "File",
        "Args": {
          "path": "Log/api.log",
          "outputTemplate": "{Timestamp} [{Level:u3}] ({SourceContext}) {Message}{NewLine}{Exception}",
          "rollingInterval": "Day",
          "retainedFileCountLimit": 7
        }
      }
    ],
    "Enrich": [
      "FromLogContext",
      "WithExceptionDetails"
    ]
  }
}

Host building:

        IHost host = Host.CreateDefaultBuilder(args)
            .ConfigureWebHostDefaults(webBuilder =>
            {
                webBuilder.UseStartup<Startup>();
                webBuilder.UseUrls($"http://*:12345");
            })
            .UseSerilog((hostingContext, loggerConfiguration) => loggerConfiguration
                .ReadFrom.Configuration(hostingContext.Configuration)
                )
            .Build()
            ;

Output in file / console:

02/18/2021 12:24:57 +01:00 [ERR] () action KO
System.NullReferenceException: Object reference not set to an instance of an object.
   at App.TestController`1.action()
02/18/2021 12:24:57 +01:00 [ERR] (App.TestController) action KO

So when I try to use a generic logger, the exception is omitted. Wheras the static logger writes it.

Am I missing something like a provider for controllers logger or is it meant to be done by UseSerilog?

EDIT

Upvotes: 1

Views: 2527

Answers (1)

Roar S.
Roar S.

Reputation: 10679

First, please change

_logger.LogError("action KO", ex);

to

_logger.LogError(ex, "action KO");

Testing the following try/catch

try
{
    throw new NullReferenceException();
}
catch (Exception ex)
{
    _logger.LogError(ex, "action KO");
}

... writes this to log file:

02/27/2021 22:55:59 +01:00 [ERR] (MyMicroservice.Controllers.WeatherForecastController) action KO
System.NullReferenceException: Object reference not set to an instance of an object.
   at MyMicroservice.Controllers.WeatherForecastController.Get() in C:\Prosjekter\MyMicroservice\WebApp\Controllers\WeatherForecastController.cs:line 51

After checking your configuration with doc, and some testing, the part you've added to your question, seems OK to me.

I've added some words about an interesting finding during testing and reading the docs, and finally there is a Program.cs you may want to have a look at.

TL;DR: Serilog recommends two-stage initialization in order to have a temporary logger before starting the host. The code below shows how to skip stage #1 with a tiny change and still get a logger before starting the host.

Serilog.AspNetCore doc: https://github.com/serilog/serilog-aspnetcore#inline-initialization

At the very beginning of Program#Main, you will have a Serilog.Core.Pipeline.SilentLogger.

If you follow the recommendations, you will have a Serilog.Extensions.Hosting.ReloadableLogger after stage #1.

Stage #1 looks like this and requires Nuget Serilog.Extensions.Hosting

        Log.Logger = new LoggerConfiguration()
            .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
            .Enrich.FromLogContext()
            .WriteTo.Console()
            .CreateBootstrapLogger();

In order to try to save us for some code lines and an additional dependency, comment out stage #1, and let's try the following approach to see if we can get an initialized logger before starting the web host.

var webHost = CreateHostBuilder(args).Build();

After this line, we do have an instance of Serilog.Core.Logger, which is the same as we'll end up with when using CreateHostBuilder(args).Build().Run(). Hence, I ended up with the below Program.cs where I omitted stage #1 entirely, but kept stage #2.

This should not have any side-effects, doc says:

To address this, Serilog supports two-stage initialization. An initial "bootstrap" logger is configured immediately when the program starts, and this is replaced by the fully-configured logger once the host has loaded.

Please note that after commenting out lines in code from doc, UseSerilog part is now equal to config from question.

I'm using appsettings.json from your question.

I have no Serilog config in Startup.cs.

using System;
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using Serilog;
using Microsoft.Extensions.DependencyInjection;

namespace MyMicroservice
{
    public class Program
    {
        public static void Main(string[] args)
        {
            // Serilog.Core.Pipeline.SilentLogger at this stage

            var webHost = CreateHostBuilder(args).Build();

            // Serilog.Core.Logger at this stage

            // proof-of-concept: This will log to file before starting the host
            var logger = webHost.Services.GetService<ILogger<Program>>();
            logger.LogWarning("Hello from Program.cs");

            try
            {
                Log.Information("Starting up");
                webHost.Run();
            }
            catch (Exception ex)
            {
                Log.Fatal(ex, "Application start-up failed");
            }
            finally
            {
                Log.CloseAndFlush();
            }
        }

        public static IHostBuilder CreateHostBuilder(string[] args) =>
            Host.CreateDefaultBuilder(args)
                .UseSerilog((context, services, configuration) => configuration
                    .ReadFrom.Configuration(context.Configuration)
                    /*.ReadFrom.Services(services) not required for this case */
                    /*.Enrich.FromLogContext()  already configured in appsettings.json */
                    /*.WriteTo.Console() already configured in appsettings.json */
                 )
                .ConfigureWebHostDefaults(webBuilder => webBuilder.UseStartup<Startup>());
    }
}

Upvotes: 4

Related Questions