【C#】ログ出力完全ガイド｜ILogger・構造化ログ・LoggerMessage・Serilog・スコープ・パフォーマンス最適化まで

int userId   = 42;
string order = "ORD-001";
decimal amount = 1280;

// NG: 文字列補間 → プロパティ名が失われ、単なる文字列としてしか検索できない
logger.LogInformation($"User {userId} placed order {order} for {amount}yen");
// → ログ基盤は "User 42 placed order ORD-001 for 1280yen" の1つの文字列しか見えない

// OK: メッセージテンプレート → プロパティごとに構造化される
logger.LogInformation(
    "User {UserId} placed order {OrderId} for {Amount}yen",
    userId, order, amount);
// → {
//     "Message": "User 42 placed order ORD-001 for 1280yen",
//     "UserId": 42,
//     "OrderId": "ORD-001",
//     "Amount": 1280
//   }
// → UserId = 42 や Amount > 1000 で検索・集計ができる

// @ プレフィックスでオブジェクトを展開（内部構造を保持）
logger.LogInformation("Order received: {@Order}", order);
// → Order プロパティがJSONオブジェクトとして保存される

// appsettings.json
{
  "Logging": {
    "LogLevel": {
      "Default": "Information",          // 既定
      "Microsoft.AspNetCore": "Warning", // ASP.NET Core の内部ログは Warning 以上
      "MyApp.Infrastructure": "Debug",   // 自分のライブラリの一部だけ詳細化
      "System.Net.Http": "Warning"
    },
    "Console": {
      "LogLevel": { "Default": "Information" }
    },
    "Debug": {
      "LogLevel": { "Default": "Debug" }  // Debug プロバイダだけ別レベル
    }
  }
}

// 階層マッチ: 長い名前が優先される
//   "MyApp.Infrastructure.DbConnection" は "MyApp.Infrastructure" の Debug に従う
//   "MyApp.Controllers" は "Default" の Information に従う

// NG: Trace が無効でも ExpensiveCompute() が毎回呼ばれる
logger.LogTrace("Details: {Data}", ExpensiveCompute());

// OK: IsEnabled で事前チェック
if (logger.IsEnabled(LogLevel.Trace))
    logger.LogTrace("Details: {Data}", ExpensiveCompute());

// メッセージテンプレートの値は遅延評価されない点に注意
// → 引数として渡したものは必ず評価される

// 従来の LogInformation は引数が object[] にボクシングされ、高頻度呼び出しでは GC 圧迫
// LoggerMessage.Define を使うと厳密な型のデリゲートが作られてボクシングなし・高速

public static class Log
{
    private static readonly Action<ILogger, int, string, Exception?> _orderProcessed =
        LoggerMessage.Define<int, string>(
            LogLevel.Information,
            eventId: new EventId(1001, nameof(OrderProcessed)),
            formatString: "Order {OrderId} processed for user {UserName}");

    public static void OrderProcessed(this ILogger logger, int orderId, string userName)
        => _orderProcessed(logger, orderId, userName, null);
}

// 呼び出し側
logger.OrderProcessed(42, "alice");

// .NET 6+ では source generator で LoggerMessage.Define 相当を自動生成できる
// 書きやすさと高速性を両立

public static partial class Log
{
    [LoggerMessage(
        EventId = 1001,
        Level   = LogLevel.Information,
        Message = "Order {OrderId} processed for user {UserName}")]
    public static partial void OrderProcessed(
        this ILogger logger, int orderId, string userName);

    [LoggerMessage(EventId = 2001, Level = LogLevel.Error,
        Message = "Payment failed for order {OrderId}")]
    public static partial void PaymentFailed(
        this ILogger logger, int orderId, Exception ex);
}

// 呼び出し側はメソッドを呼ぶだけ
logger.OrderProcessed(42, "alice");
logger.PaymentFailed(42, ex);
// → source generator が LoggerMessage.Define を生成
// → IsEnabled チェック・ボクシング回避・eventId 管理がすべて自動

// BeginScope のブロック内で出るログすべてに、指定したプロパティが自動付与される
public async Task<IActionResult> GetOrderAsync(int orderId)
{
    using (logger.BeginScope(new Dictionary<string, object>
    {
        ["OrderId"]       = orderId,
        ["CorrelationId"] = HttpContext.TraceIdentifier,
    }))
    {
        logger.LogInformation("Fetching order");
        var order = await _repo.FindAsync(orderId);

        logger.LogInformation("Order status: {Status}", order.Status);
        // ↑ この2つのログには OrderId と CorrelationId が自動で付く
    }
}

// 文字列テンプレート形式の BeginScope（ASP.NET Core で一般的）
using (logger.BeginScope("Processing request {RequestId}", Guid.NewGuid()))
{
    // スコープ内のログに RequestId が付く
}

try
{
    await ProcessOrderAsync(order);
}
catch (Exception ex)
{
    // NG: 例外を文字列補間で埋め込むとスタックトレースが失われる
    logger.LogError($"失敗: {ex.Message}");

    // NG: 例外を引数に渡すのは良いが、プロパティ名が失われている
    logger.LogError("Error: {Message}", ex.Message);

    // OK: 例外を第1引数、テンプレートを第2引数以降
    logger.LogError(ex, "Order {OrderId} processing failed", order.Id);
    // → 例外の型・メッセージ・スタックトレース・InnerException を構造化記録
    // → さらに OrderId もプロパティとして保存される

    throw;  // 必要なら再スロー
}

// 例外をログに出したら rethrow すべきか握り潰すかは明示的に
// 両方やるとログに2回出る「ダブルログ」になりがち

using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;

// Console アプリ・Worker Service でも IHostBuilder を使うのが現代的
var builder = Host.CreateApplicationBuilder(args);

// Logging 設定は appsettings.json から自動読み込みされる
builder.Services.AddTransient<OrderService>();

var app = builder.Build();

// 実行
var orderService = app.Services.GetRequiredService<OrderService>();
await orderService.ProcessAsync();

// OrderService 側
public sealed class OrderService(ILogger<OrderService> logger)
{
    public async Task ProcessAsync()
    {
        logger.LogInformation("開始");
        try { /* ... */ }
        catch (Exception ex)
        {
            logger.LogError(ex, "処理失敗");
        }
    }
}

// ① ILogger<T>: ほぼ常にこれ（カテゴリが型名になる）
public class UserService(ILogger<UserService> logger) { }

// ② ILoggerFactory: 動的にカテゴリを決めたい場合
public class GenericProcessor(ILoggerFactory factory)
{
    public void Process(string taskName)
    {
        var logger = factory.CreateLogger($"Processor.{taskName}");
        logger.LogInformation("開始");
    }
}

// ③ ILogger（型パラメータなし）: カテゴリが未定義になるので非推奨
// → ILogger<T> を使う

// NuGet パッケージ
// Serilog.AspNetCore                (ASP.NET Core 統合)
// Serilog.Sinks.Console            (コンソール出力)
// Serilog.Sinks.File               (ファイル出力)
// Serilog.Enrichers.Thread         (スレッド ID を付与)
// Serilog.Enrichers.Environment    (マシン名・ユーザー名)
// Serilog.Settings.Configuration   (appsettings.json から読み込む)

using Serilog;

var builder = WebApplication.CreateBuilder(args);

// Serilog を MEL の裏側として差し込む
builder.Host.UseSerilog((ctx, cfg) => cfg
    .ReadFrom.Configuration(ctx.Configuration)
    .Enrich.FromLogContext()
    .Enrich.WithMachineName()
    .Enrich.WithThreadId()
    .WriteTo.Console()
    .WriteTo.File(
        path: "logs/app-.log",
        rollingInterval: RollingInterval.Day,
        retainedFileCountLimit: 30,
        outputTemplate:
          "[{Timestamp:yyyy-MM-dd HH:mm:ss.fff} {Level:u3}] "
          "{Message:lj} {Properties:j}{NewLine}{Exception}"));

var app = builder.Build();
// アプリ内では ILogger<T> を普通に DI するだけで Serilog が裏で動く

// appsettings.json
{
  "Serilog": {
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Microsoft.AspNetCore": "Warning",
        "System.Net.Http": "Warning"
      }
    },
    "WriteTo": [
      { "Name": "Console" },
      {
        "Name": "File",
        "Args": {
          "path": "logs/app-.log",
          "rollingInterval": "Day",
          "retainedFileCountLimit": 30,
          "formatter": "Serilog.Formatting.Compact.CompactJsonFormatter, Serilog.Formatting.Compact"
        }
      },
      {
        "Name": "Seq",
        "Args": { "serverUrl": "http://seq.example.com:5341" }
      }
    ],
    "Enrich": [ "FromLogContext", "WithMachineName", "WithThreadId" ],
    "Properties": {
      "Application": "OrderService"
    }
  }
}

using Serilog;

// ① ブートストラップ用のロガー（設定ファイル読み込み前でも動く）
Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Information()
    .WriteTo.Console()
    .CreateBootstrapLogger();

try
{
    Log.Information("Starting up");

    var builder = WebApplication.CreateBuilder(args);

    // ② 本設定（ConfigurationManager が使えるようになったタイミング）
    builder.Host.UseSerilog((ctx, cfg) => cfg
        .ReadFrom.Configuration(ctx.Configuration));

    var app = builder.Build();
    app.Run();
}
catch (Exception ex)
{
    // builder.Build() 中の例外（設定エラー・DI 解決エラー）もここで拾える
    Log.Fatal(ex, "Startup failed");
}
finally
{
    // バッファされたログを必ずフラッシュ
    Log.CloseAndFlush();
}

Log.Logger = new LoggerConfiguration()
    .Enrich.FromLogContext()                              // BeginScope 相当
    .Enrich.WithMachineName()                             // MachineName
    .Enrich.WithEnvironmentName()                          // Env variable ASPNETCORE_ENVIRONMENT
    .Enrich.WithThreadId()                                // ThreadId
    .Enrich.WithProperty("Application", "OrderService")   // 固定プロパティ
    .Enrich.WithProperty("Version", typeof(Program).Assembly.GetName().Version!)
    .WriteTo.Console()
    .CreateLogger();

// ログに共通の Application・MachineName・ThreadId・Version が自動で付く

// カスタム Enricher も作れる（例: CorrelationId）
public sealed class CorrelationIdEnricher : ILogEventEnricher
{
    public void Enrich(LogEvent le, ILogEventPropertyFactory pf)
    {
        var id = Activity.Current?.TraceId.ToString() ?? "no-trace";
        le.AddPropertyIfAbsent(pf.CreateProperty("TraceId", id));
    }
}

// ASP.NET Core は Activity ベースで TraceId を自動発行する
// Serilog の Enrich.FromLogContext と組み合わせると全ログに TraceId が付く

app.Use(async (context, next) =>
{
    // リクエストヘッダーに X-Correlation-Id があればそれを使う、なければ新規生成
    var correlationId = context.Request.Headers["X-Correlation-Id"].FirstOrDefault()
                        ?? Guid.NewGuid().ToString();

    using (LogContext.PushProperty("CorrelationId", correlationId))
    {
        context.Response.Headers["X-Correlation-Id"] = correlationId;
        await next(context);
    }
});

// 下流 HTTP 呼び出しでも同じ CorrelationId を伝搬
public sealed class CorrelationIdHandler : DelegatingHandler
{
    private readonly IHttpContextAccessor _ctx;
    public CorrelationIdHandler(IHttpContextAccessor ctx) => _ctx = ctx;

    protected override async Task<HttpResponseMessage> SendAsync(
        HttpRequestMessage req, CancellationToken ct)
    {
        var id = _ctx.HttpContext?.Request.Headers["X-Correlation-Id"].FirstOrDefault();
        if (id is not null) req.Headers.Add("X-Correlation-Id", id);
        return await base.SendAsync(req, ct);
    }
}

using Microsoft.Extensions.Logging.Abstractions;

// ① テストで依存の ILogger<T> は NullLogger で満たす
[Fact]
public async Task Process_Success()
{
    var svc = new OrderService(NullLogger<OrderService>.Instance);
    var result = await svc.ProcessAsync();
    Assert.True(result.Success);
}

// ② ログ内容を検証したい場合は xUnit 用の TestLogger や Moq を使う
public sealed class TestLogger<T> : ILogger<T>
{
    public List<(LogLevel Level, string Message, Exception? Ex)> Entries { get; } = new();

    public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
    public bool IsEnabled(LogLevel logLevel) => true;
    public void Log<TState>(LogLevel level, EventId eventId, TState state,
        Exception? exception, Func<TState, Exception?, string> formatter)
    {
        Entries.Add((level, formatter(state, exception), exception));
    }
}

// Moq を使う場合（より簡潔）
var mock = new Mock<ILogger<OrderService>>();
var svc  = new OrderService(mock.Object);
// 実行後、mock.Verify(...) で呼び出しを検証

// NG: プレースホルダーが静的文字列でなく実行時に決まる
var propName = "User";
logger.LogInformation($"{propName} logged in", userId);  // テンプレートが変動
// → ログ集計で同じイベントとして扱えない

// OK: テンプレートは常に静的な定数
logger.LogInformation("{Property} logged in", propName);
// さらに良い: [LoggerMessage] で固定テンプレートを強制

// NG: パスワードや個人情報をそのままログに出力
logger.LogInformation("Login attempt: {@User}", user);
// → @User は全プロパティを展開するので Password フィールドも保存されてしまう

// OK: @ で展開しない・センシティブ項目を除外した DTO を作る
public sealed record UserLogDto(int Id, string Username);
logger.LogInformation("Login attempt: {@User}", new UserLogDto(user.Id, user.Username));

// Serilog の Destructure で「全体として記録しない型」を指定
Log.Logger = new LoggerConfiguration()
    .Destructure.ByTransforming<User>(u => new { u.Id, u.Username }) // Password 等を除外
    .CreateLogger();

// メールアドレスのマスキング: 独自 Enricher で実装

// NG: 秒間数千回呼ばれるホットパスで構造化ログ
public async Task HandleRequestAsync(HttpRequest req)
{
    _logger.LogInformation("Received {Path} {Method}", req.Path, req.Method);
    // 秒間 5000 リクエスト × メッセージテンプレートのフォーマット・ボクシング
    //  → CPU の数%〜数十%がログ処理で消費される
}

// OK ①: [LoggerMessage] ソースジェネレーターを使う
[LoggerMessage(EventId = 1, Level = LogLevel.Information,
    Message = "Received {Path} {Method}")]
public static partial void LogRequest(ILogger logger, string path, string method);
// 呼び出し側: _logger.LogRequest(req.Path, req.Method);

// OK ②: 本当に Information 必要？Debug に下げられないか見直す
_logger.LogDebug("Received {Path} {Method}", req.Path, req.Method);

// Serilog を使っているのにプログラム終了時にログが消える原因
public static async Task Main()
{
    using var host = Host.CreateDefaultBuilder().Build();
    await host.RunAsync();
    // ここで Log.CloseAndFlush() を忘れると
    // バッファされた Async/File/Seq の書き込みが失われる可能性
}

// 正しい実装
public static async Task Main()
{
    try
    {
        using var host = Host.CreateDefaultBuilder().Build();
        await host.RunAsync();
    }
    finally
    {
        await Log.CloseAndFlushAsync();
    }
}