VB.NETとログについての伺か

VB.NET

はじめに

弊社はロギングライブラリとかの扱いについて割と長い間悩んでいたのですが、自分の中のとりあえずの答えが出たので今回はそんな感じです。

ログライブラリへの強依存

さて、弊社はログライブラリとしてNLogに慣れ親しんでいるのでサンプル中で使うライブラリとしてNLogを使用しますが、Serilogやlog4netを使用しても大して変わらないと思います。たぶん*1

さて、NLogでログを取得するコードを書くとすると以下のような感じになるのではないでしょうか。

Module Module1

    Sub Main()
        Dim model = New SomeModel()
        Console.WriteLine($"{model.Add(1, 2)}")
        Console.WriteLine($"{model.Subtract(2, 1)}")
        Console.WriteLine($"{model.Subtract(1, 2)}")
    End Sub

End Module

Class SomeModel
    Private Shared ReadOnly Logger As NLog.ILogger = NLog.LogManager.GetCurrentClassLogger()

    Function Add(x As Integer, y As Integer) As Integer
        Dim result = x + y
        Logger.Info("{0} + {1} = {2}", x, y, result)
        Return result
    End Function

    Function Subtract(x As Integer, y As Integer) As Integer
        Dim result = x - y
        If result < 0 Then
            Logger.Warn("{0} - {1} is negative ({2})", x, y, result)
            Return 0
        Else
            Logger.Info("{0} - {1} = {2}", x, y, result)
            Return result
        End If
    End Function
End Class

はい、そうですね。べっとりNLogに依存しちゃってます。 仮に他のロギングライブラリに移行することになった場合、ロギングコードを修正する必要が出てきますし、細かくログを取得しようとしていた場合には修正箇所は相当な数になるはずです。

インタフェース化とIoCコンテナ

はいはいインターフェースインターフェース。 メソッドをインターフェースに切り出すことができればあとはIoCコンテナとかを使って外部からロガーを注入してみんなハッピーになれます。

と、ここで壁にぶち当たりました。

どのようなメソッドとしてインタフェースを切り出しましょう

NLogやSerilog、log4netではログの書き出しメソッドはログレベルとして実装されています。 まずはログレベルで検討してみましょう。

NLog Serilog log4net 簡単な説明
Trace Verbose 該当なし めっちゃ細かい
Debug Debug Debug デバッグ情報
Info Information Info 通常のイベント情報
Warn Warning Warn クリティカルではない警告
Error Error Error エラー
Fatal Fatal Fatal ちょー致命的

という感じで多少であるものの、各ロギングライブラリで使用できるログレベルには差異があります。

また、NLogとlog4netはメッセージを出力するタイプのログライブラリですが、Serilogは構造化ログライブラリなのでインターフェースでメソッドのシグネチャを統一しても幸せになれそうではありません。

ではどのようなインタフェースを用意すればいいのかと言いますと、ログイベントを意味論としてメソッドを用意してあげれば良いのではとの結論に至りました。

先ほどの例ですと、以下のような感じになります。

Interface IMyLogger
    Sub CalcAdd(x As Integer, y As Integer, result As Integer)
    Sub CalcSubtract(x As Integer, y As Integer, result As Integer)
    Sub SubtractResultIsNegative(x As Integer, y As Integer, result As Integer)
End Interface

この方法ですとプロジェクトごとにインターフェースが異なりますが、そもそもログイベントもプロジェクトごとに異なるんだからそもそもプロジェクトにまたがって共通化する必要はありませんよね。

また、イベントの種類だけメソッドが増大するという問題もありますが、そちらは、まぁ、その、いい感じにお願いします。

そんな感じで、Simple Injectorを使いつつ書き直したのが以下になります。

Imports NLog
Imports SimpleInjector

Module Module1

    Sub Main()
        Dim c = New Container()
        Dim logger = New MyLogger(LogManager.GetCurrentClassLogger())
        c.RegisterSingleton(Of IMyLogger)(logger)
        c.Register(Of SomeModel)()
        c.Verify()

        Dim model = c.GetInstance(Of SomeModel)()
        Console.WriteLine($"{model.Add(1, 2)}")
        Console.WriteLine($"{model.Subtract(2, 1)}")
        Console.WriteLine($"{model.Subtract(1, 2)}")
    End Sub

End Module

Class SomeModel
    Private ReadOnly _logger As IMyLogger

    Sub New(logger As IMyLogger)
        _logger = logger
    End Sub

    Function Add(x As Integer, y As Integer) As Integer
        Dim result = x + y
        _logger.CalcAdd(x, y, result)
        Return result
    End Function

    Function Subtract(x As Integer, y As Integer) As Integer
        Dim result = x - y
        If result < 0 Then
            _logger.SubtractResultIsNegative(x, y, result)
            Return 0
        Else
            _logger.CalcSubtract(x, y, result)
            Return result
        End If
    End Function
End Class

Interface IMyLogger
    Sub CalcAdd(x As Integer, y As Integer, result As Integer)
    Sub CalcSubtract(x As Integer, y As Integer, result As Integer)
    Sub SubtractResultIsNegative(x As Integer, y As Integer, result As Integer)
End Interface

Class MyLogger
    Implements IMyLogger

    Private ReadOnly _nlog As ILogger

    Public Sub New(logger As ILogger)
        _nlog = logger
    End Sub

    Public Sub CalcAdd(x As Integer, y As Integer, result As Integer) Implements IMyLogger.CalcAdd
        _nlog.Info("{0} + {1} = {2}", x, y, result)
    End Sub

    Public Sub CalcSubtract(x As Integer, y As Integer, result As Integer) Implements IMyLogger.CalcSubtract
        _nlog.Info("{0} - {1} = {2}", x, y, result)
    End Sub

    Public Sub SubtractResultIsNegative(x As Integer, y As Integer, result As Integer) Implements IMyLogger.SubtractResultIsNegative
        _nlog.Warn("{0} - {1} is negative ({2})", x, y, result)
    End Sub
End Class

この辺のアイデアは弊社が独自で思いついたというよりはSLABの概念とかLightNodeのコードをパクった参考にしたところがあるのでオリジナルへのリンクを付け加えておきます。

余談（ってほど余談でもない）

NLogの${callsite}とかのスタックフレームのスキップ

<target xsi:type="ColoredConsole" name="console" 
        layout="${longdate} ${uppercase:${level}} ${message}${newline}${stacktrace}${newline}${callsite}" />

みたいなレイアウトを設定している場合、出力結果は

2017-05-06 01:26:54.5080 INFO 1 + 2 = 3
Module1.Main => SomeModel.Add => MyLogger.CalcAdd
ConsoleApp2.MyLogger.CalcAdd
3
2017-05-06 01:26:54.5281 INFO 2 - 1 = 1
Module1.Main => SomeModel.Subtract => MyLogger.CalcSubtract
ConsoleApp2.MyLogger.CalcSubtract
1
2017-05-06 01:26:54.5281 WARN 1 - 2 is negative (-1)
Module1.Main => SomeModel.Subtract => MyLogger.SubtractResultIsNegative
ConsoleApp2.MyLogger.SubtractResultIsNegative
0

みたいになって、ログの実装クラスがしゃしゃり出てきてもんにょりします。

そんな時はskipFrames=Integerを設定してあげるといい感じになります。

<target xsi:type="ColoredConsole" name="console" 
        layout="${longdate} ${uppercase:${level}} ${message}${newline}${stacktrace:skipFrames=1}${newline}${callsite:skipFrames=1}" />

2017-05-06 01:30:57.3469 INFO 1 + 2 = 3
Module1.Main => SomeModel.Add
ConsoleApp2.SomeModel.Add
3
2017-05-06 01:30:57.3700 INFO 2 - 1 = 1
Module1.Main => SomeModel.Subtract
ConsoleApp2.SomeModel.Subtract
1
2017-05-06 01:30:57.3700 WARN 1 - 2 is negative (-1)
Module1.Main => SomeModel.Subtract
ConsoleApp2.SomeModel.Subtract
0

IoCコンテナとサービスロケーター

やはりあなた方のDependency Injectionはまちがっている。 — A Day in Serenity (Reloaded) — PHP, FuelPHP, Linux or something

IoCコンテナを使い始めると

コンテナをコンストラクタ引数で渡して、コンテナから必要なオブジェクトを取り出せばいいんだ

みたいに勘違いしやすいと思います。というよりは弊社は勘違いしていました。

今回ので例を示すとこんな感じですね。

Class SomeModel
    Private ReadOnly _logger As IMyLogger

    Sub New(container As Container)
        _logger = container.GetInstance(Of IMyLogger)()
    End Sub

    Function Add(x As Integer, y As Integer) As Integer
        '...
    End Function

    Function Subtract(x As Integer, y As Integer) As Integer
        '...
    End Function

End Class

これには以下のデメリットが発生します。

  • 本来IMyLoggerだけに依存したいはずなのに、IoCコンテナ（Container）にも依存してしまっている
    • 本来なら必要のない別のクラスに依存することになり、依存を減らしたいはずなのに逆に増えてしまっている
  • そのクラスが依存しているインターフェース・クラスがコンストラクタのシグネチャから判別がつかない
    • コンテナが保持するインターフェース・クラスをすべて利用することが出来てしまうため、不用意に不要なクラスへアクセス出来てしまうため、なんかやばい

なんで、まぁサービスロケーターとして使うのはやめましょうねって感じで。

おわりに

弊社は最近では自動化ツールを作ったりコンソールアプリケーションを作成する機会が多いです。

そんな中、どのみち必要になるから最初からNuGetでぶち込んでおけと思うのが以下の3つです。

今回のでロギングライブラリのもんにょりが消えたので、残るはコマンドラインオプションパーサーになるのですが、今のところしっくりくるのがありません。

なければ作るしかないっぽいのでアレですが、当面はいい感じのを探していこうと思っています。

おわり

*1:弊社はNLogとSerilogしか使ったことがないのでlog4netは微妙です