ASP.NET Core~SerilogからSeqでロギングしてslackに通知する

数年前から「プレインテキストログ派」vs「構造化ログ派」戦争が起こっているとかいないとか・・・
そんな私が関わるプロジェクトの多くは、やはり大抵log4netマンセーであります。

現在のアプリケーションにおいてロギングは当然のごとく実装すべきものであり、請負で開発するシステムにおいても不特定多数の顧客をターゲットとしたクラウド型アプリケーションでも必ず実装が必須とされます。

そこで今回は ASP.NET Core のロギングに注目したいと思います。単純なファイル出力ログではつまらないので、Serilog / Seq / Slackを絡めてみます(なので、やっていること自体は「初級」なのですが、話がややこしいかも・・・)。

「守りのロギング」から「攻めのログ解析」へ

ロギングは何のために行っているのか?

  • 運用環境において問題が発生した際の原因追及の為(出力されたエラーメッセージやスタックトレースを手掛かりに何が起きたのかを解析する情報とする)
  • 開発時のデバッグ情報を取得する為(特にサブシステム間を別チームで開発し、ソースではなくコンパイルモジュールの連携で開発する際などに有効)
  • RFPにロギングするように書いてあるから。上司が実装しろと言うから(笑。実際ありそうだし)

上記2つは立派な理由であり有益な実装目的です。しかしログにはビジネス的にもっと重要な情報が眠っているはずです。そして、活きたログ出力をアーキテクチャとして組み込むことができるはずです。
簡単な話でいえば以下のようなことが考えられます。

  • ユーザーから報告は上がらなかったがワーニングやエラーが実は発生している
  • DBの巨大化等により実行パフォーマンスが実は低下しつつあった
  • ユーザーの行動分析の有益な情報として活用(どの機能が頻繁に使われているのか?どの機能が使用されない、不要と思われる機能なのか)

上記は、一定の閾値までは、実運用に入っても潜在的顧客満足度の低下であり、明示的な報告・苦情として現れない事柄です。
開発・運用側は認識をしないまま(そして手を打たないまま)、知らず知らずのうちに「顧客のシステムへの満足度の低下」が発生してしまいます。
そう、「顧客から報告・苦情があったから、ログを見て調査して修正する」ではなく、運用・開発側は能動的にログ解析を行い、問題発生の予兆をキャッチし、求められるものを解析し、しかもそれらは自動的に行われる。そんな攻めのログ解析が、旧来のロギングに対する次なるステップとされるでしょう。

で本題は・・・

まえおきはこれくらいにして・・・
今回は、以下のようなことを行ってみようと思います。

  1. ASP.NET Coreアプリケーションを実装
  2. Serilogを使用してログ出力を実装(ログの出力先はSeq)
     以下をロギングします。
     ・レスポンス速度が5s以上かかるリクエストに対するワーニング
     ・例外発生時のエラー
  3. Seqでフィルターを利用し、通知を投げるべき事象が発生したらSlackに通知を投げる

まえおきで偉そうなことを言いましたが、本投稿は能動的ロギングを行うためのツールを使った初歩の内容になります。

Serilog

Serilog(https://serilog.net/)は構造化ログ(Structured event)に対応したロギングライブラリです。いち早くASP.NET Coreへの対応もなされています。

Seq

Seq(https://getseq.net/)はログデータの集積・分析を行うシステムです。ログの表示、フィルター、ダッシュボードへの視覚的表示、plug-inを使用する事によりメールやSlackへの通知機能等を実現します。

Slack

みんな大好き(?)Slackです。

A messaging app for teams who are changing the world!!

だそうです。

ASP.NET Coreのロギング

ASP.NET Coreではロギング機能をビルドインで提供しています。ただし、機能的には必要最低限であり、イベントログへの出力やローリングファイルへの出力等への対応は不完全です。System.Diagnostics.TraceSourceを使用したロギングには対応していますが、この場合「Coreランタイム」ではなく「フルセットの.NET Frameworkランタイム」の使用が前提となります。
一方、ASP.NET Coreのロギングは「ロギングプロバイダー」を登録するプラガブルな仕組みを採用しているため、OSSのロギングツール、サードパーティロギングツール、自前ロギングツールへの差し替えが容易に可能です。
そこで、今回はSerilogを使用する事とします。

実装手順

では実装を行っていきたいと思います。

事前準備

SerilogはVisual Studio 2015上のNugetから取得しますので事前準備はありません。
Seq(https://getseq.net/)をダウンロードしてインストールしておきましょう。このツール、実は有償なのでトライアル版になります。
Seqのインストールはインストーラのデフォルト設定を行うことを想定します。特に設定があるとすればサービスをホストするURL(ポート)ですが、以下のデフォルト設定を想定します。

f:id:daigo-knowlbo:20160721002343p:plain

通知を受け取るためのSlackアカウントも用意しておきましょう。

プロジェクトの作成

VS2015を起動し「ASP.NET Core Application」を作成します(ここではプロジェクト名はAspNetCoreLoggingとしました)。

依存ライブラリを追加(project.json

project.jsonに必要なライブラリ参照を追加します。本サンプルではセッション機能を使用するのでSessionライブラリ、それからSerilog関連ライブラリ3つを追加しています(GUIを使ったNugetから追加してもOK)。
また、Serilog.Sinks.SeqはSerilogからSeqにSinkするためのライブラリです。

以下はproject.jsonのDependenciesの抜粋。

...省略...
  "dependencies": {
    "Microsoft.NETCore.App": {
      "version": "1.0.0",
      "type": "platform"
    },
    "Microsoft.AspNetCore.Diagnostics": "1.0.0",
    "Microsoft.AspNetCore.Mvc": "1.0.0",
    "Microsoft.AspNetCore.Razor.Tools": {
      "version": "1.0.0-preview2-final",
      "type": "build"
    },
    "Microsoft.AspNetCore.Server.IISIntegration": "1.0.0",
    "Microsoft.AspNetCore.Server.Kestrel": "1.0.0",
    "Microsoft.AspNetCore.StaticFiles": "1.0.0",
    "Microsoft.AspNetCore.Session": "1.0.0",
    "Microsoft.Extensions.Configuration.EnvironmentVariables": "1.0.0",
    "Microsoft.Extensions.Configuration.Json": "1.0.0",
    "Microsoft.Extensions.Logging": "1.0.0",
    "Microsoft.Extensions.Logging.Console": "1.0.0",
    "Microsoft.Extensions.Logging.Debug": "1.0.0",
    "Microsoft.Extensions.Options.ConfigurationExtensions": "1.0.0",
    "Microsoft.VisualStudio.Web.BrowserLink.Loader": "14.0.0",
    "Serilog": "2.1.0-dev-00670",
    "Serilog.Extensions.Logging": "1.1.0-dev-10116",
    "Serilog.Sinks.Seq": "3.0.0-dev-00069"
  },
...省略...

パフォーマンスログフィルターの実装

各リクエスト(コントローラアクション)に対して処理に要した時間を測定し、5秒以上要するものをwarnningとしてログ出力します。
その処理時間測定方法としてActionFilterを使用します。ActionFilterはすべてのリクエスト処理(コントローラアクション)の開始と終了のタイミングでのイベントハンドリングを可能にします。
まず、コンストラクタ「public PerformanceLogFilter(ILoggerFactory loggerFactory)」でILoggerFactoryを受け取ります。ASP.NET Coreの機能により引数として定義したILoggerFactory型オブジェクトが、DIによってコンストラクタ インジェクションされます。
アクションの開始時(OnActionExecuting)にDateTime.Nowを取得し、アクション終了時(OnResultExecuted)に所要時間を計測します。
5000ms以上かかった場合には「_logger.LogWarning()」によりワーニングログを出力しています。その際にイベントIDは1000という数値を割り当て、イベント名称はPerformanceAlertとしています。加えてセッションからLoginEmployeeというキーに保存されたEmployee情報を取得しています。これはパフォーマンス悪化ログ出力の際の付加情報としてセッションに保存されたログインユーザー情報を出力する想定を行っています。

using System;
using Microsoft.AspNetCore.Mvc.Filters;
using Microsoft.Extensions.Logging;
using Microsoft.AspNetCore.Http;
using Newtonsoft.Json;

namespace AspNetCoreLogging.Filters
{
  public class PerformanceLogFilter : ActionFilterAttribute
  {
    private readonly ILogger _logger;
    private DateTime _start;

    public PerformanceLogFilter(ILoggerFactory loggerFactory)
    {
      _logger = loggerFactory.CreateLogger("PerformanceLogFilter");
    }

    public override void OnActionExecuting(ActionExecutingContext context)
    {
      this._start = DateTime.Now;

      base.OnActionExecuting(context);
    }

    public override void OnActionExecuted(ActionExecutedContext context)
    {
      base.OnActionExecuted(context);
    }

    public override void OnResultExecuting(ResultExecutingContext context)
    {
      base.OnResultExecuting(context);
    }

    public override void OnResultExecuted(ResultExecutedContext context)
    {
      TimeSpan ts = DateTime.Now - this._start;
      if (ts.TotalMilliseconds > 5000)
      {
        EventId eventId = new EventId(1000, "PerformanceAlert");
        var emp = JsonConvert.DeserializeObject<Models.Employee>(context.HttpContext.Session.GetString("LoginEmployee"));
        this._logger.LogWarning(eventId, "{@emp}", emp);
      }

      base.OnResultExecuted(context);
    }
  }
}

例外フィルターの実装

コントローラアクション実行時に発生した例外を一元キャッチするための例外フィルターをアクションフィルターとして実装します。
前述のPerformanceLogFilterと同じくActionFilterAttributeから継承したクラスを実装しますが、例外フィルターであるためIExceptionFilterもインプリメントします。
コンストラクタインジェクションでILoggerFactoryオブジェクトを受け取ります。
コントローラアクション実行時の例外発生時には「OnException(ExceptionContext context)」が呼び出されるので、「_logger.LogError()」によりエラーログ出力を行います。本実装では冷害に対してユニークなGUIDを割り振りログ出力しています。
「context.ExceptionHandled = true;」とすることで、例外に対する処理を行った旨を示します。これによりASP.NET Core側での例外画面の表示等を抑制することが出来ます。さらにRedirect()によりアプリケーション独自のエラー画面にリダイレクトしています。

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

namespace AspNetCoreLogging.Filters
{
  public class MyExceptionFilter : ActionFilterAttribute, IExceptionFilter
  {
    private readonly ILogger _logger;

    public MyExceptionFilter(ILoggerFactory loggerFactory)
    {
      _logger = loggerFactory.CreateLogger("Unhandled Exception");
    }

    public void OnException(ExceptionContext context)
    {
      Guid errorCode = Guid.NewGuid();
      _logger.LogError("guid: {errorCode}, exception:{@Exception}", errorCode, context.Exception);

      context.ExceptionHandled = true;
      context.HttpContext.Response.Redirect("/Home/Error/" + errorCode.ToString());
    }
  }
}

MVCコントローラとビューの実装

コントローラとビューは本サンプルの主題ではありませんが、コントローラのアクション処理におけるパフォーマンス測定・例外発生をアクションフィルターでハンドルします。以下の3つのアクションメソッドを実装します。

  • PerformanceProblem() → 5000ms以上を要するパフォーマンスワーニングを発生させるアクション
  • OccurException() → 必ず例外が発生するアクション
  • Error() → OccurException()後のエラー情報を表示するアクション

Index()では強制的にセッションにLoginEmployeeをいうキーで、Employeeオブジェクトを設定しています。これはサンプルとして、ログイン情報を強制的にセッションに差し込んでいる処理です。Performanceログ出力時に、このデータも合わせてログ出力しています。また、Serilogを使用していることでオブジェクトを自動的にJSON形式の構造化ログとして出力するサンプルとしての意味も持っています。

using Microsoft.AspNetCore.Mvc;
using AspNetCoreLogging.Models;
using AspNetCoreLogging.Filters;
using Newtonsoft.Json;

namespace AspNetCoreLogging.Controllers
{
  [ServiceFilter(typeof(PerformanceLogFilter))]
  public class HomeController : Controller
  {
    public IActionResult Index()
    {
      this.Request.HttpContext.Session.Set(
        "LoginEmployee",
        System.Text.Encoding.UTF8.GetBytes(JsonConvert.SerializeObject(new Employee() { FirstName = "Ryuichi", LastName = "Daigo" })));

      return View();
    }

    // 処理の5000ms以上を要するアクション
    public IActionResult PerformanceProblem()
    {
      System.Threading.Thread.Sleep(5000);

      return View();
    }

    // 例外が発生するアクション
    public IActionResult OccurException()
    {
      int.Parse("hello");

      return View();
    }

    // エラー情報を表示するアクション
    public IActionResult Error(string id)
    {
      this.ViewBag.ErrorCode = id;
      return View();
    }
  }
}

上記アクションに対するビュー定義は以下の通りです。

index.cshtmlの定義

<html>
  <body>
    <a href="/Home/PerformanceProblem/">performance problem page</a>
    <br />
    <a href="/Home/OccurException/">occur exception page</a>
  </body>
</html>

erro.cshtmlの定義

エラーコード:@ViewBag.ErrorCode

ログインユーザー情報としてセッションに保存されるEmployeeモデルクラス定義は以下の通り。

namespace AspNetCoreLogging.Models
{
  public class Employee
  {
    public string FirstName { get; set; }
    public string LastName { get; set; }
  }
}

Startupクラスで各種設定を初期化

Startupクラスの定義を以下に示します。

using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;

using Serilog;

using AspNetCoreLogging.Filters;

namespace AspNetCoreLogging
{
  public class Startup
  {
    public IConfigurationRoot Configuration { get; }

    public Startup(IHostingEnvironment env)
    {
      var builder = new ConfigurationBuilder()
        .SetBasePath(env.ContentRootPath)
        .AddJsonFile("appsettings.json", optional: true, reloadOnChange: true)
        .AddJsonFile($"appsettings.{env.EnvironmentName}.json", optional: true)
        .AddEnvironmentVariables();
      Configuration = builder.Build();

      // ロガーを作成。出力先はSeq。レベルは警告以上。
      Log.Logger = new LoggerConfiguration()
          //.MinimumLevel.Information()
          .MinimumLevel.Warning()
          .Enrich.FromLogContext()
          .WriteTo.Seq("http://localhost:5341")
          .CreateLogger();
    }

    
    // This method gets called by the runtime. Use this method to add services to the container.
    public void ConfigureServices(IServiceCollection services)
    {
      // Session機能を使用することをDIに宣言します。
      services.AddSession();

      // すべてのリクエストをフィルタするアクションフィルターを登録します。
      services.AddScoped<PerformanceLogFilter>();

      // Add framework services.
      services.AddMvc(options =>
      {
        // 処理中に例外が発生したらハンドルするグローバルなフィルターを登録します。
        options.Filters.Add(typeof(MyExceptionFilter));
      });
    }

    // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
    public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
    {
      // Session機能を使用します。
      app.UseSession();

      // ログファクトリにSerilogを追加します。
      loggerFactory.AddSerilog();

      app.UseMvc(routes =>
      {
        routes.MapRoute(
          name: "default",
          template: "{controller=Home}/{action=Index}/{id?}");
      });
    }
  }
}

コンストラクタでは、Loggerの初期化を行っています。警告レベルはwarnnig、Seqへの出力設定、を行っています。

ConfigureServices()では、セッションを使用する為のDIに対する宣言を行います。また、PerformanceLogFilter、MyExceptionFilterの宣言も登録します。

Configure()では、セッションを使用する事の宣言、フォグファクトリーヘのSerilogの登録を行います。

以上で、アプリケーション側の準備が整いました。ここまでで、ASP.NET Coreアプリの動作、及びパフォーマンス問題発生時のSeqへのwarnningログ出力、例外発生時のSeqへのログ出力が行われるところまで実装されました。

続いてSlack及びSeq側の通知に関する連携設定を行います。

Slackのアプリケーション連携設定

SlackがSeqからの通知を受け取れるように設定を行います。
Slackにログインし左上のアカウントクリック→ポップアップされたメニューから「Apps & Integrations」を選択します。

f:id:daigo-knowlbo:20160721002531p:plain

左上の「Build」を選択します。

f:id:daigo-knowlbo:20160721002643p:plain

右側の「Somthing just for my team」を選択します。

f:id:daigo-knowlbo:20160721002727p:plain

検索ボックスから「Inco・・・」と入力するとサジェストが効き「Incoming WebHooks」が表示されるので、これを選択します。更に「Add Configuration」を選択します。

f:id:daigo-knowlbo:20160721003023p:plain

Post to Channelとして、ここでは個人のアカウントを選択し、「Add Incoming WebHooks Integration」ボタンをクリックします。

f:id:daigo-knowlbo:20160721003255p:plain

「Webhook URL」が発行されますので、このURLをSeq側に設定するためにクリップボード等にコピーしておきましょう。

f:id:daigo-knowlbo:20160721003403p:plain

SeqにSlack連携アプリを登録

Seqポータルを開きます(http://localhost:5314/)。右上の「settings」を選択します。

f:id:daigo-knowlbo:20160721014358p:plain

「APPS」→「INSTALL FROM NUGET」を選択します。

f:id:daigo-knowlbo:20160721014437p:plain

「Package id」に「Seq.App.Slack」を入力し「INSTALL」ボタンをクリックします。

f:id:daigo-knowlbo:20160721014458p:plain

以上で、Seqに対するSlack連携のアプリケーションインストールが完了しました。

SeqにSignal(フィルタ)の登録とSlackへの通知設定の登録

Seqには特定条件におけるSignalの設定を行うことができます。更にSignalが発生した(Signalの条件として設定したログが登録された)際にメール通知やSlackへの通知といったアクションを結びつけることができます。ここではSlackへの通知機能を利用します。
Seqをブラウザから起動します(http://localhost:5341/)。右上の「events」を選択し、「Create or add a signal...」を選択します。

f:id:daigo-knowlbo:20160721005131p:plain

名称を「Preformance Alert」として「New」を選択します。

f:id:daigo-knowlbo:20160721005220p:plain

f:id:daigo-knowlbo:20160721005230p:plain

Signalの条件として「EventId.Id == 1000」を入力して「>>」ボタンをクリックします。前述のPerformanceLogFilterクラスの実装において5秒以上を要した処理のワーニング時のイベントIDは固定で1000としているためです。

f:id:daigo-knowlbo:20160721005323p:plain

「Performance Alert」Signalに対して条件の設定が完了しました。ディスクボタンをクリックして設定を保存します。

f:id:daigo-knowlbo:20160721005544p:plain

次にSignalとSlackへの通知処理を関連付けます。
右上から「settings」を選択し、「APPS」→Slack NOTIFIERの「Start new instance」を選択します。

f:id:daigo-knowlbo:20160721005644p:plain

「Title」は Performance Alert to Slack とします。「Only trigger the app manually」のチェックを外し、「Signal」は「Performance Alert」とします。また、「WebHookUrl」には、先程Slack側のWebHookを設定した際に発行されたURLを設定します。この設定により、Seqに登録したログのうち、対象Signal条件に合致するログであったら、自動で指定されたWebHook URLに通知される(つまりSlackへの通知がなされる)、ということになります。そしてSlack側では、対象Web Hookへの通知はPrivateなryuichi111stdへの通知とする、という設定がなされています。

f:id:daigo-knowlbo:20160721005810p:plain

f:id:daigo-knowlbo:20160721010152p:plain

動かしてみる

では実際に、作成したASP.NET Coreアプリを実行します(http://localhost:24140/Home/)。
リンクが2つ表示されますが、上のリンクが「必ず5秒以上を要する、パフォーマンスアラートログを出力するページ」、下のリンクが「必ず例外を発生させるページ」です。
上のリンクをクリックしてみましょう。5秒経過の後、画面が表示され、Seqにログが出力されます。さらに自動でSlackへの通知がなされます。

f:id:daigo-knowlbo:20160721010242p:plain

Seqに出力されたログ
f:id:daigo-knowlbo:20160721010629p:plain

Slackへの通知
f:id:daigo-knowlbo:20160721010700p:plain

長々と説明してきましたが、これで「ASP.NET Core → Serilog → Seq → Slack」というロギングから通知を自動化するという目的が達成されました。この実装はあくまでもサンプルであり、実運用で利用する際にはもっと抽象化すべきコード等ありますが、何かしらのヒントになればと思い、この投稿を行いました。

皆様の手掛けるシステムが「より良いアーキテクチャ」「より興奮するアーキテクチャ」を実装されますように(^^)。

ソースはこちら「https://github.com/ryuichi111std/AspNetCoreLogging