Varnishのログをsyslog/fluentdで収集

varnish-logofluentd-logo

Varnish のログを NCSA 形式で出力し、syslog/fluentd を使って収集する方法を調べた。

OS は Ubuntu 12.04、syslog は rsyslog、 varnish はオフィシャルサイトが提供するレポジトリ経由でインストールしていることを想定。

Varnish はディスク I/O を減らすために共有メモリにログ出力し、ログ取得用のプログラム(varnishlog と Apache のアクセスログ風に整形した varnishncsa)が共有メモリからログ情報を取得するアーキテクチャ。この狙いを無駄にしないログ出力をおこないたい。
今回試すログ出力形式

  1. ローカルの専用ファイルに出力
  2. ローカルの syslog に出力
  3. ローカルの syslog に出力し、リモートの syslog に転送し rsyslog で受信
  4. ローカルの syslog に出力し、リモートの syslog に転送し fluentd で受信

今回は varnishncsa を利用したけれど、varnishlog でも設定ファイルを読み替えるだけで動くと思う。

1.ローカルの専用ファイルに出力

$ varnishncsa した時にターミナルに出力されるログを専用ファイルに出力するデーモンプロセスを起動させる。

/etc/default/varnishncsa から

# VARNISHNCSA_ENABLED=1

の行のコメントを解除。

環境変数 VARNISHNCSA_ENABLED を利用し /etc/init.d/varnishncsa の先頭部分で

# If unset, or set to "0" or "no", exit
if [ -z "${VARNISHNCSA_ENABLED}" ] || \
   [ "${VARNISHNCSA_ENABLED}" = "0" ] || \
   [ "${VARNISHNCSA_ENABLED}" = "no" ]; then
  exit 0;
fi

というような処理を行っている。

起動

/etc/init.d/varnishncsa start でログ出力用プロセスを起動。
/usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D -P /var/run/varnishncsa/varnishncsa.pid のようなコマンドでプロセスが起動する。
$ tail -f /var/log/varnish/varnishncsa.log でログ出力が確認できる。

2.ローカルの syslog に出力

やりたいことは varnishncsa の出力をパイプして logger コマンドで syslog 出力する。

$ varnishncsa | logger

この対応が面倒。

  1. デーモン停止が面倒方法
  2. デーモン操作に利用している start-stop-daemon プログラムを更新する方法

の2通りがある。

2.1 デーモン停止が面倒な方法

varnishncsa では start-stop-daemon--exec に daemonize するプログラムを渡している。
varnishncsa | logger をまるごと --exec に渡したいけど、引数は executable でなければいけないので使えない。
そこで --exec には bash を指定し、本来のプログラムは bash の -c オプションに指定して呼び出す。

$ bash -c "varnishncsa | logger" を start-stop-daemon 形式に書き換える。

/etc/init.d/varnishncsa の修正

DAEMON_OPTS="-P ${PIDFILE}"
...
start_varnishncsa() {
    output=$(/bin/tempfile -s.varnish)
    log_daemon_msg "Starting $DESC" "$NAME"
    create_pid_directory
    if start-stop-daemon --start --quiet --pidfile ${PIDFILE} \
        --background --make-pidfile \
        --chuid $USER --exec /bin/bash -- -c "${DAEMON} -- ${DAEMON_OPTS} | logger -p local1.info -t varnish "; then
        log_end_msg 0

もとの DAEMON_OPTS は DAEMON_OPTS="-a -w ${LOGFILE} -D -P ${PIDFILE}"

ログ出力ファイルを指定する -w を取り除き、ファイルの追記モードを指定する -a も取り除く。

パイプでログを受け取れるように、varnishncsa のデーモン化オプション(-D)も取り除く。
かわりに、start_stop_daemon に --background オプションを指定して、実行コマンドをデーモン化させる。
さらには pid ファイルが作成されるように –make-pidfile オプションも指定。(どのプログラムだと pid ファイルを作るのかはケースバイケースみたい)

$ sudo /etc/init.d/varnishncsa で実行
$ tail /var/log/syslog すると varnish が syslog に出力されていることを確認できる。

Oct 12 17:51:47 varnish varnish: 127.0.0.1 - - [12/Oct/2013:17:51:47 +0000] "HEAD http://localhost/ HTTP/1.1" 200 0 "-" "lwp-request/6.03 libwww-perl/6.03"

プロセスの停止

この方式の問題点はプロセスの停止方法。

start-stop-daemon は停止するプロセスのプロセスIDを PID ファイルから取得し kill する。
先ほど起動したプロセスを確認すると

$ cat /var/run/varnishncsa/varnishncsa.pid
2160
$ pstree -Ap | head -n 20
init(1)-+-VBoxService(1010)-+-{VBoxService}(1012)
        ...
        |-bash(2160)-+-logger(2164)
        |            `-varnishncsa(2163)

というようになっていて PID ファイルの PIDを はデーモン化した bash で、その下にfork した varnishncsa/logger プロセスがぶら下がっている。
うっかり bash のプロセスだけを kill すると、子どは orphan プロセスになって init にぶら下がり kill されない。

$ sudo kill 2160
$ pstree -Ap | head -n 20
init(1)-+-VBoxService(1010)-+-{VBoxService}(1012)
        ...
        |-logger(2164)
        |-varnishncsa(2163)

そのため、これら3つのプロセスが共有するプロセスグループを指定して kill($ pkill -g pgrp) する必要がある。(process group id, parent process id などは $ ps axo stat,pgrp,ppid,pid,comm で確認できる)
実装例は以下の do_stop 関数を参照。

https://raw.github.com/joeytwiddle/ut_magic_redirect/master/init_script/ut_magic_redirect

2.2 start-stop-daemon プログラムを更新する方法

start-stop-daemon 1.16.5 から --no-close オプションが追加され、–background を指定しても daemonize したプロセスの FD がクローズされず、出力を使いまわせる。

commit 3de1552982f9ff60f59826d1811b2f8c0add8325
Author: Guillem Jover
Date: Sun Jun 17 06:54:40 2012 +0200

s-s-d: Add new --no-close option to disable closing fds on --background

This enabled the caller to see process messages for debugging purposes,
or to be able to redirect file descriptors to log files, syslog or
similar.

Closes: http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=627333, http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=646425

debian/changelog | 2 ++
man/start-stop-daemon.8 | 8 +++++++-
utils/start-stop-daemon.c | 23 ++++++++++++++++-------
3 files changed, 25 insertions(+), 8 deletions(-)

ただし、Ubuntu 12.04 にインストールされているバージョンは 1.16.10 と少し古いので、最新版を野良インストールする。

start-stop-daemon のインストール

start-stop-daemon は Debian の dpkg の1プログラム。dpkg のサイトからソースコードを取得する。

http://packages.debian.org/wheezy/dpkg

$ wget http://ftp.de.debian.org/debian/pool/main/d/dpkg/dpkg_1.16.10.tar.xz
$ tar Jxfv dpkg_1.16.10.tar.xz
$ cd dpkg-1.16.10
$ ./configure
$ make
$ sudo cp utils/start-stop-daemon /usr/local/bin/

/etc/init.d/varnishncsa の修正

DAEMON_OPTS="-P ${PIDFILE}"
...
start_varnishncsa() {
    output=$(/bin/tempfile -s.varnish)
    log_daemon_msg "Starting $DESC" "$NAME"
    create_pid_directory
    if /usr/local/bin/start-stop-daemon --start --quiet --pidfile ${PIDFILE} \
        --background --no-close \
        --chuid $USER --exec ${DAEMON} -- ${DAEMON_OPTS} | logger -p local1.info -t varnish &; then
        log_end_msg 0
    else
        log_end_msg 1
        cat $output
        exit 1
    fi
    rm $output
}

DAEMON_OPTS はさっきと同じ。
start-stop-daemon を新規にインストールした /usr/local/bin/start-stop-daemon に変更
start_varnishncsa には --background だけでなく--no-close も指定
logger にパイプでつなぐ

次の RedHat 向け起動スクリプト(daemon コマンドでデーモン化)に近いアプローチ。

http://d.hatena.ne.jp/dai_yamashita/20120322/1332417137

3. ローカルの syslog に出力し、リモートの syslog に転送し rsyslog で受信

ファイルシステム上にログ出力して余計なディスク I/O が発生し、 Varnish のパフォーマンスが悪化しては元も子もないので rsyslog の機能を利用して、リモートサーバに syslog を UDP 転送する。ログの集約もできるので一石二鳥(というのを同僚に教わる)。

rsyslog.conf の変更

ログサーバ

ログ(リモート)サーバの /etc/rsyslog.conf を編集
imudp モジュールを有効にして、LISTEN するポート(デフォルトは 514)を指定。変更後に $ sudo service rsyslog reload

# provides UDP syslog reception
$ModLoad imudp
$UDPServerRun 1514

Varnish サーバ

次にVarnish(ローカル)サーバの /etc/rsyslog.conf を編集。変更後に $ sudo service rsyslog reload
転送するログサーバとポートを指定。”@” のかわりに “@@” とすれば TCP 転送になる。

*.* @10.0.1.2:1514

転送テスト

Varnish サーバで logger コマンド経由で syslog 出力し、ログサーバの syslog に出力されていることを確認。

# Varnish server
$ logger log message
# log server
$ tail -f /var/log/syslog
Oct 12 22:47:36 hostname username: log message

4. ローカルの syslog に出力し、リモートの syslog に転送し fluentd で受信

最後に syslog 転送の受け口を rsyslog から fluentd に変更する。

fluentd のインストール

http://docs.fluentd.org/articles/install-by-deb を見る

$ curl -L http://toolbelt.treasure-data.com/sh/install-ubuntu-precise.sh | sudo sh

 設定の変更

fluentd サーバ

syslog の受信には標準で入っている syslog 用インプットプラグイン(in_syslog)を利用。

/etc/td-agent/td-agent.conf を編集して、末尾に追記。

<source>
  type syslog
  port 10514
  bind 0.0.0.0
  tag system.local
</source>

syslog プログラグインのサンプルがなぜかオフィシャルのドキュメント以外に見つからず。使われていないのはなにか理由があるのかな?使い方を間違えていなければいいけど。

Varnish サーバ

syslog の UDP 転送先を fluentd のホストとポートに変更する。変更後に $ sudo service rsyslog reload

*.* @10.0.1.2:10514

転送テスト

Varnish サーバ

$ logger hello from varnish server
$ HEAD http://localhost/

fluentd サーバ

連携のテストだけしたいので、ターミナルに出力させて確認

$ /usr/lib/fluent/ruby/bin/ruby /usr/sbin/td-agent --conf /etc/td-agent/td-agent.conf
2013-10-12 17:03:47 +0900 system.local.user.notice: {"host":"varnishtest","ident":"vagrant","message":"hello from varnish server"}
2013-10-12 17:04:25 +0900 system.local.local1.info: {"host":"varnishtest","ident":"varnishtest","message":"127.0.0.1 - - [12/Oct/2013:17:04:25 +0000] \"HEAD http://localhost/ HTTP/1.1\" 200 0 \"-\" \"lwp-request/6.03 libwww-perl/6.03\""}

TODO

rsyslog 同士の転送は実績があるけれど、fluent 連携は運用経験がないので、負荷の少ないサービスで仮運用しながら様子見予定。

References

Advertisements
Tagged with: , , , ,
Posted in middleware

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Archives
  • RT @__apf__: How to write a research paper: a guide for software engineers & practitioners. docs.google.com/presentation/d… /cc @inwyrd 4 months ago
  • RT @HayatoChiba: 昔、自然と対話しながら数学に打ち込んだら何かを悟れるのではと思いたち、専門書1つだけ持ってパワースポットで名高い奈良の山奥に1週間籠ったことがある。しかし泊まった民宿にドカベンが全巻揃っていたため、水島新司と対話しただけで1週間過ぎた。 それ… 5 months ago
  • RT @googlecloud: Ever wonder what underwater fiber optic internet cables look like? Look no further than this deep dive w/ @NatAndLo: https… 5 months ago
  • @ijin UTC+01:00 な時間帯で生活しています、、、 10 months ago
  • RT @mattcutts: Google's world-class Site Reliability Engineering team wrote a new book: amazon.com/Site-Reliabili… It's about managing produc… 1 year ago
%d bloggers like this: