f:id:vasilyjp:20180927090637j:plain

こんにちは。
モルトとシガーで生きてます。インフラエンジニアの光野（@kotatsu360）です。

先日、crontabで管理しているバッチ処理の監視にhorensoというツールを導入したのですが、

監視の品質が向上
毎分届く大量の実行結果メールから開放されQoL向上

という効果がありました。本日はその取り組みについてご紹介いたします。

ジレンマ：動作監視と大量のメール

冒頭の通り、VASILYでは定期的に実行したいバッチ処理をcrontabで管理しています。真新しさはありませんが、実行時間の指定が簡潔かつ柔軟で未だに愛用しています。

2016年12月現在、crontabは120行ほどです。

さて、そんなcrontabによる処理で前々から課題になっていたのが、 crontabで管理しているスクリプト達（以下cronスクリプト）の動作監視です。

当時、VASILYのcronスクリプトは3箇所に結果を出力していました。

f:id:vasilyjp:20161208185428p:plain （ログファイル・スクリプト・歯車・メールの画像クレジット *1）

1.のログは調査用、2.のSlack通知は異常検知、3.のMAILTOは過去の動作記録とそれぞれ役割をもっているのですが、ここで問題になるのは3.です。

ご存知の通り、crontabにてMAILTO要素にメールアドレスを設定しておくと、cronスクリプト実行後にメールを送信してくれます。お手軽で便利なのですが、cronスクリプトの量が増えてくるとspamよろしくメールが届きます。

正直、邪魔です。しかし、「動いた」という記録を取る意味では大変有用なため、日々大量のメールを受け取り続けていました。

問題発生：解決手段の模索

そんな状況をしばらく容認していたのですが、ある日メールがパタリと届かなくなるという問題が発生したため、一念発起、改善に着手します。

ちなみにメールが届かなくなった原因ですが、なんということはなく、あまりに量が多いため迷惑メールフォルダに分類されていたのでした

その際、手段選定の条件としたのが次の3つです。

特別な実行環境が不要
既存のスクリプトをそのまま使う
監視と本処理を独立させる

1.と2.については、短期間で移行を完了するためです。

最初は「はやりのリッチなUIをもつジョブ管理システムを導入だ！」とも考えたのですが、既存のスクリプトを短期間かつ安全に移行することを考えるとあまり現実的ではないと思い止めました。

3.については、cronスクリプトをこれ以上肥大化させないためです。バッチ処理のスクリプトはユニットテストもしづらく、監視のような「運用上は必要だけれども、スクリプト自体の処理には必要ない機能」を持たせたくありません。

そして、これらの条件を満たせるものとしてhorensoを採用しました。

horenso

horensoはSongmuさんが開発された各種コマンド用のラッパーツールで、スクリプト実行結果の「報告」をつかさどってくれます。

Goで実装されており、各プラットフォームに対応するバイナリを置くだけで利用可能です。バイナリを配置後、以下のように実行します。

$ /path/to/horenso --reporter report.rb -- /usr/bin/ruby /path/to/batch/script.rb arg1 arg2

--の後ろにあるのが、既存のcronスクリプトです。このようにして実行すると、--reporterで指定したスクリプトがcronスクリプトの実行結果をJSONで受け取ります。

{
    "command": "/usr/bin/ruby /path/to/batch/script.rb arg1 arg2",
    "commandArgs": ["/usr/bin/ruby","/path/to/batch/script.rb","arg1", "arg2"],
    "output": "message\nerror",
    "stdout": "message",
    "stderr": "error",
    "exitCode": "0",
    "result": "command exited with code: 0",
    "pid": "13813",
    "startAt": "2016-12-05T06:32:01.123456789+09:00",
    "endAt": "2016-12-05T06:32:11.987654321+09:00",
    "hostname": "cron.iqon.example.com",
    "systemTime": "0.716",
    "userTime": "5.812"
}

後はこのJSONをreporterのスクリプトで好きなように扱えば完了です。reporterには任意の実行権限がついたファイルを指定できます。

詳細な使い方は、SongmuさんのブログエントリやGithubのREADMEをご覧ください。

cron監視ver2.0

horensoを使うことによってcronスクリプトの監視方法は以下のように変わりました。

f:id:vasilyjp:20161208185924p:plain （ほうれん草の画像クレジット *2）

crontabの中では、以下のサンプルのように呼び出します。

0 0 * * * /path/to/horenso --reporter horenso.rb -- /usr/bin/ruby /path/to/batch/script.rb args...

用意したhorenso.rbの動作は大きく2つです。

exitCodeが0以外、またはstderrに出力がある場合、Slackに通知
ログをfluentdにフォワード

このログは最終的にBigQueryとS3に保存され記録されます。これにより、ほぼspamと化していたメールを廃止することができ、かつ動作記録が確実に記録できるようになりました。BigQueryにもインサートされているため、参照も非常に容易です。

なお補足をいたしますと、horenso.rbに集約したSlack通知はあくまでも監視を目的とした通知です。個々のcronスクリプトの仕様として必要なSlack通知は、そのスクリプトで実装することにしています。

導入初期に発生した諸々

horensoによって、劇的にモダンになったcron監視環境ですが、導入初期にはいくつか問題も発生しました。 cronスクリプト自体を直したほうが良いものもありますが、原則既存のスクリプトに手を入れず対応しています。

実行ディレクトリについて

幾つかの古いスクリプトでは内部で相対パスを使っており、

cd /path/to/dir ; ./batch/script.rb

というような呼び出し方をしているものがあります。しかし、horensoでは--以降で、cdをしても意味がありません。

そこで、次のように移動した上でhorensoを呼び出すことで解決しています。

cd /path/to/dir && (horenso --reporter horenso.rb -- bin/rails runner -e production batch.rb)

stderr

当初、exitCodeのみを基準に実装をしていたのですが、例外ケースがあり正しく検知できていませんでした。

VASILYのcronスクリプトはRubyですが、幾つかのスクリプトでは``でシェルコマンドを呼び出しているものがあります。シェルコマンドが失敗した場合、Rubyとして例外は出力されないため、exitCode=0（ただし失敗している）ということになります。

そのため、内部で失敗を検知し損ねているケースを考え、今のreporterスクリプトではstderrの有無も確認するようになっています。

BigQueryのクォータ

2つめの図の通り、horensoで受け取ったログは最終的にBigQueryとS3まで送られます。fluentdからBigQueryへはストリーミングインサートをしているのですがここには各種の制限が存在します。

割り当てのポリシー | BigQuery のドキュメント

スクリプトによっては大量のログを出すものがあり、それらが一度のリクエストに重なると制限に引っかかる恐れがありました。現在は、ログを次のように加工してからフォワードしています。

outputを削除
- outputはstdoutとstderrを合わせたもの
stdout/stderrを1KBで切り詰める
startAt/endAtをISO 8601形式に変換
commandArgsをJSON文字列に変換

なお、後半の2つはあとで扱いやすくするだけのものなので、BigQueryの制限とは関係ありません。切り詰める前のログはサーバ側に残っているため、どうしても全てのログを見たいケースがあればそちらを見ます。

まとめ

モダンなcron監視環境についてご紹介しました。horensoを使うことで既存のcronスクリプトをそのままに、動作記録を参照しやすい形で保存することが可能になりました。またhorensoによって、実行時間などこれまで見えていなかった情報も得られるようになりました。今後はこの環境を活かしてcronスクリプト自体の改良も行いたいと考えています。