C#でSerilogとFody.Anotarを使って、全部盛りのログをとる

概要

SerilogとFody.Anotarを使用して、ゴテゴテにした全部盛りのログを取ります。

最終的には

LogTo.Information("Hello World!");

と書くと、以下のように出力されます。

 | 22:47:59.596 | INFO | 01:MN | 21164:SerilogConsoleTest | Hello World! | SerilogConsoleTest.Program | Void Main(String[]) | 27 L | SerilogConsoleTest | 1.0.0.0 | <マシン名> | <ユーザー名> | 834036 B|

中身は記録時刻、ログレベル、スレッドID、スレッド名、プロセスID、プロセス名、メッセージ本文、呼び出し元名前空間＋クラス名、呼び出し元メソッドシグネチャ、行番号、アセンブリ名、アセンブリバージョン、マシン名、ユーザー名、使用メモリ量、(あれば例外)、と盛るぜぇ～超盛るぜぇ～になっています。

さらに、メッセージ本文と例外は構造化ログの機能があるため、単純な文字列以上の表現ができます。

方法

コンソールアプリケーション

まず、VisualStuidoのコンソールアプリケーションテンプレートを選んで作成します。
記事では.NET Coreを使用しますが、.NET Frameworkでも問題ありません。

Program.cs

class Program
{
    static void Main(string[] args)
    {
        Console.WriteLine("Hello World!");        
    }
}

これを変更していきます。

Serilogの導入

まずは最小限のSerilogを使ったログからです。
nugetで"Serilog"と検索すると、似たロゴのパッケージがズラリと並びます。

腰が引けるきもしますが、1つ1つのパッケージはそれほど重くありません。
まず、ログの出力先に合わせたパッケージを指定します。

• Serilog.Sinks.File: ファイル
• Serilog.Sinks.Console: コンソール
• Serilog.Sinks.Debug: デバッグ出力ウインドウ

そして、先ほどのコンソールアプリケーションを変更します。

Program.cs

class Program
{
    static void Main(string[] args)
    {
        SetupLoggerConfig();
        Log.Information("Hello World!");       
    }
    private static void SetupLoggerConfig()
    {        
        string template = "| {Timestamp:HH:mm:ss.fff} | {Level:u4} | {Message:j} | {NewLine}{Exception}";
        string logFilePathHead = $"logs\\{nameof(SerilogConsoleTest)}";

        Log.Logger = new LoggerConfiguration()                     
                        .MinimumLevel.Verbose()
                        .WriteTo.Console(outputTemplate: template)
                        .WriteTo.Debug(outputTemplate: template)
                        .WriteTo.File($"{logFilePathHead}.txt", LogEventLevel.Information, outputTemplate: template, rollingInterval: RollingInterval.Day)                                            
                        .CreateLogger();
    }
}

SetupLoggerConfig()でロガーのセットアップを行っています。
ここではC#を用いますが、appsettings.jsonやApp.config(XML)ファイルで設定することもできます。

各項目の解説です。

• .MinimumLevel.Verbose(): 記録するロギングレベルを決定します。Verboseは最も低いレベルです。製品にする場合はInfoにすることが多いです。またLoggingLevelSwitchを使用して、動的に変更することも可能です。
• .WriteTo.~(): ログの出力先を指定します。ここではコンソール・デバッグウインドウ・テキストファイルに出力します。出力先ごとにロギングレベルをさらにしぼることもできます。
• .WriteTo.~()内のoutputTemplate引数: 出力メッセージのフォーマットを指定します。ログの各情報の区切りは|（パイプ）にしました。このへんは好みですが、,（カンマ）や:（コロン）は後で出てくるJSON型式と被るので避けたほうがよいです。
• outputTemplate内の{Level:u4}: ロギングレベルの4文字表現です。1～11文字まで選べます。
• outputTemplate内の{Message:j}: ログメッセージ本体です。jは構造化データをJSON型式で表示します。
• .WriteTo.File()内のrollingInterval引数: ファイルを区切るタイミングを指定します。

出力はこのようになります。
まだシンプルですね。

| 21:45:47.367 | INFO | Hello World! |

Serilogパッケージの追加

ここからログ内容にいろいろ盛るぜぇ～超盛るぜぇ～。

出力内容を盛るためのパッケージを選択します。

• Serilog.Enrichers.Thread: スレッド
• Serilog.Enrichers.Process: プロセス
• Serilog.Enrichers.Environment: マシン名とユーザー情報
• Serilog.Enrichers.AssemblyName: アセンブリ情報
• Serilog.Enrichers.Memory: メモリ使用量

構造化ログ用のパッケージも選択します

• Serilog.Exceptions: 例外詳細表示
• Serilog.Formatting.Compact: Compact-JSONフォーマット

ロガーのセットアップ部分に、いろいろ追加していきます。

private static void SetupLoggerConfig()
{
    string template = "| {Timestamp:HH:mm:ss.fff} | {Level:u4} | {ThreadId:00}:{ThreadName} | {ProcessId:00}:{ProcessName} | {Message:j} | {SourceContext} | {MethodName} | {LineNumber} L | {AssemblyName} | {AssemblyVersion} | {MachineName} | {EnvironmentUserName} | {MemoryUsage} B|{NewLine}{Exception}";

    string logFilePathHead = $"logs\\{nameof(SerilogConsoleTest)}";

    Log.Logger = new LoggerConfiguration()
                    .Enrich.WithThreadId()
                    .Enrich.WithThreadName().Enrich.WithProperty("ThreadName", "__")
                    .Enrich.WithProcessId().Enrich.WithProcessName()
                    .Enrich.WithMachineName()
                    .Enrich.WithEnvironmentUserName()
                    .Enrich.WithAssemblyName()
                    .Enrich.WithAssemblyVersion()
                    .Enrich.WithMemoryUsage()
                    .Enrich.WithExceptionDetails()
                    .MinimumLevel.Verbose()
                    .WriteTo.Console(outputTemplate: template)
                    .WriteTo.Debug(outputTemplate: template)
                    .WriteTo.File($"{logFilePathHead}.txt", LogEventLevel.Information, outputTemplate: template, rollingInterval: RollingInterval.Day)
                    .WriteTo.File(new CompactJsonFormatter(), $"{logFilePathHead}_comapct.json", LogEventLevel.Information, rollingInterval: RollingInterval.Day)
                    .CreateLogger();

    Thread.CurrentThread.Name = "MN";
}

各項目の解説です。対応するものがoutputTemplateにも追加されています。

• .Enrich.WithThreadId(): スレッドIDを追加します。
• .Enrich.WithThreadName().Enrich.WithProperty("ThreadName", "__"): スレッド名を追加して、未設定なら__を変わりに表示します。
• .Enrich.WithProcessId().Enrich.WithProcessName(): プロセスIDとプロセス名を追加します
• .Enrich.WithMachineName(): マシン名（PCの名称）を追加します。
• .Enrich.WithEnvironmentUserName(): ユーザー名を追加します。
• .Enrich.WithAssemblyName(): アセンブリ名を追加します。
• .Enrich.WithAssemblyVersion(): アセンブリバージョンを追加します。
• .Enrich.WithMemoryUsage(): メモリ使用量を追加します。
• .Enrich.WithExceptionDetails(): 例外をToString()したよりも詳細な情報を追加します。
• .WriteTo.File(new CompactJsonFormatter(), ~): Compact-JSON型式の構造化ログを保存します。構造化ログについてはあとで説明します。
• Thread.CurrentThread.Name = "MN": 開始スレッド名に"MN"(Main)とつけて、他のスレッドと区別しやすくしています。デスクトップアプリケーションなど、特定のスレッドからしかアクセスできないオブジェクトがあったときに便利です。
• outputTemplate内の{SourceContext}は名前空間+クラス名、{MethodName}はメソッドシグネチャ、{LineNumber} Lはソースコード行番号ですが、今は表示されません。

ログ書き込み部分は変わらないです。
この段階での出力が以下です。一部抜けがありますが、かなり盛れています。

| 22:12:17.894 | INFO | 01:MN | 2132:SerilogConsoleTest | Hello World! |  |  |  L | SerilogConsoleTest | 1.0.0.0 | <マシン名> | <ユーザー名> | 800236 B|

Fody.Anotarの導入

さらに、メソッド名やクラス名を取得するために、Serilog連携用のFodyパッケージを使用します。
Fodyは中間言語（IL）に対してコンパイル時に加工を行うパッケージです。ログ内容を盛るためだけに使うのは大げさな気もしますが、超盛るためだからショウガナイ。

• Anotar.Serilog.Fody

プロジェクトの直下に
FodyWeavers.xmlファイルを追加して編集します。

FodyWeavers.xml

<Weavers>
  <Anotar.Serilog />
</Weavers>

Log書き込み部分をLog.~からLogTo.~に変更します。

LogTo.Information("Hello World!");

ログセットアップ部分は変更無いです。
そして最終結果が以下です。先ほど抜けていたクラス名などがFody.Anotarによって埋められました。

| 22:47:59.596 | INFO | 01:MN | 21164:SerilogConsoleTest | Hello World! | SerilogConsoleTest.Program | Void Main(String[]) | 27 L | SerilogConsoleTest | 1.0.0.0 | <マシン名> | <ユーザー名> | 834036 B|

12文字のメッセージが215文字にまで膨らみました。
めでたしめでたし

他のログ機能

ログレベル

ログ出力は全部で6段階あります。重要度が低い順に出力すると以下のようになります。

private static void CallAllLogLevel()
{
    LogTo.Verbose("Log Level 1");
    LogTo.Debug("Log Level 2");
    LogTo.Information("Log Level 3");
    LogTo.Warning("Log Level 4");
    LogTo.Error("Log Level 5");
    LogTo.Fatal("Log Level 6");
}

これをコンソールで出力すると少し色付けがされています。

出力ウインドウに表示する場合VSColorOutputを使用すると見やすくなります。

メモリ使用量と例外出力

メモリ使用量のわかり易い例と例外出力です。
以下のように、倍々で配列の長さを増やしていくと、そのうちOutOfMemoryExceptionが発生します。

private static void CauseOutOfMemoryEx()
{
    var bigArray = new int[0];
    try
    {
        for (int bit = 0; bit < 64; bit++)
        {
            bigArray = Enumerable.Range(0, (int)Math.Pow(2, bit)).ToArray();
            LogTo.Debug("Created Array {Size}", bigArray.Length);
        }

    }
    catch (Exception ex)
    {
        LogTo.Error(ex, "Fail to Create big Array");
    }
}

出力結果の一部です。
行の最後の ~Bがメモリ使用量です。
例外は例外種類・Message・StackTraceが表示されています。

| 00:20:22.613 | DBUG | ~ | Created Array 1 | SerilogConsoleTest.Program | Void CauseOutOfMemoryEx() | 59 L | ~ | 941556 B|
~
| 00:14:07.392 | DBUG | ~ | Created Array 134217728 | SerilogConsoleTest.Program | Void CauseOutOfMemoryEx() | 59 L | ~ | 806009196 B|
| 00:14:07.465 | EROR | ~ | Fail to Create big Array | SerilogConsoleTest.Program | Void CauseOutOfMemoryEx() | 65 L | ~ | 537582008 B|
System.OutOfMemoryException: Exception of type 'System.OutOfMemoryException' was thrown.
   at System.Linq.Enumerable.RangeIterator.ToArray()
   at System.Linq.Enumerable.ToArray[TSource](IEnumerable`1 source)
   at SerilogConsoleTest.Program.CauseOutOfMemoryEx() in D:\Documents\VSProjects\SerilogConsoleTest\SerilogConsoleTest\Program.cs:line 58

メッセージ内へのJSON型式埋め込み

メッセージ内にオブジェクトをJSON型式にシリアライズして埋め込みできます。

こんな変哲もないPersonクラスがあったとして、

public class Person
{
    public string Name { get; set; }
    public double Height { get; set; }
}

ログ出力します。
ポイントは@をつけること、メッセージ文字列の最初に$をつけないことです。

private static void LogStructual()
{
    var person = new Person { Name = "Tiger", Height = 143.6 };
    LogTo.Information("Show {@tiger}", person);
}

出力結果は以下のようになります。
person変数の中身がJSON型式で表示されています。

| 00:08:58.942 | INFO | ~ | Show {"Name":"Tiger","Height":143.6,"$type":"Person"} | SerilogConsoleTest.Program | Void LogStructual() | ~

構造化ログ

この記事ではあまり構造化ログについて触れていませんが、本来Serilogはそのためのライブラリです。
ログのセットアップ部分で以下のようにComact-JSON型式のファイル出力を追加します。

.WriteTo.File(new CompactJsonFormatter(), $"{logFilePathHead}_comapct.json", LogEventLevel.Information, rollingInterval: RollingInterval.Day)

上記、person変数の出力は以下のようになっています。
通常のJSON型式よりは一部が短くなっています。

SerilogConsoleTest_comapct20200501.json（一部）

{
    "@t": "2020-04-30T15:30:49.3180731Z",
    "@mt": "Show {@tiger}",
    "tiger": {
        "Name": "Tiger",
        "Height": 143.6,
        "$type": "Person"
    },
    "LineNumber": 44,
    "MethodName": "Void LogStructual()",
    "SourceContext": "SerilogConsoleTest.Program",
    "ThreadId": 1,
    "ThreadName": "MN",
    "ProcessId": 20272,
    "ProcessName": "SerilogConsoleTest",
    "MachineName": "<マシン名>",
    "EnvironmentUserName": "<ユーザー名>",
    "AssemblyName": "SerilogConsoleTest",
    "AssemblyVersion": "1.0.0.0",
    "MemoryUsage": 912476
}

構造化ログの詳細については参考URLを参照ください。

構造化ログを簡単に見たい場合は、Compact Log Format Viewerが便利です。
作成したログファイル(JSON)を読込するだけで、このように表示されます。

試していない機能

Serilogは多様なプラットフォームに対応したパッケージです。
試していませんが、ASP.NETでもできますし、最近話題のAzure App SeriviceでもAWSでも使えるようです。
webの場合RequestIdなども取得できるようです。

全体コード

以下に置いておきます。
https://github.com/soi013/SerilogConsoleTest

参考

https://github.com/serilog/serilog/wiki
https://github.com/Fody/Anotar

https://www.buildinsider.net/column/kawai-yoshifumi/003
https://www.youtube.com/watch?v=_iryZxv8Rxw

環境

VisualStudio2019
.NET Core 3.1
C#8

SerilogConsoleTest.csproj（一部)

<PackageReference Include="Anotar.Serilog.Fody" Version="5.1.0" />
<PackageReference Include="Serilog" Version="2.9.0" />
<PackageReference Include="Serilog.Enrichers.AssemblyName" Version="1.0.9" />
<PackageReference Include="Serilog.Enrichers.Environment" Version="2.1.3" />
<PackageReference Include="Serilog.Enrichers.Memory" Version="1.0.4" />
<PackageReference Include="Serilog.Enrichers.Process" Version="2.0.1" />
<PackageReference Include="Serilog.Enrichers.Thread" Version="3.1.0" />
<PackageReference Include="Serilog.Exceptions" Version="5.4.0" />
<PackageReference Include="Serilog.Formatting.Compact" Version="1.1.0" />
<PackageReference Include="Serilog.Sinks.Console" Version="3.1.1" />
<PackageReference Include="Serilog.Sinks.Debug" Version="1.0.1" />
<PackageReference Include="Serilog.Sinks.File" Version="4.1.0" />