diff --git a/README.md b/README.md index d38760c9..8906231f 100644 --- a/README.md +++ b/README.md @@ -99,7 +99,7 @@ var log = new LoggerConfiguration() .WriteTo.MSSqlServer( connectionString: logDB, tableName: logTable, - columnOptions: opts + columnOptions: options ).CreateLogger(); ``` @@ -368,7 +368,16 @@ This column stores the event level (Error, Information, etc.). For backwards-com ### TimeStamp -This column stores the time the log event was sent to Serilog as a SQL `datetime` type. While this may appear to be a good candidate as a clustered primary key, even relatively low-volume logging can emit identical timestamps forcing SQL Server to add a "uniqueifier" value behind the scenes (effectively an auto-incrementing identity-like integer). For frequent timestamp range-searching and sorting, a non-clustered index is better. +This column stores the time the log event was sent to Serilog as a SQL `datetime` (default) or `datetimeoffset` type. If `datetimeoffset` should be used, this can be configured as follows. + +```csharp +var columnOptions = new ColumnOptions(); +columnOptions.TimeStamp.DataType = SqlDbType.DateTimeOffset; +``` + +Please be aware that you have to configure the sink for `datetimeoffset` if the used logging database table has a `TimeStamp` column of type `datetimeoffset`. On the other hand you must not configure for `datetimeoffset` if the `TimeStamp` column is of type `datetime`. Failing to configure the data type accordingly can result in log table entries with wrong timezone offsets or no log entries being created at all due to exceptions during logging. + +While TimeStamp may appear to be a good candidate as a clustered primary key, even relatively low-volume logging can emit identical timestamps forcing SQL Server to add a "uniqueifier" value behind the scenes (effectively an auto-incrementing identity-like integer). For frequent timestamp range-searching and sorting, a non-clustered index is better. When the `ConvertToUtc` property is set to `true`, the time stamp is adjusted to the UTC standard. Normally the time stamp value reflects the local time of the machine issuing the log event, including the current timezone information. For example, if the event is written at 07:00 Eastern time, the Eastern timezone is +4:00 relative to UTC, so after UTC conversion the time stamp will be 11:00. Offset is stored as +0:00 but this is _not_ the GMT time zone because UTC does not use offsets (by definition). To state this another way, the timezone is discarded and unrecoverable. UTC is a representation of the date and time _exclusive_ of timezone information. This makes it easy to reference time stamps written from different or changing timezones. diff --git a/src/Serilog.Sinks.MSSqlServer/Properties/AssemblyInfo.cs b/src/Serilog.Sinks.MSSqlServer/Properties/AssemblyInfo.cs index 7013adb0..a5a9e9ca 100644 --- a/src/Serilog.Sinks.MSSqlServer/Properties/AssemblyInfo.cs +++ b/src/Serilog.Sinks.MSSqlServer/Properties/AssemblyInfo.cs @@ -3,10 +3,10 @@ [assembly: AssemblyTitle("Serilog.Sinks.MSSqlServer")] [assembly: AssemblyDescription("Serilog sink for MSSqlServer")] -[assembly: AssemblyCopyright("Copyright © Serilog Contributors 2014")] +[assembly: AssemblyCopyright("Copyright © Serilog Contributors 2020")] -[assembly: InternalsVisibleTo("Serilog.Tests, PublicKey=0024000004800000940000000602000000240000525341310004000001000100fb8d13fd344a1c" + - "6fe0fe83ef33c1080bf30690765bc6eb0df26ebfdf8f21670c64265b30db09f73a0dea5b3db4c9" + - "d18dbf6d5a25af5ce9016f281014d79dc3b4201ac646c451830fc7e61a2dfd633d34c39f87b818" + - "94191652df5ac63cc40c77f3542f702bda692e6e8a9158353df189007a49da0f3cfd55eb250066" + - "b19485ec")] +[assembly: InternalsVisibleTo("Serilog.Sinks.MSSqlServer.Tests, PublicKey=0024000004800000940000000602000000240000525341310004000001000100fb8d13fd344a1c" + + "6fe0fe83ef33c1080bf30690765bc6eb0df26ebfdf8f21670c64265b30db09f73a0dea5b3db4c9" + + "d18dbf6d5a25af5ce9016f281014d79dc3b4201ac646c451830fc7e61a2dfd633d34c39f87b818" + + "94191652df5ac63cc40c77f3542f702bda692e6e8a9158353df189007a49da0f3cfd55eb250066" + + "b19485ec")] diff --git a/src/Serilog.Sinks.MSSqlServer/Serilog.Sinks.MSSqlServer.csproj b/src/Serilog.Sinks.MSSqlServer/Serilog.Sinks.MSSqlServer.csproj index 230e71b0..3b1e381b 100644 --- a/src/Serilog.Sinks.MSSqlServer/Serilog.Sinks.MSSqlServer.csproj +++ b/src/Serilog.Sinks.MSSqlServer/Serilog.Sinks.MSSqlServer.csproj @@ -2,7 +2,7 @@ A Serilog sink that writes events to Microsoft SQL Server - 5.1.3 + 5.1.4 Michiel van Oudheusden;Serilog Contributors netstandard2.0;net452;netcoreapp2.0;net461 true diff --git a/src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/ColumnOptions/TimeStampColumnOptions.cs b/src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/ColumnOptions/TimeStampColumnOptions.cs index d9bbab18..a6c6713f 100644 --- a/src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/ColumnOptions/TimeStampColumnOptions.cs +++ b/src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/ColumnOptions/TimeStampColumnOptions.cs @@ -20,15 +20,15 @@ public TimeStampColumnOptions() : base() } /// - /// The TimeStamp column only supports the DateTime data type. + /// The TimeStamp column only supports the DateTime and DateTimeOffset data types. /// public new SqlDbType DataType { get => base.DataType; set { - if (value != SqlDbType.DateTime) - throw new ArgumentException("The Standard Column \"TimeStamp\" only supports the DateTime format."); + if (value != SqlDbType.DateTime && value != SqlDbType.DateTimeOffset) + throw new ArgumentException("The Standard Column \"TimeStamp\" only supports the DateTime and DateTimeOffset formats."); base.DataType = value; } } diff --git a/src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/MSSqlServerSinkTraits.cs b/src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/MSSqlServerSinkTraits.cs index 71648933..c1572c43 100644 --- a/src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/MSSqlServerSinkTraits.cs +++ b/src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/MSSqlServerSinkTraits.cs @@ -1,4 +1,4 @@ -// Copyright 2018 Serilog Contributors +// Copyright 2020 Serilog Contributors // // Licensed under the Apache License, Version 2.0 (the "License"); // you may not use this file except in compliance with the License. @@ -17,7 +17,6 @@ using System; using System.Collections.Generic; using System.Data; -using System.IO; using System.Linq; using System.Text; @@ -120,7 +119,7 @@ internal KeyValuePair GetStandardColumnNameAndValue(StandardColu case StandardColumn.Level: return new KeyValuePair(columnOptions.Level.ColumnName, columnOptions.Level.StoreAsEnum ? (object)logEvent.Level : logEvent.Level.ToString()); case StandardColumn.TimeStamp: - return new KeyValuePair(columnOptions.TimeStamp.ColumnName, columnOptions.TimeStamp.ConvertToUtc ? logEvent.Timestamp.ToUniversalTime().DateTime : logEvent.Timestamp.DateTime); + return GetTimeStampStandardColumnNameAndValue(logEvent); case StandardColumn.Exception: return new KeyValuePair(columnOptions.Exception.ColumnName, logEvent.Exception != null ? logEvent.Exception.ToString() : null); case StandardColumn.Properties: @@ -132,6 +131,16 @@ internal KeyValuePair GetStandardColumnNameAndValue(StandardColu } } + private KeyValuePair GetTimeStampStandardColumnNameAndValue(LogEvent logEvent) + { + var dateTimeOffset = columnOptions.TimeStamp.ConvertToUtc ? logEvent.Timestamp.ToUniversalTime() : logEvent.Timestamp; + + if (columnOptions.TimeStamp.DataType == SqlDbType.DateTimeOffset) + return new KeyValuePair(columnOptions.TimeStamp.ColumnName, dateTimeOffset); + + return new KeyValuePair(columnOptions.TimeStamp.ColumnName, dateTimeOffset.DateTime); + } + private string LogEventToJson(LogEvent logEvent) { if (columnOptions.LogEvent.ExcludeAdditionalProperties) diff --git a/test/Serilog.Sinks.MSSqlServer.Tests/Configuration/Microsoft.Extensions.Configuration/ConfigurationExtensions.cs b/test/Serilog.Sinks.MSSqlServer.Tests/Configuration/Microsoft.Extensions.Configuration/ConfigurationExtensions.cs index de702e49..16ea1cbf 100644 --- a/test/Serilog.Sinks.MSSqlServer.Tests/Configuration/Microsoft.Extensions.Configuration/ConfigurationExtensions.cs +++ b/test/Serilog.Sinks.MSSqlServer.Tests/Configuration/Microsoft.Extensions.Configuration/ConfigurationExtensions.cs @@ -10,7 +10,7 @@ namespace Serilog.Sinks.MSSqlServer.Tests { [Collection("LogTest")] - public class ConfigurationExtensions : IDisposable + public sealed class ConfigurationExtensions : IDisposable { static string ConnectionStringName = "NamedConnection"; static string ColumnOptionsSection = "CustomColumnNames"; diff --git a/test/Serilog.Sinks.MSSqlServer.Tests/DapperQueryTemplates.cs b/test/Serilog.Sinks.MSSqlServer.Tests/DapperQueryTemplates.cs index 2aa543e0..f122bb7f 100644 --- a/test/Serilog.Sinks.MSSqlServer.Tests/DapperQueryTemplates.cs +++ b/test/Serilog.Sinks.MSSqlServer.Tests/DapperQueryTemplates.cs @@ -70,6 +70,16 @@ public class StringLevelStandardLogColumns public string Level { get; set; } } + public class TestTimeStampDateTimeOffsetEntry + { + public DateTimeOffset TimeStamp { get; set; } + } + + public class TestTimeStampDateTimeEntry + { + public DateTime TimeStamp { get; set; } + } + public class TestTriggerEntry { public Guid Id { get; set; } diff --git a/test/Serilog.Sinks.MSSqlServer.Tests/Sinks/MSSqlServer/ColumnOptions/TestTimeStampColumnOptions.cs b/test/Serilog.Sinks.MSSqlServer.Tests/Sinks/MSSqlServer/ColumnOptions/TestTimeStampColumnOptions.cs new file mode 100644 index 00000000..77dba6d8 --- /dev/null +++ b/test/Serilog.Sinks.MSSqlServer.Tests/Sinks/MSSqlServer/ColumnOptions/TestTimeStampColumnOptions.cs @@ -0,0 +1,42 @@ +using System; +using System.Data; +using Xunit; + +namespace Serilog.Sinks.MSSqlServer.Tests.Sinks.MSSqlServer.ColumnOptions +{ + public class TestTimeStampColumnOptions + { + [Trait("Bugfix", "#187")] + [Fact] + public void CanSetDataTypeDateTime() + { + // arrange + var options = new Serilog.Sinks.MSSqlServer.ColumnOptions(); + + // act - should not throw + options.TimeStamp.DataType = SqlDbType.DateTime; + } + + [Trait("Bugfix", "#187")] + [Fact] + public void CanSetDataTypeDateTimeOffset() + { + // arrange + var options = new Serilog.Sinks.MSSqlServer.ColumnOptions(); + + // act - should not throw + options.TimeStamp.DataType = SqlDbType.DateTimeOffset; + } + + [Trait("Bugfix", "#187")] + [Fact] + public void CannotSetDataTypeNVarChar() + { + // arrange + var options = new Serilog.Sinks.MSSqlServer.ColumnOptions(); + + // act and assert - should throw + Assert.Throws(() => options.TimeStamp.DataType = SqlDbType.NVarChar); + } + } +} diff --git a/test/Serilog.Sinks.MSSqlServer.Tests/Sinks/MSSqlServer/TestMSSqlServerSinkTraits.cs b/test/Serilog.Sinks.MSSqlServer.Tests/Sinks/MSSqlServer/TestMSSqlServerSinkTraits.cs new file mode 100644 index 00000000..41583fd2 --- /dev/null +++ b/test/Serilog.Sinks.MSSqlServer.Tests/Sinks/MSSqlServer/TestMSSqlServerSinkTraits.cs @@ -0,0 +1,110 @@ +using Serilog.Events; +using Serilog.Parsing; +using System; +using System.Collections.Generic; +using System.Data; +using System.Globalization; +using System.Linq; +using Xunit; + +namespace Serilog.Sinks.MSSqlServer.Tests.Sinks.MSSqlServer +{ + public class TestMSSqlServerSinkTraits + { + private MSSqlServerSinkTraits traits; + private LogEvent logEvent; + + [Trait("Bugfix", "#187")] + [Fact] + public void GetColumnsAndValuesCreatesTimeStampOfTypeDateTimeAccordingToColumnOptions() + { + // arrange + var options = new Serilog.Sinks.MSSqlServer.ColumnOptions(); + var testDateTimeOffset = new DateTimeOffset(2020, 1, 1, 9, 0, 0, new TimeSpan(1, 0, 0)); // Timezone +1:00 + SetupTest(options, testDateTimeOffset); + + // act + var columns = traits.GetColumnsAndValues(logEvent); + + // assert + var timeStampColumn = columns.Single(c => c.Key == options.TimeStamp.ColumnName); + Assert.IsType(timeStampColumn.Value); + Assert.Equal(testDateTimeOffset.Hour, ((DateTime)timeStampColumn.Value).Hour); + } + + [Trait("Bugfix", "#187")] + [Fact] + public void GetColumnsAndValuesCreatesUtcConvertedTimeStampOfTypeDateTimeAccordingToColumnOptions() + { + // arrange + var options = new Serilog.Sinks.MSSqlServer.ColumnOptions + { + TimeStamp = { ConvertToUtc = true } + }; + var testDateTimeOffset = new DateTimeOffset(2020, 1, 1, 9, 0, 0, new TimeSpan(1, 0, 0)); // Timezone +1:00 + SetupTest(options, testDateTimeOffset); + + // act + var columns = traits.GetColumnsAndValues(logEvent); + + // assert + var timeStampColumn = columns.Single(c => c.Key == options.TimeStamp.ColumnName); + Assert.IsType(timeStampColumn.Value); + Assert.Equal(testDateTimeOffset.Hour - 1, ((DateTime)timeStampColumn.Value).Hour); + } + + [Trait("Bugfix", "#187")] + [Fact] + public void GetColumnsAndValuesCreatesTimeStampOfTypeDateTimeOffsetAccordingToColumnOptions() + { + // arrange + var options = new Serilog.Sinks.MSSqlServer.ColumnOptions + { + TimeStamp = { DataType = SqlDbType.DateTimeOffset } + }; + var testDateTimeOffset = new DateTimeOffset(2020, 1, 1, 9, 0, 0, new TimeSpan(1, 0, 0)); // Timezone +1:00 + SetupTest(options, testDateTimeOffset); + + // act + var columns = traits.GetColumnsAndValues(logEvent); + + // assert + var timeStampColumn = columns.Single(c => c.Key == options.TimeStamp.ColumnName); + Assert.IsType(timeStampColumn.Value); + var timeStampColumnOffset = (DateTimeOffset)timeStampColumn.Value; + Assert.Equal(testDateTimeOffset.Hour, timeStampColumnOffset.Hour); + Assert.Equal(testDateTimeOffset.Offset, timeStampColumnOffset.Offset); + } + + [Trait("Bugfix", "#187")] + [Fact] + public void GetColumnsAndValuesCreatesUtcConvertedTimeStampOfTypeDateTimeOffsetAccordingToColumnOptions() + { + // arrange + var options = new Serilog.Sinks.MSSqlServer.ColumnOptions + { + TimeStamp = { DataType = SqlDbType.DateTimeOffset, ConvertToUtc = true } + }; + var testDateTimeOffset = new DateTimeOffset(2020, 1, 1, 9, 0, 0, new TimeSpan(1, 0, 0)); // Timezone +1:00 + SetupTest(options, testDateTimeOffset); + + // act + var columns = traits.GetColumnsAndValues(logEvent); + + // assert + var timeStampColumn = columns.Single(c => c.Key == options.TimeStamp.ColumnName); + Assert.IsType(timeStampColumn.Value); + var timeStampColumnOffset = (DateTimeOffset)timeStampColumn.Value; + Assert.Equal(testDateTimeOffset.Hour - 1, timeStampColumnOffset.Hour); + Assert.Equal(new TimeSpan(0), timeStampColumnOffset.Offset); + } + + private void SetupTest(Serilog.Sinks.MSSqlServer.ColumnOptions options, DateTimeOffset testDateTimeOffset) + { + this.traits = new MSSqlServerSinkTraits("connectionString", "tableName", "schemaName", + options, CultureInfo.InvariantCulture, false); + this.logEvent = new LogEvent(testDateTimeOffset, LogEventLevel.Information, null, + new MessageTemplate(new List()), new List()); + } + } +} diff --git a/test/Serilog.Sinks.MSSqlServer.Tests/TestTimeStamp.cs b/test/Serilog.Sinks.MSSqlServer.Tests/TestTimeStamp.cs new file mode 100644 index 00000000..1df8e4a6 --- /dev/null +++ b/test/Serilog.Sinks.MSSqlServer.Tests/TestTimeStamp.cs @@ -0,0 +1,104 @@ +using System; +using System.Data; +using System.Data.SqlClient; +using System.IO; +using Dapper; +using FluentAssertions; +using Xunit; + +namespace Serilog.Sinks.MSSqlServer.Tests +{ + [Collection("LogTest")] + public class TestTimeStamp : IDisposable + { + [Trait("Bugfix", "#187")] + [Fact] + public void CanCreateDatabaseWithDateTimeByDefault() + { + // arrange + var loggerConfiguration = new LoggerConfiguration(); + Log.Logger = loggerConfiguration.WriteTo.MSSqlServer( + connectionString: DatabaseFixture.LogEventsConnectionString, + tableName: DatabaseFixture.LogTableName, + autoCreateSqlTable: true, + batchPostingLimit: 1, + period: TimeSpan.FromSeconds(10), + columnOptions: new ColumnOptions()) + .CreateLogger(); + + // act + const string loggingInformationMessage = "Logging Information message"; + Log.Information(loggingInformationMessage); + Log.CloseAndFlush(); + + // assert + using (var conn = new SqlConnection(DatabaseFixture.LogEventsConnectionString)) + { + var logEvents = conn.Query($"SELECT TimeStamp FROM {DatabaseFixture.LogTableName}"); + logEvents.Should().NotBeEmpty(); + } + } + + [Trait("Bugfix", "#187")] + [Fact] + public void CanStoreDateTimeOffsetWithCorrectLocalTimeZone() + { + // arrange + var loggerConfiguration = new LoggerConfiguration(); + Log.Logger = loggerConfiguration.WriteTo.MSSqlServer( + connectionString: DatabaseFixture.LogEventsConnectionString, + tableName: DatabaseFixture.LogTableName, + autoCreateSqlTable: true, + batchPostingLimit: 1, + period: TimeSpan.FromSeconds(10), + columnOptions: new ColumnOptions { TimeStamp = { DataType = SqlDbType.DateTimeOffset, ConvertToUtc = false }}) + .CreateLogger(); + var dateTimeOffsetNow = DateTimeOffset.Now; + + // act + const string loggingInformationMessage = "Logging Information message"; + Log.Information(loggingInformationMessage); + Log.CloseAndFlush(); + + // assert + using (var conn = new SqlConnection(DatabaseFixture.LogEventsConnectionString)) + { + var logEvents = conn.Query($"SELECT TimeStamp FROM {DatabaseFixture.LogTableName}"); + logEvents.Should().Contain(e => e.TimeStamp.Offset == dateTimeOffsetNow.Offset); + } + } + + [Trait("Bugfix", "#187")] + [Fact] + public void CanStoreDateTimeOffsetWithUtcTimeZone() + { + // arrange + var loggerConfiguration = new LoggerConfiguration(); + Log.Logger = loggerConfiguration.WriteTo.MSSqlServer( + connectionString: DatabaseFixture.LogEventsConnectionString, + tableName: DatabaseFixture.LogTableName, + autoCreateSqlTable: true, + batchPostingLimit: 1, + period: TimeSpan.FromSeconds(10), + columnOptions: new ColumnOptions { TimeStamp = { DataType = SqlDbType.DateTimeOffset, ConvertToUtc = true } }) + .CreateLogger(); + + // act + const string loggingInformationMessage = "Logging Information message"; + Log.Information(loggingInformationMessage); + Log.CloseAndFlush(); + + // assert + using (var conn = new SqlConnection(DatabaseFixture.LogEventsConnectionString)) + { + var logEvents = conn.Query($"SELECT TimeStamp FROM {DatabaseFixture.LogTableName}"); + logEvents.Should().Contain(e => e.TimeStamp.Offset == new TimeSpan(0)); + } + } + + public void Dispose() + { + DatabaseFixture.DropTable(); + } + } +}