logging（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

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 <= 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<T>:

public class SerilogLoggerAdapter<T> : ILogger<T>
{
    private readonly Serilog.ILogger _logger;
    
    public SerilogLoggerAdapter()
    {
        _logger = Serilog.Log.ForContext<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

Anti-Patterns

References

• Serilog Best Practices
• Structured Logging