20. Advanced Logging with Serilog

  1. Advanced Logging with Serilog

About this chapter

Replace default logging with Serilog for advanced structured logging capabilities including multiple sinks, enrichers, and centralized log aggregation.

  • Serilog advantages: Structured logging, flexible sinks, and semantic message templates
  • Installation: Core packages and enricher libraries
  • Configuration: Setting up Serilog in Program.cs and appsettings.json
  • Sinks: Writing logs to console, files, and centralized systems like Seq
  • Enrichers: Adding contextual information (machine name, thread ID, user ID)
  • Request logging: Capturing HTTP request/response details automatically

Learning outcomes:

  • Install and configure Serilog in ASP.NET Core
  • Write logs to multiple sinks simultaneously
  • Use enrichers to add contextual information
  • Configure file rolling and retention policies
  • Set up centralized logging with Seq
  • Log HTTP requests with custom enrichment

20.1 NEW: Installing Serilog

# Core Serilog packages
dotnet add package Serilog.AspNetCore
dotnet add package Serilog.Sinks.Console
dotnet add package Serilog.Sinks.File
dotnet add package Serilog.Sinks.Seq

# Additional enrichers
dotnet add package Serilog.Enrichers.Environment
dotnet add package Serilog.Enrichers.Process
dotnet add package Serilog.Enrichers.Thread
dotnet add package Serilog.Expressions

Why Serilog:

  • Structured Logging: First-class support for structured data
  • Flexible Sinks: Write to multiple destinations simultaneously
  • Rich Formatting: JSON, compact JSON, plain text
  • Message Templates: Efficient, semantic logging
  • Enrichers: Add contextual information automatically
  • Performance: High-throughput, low-allocation

20.2 Configuring Serilog

// Program.cs - Early initialization
using Serilog;
using Serilog.Events;
using Serilog.Formatting.Compact;

// Configure Serilog BEFORE building the host
Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Debug()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
    .MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning)
    .MinimumLevel.Override("Microsoft.EntityFrameworkCore", LogEventLevel.Warning)
    .Enrich.FromLogContext()
    .Enrich.WithMachineName()
    .Enrich.WithEnvironmentName()
    .Enrich.WithThreadId()
    .Enrich.WithProcessId()
    .WriteTo.Console(
        outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj} " +
                       "{Properties:j}{NewLine}{Exception}")
    .WriteTo.File(
        path: "logs/commandapi-.log",
        rollingInterval: RollingInterval.Day,
        outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] " +
                       "{Message:lj}{NewLine}{Exception}",
        retainedFileCountLimit: 31)
    .WriteTo.File(
        new CompactJsonFormatter(),
        path: "logs/commandapi-.json",
        rollingInterval: RollingInterval.Day,
        retainedFileCountLimit: 31)
    .WriteTo.Seq(
        serverUrl: "http://localhost:5341",
        restrictedToMinimumLevel: LogEventLevel.Debug)
    .CreateLogger();

try
{
    Log.Information("Starting CommandAPI application");
    
    var builder = WebApplication.CreateBuilder(args);
    
    // Replace built-in logging with Serilog
    builder.Host.UseSerilog();
    
    // ... rest of service configuration
    
    var app = builder.Build();
    
    // Add Serilog request logging (logs HTTP requests)
    app.UseSerilogRequestLogging(options =>
    {
        // Customize request logging
        options.MessageTemplate = 
            "HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms";
        
        options.EnrichDiagnosticContext = (diagnosticContext, httpContext) =>
        {
            diagnosticContext.Set("RequestHost", httpContext.Request.Host.Value);
            diagnosticContext.Set("RequestScheme", httpContext.Request.Scheme);
            diagnosticContext.Set("UserAgent", httpContext.Request.Headers["User-Agent"]);
            
            // Add user information if authenticated
            if (httpContext.User.Identity?.IsAuthenticated == true)
            {
                diagnosticContext.Set("UserId",
                     httpContext.User.FindFirst(ClaimTypes.NameIdentifier)?.Value);
            }
        };
        
        // Custom log level based on response
        options.GetLevel = (httpContext, elapsed, ex) =>
        {
            if (ex != null) return LogEventLevel.Error;
            if (httpContext.Response.StatusCode > 499) return LogEventLevel.Error;
            if (httpContext.Response.StatusCode > 399) return LogEventLevel.Warning;
            return LogEventLevel.Information;
        };
    });
    
    // ... rest of middleware
    
    app.Run();
}
catch (Exception ex)
{
    Log.Fatal(ex, "Application terminated unexpectedly");
}
finally
{
    Log.CloseAndFlush();
}

Configuration from appsettings.json:

{
  "Serilog": {
    "Using": ["Serilog.Sinks.Console", "Serilog.Sinks.File", "Serilog.Sinks.Seq"],
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Microsoft": "Warning",
        "Microsoft.AspNetCore": "Warning",
        "Microsoft.EntityFrameworkCore.Database.Command": "Information",
        "CommandAPI": "Debug",
        "System": "Warning"
      }
    },
    "WriteTo": [
      {
        "Name": "Console",
        "Args": {
          "outputTemplate": "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj} {Properties:j}{NewLine}{Exception}"
        }
      },
      {
        "Name": "File",
        "Args": {
          "path": "logs/commandapi-.log",
          "rollingInterval": "Day",
          "retainedFileCountLimit": 31,
          "outputTemplate": "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] {Message:lj}{NewLine}{Exception}"
        }
      },
      {
        "Name": "Seq",
        "Args": {
          "serverUrl": "http://localhost:5341"
        }
      }
    ],
    "Enrich": ["FromLogContext", "WithMachineName", "WithThreadId", "WithEnvironmentName"],
    "Properties": {
      "Application": "CommandAPI"
    }
  }
}

// Program.cs - Read from configuration
var builder = WebApplication.CreateBuilder(args);

builder.Host.UseSerilog((context, services, configuration) => configuration
    .ReadFrom.Configuration(context.Configuration)
    .ReadFrom.Services(services)
    .Enrich.FromLogContext());

20.3 Configuring Sinks

Console Sink (Development):

.WriteTo.Console(
    restrictedToMinimumLevel: LogEventLevel.Debug,
    outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {SourceContext}{NewLine}" +
                   "{Message:lj}{NewLine}{Exception}",
    theme: Serilog.Sinks.SystemConsole.Themes.AnsiConsoleTheme.Code)

File Sink (All Environments):

// Text file with rotation
.WriteTo.File(
    path: "logs/commandapi-.log",
    rollingInterval: RollingInterval.Day,        // New file daily
    rollOnFileSizeLimit: true,                   // Roll if file too large
    fileSizeLimitBytes: 10_485_760,              // 10 MB
    retainedFileCountLimit: 31,                  // Keep 31 days
    outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} " +
                   "[{Level:u3}] [{SourceContext}] {Message:lj}{NewLine}{Exception}")

// JSON file for machine parsing
.WriteTo.File(
    new CompactJsonFormatter(),
    path: "logs/commandapi-.json",
    rollingInterval: RollingInterval.Day,
    retainedFileCountLimit: 31)

Seq Sink (Structured Log Server):

.WriteTo.Seq(
    serverUrl: builder.Configuration["Seq:ServerUrl"] ?? "http://localhost:5341",
    apiKey: builder.Configuration["Seq:ApiKey"],
    restrictedToMinimumLevel: LogEventLevel.Information)

Running Seq with Docker:

# Add to docker-compose.yaml
services:
  seq:
    image: datalust/seq:latest
    container_name: seq_logs
    ports:
      - "5341:80"
    environment:
      ACCEPT_EULA: Y
    volumes:
      - seq_data:/data

volumes:
  seq_data:
    driver: local

docker-compose up -d seq
# Access Seq UI at http://localhost:5341

Application Insights Sink (Azure):

dotnet add package Serilog.Sinks.ApplicationInsights

.WriteTo.ApplicationInsights(
    telemetryConfiguration: builder.Configuration["ApplicationInsights:InstrumentationKey"],
    telemetryConverter: TelemetryConverter.Traces)

Async Wrapper (Performance):

dotnet add package Serilog.Sinks.Async

.WriteTo.Async(a => a.File(
    path: "logs/commandapi-.log",
    rollingInterval: RollingInterval.Day))

20.4 Structured Logging Benefits

Message Templates:

// ❌ String interpolation (not structured)
_logger.LogInformation($"User {userId} created platform {platformName}");

// ✅ Message template (structured)
_logger.LogInformation(
    "User {UserId} created platform {PlatformName}",
    userId,
    platformName);

Query Benefits in Seq:

-- Find all platform creations by specific user
UserId = "auth0|12345" AND PlatformName IS NOT NULL

-- Find slow operations
Elapsed > 1000

-- Find errors in specific controller
SourceContext LIKE "%PlatformsController%" AND @Level = "Error"

-- Find all operations for a specific platform
PlatformId = 42

-- Complex query
UserId = "auth0|12345" AND @Level IN ["Warning", "Error"] AND Elapsed > 500

Structured Data Example:

_logger.LogInformation(
    "Command created: {CommandId} on platform {PlatformId} " +
    "by user {UserId} with {@CommandDetails}",
    command.Id,
    command.PlatformId,
    userId,
    new 
    {
        command.HowTo,
        command.CommandLine,
        CreatedAt = command.CreatedAt,
        PlatformName = command.Platform.PlatformName
    });

// Log output (JSON):
{
  "Timestamp": "2025-11-20T10:30:45.1234567Z",
  "Level": "Information",
  "MessageTemplate": "Command created: {CommandId} on platform {PlatformId} by user {UserId} with {@CommandDetails}",
  "Properties": {
    "CommandId": 123,
    "PlatformId": 5,
    "UserId": "auth0|12345",
    "CommandDetails": {
      "HowTo": "Run container",
      "CommandLine": "docker run",
      "CreatedAt": "2025-11-20T10:30:45",
      "PlatformName": "Docker"
    },
    "SourceContext": "CommandAPI.Controllers.CommandsController",
    "MachineName": "WEB01",
    "ThreadId": 15
  }
}

Destructuring Operators:

// @ - Destructure object (serialize properties)
_logger.LogInformation("Created {@Platform}", platform);

// $ - Serialize to string (ToString())
_logger.LogInformation("Created {$Platform}", platform);

// No operator - Use ToString()
_logger.LogInformation("Created {Platform}", platform);

20.5 Log Enrichment

Built-in Enrichers:

.Enrich.FromLogContext()           // Add properties via LogContext.PushProperty
.Enrich.WithMachineName()          // Add machine name
.Enrich.WithThreadId()             // Add thread ID
.Enrich.WithProcessId()            // Add process ID
.Enrich.WithEnvironmentName()      // Add environment (Dev, Prod)
.Enrich.WithEnvironmentUserName()  // Add OS user

Custom Enricher:

using Serilog.Core;
using Serilog.Events;

public class ApplicationVersionEnricher : ILogEventEnricher
{
    private LogEventProperty? _cachedProperty;
    
    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        _cachedProperty ??= propertyFactory.CreateProperty(
            "Version",
            typeof(Program).Assembly.GetName().Version?.ToString() ?? "Unknown");
        
        logEvent.AddPropertyIfAbsent(_cachedProperty);
    }
}

// Usage
.Enrich.With<ApplicationVersionEnricher>()

Request Context Enrichment:

public class RequestLoggingMiddleware
{
    private readonly RequestDelegate _next;
    
    public RequestLoggingMiddleware(RequestDelegate next)
    {
        _next = next;
    }
    
    public async Task InvokeAsync(HttpContext context)
    {
        // Add request ID to all logs in this request
        using (LogContext.PushProperty("RequestId", context.TraceIdentifier))
        using (LogContext.PushProperty("UserAgent", context.Request.Headers["User-Agent"].ToString()))
        using (LogContext.PushProperty("ClientIp", context.Connection.RemoteIpAddress?.ToString()))
        {
            // Add user ID if authenticated
            if (context.User.Identity?.IsAuthenticated == true)
            {
                var userId = context.User.FindFirst(ClaimTypes.NameIdentifier)?.Value;
                using (LogContext.PushProperty("UserId", userId))
                {
                    await _next(context);
                }
            }
            else
            {
                await _next(context);
            }
        }
    }
}

// Register middleware
app.UseMiddleware<RequestLoggingMiddleware>();

Correlation IDs:

public class CorrelationIdMiddleware
{
    private readonly RequestDelegate _next;
    private const string CorrelationIdHeaderName = "X-Correlation-ID";
    
    public CorrelationIdMiddleware(RequestDelegate next)
    {
        _next = next;
    }
    
    public async Task InvokeAsync(HttpContext context)
    {
        // Get or create correlation ID
        var correlationId = context.Request.Headers[CorrelationIdHeaderName].FirstOrDefault()
                            ?? Guid.NewGuid().ToString();
        
        // Add to response headers
        context.Response.Headers.Add(CorrelationIdHeaderName, correlationId);
        
        // Add to all logs in this request
        using (LogContext.PushProperty("CorrelationId", correlationId))
        {
            await _next(context);
        }
    }
}

20.6 REVISIT: Updating Background Jobs with Proper Logging

ProcessCommandJob with Serilog:

public class ProcessCommandJob
{
    private readonly ICommandRepository _commandsRepo;
    private readonly IBulkJobRepository _bulkJobRepo;
    private readonly IMapper _mapper;
    private readonly ILogger<ProcessCommandJob> _logger;
    
    public ProcessCommandJob(
        ICommandRepository commandsRepo,
        IBulkJobRepository bulkJobRepo,
        IMapper mapper,
        ILogger<ProcessCommandJob> logger)
    {
        _commandsRepo = commandsRepo;
        _bulkJobRepo = bulkJobRepo;
        _mapper = mapper;
        _logger = logger;
    }
    
    [AutomaticRetry(Attempts = 0)]
    public async Task Execute(
        string userId, 
        CommandMutateDto[] commandMutateDtos,
         PerformContext context)
    {
        string jobId = context.BackgroundJob.Id;
        int totalCommands = commandMutateDtos.Length;
        
        // Add job context to all logs
        using (LogContext.PushProperty("JobId", jobId))
        using (LogContext.PushProperty("UserId", userId))
        using (LogContext.PushProperty("TotalCommands", totalCommands))
        {
            _logger.LogInformation(
                "Starting bulk command processing job {JobId} for user {UserId} " +
                "with {TotalCommands} commands",
                jobId,
                userId,
                totalCommands);
            
            var stopwatch = System.Diagnostics.Stopwatch.StartNew();
            int position = 0;
            int successCount = 0;
            int failureCount = 0;
            var failures = new List<(int Position, string Error)>();
            
            foreach (var commandDto in commandMutateDtos)
            {
                position++;
                string? exceptionMessage = null;
                
                var commandModel = _mapper.Map<Command>(commandDto);
                commandModel.UserId = userId;
                
                try
                {
                    _logger.LogDebug(
                        "Processing command at position {Position}/{TotalCommands}: {@CommandDto}",
                        position,
                        totalCommands,
                        commandDto);
                    
                    await _commandsRepo.CreateCommandAsync(commandModel);
                    await _commandsRepo.SaveChangesAsync();
                    
                    successCount++;
                    
                    _logger.LogInformation(
                        "Successfully created command {CommandId} at position {Position}. " +
                        "HowTo: {HowTo}, Platform: {PlatformId}",
                        commandModel.Id,
                        position,
                        commandModel.HowTo,
                        commandModel.PlatformId);
                }
                catch (DbUpdateException dbuEx)
                {
                    failureCount++;
                    exceptionMessage = dbuEx.Message;
                    failures.Add((position, exceptionMessage));
                    
                    _logger.LogError(dbuEx,
                        "Database error at position {Position}. " +
                        "CommandLine: {CommandLine}, Platform: {PlatformId}. " +
                        "Error: {ErrorMessage}",
                        position,
                        commandDto.CommandLine,
                        commandDto.PlatformId,
                        exceptionMessage);
                    
                    _commandsRepo.DetachModelState(commandModel);
                }
                catch (Exception ex)
                {
                    failureCount++;
                    exceptionMessage = ex.Message;
                    failures.Add((position, exceptionMessage));
                    
                    _logger.LogError(ex,
                        "Unexpected error at position {Position}. " +
                        "CommandLine: {CommandLine}",
                        position,
                        commandDto.CommandLine);
                    
                    _commandsRepo.DetachModelState(commandModel);
                }
                finally
                {
                    // Store job result
                    var bulkJobResult = new BulkJobResult
                    {
                        Position = position,
                        LoadData = JsonConvert.SerializeObject(commandModel),
                        ObjectId = commandModel.Id,
                        ObjectType = commandModel.GetType().Name,
                        LoadException = exceptionMessage ?? "n/a",
                        JobId = jobId
                    };
                    await _bulkJobRepo.CreateBulkJobResultAsync(bulkJobResult);
                    await _bulkJobRepo.SaveChangesAsync();
                }
                
                // Log progress every 10 commands
                if (position % 10 == 0)
                {
                    _logger.LogInformation(
                        "Progress: {ProcessedCount}/{TotalCommands} processed. " +
                        "Success: {SuccessCount}, Failed: {FailureCount}",
                        position,
                        totalCommands,
                        successCount,
                        failureCount);
                }
            }
            
            stopwatch.Stop();
            
            // Final summary with all details
            _logger.LogInformation(
                "Bulk job {JobId} completed in {ElapsedMs}ms. " +
                "Total: {TotalCommands}, Success: {SuccessCount}, Failed: {FailureCount}, " +
                "Success Rate: {SuccessRate:P2}",
                jobId,
                stopwatch.ElapsedMilliseconds,
                totalCommands,
                successCount,
                failureCount,
                totalCommands > 0 ? (double)successCount / totalCommands : 0);
            
            if (failureCount > 0)
            {
                _logger.LogWarning(
                    "Job {JobId} had {FailureCount} failures: {@Failures}",
                    jobId,
                    failureCount,
                    failures);
            }
        }
    }
}

Hangfire Dashboard with Serilog:

// Log Hangfire job lifecycle events
GlobalJobFilters.Filters.Add(new HangfireLoggingFilter());

public class HangfireLoggingFilter : JobFilterAttribute,
     IClientFilter, IServerFilter, IElectStateFilter, IApplyStateFilter
{
    private static readonly ILogger Logger =
         Log.ForContext<HangfireLoggingFilter>();
    
    public void OnCreating(CreatingContext context)
    {
        Logger.Information(
            "Creating job {JobId} of type {JobType}",
            context.BackgroundJob?.Id ?? "unknown",
            context.Job.Type.Name);
    }
    
    public void OnCreated(CreatedContext context)
    {
        Logger.Information(
            "Job {JobId} created successfully",
            context.BackgroundJob?.Id);
    }
    
    public void OnPerforming(PerformingContext context)
    {
        Logger.Information(
            "Starting job {JobId} of type {JobType}",
            context.BackgroundJob.Id,
            context.BackgroundJob.Job.Type.Name);
    }
    
    public void OnPerformed(PerformedContext context)
    {
        if (context.Exception != null)
        {
            Logger.Error(context.Exception,
                "Job {JobId} failed with exception",
                context.BackgroundJob.Id);
        }
        else
        {
            Logger.Information(
                "Job {JobId} completed successfully",
                context.BackgroundJob.Id);
        }
    }
    
    public void OnStateElection(ElectStateContext context)
    {
        Logger.Debug(
            "Job {JobId} state election: {NewState}",
            context.BackgroundJob.Id,
            context.CandidateState.Name);
    }
    
    public void OnStateApplied(ApplyStateContext context, IWriteOnlyTransaction transaction)
    {
        Logger.Information(
            "Job {JobId} state changed to {NewState}",
            context.BackgroundJob.Id,
            context.NewState.Name);
    }
    
    public void OnStateUnapplied(ApplyStateContext context, IWriteOnlyTransaction transaction)
    {
    }
}