Merge pull request #310 from KodrAus/feat/trace-sample

Add tracing to seqcli sample ingest

Author: nblumhardt

src/Roastery/Data/Database.cs

@@ -7,6 +7,9 @@
 using System.Threading.Tasks;
 using Roastery.Util;
 using Serilog;
+using Serilog.Events;
+using SerilogTracing;
+using SerilogTracing.Instrumentation;
 
 namespace Roastery.Data;
 
@@ -134,17 +137,23 @@ static string AsSqlLiteral(object? o)
 
     async Task LogExecAsync(string sql, int rowCount)
     {
+        using var activity = _logger.StartActivity("Execution of {Sql}", sql);
+
         if (Distribution.OnceIn(200))
         {
-            throw new OperationCanceledException(
+            var exception = new OperationCanceledException(
                 "A deadlock was detected and the transaction chosen as the deadlock victim.");
-        }
 
-        var sw = Stopwatch.StartNew();
+            activity.Complete(LogEventLevel.Error, exception);
+
+            throw exception;
+        }
+        
+        
         var delay = 10 + (int)(Distribution.Uniform() * Math.Pow(rowCount, 1.6));
         await Task.Delay(delay);
-        _logger.Debug("Execution of {Sql} affected {RowCount} rows in {Elapsed:0.000} ms",
-            sql, rowCount, sw.Elapsed.TotalMilliseconds);
+        
+        activity.AddProperty("RowCount", rowCount);
     }
 
     static T Clone<T>(T value) where T: IIdentifiable, new()

src/Roastery/Program.cs

@@ -21,7 +21,7 @@ public static async Task Main(ILogger logger, CancellationToken cancellationToke
 
         var database = new Database(webApplicationLogger, "roastery");
         DatabaseMigrator.Populate(database);
-            
+
         var client = new HttpClient(
             "https://roastery.datalust.co",
             new NetworkLatencyMiddleware(
@@ -35,13 +35,13 @@ public static async Task Main(ILogger logger, CancellationToken cancellationToke
                             }, webApplicationLogger))))));
 
         var agents = new List<Agent>();
-            
+
         for (var i = 0; i < 100; ++i)
             agents.Add(new Customer(client, Person.Generate(), (int)Distribution.Uniform(60000, 180000)));
-            
+
         for (var i = 0; i < 3; ++i)
             agents.Add(new WarehouseStaff(client));
-            
+
         var batchApplicationLogger = logger.ForContext("Application", "Roastery Batch Processing");
         agents.Add(new CatalogBatch(client, batchApplicationLogger));
         agents.Add(new ArchivingBatch(client, batchApplicationLogger));

src/Roastery/Roastery.csproj

@@ -4,9 +4,10 @@
         <TargetFramework>net8.0</TargetFramework>
         <Nullable>enable</Nullable>
     </PropertyGroup>
-    
+
     <ItemGroup>
         <PackageReference Include="Serilog" Version="3.1.1" />
+        <PackageReference Include="SerilogTracing" Version="1.0.0-dev-00088" />
     </ItemGroup>
 
 </Project>

src/Roastery/Web/RequestLoggingMiddleware.cs

@@ -1,10 +1,11 @@
 using System;
-using System.Diagnostics;
 using System.Net;
 using System.Threading.Tasks;
 using Serilog;
 using Serilog.Context;
 using Serilog.Events;
+using SerilogTracing;
+using SerilogTracing.Instrumentation;
 
 namespace Roastery.Web;
 
@@ -22,15 +23,16 @@ public RequestLoggingMiddleware(ILogger logger, HttpServer next)
     public override async Task<HttpResponse> InvokeAsync(HttpRequest request)
     {
         using var _ = LogContext.PushProperty("RequestId", request.RequestId);
-            
-        var sw = Stopwatch.StartNew();
+
+        using var activity = _logger.StartActivity("HTTP {RequestMethod} {RequestPath}", request.Method, request.Path);
+
         try
         {
             var response = await _next.InvokeAsync(request);
-            LogCompletion(null, request, sw, response.StatusCode);
+            LogCompletion(activity, null, response.StatusCode);
             return response;
         }
-        catch (Exception ex1) when (LogCompletion(ex1, request, sw, HttpStatusCode.InternalServerError))
+        catch (Exception ex1) when (LogCompletion(activity, ex1, HttpStatusCode.InternalServerError))
         {
             // We never hit this, because the exception filter always returns false.
             throw;
@@ -41,12 +43,13 @@ public override async Task<HttpResponse> InvokeAsync(HttpRequest request)
         }
     }
 
-    bool LogCompletion(Exception? exception, HttpRequest request, Stopwatch sw, HttpStatusCode statusCode)
+    bool LogCompletion(LoggerActivity activity, Exception? exception, HttpStatusCode statusCode)
     {
         var level = (int)statusCode >= 500 ? LogEventLevel.Error : LogEventLevel.Information;
-        _logger.Write(level, exception,
-            "HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.000} ms",
-            request.Method, request.Path, (int)statusCode, sw.Elapsed.TotalMilliseconds);
+
+        activity.AddProperty("StatusCode", (int)statusCode);
+        activity.Complete(level, exception);
+        
         return false;
     }
 }

src/SeqCli/Ingestion/TraceConstants.cs

@@ -0,0 +1,8 @@
+namespace SeqCli.Ingestion;
+
+static class TraceConstants
+{
+    internal const string ParentSpanIdProperty = "ParentSpanId";
+
+    internal const string SpanStartTimestampProperty = "SpanStartTimestamp";
+}

src/SeqCli/Output/OutputFormatter.cs

@@ -1,3 +1,4 @@
+using SeqCli.Ingestion;
 using SeqCli.Levels;
 using Serilog.Formatting;
 using Serilog.Templates;
@@ -7,6 +8,6 @@ namespace SeqCli.Output;
 static class OutputFormatter
 {
     internal static readonly ITextFormatter Json = new ExpressionTemplate(
-        $"{{ {{@t, @mt, @l: coalesce({LevelMapping.SurrogateLevelProperty}, if @l = 'Information' then undefined() else @l), @x, @sp, @tr, @ps, @st, ..rest()}} }}\n"
+        $"{{ {{@t, @mt, @l: coalesce({LevelMapping.SurrogateLevelProperty}, if @l = 'Information' then undefined() else @l), @x, @sp, @tr, @ps: coalesce({TraceConstants.ParentSpanIdProperty}, @ps), @st: coalesce({TraceConstants.SpanStartTimestampProperty}, @st), ..rest()}} }}\n"
     );
 }

src/SeqCli/Sample/Loader/Simulation.cs

@@ -17,6 +17,7 @@
 using Seq.Api;
 using SeqCli.Ingestion;
 using Serilog;
+using SerilogTracing;
 
 namespace SeqCli.Sample.Loader;
 
@@ -26,7 +27,7 @@ public static async Task RunAsync(SeqConnection connection, string? apiKey, int
     {
         var buffer = new BufferingSink();
 
-        await using var logger = new LoggerConfiguration()
+        var logger = new LoggerConfiguration()
             .MinimumLevel.Debug()
             .Enrich.FromLogContext()
             .Enrich.WithProperty("Origin", "seqcli sample ingest")