2,439 測定値

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

に Dmitrii Slabko12m2024/02/22

長すぎる; 読むには

ログデータを強化するという概念は、ログメッセージと一緒に追加する必要がある追加のコンテキストまたはデータを登録することを中心に展開されます。このコンテキストは、単純な文字列から複雑なオブジェクトまで、あらゆるものにすることができ、ログメッセージが書き込まれた時点ではなく、インフラストラクチャまたはビジネスコード内のある時点で生成または認識されます。したがって、このコードはログ出力を生成しないため、ログメッセージに単純に別のプロパティを追加することはできません。または、実行チェーンの下で生成されるか生成されない可能性がある複数のログメッセージにコンテキストを添付する必要があります。このコンテキストは、条件付きの場合もあります。たとえば、特定のデータをエラーログメッセージにのみ追加し、他のすべてのメッセージではそのデータを必要としません。

この記事では、ロギングに関する懸念事項とコードをインフラストラクチャやビジネスコードからどのように分離および切り離すことができるかについてのレビューを終了します。前回の記事では、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 リポジトリにあります。