Log4netの出力ログフォーマットのカスタマイズ

はじめに

こんにちは～皆様お元気にお過ごしですか～？ ROBOT PAYMENT サブスクペイのシステム基盤チームの yoponpon です。システム基盤チームではアプリケーションやシステムインフラの基礎部分の構築や管理、メンテナンス、性能改善などを行っています。今回は、C#, .net framework, Log4netを利用したシステム運用・分析やログ調査の際に運用に合わせた自社アプリケーションのログフォーマット設定の方法を書こうと思います。

なんのためにログのフォーマットを編集するのか

システムの運用をしていると不具合の調査、お客様からの調査依頼などでアプリケーションが出力するログを閲覧することはしばしばあります。ログを見る際に日時や処理内容などを注視しますが、それに紐付くパラメーター（入力内容やログインID,顧客番号や処理IDなど）を見たい場合がございます。それらをログに定常的に埋め込むことによってどのユーザーがどのような操作をしたのかその結果どんな不具合が起きたのかなど調査の対応がしやすくなります。

Log4netのログフォーマットの設定方法

Log4netの設定方法としてApp.Config、Web.Configなどへの記載がございます。例えばアプリケーションログを日次で出力したい場合は RollingLogFileAppender を利用して rollingStyle をDateに設定します。その場合のConfigのサンプルは以下です。見覚えのある人はいると思います。各Appenderのサンプルは以下で確認可能です。
logging.apache.org

    <appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
        <file value="logfile" />
        <appendToFile value="true" />
        <rollingStyle value="Date" />
        <datePattern value="yyyyMMdd-HHmm" />
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
        </layout>
    </appender>

ログのフォーマットは conversionPattern の箇所で設定可能です。ここで設定したフォーマットのとおりにログが出力される形となります。

設定パターン1 - HTTPリクエスト毎に一意なIDを設定

複数台構成のWebサービスであっても、単体のWebアプリであっても基本はHTTPリクエストの処理自体が1つのプロセス内で完結するかと思います。一つのHTTPリクエストに対して一意なIDを割り当てることによってアプリケーションのログの中からIDで紐つけてログを抽出できます。

こちらを設定することによって以下のようにログが出力されます。各ログエントリーに対して、TRANS_IDをつけて、HTTPリクエストレスポンスに対して出力されたログを一律で抽出できます。

2023-XX-XX XX:XX:XX,XXX TRANS_ID:[0d3fad5d-11ef-4555-a88b-a7106f79fe86]  INFO (TestApp.Global:Application_BeginRequest:150) - 
--- ログの内容 ---

設定パターン1 - HTTPリクエスト毎に一意なIDを設定（実装）

Web.Configファイルのlog4net設定の conversionPattern を以下のように設定してパラメーターを定義します。以下 TRANS_ID:[%property{TransID}] を記載しております。%property{xxxxx} でカスタムパラメーターが定義可能です。

<conversionPattern value="%d [%t] TRANS_ID:[%property{TransID}] %5p (%C:%M:%L) - %m%n" />

WebアプリケーションのHTTPリクエスト開始時処理にてカスタムパラメーターの設定を行います。リクエスト開始時の処理でGUIDを設定することで、該当のリクエストに一意なIDを与えて、後続の処理で出力される同一リクエストのログで同じIDが設定される形となります。IDはGUIDでも、外部から取得する形でも対応可能となります。 ※HTTPリクエストがマルチスレッドで処理される場合の検証はしておりません。

protected void Application_BeginRequest(object sender, EventArgs e)
{
    try
    {
        LogicalThreadContext.Properties["TransID"] = Guid.NewGuid();
    }
    catch (Exception ex)
    {
        LogicalThreadContext.Properties["TransID"] = "None";
    }
}

設定パターン2 - 現在ログイン中のユーザーID,顧客番号を出力

各アプリケーションのログに対してログイン中（操作者）のIDを含めることによってどのユーザーがいつ何をしたのか、その結果どんな不具合が発生したのかを調査できます。

各ログエントリーにUSER_IDを含めた場合の例です。 USER_ID:[13768937] のように、ログインしている操作者のIDをログフォーマットに含めて出力しています。

2023-XX-XX XX:XX:XX,XXX [XX] USER_ID:[13768937]  INFO (TestApp.Global:Application_AcquireRequestState:152) -

設定パターン2 - 現在ログイン中のユーザーID,顧客番号を出力（実装）

Web.Configファイルのlog4net設定の conversionPattern を以下のように設定してパラメーターを定義します。以下 USER_ID:[%property{UserID}] を記載しております。%property{xxxxx} でカスタムパラメーターが定義可能です。

<conversionPattern value="%d [%t] USER_ID:[%property{UserID}] %5p (%C:%M:%L) - %m%n" />

WebアプリケーションのHTTPリクエスト開始時処理にてカスタムパラメーターの設定を行います。リクエスト開始時の処理でHTTPContextなどから取得できるUserIDを設定します。後続の処理で出力される同一リクエストのログで操作者のIDが設定される形となります。サンプルはASP.NET WebFormsの例となります。 Application_BeginRequest の段階ではHTTPセッションが取得できないため、 Application_AcquireRequestState にて処理を実施しております。 ※HTTPリクエストがマルチスレッドで処理される場合の検証はしておりません。

protected void Application_AcquireRequestState(object sender, EventArgs e)
{
    try
    {
        // UserIDの取得部分の処理はアプリケーションごとに異なります。
        LogicalThreadContext.Properties["UserID"] = HttpContext.Current.Session['UserID'];
    }
    catch (Exception ex)
    {
        LogicalThreadContext.Properties["UserID"] = "Unknown";
    }
}