今回はCentOSで遭遇した事象についての原因と調査内容の共有です。
11/17時点でまだ解決していません。
今後も調査を続け続報をアップする予定ですが、お気付きのことがありましたらアドバイス頂けると助かります。
11/19解決しました！！
何が起きている？
シェルにログインして直接起動すると問題なく動くシェルスクリプトがあるのですが、
これを定期実行しようとcronに登録したところ、エラーが出て動かないという事象に遭遇しました。
問題が発生している環境
# vi /etc/redhat-release CentOS Linux release 7.3.1611 (Core)
これまで調べたこと
1. cronが起動しているかの確認
# systemctl status crond.service ● crond.service - Command Scheduler Loaded: loaded (/usr/lib/systemd/system/crond.service; enabled; vendor preset: enabled) Active: active (running) since 日 2017-10-01 08:38:55 JST; 1 months 17 days ago
動いてます。
2. スクリプトのパーミッションの確認
# ls -al /usr/local/bin/hoge.sh -rwxr-xr-x 1 root root 334 11月 17 21:31 /usr/local/bin/hoge.sh
パーミッションが755ですので誰でも実行可能なはずです。
3. エラーになったコマンドのログの確認
以下、ログファイルの内容
2017/11/17 19:00:00 process started. /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require': cannot load such file -- iconv (LoadError)
(以下、省略)
iconvが見つからないようです。
4. iconvの確認
# which iconv /usr/bin/iconv
/usr/binの下にあります。
5. PATHの確認
※cronの実行ユーザで確認しています。
echo $PATH /user-name/.rbenv/shims:/user-name/.rbenv/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/user-name/bin
/usr/binにもパスが通っています。
6. cron実行時のPATHの確認
cronに1分ごとにPATHを書き出すコマンドを設定して待機します。
# crontab -e */1 * * * * /bin/bash -l -c 'echo $PATH >> /tmp/path.txt'
１分後、cronが動いてファイルが作成されたので中身を確認します。
/user-name/.rbenv/shims:/user-name/.rbenv/bin:/usr/local/sbin:/usr/sbin:/usr/bin:/bin:/user-name/bin
並べてみましょう。
上が対話型ログイン状態でのPATH、下がcron時のPATHです。
/user-name/.rbenv/shims:/user-name/.rbenv/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/user-name/bin
/user-name/.rbenv/shims:/user-name/.rbenv/bin:/usr/local/sbin:/usr/sbin:/usr/bin:/bin:/user-name/bin
違いが2点ありました。
1つ目は、対話型の時には「/usr/local/bin」にパスが通っていますが、cron時には通っていません。
2つ目は、対話型の時には「/bin」にパスが通っていませんが、cron時には通っています。
今回はcronで動かないことが問題なので1つ目の方が怪しいです。
1.でも書いたように、今回起動したいスクリプトは「/usr/local/bin」の下にあります。
やはりhoge.shが実行できていないのでは？との錯覚に陥りましたが、
3.に書いたログの1行目「2017/10/04 04:03:01 process started.」はhoge.shの中で出力するように記述しているものですので、hoge.shは確実に起動しています。
もしかすると、hoge.shから呼んでいる処理の中で何らか「/usr/local/bin」の下のプログラムをパスなしで使おうとしているものがあるのかも知れません。
一縷の望みを託してhoge.shの頭に次の1行を追加してみます。
export PATH=$PATH:/usr/local/bin
7. cronの再実行を待つ
2017/11/17 22:03:01 process started.
/usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require': cannot load such file -- iconv (LoadError)
ダメでした。。。
----- 11/19追記 -----
8. rubyを疑う
今回動かしたいスクリプトはシェルからrubyのプログラムを読んでおり、そのプログラムの中でiconvを見つけられないようなのですが、rubyにちょっと事情があったことに気が付きました。
対象サーバにはrbenvが入っており、2.4.1がデフォルトになっているのですが、今回呼び出しているスクリプトは、1.8.7じゃないと動かない仕様のため、シェルからスクリプトを呼び出すときにバージョンを指定して実行しています。
実際には以下の呼び出し方をしていました。
RBENV_VERSION=1.8.7-p375 /path-to-program/program.rb
ネット上で色々調べてみると、以下のように1.8.7のrubyプログラムを直接起動するやり方があるようなので、これを試してみることにします。
/user-name/.rbenv/versions/1.8.7-p375/bin/ruby /path-to-program/program.rb
結果は、、
動きました！！！
以下、ログファイルの中身
2017/11/19 04:00:00 process started.
2017/11/19 04:15:32 process finished.
改めて考えると、バージョンを指定してrubyを起動するのに環境変数を書き換えるのはちょっと乱暴すぎる気がします。
なんで今までこのやり方を良しと思ったのかは自分でも謎ですが、修正後のように、プログラムに引く数を渡して実行する方が常識的な感じがしますね（後だしならなんとでも言える）。
とにかく、動いて良かったです。以上解決！！！
9. あとがき
プログラムが動いたことで課題は解決したのですが、その後調べていた中で１点疑問が残りました。
どうやら今回のエラーは、rubyのバージョンの指定方法が拙かった以前に、cronの中でrbenvを認識できていないことが根底にあるようでした。
対話ログインした状態では、
# which rbenv /user-name/.rbenv/bin/rbenv
とパスが返ってきますが、
cronで呼び出すシェルスクリプトの中にwhich rbenvを仕掛けて実行すると、
/usr/local/bin/hoge.sh: 行 6: rbenv: コマンドが見つかりません
となり、そもそものrbenvにパスが取っていないことが分かりました。
rbenvがある「/user-name/.rbenv/bin」にはcron時にもパスが通っていることは確認できているので、まだ何か問題が残っているようですが、当初の課題は解決したのでこれ以上の調査はペンディングにします。