logging

Logging

Overview

Effective logging is essential for debugging, monitoring, and understanding application behavior. This skill covers structured logging patterns using Serilog.

Definition of Done (DoD)

All significant operations are logged with appropriate level
Logs include correlation IDs for request tracing
Sensitive data is never logged (passwords, tokens, PII)
Log messages are structured (use templates, not string concatenation)
Errors include exception details and context
Log levels are appropriate (not everything is Warning/Error)

Log Levels Guide

Level When to Use Example

Verbose Detailed debugging only Method entry/exit, loop iterations

Debug Development diagnostics Parameter values, state changes

Information Normal operations Startup, shutdown, user actions

Warning Unexpected but handled Retry attempted, fallback used

Error Operation failed Exception caught, feature unavailable

Fatal App cannot continue Startup failure, critical resource missing

Structured Logging

Do's and Don'ts

// ❌ BAD - String interpolation loses structure Log.Information($"User {userId} loaded widget {widgetId}");

// ❌ BAD - String concatenation Log.Information("User " + userId + " loaded widget " + widgetId);

// ✅ GOOD - Message template with named properties Log.Information("User {UserId} loaded widget {WidgetId}", userId, widgetId);

// ✅ GOOD - Destructure complex objects Log.Information("Widget loaded: {@Widget}", widget);

// ✅ GOOD - Stringify instead of destructure for simple representation Log.Information("Position changed to {$Position}", position);

Property Naming

// Use PascalCase for consistency Log.Information("Widget {WidgetKey} installed by {UserName}", key, user);

// Prefix counts/durations with descriptive names Log.Information("Loaded {WidgetCount} widgets in {LoadDurationMs}ms", count, elapsed);

// Use consistent names across the codebase // - WidgetKey, not WidgetId or Key // - UserId, not User or UserID // - DurationMs, not Time or Elapsed

Correlation Context

Setting Correlation ID

public static class CorrelationContext { private static readonly AsyncLocal<string?> CurrentId = new();

public static string? Current => CurrentId.Value;

public static IDisposable BeginScope(string? correlationId = null)
{
    var id = correlationId ?? GenerateId();
    var previous = CurrentId.Value;
    CurrentId.Value = id;
    
    // Push to Serilog context
    return new CorrelationScope(previous, LogContext.PushProperty("CorrelationId", id));
}

private static string GenerateId() => Guid.NewGuid().ToString("N")[..8];

private class CorrelationScope : IDisposable
{
    private readonly string? _previous;
    private readonly IDisposable _logContext;
    
    public CorrelationScope(string? previous, IDisposable logContext)
    {
        _previous = previous;
        _logContext = logContext;
    }
    
    public void Dispose()
    {
        CurrentId.Value = _previous;
        _logContext.Dispose();
    }
}

}

Using Correlation

[RelayCommand] private async Task InstallWidgetAsync(WidgetPackage package, CancellationToken ct) { using var _ = CorrelationContext.BeginScope($"install-{package.PackageId}");

Log.Information("Starting widget installation: {PackageId}", package.PackageId);

try
{
    await _installer.InstallAsync(package, ct);
    Log.Information("Widget installation completed: {PackageId}", package.PackageId);
}
catch (Exception ex)
{
    Log.Error(ex, "Widget installation failed: {PackageId}", package.PackageId);
    throw;
}

}

Operation Logging

Timed Operations

public class OperationLogger : IDisposable { private readonly string _operationName; private readonly Stopwatch _stopwatch; private readonly IDisposable _logContext; private bool _completed;

private OperationLogger(string operationName, params (string Key, object Value)[] properties)
{
    _operationName = operationName;
    _stopwatch = Stopwatch.StartNew();
    
    var enrichers = properties
        .Select(p => LogContext.PushProperty(p.Key, p.Value))
        .ToList();
    
    _logContext = new CompositeDisposable(enrichers);
    
    Log.Debug("Operation started: {OperationName}", operationName);
}

public static OperationLogger Begin(string operationName, params (string, object)[] properties)
    => new(operationName, properties);

public void Complete()
{
    _completed = true;
    Log.Information(
        "Operation completed: {OperationName} in {DurationMs}ms",
        _operationName, _stopwatch.ElapsedMilliseconds);
}

public void Dispose()
{
    _stopwatch.Stop();
    
    if (!_completed)
    {
        Log.Warning(
            "Operation abandoned: {OperationName} after {DurationMs}ms",
            _operationName, _stopwatch.ElapsedMilliseconds);
    }
    
    _logContext.Dispose();
}

}

// Usage public async Task ProcessWidgetsAsync(CancellationToken ct) { using var op = OperationLogger.Begin("ProcessWidgets", ("Count", widgets.Count));

foreach (var widget in widgets)
{
    await ProcessAsync(widget, ct);
}

op.Complete();

}

Sensitive Data Handling

Never Log These

// ❌ NEVER log sensitive data Log.Information("User logged in with password: {Password}", password); Log.Information("API Key: {ApiKey}", apiKey); Log.Information("Token: {Token}", accessToken); Log.Information("SSN: {SSN}", socialSecurityNumber);

// ✅ Log existence, not value Log.Information("User logged in: {Username}", username); Log.Information("API Key configured: {HasApiKey}", !string.IsNullOrEmpty(apiKey)); Log.Information("Token received: {TokenLength} characters", token?.Length ?? 0);

Masking Helper

public static class LogSanitizer { public static string Mask(string? value, int visibleChars = 4) { if (string.IsNullOrEmpty(value)) return "[empty]";

    if (value.Length &#x3C;= visibleChars * 2)
        return new string('*', value.Length);
    
    return value[..visibleChars] + new string('*', value.Length - visibleChars * 2) + value[^visibleChars..];
}

public static string MaskPath(string path)
{
    var userProfile = Environment.GetFolderPath(Environment.SpecialFolder.UserProfile);
    return path.Replace(userProfile, "[USER]");
}

}

// Usage Log.Information("Credential stored for: {MaskedKey}", LogSanitizer.Mask(apiKey)); Log.Error(ex, "Failed to read file: {Path}", LogSanitizer.MaskPath(filePath));

Logger Adapter

For infrastructure code that needs ILogger:

public class SerilogLoggerAdapter<T> : ILogger<T> { private readonly Serilog.ILogger _logger;

public SerilogLoggerAdapter()
{
    _logger = Serilog.Log.ForContext&#x3C;T>();
}

public void Log(LogLevel logLevel, string message, params object[] args)
{
    var serilogLevel = logLevel switch
    {
        LogLevel.Trace => LogEventLevel.Verbose,
        LogLevel.Debug => LogEventLevel.Debug,
        LogLevel.Information => LogEventLevel.Information,
        LogLevel.Warning => LogEventLevel.Warning,
        LogLevel.Error => LogEventLevel.Error,
        LogLevel.Critical => LogEventLevel.Fatal,
        _ => LogEventLevel.Information
    };
    
    _logger.Write(serilogLevel, message, args);
}

public void LogError(Exception ex, string message, params object[] args)
{
    _logger.Error(ex, message, args);
}

// ... other interface methods

}

Serilog Configuration

Development

Log.Logger = new LoggerConfiguration() .MinimumLevel.Debug() .MinimumLevel.Override("Microsoft", LogEventLevel.Warning) .MinimumLevel.Override("System", LogEventLevel.Warning) .Enrich.FromLogContext() .Enrich.WithMachineName() .Enrich.WithThreadId() .WriteTo.Debug(outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {CorrelationId} {Message:lj}{NewLine}{Exception}") .WriteTo.File( path: "logs/3sc-.log", rollingInterval: RollingInterval.Day, retainedFileCountLimit: 7, outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff} [{Level:u3}] {CorrelationId} {Message:lj}{NewLine}{Exception}") .CreateLogger();

Production

Log.Logger = new LoggerConfiguration() .MinimumLevel.Information() .MinimumLevel.Override("Microsoft", LogEventLevel.Warning) .MinimumLevel.Override("System", LogEventLevel.Warning) .Enrich.FromLogContext() .Enrich.WithMachineName() .WriteTo.File( path: Path.Combine( Environment.GetFolderPath(Environment.SpecialFolder.LocalApplicationData), "3SC", "logs", "3sc-.log"), rollingInterval: RollingInterval.Day, retainedFileCountLimit: 30, fileSizeLimitBytes: 50_000_000, // 50MB outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff} [{Level:u3}] [{CorrelationId}] {Message:lj}{NewLine}{Exception}") .CreateLogger();

Best Practices

Practice Reason

Use message templates Enables structured querying

Include correlation IDs Trace operations across components

Log at appropriate levels Don't flood with noise

Time long operations Performance visibility

Context over comments Logs explain what code is doing

Consistent property names Enables aggregation

Anti-Patterns

Anti-Pattern Problem Solution

String interpolation Loses structure Use message templates

Logging in hot paths Performance impact Sample or disable

Swallowing exceptions Hidden failures Always log errors

PII in logs Security/compliance Mask sensitive data

ToString() in logs Allocations even when filtered Let Serilog handle

References

Serilog Best Practices
Structured Logging

Safety Notice

Copy this and send it to your AI assistant to learn

Source Transparency

Related Skills

wpf-ui-shell

wpf-mvvm

data-access