ログの強化についての詳細

この記事では、ロギングに関する懸念事項とコードをインフラストラクチャやビジネス コードからどのように分離および切り離すことができるかについてのレビューを終了します。 前回の記事では、DiagnosticSource と DiagnosticListener を使用してインフラストラクチャ操作を実現する方法を確認しました。

次に、ログに記録されたデータを追加のコンテキストで強化する方法を確認します。

基本的に、ログ データを強化するという概念は、ログ メッセージと一緒に追加する必要がある追加のコンテキストまたはデータを登録することを中心に展開します。このコンテキストは、単純な文字列から複雑なオブジェクトまで何でもあり、ログ メッセージが書き込まれた時点ではなく、インフラストラクチャまたはビジネス コード内のある時点で生成または認識されます。

したがって、このコードはログ出力を生成しないため、単純にログ メッセージに別のプロパティを追加することはできません。または、実行チェーンで生成されるか生成されない可能性がある複数のログ メッセージにコンテキストを添付する必要があります。

このコンテキストは、条件付きの場合もあります。たとえば、特定のデータをエラー ログ メッセージにのみ追加し、他のすべてのメッセージにはそのデータを追加する必要がありません。

Serilog によって非常に柔軟かつ強力になったので、Serilog とその強化機能を使用します。他のソリューションにもさまざまな成熟度レベルで同様の機能があり、Serilog の機能強化と Microsoft.Extensions.Logging がそのまま提供する機能を比較します。

Serilog 用の既存のログ エンリッチャーの概要

Serilog には、いくつかのシナリオで非常に便利な多くの便利なエンリッチャーが組み込まれています。このページ - https://github.com/serilog/serilog/wiki/Enrichment - にアクセスすると、エンリッチャーの完全なリストとその説明を確認できます。

たとえば、一致するスコープ内で追加データが書き込まれる場合、追加データをプッシュしてログ メッセージとともに記録できるようにする LogContext および GlobalLogContext エンリッチャーがあります。

LogContext エンリッチャーは、Microsoft.Extensions.Logging のログ スコープの概念と非常によく似ています。基本的に、これらは両方ともいくつかのカスタム データをプッシュし、ログ コンテキストからデータを削除するために破棄する必要がある IDisposable オブジェクトを提供します。

つまり、IDisposable オブジェクトがスコープ内にある限り、データはそのスコープ内で書き込まれるすべてのログ メッセージに添付されます。廃棄するとデータは添付されなくなります。

Serilog と Microsoft のドキュメントには次の例が記載されています。

 // For Serilog log.Information("No contextual properties"); using (LogContext.PushProperty("A", 1)) { log.Information("Carries property A = 1"); using (LogContext.PushProperty("A", 2)) using (LogContext.PushProperty("B", 1)) { log.Information("Carries A = 2 and B = 1"); } log.Information("Carries property A = 1, again"); } // For Microsoft.Extensions.Logging scopes using (logger.BeginScope(new List<KeyValuePair<string, object>> { new KeyValuePair<string, object>("TransactionId", transactionId), })) { _logger.LogInformation(MyLogEvents.GetItem, "Getting item {Id}", id); todoItem = await _context.TodoItems.FindAsync(id); if (todoItem == null) { _logger.LogWarning(MyLogEvents.GetItemNotFound, "Get({Id}) NOT FOUND", id); return NotFound(); } }

一部のシナリオでは便利ですが、かなり制限されています。このタイプのログ エンリッチメントの最適な使用法は、ミドルウェアまたはデコレータ タイプの実装です。この場合、スコープが明確に定義されており、スコープ作成の時点でデータが既知であり、データが外部の値を持たないことが確実です。範囲。

たとえば、これを使用して、単一の HTTP リクエスト処理スコープ内のすべてのログ メッセージに相関 ID を添付できます。

GlobalLogContext エンリッチャーは LogContext に似ていますが、グローバルであり、アプリケーション内で書き込まれたすべてのログ メッセージにデータをプッシュします。ただし、このタイプのエンリッチメントの実際の使用例は非常に限られています。

Serilog 用のカスタム ログ エンリッチャーのサンプル

実際のところ、Serilog 用のカスタム ログ エンリッチャーの実装は非常に簡単です。ILogEventEnricher インターフェイスを実装し、エンリッチャーをロガー構成ILogEventEnricher登録するだけです。このインターフェイスには実装するメソッドが 1 つだけあり、それはEnrichです。これはログ イベントを受け入れ、必要なデータでそれを強化します。

カスタム ログ エンリッチャーのサンプル実装を確認してみましょう。

 public sealed class CustomLogEnricher : ILogEventEnricher { private readonly IHttpContextAccessor contextAccessor; public CustomLogEnricher(IHttpContextAccessor contextAccessor) { this.contextAccessor = contextAccessor; } public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) { var source = contextAccessor.HttpContext?.RequestServices.GetService<ICustomLogEnricherSource>(); if (source is null) { return; } var loggedProperties = source.GetCustomProperties(logEvent.Level); foreach (var item in loggedProperties) { var property = item.ProduceProperty(propertyFactory); logEvent.AddOrUpdateProperty(property); } } }

ご覧のとおり、このエンリッチャーはICustomLogEnricherSourceに依存して、ログ イベントを強化するためのカスタム プロパティを取得します。通常、ログ エンリッチャーは存続期間の長いインスタンスであり、シングルトン パターンに従います。ログ エンリッチャーはアプリケーションの起動時に一度登録され、アプリケーションの存続期間全体にわたって存続します。

したがって、エンリッチャーをカスタム プロパティのソースから切り離す必要があります。ソースは、有効期間が制限されたスコープ指定されたインスタンスにすることができます。

 public sealed class CustomLogEnricherSource : ICustomLogEnricherSource { private readonly Dictionary<string, CustomLogEventProperty> properties = new(); public ICustomLogEnricherSource With<T>(string property, T? value, LogEventLevel logLevel) where T : class { if (value is null) { return this; } properties[property] = new CustomLogEventProperty(property, value, logLevel); return this; } public void Remove(string property) { properties.Remove(property); } public IEnumerable<CustomLogEventProperty> GetCustomProperties(LogEventLevel logLevel) { foreach (var item in properties.Values) { if (item.Level <= logLevel) { yield return item; } } } } // And CustomLogEventProperty is a simple struct (you can make it a class, too): public struct CustomLogEventProperty { private LogEventProperty? propertyValue; public CustomLogEventProperty(string property, object value, LogEventLevel level) { Name = property; Value = value; Level = level; } public string Name { get; } public object Value { get; } public LogEventLevel Level { get; } public LogEventProperty ProduceProperty(ILogEventPropertyFactory propertyFactory) { propertyValue ??= propertyFactory.CreateProperty(Name, Value, destructureObjects: true); return propertyValue; } }

この実装にはいくつかの簡単な詳細があります。

• エンリッチャーは、これらのコンポーネントのさまざまな存続期間とさまざまな責任を考慮して、ログ メッセージのカスタム プロパティのソースから切り離されています。異なるアプリケーション コンポーネントが異なるカスタム プロパティを生成する可能性があるため、必要に応じて、 ICustomLogEnricherSourceインスタンスのリストを使用してエンリッチャーを作成できます。

• ソース ( ICustomLogEnricherSource ) は、カスタム プロパティでログ メッセージを強化する必要があるコンポーネントに挿入できます。理想的には、カスタム プロパティを有効期限切れにする便利な方法が提供されないため、スコープ付きインスタンスにする必要があります。

• エンリッチャーとソースは、ログ メッセージのログ レベルに基づいて単純なフィルター ロジックを実装します。ただし、ロジックははるかに複雑で、他のLogEventプロパティやアプリケーションの状態に依存する場合もあります。

• CustomLogEventProperty 、複数のログ メッセージに添付される可能性があるため、同じカスタム プロパティに対して複数回作成されることを避けるために、生成されたLogEventPropertyインスタンスをキャッシュします。

もう 1 つの重要な詳細は、このコード行、 destructureObjectsパラメーターにあります。

 propertyFactory.CreateProperty(Name, Value, destructureObjects: true);

クラス、レコード、構造体、コレクションなどの複雑なオブジェクトをアタッチし、このパラメーターがtrueに設定されていない場合、Serilog はオブジェクトに対してToStringを呼び出し、結果をログ メッセージに添付します。レコードにはすべてのパブリック プロパティを出力するToString実装があり、クラスと構造体のToStringをオーバーライドできますが、常にそうとは限りません。

また、このような出力は単純な文字列になるため、構造化ログには適していません。また、添付されたオブジェクトのプロパティに基づいてログ メッセージを検索したりフィルタリングしたりすることができません。したがって、ここではこのパラメータをtrueに設定します。単純な型 (値の型と文字列) は、このパラメーターのどちらの値でも問題なく機能します。

この実装のもう 1 つの利点は、カスタム プロパティがソースに登録されると、削除されるかソースが破棄されるまで、すべてのログ メッセージに対してそのプロパティが維持されることです (スコープ付きインスタンスである必要があることに注意してください)。実装によっては、カスタム プロパティの有効期間をより適切に制御する必要がある場合があり、これはさまざまな方法で実現できます。

たとえば、特定のCustomLogEventProperty実装を提供するか、カスタム プロパティを削除する必要があるかどうかを確認するコールバックを提供します。

この有効期限ロジックをGetCustomPropertiesメソッドで使用すると、カスタム プロパティを事前チェックし、有効期限が切れている場合はソースから削除できます。

これがロギングの問題をビジネスおよびインフラストラクチャ コードから切り離すのにどのように役立つか

そうですね、理想的には、ロギングの問題をビジネス コードやインフラストラクチャ コードと混同したくありません。これは、ビジネス コードとインフラストラクチャ コードをロギング固有のコードで「ラップ」できるさまざまなデコレータ、ミドルウェア、その他のパターンを使用して実現できます。

ただし、これは常に可能であるとは限りません。場合によっては、 ICustomLogEnricherSourceなどの中間抽象化をビジネスおよびインフラストラクチャ コードに挿入し、ログ用のカスタム データを登録させる方が便利な場合があります。

このようにして、ビジネス コードとインフラストラクチャ コードは、実際のロギングについて何も知る必要がなくなりますが、実際のロギングをいくつかのロギング対応コードと混ぜ合わせます。

とにかく、このコードは結合がはるかに少なくなり、テストしやすくなります。一部の非常にホット パスのシナリオでパフォーマンスとメモリを消費しない no-op 実装として、 NullLogEnricherSourceのようなものを導入することもあります。

パフォーマンスに関する考慮事項

Microsoft が述べているように、

ログ記録は、非同期コードのパフォーマンス コストに見合わないほど高速である必要があります。

したがって、ログ メッセージを追加のコンテキストで強化する場合は常に、パフォーマンスへの影響を認識する必要があります。一般に、Serilog ログ エンリッチメントの実装は非常に高速で、少なくとも Microsoft ログ スコープと同等ですが、より多くのデータを添付すると、ログ メッセージの生成にさらに時間がかかります。

アタッチするカスタム プロパティが増えるほど、その中に含まれるオブジェクトがより複雑になり、ログ メッセージの生成に必要な時間とメモリが増えます。したがって、開発者は、ログ メッセージにどのデータを添付するか、いつ添付するか、およびその有効期間はどのくらいであるべきかについて、十分に考慮する必要があります。

以下は、Serilog ログ エンリッチメントと Microsoft ログ スコープの両方のパフォーマンスとメモリ消費量を示す小さなベンチマーク結果の表です。各ベンチマーク方法では、カスタム プロパティでメッセージを充実させるさまざまな方法で 20 個のログ メッセージが生成されます。

カスタム プロパティが添付されていません:

 | Method | Mean | Error | StdDev | Gen0 | Allocated | | SerilogLoggingNoEnrichment | 74.22 us | 1.194 us | 1.116 us | 1.2207 | 21.25 KB | | MicrosoftLoggingNoEnrichment | 72.58 us | 0.733 us | 0.685 us | 1.2207 | 21.25 KB |

各ログ メッセージには、次の 3 つの文字列が付加されています。

 | Method | Mean | Error | StdDev | Gen0 | Allocated | | SerilogLoggingWithContext | 77.47 us | 0.551 us | 0.516 us | 1.7090 | 28.6 KB | | SerilogLoggingWithEnrichment | 79.89 us | 1.482 us | 2.028 us | 1.7090 | 29.75 KB | | MicrosoftLoggingWithEnrichment | 81.86 us | 1.209 us | 1.131 us | 1.8311 | 31.22 KB |

各ログ メッセージには、次の 3 つの複雑なオブジェクト (レコード) が添付されています。

 | Method | Mean | Error | StdDev | Gen0 | Allocated | | SerilogLoggingWithObjectContext | 108.49 us | 1.193 us | 1.058 us | 5.3711 | 88.18 KB | | SerilogLoggingWithObjectEnrichment | 106.07 us | 0.489 us | 0.409 us | 5.3711 | 89.33 KB | | MicrosoftLoggingWithObjectEnrichment | 99.63 us | 1.655 us | 1.468 us | 6.1035 | 100.28 KB |The

Serilog*ContextメソッドはLogContext.PushPropertyを使用し、 Serilog*Enrichmentメソッドは記事に記載されているカスタム エンリッチャーとソース実装を使用します。一方、 Microsoft*メソッドはログ スコープを使用します。

ほとんどの場合、パフォーマンスとメモリ消費量は非常に似ており、複雑なオブジェクトを使用してエンリッチすることは、単純な型を使用してエンリッチするよりもコストがかかることがわかります。唯一の例外は、ログ メッセージにレコードを添付する場合の Microsoft 実装によるログ記録です。

これは、ログ スコープが複雑なオブジェクトを分解せず、ログ メッセージに添付するときにシリアル化にToStringメソッドを使用するためです。これにより、Microsoft の実装はわずかに高速になりますが、より多くのメモリを消費します。

デフォルトのToString実装でクラスを使用すると、メモリ消費量ははるかに少なくなりますが、これらのカスタム オブジェクトは完全修飾型名としてログに記録されるため、まったく役に立ちません。

いずれの場合も、Microsoft の実装ではこれらのオブジェクトが構造化されていないため、これらのオブジェクトのプロパティに基づいてログ メッセージを検索したりフィルタリングしたりすることはできません。

したがって、これは Microsoft のログ スコープの制限であることに注意する必要があります。単純な型は正常にログに記録され、検索やフィルタリングが可能である一方で、複雑なオブジェクトは構造化されません。

注: この記事のベンチマーク ソース コードとコード サンプルは、 GitHub リポジトリにあります。

結論

ログを適切に強化することは、コードの開発と保守の「生活の質の向上」につながります。これにより、ログ メッセージの作成時点では不明な追加のコンテキストをログ メッセージに添付することができます。

このコンテキストは、単純な文字列から複雑なオブジェクトまで何でもあり、インフラストラクチャまたはビジネス コード内のある時点で生成または認識されます。

これは、ロギングおよび可観測性のコードをインフラストラクチャおよびビジネス コードから分離し、コードをより保守しやすく、テストしやすく、読みやすくする方法です。

参考文献

• Serilog ログの強化について - https://github.com/serilog/serilog/wiki/Enrichment
• Microsoft のログ スコープについて - https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-8.0#log-scopes
• この記事のコードサンプル - https://github.com/dmitry-slabko/log-enrichment-pub