フレクトのHeroku Lab

こんにちは。珍しくHerokuではまったのでその顛末を書いておきます。
しかも間抜けなことに同じ問題で2回はまりました。。。(--

さて、それがどういう問題だったかと言うと。。。

Procfileの行末がCRLFだとDynoが正しく起動できなくなる。

というものです。(--
これ、最初から動かなかったわけではなくて少なくとも12月の中旬ごろまでは間違いなく動いていました。
それが何かの修正のタイミングで行末がCRLFだった場合は最後のCRをコマンドの一部として実行するようになったようです。

最初から動いてなければそういうものとして納得することができるんですが、ある日突然動かなくなったので非常に焦りました。
現象の現れ方としては最初に書いたとおり2パターンありました。

★パターン1 - アプリが起動しない

あるアプリに1カ月ぶり位にちょっとした修正を加えてgit pushしたところいきなりアプリが起動しなくなりました。
何故かログには「NoClassDefFoundError: 」とか出力されて止まっています。
修正自体はささいなものだったので、それが原因とは考えられず最初は何が起こっているのかまったくわかりませんでした。

原因を追究するよりも先にまずはアプリを起動状態に戻さなければならなかったので修正をリバートしたものをgit pushしたんですが状況は改善しません。(--
なかば途方にくれながら今まで一度も使ったことがないコマンド「heroku releases:rollback」を使用して以前のバージョンに戻すとようやく起動するようになりました。

□□□□

話は少しそれますが、この「heroku releases:rollback」というコマンドはコンパイル済みのスラグと環境変数一式をどこかにとっておいてまるっと差し替えるコマンドのようです。
Git repository自体には手が入らないので次回にgit pushした時にはまた最新のrepositoryから新しいスラグが作成されます。(ただし環境変数はそのまま)

動作原理がわかっているといざという時に迷わず使えて便利そうではあります。抑えておいて損はないコマンドだと思います。
(途中にAddOnの追加があった場合はどうなるんだろうという疑問はありますけど。)

□□□□

さて、これでとりあえずアプリは動作するようになったわけですが、原因を調べようにもちょっとした変更をgit pushするだけでもれなくクラッシュするのでまたしても途方にくれてしまいます。(--
この時点でHerokuのサポートにあげても良かったんですが、もうちょっと自分で調べようと思い新しいHerokuアプリを作成してそっちにソース一式をpushして調査を継続することにしました。こういうことが手軽にできるのはHerokuの良いところではありますね。(と、フォローしてみる)

そんなこんなで紆余曲折、艱難辛苦の末にたどりついた原因がProcfileだったわけですが、これには本気で脱力しました。。。(--

その時のProcfileがこれ。

web: play run --http.port=$PORT $PLAY_OPTS <CRLF>

改行コードがCRLFであることと行末にスペースが入っていることがポイントです。
playコマンドの最後の引数として単独の「<CR>」が渡されていて、それがクラス名表示のないNoClassDefErrorを引き起こしていたらしい。。。。(--
マジでか！！！

HerokuがLinux上で動くプロダクトである以上、あらゆるファイルの改行コードはLFで統一すべきという指摘はもっともだと思うし、実際エディタの設定等は気をつけてはいるんですが、Procfileはすっかりechoとリダイレクトで作成する習慣がついていたので気が付かなかったんですよね。。。

先にも書きましたがこれが最初から起こっていた現象であるなら特に文句はありません。
しかし、ある日突然動かなくなったら「こんなの気づきっこねー」と愚痴のひとつも言いたくなるというものです。

結局この日はここまでで力尽きて帰りました。

★パターン2 - アプリの起動が重くなる

さて、今にして思えばこの時点ですべてのHerokuアプリのProcfileを見直しておけば良かったんですが、何しろその日はやろうと思っていたことが何一つできなかったので次の日はそれどころではありません。一応Herokuのサポートにレポートをあげたんですが、あっさりと「ごめん、直しとく」みたいな返答がきたこともあってこの問題については自分の中ですっかりかたがついてしまっていました。

そうこうしているうちに別のアプリでやけに起動に時間がかかるという問題に気が付きます。具体的には以下のような現象が発生していました。

• git pushや環境変数の変更後ブラウザからの応答が長時間なくなる
• ログを見るとR10(Boot timeout)がしばしば記録されている。つまりHerokuがDyno起動をリクエストした後1分間起動が完了せずに再起動を繰り返すことがある
• たまに起動直後からR14(Memory quota exceeded)が記録されることがある。起動直後に大きなメモリを使用するような処理はないので明らかにおかしい

これも最初原因がわからなかったんですが、再起動時のログをtailで眺めていると常に「Precompiling...」というログを出力した後で一度ログの流れが止まることに気が付きました。あれ？起動時にPrecompileとかって走るんだっけ？？？

□□□□

で、調べてみるとPrecompileはPRODモードでかつ起動オプションに「-Dprecompiled=true」が指定されていない時に実行されることがわかりました。しかし、「-Dprecompiled=true」は環境変数のPLAY_OPTSで指定されているはず。
ということでもう一回Procfileです。

web: play run --http.port=$PORT $PLAY_OPTS<CRLF>

前のと同じに見えますか？(^^;
いえ、今回はCRLFの前にスペースがないことがポイントです。

環境変数「PLAY_OPTS」の末尾は「-Dprecompiled=true」となっていますが、これが行末のCRと結合して「-Dprecompiled=true<CR>」として引数化され、結果precompiled=trueとは解釈されないという。。。(--
またお前かよ！

実のところ2回目は問題解決にそれほど大きく時間を取られたわけではないのですが、脱力のあまりこのブログを書き始めてしまったので結局結構な時間が。。。。(--

まぁ別にいいんですけどね。(^^;;;