Logging and Structured Logging
Implement effective logging for debugging and monitoring applications.
A Simple Analogy
Structured logging is like a detailed ship's log. Instead of "engine problem," log "Engine temp: 85C, pressure: 45psi, timestamp: 14:32:15, location: coordinates." Structured data enables searching, filtering, and pattern detection.
What Is Structured Logging?
Structured logging captures information as machine-readable key-value pairs instead of unstructured text. This enables powerful querying and analysis.
Why Use Structured Logging?
- Searchability: Query logs by field (user, status, etc.)
- Analysis: Aggregate and correlate events
- Monitoring: Alert on patterns
- Debugging: Rich context for troubleshooting
- Performance: Track latency, throughput
Logging Levels
| Level | Use Case | |-------|----------| | Debug | Detailed development information | | Information | General application events | | Warning | Something unexpected (recoverable) | | Error | Error conditions (unrecoverable) | | Critical | System failure imminent |
.NET Built-in Logging
public class UserService
{
private readonly ILogger<UserService> _logger;
public UserService(ILogger<UserService> logger)
{
_logger = logger;
}
public async Task<User> CreateUserAsync(CreateUserDto dto)
{
_logger.LogInformation("Creating user: {Email}", dto.Email);
if (string.IsNullOrEmpty(dto.Email))
{
_logger.LogWarning("CreateUser called with empty email");
throw new ArgumentException("Email required");
}
try
{
var user = await _repository.CreateAsync(dto);
_logger.LogInformation("User created: {UserId} {Email}", user.Id, user.Email);
return user;
}
catch (Exception ex)
{
_logger.LogError(ex, "Error creating user: {Email}", dto.Email);
throw;
}
}
}
Structured Logging with Serilog
// Install: Serilog, Serilog.Sinks.Console, Serilog.Sinks.File
var logger = new LoggerConfiguration()
.MinimumLevel.Information()
.WriteTo.Console(
outputTemplate: "[{Timestamp:yyyy-MM-dd HH:mm:ss}] [{Level:u3}] {Message:lj}{NewLine}{Exception}"
)
.WriteTo.File(
"logs/app-.txt",
rollingInterval: RollingInterval.Day,
outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss} [{Level:u3}] {Message:lj} {Properties}{NewLine}{Exception}"
)
.Enrich.FromLogContext() // Add contextual data
.Enrich.WithProperty("Application", "MyApp")
.Enrich.WithMachineName()
.CreateLogger();
Log.Logger = logger;
// ASP.NET Core integration
builder.Host.UseSerilog();
Contextual Logging
public class OrderProcessor
{
private readonly ILogger<OrderProcessor> _logger;
public async Task ProcessOrderAsync(Order order)
{
using (_logger.BeginScope(new Dictionary<string, object>
{
["OrderId"] = order.Id,
["CustomerId"] = order.CustomerId,
["Amount"] = order.Amount
}))
{
_logger.LogInformation("Processing order");
try
{
await _paymentService.ProcessAsync(order);
_logger.LogInformation("Payment processed successfully");
await _shipmentService.ShipAsync(order);
_logger.LogInformation("Order shipped");
}
catch (Exception ex)
{
_logger.LogError(ex, "Order processing failed");
throw;
}
}
}
}
// Log output will include OrderId, CustomerId, Amount in every log within the scope
Correlation ID for Tracing
public class CorrelationIdMiddleware
{
public async Task InvokeAsync(HttpContext context, ILogger<CorrelationIdMiddleware> logger)
{
var correlationId = context.Request.Headers.TryGetValue("X-Correlation-ID", out var id)
? id.ToString()
: Guid.NewGuid().ToString();
context.Items["CorrelationId"] = correlationId;
using (LogContext.PushProperty("CorrelationId", correlationId))
{
_logger.LogInformation("Request started");
await _next(context);
_logger.LogInformation("Request completed");
}
}
}
// Now all logs in this request share the same CorrelationId
Practical Example
public class PaymentService
{
private readonly ILogger<PaymentService> _logger;
public async Task<PaymentResult> ProcessAsync(Payment payment)
{
var stopwatch = Stopwatch.StartNew();
try
{
_logger.LogInformation(
"Processing payment: Amount={Amount} Currency={Currency} Method={Method}",
payment.Amount, payment.Currency, payment.Method
);
var result = await _provider.ProcessAsync(payment);
stopwatch.Stop();
_logger.LogInformation(
"Payment processed in {ElapsedMs}ms. Status={Status} TransactionId={TransactionId}",
stopwatch.ElapsedMilliseconds, result.Status, result.TransactionId
);
return result;
}
catch (Exception ex)
{
stopwatch.Stop();
_logger.LogError(
ex,
"Payment processing failed after {ElapsedMs}ms. Amount={Amount}",
stopwatch.ElapsedMilliseconds, payment.Amount
);
throw;
}
}
}
Best Practices
- Include context: User ID, order ID, correlation IDs
- Use appropriate levels: Don't log everything as Info
- Structured data: Use named parameters
- Correlation IDs: Track requests across services
- Sensitive data: Don't log passwords, tokens, PII
Related Concepts to Explore
- ELK Stack (Elasticsearch, Logstash, Kibana)
- Application Insights
- Distributed tracing
- Log aggregation and analysis
- Performance monitoring with logs
Summary
Structured logging provides searchable, analyzable application insights. Implement contextual logging with correlation IDs to trace requests across distributed systems and troubleshoot issues quickly.