Katana + log4netによるWeb APIのロギング

ASP.NET MVCでRails::Rack::Loggerみたいなことできないかなという話。Katana + log4netでの実装とtipsについて以下述べていきます。

tl;dr

• Katanaを使ってログ用のカスタムミドルウェアを作る
• リクエストからの一連の処理を一意に識別するためにGUIDを使う

ASP.NETのミドルウェア

ASP.NETにRubyでいうRackのようなものであるOwinが搭載されました。

OWINは Open Web Interface for .Netの略で、 Webサーバに依存しないWebアプリを実現するための規格のようです。 この規格を満した開発を実現するため、Microsoftが複数コンポーネントを提供しています。 このコンポーネント群をKatana Projectと呼んでいます。

(via yamamotoさん@社内Advent Calendar)

Owin&KatanaによりASP.NETでもRackミドルウェアのようなものが差し込め、認証やロギング周りの実装がいい感じにできるようになりました。

Katanaの仕組みとしては、

1. 初めにStartupでMiddlewareというものを複数登録
2. RequestのたびにMiddlewareが順に呼ばれる

といった感じです。 このMiddlewareにやらせたい作業を記述します。

(via yamamotoさん@社内Advent Calendar)

実際の実装に関する解説は以下がとても分かりやすいです。ありがたい...!

今回はこのKatanaとロガーであるlog4netをつかって共通のロギング処理を実装してみたいと思います。

ロギング要件

以下の前提、欲望の元実装をしていこうと思います。

前提

• IISを使っている
• ASP.NET Identityを使っている
• ASP.NET Web APIを使っている

欲望

• ログ出力時にリクエストをしてきたユーザ情報を付与したい
• APIアクセスのロギングをIISログのように出したい
• IISログではrequest bodyの値がでないため、request bodyの値もできれば出したい
• HTTPリクエストのログ + 内部で呼び出されるクラス、メソッド内でのログ両方出したい
• HTTPリクエストと呼び出されるメソッドとの対応関係がとりたいので、リクエストの開始から終了までの一連の処理を一意に識別できるIDもログに出したい

なお正常系のロギングに関して考えています。エラーロギングの方はElmah + ExceptionHandler + ExceptionLoggerという便利な方法も。

miso_soup3様の記事がありがたすぎます...!

カスタムMiddleWareを作る

サンプルのためlog4netはラップしないで直接つかいます。

    public class CustomLoggerMiddleWare : OwinMiddleware
    {
        public CustomLoggerMiddleWare(OwinMiddleware next)
            : base(next)
        {
        }

        public override async Task Invoke(IOwinContext context)
        {
            var log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);
            
            // リクエスト情報
            var requestType = HttpContext.Current.Request.RequestType;
            var requestRawUrl =  HttpContext.Current.Request.RawUrl;
            var requestUserName = HttpContext.Current.User.Identity.Name;
            var requestBody =  new StreamReader(HttpContext.Current.Request.InputStream).ReadToEnd();

            var logMessage = new StringBuilder()
                .Append(requestType + " ")
                .Append(requestRawUrl + " ")
                .Append(requestUserName + " ")
                .Append(requestBody + " ");

            // ログ開始
            logger.Info(logMessage.ToString() + "START");

            await this.Next.Invoke(context);

            // ログ終了
            logger.Info(logMessage.ToString() + "END");
        }
    }

// 出力例
// 2015-01-26 19:01:33.753, INFO , POST /Sample/api/Test HogeUser CategoryId=1&Name=Test START 
// 2015-01-26 19:01:33.755, INFO , POST /Sample/api/Test HogeUser CategoryId=1&Name=Test END

あとはStartup.csにミドルウェアを登録します。

public partial class Startup
    {
        public void Configuration(IAppBuilder app)
        {
            ConfigureAuth(app);

            app.Use<CustomLoggerMiddleWare>();
        }
    }

リクエストに関する情報がHttpContextに格納されているので、プロパティをうまく使って所望のロギング処理を出力します。ミドルウェアで認証後のユーザ情報がとれるか不安でしたが、HttpContext.Current.User.Identity.Nameにちゃんと格納されていました。

リクエストからの一連の処理を一意に識別する方法

Httpリクエストをログに出力することは出来ました。リクエスト後、ASP.NET MVCだとControllerが呼び出されますが、Controller以下の内部処理でログを出したい状況があると思います。その際リクエストと内部処理との対応関係をとるため、一連処理を一意に識別するIDなどが必要となります。リクエストはどんどんやってくるので、ログの流れが別リクエストのログと混じるためです。

IISはデフォルトだとシングルプロセス、マルチスレッドなシステムです。例えばRailsのUnicornだと1プロセスが1リクエストを担ったりしますね。Web Gardenを用いることによりマルチプロセス化もできますが、とりあえずデフォルトで考えます。

スレッドIDじゃ駄目

当初「スレッドIDをログに付与すれば、リクエストからメソッドまでの流れを一意に識別できるかな？」と思いました。調べたところ、IISでは同一のスレッドが使われる保証ないとのことです。

c# - How are IIS7 threads assigned? - Stack Overflow

So any static classes you may have in your application are shared across each of these threads or application instances.

アプリケーションの静的クラスはスレッド間やアプリケーションインスタンス間で共有されるとのこと。おもしろい！ 以下も参考になります。

ASP.NET Performance-Instantiating Business Layers On Matlus

multithreading - How are threads tied to requests through Http.sys, IIS and ASP.NET - Stack Overflow

Application_BeginRequestにGUIDを付与する

スレッドIDだとどうも駄目だということでいろいろ調べると以下の情報が。

Global.asaxのApplication_BeginRequestでGUIDをHttpContext.Current.Itemsに挿入すればいいじゃん！という話。結構ごりおしですが、確かに効果的...

というわけでGlobal.asaxに以下を追加します

 protected void Application_BeginRequest()
        {
            HttpContext.Current.Items.Add("RequestIdentity", Guid.NewGuid().ToString());
        }

リクエストの開始時にGUIDをHttpContext.Currentに追加することでリクエストの一意識別IDとなります。あとは要所でHttpContext.Current.Items["RequestIdentity"]を使いGUIDをとりだせば良いかと。

まとめ

今回はログ処理をKatanaミドルウェアを使って実装してみました。ログ処理って特定の部分じゃない限りは楽して出したいところなので、ミドルウェアで実装できるの素敵です。共通のロギング処理はUnityのinterceptionでやる方法もASP.NET WEB APIだったらあるのかなーとも思います。他にもキューイングシステムを使ったロギングとかもできるのかな？ログ処理について深く考えたことがなかったので今後も色々しらべてみたいです。