Skip to content

システムログのエラーを外部に通知する ​

第2版作成 最終更新 (日本時間)
確認バージョン1.5.8.1

プリザンターには、システムログ(SysLogs)の異常を外部に知らせる機能はありません。テーブルの「通知」はサイトのレコード操作をきっかけに動くもので、システムログには使えません。 このページでは、SystemError(80)と Exception(90)を拾ってメールや Slack・Teams に送る方法を、プリザンター側の変更が要るかどうかで分けてまとめます。

方式プリザンター側の変更即時性向いている場面
NLog のターゲットを追加SysLog.json・appsettings.json・DLL の配置即時設定を変えてよい
DB トリガーなし即時(MySQL は遅延あり)本体に触れたくない
DB のポーリングなしポーリング間隔監視ツールがある
ログファイルの監視SysLog.json・appsettings.jsonほぼ即時ログ収集基盤がある
Azure のマネージドサービス方式による方式によるAzure 上で運用している

図を読み込み中…

システムログの書き込み方 ​

どの方式でも、次の性質が前提になります。

種別値NLog のレベル
Info10Info
Warning50Warn
UserError60Error
SystemError80Error
Exception90Fatal

(SysLogModel.cs)

  • リクエストごとに、開始時に Info の行を INSERT し、終了時(Finish)に同じ行を UPDATE します(SysLogModel.cs、SysLogModel.cs)。
  • 例外は new SysLogModel(context, e) で、種別を Exception にした別の行として INSERT されます。SystemError も、SAML・SendGrid・AI 連携・サーバースクリプトの logs.LogSystemError などから同じく別の行で書かれます(SysLogModel.cs)。したがって INSERT だけを見れば異常を拾えます。
  • DB への書き込みは SysLog.json の EnableLoggingToDatabase(既定 true)、NLog への出力は EnableLoggingToFile(既定 false)で切り替わります(SysLog.json)。
  • SysLogs の主キーは CreatedTime(降順)と SysLogId(IDENTITY)の複合で、SysLogType にインデックスはありません。CreatedTime は DB の既定値(now)で入ります(SysLogs_CreatedTime.json、SysLogs_SysLogId.json)。
  • 保存期間は SysLog.json の RetentionPeriod(既定 90 日)で、DeleteSysLogsTimer が古い行を削除します。

使う主な列は SysLogId・CreatedTime・SysLogType・Class(コントローラ)・Method(アクション)・Url・MachineName・ErrMessage・ErrStackTrace です。

NLog のターゲットを追加する ​

EnableLoggingToFile を true にすると、システムログが syslogs ロガーに流れます。ここに Slack やメールのターゲットを足す手順(DLL の配置、extensions、ルール)は ログ出力の拡張(NLog) を参照してください。異常だけを送るには、ルールで絞ります。

  • "minLevel": "Error" にすると UserError・SystemError・Exception が対象になります。UserError と SystemError は同じ Error なので、レベルでは区別できません。
  • UserError を外すには、syslog プロパティの SysLogType(int?。SysLogLogModel.cs)で when フィルタを掛けます。
json
{
    "logger": "syslogs",
    "minLevel": "Error",
    "writeTo": "slack",
    "filters": [
        {
            "type": "when",
            "condition": "'${event-properties:syslog:objectpath=SysLogType}' < '80'",
            "action": "Ignore"
        }
    ]
}
メール(NLog.MailKit)と Webhook(NLog.Targets.Http)のターゲット例
json
"extensions": [
    { "assembly": "NLog.MailKit" },
    { "assembly": "NLog.Targets.Http" }
],
"targets": {
    "alertMail": {
        "type": "Mail",
        "smtpServer": "${environment:SMTP_SERVER}",
        "smtpPort": 587,
        "smtpAuthentication": "Basic",
        "smtpUserName": "${environment:SMTP_USER}",
        "smtpPassword": "${environment:SMTP_PASSWORD}",
        "enableSsl": true,
        "from": "${environment:ALERT_FROM}",
        "to": "${environment:ALERT_TO}",
        "subject": "[Pleasanter Alert] ${level} - ${event-properties:syslog:objectpath=MachineName}",
        "body": "SysLogType: ${event-properties:syslog:objectpath=SysLogType}\nClass: ${event-properties:syslog:objectpath=Class}\nMethod: ${event-properties:syslog:objectpath=Method}\nUrl: ${event-properties:syslog:objectpath=Url}\nErrMessage: ${event-properties:syslog:objectpath=ErrMessage}\nErrStackTrace: ${event-properties:syslog:objectpath=ErrStackTrace}"
    },
    "alertSlack": {
        "type": "HTTP",
        "Url": "${environment:SLACK_WEBHOOK_URL}",
        "Method": "POST",
        "ContentType": "application/json",
        "BatchSize": 1,
        "Layout": {
            "type": "JsonLayout",
            "Attributes": [
                {
                    "name": "text",
                    "layout": "[${level:upperCase=true}] ${event-properties:syslog:objectpath=Class}.${event-properties:syslog:objectpath=Method}\n${event-properties:syslog:objectpath=ErrMessage}\nURL: ${event-properties:syslog:objectpath=Url}"
                }
            ]
        }
    }
}

writeTo を "alertMail,alertSlack" にすると両方に送れます。Teams に送るときは、Incoming Webhook ではなく Workflows の URL を使います(Teams 通知・Asana タスク連携 参照)。

注意点内容
全件が NLog に流れるEnableLoggingToFile を true にすると、Info を含むすべてのログが NLog に渡り、既定のルールで csvfile にも出力される
1 リクエストで 2 回開始時の WriteSysLog と終了時の UpdateSysLog の両方がログイベントになる。例外の行は WriteSysLog の 1 回
大量の通知エラーが続くと同じ数だけ送られる。NLog のラッパー(バッファリングなど)で頻度を抑える
秘密情報Webhook URL や SMTP のパスワードは ${environment:…} で環境変数から読み、設定ファイルに書かない
バージョンアップ追加した DLL と appsettings.json の変更は、バージョンアップのたびに入れ直す

DB トリガーで通知する ​

SysLogs への INSERT をトリガーで拾い、DB の機能で通知します。プリザンターの設定・コード・パッケージには触れません。EnableLoggingToDatabase が true(既定)であることが前提です。

RDBMS通知の手段常駐プロセス即時性
SQL ServerDatabase Mail(sp_send_dbmail)不要即時
PostgreSQLLISTEN / NOTIFY必要即時
MySQLキューテーブル + 定期実行必要遅延あり
SQL Server(Database Mail + トリガー)

Database Mail の有効化とプロファイル(ここでは PleasanterAlertProfile)の作成を済ませておきます。

sql
CREATE TRIGGER trg_SysLogs_Alert
ON SysLogs
AFTER INSERT
AS
BEGIN
    SET NOCOUNT ON;
    IF EXISTS (SELECT 1 FROM inserted WHERE SysLogType >= 80)
    BEGIN
        DECLARE @body NVARCHAR(MAX);
        SELECT TOP 1
            @body = CONCAT(
                N'SysLogType: ', CAST(SysLogType AS NVARCHAR(10)), NCHAR(13), NCHAR(10),
                N'Class: ', Class, NCHAR(13), NCHAR(10),
                N'Method: ', Method, NCHAR(13), NCHAR(10),
                N'ErrMessage: ', ErrMessage, NCHAR(13), NCHAR(10),
                N'Url: ', Url, NCHAR(13), NCHAR(10),
                N'MachineName: ', MachineName)
        FROM inserted
        WHERE SysLogType >= 80;

        EXEC msdb.dbo.sp_send_dbmail
            @profile_name = 'PleasanterAlertProfile',
            @recipients = 'admin@example.com',
            @subject = N'[Pleasanter] SysLog Alert',
            @body = @body;
    END
END;

sp_send_dbmail はキューに積むだけで、SMTP への送信は Database Mail のバックグラウンド処理が行います。SMTP の遅延で INSERT が待たされることはありません。

PostgreSQL(LISTEN / NOTIFY + 常駐プロセス)

pg_notify のペイロードは 8,000 バイトまでなので、ID だけを送り、受け取った側で詳細を読みます。

sql
CREATE OR REPLACE FUNCTION notify_syslog_alert()
RETURNS TRIGGER AS $$
BEGIN
    IF NEW."SysLogType" >= 80 THEN
        PERFORM pg_notify(
            'syslog_alert',
            json_build_object(
                'SysLogId', NEW."SysLogId",
                'SysLogType', NEW."SysLogType"
            )::text
        );
    END IF;
    RETURN NEW;
END;
$$ LANGUAGE plpgsql;

CREATE TRIGGER trg_syslog_alert
AFTER INSERT ON "SysLogs"
FOR EACH ROW
EXECUTE FUNCTION notify_syslog_alert();

通知はトランザクションのコミット時に配信されます。受け取る側の例(Python)です。

python
import json
import select

import psycopg2
import psycopg2.extensions
import requests

conn = psycopg2.connect("dbname=... user=... host=...")
conn.set_isolation_level(psycopg2.extensions.ISOLATION_LEVEL_AUTOCOMMIT)
cur = conn.cursor()
cur.execute("LISTEN syslog_alert;")

while True:
    if select.select([conn], [], [], 60) != ([], [], []):
        conn.poll()
        while conn.notifies:
            payload = json.loads(conn.notifies.pop(0).payload)
            cur.execute(
                'SELECT "Class", "Method", "ErrMessage", "Url" FROM "SysLogs" WHERE "SysLogId" = %s',
                (payload["SysLogId"],))
            row = cur.fetchone()
            requests.post(
                "https://hooks.slack.com/services/xxx",
                json={"text": json.dumps({"SysLogType": payload["SysLogType"], "detail": row}, ensure_ascii=False)})
MySQL(キューテーブル + 定期実行)

MySQL のトリガーからは外部に通知できないため、キューテーブルに積んで別プロセスが定期的に読みます。

sql
CREATE TABLE SysLogAlertQueue (
    QueueId BIGINT AUTO_INCREMENT PRIMARY KEY,
    SysLogId BIGINT NOT NULL,
    SysLogType INT NOT NULL,
    Class VARCHAR(256),
    Method VARCHAR(256),
    ErrMessage TEXT,
    Url TEXT,
    MachineName VARCHAR(256),
    CreatedAt DATETIME DEFAULT CURRENT_TIMESTAMP,
    Processed BOOLEAN DEFAULT FALSE
);

DELIMITER //
CREATE TRIGGER trg_syslog_alert
AFTER INSERT ON SysLogs
FOR EACH ROW
BEGIN
    IF NEW.SysLogType >= 80 THEN
        INSERT INTO SysLogAlertQueue (SysLogId, SysLogType, Class, Method, ErrMessage, Url, MachineName)
        VALUES (NEW.SysLogId, NEW.SysLogType, NEW.Class, NEW.Method, NEW.ErrMessage, NEW.Url, NEW.MachineName);
    END IF;
END //
DELIMITER ;

トリガーは INSERT と同じトランザクションで動く

トリガー内でエラーが起きると、システムログの INSERT ごと失敗する可能性があります。システムログはすべてのリクエストで書かれるため、トリガーの処理は軽く保ちます。テーブル定義が変わるバージョンアップでは、トリガーの見直しも要ります。

DB をポーリングする ​

Grafana・Zabbix などの監視ツールや cron のスクリプトから、SysLogs を定期的に読みます。プリザンターの設定は変えません。

SysLogType だけの条件はインデックスが無く全体を読むことになるため、主キーの先頭の CreatedTime で直近の範囲に絞ります。CreatedTime は DB の時計で入るので、比較の基準も DB 側の現在時刻を使います。

sql
-- SQL Server(直近 2 分)
SELECT SysLogId, SysLogType, Class, Method, ErrMessage, Url, MachineName, CreatedTime
FROM SysLogs
WHERE CreatedTime > DATEADD(MINUTE, -2, GETDATE())
  AND SysLogType >= 80
ORDER BY CreatedTime;
sql
-- PostgreSQL(直近 2 分)
SELECT "SysLogId", "SysLogType", "Class", "Method", "ErrMessage", "Url", "MachineName", "CreatedTime"
FROM "SysLogs"
WHERE "CreatedTime" > CURRENT_TIMESTAMP - INTERVAL '2 minutes'
  AND "SysLogType" >= 80
ORDER BY "CreatedTime";
sql
-- MySQL(直近 2 分)
SELECT SysLogId, SysLogType, Class, Method, ErrMessage, Url, MachineName, CreatedTime
FROM SysLogs
WHERE CreatedTime > CURRENT_TIMESTAMP(3) - INTERVAL 2 MINUTE
  AND SysLogType >= 80
ORDER BY CreatedTime;

範囲が重なる分の重複は、SysLogId を覚えておいて除きます。ポーリング間隔が長く読む行が多いときは、異常の行だけの部分インデックスを足すと軽くなります。

sql
-- SQL Server
CREATE NONCLUSTERED INDEX IX_SysLogs_Alert ON SysLogs (CreatedTime, SysLogType) WHERE SysLogType >= 80;
-- PostgreSQL
CREATE INDEX ix_syslogs_alert ON "SysLogs" ("CreatedTime") WHERE "SysLogType" >= 80;
-- MySQL(部分インデックスは無い)
CREATE INDEX ix_syslogs_alert ON SysLogs (CreatedTime, SysLogType);

読み取りだけなので、書き込みや DeleteSysLogsTimer の削除(90 日前より古い行)と競合しません。

ログファイルを監視する ​

Fluent Bit・Promtail・Filebeat・Vector などでログファイルを読み、SysLogType で絞って送ります。

EnableLoggingToFile を true にしても、既定のルールで syslogs が書き込むのは csvfile(logs/yyyy/MM/dd/syslogs.csv)だけです。JSON で読みたい場合は、jsonfile ターゲットへのルールを足します(ログ出力の拡張(NLog))。

ini
[INPUT]
    Name tail
    Path /app/logs/**/syslogs.json
    Parser json
    Tag  syslog

[FILTER]
    Name    grep
    Match   syslog
    Regex   SysLogType ^(80|90)$

[OUTPUT]
    Name  slack
    Match syslog
    Webhook https://hooks.slack.com/services/xxx

Azure で通知する ​

Azure App Service と Azure SQL Database(または Azure Database for PostgreSQL)で動かしている場合の選択肢です。

方式プリザンター側の変更使うサービス検知までの時間
NLog → Application Insights → アラートappsettings.json と DLLApplication Insights・Azure Monitor・アクショングループアラートの評価間隔(5 分など)
NLog → Event Hubs → Logic Apps / Functionsappsettings.json と DLLEvent Hubs・Logic Apps または Functions数秒〜30 秒程度
Logic Apps で DB をポーリングなしLogic Apps(SQL Server コネクタ)ポーリング間隔
Functions のタイマーで DB をポーリングなしAzure Functions(従量課金プラン可)タイマー間隔

Azure SQL の監査ログや診断ログからは、INSERT された行の SysLogType を取り出せないため、監査ログのアラートでは絞り込めません。プリザンター側を変えないなら、ポーリングのどちらかを使います。

Application Insights に送る ​

NLog のターゲット Microsoft.ApplicationInsights.NLogTarget を配置し、異常の行だけを送ります。contextProperties に SysLogType などを付けると、traces の customDimensions で絞れます。

json
"extensions": [{ "assembly": "Microsoft.ApplicationInsights.NLogTarget" }],
"targets": {
    "appInsights": {
        "type": "ApplicationInsightsTarget",
        "contextProperties": [
            { "name": "SysLogType", "layout": "${event-properties:syslog:objectpath=SysLogType}" },
            { "name": "Class", "layout": "${event-properties:syslog:objectpath=Class}" },
            { "name": "Method", "layout": "${event-properties:syslog:objectpath=Method}" },
            { "name": "ErrMessage", "layout": "${event-properties:syslog:objectpath=ErrMessage}" },
            { "name": "Url", "layout": "${event-properties:syslog:objectpath=Url}" },
            { "name": "MachineName", "layout": "${event-properties:syslog:objectpath=MachineName}" }
        ]
    }
}

ルールは NLog のターゲットを追加する と同じく minLevel: Error と when フィルタで絞ります。アラートのログクエリの例です。

kusto
traces
| where customDimensions.SysLogType in ("80", "90")
| project timestamp, message,
    SysLogType = tostring(customDimensions.SysLogType),
    Class = tostring(customDimensions.Class),
    Method = tostring(customDimensions.Method),
    ErrMessage = tostring(customDimensions.ErrMessage),
    Url = tostring(customDimensions.Url)

このクエリで「件数 > 0」のログ検索アラートを作り、アクショングループでメールや Webhook に送ります。

Functions のタイマーでポーリングする ​

プリザンターを変えずに済み、従量課金プランの無料枠に収まりやすい方式です。Functions のマネージド ID に SysLogs の SELECT 権限を付けて接続します。

Azure Functions(C#、isolated worker)の例
csharp
using System.Net.Http;
using System.Text;
using System.Text.Json;
using Microsoft.Azure.Functions.Worker;
using Microsoft.Data.SqlClient;
using Microsoft.Extensions.Logging;

public class SysLogPollingFunction
{
    private static readonly HttpClient _httpClient = new();
    private static long? _lastSysLogId;

    [Function("SysLogPolling")]
    public async Task Run(
        [TimerTrigger("0 */1 * * * *")] TimerInfo timer,
        FunctionContext context)
    {
        var logger = context.GetLogger("SysLogPolling");
        var webhookUrl = Environment.GetEnvironmentVariable("WEBHOOK_URL");
        using var conn = new SqlConnection(
            Environment.GetEnvironmentVariable("SqlConnectionString"));
        await conn.OpenAsync();
        if (_lastSysLogId == null)
        {
            // 初回(起動直後)は現在の最大 ID から始める
            using var init = new SqlCommand(
                "SELECT ISNULL(MAX(SysLogId), 0) FROM SysLogs", conn);
            _lastSysLogId = Convert.ToInt64(await init.ExecuteScalarAsync());
            return;
        }
        // CreatedTime で直近に絞り(主キーを使う)、SysLogId で送信済みを除く
        using var cmd = new SqlCommand(@"
            SELECT TOP 100 SysLogId, SysLogType, Class, Method, ErrMessage, Url, CreatedTime
            FROM SysLogs
            WHERE CreatedTime > DATEADD(MINUTE, -10, GETDATE())
              AND SysLogId > @LastId
              AND SysLogType >= 80
            ORDER BY SysLogId", conn);
        cmd.Parameters.AddWithValue("@LastId", _lastSysLogId.Value);
        using var reader = await cmd.ExecuteReaderAsync();
        while (await reader.ReadAsync())
        {
            _lastSysLogId = reader.GetInt64(0);
            var text = $"[Pleasanter] SysLogType={reader["SysLogType"]} "
                + $"{reader["Class"]}.{reader["Method"]}\n{reader["ErrMessage"]}\n{reader["Url"]}";
            await _httpClient.PostAsync(
                webhookUrl,
                new StringContent(
                    JsonSerializer.Serialize(new { text }),
                    Encoding.UTF8,
                    "application/json"));
        }
        logger.LogInformation("Last SysLogId: {Id}", _lastSysLogId);
    }
}

_lastSysLogId は関数のインスタンスが入れ替わると初期化され、その間の異常は送られません。取りこぼしを避けたい場合は、最後に送った ID を Table Storage などに保存します。

採らなかった方法 ​

方法理由
テーブルの「通知」を使う通知はサイトの設定に属し、レコードの作成・更新などをきっかけに動く。システムログの書き込みとは関係しない
サーバースクリプトの logslogs.LogSystemError などは自分でログを書く機能で、内部で起きた例外を拾う仕組みではない
ヘルスチェック(/healthz)DB 接続とウォームアップの状態を返す死活監視用で、ログの内容は見ない(HealthCheckExtensions.cs)
監視用のバックグラウンドサービスを本体に足す本体の改修になり、バージョンアップのたびに追従が要る

関連ページ ​

変更履歴

第2版システムログのポーリング SQL を3種類のDBMSに対応
第1版通知とリマインダーの書式・置き換わらない書き方・タイムゾーンの影響、システムログの外部通知の解説と、関連する改修・設計メモを追加