Exception thrown in SerilogLogger when non-zero incorrect number of parameters is used.

[gkinsman]

Hi there!

This code throws because the SerilogLogger doesn't handle exceptions when MEL throws because of a missing log property value:

Log.Logger = new LoggerConfiguration()
.CreateLogger();

LoggerFactory.Create(c => { c.AddSerilog(); })
    .CreateLogger("TestCategory")
    .LogInformation("Some test message with a {Two} {Properties}", new object[] {"OneProperty"});

throws:

IndexOutOfRangeException: Index was outside the bounds of the array. 
at Microsoft.Extensions.Logging.LogValuesFormatter.GetValue(Object[] values, Int32 index)
at Microsoft.Extensions.Logging.FormattedLogValues.get_Item(Int32 index)
at Microsoft.Extensions.Logging.FormattedLogValues.GetEnumerator()+MoveNext()
at Serilog.Extensions.Logging.SerilogLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
at Microsoft.Extensions.Logging.Logger.<Log>g__LoggerLog|12_0[TState](LogLevel logLevel, EventId eventId, ILogger logger, Exception exception, Func`3 formatter, List`1& exceptions, TState& state)

Given Serilog has a strong 'no-throw' on ILogger policy, it's a bit surprising when using a Serilog app logger that exceptions occur in badly-formed library log calls. Is it possible that this integration should protect against missing values and render them the same way Serilog does (i.e. as {PropertyString}?

One impact of this is that it's not really possible to safely accept an object[] args to pass into log statement (as e.g. SerilogTimings does) as if the user doesn't pass the correct number of args, the logger throws.

I believe MEL is acting badly here, as its ILogger throws when this occurs in client code so they aren't protecting against it.:

LoggerFactory.Create(c => { c.AddConsole(); }).CreateLogger("TestCategory")
    .LogInformation("Some test message with a {Few} {Properties}", new object[] { "123" });

throws:

FormatException: Index (zero based) must be greater than or equal to zero and less than the size of the argument list.
 at System.Text.StringBuilder.AppendFormatHelper(IFormatProvider provider, String format, ParamsArray args)
   at System.String.FormatHelper(IFormatProvider provider, String format, ParamsArray args)
   at System.String.Format(IFormatProvider provider, String format, Object[] args)
   at Microsoft.Extensions.Logging.FormattedLogValues.ToString()
   at Microsoft.Extensions.Logging.LoggerExtensions.MessageFormatter(FormattedLogValues state, Exception error)
   at Microsoft.Extensions.Logging.Console.ConsoleLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at Microsoft.Extensions.Logging.Logger.<Log>g__LoggerLog|12_0[TState](LogLevel logLevel, EventId eventId, ILogger logger, Exception exception, Func`3 formatter, List`1& exceptions, TState& state)

Thoughts?

[nblumhardt]

Hi George, thanks for the heads-up!

I think in the long run, being consistent with the rest of the MEL sinks is probably the way to go, here (in case, for example, MEL centralizes recording of these kinds of exceptions).

I'm not sure though whether we should still behave this way when the UseSerilog()/SerilogLoggerFactory variant is used (in that case I think we should be tighter and record these problems to SelfLog).

If the latter fix is required, and had the effect of modifying the AddSerilog() behavior, too, I'd be okay with that. What do you think?

[gkinsman]

Hey thanks for the speedy reply!

I think you're right - and it sounds like a pretty reasonable idea to stay consistent with MEL when using a MEL factory. I haven't taken a look at how the SelfLog pipe might work yet - can the factory capture the exceptions or would it need to tell the logger to do it? If that makes sense :).

Changing the behaviour of AddSerilog would be acceptable as I don't think its an exception anyone could reasonably handle.

[antonKrouglov]

Hello I am pretty new to Serilog as I have used log4net for the last decade. I have the same problem and this is damn annoying. I have Net Core 3.1 project (Worker Service Template), Serilog 2.9.0. UseSerilog() is called on IHostBulder; ILogger is injected to every class with Autofac. Any mistake in structured logging formatting throws an error. How to make it silent? Can I use dev version of Serilog? How to set it up?