Merge pull request #142 from serilog-contrib/dev

prevent duplicate rowkey

samples/SampleStressTest/Program.cs

@@ -0,0 +1,53 @@
+using Azure.Data.Tables;
+
+using Microsoft.Extensions.Configuration;
+using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.DependencyInjection.Extensions;
+using Microsoft.Extensions.Hosting;
+
+using Serilog;
+
+namespace SampleStressTest;
+
+internal static class Program
+{
+    public static async Task<int> Main(string[] args)
+    {
+        try
+        {
+            var app = Host
+                .CreateDefaultBuilder(args)
+                .ConfigureServices(services => services
+                    .AddHostedService<StressTestService>()
+                    .TryAddSingleton(sp =>
+                    {
+                        var configuration = sp.GetRequiredService<IConfiguration>();
+                        var connectionString = configuration.GetConnectionString("StorageAccount");
+                        return new TableServiceClient(connectionString);
+                    })
+                )
+                .UseSerilog((context, services, configuration) => configuration
+                    .ReadFrom.Services(services)
+                    .Enrich.FromLogContext()
+                    .WriteTo.AzureTableStorage(
+                        storageAccount: services.GetRequiredService<TableServiceClient>(),
+                        storageTableName: "SampleStressTest"
+                    )
+                )
+                .Build();
+
+            await app.RunAsync();
+
+            return 0;
+        }
+        catch (Exception ex)
+        {
+            Log.Fatal(ex, "Host terminated unexpectedly");
+            return 1;
+        }
+        finally
+        {
+            await Log.CloseAndFlushAsync();
+        }
+    }
+}

samples/SampleStressTest/SampleStressTest.csproj

@@ -0,0 +1,31 @@
+<Project Sdk="Microsoft.NET.Sdk">
+
+  <PropertyGroup>
+    <OutputType>Exe</OutputType>
+    <TargetFramework>net8.0</TargetFramework>
+    <ImplicitUsings>enable</ImplicitUsings>
+    <Nullable>enable</Nullable>
+  </PropertyGroup>
+
+  <ItemGroup>
+    <None Remove="appsettings.json" />
+  </ItemGroup>
+
+  <ItemGroup>
+    <Content Include="appsettings.json">
+      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
+      <ExcludeFromSingleFile>true</ExcludeFromSingleFile>
+      <CopyToPublishDirectory>PreserveNewest</CopyToPublishDirectory>
+    </Content>
+  </ItemGroup>
+
+  <ItemGroup>
+    <PackageReference Include="Microsoft.Extensions.Hosting" Version="8.0.0" />
+    <PackageReference Include="Serilog.Extensions.Hosting" Version="8.0.0" />
+  </ItemGroup>
+
+  <ItemGroup>
+    <ProjectReference Include="..\..\src\Serilog.Sinks.AzureTableStorage\Serilog.Sinks.AzureTableStorage.csproj" />
+  </ItemGroup>
+
+</Project>

samples/SampleStressTest/StressTestService.cs

@@ -0,0 +1,62 @@
+using Microsoft.Extensions.Hosting;
+using Microsoft.Extensions.Logging;
+
+namespace SampleStressTest;
+
+public class StressTestService : IHostedLifecycleService
+{
+    private readonly ILogger<StressTestService> _logger;
+
+    public StressTestService(ILogger<StressTestService> logger)
+    {
+        this._logger = logger;
+    }
+
+    public Task StartAsync(CancellationToken cancellationToken)
+    {
+        _logger.LogInformation("StartAsync Called");
+        return Task.CompletedTask;
+    }
+
+    public Task StartedAsync(CancellationToken cancellationToken)
+    {
+        _logger.LogInformation("StartedAsync Called");
+
+        // hammer the logger
+        var result = Parallel.For(1, 10000, index =>
+        {
+            _logger.LogInformation("Logging Loop {index}", index);
+            _logger.LogInformation("Another Entry {index}", index);
+            _logger.LogInformation("Duplicate Entry {index}", index);
+        });
+
+        _logger.LogInformation("Stress test: {completed}", result.IsCompleted);
+
+        return Task.CompletedTask;
+    }
+
+    public Task StartingAsync(CancellationToken cancellationToken)
+    {
+        _logger.LogInformation("StartingAsync Called");
+        return Task.CompletedTask;
+    }
+
+    public Task StopAsync(CancellationToken cancellationToken)
+    {
+        _logger.LogInformation("StopAsync Called");
+        return Task.CompletedTask;
+    }
+
+    public Task StoppedAsync(CancellationToken cancellationToken)
+    {
+        _logger.LogInformation("StoppedAsync Called");
+        return Task.CompletedTask;
+    }
+
+    public Task StoppingAsync(CancellationToken cancellationToken)
+    {
+        _logger.LogInformation("StoppingAsync Called");
+        return Task.CompletedTask;
+    }
+
+}

samples/SampleStressTest/appsettings.json

@@ -0,0 +1,12 @@
+{
+  "Logging": {
+    "LogLevel": {
+      "Default": "Information",
+      "Microsoft.AspNetCore": "Warning"
+    }
+  },
+  "ConnectionStrings": {
+    "StorageAccount": "DefaultEndpointsProtocol=http;AccountName=devstoreaccount1;AccountKey=Eby8vdM02xNOcqFlqUwJPLlmEtlCDXJ1OUzFT50uSRZ6IFsuFq2UVErCz4I6tq/K1SZFPTOtr/KBHBeksoGMGw==;BlobEndpoint=http://127.0.0.1:10000/devstoreaccount1;QueueEndpoint=http://127.0.0.1:10001/devstoreaccount1;TableEndpoint=http://127.0.0.1:10002/devstoreaccount1;"
+  },
+  "AllowedHosts": "*"
+}

samples/SampleWebApplication/Pages/Logs.cshtml

@@ -66,7 +66,8 @@
                 <colgroup>
                     <col style="width: 30px" />
                     <col style="width: 30px" />
-                    <col style="width: 200px" />
+                    <col style="width: 100px" />
+                    <col style="width: 150px" />
                     <col style="width: 120px" />
                     <col style="" />
                 </colgroup>
@@ -75,6 +76,7 @@
                         <th scope="col"></th>
                         <th scope="col"></th>
                         <th scope="col">Date</th>
+                        <th scope="col">Time</th>
                         <th scope="col">Level</th>
                         <th scope="col">Message</th>
                     </tr>
@@ -111,7 +113,8 @@
                                         break;
                                 }
                             </td>
-                            <td>@log.Timestamp?.ToString("g")</td>
+                            <td>@log.Timestamp?.ToString("d")</td>
+                            <td>@log.Timestamp?.ToString("hh:mm:ss.fffffff")</td>
                             <td>@log.Level</td>
                             <td>@log.RenderedMessage</td>
                         </tr>

serilog-sinks-azuretablestorage.sln

@@ -20,6 +20,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "SampleWebApplication", "sam
 EndProject
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "SampleConsoleApplication", "samples\SampleConsoleApplication\SampleConsoleApplication.csproj", "{2F82E3DC-7071-41AD-A1E9-9CB70CF27CDA}"
 EndProject
+Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "SampleStressTest", "samples\SampleStressTest\SampleStressTest.csproj", "{31F5B01D-F6D1-4802-B412-167A424F3818}"
+EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
 		Debug|Any CPU = Debug|Any CPU
@@ -42,13 +44,18 @@ Global
 		{2F82E3DC-7071-41AD-A1E9-9CB70CF27CDA}.Debug|Any CPU.Build.0 = Debug|Any CPU
 		{2F82E3DC-7071-41AD-A1E9-9CB70CF27CDA}.Release|Any CPU.ActiveCfg = Release|Any CPU
 		{2F82E3DC-7071-41AD-A1E9-9CB70CF27CDA}.Release|Any CPU.Build.0 = Release|Any CPU
+		{31F5B01D-F6D1-4802-B412-167A424F3818}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{31F5B01D-F6D1-4802-B412-167A424F3818}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{31F5B01D-F6D1-4802-B412-167A424F3818}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{31F5B01D-F6D1-4802-B412-167A424F3818}.Release|Any CPU.Build.0 = Release|Any CPU
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE
 	EndGlobalSection
 	GlobalSection(NestedProjects) = preSolution
 		{420A3E41-C520-420D-95E6-24CF86BF7477} = {18BA35F3-24C4-4297-859A-C3DCB2D00488}
 		{2F82E3DC-7071-41AD-A1E9-9CB70CF27CDA} = {18BA35F3-24C4-4297-859A-C3DCB2D00488}
+		{31F5B01D-F6D1-4802-B412-167A424F3818} = {18BA35F3-24C4-4297-859A-C3DCB2D00488}
 	EndGlobalSection
 	GlobalSection(ExtensibilityGlobals) = postSolution
 		SolutionGuid = {73E16F7E-6DF4-4355-BF3C-73DDBBA1867E}

src/Serilog.Sinks.AzureTableStorage/LoggerConfigurationAzureTableStorageExtensions.cs

@@ -38,7 +38,7 @@ public static class LoggerConfigurationAzureTableStorageExtensions
     /// A reasonable default for the number of events posted in
     /// each batch.
     /// </summary>
-    public const int DefaultBatchSizeLimit = 100;
+    public const int DefaultBatchSizeLimit = 1000;
 
     /// <summary>
     /// A reasonable default time to wait between checking for event batches.

src/Serilog.Sinks.AzureTableStorage/Sinks/AzureTableStorage/DefaultKeyGenerator.cs

@@ -1,4 +1,5 @@
 using System;
+using System.Threading;
 
 using Serilog.Events;
 using Serilog.Sinks.AzureTableStorage.Extensions;
@@ -10,6 +11,7 @@ namespace Serilog.Sinks.AzureTableStorage;
 /// </summary>
 public class DefaultKeyGenerator : IKeyGenerator
 {
+
     /// <summary>
     /// Automatically generates the PartitionKey based on the logEvent timestamp
     /// </summary>
@@ -33,7 +35,7 @@ public virtual string GeneratePartitionKey(LogEvent logEvent, AzureTableStorageS
     }
 
     /// <summary>
-    /// Automatically generates the RowKey using the timestamp 
+    /// Automatically generates the RowKey using the timestamp
     /// </summary>
     /// <param name="logEvent">the log event</param>
     /// <param name="options">The table storage options.</param>
@@ -48,4 +50,69 @@ public virtual string GenerateRowKey(LogEvent logEvent, AzureTableStorageSinkOpt
         var utcEventTime = logEvent.Timestamp.UtcDateTime;
         return utcEventTime.GenerateRowKey();
     }
+
+
+
+    /// <summary>
+    /// Generates the PartitionKey based on the logEvent timestamp
+    /// </summary>
+    /// <param name="utcEventTime">The UTC event time.</param>
+    /// <param name="roundSpan">The round span.</param>
+    /// <returns>
+    /// The Generated PartitionKey
+    /// </returns>
+    /// <remarks>
+    /// The partition key based on the Timestamp rounded to the nearest 5 min
+    /// </remarks>
+    public static string GeneratePartitionKey(DateTime utcEventTime, TimeSpan? roundSpan = null)
+    {
+        var span = roundSpan ?? TimeSpan.FromMinutes(5);
+        var roundedEvent = Round(utcEventTime, span);
+
+        // create a 19 character String for reverse chronological ordering.
+        return $"{DateTime.MaxValue.Ticks - roundedEvent.Ticks:D19}";
+    }
+
+    /// <summary>
+    /// Generates the RowKey using the timestamp
+    /// </summary>
+    /// <param name="utcEventTime">The UTC event time.</param>
+    /// <returns>
+    /// The generated RowKey
+    /// </returns>
+    public static string GenerateRowKey(DateTime utcEventTime)
+    {
+        // create a reverse chronological ordering date
+        var targetTicks = DateTime.MaxValue.Ticks - utcEventTime.Ticks;
+
+        // add incrementing value to ensure unique
+        int padding = Next();
+
+        return $"{targetTicks:D19}{padding:D4}";
+    }
+
+    /// <summary>
+    /// Rounds the specified date.
+    /// </summary>
+    /// <param name="date">The date to round.</param>
+    /// <param name="span">The span.</param>
+    /// <returns>The rounded date</returns>
+    public static DateTime Round(DateTime date, TimeSpan span)
+    {
+        long ticks = (date.Ticks + (span.Ticks / 2) + 1) / span.Ticks;
+        return new DateTime(ticks * span.Ticks);
+    }
+
+
+    private static int _counter = new Random().Next(_minCounter, _maxCounter);
+
+    private const int _minCounter = 1;
+    private const int _maxCounter = 9999;
+
+    private static int Next()
+    {
+        Interlocked.Increment(ref _counter);
+        return Interlocked.CompareExchange(ref _counter, _minCounter, _maxCounter);
+    }
+
 }

src/Serilog.Sinks.AzureTableStorage/Sinks/AzureTableStorage/Extensions/DateTimeExtensions.cs

@@ -7,6 +7,7 @@ namespace Serilog.Sinks.AzureTableStorage.Extensions;
 /// </summary>
 public static class DateTimeExtensions
 {
+
     /// <summary>
     /// Generates the PartitionKey based on the logEvent timestamp
     /// </summary>
@@ -20,11 +21,7 @@ public static class DateTimeExtensions
     /// </remarks>
     public static string GeneratePartitionKey(this DateTime utcEventTime, TimeSpan? roundSpan = null)
     {
-        var span = roundSpan ?? TimeSpan.FromMinutes(5);
-        var roundedEvent = Round(utcEventTime, span);
-
-        // create a 19 character String for reverse chronological ordering.
-        return $"{DateTime.MaxValue.Ticks - roundedEvent.Ticks:D19}";
+        return DefaultKeyGenerator.GeneratePartitionKey(utcEventTime, roundSpan);
     }
 
     /// <summary>
@@ -36,8 +33,7 @@ public static string GeneratePartitionKey(this DateTime utcEventTime, TimeSpan?
     /// </returns>
     public static string GenerateRowKey(this DateTime utcEventTime)
     {
-        // create a 19 character String for reverse chronological ordering.
-        return $"{DateTime.MaxValue.Ticks - utcEventTime.Ticks:D19}";
+        return DefaultKeyGenerator.GenerateRowKey(utcEventTime);
     }
 
     /// <summary>
@@ -48,7 +44,6 @@ public static string GenerateRowKey(this DateTime utcEventTime)
     /// <returns>The rounded date</returns>
     public static DateTime Round(this DateTime date, TimeSpan span)
     {
-        long ticks = (date.Ticks + (span.Ticks / 2) + 1) / span.Ticks;
-        return new DateTime(ticks * span.Ticks);
+        return DefaultKeyGenerator.Round(date, span);
     }
 }