syslogのRFC 3164とRFC 5424の違い|1桁日と年またぎでログが消えるパーサの話

Security

ログ基盤やSIEMにsyslogを集約すると、必ずどこかで「パースできない行」に出会います。原因のほとんどは、syslogに2つの異なる仕様が混在していることです。RFC 3164(2001年)とRFC 5424(2009年)で、タイムスタンプの形も、ヘッダのフィールド構成も違います。

やっかいなのは、RFC 5424が出た今もRFC 3164形式を吐く機器が現役で大量に動いていることです。ネットワーク機器やアプライアンスは特にそうです。この記事では両者の違いをRFCで確認したうえで、両方を扱うパーサを書き、実際に踏んだ3つのバグを残します。

RFC 3164は「標準」ではない

前提として押さえておきたいのが、RFC 3164の位置づけです。これはInformational(情報提供)であり、標準化された仕様ではありません。当時すでに実装されていたsyslogの挙動を観察して文書化したものです。タイトルも「The BSD syslog Protocol」です。

対してRFC 5424はStandards Track(標準化過程)で、こちらが正式なsyslogプロトコルです。ただし現実には、RFC 3164形式のほうが依然として多数派です。

この非対称性が実務では効いてきます。「RFC 5424に準拠していない機器がおかしい」ではなく、「両方来る前提で書く」しかありません。

2つの形式の違い

RFC 3164

<34>Oct 11 22:14:15 mymachine su: 'su root' failed for lonvick on /dev/pts/8
 └┬┘└──────┬──────┘ └───┬───┘ └──────────────┬──────────────────────┘
 PRI   TIMESTAMP      HOSTNAME                MSG

構造は<PRI>TIMESTAMP HOSTNAME MSGの3つだけです。メッセージ全体は1024バイト以下でなければならない、という制約もあります。

RFC 5424

<165>1 2026-08-28T22:14:15.003Z mymachine.example.com evntslog - ID47 [exampleSDID@32473 iut="3"] An application event
 └─┬┘│ └────────┬───────────┘ └─────────┬─────────┘ └───┬──┘ │  └┬─┘ └──────────────┬───────────┘ └────────┬────────┘
  PRI VER    TIMESTAMP              HOSTNAME          APP-NAME PROCID MSGID    STRUCTURED-DATA                 MSG

PRIの直後にバージョン番号1が入るのが最大の見分けどころです。フィールドが増え、タイムスタンプはRFC 3339形式(タイムゾーン付き)になり、構造化データを持てるようになりました。

PRIの読み方

PRIはFacilityとSeverityを1つの数値に畳んだものです。RFC 5424 6.2.1の定義はこうです。

PRIVAL = Facility × 8 + Severity

RFCが挙げている例で確かめます。kernel(Facility 0)のEmergency(Severity 0)はPRI 0。local use 4(Facility 20)のNotice(Severity 5)は20×8+5でPRI 165。手元の実装に通したところ、どちらも定義どおりに分解できました。

pri=0   → facility 0(期待0)  severity 0(期待0)  OK
pri=165 → facility 20(期待20) severity 5(期待5)  OK

パーサ

両形式を受けて正規化するスクリプトです。Python標準ライブラリだけで動きます。

#!/usr/bin/env python3
"""syslogparse.py - RFC 3164 / RFC 5424 のsyslog行を解析する

使い方:
    cat /var/log/messages | ./syslogparse.py
"""
import sys, re, datetime

# RFC 5424: <PRI>VERSION SP TIMESTAMP SP HOSTNAME SP APP-NAME SP PROCID SP MSGID SP [SD] SP MSG
RE_5424 = re.compile(
    r'^<(?P<pri>\d{1,3})>(?P<ver>\d{1,2}) '
    r'(?P<ts>\S+) (?P<host>\S+) (?P<app>\S+) (?P<procid>\S+) (?P<msgid>\S+)'
    r'(?: (?P<rest>.*))?$'
)

# RFC 3164: <PRI>Mmm d hh:mm:ss HOSTNAME MSG
# dd は1桁のとき空白埋め(RFC 3164 4.1.2)。\d{2} と書くと1桁日で全滅する
RE_3164 = re.compile(
    r'^<(?P<pri>\d{1,3})>'
    r'(?P<mon>[A-Z][a-z]{2}) {1,2}(?P<day>\d{1,2}) '
    r'(?P<h>\d{2}):(?P<mi>\d{2}):(?P<s>\d{2}) '
    r'(?P<host>\S+) (?P<msg>.*)$'
)

MONTHS = {m: i + 1 for i, m in enumerate(
    ['Jan', 'Feb', 'Mar', 'Apr', 'May', 'Jun',
     'Jul', 'Aug', 'Sep', 'Oct', 'Nov', 'Dec'])}

FACILITY = [
    'kern', 'user', 'mail', 'daemon', 'auth', 'syslog', 'lpr', 'news',
    'uucp', 'cron', 'authpriv', 'ftp', 'ntp', 'audit', 'alert', 'clock',
    'local0', 'local1', 'local2', 'local3', 'local4', 'local5', 'local6', 'local7',
]
SEVERITY = ['emerg', 'alert', 'crit', 'err', 'warning', 'notice', 'info', 'debug']


def decode_pri(pri):
    """PRIVAL = Facility * 8 + Severity(RFC 5424 6.2.1)

    Python3 の / は真の除算で小数になる。必ず // を使う
    """
    fac, sev = pri // 8, pri % 8
    return {
        'facility': fac,
        'facility_name': FACILITY[fac] if fac < len(FACILITY) else str(fac),
        'severity': sev,
        'severity_name': SEVERITY[sev],
    }


def resolve_year(mon, day, h, mi, s, now=None):
    """RFC 3164 のタイムスタンプには年が無いので補う

    素朴に「現在の年」を入れると、年またぎ直後に約1年先の未来になる。
    未来に大きくずれたら前年とみなす。
    """
    now = now or datetime.datetime.now()
    try:
        dt = datetime.datetime(now.year, MONTHS[mon], day, h, mi, s)
    except ValueError:
        # 2月29日を平年に当てはめた場合など
        return None
    if (dt - now).total_seconds() > 86400:
        try:
            dt = dt.replace(year=now.year - 1)
        except ValueError:
            return None
    return dt


def parse(line, now=None):
    line = line.rstrip('\n')

    m = RE_5424.match(line)
    if m and m.group('ver') == '1':
        d = m.groupdict()
        rest = d.get('rest') or ''
        sd, msg = split_sd(rest)
        out = {'format': 'RFC5424', 'timestamp': d['ts'],
               'host': nil(d['host']), 'app': nil(d['app']),
               'procid': nil(d['procid']), 'msgid': nil(d['msgid']),
               'sd': sd, 'msg': strip_bom(msg)}
        out.update(decode_pri(int(d['pri'])))
        return out

    m = RE_3164.match(line)
    if m:
        d = m.groupdict()
        dt = resolve_year(d['mon'], int(d['day']),
                          int(d['h']), int(d['mi']), int(d['s']), now)
        out = {'format': 'RFC3164',
               'timestamp': dt.isoformat() if dt else None,
               'host': d['host'], 'app': None, 'procid': None,
               'msgid': None, 'sd': None, 'msg': d['msg']}
        out.update(decode_pri(int(d['pri'])))
        return out

    return {'format': 'UNKNOWN', 'raw': line}


def nil(v):
    """NILVALUE の "-" は「値なし」を表す(RFC 5424 6.2)"""
    return None if v == '-' else v


def strip_bom(msg):
    """MSG が UTF-8 のときは先頭に BOM が付く(RFC 5424 6.4)"""
    if msg.startswith('\ufeff'):
        return msg[1:]
    if msg.startswith('BOM'):  # BOMをASCIIで書く実装への保険
        return msg[3:]
    return msg


def split_sd(rest):
    """構造化データ部とMSGを分ける。"-" なら構造化データなし"""
    if rest.startswith('-'):
        return None, rest[1:].lstrip(' ')
    if not rest.startswith('['):
        return None, rest
    # \] でエスケープされた ] は終端ではない(RFC 5424 6.3.3)
    i, depth, esc = 0, 0, False
    while i < len(rest):
        c = rest[i]
        if esc:
            esc = False
        elif c == '\\':
            esc = True
        elif c == '[':
            depth += 1
        elif c == ']':
            depth -= 1
            if depth == 0:
                return rest[:i + 1], rest[i + 1:].lstrip(' ')
        i += 1
    return rest, ''


def main():
    for line in sys.stdin:
        if not line.strip():
            continue
        r = parse(line)
        if r['format'] == 'UNKNOWN':
            print('UNKNOWN | %s' % r['raw'][:70])
            continue
        print('%s | %s.%s | %s | %s | %s' % (
            r['format'], r['facility_name'], r['severity_name'],
            r['timestamp'], r['host'] or '-', (r['msg'] or '')[:50]))
    return 0


if __name__ == '__main__':
    sys.exit(main())

書いてから気づいた実装上の注意

第1版を実サンプルに通して直した箇所が3つあります。

1. 日付を \d{2} と書くと1桁日で全滅する

これが最も引っかかりやすい罠でした。RFC 3164のタイムスタンプはMmm dd hh:mm:ssですが、日が1桁のときゼロ埋めではなく空白埋めになります。RFC 3164 4.1.2は、8月7日はAug 7のように「gと7の間にスペースが2つ入る」と明記しています。

素朴に(\w{3} \d{2} \d{2}:\d{2}:\d{2})と書いた第1版に、実際のログ3行を通した結果です。

OK   | <34>Oct 11 22:14:15 mymachine su: 'su root' failed
FAIL | <13>Aug  7 09:05:01 web01 CROND[1234]: (root) CMD
FAIL | <165>Feb  3 04:02:00 fw01 %ASA-6-302013: Built inbound

2桁日だけが通り、1桁日は落ちました。毎月1日から9日までのログだけが消えるパーサができあがります。月初にログが少ないことに気づくまで発覚しません。{1,2}で空白の数を許容する必要があります。

2. 年が無いので、年またぎで約1年ずれる

RFC 3164のタイムスタンプには年もタイムゾーンも入っていません。受信側が補うしかないのですが、素朴に「現在の年」を入れると年またぎの直後に破綻します。

受信時刻が2027年1月1日0時0分30秒、ログが12月31日23時59分58秒(32秒前のログ)というケースを通しました。

受信時刻      : 2027-01-01T00:00:30Z
ログ(Dec 31)  : 年が無い
現在年を補うと: 2027-12-31T23:59:58Z  → 未来に365日ずれる
補正版        : 2026-12-31T23:59:58Z  → 差 32秒(正しい)

32秒前のログが約1年後の未来として記録されます。時系列でソートすると末尾に飛び、期間で絞り込む検索からは消えます。大晦日から元日にかけての障害調査で、まさにそのログが見つからないという形で顕在化します。

対処は、補った結果が未来に大きくずれたら前年とみなすことです。上のスクリプトでは1日以上未来なら前年に倒しています。うるう日(2月29日)を平年に当てはめるとValueErrorになるので、そこも握っておく必要があります。

そもそもタイムゾーンが無いため、機器のローカル時刻と受信側の時刻がずれていると補正のしようがありません。可能ならRFC 5424形式で送るよう機器側を設定するのが本筋です。

3. facilityの除算で小数になる

PRIからFacilityを求めるとき、pri / 8と書くとPython 3では真の除算になり小数が返ります。

pri=13 のとき
  13 / 8  → 1.625   ← 配列の添字に使えない
  13 // 8 → 1       (user)
  13 % 8  → 5       (notice)

Python 2の感覚で書くと踏みます。facility名の配列を引く段階でTypeErrorになるので即座に気づけますが、数値のまま保存していると「facility 1.625」のような値がそのままログ基盤に入ります。

RFC 5424側の細かい注意

  • NILVALUE… 値が無いフィールドは-で埋まります。文字列の"-"として扱うとホスト名が-のログが量産されるので、Noneに正規化します
  • MSGのBOM… RFC 5424 6.4は、MSGの文字セットはUNICODEであるべき(SHOULD)としており、UTF-8の場合は先頭にBOMが付きます。剥がさないとメッセージ先頭に見えない文字が残り、完全一致の検索が当たりません
  • 構造化データの]… 構造化データ部のパラメータ値に含まれる]\]とエスケープされます。単純に最初の]で切ると途中で切れます。上のスクリプトではエスケープを見ながら対応する括弧を探しています
  • バージョン番号… PRI直後の数字が1であることを確認してから5424として扱います。これを省くとRFC 3164のメッセージを誤判定する可能性があります

実務での方針

  • 送信側をRFC 5424に寄せられるなら寄せる。年もタイムゾーンも入るので、受信側の推測が不要になります。rsyslogやsyslog-ngはテンプレート指定で出力形式を変えられます
  • 変えられない機器は、受信側で受信時刻も一緒に記録する。機器の時刻が狂っていても、受信時刻があれば順序は復元できます
  • パーサのテストに1桁日と年またぎを必ず入れる。この2つは通常のテストデータでは再現しません
  • UDPで送っている場合は欠損を前提にする。「ログが無い=事象が無い」とは言えません

まとめ

  • syslogにはRFC 3164(Informational・BSD慣習の記述)とRFC 5424(Standards Track)が混在する。両方来る前提で書く
  • PRIVAL = Facility × 8 + Severity。Python 3では//を使う
  • RFC 3164の日は空白埋め\d{2}だと毎月1〜9日のログが消える
  • RFC 3164には年もタイムゾーンも無い。素朴に現在年を入れると年またぎで約1年ずれる
  • RFC 5424はNILVALUE(-)、MSGのBOM、構造化データ内のエスケープされた]に注意

参考:RFC 3164(The BSD syslog Protocol)4.1.1〜4.1.2、RFC 5424(The Syslog Protocol)6.2〜6.4

関連記事

タイトルとURLをコピーしました