cron の意外な落とし穴!
システムを運用していく上で cron を使う場面はよくありますよね
処理をスケジュール実行したい時にとても便利です
そんな cron ですが、最近仕事で作業しているときに ntpdate でシステム時刻を変更した後に cron で設定した時刻になってもジョブが実行されないという問題が見つかりました
全てのジョブが実行されていないわけではなく一部のジョブは実行されているようでした
また、時刻を変更した後に crond を再起動すれば全てのジョブが正常に実行されるようになりました
幸い、実運用ではなくてシステムテスト中に見つかった問題なのでまだよかったんですが、運用している環境で同じ問題が起きたら相当マズイですよね
そもそも ntp の時刻同期でシステム時刻が修正された場合にも同じ問題が起きそうじゃないですか?
ググっても同じような事象は見つからず、社内のメンバーにも聞いてみても cron でこういった問題が過去に起きたことはないようでした
今まで cron なんて特に意識せず当たり前に使ってきましたし、何か問題があったら困るのでこの機会に cron のソースから動作を調べました
この記事では
1. ソースの入手方法
2. cron の処理概要
3. cron のソースを見よう
4. まとめ
について説明します
今回はそんな cron の仕組みを見ていきましょう!
1. ソースの入手方法
cron といっても実際にはいくつかの実装が存在しているらしく、Linux ディストリビューションによってどのパッケージが入っているかは違うみたいです
cron にはバージョンを確認できるようなオプションが用意されていないので、インストールされているパッケージの情報を調べる必要がありました
rpm を利用している環境であれば以下のコマンドで確認することができます
$ whereis -b crontab | cut -d' ' -f2 | xargs rpm -qf
CentOS6.4 と EC2 の Amazon Linux AMI 2014.09.2 で確認したところ、cronie が入っていることがわかりました
cronie の git リポジトリは以下の URL でした
https://git.fedorahosted.org/git/cronie.git
任意のディレクトリで以下のコマンドを実行してクローンを取得します
$ git clone https://git.fedorahosted.org/git/cronie.git
2. cron の処理概要
ソースを見てだいたいの処理構成が分かったので cron の超ざっくり版処理フローを書いてみました
実際は細かい処理もっとが入ってますが、ポイントになりそうな部分だけ抜き出してます
時刻の基準について
cron 内部ではいくつかの時刻を保持していますが全て GMT に変換してから計算された値が保持されています
また、現在時刻から GMT への変換はタイムゾーンのオフセット値を加算・減算することで変換していることが分かりました
タイムゾーンの取得について
タイムゾーンは crond の起動時にのみ実行環境に設定されている値を取得しています
起動後にはタイムゾーンの更新は行われないので crond の起動後にタイムゾーンを変更しても変更前のタイムゾーンのまま動作します
例外として、crond の起動中にサマータイムに切り替わった時のみタイムゾーンのオフセットを更新するようになっていました
ジョブチェックの間隔
実行対象のジョブをチェックする間隔は1分間でした
チェックが終わったら1分経つまでの間スリープしています
厳密には、次の分までの秒数+1秒 の間スリープするよう実装されていました
開始された時刻が 00:00:30 だった場合には 00:01:01 までの31秒間スリープすることになります
なので、ジョブが開始されるのは厳密に0秒というわけではないんですね
ジョブチェック 〜 ジョブ実行までの詳細
対象の時刻に実行対象のジョブがあるかをチェックし実行するジョブがあればジョブをキューに追加します
ただ、この処理の中に想定してなかったロジックが入っていることが分かりました
前回のジョブチェック時の時間を保持しておき、実際にどれだけ時間が経過したかをジョブチェックの都度計算しています
そして、実際に経過した時間によってキューにジョブを追加する処理が異なることがわかりました
普通に動けば必ず1分にしかならないはずですが、どういうことなのかを見ていきましょう
差分が 1分 の場合
通常の動作はほとんどがこの場合です
この場合は、現在時刻に実行される予定のジョブを全て実行キューに追加します
差分が 0〜5分 の場合
ジョブの実行間隔が1分より少しだけ過ぎてしまった場合です
サーバーの負荷状況などで多少実行が遅れた場合が考えられます
基準の時刻を1分づつ進めながら、遅れた分の時間に実行する予定のジョブを全てキューに追加しジョブ実行もこの処理の中で実行します
差分が 5分〜3時間 の場合
さらに大きいジョブの遅延が発生した場合です
ここではサマータイムが始まった時にシステム時刻を進めた場合を想定しているようです
ここでも基準の時刻を1分づつ進めながら遅れたジョブを全てキューに追加し実行しますが、この場合だけリカバリの処理が可能な時間がなぜか1分間に限られています
そして、もし遅れたジョブをキューに追加する処理が1分を超えてしまった場合には、残されたジョブは全てスキップされます
また、この場合の処理では定時に設定しているジョブのみが実行され、ワイルドカードに設定しているジョブはスキップされるようになっています
ワイルドカードのジョブの場合は時刻を進めても同じタイミングで実行されるので影響はないと判断し、定時のジョブのみリカバリする、という考えのようです
※定時、ワイルドカードと書いてるのはそれぞれこんな設定のジョブを指してます
定時のジョブ
0 0 * * * hoge
ワイルドカードのジョブ
0 * * * * fuga または * 0 * * * fuga
今回の問題となっていた動作の原因
いままで説明した部分から、crond の起動中にシステム時刻を変更した場合にはジョブの実行がスキップされる動作をするということがわかりました
そのため、ntpdate で時刻を変更した場合にはどれくらい時間を進めた or 戻したかによって挙動が異なるということです
問題の動作が見つかった時には、定刻のジョブを cron で設定している状態で ntpdate で時刻をジョブの設定時刻より前に戻していました
つまり、ジョブチェック時の差分が 0分〜-3時間 の場合にあてはまっていたのでジョブが実行されないパターンだったということがわかりました
ちょっと言葉だけだと説明が難しいですね
それでは次に、説明した部分のソースを見ていきましょう
3. cron のソースを見よう
先ほど言葉で説明した処理のソースを見ていきましょう
まず、cron の内部で利用されている時刻の変数をまとめました
ソースを追ってくうちにどれがどれか分からなくなるので見失ったらこれを見てください
また、最初の方に載せた処理フローも確認しながらソースを追ってみてください
現在時刻を取得 & タイムゾーンのオフセット計算
処理フロー中は現在時刻の取得とオフセット計算を別々の処理として書きましたが、実際は1つのset_time() 内に実装されてます
引数の initialize が TRUE の場合、もしくはタイムゾーンの isdst が変化した場合のみ GMToff を更新していることがわかります
※isdst : 該当のタイムゾーンがサマータイムかどうかを示すフラグ
cron.c 599行目
/* * Set StartTime and clockTime to the current time. * These are used for computing what time it really is right now. * Note that clockTime is a unix wallclock time converted to minutes. */ static void set_time(int initialize) { struct tm tm; static int isdst; StartTime = time(NULL); /* We adjust the time to GMT so we can catch DST changes. */ tm = *localtime(&StartTime); if (initialize || tm.tm_isdst != isdst) { isdst = tm.tm_isdst; GMToff = get_gmtoff(&StartTime, &tm); Debug(DSCH, ("[%ld] GMToff=%ld\n", (long) getpid(), (long) GMToff)); } clockTime = (StartTime + GMToff) / (time_t) SECONDS_PER_MINUTE; }
実行対象ジョブのチェック間隔
ジョブチェックの間隔を制御している処理のソースです
cron_sleep() という関数で、次の分までの秒数でスリープする処理が実装されています
cron.c 356行目
/* ... wait for the time (in minutes) to change ... */ do { cron_sleep(timeRunning + 1, &database); set_time(FALSE); } while (!got_sigintterm && clockTime == timeRunning); if (got_sigintterm) break; timeRunning = clockTime;
cron_sleep() の中身も見てみましょう
内部で保持しているタイマーは秒→分に丸められた値で保持しているので、秒に変換した上で 差分の秒数+1秒の間だけスリープしていることがわかります
cron.c 620行目
/* * Try to just hit the next minute. */ static void cron_sleep(int target, cron_db * db) { time_t t1, t2; int seconds_to_wait; t1 = time(NULL) + GMToff; seconds_to_wait = (int) (target * SECONDS_PER_MINUTE - t1) + 1; Debug(DSCH, ("[%ld] Target time=%ld, sec-to-wait=%d\n", (long) getpid(), (long) target * SECONDS_PER_MINUTE, seconds_to_wait)); while (seconds_to_wait > 0 && seconds_to_wait < 65) { sleep((unsigned int) seconds_to_wait); if (got_sigintterm) return; /* * Check to see if we were interrupted by a signal. * If so, service the signal(s) then continue sleeping * where we left off. */ handle_signals(db); t2 = time(NULL) + GMToff; seconds_to_wait -= (int) (t2 - t1); t1 = t2; } }
ジョブチェックの詳細
それでは次に、今回の問題の原因となっていたジョブチェックを行う部分のソースを見てましょう
timeDiff の値によって処理が分岐しており、timeDiff の値が1の場合だけは先に分岐が書かれていました
timeDiff が 1分
virtualTime を現在の GMT 時刻まで進めて、現在時刻に実行されるジョブを実行キューに追加しています
find_jobs() は指定した時刻にあるジョブを実行キューに追加する関数で、ジョブの実行はここには含まれていません
cron.c 384行目
/* shortcut for the most common case */ if (timeDiff == 1) { virtualTime = timeRunning; oldGMToff = GMToff; find_jobs(virtualTime, &database, TRUE, TRUE, oldGMToff); }
続いて、1分以外の場合は以下のように switch で分岐するようになっています
cron.c 390行目
else { if (timeDiff > (3 * MINUTE_COUNT) || timeDiff < -(3 * MINUTE_COUNT)) wakeupKind = large; else if (timeDiff > 5) wakeupKind = medium; else if (timeDiff > 0) wakeupKind = small; else wakeupKind = negative; switch (wakeupKind) {
timeDiff が 0〜5分 (wakeupKind が small の場合)
virtualTime を1分づつインクリメントして、virtualTime が timeRunning を同じになるまで処理されます
キューに追加しつつ、job_runqueue() を呼び出してキューに入っているジョブを実行していることがわかります
※job_runqueue() はキューのジョブを実行する関数です
cron.c 401行目
case small: /* * case 1: timeDiff is a small positive number * (wokeup late) run jobs for each virtual * minute until caught up. */ Debug(DSCH, ("[%ld], normal case %d minutes to go\n", (long) pid, timeDiff)); do { if (job_runqueue()) sleep(10); virtualTime++; if (virtualTime >= timeRunning) /* always run also the other timezone jobs in the last step */ oldGMToff = GMToff; find_jobs(virtualTime, &database, TRUE, TRUE, oldGMToff); } while (virtualTime < timeRunning); break;
timeDiff が 5分〜3時間 (wakeupKind が medium の場合)
ざっとみると 0〜5分 と比べて以下の違いがあります
- find_jobs() の引数が異なる
- clockTime と timeRunning の値が同じ間だけ処理する
find_jobs() の第3、第4引数では実行対象のジョブを区別できるようになっていて、第3引数がワイルドカードのジョブ、第4引数が定刻のジョブと対応しています
cron.c 420行目
case medium: /* * case 2: timeDiff is a medium-sized positive * number, for example because we went to DST * run wildcard jobs once, then run any * fixed-time jobs that would otherwise be * skipped if we use up our minute (possible, * if there are a lot of jobs to run) go * around the loop again so that wildcard jobs * have a chance to run, and we do our * housekeeping. */ Debug(DSCH, ("[%ld], DST begins %d minutes to go\n", (long) pid, timeDiff)); /* run wildcard jobs for current minute */ find_jobs(timeRunning, &database, TRUE, FALSE, GMToff); /* run fixed-time jobs for each minute missed */ do { if (job_runqueue()) sleep(10); virtualTime++; if (virtualTime >= timeRunning) /* always run also the other timezone jobs in the last step */ oldGMToff = GMToff; find_jobs(virtualTime, &database, FALSE, TRUE, oldGMToff); set_time(FALSE); } while (virtualTime < timeRunning && clockTime == timeRunning); break;
timeDiff が 0分〜-3時間 (wakeupKind が negative の場合)
ここでは find_jobs() の第3引数が TRUE になっているので、ワイルドカードのジョブのみキューに追加されます
また、今までみた分岐と比べると virtualTime の値は更新されていないことがわかります
この時点では virtualTime は timeRunning よりも未来の時刻になっておりので、ループを繰り返して timeRunning の値が1分づつ増えて自然に virtualTime の時刻に追いつくまでは毎回このケースの処理に該当します
cron.c 450行目
case negative: /* * case 3: timeDiff is a small or medium-sized * negative num, eg. because of DST ending. * Just run the wildcard jobs. The fixed-time * jobs probably have already run, and should * not be repeated. Virtual time does not * change until we are caught up. */ Debug(DSCH, ("[%ld], DST ends %d minutes to go\n", (long) pid, timeDiff)); find_jobs(timeRunning, &database, TRUE, FALSE, GMToff); break;
timeDiff が 上記以外 (wakeupKind が large の場合)
現在時刻に設定されたジョブを実行し virtualTime も現在時刻に上書きしています
find_jobs() の第3、第4引数はどちらも TRUE になっているので、現在時刻に設定されているジョブは全てキューに追加されます
cron.c 463行目
default: /* * other: time has changed a *lot*, * jump virtual time, and run everything */ Debug(DSCH, ("[%ld], clock jumped\n", (long) pid)); virtualTime = timeRunning; oldGMToff = GMToff; find_jobs(timeRunning, &database, TRUE, TRUE, GMToff);
上記の分岐を抜けた後にキューに溜まっているジョブを実行します
そしてまたジョブチェックのループの戦闘に戻ります
cron.c 475行目
/* Jobs to be run (if any) are loaded; clear the queue. */
job_runqueue();
find_jobs() の中身
キューにジョブを追加する find_jobs() の中身を見てみましょう
先に引数を見ると、doWild がワイルドカードジョブの実行フラグ、doNonWild 定刻ジョブの実行フラグになっています
cron.c 524行目
static void find_jobs(int vtime, cron_db * db, int doWild, int doNonWild, long vGMToff) {
中身の処理を見てみましょう
コメントを見ると dom (日付) と dow (曜日) が同時に指定された場合の挙動がややこしいよ、と書かれています
※dom → Day of month の略、dow → Day of week の略
" * * 1,15 * Sun " と指定した場合には "毎月1日、15日 更に、毎週日曜日" にジョブが実行されると書いています
"(1日 または 15日) かつ 日曜日" ではないということですね
job_add() がキューにジョブを追加する関数です
cron.c 556行目
〜 省略 〜 /* the dom/dow situation is odd. '* * 1,15 * Sun' will run on the * first and fifteenth AND every Sunday; '* * * * Sun' will run *only* * on Sundays; '* * 1,15 * *' will run *only* the 1st and 15th. this * is why we keep 'e->dow_star' and 'e->dom_star'. yes, it's bizarre. * like many bizarre things, it's the standard. */ for (u = db->head; u != NULL; u = u->next) { for (e = u->crontab; e != NULL; e = e->next) { time_t virtualSecond = (vtime - e->delay) * SECONDS_PER_MINUTE; time_t virtualGMTSecond = virtualSecond - vGMToff; job_tz = env_get("CRON_TZ", e->envp); maketime(job_tz, orig_tz); /* here we test whether time is NOW */ if (bit_test(e->minute, minute) && bit_test(e->hour, hour) && bit_test(e->month, month) && (((e->flags & DOM_STAR) || (e->flags & DOW_STAR)) ? (bit_test(e->dow, dow) && bit_test(e->dom, dom)) : (bit_test(e->dow, dow) || bit_test(e->dom, dom)) ) ) { if (job_tz != NULL && vGMToff != GMToff) /* do not try to run the jobs from different timezones * during the DST switch of the default timezone. */ continue; if ((doNonWild && !(e->flags & (MIN_STAR | HR_STAR))) || (doWild && (e->flags & (MIN_STAR | HR_STAR)))) job_add(e, u); /*will add job, if it isn't in queue already for NOW. */ } } 〜 省略 〜
job_runqueue() の中身
jhead は job_add() でジョブを追加したキューの先頭を指しています
そこから1つづつ do_command() を実行していきます
job.c 95行目
int job_runqueue(void) { job *j, *jn; int run = 0; for (j = jhead; j; j = jn) { do_command(j->e, j->u); jn = j->next; free(j); run++; } jhead = jtail = NULL; return (run); }
do_command() の中身
ジョブを実行する部分のコードです
ジョブの時刻はフォークして子プロセスで実行していることがわかります
なので、複数のジョブが設定されている場合でもフォークされて並列に実行されることになります
do_command.c 46行目
void do_command(entry * e, user * u) { pid_t pid = getpid(); int ev; char **jobenv = 0L; Debug(DPROC, ("[%ld] do_command(%s, (%s,%ld,%ld))\n", (long) pid, e->cmd, u->name, (long) e->pwd->pw_uid, (long) e->pwd->pw_gid)); /* fork to become asynchronous -- parent process is done immediately, * and continues to run the normal cron code, which means return to * tick(). the child and grandchild don't leave this function, alive. * * vfork() is unsuitable, since we have much to do, and the parent * needs to be able to run off and fork other processes. */ switch (fork()) { case -1: log_it("CRON", pid, "CAN'T FORK", "do_command", errno); break; case 0: /* child process */ acquire_daemonlock(1); /* Set up the Red Hat security context for both mail/minder and job processes: */ if (cron_set_job_security_context(e, u, &jobenv) != 0) { _exit(ERROR_EXIT); } ev = child_process(e, jobenv); #ifdef WITH_PAM cron_close_pam(); #endif env_free(jobenv); Debug(DPROC, ("[%ld] child process done, exiting\n", (long) getpid())); _exit(ev); break; default: /* parent process */ break; } Debug(DPROC, ("[%ld] main process returning to work\n", (long) pid)); }
4. まとめ
結局のところ crond の起動中に時刻が修正された場合、しばらく経てば元の状態に戻ることが分かりました
ですが、時刻が変わった直後はジョブが実行されなかったり、想定していなかったジョブが実行される場合があることが分かりました
時刻の修正が数分程度であればあまり気にすることはないと思いますが、大幅な時刻の修正やタイムゾーンの変更をする場合は念のため
- crond の停止
- 時刻の変更
- crond の起動
とした方が不本意にジョブが実行されることがないので安全ですね
運用に乗っている環境で時刻の変更を行う場合は気を付けた方が良さそうです
僕は日本で運用しているシステムしか見たことがないので今までサマータイムを気にしたことはなかったですが、まさか処理中にここまで意識されていると思わなかったです
軽く調べたら、サマータイムに入る時は時計を1時間進めるらしく AM 1:59:59 の次が AM 3:00:00 になるらしいです
逆にサマータイムが終わるときは1時間戻す必要があるので AM 1:59:59 の次が AM 1:00:00 になるそうで、なんとその日は AM 1時台が2回来るらしいです・・・!
なのでサマータイムが切り替わるときは AM 1:00:00 と書いてもどっちの時刻なのかは分からないので、サマータイム中の1時は AM 1:00:00(DT) 、サマータイム終了後の1時は AM 1:00:00(ST) と書くことで区別するそうです
※DT: Daylight Time、ST: Standard Time
軽く想像しただけでヤバいですね
サマータイムが適用されている国のエンジニア達は毎年2回はアツいということですかね
今回は cron のソースを通してそんな異国のエンジニア達の苦悩を垣間見たような気がしました