Serilogのログイベントからの情報抜き出し方法

はじめに

c#の構造化ログフレームワークの一つにSerilogがある。

.NET Frameworkの世界において、構造化されたログを扱うフレームワークは下記のようなものが存在する。

• SLAB
• EtwStream
• Serilog

ただし、SLABに関してはcore対応する気配がなく、EtwStreamについてはMicrosoft.Diagnostics.Tracing.TraceEventに依存しているので、記事作成時点(2016/3～4)ではcoreで使えなかった。なお、両フレームワークが使用しているSystem.Diagnostics.Tracing自体はcoreclrで使用できる模様。ただし、frameworksに"dnx452"は使用できないので注意。

ETWに関しては.NET Coreで対応も検討されているみたいだが、現時点でどのような状況になっているかは不明。

というわけで、coreclrにも使用できるSerilogを使おうと思ったわけだけど、何も意識しないと文字列が'"'でエスケーピングされるという仕様だったり、パラメーターとして来た値がただでは取り出すことができなかったり等、多少癖があったので値の扱い方について書いていく。

ただ、ぶっちゃけていうと、フルの.NET Frameworkを使用していい環境なら、前二者を使用した方が効率がいいかもしれない(厳密に検証したわけではない)ので、要件が許すならそちらを使った方がいいと思う。

Serilogについて

Serilogについての基本的なことは、Serilogのwikiページを見てもらうとして、より細かい出力制御を行いたい場合、WriteTo.Observersを使うのが一番簡単。

現在の安定板は1.5.4だが、coreclr上で使用する場合は、2.x系を使用する必要がある。2.x系では新機能追加の他、nugetの構成がより細分化されているので注意。

WriteTo.Observersの使用例

// using Serilog;
Log.Logger = new LoggerConfiguration()
.WriteTo.Observers((IObservable<Serilog.Events.LogEvent> obs) => 
{
  obs.Subscribe((le)=>
  {
    Console.WriteLine("{0}",le.RenderMessage());
  }
})

Log.Information("{Foo} {Bar}","abc",0);

以下のようにすると、コンソールに以下のように表示される

"abc" 0

RenderMessageでは、時間やログレベル等の情報について含まれた状態で出力されるわけではないことに注意。
また、デフォルトでは文字列が自動的に"で囲まれ、かつ文字列中に"があった場合、\でエスケープされる。

Serilog.Events.LogEventについて

メンバー

• DateTimeOffset Timestamp = ログ書き込み時刻
• Serilog.Events.LogEventLevel Level = ログ書き込み時に指定したInformation、Warning,Error等のenum値
• Serilog.Events.MessageTemplate MessageTemplate = ログ書き込み時に指定したフォーマット部分。メッセージテキスト部分と、パースした結果のトークンリストが格納される
• IReadOnlyDictionary<string,Serilog.Events.LogEventPropertyValue> Properties = パラメーター部分で指定した値のリストや、その他追加のコンテキスト情報が辞書として格納される
• Exception Exception = ログ書き込みの際、Exceptionオブジェクトを渡していた場合に、ここにオブジェクトが格納される

MessageTemplateについて

MessageTemplateは以下の要素で構成される

• string Text = フォーマット部分で指定した文字列そのまま
• IEnumerable<Serilog.Parsing.MessageTemplateToken> Tokens = Textを分解した結果
  • MessageTemplateTokenクラス自身には情報がなく、必ずSerilog.Parsing.PropertyTokenかSerilog.Parsing.TextTokenのどちらかになるので、中の値を扱う場合はキャストが必要
  • PropertyTokenには、パラメーター名と、出力指定フォーマット等の情報が入っている
  • TextTokenには、パラメーター部分以外のテキストが入っている

LogEventPropertyValueについて

パラメーター部分で指定した値を、Serilogが解釈した結果が入る。
以下のような派生クラスのどれかになるので、実際に値を取り出す時はキャストして使用することになる。
なお、名前空間はいずれもSerilog.Events以下。

• ScalarValue = Serilogのパラメーターの最小単位で、Valueに https://github.com/serilog/serilog/wiki/Structured-Data#simple-scalar-values で示された型の値が格納される。全てのパラメーターの末端部分はこのScalarValueになる(Valueがnullの可能性もある)
  • stringに関してはエスケープ前の文字列が入る
  • 解釈できない値に関しては、ToStringした上でScalarValue.Valueに格納される
• DictionaryValue = IDictionary<TKey,TValue>で渡されたインスタンスを、IDictionary<ScalarValue,LogEventPropertyValue>に変換したものが入る
• SequenceValue = IEnumerable<T>で渡されたインスタンスを、IEnumerable<LogEventPropertyValue>に変換したもの
• StructureValue = ログフォーマットで@を指定した場合で、かつSerilogで解釈できる基本形ではない場合にこのクラスに変換される
  • 型の名前はTypeTagに格納されるが、匿名型の場合はここがnullになる

文字列のエスケープについて

Serilogでは、デフォルトで文字列に"のエスケープがかかる。これを回避するには、フォーマットに部分で{Param:l}のように指定すればいいわけだが、これが有効なのは最上位のScalarValueのみなので、Dictionary<string,string>みたいなインスタンスを渡していた場合は、自分でScalarValueを取り出して値を解釈する必要がある。

値取り出し例

最後に、値取り出しの検証用に使用したコードを以下に貼っておく。

// using Serilog;
// using Serilog.Events;
// using Serilog.Parsing;
static void WriteEvent(LogEvent le)
{
    var sb = new StringBuilder();
    // プロパティの取り出し
    foreach (var prop in le.Properties)
    {
        var name = prop.Key;
        if (prop.Value is ScalarValue)
        {
            var scval = prop.Value as ScalarValue;
            //sb.AppendFormat("scval({0})={1}", name, Jil.JSON.SerializeDynamic(scval.Value, Jil.Options.ISO8601));
            sb.AppendFormat("scval({0})={1}", name, scval.Value);
        }
        else if (prop.Value is StructureValue)
        {
            var stval = prop.Value as StructureValue;
            sb.AppendFormat("stval({0})={1}", name, stval.ToString());
        }
        else if (prop.Value is DictionaryValue)
        {
            var dicval = prop.Value as DictionaryValue;
            sb.AppendFormat("dicval({0})={1}", name, string.Join(";", dicval.Elements.Select(kv => string.Format("{0}={1}", kv.Key, kv.Value))));
        }
        else if (prop.Value is SequenceValue)
        {
            var seqval = prop.Value as SequenceValue;
            sb.AppendFormat("seqval({0})={1}", name, string.Join(";", seqval.Elements));
        }
        else
        {
            continue;
        }
        sb.AppendLine();
    }
    // テンプレート構成要素の取り出し
    foreach (var token in le.MessageTemplate.Tokens)
    {
        if (token is Serilog.Parsing.PropertyToken)
        {
            var propToken = (Serilog.Parsing.PropertyToken)token;
            sb.AppendFormat("proptoken={0},{1},{2}", propToken.PropertyName, propToken.Destructuring, propToken.Format);
            sb.AppendLine();
        }else if(token is Serilog.Parsing.TextToken)
        {
            var textToken = (Serilog.Parsing.TextToken)token;
        }
    }
    // 最終的にSerilogが解釈した文字列の取得
    sb.AppendLine(le.RenderMessage());
    System.Diagnostics.Trace.WriteLine(sb.ToString());
}