Logging Study Portal

Additional notes

Principles and Goals

• Observability first: Capture structured events (no free-form strings) with fields for correlation IDs, tenant, region, and service version.
• Consistency across tiers: Standardize ILogger scopes and message templates so API, workers, and background jobs emit comparable fields.
• Backpressure-aware: Protect the app by sampling noisy events (e.g., debug traces) and using bounded queues for async sinks.
• Fail-safe: Logging must never block request completion; prefer drop-and-alert over throttling callers.

Recommended Stack

• Microsoft.Extensions.Logging as the facade for framework integrations.
• Structured logger: Serilog or Seq sink for JSON; use message-template placeholders ({OrderId}) instead of string interpolation.
• OpenTelemetry: Export traces/logs/metrics consistently; include W3C trace/context propagation headers.
• Shipping: Centralize via OTLP/HTTP, gRPC, or Kafka; avoid writing to local disk in containers except for bootstrap/debug.
• NLog context:
• Where it shines: Mature ecosystem with rich target support (file, database, email, Azure Log Analytics), high-performance async targets, and flexible routing/layouts for multi-tenant or blue/green rollouts.
• Advantages: Simple XML/JSON configuration, fast text file output, built-in filtering/rules, and battle-tested community extensions. Great when you need to fan out to multiple sinks without custom code.
• Trade-offs: Configuration can become verbose, JSON structure requires explicit layouts, and mixing NLog APIs with ILogger can create duplicate pipelines. Prefer running NLog behind Microsoft.Extensions.Logging via the NLog provider to keep a single abstraction and leverage dependency injection.
• Operational note: Keep targets async, set overflowAction="Discard" or sampling for noisy rules, and set per-environment config (dev = verbose file, prod = centralized structured logs) through NLog.config transforms.

Patterns to Prefer

• Message templates over interpolation: logger.LogInformation("Processed {Count} items", count); avoids unnecessary string formatting when disabled.
• Enriched scopes: Wrap requests with using var scope = logger.BeginScope(new { CorrelationId = traceId, Tenant = tenant }); so child logs inherit fields.
• Categorized loggers: Request typed loggers per class (ILogger<CheckoutHandler>) for filters and metrics alignment.
• Level hygiene:
• Critical/Error: actionable failures only.
• Warning: degradation/path to failure.
• Information: business milestones.
• Debug/Trace: development and short-term diagnostics; gate behind config.
• Async/buffered sinks: Use non-blocking background queues with bounded capacity; drop oldest or sample when full.
• Health/availability focus: Emit heartbeats and dependency outcome events (latency, status, retries) to support SLO dashboards.

High-Performance Techniques

• Avoid work when disabled: Use message templates (no interpolation) and guard expensive work with logger.IsEnabled(LogLevel.Debug).
• Prefer compile-time logging in hot paths: Use LoggerMessage source generators for high-volume events (less boxing/allocations).
• Keep request threads off I/O: Use async/buffered sinks with bounded queues; choose overflow behavior (Discard vs block) intentionally.
• Avoid expensive enrichers/layouts by default: Callsite/stacktrace capture and deep object serialization can dominate CPU; enable only for short-lived debugging.
• Batch and flush strategically: Batch OTLP/HTTP exports; tune batch sizes/flush intervals to keep p95/p99 latency stable.
• Control volume: Use sampling/rate limiting on noisy categories and add time-bounded flags for temporary Debug/Trace.
• Avoid allocations on hot paths: Prefer value types for high-frequency metrics; avoid string concatenation; reach for Span<T>/stackalloc when shaping log arguments.
• Pre-allocate logger scopes: Reuse static EventId and pre-built scope state where possible; avoid creating dictionaries or anonymous objects for fields that don't change between calls.
• Tune buffers: Size async sink channels based on peak RPS and expected burst size; expose metrics for dropped events so the sink doesn't silently swallow them.

Code examples (proper + low overhead)

1) Message templates + EventId (cheap when disabled)

private static readonly EventId OrderAccepted = new(2001, nameof(OrderAccepted));

logger.LogInformation(
    OrderAccepted,
    "Order {OrderId} accepted for {Tenant} in {ElapsedMs}ms",
    orderId,
    tenant,
    elapsedMs);

2) Avoid interpolated strings (allocates even if not logged)

// ❌ Avoid (allocates string regardless of level)
logger.LogDebug($"Calculated price for {sku}: {price}");

// ✅ Prefer (no formatting work when Debug is disabled)
logger.LogDebug("Calculated price for {Sku}: {Price}", sku, price);

3) Guard expensive work (serialization, LINQ, stack traces)

if (logger.IsEnabled(LogLevel.Debug))
{
    var payloadJson = JsonSerializer.Serialize(payload); // potentially expensive
    logger.LogDebug("Outgoing payload: {PayloadJson}", payloadJson);
}

4) Correct exception logging (keep stack trace)

try
{
    await processor.ProcessAsync(order, ct);
}
catch (Exception ex)
{
    logger.LogError(ex, "Order {OrderId} processing failed", order.Id);
    throw;
}

5) Use scopes for correlation (applies to all nested logs)

using var scope = logger.BeginScope(new Dictionary<string, object>
{
    ["CorrelationId"] = correlationId,
    ["Tenant"] = tenant,
    ["Region"] = region
});

logger.LogInformation("Checkout started");

6) High-volume logging with LoggerMessage source generator

internal static partial class CheckoutLog
{
    [LoggerMessage(
        EventId = 3001,
        Level = LogLevel.Information,
        Message = "Charged {Amount} {Currency} for order {OrderId}")]
    public static partial void Charged(
        this ILogger logger,
        decimal amount,
        string currency,
        Guid orderId);
}

// usage
CheckoutLog.Charged(logger, amount, currency, orderId);

7) Simple rate limiting for noisy warnings (protects throughput)

private static long _suppressed;
private static long _lastLogTicks;

// Allow one log per second (example)
var now = Environment.TickCount64;
var last = Interlocked.Read(ref _lastLogTicks);

if (now - last >= 1000 &&
    Interlocked.CompareExchange(ref _lastLogTicks, now, last) == last)
{
    var dropped = Interlocked.Exchange(ref _suppressed, 0);
    logger.LogWarning("Cache miss storm detected (suppressed {SuppressedCount} warnings)", dropped);
}
else
{
    Interlocked.Increment(ref _suppressed);
}

NLog: Performance Playbook (Practical)

• Use NLog via Microsoft.Extensions.Logging: Keep one abstraction (ILogger) and route to NLog with NLog.Extensions.Logging.
• Make targets non-blocking: Wrap file/network targets in AsyncWrapper with a bounded queueLimit; decide overflowAction (often Discard for high-RPS services).
• Keep layouts cheap: Avoid ${callsite}, ${stacktrace}, and ${all-event-properties} in production rules; explicitly list JSON attributes you need.
• Tune file target for throughput: For single-process file logging, prefer keepFileOpen="true" (lower overhead). If multiple processes must write the same file, use concurrentWrites="true" (slower, but safe).
• Don’t pre-format strings: Prefer logger.LogDebug("Order {OrderId} validated in {ElapsedMs}ms", orderId, elapsedMs) and only compute heavy values when the level is enabled.

NLog.config example (bounded async file)

<targets>
  <target xsi:type="AsyncWrapper"
          name="asyncFile"
          queueLimit="10000"
          overflowAction="Discard">
    <target xsi:type="File"
            fileName="${basedir}/logs/app-${shortdate}.log"
            keepFileOpen="true"
            concurrentWrites="false"
            layout="${longdate}|${level:uppercase=true}|${logger}|${message} ${exception:format=ToString}" />
  </target>
</targets>

<rules>
  <logger name="Microsoft.*" maxlevel="Info" writeTo="asyncFile" final="true" />
  <logger name="System.*" maxlevel="Info" writeTo="asyncFile" final="true" />
  <logger name="*" minlevel="Info" writeTo="asyncFile" />
</rules>

NLog.config example (JSON + scopes for correlation)

<targets>
  <target xsi:type="AsyncWrapper"
          name="asyncJsonFile"
          queueLimit="20000"
          overflowAction="Discard">
    <target xsi:type="File"
            fileName="${basedir}/logs/app-${shortdate}.jsonl"
            keepFileOpen="true"
            concurrentWrites="false">
      <layout xsi:type="JsonLayout" includeAllProperties="false">
        <attribute name="ts" layout="${date:format=o}" />
        <attribute name="level" layout="${level:uppercase=true}" />
        <attribute name="logger" layout="${logger}" />
        <attribute name="message" layout="${message}" />
        <attribute name="eventId" layout="${event-properties:item=EventId_Id}" />
        <attribute name="correlationId" layout="${scopeproperty:CorrelationId}" />
        <attribute name="tenant" layout="${scopeproperty:Tenant}" />
        <attribute name="traceId" layout="${activity:property=TraceId}" />
        <attribute name="spanId" layout="${activity:property=SpanId}" />
        <attribute name="exception" layout="${exception:format=ToString}" />
      </layout>
    </target>
  </target>
</targets>

Program.cs sketch (NLog provider)

builder.Logging.ClearProviders();
builder.Host.UseNLog();

Operational Best Practices

• Correlate everything: Propagate trace/span IDs across HTTP, messaging, and background jobs.
• Schema discipline: Maintain a central log schema (event name, category, correlation, tenant, outcome, duration).
• PII controls: Classify fields and redact at the edge; log tokens/credentials only in secure staging with strict retention.
• Deployment safety: Use configuration-driven sinks/levels; favor hot-reloadable changes (appsettings, feature flags) over redeploys.
• Alerting: Alert on error-rate deltas, burst of dropped events, and missing heartbeats rather than raw log volume.
• What to log (and not):
• Log: Request/response envelope metadata (not bodies) for public APIs, dependency outcomes (latency/status/retries), domain milestones (order accepted/settled), security-relevant events (authn/z decisions), and drop reason when sampling/discarding.
• Avoid: Large payloads, secrets, personal data, high-cardinality values (raw GUID lists), and repetitive success spam in hot loops. Summarize counts instead.
• Environments:
• Local/dev: Enable Debug/Trace, file/console targets, and payload logging only with synthetic data.
• Staging: Mirror production sinks/levels; allow short-term Debug with sampling for reproductions.
• Production: Default to Information for business events and Warning/Error for issues; enable Debug/Trace only via time-bound flags with sampling to protect throughput and cost.
• Performance guardrails: Keep hot-path logging off by default, prefer structured summaries, and set per-rule rate limits so troubleshooting toggles don't DOS the service.

Sample Diagnostic Pattern (Resilient HTTP Client)

public class InventoryClient
{
    private static readonly EventId FetchInventory = new(1001, nameof(FetchAsync));
    private readonly HttpClient _httpClient;
    private readonly ILogger<InventoryClient> _logger;

    public InventoryClient(HttpClient httpClient, ILogger<InventoryClient> logger)
    {
        _httpClient = httpClient;
        _logger = logger;
    }

    public async Task<InventoryResponse?> FetchAsync(string sku, CancellationToken ct)
    {
        using var scope = _logger.BeginScope(new { Sku = sku });

        _logger.LogInformation(FetchInventory, "Fetching inventory");

        try
        {
            var response = await _httpClient.GetAsync($"/inventory/{sku}", ct);
            var body = await response.Content.ReadAsStringAsync(ct);

            if (!response.IsSuccessStatusCode)
            {
                _logger.LogWarning("Inventory lookup failed with {StatusCode} and body length {Length}",
                    (int)response.StatusCode, body.Length);
                return null;
            }

            _logger.LogInformation("Inventory fetched successfully in {ElapsedMs} ms",
                response.Headers.GetValues("X-ElapsedMs").FirstOrDefault());

            return JsonSerializer.Deserialize<InventoryResponse>(body);
        }
        catch (OperationCanceledException) when (ct.IsCancellationRequested)
        {
            _logger.LogWarning("Inventory fetch canceled by caller");
            throw;
        }
        catch (Exception ex)
        {
            _logger.LogError(ex, "Unexpected failure during inventory fetch");
            throw;
        }
    }
}