[アーティクル]
05/02/2016

April 2016

Volume 31 Number 4

Essential .NET - .NET Core によるログ記録

Mark Michaelis 2 月号のコラムでは、「.NET Core 1.0」と新たに名付けられたプラットフォームに含まれる新しい構成 API を取り上げました (bit.ly/1OoqmkJ)。「.NET Core 1.0」は、以前「.NET Core 5」という名前で、ASP.NET 5 プラットフォームの一部でしたが最近改名されました (bit.ly/1Ooq7WI、英語)。前回は、Microsoft.Extensions.Configuration API を調べるために単体テストを使用しました。今回は、同じアプローチを使って Microsoft.Extensions.Logging について調べます。今回大きく異なるのは、ASP.NET Core プロジェクトからではなく、.NET 4.6 CSPROJ ファイルからテストする点です。こうすれば、ASP.NET Core プロジェクトにまだ移行していない場合でも、思いついたらすぐに .NET Core を利用できるようになります。

ログ記録を取り上げるのはなぜでしょう。新たなログ記録フレームワークが必要なのはどうしてでしょう。ログ記録フレームワークは、NLog、Log4Net、Loggr、Serilog、組み込みの Microsoft.Diagnostics.Trace/Debug/TraceSource など、名前を挙げるだけでも既にいくつか存在します。実は、このようにログ記録フレームワークが多数存在することが、Microsoft.Extensions.Logging が公開されるきっかけの 1 つになっています。多数の選択肢を用意されても、開発者は、後で別の選択肢に変えるかもしれないと考えながらどれか 1 つを選ぶことになります。そこで、開発者は、独自のログ記録 API ラッパーを作成し、自身や会社がどのようなログ記録フレームワークを選んだとしても、それを起動できるようにすることを考えます。同様に、アプリケーションで使用しているライブラリの 1 つが別のフレームワークのライブラリを使用していることがわかっただけで、特定のログ記録フレームワークを使用することになり、フレームワーク間で相互にメッセージを交換するリスナーを作成することもあります。

マイクロソフトが Microsoft.Extensions.Logging によって提供するのがこのようなラッパーです。これを利用すれば、独自のラッパーを作成する必要はまったくなくなります。このラッパーが提供する 1 セットの API が、選択したプロバイダーに転送されます。マイクロソフトは、コンソール (Microsoft.Extensions.Logging.Console)、デバッグ (Microsoft.Extensions.Logging.Debug)、イベントログ (Microsoft.Extensions.Logging.EventLog)、TraceSource (Microsoft.Estensions.Logging.TraceSource) などをターゲットとするプロバイダーを用意する一方で、ログ記録フレームワークのさまざまなチーム (NLog、Serilog、Loggr、Log4Net などのサードパーティ) とも連携して、そのようなフレームワークに Microsoft.Extensions.Logging 互換のプロバイダーも提供しています。

作業の開始

ログ記録のアクティビティは、ログファクトリをルートとして、そこから始まります (図 1 参照)。

図 1 Microsoft.Extensions.Logging の使用方法

public static void Main(string[] args = null)
{
  ILoggerFactory loggerFactory = new LoggerFactory()
    .AddConsole()
    .AddDebug();
  ILogger logger = loggerFactory.CreateLogger<Program>();
  logger.LogInformation(
    "This is a test of the emergency broadcast system.");
}

コードが示すように、まず、Microsoft.Extensions.Logging.LoggerFactory のインスタンスを作成します。これは同じ名前空間に ILoggerFactory を実装します。次に、ILoggerFactory の拡張メソッドを使用して、利用するプロバイダーを指定します。図 1 では、具体的に、Microsoft.Extensions.Logging.ConsoleLoggerExtensions.AddConsole と Microsoft.Extensions.Logging.DebugLoggerFactoryExtensions.AddDebug を使用しています (どちらのクラスも Microsoft.Extensions.Logging 名前空間に含まれますが、実際にはそれぞれ Microsoft.Extensions.Logging.Console パッケージと Microsoft.Extensions.Logging.Debug NuGet パッケージで見つかります)。

これらの拡張メソッドは、プロバイダーを追加する一般的な方法 (ILoggerFactory.AddProvider (ILoggerProvider プロバイダー)) の便利なショートカットにすぎません。AddProvider メソッドにはログプロバイダーのインスタンスが必要です。これはメソッドのコンストラクターが通常ログレベルのフィルター式を必要とするためです。これに対して拡張メソッドはこのようなフィルター式の既定の式を提供します。たとえば、ConsoleLoggerProvider のコンストラクターのシグネチャは、次のようになります。

public ConsoleLoggerProvider(Func<string, LogLevel, bool> filter,
  bool includeScopes);

この最初のパラメーターが述語式で、ログ記録されたテキストとログレベルの値に基づいてメッセージをそのプロバイダーに出力するかどうかを定義できるようにします。

たとえば、ConsoleLoggerProvider インスタンスを具体的に指定して AddProvider を呼び出して、以下のように LogLevel.Information よりも高い (重要な) すべてのメッセージを出力するようにフィルターを構成できます。

loggerFactory.AddProvider(
  new ConsoleLoggerProvider(
    (text, logLevel) => logLevel >= LogLevel.Verbose , true));

興味深いことに、ILoggerFactory を返す拡張メソッドとは異なり、AddProvider は何も返さないため、図 1 に示す流れるような構文にはなりません。

ログレベル値の重要度の高低については、残念ながら、ログプロバイダーごとに多少のばらつきがあることを頭に入れておくことが重要です。ログレベル 6 は、致命的なエラーが発生したことを示す場合も、単なる詳細診断メッセージの場合もあります。Microsoft.Extensions.Logging.LogLevel は、以下の LogLevel 列挙型宣言を使用します。この場合、値が大きいほど高い優先度を示します。

public enum LogLevel
{
  Debug = 1,
  Verbose = 2,
  Information = 3,
  Warning = 4,
  Error = 5,
  Critical = 6,
  None = int.MaxValue
}

したがって、ConsoleLoggerProvider のインスタンスを作成するときに logLevel が LogLevel.Verbose 以上のときのみメッセージを書き込むように指定して、デバッグレベルのメッセージだけは書き込まないようにすることができます。

ログファクトリには、同じ種類のプロバイダーも含めて、複数のプロバイダーを追加できます。したがって、図 1 のコードに ILoggerFactory.AddProvider への呼び出しを追加すると、ILogger.LogInformation への呼び出しによって、メッセージがコンソールに 2 回表示されます。最初のコンソールプロバイダー (AddConsole で追加したプロバイダー) は既定のプロバイダーとして、LogLevel.Information 以上のすべてのメッセージを表示します。ですが、2 つ目のプロバイダー (AddProvider メソッドで追加したプロバイダー) だけは、フィルターによる除外が適切に回避されるため、ILogger.LogVerbose の呼び出しは一度しか行われません。

ログ記録のパターン

図 1 に示すように、すべてのログ記録はログファクトリをルートとして始まります。このログファクトリから ILoggerFactory.CreateLogger<T> メソッドを使って ILogger を要求できます。このメソッドのジェネリック型 T は、コードが実行されるクラスを特定するため、ロガーがメッセージを書き込んでいるクラスの名前を書き出すことができます。つまり、loggerFactory.CreateLogger<Program> を呼び出すことで、実質的には Program クラス固有のロガーを起動して、メッセージを書き込むたびに、Program クラス内に実行されているものとして、実行コンテキストを書き込むこともできます。したがって、図 1 のコンソールの出力は次のようになります。

info: SampleWebConsoleApp.Program[0]
      This is a test of the emergency broadcast system.

この出力は、以下のことに基づいています。

「info」は、LogInformation メソッドの呼び出しであることを示します。
「SampleWebConsoleApp.Program」は T によって決まります。
「[0]」はイベント ID です。今回は指定していないので、既定値の 0 になります。
「This is a test of the emergency broadcast system」は、LogInformation に引数として渡したメッセージです。

値 Program はクラスレベルのコンテキストを示すため、おそらく、ログを記録するクラスごとに異なるロガーインスタンスを作成することになります。たとえば、Program から Controller クラスのインスタンスを作成して呼び出す場合、Controller クラス内に新しいロガーインスタンスを用意します。このロガーインスタンスは、T に Controller を指定して別のメソッド呼び出しで作成することになります。

loggerFactory.CreateLogger<Controller>()

この場合、以前にプロバイダーを構成したときと同じロガーファクトリのインスタンスにアクセスする必要があります。ログ記録を実行するすべてのクラスにロガーファクトリのインスタンスを渡してもかまいませんが、すぐに面倒な状態になり、リファクタリングが必要になります。

解決策は、1 つの静的 ILoggerFactory を静的プロパティとして保存し、オブジェクト固有の ILoggger インスタンスを作成するときに、すべてのクラスから利用できるようにすることです。たとえば、以下のように静的 ILoggerFactory インスタンスを含む静的クラス ApplicationLogging を追加します。

public static class ApplicationLogging
{
  public static ILoggerFactory LoggerFactory {get;} = new LoggerFactory();
  public static ILogger CreateLogger<T>() =>
    LoggerFactory.CreateLogger<T>();
}

明らかな問題は、LoggerFactory がスレッドセーフかどうかです。さいわい、AddProvider は 図 2 に示すようにスレッドセーフです。

図 2 Microsoft.Extensions.Logging.LoggerFactory AddProvider の実装

public void AddProvider(ILoggerProvider provider)
{
  lock (_sync)
  {
    _providers = _providers.Concat(new[] { provider }).ToArray();
    foreach (var logger in _loggers)
    {
      logger.Value.AddProvider(provider);
    }
  }
}

ILogger インスタンス内唯一のデータはジェネリック型 T によって決まるため、各クラスのオブジェクトが使用できる静的 ILogger が各クラスにあれば問題ありません。しかし、それにはすべての静的メンバーに対してスレッドセーフ性を確保するというプログラミング標準が前提になります。そうすると、ILogger の実装内に (既定では存在しない) 同時実行制御が必要になり、ロックの取得や解放を行うため、結果的には重大なボトルネックになる可能性があります。このような理由で、実際には、クラスのインスタンスごとに個別の ILogger インスタンスを用意するのがお勧めです。その結果、ログ記録をサポートするクラスに、ILogger プロパティをそれぞれ用意することになります (図 3 参照)。

図 3 ログ記録が必要な各オブジェクトに ILogger インスタンスを追加

public class Controller
{
  ILogger Logger { get; } =
    ApplicationLogging.CreateLogger<Controller>();
  // ...
  public void Initialize()
  {
    using (Logger.BeginScopeImpl(
      $"=>{ nameof(Initialize) }"))
    {
      Logger.LogInformation("Initialize the data");
      //...
      Logger.LogInformation("Initialize the UI");
      //...
    }
  }
}

スコープについて

多くのプロバイダーは、「スコープ」という概念をサポートします。開発者は、このスコープを利用して、(たとえば) コードが呼び出しチェーン全体をどのように処理したかをログに記録することができます。先ほどの例に戻ると、Program が Controller クラスのメソッドを呼び出すと、次にそのクラスが型 T の独自のコンテキストを指定してクラス独自のロガーインスタンスを作成します。ただし、単純に info: SampleWebConsoleApp.Program[0] と info: SampleWebConsoleApp.Controller[0] のメッセージコンテキストを続けて表示するのではなく、Program が呼び出した Controller をログに記録して、さらに可能であればメソッドの名前自体を含めたいと考えたとします。これを実現するには、プロバイダー内でスコープの概念をアクティブにします。図 3 は、Initialize メソッドの内部で Logger.BeginScopeImpl の呼び出しを使用する例を示しています。

スコープをアクティブにした状態でログ記録パターンを使用する場合は 図 4 のような Program クラスになります。

図 4 更新した Program の実装

public class Program
{
  static ILogger Logger { get; } =
    ApplicationLogging.CreateLogger<Program>();
  public static void Main(string[] args = null)
  {
    ApplicationLogging.LoggerFactory.AddConsole(true);
    Logger.LogInformation(
      "This is a test of the emergency broadcast system.");
    using (Logger.BeginScopeImpl(nameof(Main)))
    {
      Logger.LogInformation("Begin using controller");
      Controller controller = new Controller();
      controller.Initialize();
      Logger.LogInformation("End using controller");
    }
    Logger.Log(LogLevel.Information, 0, "Shutting Down...", null, null);
  }
}

図 3 と図4 の出力を組み合わせると 図 5 のようになります。

図 5 スコープを含めたコンソールログ出力

info: SampleWebConsoleApp.Program[0]
      This is a test of the emergency broadcast system.
info: SampleWebConsoleApp.Program[0]
      => Main
      Begin using controller
info: SampleWebConsoleApp.Controller[0]
      => Main => Initialize
      Initialize the data
info: SampleWebConsoleApp.Controller[0]
      => Main => Initialize
      Initialize the UI
info: SampleWebConsoleApp.Program[0]
      => Main
      End using controller
info: SampleWebConsoleApp.Program[0]
      Shutting down...

スコープが自動的にアンワインドする方法には、Initialize や Main がまったく含まれていないのがわかります。この機能は、BeginScopeImpl が IDisposable インスタンスを返すことによって実現されます。IDisposable インスタンスは、using ステートメントが Dispose を呼び出すときに、スコープを自動的にアンワインドします。

サードパーティ製のプロバイダーの利用

著名なサードパーティ製ログ記録フレームワークをいくつか使用できるようにするため、マイクロソフトはその開発者と連携し、フレームワークごとにプロバイダーを用意しています。ここでは NLog フレームワークを接続する方法を示します (図 6 参照)。このフレームワークを選んだことに特別な意味はありません。

図 6 NLog を Microsoft.Extensions.Logging プロバイダーとして構成

[TestClass]
public class NLogLoggingTests
{
  ILogger Logger {get;}
    = ApplicationLogging.CreateLogger<NLogLoggingTests>();
  [TestMethod]
  public void LogInformation_UsingMemoryTarget_LogMessageAppears()
  {
    // Add NLog provider
    ApplicationLogging.LoggerFactory.AddNLog(
      new global::NLog.LogFactory(
        global::NLog.LogManager.Configuration));
    // Configure target
    MemoryTarget target = new MemoryTarget();
    target.Layout = "${message}";
    global::NLog.Config.SimpleConfigurator.ConfigureForTargetLogging(
      target, global::NLog.LogLevel.Info);
    Logger.LogInformation(Message);
     Assert.AreEqual<string>(
      Message, target.Logs.FirstOrDefault<string>());
  }
}

NLoｇを使い慣れていれば、上記の大半はよく知っているコードです。最初に、NLog.Targets.MemoryTarget 型の NLog ターゲットのインスタンスを作成して構成します (NLog ターゲットの数は多く、NLog 構成ファイル内でターゲットを特定して構成し、さらに図 6 で示すように構成コードを使用します)。見た目は似ていますが、Layout は文字列の補間値ではなく、${message} というリテラル値が代入されます。

コードを LoggerFactory に追加して構成したら、コードは他の任意のプロバイダーコードと同じになります。

例外処理

当然、ログに記録する最も多い理由の 1 つは、例外がスローされるときに記録をとることです。具体的には、例外が再スローされるのではなく処理されるときや、例外がまったく処理されないときに記録をとります (bit.ly/1LYGBVS 参照)。Microsoft.Extensions.Logging には例外を処理する特定のメソッドがあります。そのようなメソッドのほとんどは、Microsoft.Extensions.Logging.LoggerExtensions に、ILogger の拡張メソッドとして実装されています。また、特定のログレベル (ILogger.LogInformation、ILogger.LogDebug、ILogger.LogCritical など) に固有のメソッドもこのクラスから実装されます。たとえば、(アプリケーションを適切にシャットダウンする前に) 例外に関する LogLevel.Critical メッセージをログ記録する場合は、以下を呼び出します。

Logger.LogCritical(message,
  new InvalidOperationException("Yikes..."));

ログ記録と例外処理のもう 1 つの重要な側面があります。それは、特に例外を処理するときのログ記録では例外をスローしてはいけないという点です。ログ記録中に例外をスローすると、おそらくメッセージも例外も書き込まれず、その重要度に関わらず、まったく気付かれない可能性があります。残念ながら、ILogger 実装そのもの (Microsoft.Extensions.Logging.Logger) にはそのような例外処理がないため、例外が発生する場合は、呼び出し側のノードで例外を処理する必要があることになります。この処理は、Logger.LogX が呼び出されるたびに行います。これを解決する一般的なアプローチは、例外をキャッチできるように Logger をラップすることです。ただし、独自のバージョンの ILogger や ILoggerFactory を実装することもできます (例については bit.ly/1LYHq0Q (英語) を参照)。.NET Core がオープンソースであることを考えれば、クラスを複製したり、専用の LoggerFactory の実装や ILogger の実装に例外処理を意図的に実装することもできます。

まとめ

冒頭で、「新たなログ記録フレームワークが必要になるのはなぜでしょう」という疑問を投げかけました。ここまでお読みいただければ、その理由が明らかになったと思います。新しいフレームワークは抽象化レイヤー (ラッパー) を作成します。このラッパーにより、任意のログ記録フレームワークをプロバイダーとして使用できるようになります。これによって、開発者としての作業に最大限の柔軟性が提供されます。また、これは .NET Core でしか利用できませんが、標準の Visual Studio の .NET 4.6 プロジェクト用に Microsoft.Extensions.Logging のような .NET Core NuGet パッケージを参照しても問題ありません。

Mark Michaelis は、IntelliTect の創設者で、同社でチーフテクニカルアーキテクト兼トレーナーを務めています。20 年にわたって Microsoft MVP に認定され、2007 年から Microsoft Regional Director を務めています。また、C#、Microsoft Azure、SharePoint、Visual Studio ALM など、マイクロソフトソフトウェアの設計レビューチームにもいくつか所属しています。開発者を対象としたカンファレンスで講演を行い、多数の書籍を執筆しています。最近では、『Essential C# 6.0 (5th Edition)』(Addison-Wesley Professional、2015 年) を執筆しました (itl.tc/EssentialCSharp、英語)。連絡先は、Facebook (facebook.com/Mark.Michaelis、英語)、ブログ (IntelliTect.com/Mark、英語)、Twitter (@markmichaelis、英語)、または電子メール mark@IntelliTect.com (英語のみ) です。

この記事のレビューに協力してくれた IntelliTect の技術スタッフの Kevin Bost、Chris Finlayson、および Michael Stokesbary に心より感謝いたします。