serilog / serilog-extensions-hosting

Serilog logging for Microsoft.Extensions.Hosting
Apache License 2.0
141 stars 34 forks source link

Logs from within UseSerilog() not printed #51

Closed catcake closed 3 years ago

catcake commented 3 years ago

Hello!

So, I configure Log.Logger initially in Main() and this works up until and then after, but not inside of UseSerilog(IHostBuilder, Action<HostBuilderContext, IServiceProvider, LoggerConfiguration>, bool, bool). I think it has to do with the previous sinks not being flushed before the new configuration is applied because when using the Console and File sinks without the Async sink, the Console sink outputs as expected, yet the File sink still does not. I am referring to log inside the if statement within UseSerilog() (and the regular WriteLine() does print).

The output appears in both desired sinks when preserveStaticLogger is set to true, but this isn't an ideal solution because the logs for the File sink are split across two separate files.

I'm not sure if this is something that simply not supported, a problem on my part, or a bug in UseSerilog().

Here's my Program.cs file, as most of it is relevant:

internal static class Program
{
    private const string LogTemplate = 
        "[{Timestamp:HH:mm:ss} {Level:u3}] ({SourceContext}) {Message:lj}{NewLine}{Exception}";

    private static ILogger _log;

    private static async Task Main(string[] args)
    {
        Log.Logger = new LoggerConfiguration().ConfigureLogger().CreateBootstrapLogger();
        _log = Log.ForContext(typeof(Program));

        try
        {
            _log.Information("Starting...");
            await CreateHostBuilder(args).Build().RunAsync();
        }
        catch (Exception e)
        {
            _log.Fatal(e, "Terminating: unhandled exception");
        }
        finally
        {
            _log.Information("Shutting down...");
            Log.CloseAndFlush();
        }
    }

    private static LoggerConfiguration ConfigureLogger(this LoggerConfiguration config,
        LoggingLevelSwitch logLevel = null,
        bool seqEnabled = false,
        string seqUrl = "",
        string seqToken = "",
        string template = LogTemplate)
    {
        config ??= new LoggerConfiguration();
        logLevel ??= new LoggingLevelSwitch(LogEventLevel.Debug);

        if (seqEnabled && (seqUrl == string.Empty || seqToken == string.Empty))
            throw new ArgumentException($"{nameof(seqUrl)} and/or {nameof(seqToken)} is empty while {nameof(seqEnabled)} is {true}");

        return config
            .Enrich.WithEnvironmentName()
            .Enrich.FromLogContext()
            .Enrich.WithProperty("ProjectName", "PlaylistCopy.Api")
            .MinimumLevel.ControlledBy(logLevel)
//                .MinimumLevel.Override("System", LogEventLevel.Information)
            .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
            .MinimumLevel.Override("Microsoft.Hosting.Lifetime", LogEventLevel.Information)
//                .WriteTo.Async(a => a.Console(outputTemplate: template))
            .WriteTo.Console(outputTemplate: template)
//                .WriteTo.Async(a => a.File(
            .WriteTo.File(
                new CompactJsonFormatter(),
                "logs/playlist-copy-api-.log",
                rollingInterval: RollingInterval.Day)
            .EnableProductionOnlySinks(seqEnabled, seqUrl, seqToken);
    }

    private static LoggerConfiguration EnableProductionOnlySinks(this LoggerConfiguration config,
        bool production,
        string seqUrl,
        string seqToken) =>
        production ? config.WriteTo.Seq(seqUrl, apiKey: seqToken) : config;

    private static IHostBuilder CreateHostBuilder(string[] args) => Host
        .CreateDefaultBuilder(args)
        .ConfigureServices((context, services) =>
        {
            var logConfig = context.Configuration.GetSection("Logging");
            var selectedLogLevel = logConfig.GetValue("Level", defaultValue: LogEventLevel.Information);
            services.AddSingleton(new LoggingLevelSwitch(selectedLogLevel));
            _log.Information("test");
        })
        .UseSerilog(preserveStaticLogger: false, configureLogger: (context, services, configureLog) =>
        {
            var logConfig = context.Configuration.GetSection("Logging");
            var seqConfig = logConfig.GetSection("Seq");
            var seqEnable = seqConfig.GetValue("Enable", defaultValue: false);
            var seqUrl = seqConfig.GetValue("Url", defaultValue: string.Empty);
            var seqToken = seqConfig.GetValue("Token", defaultValue: string.Empty);
            var logLevel = services.GetRequiredService<LoggingLevelSwitch>();

            if (seqEnable && (string.IsNullOrWhiteSpace(seqUrl) || string.IsNullOrWhiteSpace(seqToken)))
            {
                _log.Warning("Seq sink disabled: required parameter empty");
                Console.WriteLine("this prints");
                seqEnable = false;
            }

            configureLog.ConfigureLogger(logLevel, seqEnable, seqUrl, seqToken);
        })
        .ConfigureWebHostDefaults(webBuilder => webBuilder
            .UseStartup<Startup>()
            .UseKestrel()
            .ConfigureKestrel((context, kestrelOptions) => kestrelOptions
                .Listen(IPAddress.Parse(context.Configuration["Ip"]),
                    context.Configuration.GetValue<int>("Port"),
                    listenOptions => listenOptions
                    .UseHttps(context.Configuration["CertFilename"], context.Configuration["CertPassword"]))));
}

Thank you!

nblumhardt commented 3 years ago

Hello @catcake - thanks for the note.

Do you mean that the output of this statement is missing?

_log.Warning("Seq sink disabled: required parameter empty");

I.e. are logs working again once UseSerilog() has returned?

I think this may be a side-effect of the current design; in ReloadableLogger, the initial pipeline is disposed before the new one is configured:

https://github.com/serilog/serilog-extensions-hosting/blob/dev/src/Serilog.Extensions.Hosting/Extensions/Hosting/ReloadableLogger.cs#L63

(This avoids problems where an existing sink might exclusively lock some shared resource.)

catcake commented 3 years ago

Yes, that is the missing statement and yes, everything works flawlessly once UseSerilog() has returned. Thank your for the feedback!