新規作成 | 編集(管理者用) | 差分 | 検索 | tnetio | 一覧 | 更新履歴 | RSS SourceForge.jp

99syslog - syslog() 及び syslogd の考察(最終更新:2003/5/30)

ここでは、私が、Linux システムで使われている syslogd(sysklogd-1.4.1) の ソースを解析して分かった事について述べます。

syslogd は、標準ではログメッセージを記録する度に fsync() します。

syslogd は、syslog() を通じてやったきたログメッセージを、ファイルに 記録する度に fsync() します。

 

これはこれで、一見、ちゃんとした実装に見えます。ログメッセージを受け 取り、ログファイルに書く度に fsync() しますので、ディスクへの書込みが 確実となり、不意に電断が発生しても、ファイルシステムの整合性はともかく、 syslogd は、出来るだけ電断前の記録を残すのですから。

 

しかし、「ログメッセージをファイルに書く度に fsync() する」と言う事は、 裏を返すと、「ログメッセージが大量に発生すると、fsync() も大量に呼び出される」、 すなわち、ログメッセージが大量に発生すると、syslogd のレスポンスが低下する事を 意味します。

 

私は試しに、100個 fork() して、それぞれのプロセスで 10行 syslog() する プログラムを作成し、実行させてみました。これは、中規模のMLシステムを 運営していると、sendmail や postfix で、この程度のログが残ると推測してです。

 

上のプログラムを走らせると、確かに、syslogd の能力は著しく低下しました。 理由は単純で、100個 fork() して、10行 syslog() ですから、合計1000回の ログメッセージが発生し、その度に fsync() されるのですから。

 

なお、D. J. Bernstein さん作の daemontools に含まれる multilog は、ログ ファイル(current)に書く度に fsync() しません。

syslogd の能力低下は、システム全体の能力低下に繋がります。

syslogd が、標準ではログメッセージを書く度に fsync() しており、その結果 大量のログメッセージが発生すると、syslogd の能力低下に繋がる事が分かり ました。

 

では、syslogd の能力が低下すると、どの様な事が考えられるでしょうか?

 

syslogd が記録を残すメカニズムは、Linux の場合、以下のメカニズムで記録 されます。

      プロセス                          syslogd
  +---------------+                +---------------+
  |       :       |                |       :       |
  | syslog() 呼出 | → /dev/log → |  受信(recv()) |
  |       :       |                |       :       |
  +---------------+                +---------------+

syslogd を通じて、ログメッセージを記録させたいプロセスは、syslog() を 呼出し、記録させます。

 

呼び出された syslog() は、内部で /dev/log と言う名前の「UNIX ドメインソケット」 に接続し、メッセージを書き込みます。

 

syslogd は、/dev/log に渡ってきたメッセージを受信し、ログファイルに 記録します。

 

従って、syslogd の能力が低下すると言う事は、/dev/log からの受信が遅くなると 言う事であり、もし、大量のログメッセージが発生した場合、最悪、/dev/log の カーネル内バッファが一杯になる場合があります。

 

もし、/dev/log のバッファが一杯の状態で、syslog() を呼び出した場合、syslogd が /dev/log からデータを抜き取り、バッファに空きが出来るまで、 *呼び出したプロセス側が待たされる事になります*

 

従って、syslogd の能力が低下する事は、システム全体の能力が低下している事を 意味し、最悪、この状態に陥ると、その間はログインすら出来ない(ログイン記録を syslog() を通じてログに残すが、その syslog() が待たされるのでログインが完了しない)状態に陥る場合があります。

syslogd の能力低下を防ぐには

syslogd の能力低下を防ぐには、syslog.conf で、記録するログファイルを指定しますが、例えば /usr/adm/messages への書き込みに、fsync() を使用したくない場合は、

 *.=info;*.=notice                               -/usr/adm/messages

上記の様に記録したいログファイル名の直前に '-' を付加する事で、そのファイルに 対しては fsync() を呼び出さなくなるので、レスポンスが著しく低下する事を防ぐ事 ができます。

 

もし、fsync() を呼ばなくなるのは心配...と言う事であれば、それは、UPS 等を 設置した方が適切であると考えます。

 

実際問題、syslogd が fsync() していても、それを読み出す /dev/log は、カーネル内で「バッファ」として持っています。ですので、syslogd が、ログメッセージ毎に fsync()していても、/dev/log がバッファ構造である限り、fsync() だけでは不十分なのです。

ログメッセージの「取りこぼし」について

時折、「syslogd はログメッセージの取りこぼしが起こる...」と言う言葉を聞きます。

 

ログメッセージの取りこぼしが発生していると言う事は、当たり前ですが残すべきログ が正しく残らない事ですので、システムに何か問題があった時に、ログから解決できな い場合が起こり得るという事です。

 

本当に、そんな事が発生し得るのでしょうか?

 

私が syslogd のソース解析を行った範疇では、以下のタイミングで、「ログメッセージを取りこぼす」タイミングがあります。

 syslogd が、リモート(別サーバ)のログメッセージを受信している時。

理由は単純で、syslogd が、リモートでログメッセージを送る(受ける)メカニズムは、 以下の様になっています。

      プロセス                         syslogd(A)                  syslogd(B)
  +---------------+                +---------------+          +---------------+
  |       :       |                |       :       |          |        :      |
  | syslog() 呼出 | → /dev/log → |  受信(recv()) |          |        :      |
  |       :       |                |  送信(sendto) | → UDP →|       受信    |
  +---------------+                |       :       |          |        :      |
                                   +---------------+          +---------------+
  |<-------------------- ホスト A ---------------->|          | <- ホストB -> |

ホストA 側の syslogd は、受け取ったメッセージを、ホストB の syslogd に送信する際、TCP ではなく、UDP を使います。

 

UDP と言うのは、ご存知の方も多々いらっしゃると思いますが、信頼性がなく、 途中でパケットロス(データ消失)が発生しても、サーバもクライアントも分かりません。 エラーリカバリーは、原則的にサーバ/クライアントプロセスの仕事となります。

 

例えば、中規模な ML システムを運用しており、そのメールサーバがログサーバに 対して、syslogd を通じてログを残すような仕組みにしているとします。

 

この状態で、運営を続けており、もし仮に、多数のメールを処理している場合、 これも裏を返すと、「大量の TCP パケットが発生している」事を示します。

 

この状態で、ログサーバにログメッセージを記録させようとしている場合、ただでさえ、 TCP パケットが大量発生しているのに、UDP パケットまで発生させてしまうので、TCP 側はパケットロスが発生しても復帰が可能ですが、UDP はパケットロスを検出できませ んので、結果的に「取りこぼし」が発生します。

 

とは言え、大抵は、メールのネットワークインターフェースと、ログサーバへの ネットワークインターフェースは、セキュリティ的に考えても分けるのが通常手段 だとは思いますが、それでも、原則的に UDP は信頼性の無いものですので、それを 使用している限り、syslogd 自身でエラー訂正を行うメカニズムを実装しない限り、 「ログメッセージの取りこぼし」は十分に考えられます。

ログ時間がズレている?

これも、ログメッセージの取りこぼしに関係しますが、「ログが取れても、時間が ズレているんじゃないか...?」と言う事を聞きます。

 

これについても、ソースを解析した範疇では、ログサーバに書き込みを行う場合、 時間がズレて記録されている事が考えられます。

そもそも「ログメッセージに書かれている時間」は、いつの時間だ?

syslogd を通じて記録されているログメッセージには、大抵、先頭に日付時刻が 書き込まれています。そもそも、これはどのタイミングの時間なのでしょうか?

 

正解は、「syslog() を呼び出した時の時間」です。従って、ログメッセージに ある時間は、その syslog() を呼び出した時のサーバ上の時間ですので、秒単位で 精度があるはずです。これが、何故ズレるのでしょうか?

syslogd は、ログサーバにログメッセージを送る際、相手に時間を送りません。

syslogd のソースを解析した所、個人的には、ちょっと信じられないのが正直な 感想なのですが、syslogd が、別のログサーバに UDP を通じてログメッセージを 送る際、syslog() 呼び出しの時に埋め込んだ日付時刻を送信していない事が分か りました。

 

UDP で待受ける syslogd は、受け取ったメッセージ内部に時間情報が存在しない 場合、自分の時間を書き込みます。従って、 *syslog() 発生時の時間ではなく、ログサーバの syslogd が受け取った時の時間* が書き込まれますので、もし、サーバー間で時間がズレている場合、そのズレが直接 影響しますし、また、UDP 送信のタイムラグによってもズレます。

syslogd の考察

個人的には、これらの解析結果から、「Linux の syslogd を使ってリモートログシステムを構成するのは、*全くお薦めできない*」と考えています。

 

もし、どうしても syslogd を使って、別のログサーバに記録を残す必要があるのなら ば、一旦ディスクに記録させ、時間単位で、rsync 等のツールを用いてログファイルを 転送させる方が、取りこぼしにも、時間のズレにも影響しません。

 

これらの考察が、全て間違いである事を望みます。