もろず blog

もろちゃんがITに関しての様々なトピックを解説します


cron の意外な落とし穴!



f:id:chanmoro999:20150317014415j:plain

システムを運用していく上で 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 の超ざっくり版処理フローを書いてみました
実際は細かい処理もっとが入ってますが、ポイントになりそうな部分だけ抜き出してます

f:id:chanmoro999:20150317012619j:plain

時刻の基準について

cron 内部ではいくつかの時刻を保持していますが全て GMT に変換してから計算された値が保持されています
また、現在時刻から GMT への変換はタイムゾーンのオフセット値を加算・減算することで変換していることが分かりました

タイムゾーンの取得について

タイムゾーンは crond の起動時にのみ実行環境に設定されている値を取得しています

起動後にはタイムゾーンの更新は行われないので crond の起動後にタイムゾーンを変更しても変更前のタイムゾーンのまま動作します

例外として、crond の起動中にサマータイムに切り替わった時のみタイムゾーンのオフセットを更新するようになっていました

ジョブチェックの間隔

実行対象のジョブをチェックする間隔は1分間でした
チェックが終わったら1分経つまでの間スリープしています

厳密には、次の分までの秒数+1秒 の間スリープするよう実装されていました
開始された時刻が 00:00:30 だった場合には 00:01:01 までの31秒間スリープすることになります

なので、ジョブが開始されるのは厳密に0秒というわけではないんですね

ジョブチェック 〜 ジョブ実行までの詳細

対象の時刻に実行対象のジョブがあるかをチェックし実行するジョブがあればジョブをキューに追加します

ただ、この処理の中に想定してなかったロジックが入っていることが分かりました

前回のジョブチェック時の時間を保持しておき、実際にどれだけ時間が経過したかをジョブチェックの都度計算しています
そして、実際に経過した時間によってキューにジョブを追加する処理が異なることがわかりました


普通に動けば必ず1分にしかならないはずですが、どういうことなのかを見ていきましょう

差分が 1分 の場合

通常の動作はほとんどがこの場合です
この場合は、現在時刻に実行される予定のジョブを全て実行キューに追加します

f:id:chanmoro999:20150312170356j:plain

差分が 0〜5分 の場合

ジョブの実行間隔が1分より少しだけ過ぎてしまった場合です
サーバーの負荷状況などで多少実行が遅れた場合が考えられます

基準の時刻を1分づつ進めながら、遅れた分の時間に実行する予定のジョブを全てキューに追加しジョブ実行もこの処理の中で実行します

f:id:chanmoro999:20150312170406j:plain

差分が 5分〜3時間 の場合

さらに大きいジョブの遅延が発生した場合です
ここではサマータイムが始まった時にシステム時刻を進めた場合を想定しているようです


ここでも基準の時刻を1分づつ進めながら遅れたジョブを全てキューに追加し実行しますが、この場合だけリカバリの処理が可能な時間がなぜか1分間に限られています

そして、もし遅れたジョブをキューに追加する処理が1分を超えてしまった場合には、残されたジョブは全てスキップされます


また、この場合の処理では定時に設定しているジョブのみが実行され、ワイルドカードに設定しているジョブはスキップされるようになっています
ワイルドカードのジョブの場合は時刻を進めても同じタイミングで実行されるので影響はないと判断し、定時のジョブのみリカバリする、という考えのようです

f:id:chanmoro999:20150312170444j:plain
※定時、ワイルドカードと書いてるのはそれぞれこんな設定のジョブを指してます
定時のジョブ
0 0 * * * hoge
ワイルドカードのジョブ
0 * * * * fuga または * 0 * * * fuga

差分が 0分〜-3時間 の場合

前回のジョブチェック時刻よりも現在時刻が過去になっている場合です
サマータイムが終わった時にシステム時刻を戻した場合を想定しているようです

基準の時刻が過去になっているため、基準の時刻が前回のジョブチェック時間に自然に追いつくまでワイルドカードのジョブのみ実行します
この場合の処理では内部の時計を無理やり進めたり戻すことはしない変わりに、前回のジョブチェック時間を更新せずに "自然に" 基準の時刻が追いつくまで保持し続けます

また、ここでは定刻のジョブは "実行済み" として扱うようなので、追いつくまでの時間に設定された定刻ジョブは実行されません

f:id:chanmoro999:20150312170455j:plain

上記以外

±3時間以上ズレが発生していた場合は内部の時計を現在時刻に合わせてリセットします
ジョブのリカバリは一切せずに、間の時間はなかったことにしているようです

f:id:chanmoro999:20150312170508j:plain


今回の問題となっていた動作の原因

いままで説明した部分から、crond の起動中にシステム時刻を変更した場合にはジョブの実行がスキップされる動作をするということがわかりました

そのため、ntpdate で時刻を変更した場合にはどれくらい時間を進めた or 戻したかによって挙動が異なるということです


問題の動作が見つかった時には、定刻のジョブを cron で設定している状態で ntpdate で時刻をジョブの設定時刻より前に戻していました
つまり、ジョブチェック時の差分が 0分〜-3時間 の場合にあてはまっていたのでジョブが実行されないパターンだったということがわかりました


ちょっと言葉だけだと説明が難しいですね

それでは次に、説明した部分のソースを見ていきましょう


記事の先頭に戻る



3. cron のソースを見よう

先ほど言葉で説明した処理のソースを見ていきましょう

まず、cron の内部で利用されている時刻の変数をまとめました
ソースを追ってくうちにどれがどれか分からなくなるので見失ったらこれを見てください

f:id:chanmoro999:20150312185223j:plain

また、最初の方に載せた処理フローも確認しながらソースを追ってみてください


現在時刻を取得 & タイムゾーンのオフセット計算

処理フロー中は現在時刻の取得とオフセット計算を別々の処理として書きましたが、実際は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分 と比べて以下の違いがあります

  1. find_jobs() の引数が異なる
  2. 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 の起動中に時刻が修正された場合、しばらく経てば元の状態に戻ることが分かりました
ですが、時刻が変わった直後はジョブが実行されなかったり、想定していなかったジョブが実行される場合があることが分かりました

時刻の修正が数分程度であればあまり気にすることはないと思いますが、大幅な時刻の修正やタイムゾーンの変更をする場合は念のため

  1. crond の停止
  2. 時刻の変更
  3. 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 のソースを通してそんな異国のエンジニア達の苦悩を垣間見たような気がしました


記事の先頭に戻る