目次
今回はAzure Cognitive SearchのSDKを利用したアプリケーションが、実際にAzure Cognitive Searchに対して送信しているリクエストのパラメータとボディをログに保存する方法について紹介します。
動機
アプリケーションでリクエストを組み立てて、SDK経由で送信していると、最終的にAzure Cognitive Searchに対して送信されているリクエストのパラメータや検索条件などをひと目で見たいことがあります。 アプリケーションでは、ソート条件や、クエリ文字列の組み立てなどの処理は異なる場所で行われたりしますので。
また、公式リファレンスでは、機能の説明はRest APIの使い方と組み合わせで説明されることが多いです。
ということで、SDKを利用しているアプリからAzure Searchへ送信されているリクエストをログに保存する方法を調べてみました。
方法
調べてみるといくつかの手段を取ることができそうだとわかりました。実際に調べて実装する方法を4種類ほど試してみたのでブログに残しておきます。なお、2020年4月時点でのSDKとAzureの仕組みに基づいたブログになります。最新版ではお手軽な方法があるかもしれません。
- DelegatingHandlerを利用する
- ServiceClientTracingの機能を利用する
- Azure Application Insightsを活用する
- Azure Cognitive Searchのコンソールにある診断情報の機能を利用する
1、2はAzure Cognitive SearchのSDKのリファレンスから当たりを付けて見つけた方法です。 3はApplication Insights、4はAzure Cognitive Searchの機能になります。 これらの方法について個別に説明していきます。
1. DelegatingHandleを利用する
まずは、SDKでロギングの機能がないかを調べて見つけた機能がこちらです。 SDKのSearchServiceClientのコンストラクタの引数にDelegatingHandlerというものが渡せることを発見しました。
これは、.NET FrameworkのHttpのAPIに存在するクラスで、HTTPのクライアントがHTTPの送受信時に、処理を挟むことができる機能です。フレームワーク側で、LoggingHttpMessaggeHandlerというクラスを用意してくれていましたが、残念ながらこちらは、リクエストとレスポンスのヘッダのみをロギングするクラスでした。
ということで、リクエストボディをログに出力したい場合は独自に拡張してやる必要があります。なお、ロギングにはMicrosoft.Extensions.LoggingのILoggerを使用します。
また、Azure Cognitive SearchのSDK側に違う問題点もありました。チュートリアルにあるように、検索するときには、SDKは次のような使い方を想定しています。
// Create a service and index client.
_serviceClient = new SearchServiceClient(searchServiceName, new SearchCredentials(queryApiKey));
_indexClient = _serviceClient.Indexes.GetClient("hotels");
インデックス用のクライアントを取得するために、GetClient(インデックス名)というメソッドを使用します。このGetClientメソッドのバリエーションとして、DelegatingHandlerを受け取るメソッドがないのです。。。
ということで、DelegationHandlerを活用する方法としては、以下の2つを実装する必要があります。
- CustomなLoggingHttpMessageHandlerクラスを実装
- GetClientと同等の処理をDelegatingHandlerを引数にしたものを実装する
以上の2つを実装し、アプリケーション側から2で作成したGetClientを呼び出すことで、リクエストをボディも含めてログ出力することが可能になります。以下は実装例です。
CustomHttpMessageHandlerクラス。
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Net.Http;
using System.Net.Http.Headers;
using System.Text;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
namespace AzureSearchSample
{
public class CustomLoggingHttpMessageHandler : DelegatingHandler
{
private readonly ILogger _logger;
private readonly bool _logContent = false;
public CustomLoggingHttpMessageHandler(ILogger logger, bool logContent)
{
if (logger == null)
{
throw new ArgumentNullException(nameof(logger));
}
this._logger = logger;
this._logContent = logContent;
}
protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
{
if (request == null)
{
throw new ArgumentNullException(nameof(request));
}
await Log.RequestStart(this._logger, request, this._logContent);
var stopwatch = new Stopwatch();
HttpResponseMessage response = await base.SendAsync(request, cancellationToken).ConfigureAwait(false);
stopwatch.Stop();
await Log.RequestEnd(this._logger, response, stopwatch.Elapsed);
return response;
}
private static class Log
{
private static class EventIds
{
public static readonly EventId RequestStart = new EventId(100, "RequestStart");
public static readonly EventId RequestEnd = new EventId(101, "RequestEnd");
}
public static async Task RequestStart(ILogger logger, HttpRequestMessage request, bool logContent)
{
StringBuilder message = new StringBuilder();
message.AppendLine($"Sending HTTP request {request.Method} {request.RequestUri}");
if (logger.IsEnabled(LogLevel.Trace))
{
LogHttpHeaders(message, request.Headers);
await LogHttpContent(message, request.Content, logContent);
logger.Log(
LogLevel.Trace,
EventIds.RequestStart,
message,
null,
(state, ex) => state.ToString());
}
}
public static async Task RequestEnd(ILogger logger, HttpResponseMessage response, TimeSpan duration)
{
StringBuilder message = new StringBuilder();
message.AppendLine(
$"Recieving HTTP response after {duration.TotalMilliseconds}ms - {response.StatusCode}");
if (logger.IsEnabled(LogLevel.Trace))
{
LogHttpHeaders(message, response.Headers);
await LogHttpContent(message, response.Content, false);
logger.Log(
LogLevel.Trace,
EventIds.RequestEnd,
message,
null,
(state, ex) => state.ToString()
);
}
}
private static void LogHttpHeaders(StringBuilder message, HttpHeaders headers)
{
if (headers == null) throw new ArgumentNullException(nameof(headers));
foreach (KeyValuePair<string, IEnumerable<string>> header in headers)
{
foreach (string value in header.Value)
{
message.AppendLine($"{header.Key}: {value}");
}
}
}
private static async Task LogHttpContent(StringBuilder message, HttpContent content,
bool logContent)
{
if (content != null)
{
foreach (KeyValuePair<string,IEnumerable<string>> header in content.Headers)
{
foreach (string value in header.Value)
{
message.AppendLine($"{header.Key}: {value}");
}
}
if (logContent)
{
string contentBody = await content.ReadAsStringAsync();
message.AppendLine(contentBody);
}
}
}
}
}
}
GetClientの実装
private ISearchIndexClient GetClient(string indexName, params DelegatingHandler[] handlers)
{
var rootHandler = _searchServiceClient.HttpMessageHandlers.OfType<HttpClientHandler>().SingleOrDefault();
var indexClient =
new SearchIndexClient(_searchServiceClient.SearchServiceName, indexName,
_searchServiceClient.SearchCredentials, rootHandler, handlers)
{
SearchDnsSuffix = _searchServiceClient.SearchDnsSuffix
};
indexClient.HttpClient.Timeout = _searchServiceClient.HttpClient.Timeout;
return indexClient;
}
出力されるログ例
2020/04/14 19:17:53.591|TRACE|Sending HTTP request POST https://サービス名.search.windows.net/indexes('インデックス名')/docs/search.post.search?api-version=2019-05-06
client-request-id: be02140f-3a07-48cc-b018-d8aa5e819bc3
Accept-Language: en-US
Accept: application/json; odata.metadata=none
api-key: APIキー
User-Agent: FxVersion/4.700.20.11803
User-Agent: OSName/MacOs
User-Agent: OSVersion/Darwin.19.4.0.Darwin.Kernel.Version.19.4.0.Wed.Mar.4.22.28.40.PST.2020.root.xnu.6153.101.6.15RELEASE.X86.64
User-Agent: Microsoft.Azure.Search.SearchIndexClient/10.100.19.52907
Content-Type: application/json; charset=utf-8
{
"count": false,
"facets": [],
"queryType": "simple",
"scoringParameters": [],
"search": "azure",
"searchMode": "any"
}
|AzureSearchSample.SearchService|EventId_Id=100, EventId_Name=RequestStart, EventId=RequestStart
メリット、デメリット
Azure Cognitive Searchの検索の処理だけを対象にリクエストのログを出力することが可能です。また、影響範囲はアプリケーションだけに閉じていますので、デバッグ目的などでログ出力したい場合に、自分だけの手元でログの確認が可能になります。
デメリットとしては、独自に実装しなければいけない範囲が広いことです。
2. ServiceClientTracingの機能を利用する
Microsoft.Rest.ClientRuntimeというライブラリをAzure Cognitive Searchは利用しています。
このライブラリにServiceClientTracingというクラスが存在します。
なにやら、クライアントの処理のトレースができそうです。
Azure Cognitive SearchのSDKの実装がGitHubに公開されており、検索リクエストの処理を投げる直前に、このトレースの仕組がONになっていると、ServiceClientTracing.SendRequestメソッドを呼び出していました。
実際にSendRequestメソッドに送られたものに対して何かしらの処理を行うのは、IServiceClientTracingIntercepterインターフェースを実装したクラスになります。
このインターフェースの実装がLog4Netに存在します。Log4Netを利用している場合は、これを活用すれば楽ができます。
実際にServiceClientTracingを有効にするには、以下の2行を呼び出すだけです。
ServiceClientTracing.IsEnabled = true;
ServiceClientTracing.AddTracingInterceptor(new Log4NetTracingInterceptor());
あとは、Rest.ClientRuntimeがよしなにやってくれます。 1とは異なり、トレースログなので、リクエストのボディについても出力してくれます。
2020-05-26 19:09:04,058 [1] DEBUG Microsoft.Rest.Tracing.Log4Net.Log4NetTracingInterceptor [(null)] - invocationId: 1
instance: Microsoft.Azure.Search.DocumentsProxyOperations
method: SearchPost
parameters: {searchRequest=Microsoft.Azure.Search.Models.SearchRequest,clientRequestId=,cancellationToken=System.Threading.CancellationToken}
2020-05-26 19:09:04,164 [1] DEBUG Microsoft.Rest.Tracing.Log4Net.Log4NetTracingInterceptor [(null)] - invocationId: 1
request: Method: POST, RequestUri: 'https://サービス名.search.windows.net/indexes('インデックス名')/docs/search.post.search?api-version=2019-05-06', Version: 2.0, Content: System.Net.Http.StringContent, Headers:
{
client-request-id: 591cb14f-e5c2-4a85-977d-01d1f6431ddc
Accept-Language: en-US
Accept: application/json; odata.metadata=none
api-key: APIキー
Content-Type: application/json; charset=utf-8
}
Body:
{
{
"count": false,
"facets": [],
"queryType": "simple",
"scoringParameters": [],
"search": "azure",
"searchMode": "any"
}
}
2020-05-26 19:09:04,459 [Thread Pool Worker] DEBUG Microsoft.Rest.Tracing.Log4Net.Log4NetTracingInterceptor [(null)] - invocationId: 1
response: StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
Cache-Control: no-cache
Pragma: no-cache
request-id: 591cb14f-e5c2-4a85-977d-01d1f6431ddc
elapsed-time: 72
OData-Version: 4.0
Preference-Applied: odata.include-annotations="*"
Strict-Transport-Security: max-age=15724800; includeSubDomains
Date: Tue, 26 May 2020 10:09:04 GMT
Content-Type: application/json; odata.metadata=none
Expires: -1
Content-Length: 376
}
メリット、デメリット
Log4Netを利用しているアプリの場合、2行だけを追加することで実装が完了するのがお手軽な点です。
難点としては、Rest Client全てにたいしてトレース処理が入ってしまうので、Azure Cognitive Search以外にもRestクライアントを利用しているものが存在した場合、ログの量が増えてしまいます。また、検索以外の処理でもトレースされてしまうのもデメリットになります。
Log4Net以外のログ機構を使用している場合は、自分でIServiceClientTracingInterceptorを実装する必要も出てきます(参考:StackOverflow)。
3. Azure Application Insightsを活用する
ここから紹介する3と4については、ログの出力先がAzure上になります。
AzureのApplication Insightsを利用する方法です。 Azure?.NET?のアプリケーションパフォーマンスモニタリングのサービスです。
Application Insightsを自分のアプリケーションに設定することで、アプリケーションのパフォーマンス監視に関する情報がAzure上のApplication Insightsリソースに送信されるようになります。
ただ、Application Insightsのデフォルトの機能では、URL程度の情報だけが送信されます(参考:しばやんさんのブログ)
こちらも拡張機能が用意されており、ITelemetryInitializerのインターフェースを実装したクラスを用意することで、独自の情報をApplication Insightsに出力することが可能となります。詳細についてはしばやんさんのブログを参考にしてもらうのが良いかと。
Httpリクエストを出力する実装例は次のとおりです。ただ、ちょっとうまく行かないパターンがあったので、コメントアウトとして残してあったりします(なんでだろう?)
using System.Collections.Generic;
using System.Net.Http;
using System.Net.Http.Headers;
using Microsoft.ApplicationInsights.Channel;
using Microsoft.ApplicationInsights.DataContracts;
using Microsoft.ApplicationInsights.Extensibility;
namespace AzureSearchWebSample.ApplicationInsights
{
public class HttpRequestInitializer : ITelemetryInitializer
{
public void Initialize(ITelemetry telemetry)
{
if (!(telemetry is DependencyTelemetry dependency))
{
return;
}
HttpRequestMessage requestMessage = null;
HttpRequestHeaders requestHeaders;
if (dependency.TryGetOperationDetail("HttpRequest", out var details) &&
details is HttpRequestMessage request)
{
requestMessage = request;
requestHeaders = request.Headers;
if (requestMessage.Method == HttpMethod.Post)
{
string contentBody = requestMessage.Content.ReadAsStringAsync().GetAwaiter().GetResult();
dependency.Properties.Add("RequestBody",contentBody);
}
}
else if (dependency.TryGetOperationDetail("HttpRequestHeaders", out details) &&
details is HttpRequestHeaders headers)
{
requestHeaders = headers;
}
else
{
return;
}
foreach (KeyValuePair<string,IEnumerable<string>> header in requestHeaders)
{
foreach (string value in header.Value)
{
dependency.Properties.Add(header.Key, value);
}
}
//この実装の場合は出力されなかった。なぜ?
// if (requestMessage != null && requestMessage.Method == HttpMethod.Post)
// {
// string contentBody = requestMessage.Content.ReadAsStringAsync().GetAwaiter().GetResult();
// dependency.Properties.Add("RequestBody",contentBody);
// }
}
}
}
メリット、デメリット
すでにApplication Insightsを利用している場合はついでに情報が出力されるので便利です。かつ、常にリクエストログを見れるようにしておく場合はとても便利だと思います。
Application Insightsを利用していない場合は、そこから導入しなければならなくなるので、手間が増えるかもしれないです。
4. Azure Cognitive Searchのコンソールにある診断情報の機能を利用する。
最後はAzure Cognitive Searchの診断ログを有効にする方法です。 ここまで説明してきた方法の中で、一番お手軽な方法です。。。
これまでは、リクエストボディを出力する方法を考えていましたが、Azure Cognitive Search側の診断ログを有効にすると、リクエストボディで送信したものが、Azure Cognitive Search側で、クエリパラーメータとして、診断ログに出力されます(診断ログのQuery_s)。
あとは、Azureのコンソールで当該時間のログを見ればよいだけです。以下は出力されたログの一部です。Description_sにはURLのパスが記載されています。
診断ログ例(一部)
Description_s POST /indexes('multi-field-test')/docs/search.post.search
Query_s ?api-version=2019-05-06&searchMode=Any&search=azure&queryType=Simple&$count=false
メリット、デメリット
アプリケーション側に手を入れる必要がなのでお手軽です。 一度設定しておけばコンソール側でログをいつでも見れるので便利です。
リクエスト量が多くなってしまうと、ログの量も多くなり、費用がかさむ恐れがあります。また、複数の人が触る環境の場合は自分で送信したリクエストがどれだったのか?といった状況に陥る可能性はあります。
その他は?
Azureに対してではないですが、昔似たようなことをやるときにやっていた方法として、ローカルにプロキシサーバーを起動し、そのプロキシサーバー経由でアプリケーションから、Azureに接続することで、リクエストを保存する方法もあります。 ざんねんながら、未調査ですがアプリなどにはそれほど手を入れる必要はないかと思います。
まとめ
ちょっと送信リクエストの内容が見てみたいという話でしたが、いろいろな手段が存在しました。 自分の状況、環境に合わせて手段を選択肢てみるのがいいかと思います。 まずは、簡単な診断ログあたりからでしょうか?
comments powered by Disqus
See Also by Hugo
- Visual Studio Codeのプラグインを作ってみた(Azure Search Analyze Client)
- インデックスエイリアス - Azure Cognitive Searchの新機能
- Azure Cognitive Searchの新機能、Semantic Searchを試してみた
- TerraformでAzure Cognitive Searchのクラスターを起動
- Azure Cognitive Searchでオートコンプリートやサジェストをしてみる