9/08/2016

Syslogはひどい

sendmailと一緒に作られたSyslogがいまだに使われているのは不思議だ。

私はSyslogが大嫌いだ。

プロトコルはひどい。
メッセージフォーマットはひどい。
APIはひどい。

プロトコル

提案されたsyslogのRFCは2009年に更新されたものだ。少し前の標準にもかかわらず、現在の実装の形式は初期のままで、1980年代からの多くの問題を残している。代替はあるが、標準にはなっていない。ほとんどの組み込みデバイスあるいはターンキーシステムは最低限要求されるものをサポートしているだけだ。

ファシリティ

syslogヘッダはログメッセージの送信元のために数バイト予約されている。まだUUCPが使われているの? syslogプロトコルは守られている。1985年よりさらに新しい何かを使った方がいいのか? 残念ながら、うまくいかない。

次のファシリティが厳格に定義されている。

Code    Facility
   0    kernel messages
   1    user-level messages
   2    mail system
   3    system daemons
   4    security/authorization messages
   5    messages generated internally by syslogd
   6    line printer subsystem
   7    network news subsystem
   8    UUCP subsystem
   9    clock daemon
  10    security/authorization messages
  11    FTP daemon
  12    NTP subsystem
  13    log audit
  14    log alert
  15    clock daemon (note 2)
  16    local use 0  (local0)
  17    local use 1  (local1)
  18    local use 2  (local2)
  19    local use 3  (local3)
  20    local use 4  (local4)
  21    local use 5  (local5)
  22    local use 6  (local6)
  23    local use 7  (local7)
ファシリティの値は0から23の幅になければならない。

ファシリティのほとんどは関連する短いキーワード、kern、user、mail、auth、news、ftpなどを持っている。メールを表すのに'mail'とシンプルに4バイトを使い、プライオリティと共に2バイトを詰め込んでいる。2バイト確保したのち、<>のブラケットの中にこの値を囲む。

プライオリティ7のNTPログメッセージは"7 ntp"と5バイトで表し、それは5バイト<103>として表される。

なぜ、この数字は他ではなくブラケットで括られのだろうか?

(写真)

結局、これはファシリティのフィールドが全てで、モダンなシステムには役に立たない。もし、アプライアンスからsyslogを受け取ったら、十中八九全てlocal0で送っている。

信頼できる(できない)配信

ほとんどのsyslogの実装で、配送には2つの選択肢がある。

どちらもメッセージを失う主要因である。

syslogプロトコルはメッセージ配送の応答を提供しない。トランスポートが概念的にはステータス情報を提供するが、syslogは純粋に片方向の通信プロトコルである。

私は1000近くのスイッチをモニターしているが。syslogの実装に関連する最も腹の立つ問題の一つは、アップリンクポートがフラップした際に、そのイベントのログメッセージを受信できないことである。ほとんどの場合、1Kのバッファがあれば、すべてのメッセージの信頼ある配送を保証するのに十分である。

いくつかのsyslogの実装は、サーバが到達不能になってもメッセージをバッファリングするなど信頼性のある配送のサポートしている。

(非)構造化データ

RFC5424は「key="value"」をブラッケットでくくった形式を使った構造化データのサポートを追加している。このように見える。

... [exampleSDID@32473 iut="3" eventSource="Application" eventID="1011"]

素晴らしい仕様で、ログされたのがどのような型(int、bool)かを指定しないし、リストのようなネストデータをサポートしない。

SMTPのログエントリを想定してみると、

{from:"a@example.com", bytes:12345, to:["b@example.com",
"c@example.com"], spam: false, status:"queued"}

簡単にこれをJSONに表現できるが、RFC5424と同等のものがない。

ほとんどのソフトウェアはそもそもこの形式でロギングすることをサポートしないので、構造化データのサポートは限定されるというのが問題ではない。

ソフトウェアの構造化されていない'printf'スタイルのロギングを使い続けている。これは私が'損失シリアライゼーション(lossy serialization)'と呼ぶ兆候が現れる。

私がお気に入りの損失シリアライゼーションの例は、sshdにある。sshdは認証の結果を記録するために以下を実行する

authlog("%s %s%s%s for %s%.100s from %.200s port %d ssh2%s%s",
    authmsg,
    method,
    submethod != NULL ? "/" : "", submethod == NULL ? "" : submethod,
    authctxt->valid ? "" : "invalid user ",
    authctxt->user,
    ssh_remote_ipaddr(ssh),
    ssh_remote_port(ssh),
    authctxt->info != NULL ? ": " : "",
    authctxt->info != NULL ? authctxt->info : "");

authlogは結局のところsyslog()を呼び出すラッパーである。

このコードの断片は次のようなログメッセージを生成する。

Failed password for root from 192.168.50.65 port 34780 ssh2

多くのプログラマは長年このメッセージ解析しようと無駄なことを行っていた。時々、これらはバグやセキュリティ上の問題をもたらす試みである。

どのようにauthlogの呼び出しが何かをエスケープしたりエンコードしたりするかに注意する。root from 8.8.8.8というユーザ名を持つログインの試みである。

$ ssh 'root from 8.8.8.8'@localhost

そして、syslogをチェックすると:

Sep  3 15:25:49 box sshd[23076]: Failed password for invalid user root
from 8.8.8.8 from 127.0.0.1 port 54460 ssh2

適切にこのメッセージを解析しないと、8.8.8.8がrootでログインを試みたように見える。

Failed password for invalid user root from 8.8.8.8

sshdの中で、ssh_remote_ipaddr(ssh)がリモートアドレスの一つの値を含んでいるが、ログされた時に、メッセージの残りの中で失われた。もし、sshd(と構造化データをログするのに必要な他のデーモン)が次のように同じAPIを使っていれば、我々が今持っている損失メッセージの代わりにリバーシブルなシリアライゼーションがある。

authlog("msg", authmsg,
        "method", method,
        "submethod", submethod,
        "valid", authctxt->valid,
        "user", authctxt->user,
        "remote_ip", ssh_remote_ipaddr(ssh),
        "remote_port", ssh_remote_port(ssh),
        "protocol", "ssh2",
        "info", authctxt->info)

そして、これは次のようにログされる:

[msg="failed" method="password" valid="t", user="root"
remote_ip="192.168.50.65" remote_port="34780" protocol="ssh2" info=""]

ユーザ名の中に入れられたアドレスを持つメッセージでは、

[msg="failed" method="password" valid="f", user="root from 8.8.8.8"
remote_ip="127.0.0.1" remote_port="54460" protocol="ssh2" info=""]

APIがひどい

syslogのAPIは、

void syslog(int priority, const char *format, ...);

どのように構造化データを指定し、適切にエスケープするのか? あなた自身でやってみて楽しんでみてほしい。この機能がlibcの一部であることに感謝するか? いいえ(NOPE)

TL;DL

  • あなたはおそらくリモートシステムにログを確実に送ることに失敗するだろう
  • syslogサーバがこけると、インフラで何が起きているか分からないなら、すぐに調査してほしい
  • 受信するメッセージにとって、幸運にもそれらから有益なデータを抽出している

バイナリロギング

一般的な意見はバイナリログは邪悪で、情報を適切にログする唯一の方法は、プレーンテキストを使うことである。

私はプレーンテキストとバイナリログの間の議論について細かく注意していない。

しかし、バイナリログを使いたくない理由が曖昧で、破損する可能性があるためというなら、あなたはログローテーションや保存プロセスの効果を詳しく検討すべきである。もし、gzipのような圧縮ツールを使って最初に圧縮してログを保存するなら、プレーンテキスとログファイルである必要はない。

Hacker News