現象：cron実行すると実行時間が実際とずれる

MySQLのテーブルを更新するスクリプトをcronで実行していた。
更新時間を記録するカラムにはMySQLのNOW()関数でそのときの時間を登録する。
コマンドラインでスクリプトを実行すると想定通りの更新時間が登録される。
しかし、cronからそのスクリプトを実行するとNOW()の更新時間がずれる。

cronの実行時間を確認

cronの設定はこのようになっていた。

$ crontab -l
11 8 * * * /bin/sh /path/to/script.sh

毎日8時11分に実行しているはずだ。

/var/log/syslogにはCRON実行のログが出ている。

Nov 27 08:11:01 myhost CRON[16243]: (user) CMD (/bin/sh /path/to/script.sh)

実行は11/27の8:11なのに、DBに登録される時間は17:11。9時間ズレている。

試しにcronでtimeコマンドを実行してみる。
5分毎に/tmp/time.logに時間を出力する。

*/5 * * * * echo `date` >> /tmp/time.log

time.logファイルにはJSTの時間が出力されていた。

$ cat /tmp/time.log 
Mon Nov 28 09:40:01 JST 2016

もう一度syslogを見てみる。

Nov 28 00:40:01 myhost CRON[15970]: (user) CMD (echo `date` >> /tmp/time.log)

cronの実行時間がJSTになっていない。cronの時計がおかしいようだ。

cronサーバを再起動

問題のサーバのタイムゾーンは最初UTCだったが、それをJSTに設定変更していた。
しかしサーバ自体を再起動していなかったのか、cronサービスの時間は反映されていないようだった。
cronサービスを再起動してみる。

$ sudo service cron restart

cronサービス再起動の後にsyslogを見るとJSTでログが出ていた。解決。

Nov 28 09:50:01 myhost CRON[15970]: (user) CMD (echo `date` >> /tmp/time.log)

教訓：タイムゾーンを変更したらサーバを再起動すること。