ETW/EventSource によるロギングを試してみる

最近、以下の記事を拝見しました。

neue cc - EtwStream - ETW/EventSourceのRx化 + ビューアーとしてのLINQPad統合

正直、EtwやEventSourceというものに馴染みが無かったのですが、これからは必須の技術となりそうですね。

さて、EventSourceですが、いきなり構造化ログってのもかなりダルいので、まずは非構造化ログをEventSourceで実現するところから初めてみましょう。

という事で、前回の記事で書いた、ScheduledNotifierをベースとした自作のLogger、LogMessageNotifierをEventSourceに置き換えることから初めてみたいと思います。

LogMessageNotifierをEventSourceに変更する

今回は、Logging用のEventSourceに冒頭の記事の中で掲載されていたLoggerEventSource クラスのコードをそのまま利用させて頂く事とします。

LoggerEventSourceクラスのメソッドをそのまま呼び出しても良いのですが、既存のコードでは、Model側はILoggerインターフェースを通じてLogの書き込みを行っていました。
ひとまずはこの部分は変えずに、LoggerEventSource をILoggger でラップすることで対応します。

using ReactiveBingViewer.Diagnostics;
using System;

namespace ReactiveBingViewer.Notifiers
{
    /// <summary>
    /// Logメッセージ通知オブジェクト
    /// </summary>
    public class EventSourceLogger : ILogger
    {

        public LoggerEventSource EventSource { get; private set; }
        public EventSourceLogger(LoggerEventSource eventSource =null)
        {
            EventSource = eventSource?? LoggerEventSource.Log;
        }

        public void Trace(string message) => EventSource.Verbose(message);
        public void Debug(string message) => EventSource.Debug(message);
        public void Info(string message) => EventSource.Informational(message);
        public void Warn(string message) => EventSource.Warning(message);
        public void Error(string message) => EventSource.Error(message);
        public void Fatal(string message) => EventSource.Critical(message);
        public void Trace(string message, Exception e)
        {
            Trace(message);
            LogException(e);
        }
        public void Debug(string message, Exception e)
        {
            Debug(message);
            LogException(e);
        }
        public void Info(string message, Exception e)
        {
            Info(message);
            LogException(e);
        }
        public void Warn(string message, Exception e)
        {
            Warn(message);
            LogException(e);
        }
        public void Error(string message, Exception e)
        {
            Error(message);
            LogException(e);
        }
        public void Fatal(string message, Exception e)
        {
            Fatal(message);
            LogException(e);
        }


        private void LogException(Exception e)
        {
            EventSource.Exception(e.GetType().FullName, e.StackTrace.ToString(), e.Message);
        }
    }
}

ILoggerをそのまま温存したので Model内でのlogの書き込み部分は変更する必要がありません。

後は、ViewModel のコンストラクタで行っている ReactiveProperty を初期化している部分をEventSourceの型に合わせてほんの少し修正するだけで済みそうです。

public class MainWindowViewModel
{
    //private LogMessageNotifier logger = new LogMessageNotifier();
    private EventSourceLogger logger = new EventSourceLogger();

    public MainWindowViewModel()
    {
        //Modelのコンストラクタに logger を渡す
        webImageStore = new WebImageStore(App.BingApiAccountKey,
            App.VisionApiSubscriptionKey, logger).AddTo(disposables);        
        
        var logListner = EtwStream.ObservableEventListener.FromEventSource(logger.EventSource);

        ////Logファイルに書き出し
        System.Diagnostics.Trace.Listeners.Add(new System.Diagnostics.TextWriterTraceListener("log.txt"));
        //logger.Subscribe(log =>
        logListner.Subscribe(log =>
        {
            System.Diagnostics.Trace.WriteLine(log);
            System.Diagnostics.Trace.Flush();
        }).AddTo(disposables);

        ////Infoレベルのログはステータスバーに表示
        //StatusMessage = logger.Where(x => x.Level == LogLevel.Info)
        //    .Select(x => x.Message)
        //    .ToReadOnlyReactiveProperty();
        StatusMessage = logListner.Where(x => x.Level == System.Diagnostics.Tracing.EventLevel.Informational)
            .Select(x => x.Payload.First().ToString())
            .ToReadOnlyReactiveProperty();

        ////Warn レベル以上 は エラーリストに表示
        ClearErrorLogsCommand = new ReactiveCommand();  //リストクリア用
        //ErrorLogs = logger
        //    .Where(x => x.Level >= LogLevel.Warn)
        //    .ToReadOnlyReactiveCollection(ClearErrorLogsCommand.ToUnit());
        ErrorLogs = logListner.Where(x => (int)x.Level <= (int)System.Diagnostics.Tracing.EventLevel.Warning)
            .Select(x=>$"[{x.Level}]{x.Payload[0]} ({x.Payload[2]})")
            .ToReadOnlyReactiveCollection(ClearErrorLogsCommand.ToUnit());

        ////エラーリスト表示切替。 ErrorLogs にアイテムがある場合のみ表示する
        ErrorLogsVisibility = ErrorLogs
            .CollectionChangedAsObservable()
            .Select(_ => (ErrorLogs.Count > 0) ? Visibility.Visible : Visibility.Collapsed)
            .ToReactiveProperty(Visibility.Collapsed);
    }
}

これで実行してみます。

f:id:pierre3:20151105054819p:plain

おお、ちゃんと動きました。

EtwStream で(超簡易版)Etwビューアを作ってみる

後は、EventSourceとしたことでEtwStream を使えばプロセス外からも参照できるはず。早速LINQPadで...
と思ったのですが無償版ではEtwStream.LingPad をNuGetできないのですね。

幸い、ベースライブラリである EtwStream.Core は通常の.Netプロジェクトに入れられるようですので、これを利用して簡易ビューアを作ってみたいと思います。

WPFアプリケーションで作ります。
NuGetでEtwStream とReactiveProperty をインストールします。

PM> Install-Package EtwStream

PM> Install-Package ReactiveProperty

ViewModel を定義します。

ObservableEventListener.FromTraceEvent() で取得したIObservable<TraceEvent> をReactiveCollection に変換します。

using EtwStream;
using Reactive.Bindings;
using System.Linq;
using System.Reactive.Linq;

namespace EtwStreamViewer 
{
    public class MainWindowViewModel
    {
        public ReadOnlyReactiveCollection<string> LogEvents { private set; get; }
        public MainWindowViewModel()
        {
            LogEvents = ObservableEventListener.FromTraceEvent("LoggerEventSource")
                .Select(x =>$"[{x.TimeStamp}][{x.Level}]: {x.FormattedMessage}" )
                .ToReadOnlyReactiveCollection();
        }
    }
}

XAML を定義します。

WindowにListBoxを追加して、ReactiveCollection をバインドします。

<Window x:Class="EtwStreamViewer.MainWindow"
        xmlns="http://schemas.microsoft.com/winfx/2006/xaml/presentation"
        xmlns:x="http://schemas.microsoft.com/winfx/2006/xaml"
        xmlns:d="http://schemas.microsoft.com/expression/blend/2008"
        xmlns:mc="http://schemas.openxmlformats.org/markup-compatibility/2006"
        xmlns:local="clr-namespace:EtwStreamViewer"
        mc:Ignorable="d"
        Title="MainWindow" Height="350" Width="525">

    <Grid>
        <ListBox ItemsSource="{Binding LogEvents}"></ListBox>
    </Grid>
</Window>