BUG: exception in SqlTableCreator.CreateTable causes format exception

[sommmen]

Bug Report / Support Request Template

If you are opening a feature request, you can ignore this template. Bug reports and requests for assistance usually require the same basic information described below. This will help us more quickly reproduce and investigate the problem you're reporting. (If you are using Serilog.Sinks.MSSqlServerCore, that package is deprecated, please switch to Serilog.Sinks.MSSqlServer before reporting an issue.)

Please clearly describe what the SQL Sink is doing incorrectly:

Pretty odd but my app runs fine when running as console app. However when running as windows service the app faults when trying to create the SQL table.

In short in the try-catch below some exception happens:

public void CreateTable(DataTable dataTable)
{
    try
    {
        using (var conn = _sqlConnectionFactory.Create())
        {
            var sql = _sqlCreateTableWriter.GetSqlFromDataTable(_schemaName, _tableName, dataTable, _columnOptions);
            using (var cmd = conn.CreateCommand(sql))
            {
                conn.Open();
                cmd.ExecuteNonQuery();
            }
        }
    }
    catch (Exception ex)
    {
        SelfLog.WriteLine($"Exception creating table {_tableName}:\n{ex}");
    }
}

The exception gets swallowed and forwarded to the Selflog but SelfLog.WriteLine causes an exception to be thrown - and this causes my entire app to crash on startup.

Event logs will show this:

CoreCLR Version: 6.0.121.56705
.NET Version: 6.0.1
Description: The process was terminated due to an unhandled exception.
Exception Info: System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation.
 ---> System.FormatException: Input string was not in a correct format.
   at System.Text.ValueStringBuilder.ThrowFormatError()
   at System.Text.ValueStringBuilder.AppendFormatHelper(IFormatProvider provider, String format, ParamsArray args)
   at System.String.FormatHelper(IFormatProvider provider, String format, ParamsArray args)
   at System.String.Format(String format, Object arg0, Object arg1, Object arg2)
   at Serilog.Debugging.SelfLog.WriteLine(String format, Object arg0, Object arg1, Object arg2)
   at Serilog.Sinks.MSSqlServer.Platform.SqlTableCreator.CreateTable(DataTable dataTable)
   at Serilog.Sinks.MSSqlServer.MSSqlServerSink.CreateTable(MSSqlServerSinkOptions sinkOptions, SinkDependencies sinkDependencies)
   at Serilog.Sinks.MSSqlServer.MSSqlServerSink..ctor(MSSqlServerSinkOptions sinkOptions, SinkDependencies sinkDependencies)
   at Serilog.Sinks.MSSqlServer.MSSqlServerSink..ctor(String connectionString, MSSqlServerSinkOptions sinkOptions, IFormatProvider formatProvider, ColumnOptions columnOptions, ITextFormatter logEventFormatter)
   at Serilog.Sinks.MSSqlServer.Configuration.Factories.MSSqlServerSinkFactory.Create(String connectionString, MSSqlServerSinkOptions sinkOptions, IFormatProvider formatProvider, ColumnOptions columnOptions, ITextFormatter logEventFormatter)
   at Serilog.LoggerConfigurationMSSqlServerExtensions.MSSqlServerInternal(LoggerSinkConfiguration loggerConfiguration, String connectionString, MSSqlServerSinkOptions sinkOptions, IConfigurationSection sinkOptionsSection, IConfiguration appConfiguration, LogEventLevel restrictedToMinimumLevel, IFormatProvider formatProvider, ColumnOptions columnOptions, IConfigurationSection columnOptionsSection, ITextFormatter logEventFormatter, IApplySystemConfiguration applySystemConfiguration, IApplyMicrosoftExtensionsConfiguration applyMicrosoftExtensionsConfiguration, IMSSqlServerSinkFactory sinkFactory, IPeriodicBatchingSinkFactory batchingSinkFactory)
   at Serilog.LoggerConfigurationMSSqlServerExtensions.MSSqlServer(LoggerSinkConfiguration loggerConfiguration, String connectionString, MSSqlServerSinkOptions sinkOptions, IConfigurationSection sinkOptionsSection, IConfiguration appConfiguration, LogEventLevel restrictedToMinimumLevel, IFormatProvider formatProvider, ColumnOptions columnOptions, IConfigurationSection columnOptionsSection, ITextFormatter logEventFormatter)
   --- End of inner exception stack trace ---
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Span`1& arguments, Signature sig, Boolean constructor, Boolean wrapExceptions)
   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
   at Serilog.Settings.Configuration.ConfigurationReader.CallConfigurationMethods(ILookup`2 methods, IList`1 configurationMethods, Object receiver)
   at Serilog.Settings.Configuration.ConfigurationReader.ApplySinks(LoggerConfiguration loggerConfiguration)
   at Serilog.Settings.Configuration.ConfigurationReader.Configure(LoggerConfiguration loggerConfiguration)
   at Serilog.Configuration.LoggerSettingsConfiguration.Settings(ILoggerSettings settings)
   at Serilog.ConfigurationLoggerConfigurationExtensions.Configuration(LoggerSettingsConfiguration settingConfiguration, IConfiguration configuration, String sectionName, DependencyContext dependencyContext)
   at Serilog.ConfigurationLoggerConfigurationExtensions.Configuration(LoggerSettingsConfiguration settingConfiguration, IConfiguration configuration, DependencyContext dependencyContext)
   at Foundation.GenericHostApplicationBootstrapper.InitLogging() in C:\Repos\dotnet-api\Libraries\Foundation\Foundation\GenericHostApplicationBootstrapper.cs:line 212

Looking at the code in SelfLog.Writeline i see:

    public static void WriteLine(string format, object arg0 = null, object arg1 = null, object arg2 = null)
    {
      Action<string> output = SelfLog._output;
      if (output == null)
        return;
      output(string.Format(DateTime.UtcNow.ToString("o") + " " + format, arg0, arg1, arg2));
    }

So what i'm thinking that happens is that the exception passed will cause string.format to fail because the string contains text that its trying to format somehow?

A possible fix (that i don't know will work but wont do much harm) would be:

SelfLog.WriteLine($"Exception creating table {_tableName}:\n{{0}}", ex.ToString());

Please clearly describe the expected behavior:

Get the original exception instead of this follow up exception...

List the names and versions of all Serilog packages used in the project:

(i'm using all latest packages)

Target framework and operating system:

[ x ] .NET Core 2.0 (i'm running net core 6) [ ] .NET Framework 4.7 [ ] .NET Framework 4.6.x [ ] .NET Framework 4.5.x OS: Windows

Provide a simple reproduction of your Serilog configuration code:

// In the rare case Serilog fails, only really only when a) buffer becomes full or b) some configuration mistake happens, we create configure this to fall back to..
SelfLog.Enable(SerilogSelfLogOutput);

var loggerConfiguration = new LoggerConfiguration();

// NOTE A temporary configuration is built to read the Serilog configuration.
//      The actual config is loaded after logging has initialized.

var tempConfiguration = new ConfigurationBuilder()
    .ConfigureOPGAppSettings()
    .Build();

loggerConfiguration.ReadFrom.Configuration(tempConfiguration);

foreach (var exclusionPredicate in LogExclusionPredicates)
{
    loggerConfiguration
        .Filter
        .ByExcluding(exclusionPredicate);
}

var logger = loggerConfiguration.CreateLogger();

// Set global static logger (although obviously you should not use this, just inject an ILogger<>)
// This is also used by .UseSerilog()
Log.Logger = logger;

Provide a simple reproduction of your Serilog configuration file, if any:

Foundation library has generic serilog settings:

{
  "Serilog": {
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Microsoft": "Warning",
        "Microsoft.Hosting.Lifetime": "Information",
        "System": "Warning",
        "System.Net.Http.HttpClient": "Warning",
        "Hangfire": "Warning"
      }
    },
    "Using": [ "Serilog.Sinks.Console", "Serilog.Sinks.File" ],
    "Enrich": [ "FromLogContext" ],
    "WriteTo": [
      {
        "Name": "Console",
        "Args": {
          "outputTemplate": "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj} {SourceContext}{NewLine}{Exception}"
        }
      },
      {
        "Name": "File",
        "Args": {
          "path": "%CUROUTDIR%\\..\\Logs\\%ENTRYASSEMBLYNAME%\\%ENTRYASSEMBLYNAME% .txt",
          "rollingInterval": "Day",
          "rollOnFileSizeLimit": true,
          "retainedFileCountLimit": 31,
          "fileSizeLimitBytes": 5242880,
          "outPutTemplate": "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj} {Properties:j}{NewLine}{Exception}"
        }
      }
    ]
  }
}

Application specific overrides in appsettings.json:

  "Serilog": {
    "Using:2": "Serilog.Sinks.MSSqlServer",
    "WriteTo:2": {
      "Name": "MSSqlServer",
      "Args": {
        "connectionString": "DefaultConnection",
        "sinkOptionsSection": {
          "tableName": "Hangfire",
          "schemaName": "AppLog",
          "autoCreateSqlTable": true
        }
      }
    }
  }

Provide a simple reproduction of your application code:

[sommmen]

Just confirmed that this will fault (naturally):

  var someStackTraceString = " {SomeText}  ---> System.FormatException: Input string w";
  SelfLog.WriteLine($"Exception creating table {tableName}:\n{someStackTraceString}");

And these won't:

 var someStackTraceString = " {SomeText}  ---> System.FormatException: Input string was not
 SelfLog.WriteLine($"Exception creating table {tableName}:\n{{0}}", someStackTraceString);
 SelfLog.WriteLine("Exception creating table {0}:\n{1}", tableName, someStackTraceString);

[ckadluba]

Thank you for the contribution. It is highly appreciated. 👍

[sommmen]

Thank you for the contribution. It is highly appreciated. 👍

Glad to be able to help.

Could you push a release for me? that way i can debug the actual exception ^^.

[ckadluba]

Here you go! Just released Serilog.Sinks.MSSSqlServer 5.7.0 https://github.com/serilog/serilog-sinks-mssqlserver/releases/tag/v439. The new version is available on nuget.org now.