ssh 呼び出しのバッチが動かないトラブルを調べた話【vol.1】

株式会社オズビジョンのユッコ (@terra_yucco) です。
今日はトラブル調査っぽい話です。

ハピタスのバッチ管理の話

メインプロダクト「ハピタス」はそれなりに大きくなってきたのですが、まだまだ定刻処理の起動は crond に頼っています。
ただ、中央管理っぽいことはやりはじめています。具体的には、各 EC2 の crontab にそれぞれバラバラに書くのではなく、スケジューラの役割を持たせた EC2 の crontab に集約させ、そこから ssh 経由で実行をしています。
(最終的には、いろいろありますが Azkaban Jenkins Airflow Rundeck などいろいろあるスケジューラを使っていきたいな、とは考えています。)

そんな中で発生した問題は以下のようなものでした。
/var/log/cron には起動痕跡があるのに、実際にはリモートのスクリプトが想定通り動いていない

以下に順に、構成と、調べたことやったことを書いていきます。

crontab

中央管理の EC2 の crontab に以下のように記述することで各 EC2 へ振り分け、実行をしています。

/etc/crontab

SHELL=/bin/bash
PATH=/sbin:/bin:/usr/sbin:/usr/bin
MAILTO=""
HOME=/

# For details see man 4 crontabs

# Example of job definition:
# .---------------- minute (0 - 59)
# |  .------------- hour (0 - 23)
# |  |  .---------- day of month (1 - 31)
# |  |  |  .------- month (1 - 12) OR jan,feb,mar,apr ...
# |  |  |  |  .---- day of week (0 - 6) (Sunday=0 or 7) OR sun,mon,tue,wed,thu,fri,sat
# |  |  |  |  |
# *  *  *  *  *  command to be executed

*/5 * * * * root remoteexe host_sum_batch01  /path/to/starting_sh/sum.sh
* * * * *   root remoteexe host_user_batch02 "/path/to/starting_sh/user_log.sh action"

# (以下略)

独自コマンド

remoteexe は ssh を発行するだけのプログラムで、引数には通信先のホスト名 (/etc/hosts で解決させる) と、呼び出し先スクリプトを渡します。呼び出し先スクリプトには引数は渡せないのですが、クォートで囲むことで 1 つと認識させれば無理やり渡すことができるようになっていました。
/usr/bin から Git の deploy 先へシンボリックリンクを張り、パス無しの remoteexe 指定で起動するようにしています。

この方法の問題点

もちろん、素の crond を使っている時点で、スケジューラなら解決できるいろいろな問題点があります。
今回私たちの開発現場で問題になり、以下に記載するスクリプトで解消できたのは以下の点でした。

• リモートのスクリプトが起動されたかどうかがわからない
• リモートのスクリプトがどのような出力をしたか・結果を返したかがわからない
  • これは起動頻度を鑑みて MAILTO を切ってしまっていることも原因の 1 つ

上記を解決するために

もともと C で作られていて、第 1 引数と第 2 引数を元に ssh を発行するしか機能のなかった remoteexe を bash で実装しなおし、以下の機能を合わせて追加しました。
※スケジューラの機能は crond のままです。

• 起動、発行コマンド (ssh)、終了のログを出力
• 発行コマンドの stdout/stderr もログに出力
• 終了ログに発行コマンドの return value を出力

remoteexe

# !/bin/bash -u
log_path=/tmp/$( date +'%Y%m%d' )_remoteexe.log

function log()
{
  echo "[$( date +'%Y-%m-%d %H:%M:%S' )][$$] $@" >> ${log_path}
}

parameters="$@"
log "START,-,${parameters}"

function validate()
{
  error_code=10
  if [ $# -lt 2 ]; then
    log "usage: remoteexe target script [parameters]"
    log "e.g.) remoteexe host_sum_batch01 /path/to/starting_sh/sum.sh"
    log "e.g.) remoteexe host_user_batch02 "/path/to/starting_sh/user_log.sh action"
    log "END,${error_code},${parameters}"
    exit ${error_code}
  fi
}

validate $@
host=${1}
shift

command="ssh -i /path/to/key root@${host} ${@}"
log "command,${command}"
output=$( ${command} 2>&1 )
rc=$?

while read line
do
  log "${line}"
done << EOS
${output}
EOS

log "END,${rc},${parameters}"

工夫した点

crond から呼び出される前提

• PID を出力内容に追加
• stdout/stderr 出力内容にもヘッダ (タイムスタンプ, PID) を追加

crond からは様々な頻度でリモートプロセスが呼び出されます。そのため、開始終了はともかく、リモートプロセスの標準出力/標準エラー出力はごちゃごちゃに混ざります。
最初は ${command} 1>>${log_path} 2>&1 としていたのですが、後にコード記載の方法に変えました。出力が非常に大きい場合にはメモリの問題が出そうですが、出力を一度変数に格納し、出力時に 1 行ずつタイムスタンプと PID のヘッダをつけて出力するというものになります。
ヘッダを付けたのは、順番がごちゃごちゃになっても、タイムスタンプと PID で同一プロセスによるログはほぼ区別できるだろうと判断したからになります。

ログのローテートは OS の機能を利用

ログを日単位で /tmp に出すことで、必要以上にディスクを圧迫しないようにしました。

Exit Code

今回のスクリプトには引数チェックが入っています。こういう処理でエラーになった場合、普段はあまり考えずに exit 1 とすることが多かったのです。
が、以下の記事を見、今回は予約されておらず他と区別可能そうなコードをバリデーションエラーの値として使いました。

• コマンドラインツールを書くなら知っておきたい Bash の 予約済み Exit Code

結果だけ言うと、この判断は正解でした。
呼び出し先のリモートのスクリプト内では、多重起動除けに flock --timeout=0 <command> の書式を使っており、この排他ではじかれた場合には Exit Code が 1 になっていたためです。何も考えず 1 で実装していたら、切り分けが困難になるところでした。

END ログ

終了ログ (END ログ) にも、情報としては重複ですが起動引数を出力するようにしました。
これにより Exit Code を grep で集計した場合など、どの呼び出しが原因だったのかをすぐに見ることができます。

$  grep -o "END,255.*$" /tmp/20190625_remoteexe.log | sort | uniq -c
     21 END,255,host_sum_batch11 /path/to/starting_sh/sum.sh
     16 END,255,host_sum_batch12 /path/to/starting_sh/sum.sh

実際に取得できたログ (一部)

START/END の他に ssh の出力やリモートスクリプトの出力など、いろいろなものが取得できました。

$ grep "\[913\]" /tmp/20190625_remoteexe.log
[2019-06-25 13:21:01][913] START,-,host_sum_batch02 /path/to/starting_sh/sum.sh
[2019-06-25 13:21:01][913] command,ssh -i /path/to/key root@host_sum_batch02 /path/to/starting_sh/sum.sh
[2019-06-25 13:21:58][913] END,0,host_sum_batch02 /path/to/starting_sh/sum.sh
[2019-06-25 15:09:02][913] START,-,host_user_batch01 /path/to/starting_sh/user_log.sh action
[2019-06-25 15:09:02][913] command,ssh -i /path/to/key root@host_user_batch01 /path/to/starting_sh/user_log.sh action
[2019-06-25 15:09:05][913] Warning: Permanently added 'host_user_batch01,xxx.xxx.xxx.xxx' (RSA) to the list of known hosts.
[2019-06-25 15:09:05][913] collect user log(action)
[2019-06-25 15:09:05][913] END,0,host_user_batch01 /path/to/starting_sh/user_log.sh action
[2019-06-25 18:05:46][913] START,-,host_user_batch02 /path/to/starting_sh/user_log.sh action
[2019-06-25 18:05:46][913] command,ssh -i /path/to/key root@host_user_batch02 /path/to/starting_sh/user_log.sh action
[2019-06-25 18:05:46][913] Warning: Permanently added 'host_user_batch02,xxx.xxx.xxx.xxx' (RSA) to the list of known hosts.
[2019-06-25 18:05:46][913] collect user log(action)
[2019-06-25 18:05:46][913] END,0,host_user_batch02 /path/to/starting_sh/user_log.sh action
[2019-06-25 20:53:01][913] START,-,host_user_batch01 /path/to/starting_sh/user_log.sh action
[2019-06-25 20:53:01][913] command,ssh -i /path/to/key root@host_user_batch01 /path/to/starting_sh/user_log.sh action
[2019-06-25 20:53:02][913] ssh_exchange_identification: Connection closed by remote host
[2019-06-25 20:53:02][913] END,255,host_user_batch01 /path/to/starting_sh/user_log.sh action

Conclusion

crond をすぐには脱却できませんが、元々のスクリプトを改修することで、ある程度調査に使えそうなログを得ることができました。
vol.2 では、これを元にどのように原因特定しようとしたかを書いていきます。