監視とは継続的なテストである、という話 (もしくは cronlog とテストスクリプトを組み合わせた監視手法について)

 結論から先に。cronlog を使えば、アプリケーションのテストコードと全く同じ形式で、監視用のスクリプトを書くことができます。プログラマが監視ツールの記法を覚える必要はありません。これは、プログラマが運用も行うケースでは特に有効な手法だと思います。

 先週公開した Kazuho@Cybozu Labs: crontab を使って効率的にサービス監視する方法 というエントリで、crontab と拙作の cronlog を用いてサービス監視を書く手法を紹介しました。しかし、挙げた例はいずれも ping や http のテストといった外形監視の手法です。RDBMS とウェブアプリケーションのみから構成されるサービスならそれだけで十分でしょう。

 しかし、外形監視だけでは、メッセージキューのような非同期処理の遅延を観測することはできません。また、http のログを監視して、エラーレスポンスや平均応答時間の監視も行うことが望ましいです。それらの処理をどう書くか。

 自分は、監視とは継続的なテストである、という観点から、キューの処理遅延等の監視を、アプリケーションのテストスートの一部として書いています。具体的には、以下のような感じ (一部改変)。テストはアプリケーションと設定情報を共有しているので、監視ソフトウェアに様々な設定値を入力する必要もありません。

use strict;
use warnings;

use Test::More;
use Pathtraq;

my $app = Pathtraq->new;

cmp_ok
do {
my $row = $app->dbh->selectrow_arrayref(
'select XXXX', # Q4M 使ってない昔のキュー監視
) or die $app->dbh->errstr;
$row->[0];
},
'<',
1000,
'delay of updater';

for my $tbl (qw(analyze_page set_page_info analyze_keyword)) {
cmp_ok
do {
my $row = $app->dbh_queue->selectrow_arrayref(
"select count(*) from $tbl",
) or die $app->dbh_queue->errstr;
$row->[0];
},
'<',
1000,
"delay of $tbl",
}

done_testing;

 あとは、これらのテストコードを、crontab 上で cronlog を介してテストの実行ツール (perl なら prove) に食わせるだけ。

*/5 * * * * cd /var/webapp && exec setlock -nX /tmp/monitor.lock cronlog -- prove -v monitor.t/*.t 2>&1

 これで、監視対象項目 (=テスト項目) になんらかの問題が見つかった場合には、以下のような感じのメールが届くようになります。

Subject: Cron <user@host> cd /var/webapp && exec setlock -nX /tmp/monitor.lock cronlog -- prove -v monitor.t/*.t 2>&1

host.example.com starting: prove -v monitor.t/queue.t

# Failed test 'delay of analyze_page'
# at monitor.t/queue.t line 23.
# '1396'
# <
# '1000'
# Looks like you failed 1 test of 4.
monitor.t/queue.t ..
ok 1 - delay of updater
not ok 2 - delay of analyze_page
ok 3 - delay of set_page_info
ok 4 - delay of analyze_keyword
1..4
Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/4 subtests

Test Summary Report
-------------------
monitor.t/queue.t (Wstat: 256 Tests: 4 Failed: 1)
Failed test: 2
Non-zero exit status: 1
Files=1, Tests=4, 0 wallclock secs ( 0.02 usr 0.00 sys + 0.40 cusr 0.08 csys = 0.50 CPU)
Result: FAIL
command exited with code:1

 perl に限らず、テストの実行ツールは一般に、成功した場合はゼロ、失敗した場合は非ゼロを返します (そうしないと make test && make install とか自動化できない)。この特性と cronlog の、非ゼロが返った場合だけ cron を経由してログをメールで送信する、という機能を組み合わせることで、テストコードが監視系に早変わりするのです。さらに外側で setlock -nX しているのは、5分間でテストが終了しなかった場合に、やはりエラーメールを送信するため。

 以上のように、cronlog を使えば、プログラマが使い慣れたテストスートの一部として監視系を書くことができます。パストラックでは更に、リバースプロキシのログ監視を touch_if コマンドとテストコードを連動する形で実施するようにしています。どうぞご覧ください。