はじめに
こんにちは、GxPのZhongです。
こちらはグロースエクスパートナーズ Advent Calendar 2023の12日目の記事です。
最近業務でサービスが叩くAPIで障害が発生したのでドットネットの主にHTTPContextクラスからリクエストやレスポンスの情報を出力して障害調査をしました。
その時に各APIを叩いていくのは大変なので、どうやって複数あるAPIへのリクエスト、レスポンス情報を一度に取得したか書いてみます。
環境
言語 ：C＃
使用フレームワーク：ASP.NET Core 6.0
ログライブラリ ：Serilog 6.0.1
テストライブラリ ：NUnit 4.2.1
障害状況
あるアクションメソッドのレスポンスが想定していたレスポンスを返してくれなかった。（レスポンスボディ情報の不足）
こちらは、ソースコードを修正し、不足していた情報をレスポンス内容に含めるようにして改修。
一方同じように想定していたレスポンスを返していないAPIが無いかを調査するため、全てのアクションメソッドに対するレスポンス内容を確認したい。
※アクションメソッド
クライアントからのリクエストに対して実行されるメソッド
やりたいこと
・全てのIntegrationテストを実行した時にリクエスト及びレスポンス情報を取得。
・レスポンス内容だけでなく、アクションメソッドの情報やリクエスト内容も含めて取得。
調査の流れ
下の流れで調査しました。
- ログ情報をファイルに出力するように設定
- IResourceFilterを実装したクラスを作成し起動プロセスで読み込み
- ログファイル内を色々と検索（grep,sedとかを使用）
1.ログ情報をファイルに出力するように設定
今回ログライブラリとしてSerilogを使用しており、出力設定は起動プロセスでappsetting.jsonを読み込んでいたので出力先をWriteToへfile出力を設定。appsetting.Development.jsonにログの出力を記載。
{
"Serilog": {
"Using": [
"Serilog.Sinks.File"
],
"MinimumLevel": {
"Default": "Debug"
},
"WriteTo": [
{
"Name": "Debug"
},
{
"Name": "File",
"Args": {
"path": "出力先パス\\api-log-.txt",
"rollingInterval": "Day",
"outputTemplate": "{Timestamp:yyyy/MM/dd HH:mm:ss.fff zzz} {Message}{NewLine}{Exception}"
}
}
]
}
2. IResourceFilterを実装したクラスを作成し起動プロセスで読み込み
コンテキストの情報をログに出力させる処理をどこに記載すれば良いのか！？
アクションメソッドを実行する際、共通して呼ばれる箇所でログ出力するコードを記載したい。
IResourceFilterはASP.NET Coreにおいて、リソース（※アクション メソッド）の実行前と実行後に特定のカスタム ロジックを追加できるフィルターの一種。アクション メソッドの実行前や実行後に様々なタイプのフィルターを適用することができる。
下のようなフィルタークラスで、今回レスポンス内容も含めて知りたいので、アクションメソッド実行後に処理されるOnResourceExecutedに記載する。
using Microsoft.AspNetCore.Mvc.Filters;
using Microsoft.Extensions.Logging;
public class MyResourceFilter : IResourceFilter
{
private readonly ILogger<MyResourceFilter> _logger;
public MyResourceFilter(ILogger<MyResourceFilter> logger)
{
_logger = logger;
}
public void OnResourceExecuting(ResourceExecutingContext context)
{
// リソースの実行前のカスタム ロジック
_logger.LogInformation("Resource is executing...");
}
public void OnResourceExecuted(ResourceExecutedContext context)
{
// リソースの実行後のカスタム ロジック
_logger.LogInformation("Resource has executed.");
}
}
テスト実行前にフィルターの設定をしたいので[OneTimeSetUp]にフィルターを指定。
using NUnit.Framework;
[TestFixture]
public class MyTest
{
[OneTimeSetUp]
public void Init()
{
Factory = new WebApplicationFactory<TEntryPoint>().WithWebHostBuilder(builder =>
builder.ConfigureServices(services =>
services.AddControllers(options =>
options.Filters.Add(typeof(MyResourceFilter))
)));
}
}
ResourceExecutedContext内から取得したい基本的な情報
以下のような情報が有れば分析しやすいと考え取り敢えず取得してみる。
※調査したい内容等を考えログファイルへ出力する順序、grepして確認しやすいような並びになると尚良いと思われる。今回は必要な情報を取得してログ出力をするのみとする。
・どのテストを実行したか
・どのアクションメソッドが呼ばれたか
・HTTPメソッド（Get, Post, DELETE？）
・リクエストパス
・リクエストボディ
・クエリパラメータ
・リクエストヘッダー
・レスポンスボディ
public void OnResourceExecuted(ResourceExecutedContext context)
{
// TestContextクラスは、テストの実行中にテストの状態や情報にアクセスするための機能を提供
var testContext = TestContext.CurrentContex
// リクエストボディの読み取り
// HttpRequest については EnableBuffering() というメソッドを先に呼んで
// リクエストボディのバッファリングが有効にすることで、再読み込み可能なStreamとして使用可能になる
context.HttpContext.Request.EnableBuffering();
var request = context.HttpContext.Request;
request.Body.Seek(0, SeekOrigin.Begin);
string requestBody;
using (var reader = new StreamReader(request.Body, Encoding.UTF8))
{
requestBody = reader.ReadToEnd();
};
// レスポンス情報が入っているValueを取得するためObjectResulへキャスト
ObjectResult objectResult = context.Result as ObjectResul
// 後で確認しやすいように成型
var serializeResponse = JsonSerializer.Serialize(objectResult.Value, _jsonSerializerOptions);
// 他はcontextからたどれば簡単に取れる
var actionName = context.ActionDescriptor.DisplayName;
var requestPath = context.HttpContext.Request.Path;
var httpMethod = context.HttpContext.Request.Method;
var requestHeaders = string.Join(", ", context.HttpContext.Request.Headers.Select(kv => $"{kv.Key}: {kv.Value}"));
var queryString = context.HttpContext.Request.QueryString;
_logger.LogInformation("---------------------------------------------------------------------------------------");
// ・どのテストを実行したか
// testContext.Test.MethodNameでは"AdhocTestMethod"と出力されてしまう。
_logger.LogInformation("TEST METHOD NAME | {testMethod}", testContext.Test.MethodName);
// ・どのアクションメソッドが呼ばれたか
_logger.LogInformation("METHOD NAME | {actionName}", actionName);
// ・HTTPメソッド（Get, Post, DELETE？）,リクエストパス
_logger.LogInformation("HTTP REQUEST | {httpMethod} {requestPath}", httpMethod, requestPath);
// ・リクエストボディ
_logger.LogInformation("REQUEST BODY | {requestBody}", requestBody);
// ・リクエストヘッダー
_logger.LogInformation("REQUEST HEADERS | {requestHeaders}", requestHeaders);
// ・クエリパラメータ
_logger.LogInformation("QUERY STRING | {queryString}", queryString);
// レスポンスボディ
_logger.LogInformation("SERIARIZE RESPONSE | {serializeResponse}", serializeResponse);
_logger.LogInformation("-------------------------------------------------------------------------------------------"
}
しかしながら、、、
上のだとNUnitでテストを実行するとtestContext.Test.MethodNameの中身は"AdhocTestMethod"と出力されてしまう。。。
なぜテストメソッドが出力されないのか？
TestContextのドキュメンテーションコメントを見ると、どうやらTestContextはTestクラス外から呼び出すことを推奨していない模様。
// 概要:
// Get the current test context. This is created as needed. The user may save the
// context for use within a test, but it should not be used outside the test for
// which it is created.
public static TestContext CurrentContext { get; }
取り敢えずテストクラス内でTestContextを取得するように変更、、、
期待通りにTestMethodName を取得するには、NUnitテストの実行中にそのメソッド名を取得したらどないか、、、ということで、TestクラスのSetUpメソッドでTestContext.CurrentContext.Test.MethodNameを取得し、正しいメソッド名が得られないかを試してみる。
using NUnit.Framework;
[TestFixture]
public class MyTest
{
[SetUp]
public void Setup()
{
// テスト用のスコープを作成
using (var scope = Factory.Services.CreateScope())
{
// ILogger のインスタンスを取得
var logger = scope.ServiceProvider.GetRequiredService<ILogger<MyTests>>();
// ここでテストを実行し、必要に応じてログを記録
logger.LogInformation("TEST METHOD NAME | {testMethodName}", TestContext.CurrentContext.Test.MethodName);
}
}
}
一応成功！！
3.ログファイル内を色々と検索（grepやsedとかを使用）
こちらは分析したい内容が人それぞれだと思いますので、各自使用したいコマンドで中身見てみれば良いかと、、、
また、今回 TEST METHODのみ出力箇所が並びになっていないのでsedなどのコマンドで整形してからgrepすればより調査がしやすいかな？と思います。
例：grep -n "取得したい文字列（※TEST METHOD NAME等）" api-log-20231122.txt
まとめ
HTTPContext内をデバック実行で確認することはありましたが、複数のアクションメソッドに対して網羅的に調査していきたい時の方法として勉強になりました。
今回私が行った方法が最適な方法かは分からないのですが、障害調査の一助になればと思います。