Serilog.Sinks.File + buffered = truncated JSON logs

[dhabierre]

Hi,

I am using Serilog + File sink to write JSON logs.

When I set the buffered option to true, log entries can be truncated (latest line):

{"timestamp":"2020-03-14T11:21:39.6329431Z","message":"[\"Start\"] The application is starting","eventId":"95bfe00a","logId":"39c4b40d8804","severity":"INF","Type":"Start","SourceContext":"X.X.Web.MvcApplication","Environment":"DEV-LOCAL","ApplicationType":"Web","ApplicationName":"X.X.Web","ApplicationVersion":"V.16.3.14.001","HttpRequestId":"13e1d961-a556-49d2-a7f2-afbdd9de9faa","HttpRequestNumber":1,"EnvironmentUserName":"KOPAXI\\dhabi","MachineName":"KOPAXI","ProcessId":7420,"ThreadId":1,"CorrelationId":"9f8b416c-b3c2-42af-8497-7041125f8511"}
{"timestamp":"2020-03-14T11:21:47.1380499Z","message":"HTTP \"GET\" \"/\" responded 401 in 409ms","eventId":"c4ef1b8d","logId":"39c4b884479c","severity":"INF","Method":"GET","RawUrl":"/","StatusCode":401,"ElapsedMilliseconds":409,"SourceContext":"SerilogWeb.Classic.ApplicationLifecycleModule","Environment":"DEV-LOCAL","ApplicationType":"Web","ApplicationName":"X.X.Web","ApplicationVersion":"V.16.3.14.001","HttpRequestClientHostIP":"::1","HttpRequestClientHostName":"::1","HttpRequestId":"26ccd89a-33ad-42f3-af9b-5a9bb5e46780","HttpRequestNumber":5,"HttpRequestRawUrl":"/","HttpRequestType":"GET","HttpRequestUrl":"http://localhost:33064/","HttpRequestUserAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/80.0.3987.132 Safari/537.36","UserName":"(anonymous)","EnvironmentUserName":"KOPAXI\\dhabi","MachineName":"KOPAXI","ProcessId":7420,"ThreadId":7,"CorrelationId":"1df2e5b9-a32f-421d-b3fc-0516a1fd31fd"}
{"timestamp":"2020-03-14T11:22:18.6835729Z","message":"The attribute 'connectionStringName' is missing or empty.","eventId":"30511a46","logId":"39c4cb4a45c1","severity":"ERR","exception":"System.Configuration.Provider.ProviderException: The attribute 'connectionStringName' is missing or empty.\r\n   at System.Web.Util.SecUtility.GetConnectionString(NameValueCollection config)\r\n   at System.Web.Security.SqlMembershipProvider.Initialize(String name, NameValueCollection config)\r\n   at X.X.Web.Common.Providers.CustomMembershipProvider.Initialize(String name, NameValueCollection config) in C:\\DEV\\X\\X.X\\X.X.Web\\Common\\Providers\\CustomMembershipProvider.cs:line 44","SourceContext":"X.X.Web.Common.Providers.CustomMembershipProvider","Environment":"DEV-LOCAL","ApplicationType":"Web","ApplicationName":"X.X.Web","ApplicationVersion":"V.16.3.14.001","HttpRequestClientHostIP":"::1","HttpRequestClientHostName":"::1","HttpRequestId":"00820645-2e22-435b-8df1-bd3f840f6071","HttpRequestNumber":8,"HttpRequestRawUrl":"/Account/Login","HttpRequestType":"POST","HttpRequestUrl":"http://localhost:33064/Account/Login","HttpRequestUrlReferrer":"http://localhost:33064/Account/LoginInterne","HttpRequestUserAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/80.0.3987.132 Safari/537.36","HttpSessionId":"pslmzxnnlaxoin5ap11jaj2s","UserName":"(anonymous)","EnvironmentUserName":"KOPAXI\\dhabi","MachineName":"KOPAXI","ProcessId":7420,"ThreadId":7,"CorrelationId":"78dc2d5d-14c9-4310-a1d3-6426dbb23643"}
{"timestamp":"2020-03-14T11:22:20.5205151Z","message":"[\"Metric\"] - \"Technic\" - \"LoginFailureAudit\" => \"root\"","eventId":"65c0e83b","logId":"39c4cc5ff99f","severity":"INF","Type":"Metric","MetricEventCategory":"Technic","MetricEventName":"LoginFailureAudit","MetricEventUserName":"root","SourceContext":"X.X.Web.Controllers.BaseController","Environment":"DEV-LOCAL","Applicati

Dependencies:

<package id="Serilog" version="2.9.0" targetFramework="net452" />
<package id="Serilog.Enrichers.CorrelationId" version="3.0.1" targetFramework="net452" />
<package id="Serilog.Enrichers.Environment" version="2.1.3" targetFramework="net452" />
<package id="Serilog.Enrichers.Process" version="2.0.1" targetFramework="net452" />
<package id="Serilog.Enrichers.Thread" version="3.1.0" targetFramework="net452" />
<package id="Serilog.Filters.Expressions" version="2.1.0" targetFramework="net452" />
<package id="Serilog.Settings.AppSettings" version="2.2.2" targetFramework="net452" />
<package id="Serilog.Sinks.Debug" version="1.0.1" targetFramework="net452" />
<package id="Serilog.Sinks.File" version="4.1.0" targetFramework="net452" />
<package id="SerilogWeb.Classic" version="5.0.52" targetFramework="net452" />

Configuration:

<!-- Serilog (BEGIN) -->
<add key="serilog:minimum-level" value="Information" />
<!-- Debug Sink -->
<add key="serilog:using:Debug" value="Serilog.Sinks.Debug" />
<add key="serilog:write-to:Debug" />
<add key="serilog:write-to:Debug.restrictedToMinimumLevel" value="Verbose" />
<add key="serilog:write-to:Debug.outputTemplate" value="[{Timestamp:HH:mm:ss.fff} {CorrelationId} {Level:u3}] {Message}{NewLine}{Exception}" />
<!-- File Sink -->
<add key="serilog:using:File" value="Serilog.Sinks.File" />
<add key="serilog:write-to:File.restrictedToMinimumLevel" value="Information" />
<!-- ***************************************************** -->
<!-- I use my own Formatter that implements ITextFormatter -->
<add key="serilog:write-to:File.formatter" value="C4.Logging.Serilog.Formatting.Json.RenderedCompactJsonFormatter, C4.Logging.Serilog" />
<!-- ***************************************************** -->
<add key="serilog:write-to:File.path" value="C:\X\WEB\LogM\X-.json" />
<add key="serilog:write-to:File.rollingInterval" value="Day" />
<add key="serilog:write-to:File.fileSizeLimitBytes" />
<add key="serilog:write-to:File.retainedFileCountLimit" value="14" />
<add key="serilog:write-to:File.buffered" value="false" />
<!-- SerilogWeb.Classic enrichers -->
<add key="serilog:using:SerilogWeb.Classic" value="SerilogWeb.Classic" />
<add key="serilog:enrich:WithHttpRequestClientHostIP" />
<add key="serilog:enrich:WithHttpRequestClientHostName" />
<add key="serilog:enrich:WithHttpRequestId" />
<add key="serilog:enrich:WithHttpRequestNumber" />
<add key="serilog:enrich:WithHttpRequestRawUrl" />
<add key="serilog:enrich:WithHttpRequestType" />
<add key="serilog:enrich:WithHttpRequestUrl" />
<add key="serilog:enrich:WithHttpRequestUrlReferrer" />
<add key="serilog:enrich:WithHttpRequestUserAgent" />
<add key="serilog:enrich:WithHttpSessionId" />
<add key="serilog:enrich:WithUserName" />
<!-- Serilog.Enrichers.Environment enrichers -->
<add key="serilog:using:Serilog.Enrichers.Environment" value="Serilog.Enrichers.Environment" />
<add key="serilog:enrich:WithEnvironmentUserName" />
<add key="serilog:enrich:WithMachineName" />
<!-- Serilog.Enrichers.Process enrichers -->
<add key="serilog:using:Serilog.Enrichers.Process" value="Serilog.Enrichers.Process" />
<add key="serilog:enrich:WithProcessId" />
<!-- Serilog.Enrichers.Process enrichers -->
<add key="serilog:using:Serilog.Enrichers.Thread" value="Serilog.Enrichers.Thread" />
<add key="serilog:enrich:WithThreadId" />
<!-- Serilog.Enrichers.Process enrichers -->
<add key="serilog:using:Serilog.Enrichers.CorrelationId" value="Serilog.Enrichers.CorrelationId" />
<add key="serilog:enrich:WithCorrelationId" />
<!-- Serilog (END) -->

Code:

private void RegisterSerilog() // => call once when the ASPNET MVC5 App is starting (Global.asax / Application_Start())
{
    var environment = ConfigurationManager.AppSettings["Environment"];
    var applicationType = ConfigurationManager.AppSettings["ApplicationType"];
    var applicationName = ConfigurationManager.AppSettings["ApplicationName"];
    var applicationVersion = ConfigurationManager.AppSettings["ApplicationVersion"];

    Log.Logger = new LoggerConfiguration()
        .Enrich.WithEnvironment(environment)
        .Enrich.WithApplicationType(applicationType)
        .Enrich.WithApplicationName(applicationName)
        .Enrich.WithApplicationVersion(applicationVersion)
        .Enrich.FromLogContext()
        .ReadFrom.AppSettings()
        .CreateLogger();
}

My own formatter:

namespace C4.Logging.Serilog.Formatting.Json
{
    using System;
    using System.Collections.Generic;
    using System.IO;
    using Compact;
    using global::Serilog.Events;
    using global::Serilog.Formatting;
    using global::Serilog.Formatting.Json;

    public class RenderedCompactJsonFormatter : ITextFormatter
    {
        private const string TimestampDefaultKey = "timestamp";
        private const string SeverityDefaultKey = "severity";
        private const string EventIdDefaultKey = "eventId";
        private const string LogIdDefaultKey = "logId";
        private const string MessageDefaultKey = "message";
        private const string ExceptionDefaultKey = "exception";

        private static readonly IDictionary<LogEventLevel, string> ShortLevels =
            new Dictionary<LogEventLevel, string>
            {
                { LogEventLevel.Debug, "DBG" },
                { LogEventLevel.Error, "ERR" },
                { LogEventLevel.Fatal, "FTL" },
                { LogEventLevel.Information, "INF" },
                { LogEventLevel.Verbose, "VRB" },
                { LogEventLevel.Warning, "WRN" }
            };

        private readonly string timestampKey;
        private readonly string levelKey;
        private readonly string eventIdKey;
        private readonly string logIdKey;
        private readonly string messageKey;
        private readonly string exceptionKey;

        private readonly JsonValueFormatter valueFormatter;

        private readonly bool withEventId;
        private readonly bool withLogId;

        public RenderedCompactJsonFormatter(
            JsonValueFormatter valueFormatter = null,
            string timestampKey = TimestampDefaultKey,
            string severityKey = SeverityDefaultKey,
            string eventIdKey = EventIdDefaultKey,
            string logIdKey = LogIdDefaultKey,
            string messageKey = MessageDefaultKey,
            string exceptionKey = ExceptionDefaultKey,
            bool withEventId = true,
            bool withLogId = true)
        {
            this.valueFormatter = valueFormatter ?? new JsonValueFormatter(typeTagName: "$type");

            CheckKeyValue(nameof(timestampKey), timestampKey);
            CheckKeyValue(nameof(severityKey), severityKey);
            CheckKeyValue(nameof(eventIdKey), eventIdKey);
            CheckKeyValue(nameof(logIdKey), logIdKey);
            CheckKeyValue(nameof(messageKey), messageKey);
            CheckKeyValue(nameof(exceptionKey), exceptionKey);

            this.timestampKey = timestampKey;
            this.levelKey = severityKey;
            this.eventIdKey = eventIdKey;
            this.logIdKey = logIdKey;
            this.messageKey = messageKey;
            this.exceptionKey = exceptionKey;
            this.withEventId = withEventId;
            this.withLogId = withLogId;
        }

        public void Format(LogEvent logEvent, TextWriter output)
        {
            this.FormatEvent(logEvent, output);

            output.WriteLine();
        }

        private void FormatEvent(LogEvent logEvent, TextWriter output)
        {
            if (logEvent == null)
            {
                throw new ArgumentNullException(nameof(logEvent));
            }

            if (output == null)
            {
                throw new ArgumentNullException(nameof(output));
            }

            output.Write($"{{\"{timestampKey}\":\"");
            output.Write(logEvent.Timestamp.UtcDateTime.ToString("O"));

            output.Write($"\",\"{messageKey}\":");

            var message = logEvent.MessageTemplate.Render(logEvent.Properties);

            JsonValueFormatter.WriteQuotedJsonString(message, output);

            if (this.withEventId)
            {
                output.Write($",\"{eventIdKey}\":\"");

                var id = EventIdHash.Compute(logEvent.MessageTemplate.Text);

                output.Write(id.ToString("x8"));
                output.Write('"');
            }

            if (this.withLogId)
            {
                output.Write($",\"{logIdKey}\":\"");

                var id = LogIdHash.Compute();

                output.Write(id);
                output.Write('"');
            }

            output.Write($",\"{levelKey}\":\"");
            output.Write(ShortLevels[logEvent.Level]);
            output.Write('\"');

            if (logEvent.Exception != null)
            {
                output.Write($",\"{exceptionKey}\":");

                JsonValueFormatter.WriteQuotedJsonString(logEvent.Exception.ToString(), output);
            }

            foreach (var property in logEvent.Properties)
            {
                var propertyName = property.Key;

                if (propertyName.Length > 0 && propertyName[0] == '@')
                {
                    propertyName = '@' + propertyName; // Escape first '@' by doubling
                }

                output.Write(',');

                JsonValueFormatter.WriteQuotedJsonString(propertyName, output);

                output.Write(':');

                this.valueFormatter.Format(property.Value, output);
            }

            output.Write('}');
        }

        private static void CheckKeyValue(string parameterName, string parameterValue)
        {
            if (parameterValue == null)
            {
                throw new ArgumentNullException(
                    parameterName,
                    $"the parameter '{parameterName}' cannot be null or empty");
            }

            if (string.IsNullOrWhiteSpace(parameterValue))
            {
                throw new ArgumentException(
                    $"the parameter '{parameterName}' cannot be null or empty",
                    parameterName);
            }
        }
    }
}

If I inspect the Serilog.Sinks.File.FileSink class, where _buffered member is used:

bool IFileSink.EmitOrOverflow(LogEvent logEvent)
{
	if (logEvent == null)
	{
		throw new ArgumentNullException("logEvent");
	}
	lock (_syncRoot)
	{
		if (_fileSizeLimitBytes.HasValue && _countingStreamWrapper.CountedLength >= _fileSizeLimitBytes.Value)
		{
			return false;
		}
		_textFormatter.Format(logEvent, _output);
		if (!_buffered)
		{
			_output.Flush(); // <== all the content is not flushed?
		}
		return true;
	}
}

Any idea?
Thank you.

[nblumhardt]

Hi! Are you observing the log file before the process is (cleanly) shut down? That would explain the behaviour - when buffering is used, the file sink will only guarantee to flush its output on clean shutdown.

[dhabierre]

@nblumhardt

This occured when the process is running.
I have a process that observes the log file to send each JSON line to a Log Manager.
If the JSON is truncated...

So at present time I set buffered to false.

[nblumhardt]

Okay, thanks for the follow-up. Yes, this is the expected behavior.

Your observer process should watch for newlines - even without buffering (and with shared: true atomic appends), there are still edge cases in which the observer might see partial events. The CLEF output format uses newline delimiters and these signal when an event is fully written.