vaguely

和歌山に戻りました。ふらふらと色々なものに手を出す毎日。

ASP.NET Core でのログ出力( ILogger + NLog )

はじめに

今回はログ出力を追ってみることにします。

.NET でログを出力するライブラリはたくさんあるようですが、今回は組み込みである ILogger を使ってみます。

内容としては ILogger の使い方、特にファイルに内容を出力する方法が中心になる予定です。

httpsについて

いきなり違う話から入るのですが、 ASP.NET Core2.1 でプロジェクトを作ると https://localhost:5XXXhttps でページを開くようになります。
(Visual Studio でプロジェクトを作る場合、プロジェクト生成時にチェックを外すと http で開くよう設定を変更できます)

それは良いのですが、 Firefox では証明書が不正となりページが開けません。

ググってみたところ、 https://localhost:(ポート番号) を例外として設定する以外に開く方法はなさそうです。

localhost なんだし多めに見て、という気持ちはありますが、まぁ仕方ありませんね。

実際のリリース時には正しい証明書などを用意することとして、開発中は例外設定してしまいたいと思います。

ログ出力してみる

気を取り直して、とりあえずログを出力してみます。

例えば HomeController.cs からログを出力したい場合、 HomeController クラスのコンストラクタに ILogger< HomeController> を渡します。

HomeController.cs

using Microsoft.AspNetCore.Mvc;
using Microsoft.Extensions.Logging;

namespace WebApplication1.Controllers {
    public class HomeController : Controller {
        private readonly ILogger< HomeController> logger;

        // DI でインスタンスをセット.
        public HomeController(ILogger< HomeController> logger) {
            this.logger = logger;
        }
        public string Index() {
            // INFO レベルでログを出力.
            logger.Log(LogLevel.Information, "Hello work!");

            return "hello";
        }
        ~省略~
    }
}
  • ILogger< TCategoryName> の型は、ログの「カテゴリ」を指定するためのもので、
    文字列で指定することもできるが、ログを書き込むクラスを指定する必要があるため型を渡す方が簡単にできます。
  • 「カテゴリ」が何を指すのかは正確にはわからなかったのですが、そのログがどのクラスから出力されたのかを判別するもの、
    というくらいのものであるようです(そのためクラスの完全修飾名が必要)。

Service への追加?

DI ということで、以前と同じように Startup クラスで Service に追加…

する必要はありません。

Program クラスで下記を使用している場合、デフォルトのログ出力設定が CreateDefaultBuilder の中で行われます。

Program.cs

using Microsoft.AspNetCore;
using Microsoft.AspNetCore.Hosting;

namespace WebApplication1 {
    public class Program {
        public static void Main(string[] args) {
            CreateWebHostBuilder(args).Build().Run();
        }
        public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>
            WebHost.CreateDefaultBuilder(args)
                .UseStartup< Startup>();
    }
}

WebHost.cs

// Decompiled with JetBrains decompiler
// Type: Microsoft.AspNetCore.WebHost
~省略~
public static IWebHostBuilder CreateDefaultBuilder(string[] args) {
    IWebHostBuilder hostBuilder = new WebHostBuilder()
        ~省略~
      .ConfigureLogging((Action) ((hostingContext, logging) =>
      {
        logging.AddConfiguration((IConfiguration) hostingContext.Configuration.GetSection("Logging"));
        logging.AddConsole();
        logging.AddDebug();
      }))
    ~省略~
}

ILoggerFactory

なおググっている中で、 Startup の Configure の引数として ILoggerFactory を渡しているものもありました。

Startup.cs

~省略~
public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory) {
  ~省略~  
}

で、この ILoggerFactory でも AddConsole や AddDebug を実行することはできるようでした。

両者の使い分けに悩むところですが、少なくとも Microsoft Doscs を見る限りだと前者を使う方が良さそうです。
(後者はダメとまでは書かれていませんが、特に触れられていないため)

docs.microsoft.com

NLogを試してみる

Console に出力する分には問題がないのですが、ファイル出力したい今回のような場合、 Provider を自分で作る(またはサードパーティーのものを使う)必要があるようです。

今回は NLog を使ってみることにしました。

NLog の Wiki を基に進めていきます。

github.com

インストール

NuGet で NLog.Web.AspNetCore をインストールします
(いくつか種類がありますが、 ASP.NET Core 用のものを選びます。 ver.4.6 でした)。

ファイルを追加する

1.NLog の設定ファイル( nlog.config )をプロジェクト直下に作ります。 2.nlog.config のプロパティで、 詳細設定 > 出力ディレクトリにコピー の値を「常にコピーする」に変更します。

f:id:mslGt:20180906043538j:plain

※画像は Visual Studio ですが、 Rider の場合はファイル上で右クリック > Properties > Copy to output directory から設定できます。

3.Program.cs で NLog を有効にします。

Program.cs

using System;
using System.IO;
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Logging;
using NLog.Web;

namespace WebApplication1 {
    public class Program {
        public static void Main(string[] args) {
            // nlog.configの読み込み.
            var logger = NLog.Web.NLogBuilder.ConfigureNLog("nlog.config").GetCurrentClassLogger();
            try {
                CreateWebHostBuilder(args).Build().Run();
            }
            catch (Exception ex) {
                logger.Error(ex, "Stopped program because of exception");
                throw;
            }
            finally {
                NLog.LogManager.Shutdown();
            }
        }

        public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>
            new WebHostBuilder()
                .UseKestrel()
                .UseContentRoot(Directory.GetCurrentDirectory())
                .UseIISIntegration()
                .UseStartup< Startup>()
                .ConfigureLogging((hostingContext, logging) => {
                    // NLog 以外で設定された Provider の無効化.
                    logging.ClearProviders();
                    // 最小ログレベルの設定.
                    logging.SetMinimumLevel(LogLevel.Trace);
                })
                // NLog を有効にする.
                .UseNLog();
        }
    }
}

nlog.configを読む

Wiki の「2.Create a nlog.config file.」を見てみると、結構複雑な感じがしてきます。

とはいえ個別にコメントを書いてくれているのと、 Wiki に nlog.config の個別ページも用意されているため、追いかけるのは容易そうです。

github.com

  • nlog: nlog.config 全体の設定、 internal-nlog.txt の出力設定を行います。
  • extensions: nlog.config の中で使われる、「${ }」のような表現方法を有効にするための機能を有効にします。
  • targets: ログの出力タイプ(ファイルとかコンソールとか)、名前( rules でこの値を使ってターゲットを指定します)、ファイルの場合はその出力先などを指定します。
  • rules: targets の中で設定したそれぞれのターゲットに、どのレベル( Info, Warning など)のログを出力するかなどのルールを指定します。

出力されるファイルは下記の三つです。

  • internal-nlog.txt: NLog の内部処理に関するログが出力されます。
  • nlog-all-${shortdate}.log: Trace レベルのログを出力します。
  • nlog-own-${shortdate}.log: Microsoft.* 名前空間下の Info レベルのログを除く、Trace レベルのログを出力します。

ログレベルについては下記参照、ということなのですが、Trace レベルが「メソッド X の始め、メソッド X の終わり、etc.」のように書かれていて、あまりよく分かりませんでした(- _ -;)

github.com

出力されたものを見ると、呼ばれたメソッドの情報が出力される、ということのようでした。

また rules で設定されるルールで、 nlog-all-${shortdate}.log と nlog-own-${shortdate}.log のルールは同じように見えるのですが、間に final="true" を持ったルールが追加されることで、Microsoft.* 名前空間下の Info レベルのログが除かれる結果となっています。

nlog.config

~省略~
  < rules>
    < !--All logs, including from Microsoft-->
    < logger name="*" minlevel="Trace" writeTo="allfile" />

    < !--Skip non-critical Microsoft logs and so log only own logs-->
    < logger name="Microsoft.*" maxLevel="Info" final="true" /> < !-- BlackHole without writeTo -->
    < logger name="*" minlevel="Trace" writeTo="ownFile-web" />
  < /rules>
  ~省略~

nlog.configを書く

ではこのサンプルを基に、自分でも nlog.config を書いてみようと思います。

nlog.config

< ?xml version="1.0" encoding="utf-8" ?>
< !-- NLog 内部のログはいったん出力しないこととする -->
< nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      autoReload="true">

  < extensions>
    < add assembly="NLog.Web.AspNetCore"/>
  < /extensions>

  < targets>
    < !-- コンソールに出力  -->
    < target xsi:type="Console" name="alloutput"
            layout="${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}" />

    < target xsi:type="File" name="ownFile-web" fileName="C:\temp\logs\${date:format=yyyy}\${date:format=MM}\nlog-own-${shortdate}.log"
            layout="${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}|url: ${aspnet-request-url}|action: ${aspnet-mvc-action}" />

    < target xsi:type="File" name="ownFile-access" fileName="C:\temp\accessLogs\${date:format=yyyy}\${date:format=MM}\nlog-access-${shortdate}.log"
            layout="${longdate},${message} ${exception:format=tostring}" />
  < /targets>
  < rules>
    < !--コンソールには Trace レベル以上のログすべてを出力-->
    < logger name="*" minlevel="Trace" writeTo="alloutput" />
    < !--Microsoft.* のクラスの Info レベル以下のログはスキップ-->
    < logger name="Microsoft.*" maxLevel="Info" final="true" />
    < logger name="*" minlevel="Info" writeTo="ownFile-web" />
    < !-- HomeController に対するアクセスログ( Info レベル)のみ記録 -->
    < logger name="WebApplication1.Controllers.HomeController" minLevel="Info" maxLevel="Info" writeTo="ownFile-access" />
  < /rules>
< /nlog>

これで例えば今日( 2018.09.06 )実行した場合、下記の場所にファイルが出力されます。

  • C:\temp\accessLogs\2018\09: HomeController にアクセスしたときのログ
  • C:\temp\logs\2018\09: Microsoft.* 以下のクラスを除くアプリケーション全体での、Info レベル以上のログ

※ NLog 内部処理のログを出力しない設定にしていますが、本来出すべきだとは思います。

おわりに

一応これでログ出力はできるようになりましたが、まだいくつか課題はあります。

  1. ログがどのように出力されるかわかっていない → Program.cs に追加した NLog 関連のコードからたどっていくのが良さそう?
  2. ログを出力するレベルや、フォーマットなどログ設計について学習が必要
  3. Visual Studio で nlog.config を編集しているときに、設定が正しく反映されないことがあった
  4. Rider で nlog.config を開くと xsi:type="Console" などでエラーとして表示(ビルドや実行には問題なし)

3.については Program.cs でログ出力すると直ったり、4.は nlog.config に限らず IntelliJAndroid Studio などでも見かけた現象だったりするので、改善の余地もありそうです。

これらについてはおいおい解決していきたいと思います。

また今回は触れませんでしたが、 NLog の出力先として DB やメールなども利用可能(らしい)ですので、そちらも試してみたいと思います。

参照

https

ILogger

NLog