ASP.NET Core のカスタムロガーを使用したログ取得方法です。
実際に、社内で ASP.NET Core MVC のWebアプリケーションを開発した時に、ログをどのように記録するか試行しながら辿り着いた方法です。
ASP.NET Core では、フレームワーク内からのログが細かく多く出力されるので、これらのログが確認できると詳細な分析にも役立ちます。
Microsoft Docs 参考サイト
.NET Core および ASP.NET Core でのログ記録
カスタム ロガーを作成する
参考サイトの説明を、より具体的なコードに表して、後々他のプロジェクトでもコードコピーして利用できれば良いと思いエントリーします。元々 ASP.NET Core 2.x の時に作成したものですが、ASP.NET Core 3.1 で動くように調整して動くものにしています。
ASP.NET Core のログを処理する際には、ILogger, ILoggerProvider, ILoggerFactory の関係を理解することが起点になりますので、段階的な順としてまとめています。
※ 当内容は、.NET Framework で例えると、カスタムな TraceListener を作成することに近い内容です。
目次
- ログのための最小限の雛形
- コントローラーの Logger インスタンス
- モデルクラスや個別クラスの Logger インスタンス
- Viewの Logger インスタンス
- static の Logger インスタンス
- ログの詳細を取得してオブジェクト化
- ログのプールクラスとログの出力
- ログを処理させるBackgroundService
※ サンプルコードのプロジェクト名は LoggerSample としています。このため、各コード内のベースの名前空間は LoggerSample となります。
ログのための最小限の雛形
カスタムロガーを使用するためには、カスタムロガー用のロガープロバイダーが必要になります。
まず、SystemLogger.cs をプロジェクトに新規追加し、
カスタムロガーとして SystemLogger クラスを、
ロガープロバイダーとして SystemLoggerProvider クラスを
以下の内容で作成します。
Modelsフォルダに作成しますが、作成場所は好みで良いです。
...
using Microsoft.Extensions.Logging;
namespace LoggerSample.Models
{
public class SystemLoggerProvider : ILoggerProvider
{
public ILogger CreateLogger(string categoryName)
{
return new SystemLogger(categoryName);
}
public void Dispose()
{
}
}
public class SystemLogger : ILogger
{
private readonly string CategoryName;
public SystemLogger(string categoryName)
{
CategoryName = categoryName;
}
public IDisposable BeginScope<tstate>(TState state) => null;
public bool IsEnabled(LogLevel logLevel) => true;
public void Log<tstate>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
// ここにログの詳細を取得するコードを入れる
var message = formatter(state, exception);
var level = (int)logLevel;
}
}
}
このロガープロバイダーは、ロガーファクトリに登録しないと動きません。つまり、カスタムロガーも動かないことになります。
ロガーファクトリに登録するには、2通りの方法があります。
・IHostBuilder を生成する CreateHostBuilder 内で、ConfigureLogging で構成する方法 (Program.cs)
・Startupクラスの Configure で登録する方法 (Startup.cs)
先に、Startupクラスの Configure で登録する方法です。
Startup.cs を修正。Configureメソッドで ILoggerFactory をDIで受け取り、ロガーファクトリに AddProvider でロガープロバイダ（SystemLoggerProvider）を登録します。
...
using Microsoft.Extensions.Logging;
using LoggerSample.Models;
namespace LoggerSample
{
public class Startup
{
public Startup(IConfiguration configuration)
{
Configuration = configuration;
}
public IConfiguration Configuration { get; }
// This method gets called by the runtime. Use this method to add services to the container.
public void ConfigureServices(IServiceCollection services)
{
...
}
// This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
public void Configure(IApplicationBuilder app, IWebHostEnvironment env, ILoggerFactory loggerFactory)
{
loggerFactory.AddProvider(new SystemLoggerProvider());
...
}
}
}
次に、CreateHostBuilder 内で、ConfigureLogging で構成する方法です。
Program.cs を修正。ConfigureLogging を追加し、AddProvider でロガープロバイダ（SystemLoggerProvider）を登録します。
...
using LoggerSample.Models;
namespace LoggerSample
{
public class Program
{
public static void Main(string[] args)
{
CreateHostBuilder(args).Build().Run();
}
public static IHostBuilder CreateHostBuilder(string[] args) =>
Host.CreateDefaultBuilder(args)
.ConfigureLogging(logging =>
{
logging.AddProvider(new LoggerSample.Models.SystemLoggerProvider());
})
.ConfigureWebHostDefaults(webBuilder =>
{
webBuilder.UseStartup<Startup>();
});
}
}
こちらの場合、Startupクラスに関係なく、ロガービルダーが構成される時に、ロガーファクトリに含まれることになります。
このため、Startupクラスの Configureメソッドで ILoggerFactory を受け取ることが出来ますが、ロガーファクトリには、ロガープロバイダ（SystemLoggerProvider）は既に登録されています。ここで AddProvider でロガープロバイダ（SystemLoggerProvider）を登録すると、更にカスタムロガーが追加されるので、ログが2重になることになります。
どちらのコードでも、ロガーファクトリには、ロガープロバイダ（SystemLoggerProvider）が登録されるので、ILogerから発生するログは、全て SystemLogger の Log メソッドに入ります。
雛形のため、一旦 Log メソッドは簡易的にメッセージが確認できる程度のものにしています。
試しに、HomeControllerにログを出力するコードを入れてデバッグ実行してみます。
namespace LoggerSample.Controllers
{
public class HomeController : Controller
{
private readonly ILogger<HomeController> _logger;
public HomeController(ILogger<HomeController> logger)
{
_logger = logger;
}
public IActionResult Index()
{
_logger.LogInformation("HomeコントローラーのIndex()");
return View();
}
Log メソッド内にブレークポイントを張り、デバッグ実行してみます。
| CategoryName | logLevel | message | |
| 1回目 | Microsoft.Hosting.Lifetime | Information | Application started. Press Ctrl+C to shut down. |
| 2回目 | Microsoft.Hosting.Lifetime | Information | Hosting environment: Development |
| 3回目 | Microsoft.Hosting.Lifetime | Information | Content root path: D:\\Workin ... 略 |
| 4回目 | LoggerSample.Controllers.HomeController | Information | HomeコントローラーのIndex() |
初回実行時では、HomeコントローラーのIndex()メソッドが呼ばれる前に、3回のログが出ました。
カテゴリ名が "Microsoft.Hosting.Lifetime" となっているので、ASP.NET Core アプリケーションが起動された時の(Hosting)ログと推測できます。
4回目のログが、意図的に出力したログです。
カテゴリ名は、ログが出力された名前空間になっているので察しやすいですね。
さて、
上の例では、ログが4回で済んでいますが、これはログレベルが絞られている状態です。
ログレベルは、appsettings.json の "Logging" -> "LogLevel" でフィルタされます。
デフォルトの appsettings.Development.json を見てみます。
{
"Logging": {
"LogLevel": {
"Default": "Information",
"Microsoft": "Warning",
"Microsoft.Hosting.Lifetime": "Information"
}
}
}
ログレベルの指定は、Default のレベルをベースとして、カテゴリ名の接頭句で上書き設定されます。
この例では、
Default は Information で、
Microsoft で始まるカテゴリ名は Warning 以上にする。
但し、Microsoft.Hosting.Lifetime で始まるカテゴリ名は Information 以上でログ出力する。
ということになります。
この初期状態としては、名前空間を変に細工せず普通にアプリケーションを作成していれば、アプリケーション用の名前空間のログと、System名前空間のログは、Information 以上のログが出力されることになります。
System名前空間のログは、実際には確認できたことが無いので、System名前空間のものはフレームワーク内でのログを出力していないと推測しています。
ログレベルを変えて確認してみましょう。"Microsoft": "Warning" を "Information" に変えてみます。
{
"Logging": {
"LogLevel": {
"Default": "Information",
"Microsoft": "Information",
"Microsoft.Hosting.Lifetime": "Information"
}
}
}
※ この場合、Microsoft で始まるものを Information レベルにしたので、Microsoft.Hosting.Lifetime を Information 指定することは重複して意味が無くなるので削除しても良いです。
これで、デバッグ実行すると、IndexのViewページが表示されるまで、4回のログで済んでいたものが、10数回のログが出力されるようになります。MVCのActionやViewResult等の Information ログが増えてきます。
Microsoft のログレベルを、Information より更に下げると(Debug や Trace)、もっと多くのログを確認できますが、避けたほうが良いでしょう。
一度試してみることには賛成しますが、相当な量のログが出力されるので、ログをファイルやDBに出力していると、アプリケーションが重くなったり、ログ出力されたデータの掃除にも手間が増えるので、何かのLowレベルな確認以外に利用することは無いと思います。
ILogerからのログは確認できましたので、システム例外時のエラーも確認してみます。
コントローラーから _logger.LogInformation("HomeコントローラーのIndex()"); でログを出力していた箇所を、例外が発生するように変更してみます。
public IActionResult Index()
{
//Logger.LogInformation("HomeコントローラーのIndex()");
int a = 1 / int.Parse("0");
return View();
}
0除算を意図的に入れました。見て分かるように例外が発生するコードです。
これで実行すると、Log メソッドには例外が発生した内容が入ってきます。
| CategoryName | Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware |
| logLevel | Error |
| message | An unhandled exception has occurred while executing the request. |
| exception.Message | Attempted to divide by zero. |
ILogerからのログの出力はしていませんが、フレームワーク内からのエラーログが出力された結果をトレースしたことになります。
このエラーログは、Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware から出されたことが判ります。
渡ってきた exception は、Attempted to divide by zero. が確認できます。
logLevelは、Error (=4) なので、この例外内容をメールで通知するなどの処理を入れるのが適切になります。
ASP.NET Core では、例外時にもこのようにフレームワーク内からエラーログが出力されるので、エラーハンドリング処理内からエラー通知をするよりも、カスタムロガーからエラーログを検知してエラー通知をするほうが、抜け目無く効率が良いと思います。
フレームワーク内から出力される Information ログは、アプリケーションの実行順を追えるくらいのログが出力されるので、これだけでシステムログとしての目的が果たせます。
これを利用すると、アプリケーションから任意にログを出力する場面は少ないかもしれません。
複雑な処理や重要な処理をしている箇所を、ログで確認できるようにするなどの用途に限ってくるかと思います。
コントローラーの Logger インスタンス
ASP.NET Core MVC のプロジェクトテンプレートで作成されるコントローラーは、ILogger<HomeController> という型付けしたILoggerのインスタンスを受け取り、自身のプロパティに格納しています。
この型付けは、ログのカテゴリ名（＝名前空間）になるため、正しく設定されないといけませんが、コントローラーのクラスを指定するため、コントローラー毎に変えていきます。コントローラーが増えるにつれて、これが負担となり面倒で煩雑になります。
このように感じたら、DIに頼らずにロガーファクトリからILoggerを指定名で作成しましょう。
まず、ILoggerFactoryのインスタンスを得るため、Startupクラスの Configure で ILoggerFactory を受け取った後、このインスタンスをスタティックなプロパティとして維持します。
Startup.csで、AppGlobalObjectというクラスを作成し、Configure も次のように変更します。
...
using Microsoft.Extensions.Logging;
using LoggerSample.Models;
namespace LoggerSample
{
public class AppGlobalObject
{
public static IConfiguration Configuration { get; set; }
public static ILoggerFactory LoggerFactory;
}
public class Startup
{
public Startup(IConfiguration configuration)
{
AppGlobalObject.Configuration = configuration;
Configuration = configuration;
}
public IConfiguration Configuration { get; }
// This method gets called by the runtime. Use this method to add services to the container.
public void ConfigureServices(IServiceCollection services)
{
...
}
// This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
public void Configure(IApplicationBuilder app, IWebHostEnvironment env, ILoggerFactory loggerFactory)
{
AppGlobalObject.LoggerFactory = loggerFactory;
AppGlobalObject.LoggerFactory.AddProvider(new SystemLoggerProvider());
...
}
}
}
コントローラーを次のように変更します。比較用に変更前の行をコメントにしました。
namespace LoggerSample.Controllers
{
public class HomeController : Controller
{
//private readonly ILogger<HomeController> _logger;
private readonly ILogger _logger;
//public HomeController(ILogger<HomeController> logger)
public HomeController()
{
//_logger = logger;
_logger = AppGlobalObject.LoggerFactory.CreateLogger(GetType().ToString());
}
public IActionResult Index()
{
_logger.LogInformation("HomeコントローラーのIndex()");
return View();
}
コンストラクタのDIに頼らず、ロガーファクトリの CreateLogger でILoggerのインスタンスを作成します。
CreateLogger メソッドには GetType().ToString() で現在のインスタンスのType文字列を得て、引数に渡すことで Logger のカテゴリ名になります。
デバッグ実行しても、_logger.LogInformation("HomeコントローラーのIndex()"); のログが、変更前と同じカテゴリ名で確認できます。
コントローラーのコンストラクタ引数が減ってすっきりしますし、コントローラー毎の差異も無くなり、共通コードでログのためのインスタンスを用意することが出来ます。
それでも、プロパティを用意してインスタンス生成をするのが面倒になる場合は、コントローラーのBaseクラスを作成して、全てのコントローラーがBaseクラスを継承するようにすれば更にすっきりします。ここまで行おうとすると、プロジェクトの標準化にもなってくるので初期段階で検討しておくほうが良いでしょう。
以下、継承元のBaseコントローラークラスです。CommonBase.cs として、Modelsフォルダに作成します。
...
using Microsoft.AspNetCore.Mvc;
using Microsoft.Extensions.Logging;
namespace LoggerSample.Models
{
public abstract class BaseController : Controller
{
private ILogger _logger;
protected ILogger Logger
{
get
{
if (_logger == null)
{
_logger = AppGlobalObject.LoggerFactory.CreateLogger(GetType().ToString());
}
return _logger;
}
}
}
}
Loggerプロパティをシングルトンで持ち、初回参照時にインスタンス化されます。
このBaseコントローラーを継承すると、既存のコントローラーは次のようになります。比較用に元のコントローラーからの変更行をコメント化してます。
...
using LoggerSample.Models;
namespace LoggerSample.Controllers
{
//public class HomeController : Controller
public class HomeController : BaseController
{
//private readonly ILogger<HomeController> _logger;
//public HomeController(ILogger<HomeController> logger)
public HomeController()
{
//_logger = logger;
}
public IActionResult Index()
{
//_logger.LogInformation("HomeコントローラーのIndex()");
Logger.LogInformation("HomeコントローラーのIndex()");
return View();
}
ILoggerのためのコードは無くなり、直接 Logger プロパティを使用してログを出力することができます。
上のコメント化した行は、実際にはソースコードから無くなり、ログのためのインスタンス生成箇所は見えなくなるので、隠蔽されたような感じにもなります。
ここまでのコードに至るまでの経緯が判れば、ILoggerの理解も深まると思いますが、ASP.NET Core に慣れていない技術者が、プロジェクトに参画してこのコードを見ると、ログのための根幹部分が分からないまま開発することになるので、標準化等の施策で教えてあげましょう。
モデルクラスや個別クラスの Logger インスタンス
モデルクラスの場合、コンストラクタでDIさせることができません。明示的にインスタンスを生成する場合には、コンストラクタに引数を与えられますが、POST時などのモデルバインディングでインスタンスが生成される時には、空のコンストラクタで作成されるためです。
モデルの場合もコントローラーと同じ方法で、ILogger のプロパティを持たせて、コンストラクタでロガーファクトリの CreateLogger でILoggerのインスタンスを作成します。
モデル用途ではない個別クラスの場合でも同じです。
仮サンプルとして、Homeモデルを作成してみます。ModelsフォルダにHomeModel.csを作成します。
...
using Microsoft.Extensions.Logging;
namespace LoggerSample.Models
{
public class HomeModel
{
private readonly ILogger _logger;
public HomeModel()
{
_logger = AppGlobalObject.LoggerFactory.CreateLogger(GetType().ToString());
}
public void LogTest()
{
_logger.LogInformation("HomeModelのLogTest()");
}
}
}
ログのためのプロパティの持ち方とインスタンス化は、コントローラーと同じです。
プロパティとコンストラクタの記述が煩雑に感じたら、Baseコントローラークラスと同じように、Baseモデルクラスを作成して継承するようにしても良いでしょう。
このモデルには、テスト用にログを出力させる LogTest() メソッドを用意しました。
Homeコントローラーでモデルのインスタンスを作り、LogTest() を呼んでみます。
...
public IActionResult Index()
{
//Logger.LogInformation("HomeコントローラーのIndex()");
var model = new HomeModel();
model.LogTest();
return View();
}
生成したモデルは、ビューの用途のために実際は View() の引数に渡すものですが、テスト確認なので調整してません。
このモデルの LogTest() から出力されるログは、次の内容になります。
| CategoryName | LoggerSample.Models.HomeModel |
| logLevel | Information |
| message | HomeModelのLogTest() |
カテゴリ名が、ログを発したインスタンスの名前空間になっていることが重要ですが、正しく設定されていることが確認できます。
Viewの Logger インスタンス
次に、Viewからログを出力した場合の内容を確認してみます。
Viewの場合はクラスでは無いので、直接 ILogger を作成してログを出力することになります。以下のようなコードになります。
これは、HomeのIndexビューに追加した場合です。
@using Microsoft.Extensions.Logging
@{
ViewData["Title"] = "Home Page";
ILogger _logger = AppGlobalObject.LoggerFactory.CreateLogger(GetType().ToString());
}
<div class="text-center">
<h1 class="display-4">Welcome</h1>
<p>Learn about <a href="https://docs.microsoft.com/aspnet/core">building Web apps with ASP.NET Core</a>.</p>
</div>
@{
_logger.LogInformation("Views - Home - Index.cshtml");
}
このログは次の内容で出力されました。
| CategoryName | AspNetCore.Views_Home_Index |
| logLevel | Information |
| message | Views - Home - Index.cshtml |
Viewからの GetType().ToString() から、カテゴリ名は、AspNetCore.Views_Home_Index になりました。
ログの結果として、カテゴリ名を良しとするならこれで良いです。
Viewの冒頭でILoggerを作成する手間が掛かりますが、Viewはクラスでは無いので仕方無いでしょう。
ILoggerの作成が面倒な場合は、カテゴリ名が犠牲になりますが、次の ststic の Logger インスタンスも検討してみてください。
static の Logger インスタンス
ILoggerは特定クラスのメンバとしてインスタンスを作成しますが、ststic の Logger が用意できれば、いつでもどこでもログを出力できます。
ststicのインスタンスになるので、Logger の名前空間が全て同じになります。これはフィルタでログの出力が振り分け出来ないことになります。
AppGlobalObjectクラスで、次のような GlobalLogger という ststic の ILogger プロパティを用意します。
...
using Microsoft.Extensions.Logging;
namespace LoggerSample
{
public class AppGlobalObject
{
public static IConfiguration Configuration { get; set; }
public static ILoggerFactory LoggerFactory;
private static ILogger _globalLogger;
public static ILogger GlobalLogger
{
get
{
if (_globalLogger == null)
{
_globalLogger = LoggerFactory.CreateLogger("LoggerSample.AppGlobalObject");
}
return _globalLogger;
}
}
}
ロガーファクトリの CreateLogger の引数には、ログのカテゴリ名になる名前空間の文字列を直接指定します。これは、static メソッドなので GetType() が使えないからです。
ダミーオブジェクトやリフレクションなどで名前空間を得ることもできなくはないですが、そこまでする必要も無いでしょう。
この AppGlobalObject.GlobalLogger を使うことで、どこからでもログの出力が出来ます。
カテゴリ名は、"LoggerSample.AppGlobalObject" に固定されて全て同一になるので、後々ログの一覧を確認する際に、どこで出力したログなのか分かり難いことになるので、この GlobalLogger でログを出力する場合には、EventId を含ませて、開発アプリケーション内で EventId値のルールをきちんと決めておいたほうが良いでしょう。
先の、HomeのIndexビューのログ出力を、GlobalLogger を使うようにしてみます。
@{
AppGlobalObject.GlobalLogger.LogInformation(new EventId(10001, "test"), "Views - Home - Index.cshtml");
}
| CategoryName | LoggerSample.AppGlobalObject |
| logLevel | Information |
| message | Views - Home - Index.cshtml |
| eventId.Id | 10001 |
| eventId.Name | test |
カテゴリ名は、LoggerSample.AppGlobalObject になります。
EventIdには、指定した 10001 と test という文字列が入ってくることが判ります。
ログの詳細を取得してオブジェクト化
これまで、SystemLogger の Log メソッドは、実際の処理としては何もしていません。
public void Log<tstate>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
// ここにログの詳細を取得するコードを入れる
var message = formatter(state, exception);
var level = (int)logLevel;
}
これだとデバッグ実行時の確認程度しかできません。
ログの目的は、ファイルに格納する、DBに格納する、エラーはメールで通知するなどがあります。このためのログの項目を持つ詳細クラスを定義して、各項目値を取得していきます。
ここからは、ログの詳細取得の処理になります。
準備としてまず先に、ASP.NET Core なので、Webリクエストの情報を得るために HttpContext が必要になります。
ASP.NET Core では ASP.NET Framework にあった System.Web.HttpContext.Current のようなアクセサはデフォルトで無くなりましたが、IHttpContextAccessor を使用することで HttpContext を得ることが出来ます。
IHttpContextAccessor を使用するためには、Startupクラスで登録しておく必要があります。
...
using Microsoft.AspNetCore.Http;
using Microsoft.Extensions.Logging;
using LoggerSample.Models;
namespace LoggerSample
{
public class AppGlobalObject
{
public static IConfiguration Configuration { get; set; }
public static ILoggerFactory LoggerFactory;
public static IHttpContextAccessor HttpContextAccessor;
...
}
public class Startup
{
...
public void ConfigureServices(IServiceCollection services)
{
...
services.AddHttpContextAccessor();
}
public void Configure(IApplicationBuilder app, IWebHostEnvironment env, ILoggerFactory loggerFactory)
AppGlobalObject.LoggerFactory = loggerFactory;
AppGlobalObject.LoggerFactory.AddProvider(new SystemLoggerProvider());
AppGlobalObject.HttpContextAccessor = app.ApplicationServices.GetRequiredService<IHttpContextAccessor>();
...
ConfigureServices で、services.AddHttpContextAccessor(); を行うことで、IHttpContextAccessor が登録されるので、各所でDIも出来るようになります。
確か、ASP.NET Core 2.x では、services.AddSingleton<IHttpContextAccessor, HttpContextAccessor>() で、登録していた気がしますが、ASP.NET Core 3.1 では services.AddHttpContextAccessor(); で良いです。
Configure で、GetRequiredService を使用して IHttpContextAccessor を取得し、AppGlobalObject.HttpContextAccessor に割り当てます。これで、AppGlobalObject.HttpContextAccessor からいつでも取得できます。
各項目の取得に戻りましょう。
ログ詳細クラスを、一例として次のようにしました。項目名から各値が何か想像できるでしょうか？
SystemLogger.csに追加します。
public class SystemLog
{
public DateTime LogDate { get; set; }
public string MachineName { get; set; }
public int ProcessId { get; set; }
public int ThreadId { get; set; }
public int LogLevel { get; set; }
public string CategoryName { get; set; }
public int EventId { get; set; }
public string EventName { get; set; }
public string RemoteIpAddress { get; set; }
public string UrlPath { get; set; }
public string UserIdentifier { get; set; }
public string MethodFullName { get; set; }
public string MethodName { get; set; }
public string FileName { get; set; }
public int LineNumber { get; set; }
public string Message { get; set; }
public string ExceptionType { get; set; }
public string ExceptionMessage { get; set; }
public string StackTrace { get; set; }
}
Log メソッドは同期メソッドなので、処理に時間が掛かってしまうと、ページ表示も比例して遅くなるため、各項の取得はなるべく早く済ませます。また この処理内で例外が発生するとエラーがループするので、例外が発生しないようにしてください。
まずは簡単な項目から
...
using System.Diagnostics;
using System.Reflection;
using System.Security.Claims;
using System.Threading;
using Microsoft.AspNetCore.Http.Extensions;
...
public void Log<tstate>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
var log = new SystemLog();
log.LogDate = DateTime.UtcNow.AddHours(9);
log.MachineName = Environment.MachineName;
log.ProcessId = Process.GetCurrentProcess().Id;
log.ThreadId = Thread.CurrentThread.GetHashCode();
log.LogLevel = (int)logLevel;
log.CategoryName = CategoryName ?? string.Empty;
log.EventId = eventId.Id;
log.EventName = eventId.Name ?? string.Empty;
log.Message = formatter(state, exception);
| LogDate |
現在日時です。日本時間にするため、UTC日時から9時間を足します。 |
| MachineName |
実行しているPC名です。冗長構成の場合にどのPCの処理なのか分かるようにするためです。Azure Web Appsでもこれで取得できます。 もし同一PC上で冗長化サイトを動かす場合は、これだと問題になるので、アプリケーション毎に明示的な文字列が設定されるようにしてください。 |
| ProcessId |
WebサーバーのプロセスIdです。IISの場合はアプリケーションプールのプロセスになります。 ASP.NET Core のアプリケーションが再起動されるとIdが変わります。 |
| ThreadId |
Webサーバーがリクエストを受けたスレッドのIdです。リクエスト毎にIdは変わります。通常は同一リクエスト内で同一Idです。 連続したログの流れを追う時、スレッドIdが違う場合は別リクエストと判断できるものになります。 実行スレッドのIdなので、処理内から別スレッドを動かして処理している場合は別Idになります。そのような処理内のログは、同一リクエストかの判断はできませんので、あまりあてにできないこともあります。 |
| LogLevel |
Log メソッドに渡されるlogLevelのint値です。 |
| CategoryName |
Logger に設定されているカテゴリ名です。Log メソッドを呼び出したところの名前空間になります。 |
| EventId |
Log メソッドに渡されるeventIdのId値です。 |
| EventName |
Log メソッドに渡されるeventIdのName値です。 |
| Message |
ログの文字列です。Log メソッドに渡されたformatterデリゲートを使用してログの文字列が得られます。 |
次にリクエスト情報です。
...
var httpContext = AppGlobalObject.HttpContextAccessor?.HttpContext;
log.RemoteIpAddress = httpContext?.Request?.Headers["X-Forwarded-For"].FirstOrDefault()?.Split(":".ToCharArray())?.FirstOrDefault();
log.RemoteIpAddress = log.RemoteIpAddress ?? httpContext?.Connection?.RemoteIpAddress?.ToString();
log.RemoteIpAddress = log.RemoteIpAddress ?? httpContext?.Request?.Headers["REMOTE_ADDR"].FirstOrDefault();
log.RemoteIpAddress = log.RemoteIpAddress ?? string.Empty;
log.UrlPath = httpContext?.Request?.GetDisplayUrl() ?? string.Empty;
log.UserIdentifier = httpContext?.User?.Claims?.FirstOrDefault(x => x.Type == ClaimTypes.NameIdentifier)?.Value ?? string.Empty;
HttpContextから、リモートIPアドレス、アクセスURL、認証で承認されたユーザーId を取得します。
Webリクエストから発するログは HttpContext が存在しますが、バックグラウンドサービスなど HttpContext が無い (null) 場合もあるので、考慮しておきましょう。
| RemoteIpAddress |
リモートIPアドレスです。HttpContext が無い場合は空文字にします。 上のコードで取得できるかは、実際の稼働環境にもよります。 Startupで UseForwardedHeaders を使用する場合や、ARRや他のロードバランサーの設定次第でも変わる可能性があるので、稼働環境で事前にテストしてください。 また、Azure SignalR を使用する場合も、リモートIPアドレスが正しく取得できるか確認しておきましょう。 DNSにアクセスできれば、逆引きしてホスト名も解決できますが、コストが掛かるので Log メソッド内で行うのはお薦めしません。 |
| UrlPath |
アクセスされたURLです。HttpContext が無い場合は空文字にします。 |
| UserIdentifier |
Cookie認証の承認ユーザーを想定していますが、ClaimTypes.NameIdentifier のクレーム情報を記録します。 このログ処理に合わせて、初期の段階でクレーム情報のトークンを決めておくほうが良いでしょう。 私は社内アプリケーションの開発で、ログの処理を後回しにして、Areaで3区分に分かれているところを別々のクレーム情報で認証/承認処理をしてしまいました。いざ、ログの処理を進めていくうちに、クレーム情報がバラバラだとログのための取得コードもバラバラになってしまい、統一させるためにクレーム情報の項目名が同じになるように修正することになりました。 |
HttpContextからは、他にも、POST時のデータ、Cookie値、Session値、リファラ などが取得できます。
全ての Log で取得するには幾分無駄を感じるので、LogLevel が Warning (=3) 以上、または特定イベントの Log だけで取るようにしました。
特定イベントの Log は、
Microsoft.AspNetCore.Hosting.Diagnostics
EventId.Id が 1
の Information ログです。
このログは、Webリクエストの最初のログです。このログの後に ControllerActionInvoker や、ViewResultExecutor などのログが続きます。
Webリクエストの終了時のログで、もう一度、Microsoft.AspNetCore.Hosting.Diagnostics が出ますが、終了時は、EventId.Id = 2 のログです。
このログを利用すると、ページビューの件数も把握できることになります。
実はこのタイミングのログは、ASP.NET Core 2.x のときは、"Microsoft.AspNetCore.Hosting.Internal.WebHost" でした。ASP.NET Core 3.x で変わったので、ASP.NET Core のバージョンアップ時には追従する必要があります。
以下、POSTデータ等の取得コードです。全て文字列値にして、Message の後ろに追加することにしますが、ログの項目にすることもできます。
string requestValue = string.Empty;
if (httpContext != null && (
log.LogLevel >= 3 ||
(CategoryName.Equals("Microsoft.AspNetCore.Hosting.Diagnostics", StringComparison.OrdinalIgnoreCase) && eventId.Id == 1)
))
{
string userAgent = string.Empty;
string queryValues = string.Empty;
string formValues = string.Empty;
string sessionValues = string.Empty;
string cookieValues = string.Empty;
// UserAgent
try
{
if (httpContext.Request?.Headers?.ContainsKey("User-Agent") ?? false)
{
userAgent = httpContext.Request.Headers["User-Agent"].FirstOrDefault() ?? string.Empty;
}
}
catch
{
userAgent = string.Empty;
}
// QueryString
try
{
IQueryCollection queryInfo = httpContext.Request?.Query;
if (queryInfo != null && queryInfo.Count > 0)
{
foreach (var query in queryInfo)
{
queryValues += string.Format("{0}={1}\r\n", query.Key, query.Value);
}
}
}
catch
{
queryValues = string.Empty;
}
// Form
try
{
IFormCollection formInfo = httpContext.Request?.Form;
if (formInfo != null && formInfo.Count > 0)
{
foreach (var form in formInfo)
{
formValues += string.Format("{0}={1}\r\n", form.Key, form.Value);
}
}
}
catch
{
formValues = string.Empty;
}
// Session
try
{
ISession sessionInfo = httpContext.Session;
if (sessionInfo != null)
{
foreach (var sessionKey in sessionInfo.Keys.ToList())
{
var sessionValue = sessionInfo.GetString(sessionKey);
sessionValues += string.Format("{0}={1}\r\n", sessionKey, sessionValue);
}
}
}
catch
{
sessionValues = string.Empty;
}
// Cookie
try
{
IRequestCookieCollection cookieInfo = httpContext.Request?.Cookies;
if (cookieInfo != null && cookieInfo.Count > 0)
{
foreach (var cookie in cookieInfo)
{
cookieValues += string.Format("{0}={1}\r\n", cookie.Key, cookie.Value);
}
}
}
catch
{
cookieValues = string.Empty;
}
if (!string.IsNullOrEmpty(userAgent))
{
requestValue += string.Format("***** User-Agent *****\r\n{0}\r\n", userAgent);
}
if (!string.IsNullOrEmpty(queryValues))
{
requestValue += string.Format("***** Query *****\r\n{0}", queryValues);
}
if (!string.IsNullOrEmpty(formValues))
{
requestValue += string.Format("***** Form *****\r\n{0}", formValues);
}
if (!string.IsNullOrEmpty(sessionValues))
{
requestValue += string.Format("***** Session *****\r\n{0}", sessionValues);
}
if (!string.IsNullOrEmpty(cookieValues))
{
requestValue += string.Format("***** Cookie *****\r\n{0}", cookieValues);
}
if (!string.IsNullOrEmpty(requestValue))
{
requestValue = string.Format("\r\n----- RequestInfo -----\r\n{0}-----------------------\r\n", requestValue);
}
}
if (!string.IsNullOrEmpty(requestValue))
{
log.Message += string.Format("\r\n{0}", requestValue);
}
念のためですが、上のコードのPOSTデータの取得は、テキストボックスなどの入力値を想定しています。ファイル送信やバイナリをエンコード文字列にしたような大きなものは想定していません。そのようなPOST値が含まれると、ログ内容も肥大化し認識できないデータが多くを占めても意味も無いので、文字数を制限するか、特定のトークン（inputタグのnameなど）を事前に決めておいて細工できるようにしても良いかもしれません。
次に、スタックトレースと例外情報を取得します。
StackTrace stackTrace;
if (exception != null)
{
stackTrace = new StackTrace(exception, true);
log.StackTrace = exception.StackTrace ?? string.Empty;
log.ExceptionType = exception.GetType().ToString();
log.ExceptionMessage = exception.Message;
Exception ex = exception.InnerException;
while (ex != null)
{
log.ExceptionMessage += string.Format(
"\r\n----- InnerException -----\r\nExceptionType: {0}\r\nExceptionMessage: {1}",
ex.GetType().ToString(),
ex.Message);
ex = ex.InnerException;
}
}
else
{
stackTrace = new StackTrace(true);
log.StackTrace = stackTrace.ToString();
log.ExceptionType = string.Empty;
log.ExceptionMessage = string.Empty;
}
Log に exception が渡ってきたら、exception のスタックトレースを取得します。例外の型と内容も取得します。
例外情報には、InnerException があるので、全部取っておきます。
exception が渡ってこない場合は、現在のスタックトレースを取得しておきます。これは、この Log メソッドのスタックトレースになります。
もし、この Log メソッドから別メソッドを作って詳細を取得する場合はスタック位置がその分ズレるので注意してください。
次に、取得したスタックトレースから、メソッドベースと、ファイル名、行番号 を取得します。
この部分は、動作確認と努力が必要になります。実際に確認しながら完成したコードを載せますが、ASP.NET Core のバージョンが上がる時に(メジャーバージョン、マイナーバージョンの両方で)、フレームワーク内の名前空間が変わることがあるので、ログの出方がおかしいと気付いたら都度確認して調整が必要になるかもしれません。
StackFrame[] stackFrames = stackTrace.GetFrames();
StackFrame stackFrame;
MethodBase methodBase;
string methodBaseFullName = string.Empty;
string methodBaseName = string.Empty;
string fileName = string.Empty;
int? lineNumber = null;
int frameIndex = -1;
string thisClassTypeFullName = GetType().ToString(); // 自身の名前空間 LoggerSample.Models.SystemLogger
for (int i = 0; i < stackFrames.Length; i++)
{
stackFrame = stackFrames[i];
// Log を発生させたスタックフレームを探す
if (frameIndex < 0)
{
methodBase = stackFrame.GetMethod();
methodBaseFullName = methodBase.DeclaringType?.FullName ?? string.Empty;
if (methodBaseFullName.StartsWith(thisClassTypeFullName)) continue;
if (methodBaseFullName.StartsWith("Microsoft.Extensions.Logging.Logger")) continue;
if (methodBaseFullName.StartsWith("System.ThrowHelper")) continue;
methodBaseName = methodBase.Name;
// 対象フレームのインデックス
frameIndex = i;
}
// ファイル名
if (string.IsNullOrEmpty(fileName))
{
fileName = stackFrame.GetFileName();
}
// 行番号
if (lineNumber == null || lineNumber <= 0)
{
lineNumber = stackFrame.GetFileLineNumber();
}
if (!string.IsNullOrEmpty(fileName) && lineNumber > 0)
{
break;
}
// ファイル名、行番号は、対象フレームの次のフレームにあることがある
if (i > frameIndex)
{
break;
}
}
log.MethodFullName = methodBaseFullName;
log.MethodName = methodBaseName;
log.FileName = fileName ?? string.Empty;
log.LineNumber = lineNumber == null ? 0 : (int)lineNumber;
ピンポイントのメソッドベースを取るために、スタックトレースから、スタックフレームの配列を取得し、対象のフレームを探します。
ログを発したところ、もしくは例外が発生したところから、この Log メソッドに至るまでのスタックフレームは不要なので無視して飛ばします。これは continue が3つ並んでいるところです。フレームワーク内の名前空間の接頭句で判断しています。
無視して飛ばした次のフレームが、対象のスタックフレームなので、ここのメソッドベースから、名前空間とメソッド名を取ります。
ファイル名と行番号も、メソッドベースから取得できます。
ですが、特定のミドルウェアで取得できないものがあり、次のフレームにあったため、もう一度ループして取得を試みています。このために frameIndex 変数を使用しています。
スタックフレームの配列は、20以上、多いと100を超える場合もあります。対象目的のメソッドベースのスタックフレームは、大体5～6番目にあるので、無用なループを避けるためにも、深くまでループせずに取得できたら break で抜けます。
なお、フレームワーク内から発生したエラー（Microsoft.で始まる名前空間）や、デバッグ情報が無い状態(リリースビルド)では、メソッドベースの取得は出来ますが、ファイル名と行番号は取得できません。その場合にも早くループを抜けるために、frameIndex 変数と break が必要です。
ここまでで、ログの詳細が取得できました。
ログ内容として、スタックトレースの情報は Information で不要と思いますので削除します。削除するかは好みですがストレージのデータ量が無用に増えることになります。
また、スタックトレースがある場合の改行コードを統一しておきます。
if (log.LogLevel <= 2)
{
log.StackTrace = string.Empty;
}
log.StackTrace = log.StackTrace.Replace("\r\n", "\n").Replace("\n", "\r\n");
この後ログとして書き出しますが、Log メソッドは同期メソッドなので、ここでは次項のプールクラスの Add でログの配列に加えるだけにします。
SystemLogPool.Add(log);
ログのプールクラスとログの出力
ログデータをリスト(メモリ上)として、一時格納するプールクラスを用意します。
プールクラスと言うと大げさに聞こえますが、単にリストを用意して処理するだけのものです。リスト上にデータが残っている状態でPCがダウンしたらデータは失われます。堅牢にしようとすると処理時間コストが増えますが、処理を早くすることが目的のため妥協も必要です。
SystemLogPoolクラスを、SystemLogger.csに追加します。
public class SystemLogPool
{
private static readonly object Sync = new object();
// ログをプールするリスト
private static List _poolLogs = null;
private static List PoolLogs
{
get
{
if (_poolLogs == null)
{
_poolLogs = new List();
}
return _poolLogs;
}
}
public static void Add(SystemLog log)
{
lock (Sync)
{
PoolLogs.Add(log);
}
}
public static void Write()
{
lock (Sync)
{
if (PoolLogs.Count > 0)
{
// ログをコピー
List logs = PoolLogs.OrderBy(x => x.LogDate.Ticks).ToList();
// ログのプールをクリア
PoolLogs.Clear();
// ログの出力
WriteLog(logs);
}
}
}
private static void WriteLog(List logs)
{
// ここにログを出力するコードを入れる
//foreach (SystemLog log in logs)
//{
//}
}
}
ログのリストは、複数スレッドから同時処理されないように、空オブジェクト(Sync)を作成して lock で保護します。
static の Add メソッドでログデータを溜め込み、static の Write メソッドでログデータの出力、ログのリストもリリースします。
具体的に、ここはアプリケーションの要件になりますが、SQL Server のテーブルへ格納するものとします。
..のちに追加します
ログを処理させるBackgroundService
バックグラウンドで一定時間毎にログを処理させるための BackgroundService を作成します。
実行させる処理は、先の SystemLogPool.Write(); を呼ぶだけのものです。
SystemLogger.cs に、BackgroundWorker というクラスを以下のように追加します。
...
using System.Threading;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
namespace LoggerSample.Models
{
...
public class BackgroundWorker : BackgroundService
{
protected override async Task ExecuteAsync(CancellationToken stoppingToken)
{
while (!stoppingToken.IsCancellationRequested)
{
try
{
SystemLogPool.Write();
}
catch
{
}
await Task.Delay(10000);
}
}
}
}
次に、この BackgroundService をStartupクラスの ConfigureServicesメソッド内で登録します。
Startup.csに以下を追加。
...
using Microsoft.Extensions.Logging;
using LoggerSample.Models;
namespace LoggerSample
{
...
public class Startup
{
...
public void ConfigureServices(IServiceCollection services)
{
...
services.AddHostedService<BackgroundWorker>();
}
BackgroundWorker では、whileで条件的な無限ループをしてログの処理をします。例外が発生するとwhileループから抜けてしまうため、例外が発生しないようにします。
10秒のDeleyを掛けていますので、1分間に最大6回動くことになります。
アクセスが多いサイトなら短くしても良いと思いますが、どのくらいDeleyを掛けるかは運用状況次第で決めてください。
メール通知を纏めて行っている場合は、1日のメール送信の最大件数も計算できます。
1分間で6回、1時間だと360回, 24時間だと8640回です。
仮に、ずっとエラーが続いている場合、1日に8640件のメールが送信されることになります。SMTPサーバーに、1日の送信件数の上限がある場合は、Deleyを長くすることで調整できます。
このバックグラウンド処理は、ASP.NET Core アプリケーションが実行されるときに自動的に呼び出されます。サイトが稼働中は一定秒毎に処理が動くので定期的なバッチ処理のような振る舞いになります。
実際に Azure Web Apps とオンプレミスのIISで、この処理方法で数日連続稼働させていますが、ASP.NET Core のアプリケーションで、このログの処理が滞ったり動かなくなったりしたことはこれまでありません。
コメントする