Semantic Logging Application Block で ETW ログを Azure Search に出力する

www.buildinsider.net

先月、Build Insider MEETUP with Grani に参加してきました。C# で Web アプリケーションを作るフレームワークの話のなかで、Semantic Logging Application Block（SLAB）が面白そうだったので、試してみました。

SLAB は、Event Tracing for Windows（ETW）のログを出力できるライブラリであり、Enterprise Library 6.0 に含まれるアプリケーションブロックのひとつです。厳密に型付けされたイベントをベースにしたログは、コンソールアプリ、テキストファイル、SQL Server、Azure Table Storage、Elasticsearch などに出力できます。Elasticsearch に出力できるなら、Azure Search に出力してもよさそうなので試してみました。ASP.NET Web API で発生した例外をハンドリングして、ETW ログを出力するシナリオです。

ETW ログを書き込む

ASP.NET Web API の Web アプリケーションを作成し、ETW ログを書き込むクラスを作成します。EventSource クラスを継承したクラスを作成し、ログを書き込む Error メソッドを実装します。ログに書き込む情報は、HTTP メソッド、URL の絶対パス、例外メッセージの３つとします。

#MyEventSource.cs
[EventSource(Name = "MyEventSource")]
public sealed class MyEventSource : EventSource
{
    private readonly static MyEventSource log = new MyEventSource();
    private MyEventSource() { }
    public static MyEventSource Log { get { return log; } }
 
    [Event(1, Level = EventLevel.Error, Message = "An error has occurred")]
    public void Error(string method, string path, string exceptionMessage)
    {
        WriteEvent(1, method, path, exceptionMessage);
    }
}

例外をハンドリングする ExceptionLogger クラスを継承したクラスを作成してロギングします。

#MyExceptionLogger.cs
[EventSource(Name = "MyEventSource")]
public class MyExceptionLogger : ExceptionLogger
{
    public override void Log(ExceptionLoggerContext context)
    {
        var method = context.Request.Method.ToString();
        var path = context.Request.RequestUri.AbsolutePath;
        var exceptionMessage = context.Exception.Message;
 
        MyEventSource.Log.Error(method ?? "", path ?? "", exceptionMessage ?? "");
    }
}

MyExceptionLogger クラスは、WebApiConfig クラスで有効化しておきます。

#WebApiConfig.cs
[EventSource(Name = "MyEventSource")]
public static class WebApiConfig
{
    public static void Register(HttpConfiguration config)
    {
        config.Services.Add(typeof(IExceptionLogger), new MyExceptionLogger());
 
        （省略）
        );
    }
}

Azure Search のアクセスクラスを作成する

Web アプリケーションのプロジェクトに、Azure Search Library（Preview）を NuGet からインストールします。ログのデータをモデルに詰め替えたいので、AutoMapper も合わせてインストールします。

Install-Package Microsoft.Azure.Search -Pre
Install-Package AutoMapper -Version 3.3.1

Azure Search に対して、インデックスの作成、ログのアップロード、ログの検索を行うアクセスクラスを作成します。

#EventSearchClient.cs
public class EventSearchClient
{
    private readonly string _serviceName;
    private readonly string _apiKey;
    private readonly string _indexName;
 
    public EventSearchClient(string serviceName, string apiKey)
    {
        this._serviceName = serviceName;
        this._apiKey = apiKey;
        this._indexName = "event";
    }
 
    public async Task CreateIndexAsync()
    {
        using (var serviceClient = new SearchServiceClient(this._serviceName, new SearchCredentials(this._apiKey)))
        {
            // インデックスの削除
            if (await serviceClient.Indexes.ExistsAsync(this._indexName))
            {
                await serviceClient.Indexes.DeleteAsync(this._indexName);
            }
 
            // インデックスの作成
            var definition = new Index()
            {
                Name = this._indexName,
                Fields = new[]
                    {
                        new Field("id", DataType.String)    { IsKey = true },
                        new Field("providerId", DataType.String)  { IsSearchable = true, IsFilterable = true },
                        new Field("eventId", DataType.Int32)  { IsFilterable = true },
                        new Field("keywords", DataType.Int32)  { IsFilterable = true },
                        new Field("level", DataType.Int32)  { IsFilterable = true },
                        new Field("message", DataType.String)  { IsSearchable = true, IsFilterable = true },
                        new Field("opcode", DataType.Int32)  { IsFilterable = true },
                        new Field("task", DataType.Int32)  { IsFilterable = true },
                        new Field("version", DataType.Int32)  { IsFilterable = true },
                        new Field("eventName", DataType.String)  { IsSearchable = true, IsFilterable = true },
                        new Field("timestamp", DataType.DateTimeOffset)  { IsFilterable = true, IsSortable = true },
                        new Field("processId", DataType.Int32)  { IsFilterable = true },
                        new Field("threadId", DataType.Int32)  { IsFilterable = true },
                        new Field("method", DataType.String)  { IsSearchable = true, IsFilterable = true },
                        new Field("path", DataType.String)  { IsSearchable = true, IsFilterable = true },
                        new Field("exceptionMessage", DataType.String)  { IsSearchable = true, IsFilterable = true },
                    }
            };
            await serviceClient.Indexes.CreateAsync(definition);
        }
    }
 
    public async Task UploadAsync(string json)
    {
        using (var serviceClient = new SearchServiceClient(this._serviceName, new SearchCredentials(this._apiKey)))
        using (var indexClient = serviceClient.Indexes.GetClient(this._indexName))
        {
            // JSON 形式のログを、Azure Search で検索しやすい MyEventEntryModel 型に変換
            var eventEntry = JsonConvert.DeserializeObject<List<MyEventEntry>>(json);
            var documents = eventEntry.Select(x => Mapper.Map<MyEventEntryModel>(x));
            try
            {
                // ログのアップロード
                await indexClient.Documents.IndexAsync(IndexBatch.Create(documents.Select(x => IndexAction.Create(x))));
            }
            catch (IndexBatchException e)
            {
                var message = String.Format(
                    "Failed to index some of the documents: {0}",
                    String.Join(", ", e.IndexResponse.Results.Where(r => !r.Succeeded).Select(r => r.Key)));
                throw new Exception(message);
            }
            await Task.Delay(2000); // 非同期で作成されるので、少し待機する
        }
    }
 
    public async Task<IEnumerable<MyEventEntryModel>> SearchAsync(string searchText)
    {
        using (var serviceClient = new SearchServiceClient(this._serviceName, new SearchCredentials(this._apiKey)))
        using (var indexClient = serviceClient.Indexes.GetClient(this._indexName))
        {
            var sp = new SearchParameters();
            sp.OrderBy = new List<string> { "timestamp desc" };
            var response = await indexClient.Documents.SearchAsync<MyEventEntryModel>(searchText, sp);
            return response.Results.Select(x => x.Document);
        }
    }
}

UploadAsync メソッドでは、JSON 形式で渡されてきたログを MyEventEntry クラスにデシリアライズしています。MyEventEntry クラスは、Payload プロパティに HTTP メソッド、URL の絶対パス、例外メッセージが内包されていて Azure Search では検索し難いため、AutoMapper でフラットな MyEventEntryModel クラスに詰め替えています。

#MyEventEntry.cs
[SerializePropertyNamesAsCamelCase]
public class MyEventEntryModel
{
    public string Id { get; set; }
    public string ProviderId { get; set; }
    public int? EventId { get; set; }
    public int? Keywords { get; set; }
    public int? Level { get; set; }
    public string Message { get; set; }
    public int? Opcode { get; set; }
    public int? Task { get; set; }
    public int? Version { get; set; }
    public string EventName { get; set; }
    public DateTimeOffset? Timestamp { get; set; }
    public int? ProcessId { get; set; }
    public int? ThreadId { get; set; }
    public string Method { get; set; }
    public string Path { get; set; }
    public string ExceptionMessage { get; set; }
}

#MyEventEntryModel.cs
[SerializePropertyNamesAsCamelCase]
public class MyEventEntryModel
{
    public string Id { get; set; }
    public string ProviderId { get; set; }
    public int? EventId { get; set; }
    public int? Keywords { get; set; }
    public int? Level { get; set; }
    public string Message { get; set; }
    public int? Opcode { get; set; }
    public int? Task { get; set; }
    public int? Version { get; set; }
    public string EventName { get; set; }
    public DateTimeOffset? Timestamp { get; set; }
    public int? ProcessId { get; set; }
    public int? ThreadId { get; set; }
    public string Method { get; set; }
    public string Path { get; set; }
    public string ExceptionMessage { get; set; }
}

MyEventEntryModel クラスには、ポイントが３つあります。

SerializePropertyNamesAsCamelCase 属性により、大文字小文字の違いを意識しないで大丈夫
値型は NULL を許容する必要がある
Azure Search の日付型は、DateTimeOffset

AutoMapper のマッピング定義は、Global.asax の Application_Start メソッドで設定しておきます。

#Global.asax
public class MvcApplication : System.Web.HttpApplication
{
    protected void Application_Start()
    {
        （省略）
 
        Mapper.CreateMap<MyEventEntry, MyEventEntryModel>()
            .ForMember(dst => dst.Method, opt => opt.MapFrom(src => src.Payload.method))
            .ForMember(dst => dst.Path, opt => opt.MapFrom(src => src.Payload.path))
            .ForMember(dst => dst.ExceptionMessage, opt => opt.MapFrom(src => src.Payload.exceptionMessage))
            .ForMember(dst => dst.Timestamp, opt => opt.MapFrom(src => new DateTimeOffset(src.Timestamp)))
            .ForMember(dst => dst.Id, opt => opt.MapFrom(src => String.Format("{0:D19}", DateTime.MaxValue.Ticks - src.Timestamp.Ticks)));
    }
}

SLAB の Custom Event Sink を作成する

SLAB で任意のストレージにログを出力したい場合には、Custom Event Sink を作成します。IObserver<EventEntry> クラスを継承したクラスを作成し、OnNext メソッドでログの出力を実装します。EventSearchClient クラスの UploadAsync メソッドの呼び出しは、UI スレッドに戻さないように ConfigureAwait(false) で待機する必要があります。

#AzureSearchSink.cs
public class AzureSearchSink : IObserver<EventEntry>
{
    private readonly string _serviceName;
    private readonly string _apiKey;
 
    public AzureSearchSink(string serviceName, string apiKey)
    {
        this._serviceName = serviceName;
        this._apiKey = apiKey;
    }
 
    public void OnCompleted()
    {
    }
 
    public void OnError(Exception error)
    {
    }
 
    public void OnNext(EventEntry value)
    {
        if (value != null)
        {
            using (var writer = new StringWriter())
            {
                new JsonEventTextFormatter().WriteEvent(value, writer);
                Post(writer.ToString());
            }
        }
    }
 
    private void Post(string body)
    {
        var json = String.Format("[{0}]", body);    // JSON配列
        new EventSearchClient(this._serviceName, this._apiKey).UploadAsync(json).ConfigureAwait(false);
    }
}

ObservableEventListener クラスに AzureSearchSink クラスを設定する拡張メソッドを定義し、Global.asax の Application_Start メソッドで設定します。LogToAzureSearch メソッドのサービス名と API キーは、Azure 管理ポータルから取得した情報を設定してください。

#AzureSearchSinkExtensions.cs
public static class AzureSearchSinkExtensions
{
    public static EventListener CreateListener(string serviceName, string apiKey)
    {
        var listener = new ObservableEventListener();
        listener.LogToAzureSearch(serviceName, apiKey);
        return listener;
    }
 
    public static SinkSubscription<AzureSearchSink> LogToAzureSearch(this IObservable<EventEntry> eventStream, string serviceName, string apiKey)
    {
        var sink = new AzureSearchSink(serviceName, apiKey);
        var subscription = eventStream.Subscribe(sink);
        return new SinkSubscription<AzureSearchSink>(subscription, sink);
    }
}

#Global.asax
public class MvcApplication : System.Web.HttpApplication
{
    protected void Application_Start()
    {
        （省略）
 
        var listener = new ObservableEventListener();
        listener.EnableEvents(MyEventSource.Log, EventLevel.Error);
        listener.LogToAzureSearch("xxx", "xxx");
    }
}

Web API を作成する

ASP.NET Web API の EventController クラスを作成し、POST メソッドでインデックスの作成、GET メソッドでログの検索を行います。

#EventController.cs
[RoutePrefix("api/event")]
public class EventController : ApiController
{
    private readonly string _serviceName = "xxx";
    private readonly string _apiKey = "xxx";
 
    [Route]
    public async Task<IEnumerable<MyEventEntryModel>> Get()
    {
        return await new EventSearchClient(this._serviceName, this._apiKey).SearchAsync("");
    }
 
    [Route("{searchText}")]
    public async Task<IEnumerable<MyEventEntryModel>> Get(string searchText)
    {
        return await new EventSearchClient(this._serviceName, this._apiKey).SearchAsync(searchText);
    }
 
    [Route]
    public async Task Post()
    {
        await new EventSearchClient(this._serviceName, this._apiKey).CreateIndexAsync();
    }
}

もうひとつ、例外を発生させる TestController クラスも作成します。

#TestController.cs
[RoutePrefix("api/test")]
public class TestController : ApiController
{
    [Route("{id:int}")]
    public string Get(int id)
    {
        throw new Exception(String.Format("test{0}", id));
        return "success";
    }
}

結果確認

Google Chrome の Postman を使って、Web API を実行します。

POST api/event/
GET api/test/1/
GET api/test/2/
GET api/test/3/
GET api/event/

上記のような 5 つの Web API を実行すると、Azure Search にインデックスが作成され、発生した例外のログがアップロードされます。結果として、3 件のログを取得できます。

また、GET api/event/test2/ を実行すると、条件を絞り込んでログを取得することも可能です。

まとめ

アプリケーションのログは、単に溜め込んでいくだけでは十分な分析や活用ができないので、活用しやすい構造で保管していくことが重要です。SLAB と ETW を使えば、セマンティックな構造化されたログを、任意のストレージに出力することができます。コンソールや Windows Service を使って SLAB を Out of Process でホストさせることも可能です。自前でログを作り込むのもよいですが、SLAB はなかなか面白いライブラリなので、使ってみるのもありだと思いました。