Azure Web Apps + ASP.NET MVC のアプリログ出力

ASP.NET MVC ASP.NET Core MVC Azure Web Apps

Azure Web Apps + ASP.NET MVC でアプリケーションログを出力する場合、log4net などのログライブラリを使用するのも可能ではあるが、Azure のビルトインとして用意されている App Service ログを使用した方が、ちゃんとログ出力されるかなど余計な心配をしなくて済む（ファイル名はインスタンス ID ＋ PID で生成される）。

Azure ポータルでの設定

f:id:poke_dev:20191124111934p:plain

Storage Explorer でログファイルを確認

f:id:poke_dev:20191124112359p:plain

出力されたログファイルの中身

f:id:poke_dev:20191124112652p:plain

複数インスタンス、ワーカープロセスで同時に実行されていても問題ない

f:id:poke_dev:20191124112743p:plain

但し、以下のようにデメリットもある。

  • ログ出力のフォーマットがカスタマイズできない。開発者が出力内容として手を出せるのは Message プロパティのみ
  • 古いログをどこまで残すかの設定は、日数によるリテンション期間の指定のみ
  • ログローテーションの種別は、日時のみ。時間単位での出力のみとなるため、一日通してのログを確認したい時などは、やや手間

上記のような制限はあるものの、自分のプログラム側での仕掛けが一切不要であることや Azure Web Apps 環境で安定してログ出力できることと天秤にかけた場合、受け入れ可能な範囲だと思う。

但し、ASP.NET MVC アプリとしてログ出力する場合、上記とは別に、一つ大きな問題が発生する可能性がある。 通常、Web アプリでログを出力する場合、リクエストを跨いだ同一ユーザーの一連の流れを追うため、セッション ID のような同一セッションを追跡できる情報を補足情報として出力する必要があるが、App Service ログで使用される Trace クラスにはそれに適したプロパティなどはないため、プログラム側でどうにかして、Message プロパティに含める必要がある。

一応、App Service ログ出力項目の一つである ActivityId がトレース用の情報として使えそうではあるが、リクエスト単位で変わったり、非同期メソッド呼び出し時に切り替わったり、そもそも空で出力される挙動などがあるため、セッション追跡用の情報としてはやはり使えない。

対応方法

結論としては、アプリで Trace 出力する Message に Session.SessionID を常に含めれば良いわけだが、Session クラスは ASP.NET のレイヤー上にあり、アプリ全体でログ出力が必要になることを考えると、そのまま使うわけにはいかない。

この問題に対処するため、CallContext を使用する。リクエスト受信時、セッションが使用可能になったタイミング (Application_PostAcquireRequestState) で CallContext に SessionID を格納し、ログ出力時は CallContext から SessionID を取り出して使用する。

Application_PostAcquireRequestState イベントより前のメソッドについてはセッション ID が使えないので、ActivityId で追跡する。 なお、上述したように空になる可能性があるため、これを緩和するために BeginRequest で初期化を行う。

Global.asax.cs

protected void Application_BeginRequest(object sender, EventArgs e)
{
    // empty になる場合があるので、強制的に初期化する
    Trace.CorrelationManager.ActivityId = Guid.NewGuid();

    Trace.WriteLine("Application_BeginRequest start");
}

protected void Application_PostAcquireRequestState(object sender, EventArgs e)
{
    if (Context.Handler is IRequiresSessionState)
    {
        CallContext.LogicalSetData("SID", Session.SessionID);
    }

    // 以降は、以下のように CallContext から SessionID を取得して、使用する
    var sessionId = CallContext.LogicalGetData("SID");
    Trace.WriteLine(string.Format("[SID: {0}] Application_PostAcquireRequestState start", sessionId));
}

続、問題 (CallContext に格納した情報が null になる)

基本的には上記の対応で、トレース用の SessionID が App Service ログに出力されるようになるはずなのだが、まだ問題がある。

CallContext に格納した情報が、なぜか null になってしまうタイミングが、自分が確認する限りあった。 原因の詳細は不明だが、自分が確認する限り、ライフサイクルの中で、ページの処理に入ったタイミングと出るタイミングでの発生を確認した（この場合も必ず発生するわけではない）。

原因が不明なので少し気持ちは悪いが、上記のタイミングにフォーカスして問題を緩和するため、以下のようにページの処理に入った直後と出た直後のタイミングでそれぞれ CallContext の状態を確認し、null なら再設定を行うことで基本的にはセッション情報が出力されるようになるのを確認した。

Controller

public class HomeController : Controller
{
    protected override void OnAuthorization(AuthorizationContext filterContext)
    {
        base.OnAuthorization(filterContext);

        try
        {
            var sessionId = CallContext.LogicalGetData("SID");

            if (sessionId == null)
            {
                CallContext.LogicalSetData("SID", Session.SessionID);
            }
        }
        catch
        {
            // 問題発生しても何もしない
        }
    }

Global.asax.cs

protected void Application_PostRequestHandlerExecute(object sender, EventArgs e)
{
    try
    {
        var sessionId = CallContext.LogicalGetData("SID");

        if (sessionId == null)
        {
            CallContext.LogicalSetData("SID", Session.SessionID);
        }
    }
    catch
    {
        // 問題発生しても何もしない
    }
}
参考