Search code examples
loggingasp.net-core-2.1serilog

Serilog creates files before reaching max file size


I have created an API using .NET core 2.1 and used Serilog to log every single response and request on API level for all methods types : Get, Post ... despite the response code; Below is my code added to a middleware class:

var request = context.Request;
    var stopWatch = Stopwatch.StartNew();
    var requestTime = DateTime.UtcNow;
    var requestBodyContent = await ReadRequestBody(request);
    var originalBodyStream = context.Response.Body;
    generalError = Configuration["generalError"];

        using (var memStream = new MemoryStream())
        {
            HttpResponse response = context.Response;
            response.Body = memStream;
            await next(context);
            stopWatch.Stop();

            string responseBodyContent = null;
            responseBodyContent = ReadResponseBody(memStream);
            memStream.CopyTo(originalBodyStream);

            string infoToLog = "\r\n" +
                               "------------------------ \r\n" +
                               "Elapsed Milliseconds: " + stopWatch.ElapsedMilliseconds + "\r\n" +
                               "Status Code: " + context.Response.StatusCode + "\r\n" +
                               "Method: " + request.Method + "\r\n" +
                               "Path: " + request.Path + "\r\n" +
                               "QueryString: " + request.QueryString.ToString() + "\r\n" +
                               "Request Body: " + requestBodyContent + "\r\n" +
                               "Response Body: " + responseBodyContent + "\r\n" +
                               "------------------------" + "\r\n\r\n";

            Log.Logger = new LoggerConfiguration()
                .WriteTo.Async(a => a.File("Logs/myapp.log",
                          rollOnFileSizeLimit: true,                                  
                          fileSizeLimitBytes: Convert.ToInt32(Configuration["MaxLogFileSize"])))
                            //shared:true,
                .CreateLogger();

            if (context.Response.StatusCode == 200)
            {
                Log.Information(infoToLog);                        
            }
            else {
                Log.Error(infoToLog);                        
            }

            Log.CloseAndFlush();

            context.Response.Body = originalBodyStream;
        }

So As you can see, i have implemented a rolling logging method that creates a new file only after the max File size issue is reached. The main issue is that, after publishing, and when the API became called from a mobile application, we realized that many logging files are created at the same time without reaching the max file size, more specifically when multiple methods should be logged at the same time. Is there anyway we can fix this issue?


Solution

  • You are instantiating a new logger on every webrequest in your middleware and I think you are also closing the log file with Log.CloseAndFlush();, when I think it should be a singleton if I recall the docs.

    From what I remember, you only need to create the logger during application bootstrap. This is how I did it (program.cs with .NET core 2.2):

        public class Program
        {
            private static readonly string _applicationName = System.Reflection.Assembly.GetEntryAssembly().GetName().Name;
            public static IConfiguration Configuration = new ConfigurationBuilder()
                      .SetBasePath(Directory.GetCurrentDirectory())
                      .AddJsonFile("appsettings.json", optional: true, reloadOnChange: true)
                      .AddJsonFile($"appsettings.{Environment.GetEnvironmentVariable("ASPNETCORE_ENVIRONMENT")}.json", reloadOnChange: true, optional: true)
                      .AddEnvironmentVariables()
                      .Build();
    
        public static int Main(string[] args)
        {
            // serilog
            Log.Logger = new LoggerConfiguration()
                            .ReadFrom.Configuration(Configuration)
                            .Enrich.FromLogContext()
                            .CreateLogger();
    
            try
            {
                if (string.IsNullOrWhiteSpace(Environment.GetEnvironmentVariable("ASPNETCORE_ENVIRONMENT")))
                    throw new Exception("Hosting environment variable not set");
    
                Log.Information($"Bootstrapping application: {_applicationName}");
                CreateWebHostBuilder(args).Build().Run();
                Log.Information($"Gracefully closing application: {_applicationName}");
                return 0; // returning a zero, indicates a successful shutdown.
            }
            catch (Exception e)
            {
                Log.Warning($"Host {_applicationName} - terminated unexpectedly.");
                Log.Fatal(e.Message);
                return 1; // returning a none-zero, indicates failure.
            }
            finally
            {
                Log.CloseAndFlush();
            }
        }
    
        public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>
            WebHost.CreateDefaultBuilder(args)
                .UseStartup<Startup>()
                .UseConfiguration(Configuration)
                .UseSerilog();
    }
    

    So when you do want to log something, simply import using Serilog; and call Log.Information("Your message.")

    More information can be found at the bottom of: https://serilog.net/ or at https://github.com/serilog/serilog

    Edit

    And this is my config, specifying console as sink (you can add more like files, elasticsearch, seq... others too) and I'm also overriding Microsofts default logger to only display log level warning or higher:

      "Serilog": {
        "MinimumLevel": {
          "Default": "Information",
          "Override": {
            "Microsoft": "Warning",
            "System": "Warning"
          }
        },  
        "WriteTo": [
          {
            "Name": "Console",
            "Args": {
              "outputTemplate": "[{Timestamp:yyyy-MM-dd HH:mm:ss} {Level:u3}] {Message:lj} {SourceContext}>{NewLine}{Exception}"
            }
          }
        ]
      },
    

    Update

    Well, you place your log where the tutorial says //TODO: Save log to chosen datastore, that simply just mean in serilog terms Log.Information("Your message");. I've marked the serilog part in my example with // serilog - so if you want to configure the logger to log to the file aswell, just add your configuration part to it like yours:

    // serilog
    Log.Logger = new LoggerConfiguration()
                     .ReadFrom.Configuration(Configuration)
                     .Enrich.FromLogContext()
                     .WriteTo.Async(a => a.File("Logs/myapp.log",
                               rollOnFileSizeLimit: true,                                  
                               fileSizeLimitBytes: Convert.ToInt32(Configuration["MaxLogFileSize"])))
                     .CreateLogger();
    

    You can also add that part through configuration with appsettings.json- And if you don't want this part .ReadFrom.Configuration(Configuration).Enrich.FromLogContext() just remove it.

    So your middleware code would look like this:

        var request = context.Request;
        var stopWatch = Stopwatch.StartNew();
        var requestTime = DateTime.UtcNow;
        var requestBodyContent = await ReadRequestBody(request);
        var originalBodyStream = context.Response.Body;
        generalError = Configuration["generalError"];
    
            using (var memStream = new MemoryStream())
            {
                HttpResponse response = context.Response;
                response.Body = memStream;
                await next(context);
                stopWatch.Stop();
    
                string responseBodyContent = null;
                responseBodyContent = ReadResponseBody(memStream);
                memStream.CopyTo(originalBodyStream);
    
                string infoToLog = "\r\n" +
                                   "------------------------ \r\n" +
                                   "Elapsed Milliseconds: " + stopWatch.ElapsedMilliseconds + "\r\n" +
                                   "Status Code: " + context.Response.StatusCode + "\r\n" +
                                   "Method: " + request.Method + "\r\n" +
                                   "Path: " + request.Path + "\r\n" +
                                   "QueryString: " + request.QueryString.ToString() + "\r\n" +
                                   "Request Body: " + requestBodyContent + "\r\n" +
                                   "Response Body: " + responseBodyContent + "\r\n" +
                                   "------------------------" + "\r\n\r\n";
    
                if (context.Response.StatusCode == 200)
                {
                    Log.Information(infoToLog);                        
                }
                else 
                {
                    Log.Error(infoToLog);                        
                }    
    
                context.Response.Body = originalBodyStream;
            }
    

    Also note that I call .UseSerilog(); on this method public static IWebHostBuilder CreateWebHostBuilder(string[] args) => in program.cs to override Microsfts default logger (I like serilog more for all logs).