serilog-mssql / serilog-sinks-mssqlserver

A Serilog sink that writes events to Microsoft SQL Server and Azure SQL
Apache License 2.0
283 stars 148 forks source link

SqlClient exceptions thrown during logger configuration are hard to understand #481

Closed cremor closed 1 year ago

cremor commented 1 year ago

Please clearly describe what the SQL Sink is doing incorrectly:

If you enable the AutoCreateSqlTable and/or AutoCreateSqlDatabase option and the configuration either contains no connection string or an invalid connection string then a complicated exception is thrown during the configureLogger action passed to UseSerilog. That exception is thrown directly from SqlClient and may have messages like "someArg must not be null" or "invalid token at index 0". So if you read just the message then you don't know what the error is. Only if you go over the (long) stack trace you figure out that it is the Serilog.Sinks.MSSqlServer setup that causes the exception.

Please clearly describe the expected behavior:

The exceptions in those cases should be immediately understandable. E.g. they could be wrapped in an exception that has a message like "Setup of the Serilog Microsoft SQL Server sink failed, see inner exception for details."

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

Target framework and operating system:

.NET 7 OS: Windows 10

Provide a simple reproduction of your Serilog configuration code:

var builder = WebApplication.CreateBuilder(args);
// configure services ...

builder.Host.UseSerilog((context, services, loggerConfiguration) => loggerConfiguration
    .ReadFrom.Configuration(context.Configuration));

var app = builder.Build();
// ...

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

  "Serilog": {
    "WriteTo": {
      "DbSink": {
        "Name": "MSSqlServer",
        "Args": {
          "connectionString": "DefaultConnection",
          "sinkOptionsSection": {
            "tableName": "Logs",
            "autoCreateSqlTable": true,
            "AutoCreateSqlDatabase":  true
          }
        }
      }
    }
  }

Provide a simple reproduction of your application code:

Not required. The error is logged as soon as builder.Build() is called.

ckadluba commented 1 year ago

Hi @cremor!

Thanks for sharing your experience.

I think the original exception from the SqlClient library provides the most valuable information about what is actually going wrong. If you want to get the context of where the exception was thrown you have to look at the call stack. It will show exactly in which sink the exception was caused.

grafik

Since I think the original exception with it's type, message and stack trace is sufficient, I would refrain from wrapping it yet again in another sink specific exception which does not really add any valuable information.

One thing that your report pointed out to me is, that exceptions during SQL DB or table creation are handled by the MSSQL sink. It only logs them to the Serilog SelfLog but does not rethrow them to the caller. I will change that. Execptions during sink initialization should be rethrown (as shown in my PoC screenshot above).

Best regards. Christian

cremor commented 1 year ago

As can be seen in your screenshot, the original exception is already wrapped in a TargetInvocationException. So there is no useful exception type or message there. Only if you look through the call stack, and only about 10 level down, you see that it is actually a Serilog sink exception. In my opinion an exception type and/or message would be very helpful there.

I will change that. Execptions during sink initialization should be rethrown (as shown in my PoC screenshot above).

Please be careful that this doesn't cause unhandled exceptions when the DB already exists (see #478).

ckadluba commented 1 year ago

Don't worry. The exception if the DB already exists will be fixed in the SQL that is emitted. Just like it is done in for create table.

cremor commented 1 year ago

@ckadluba Seems like this issue was auto-closed when PR #482 was merged. Was this on purpose?

If it was, then I assume you think that an exception like this is acceptable user experience? grafik

ckadluba commented 1 year ago

Can you show the call stack please?

cremor commented 1 year ago

The full stack trace reveals that the error is coming from this sink. But only if you look quite a few lines down. My point is that you don't see the problem source at a glance.

System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation.
 ---> System.ArgumentException: Format of the initialization string does not conform to specification starting at index 0.
   at System.Data.Common.DbConnectionOptions.GetKeyValuePair(String connectionString, Int32 currentPosition, StringBuilder buffer, Boolean useOdbcRules, String& keyname, String& keyvalue)
   at System.Data.Common.DbConnectionOptions.ParseInternal(Dictionary`2 parsetable, String connectionString, Boolean buildChain, Dictionary`2 synonyms, Boolean firstKey)
   at System.Data.Common.DbConnectionOptions..ctor(String connectionString, Dictionary`2 synonyms, Boolean useOdbcRules)
   at System.Data.Common.DbConnectionStringBuilder.set_ConnectionString(String value)
   at Microsoft.Data.SqlClient.SqlConnectionStringBuilder..ctor(String connectionString)
   at Serilog.Sinks.MSSqlServer.Platform.SqlClient.SqlConnectionStringBuilderWrapper..ctor(String connectionString, Boolean enlist)
   at Serilog.Sinks.MSSqlServer.Dependencies.SinkDependenciesFactory.Create(String connectionString, MSSqlServerSinkOptions sinkOptions, IFormatProvider formatProvider, ColumnOptions columnOptions, ITextFormatter logEventFormatter)
   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)
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)
   --- End of inner exception stack trace ---
   at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)
   at System.Reflection.RuntimeMethodInfo.InvokeWithManyArguments(RuntimeMethodInfo mi, Int32 argCount, Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
   at System.Reflection.MethodBase.Invoke(Object obj, Object[] parameters)
   at Serilog.Settings.Configuration.ConfigurationReader.CallConfigurationMethods(ILookup`2 methods, IReadOnlyCollection`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, ConfigurationReaderOptions readerOptions)
ckadluba commented 1 year ago

Everything you need for analysis is there. Therefore I would rather not create a sink specific exception which only nests the original SqlClient exception as an inner exception when you have to end up looking at this anyway.

But in general we are always open for good PRs if they bring value to the project.