NLog LayoutRendererを自作する
はじめに
NLog の使い方は一般的に
logger.info("メッセージ")
になりますが、「メッセージ(文字列)」しか指定できません。 通常はこれで問題はないのですがそれ以外の情報も出力したいことがあります。
通常のコード
例えば、SQLのロギングを考えてみます。以下のような情報も出したいですね。
開始時なら
- SQL文
終了時なら
- 実行時間
では、この場合のロギングコードを書いてみます。
logger.info("開始 | {0}", sql) Dim sw As New Stopwatch sw.Start() 'SQLの実行 sw.Stop() logger.info("終了 | {0:n0}msec", sw.ElapsedMilliseconds)
一見何も問題はないですが、ステータスの情報とそれ以外の情報をくっつけて渡してしまっています。 今後処理時間が遅いSQL文だけを調べようと思ってもメッセージから処理時間を切り出し(文字列分解)しないといけないので、分析には不向きです。 また区切り文字を「|」にしてしますが、本来区切り文字はconfigのlayoutで制御すべきです。これも分析には不向きになってしまいます。
LayoutRendererを自作する
上記の問題はLayoutRendererを自作することで解決します。 LayoutRendererっていうのは端的に言えば「${logger}」、や「${message}」のことです。
今回は「${status}」というLayoutRendererを作って開始、終了の情報をメッセージから切り出してみます。
StatusLayoutRenderer.vb
Imports System.Runtime.CompilerServices Imports System.Text Imports NLog Imports NLog.LayoutRenderers <LayoutRenderer("status")> Public Class StatusLayoutRenderer Inherits LayoutRenderer Protected Overrides Sub Append(builder As StringBuilder, logEvent As LogEventInfo) If logEvent.Exception IsNot Nothing Then builder.Append("excep") Return End If Dim name As String = "status" If logEvent.Properties.ContainsKey(name) = False Then Return builder.Append(logEvent.Properties(name)) End Sub Public Enum Statuses Start [End] Exception End Enum End Class Public Module LogEventInfoExtension <Extension> Public Sub SetStatus(source As LogEventInfo, value As StatusLayoutRenderer.Statuses) source.Properties("status") = value End Sub End Module
Module1.vb
Imports NLog Module Module1 Private logger As NLog.Logger = NLog.LogManager.GetCurrentClassLogger Sub Main() Action1() Action2() End Sub Private Sub Action1() Dim evt As New LogEventInfo evt.Properties("status") = StatusLayoutRenderer.Statuses.Start logger.Info("開始しました", evt) 'TODO:なにかの処理 evt.Properties("status") = StatusLayoutRenderer.Statuses.End logger.Info("終了しました", evt) End Sub Private Sub Action2() Dim evt As New LogEventInfo evt.SetStatus(StatusLayoutRenderer.Statuses.Start) logger.Info("開始しました", evt) 'TODO:なにかの処理 evt.SetStatus(StatusLayoutRenderer.Statuses.End) logger.Info("終了しました", evt) End Sub End Module
NLog.config
<?xml version="1.0" encoding="utf-8" ?> <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd" autoReload="true" throwExceptions="false" internalLogLevel="Off" internalLogFile="logs/nlog-internal.log" > <extensions> <!--TODO:自作クラスがあるアセンブリ名を記述してください--> <add assembly="NlogCustomLayoutRenderer"/> </extensions> <targets> <target name="debugger" xsi:type="Debugger" header="${splitter}${newline}${processname} ver.${assembly-version}" layout="${date:format=HH\:mm\:ss.fff} | ${pad:padding=-5:inner=${level:uppercase=true}} | ${logger:shortName=true:padding=30} | ${pad:padding=-9:inner=${status:uppercase=true}} | ${replace-newlines:${message}}${onexception:inner=${newline}${exception}" /> </targets> <rules> <logger name="*" minlevel="Trace" writeTo="debugger" enabled="true" /> </rules> </nlog>
実行結果
22:24:22.560 | INFO | Module1 | START | 開始しました 22:24:22.673 | INFO | Module1 | END | 終了しました 22:24:22.680 | INFO | Module1 | START | 開始しました 22:24:22.680 | INFO | Module1 | END | 終了しました
ミソ
logger.info("メッセージ")
と書くところを
Dim evt As New LogEventInfo evt.Properties("属性名") = 属性値 logger.Info("メッセージ", evt)
って書くところがミソ。 そうすることでLayoutRendererに情報が渡せるので、あとはその情報を取り出しアウトプットするクラスを作ってやるだけ。
注意点はカスタム処理を入れていることをNLogに通知させるために、NLogのConfigに以下のコードを書くのを忘れない。
<extensions> <!--TODO:自作クラスがあるアセンブリ名を記述してください--> <add assembly="NlogCustomLayoutRenderer"/> </extensions>
ちなみにアセンブリの名称を「NLog.*」にすると上記のConfigを書かなくてもよかったはず。