Icon kobu medium
Kota Miyake

cronが動かない原因を探る

個人的に作成しているRailsアプリで、cronを使ってタスクを実行しようとしたのですが、うまくいかないので原因を調べてみました。

cronの実行ログを確認してみると実行はされているようでした。

$ sudo tail -f /var/log/cron.log

どうやらタスク自体の実行がうまくいっていない様子。

cronのログはcron自体が実行できたかどうかしか出力しないということなので、標準エラーをファイルに書き出すよう設定して確認することにします。

$ command 2>> /tmp/cron-error.log

無事?出力されたエラーを確認してみると、どうやらgemへのパスが上手く通っていないということがわかりました。

/bin/bash: bundle: コマンドが見つかりません

タスクの実行前にrbenvを初期してあげる必要があるみたいです。

job_type :rake, "export PATH=\"$HOME/.rbenv/bin:$PATH\"; eval \"$(rbenv init -)\"; cd :path && RAILS_ENV=:environment bundle exec rake :task --silent :output”

これで無事タスクが実行されました。

Icon kobu medium
Kota Miyake

Rails4.2.8.rc1のMessageVerifierでハマる

ついにRuby2.4に対応したRails4.2.8.rc1がリリースされたので、社内のプロジェクトでさっそくアップデートを試してみました。

gem 'rails', '4.2.8.rc1'
$ bundle update rails

とりあえずテストを流してみたのですが、いくつかテストが失敗してしましました。。。

どうやらトークンがデータベースで用意しているカラムの長さを超えてしまったようです。

ActiveRecord::StatementInvalid:
Mysql2::Error: Data too long for column 'token' at row 1

ちなみにトークンを生成しているロジックは以下のような感じです。

Rails.application.message_verifier(:invitation).generate([1, Time.current])

失敗しているはずのテストが、なぜか単体で動かすと成功するという謎の挙動をしていました。

細かくテストを実行していったところ、どうやらタイムゾーンが変わる部分のテスト以降で落ちているようだったので、コンソールでタイムゾーンを切り替えて結果がどうなるか実行してみました。

pry(main)> Time.zone = 'UTC'
=> "UTC"
pry(main)> Rails.application.message_verifier(:invitation).generate([1, Time.current])
=> "BAhbB2kGVTogQWN0aXZlU3VwcG9ydDo6VGltZVdpdGhab25lWwhJdToJVGltZQ2qRR3ARpubjAY6CXpvbmVJIghVVEMGOgZFRkkiCFVUQwY7CFRACQ==--37c53d559cbb466f31e5cfcc5c11404280264b1f"
pry(main)> Time.zone = 'Tokyo'
=> "Tokyo"
pry(main)> (:invitation).generate([1, Time.current])
=> "BAhbB2kGVTogQWN0aXZlU3VwcG9ydDo6VGltZVdpdGhab25lWwhJdToJVGltZQ2qRR3A4swAjQc6CXpvbmVJIghVVEMGOgZFRjohQF90b190aW1lX3dpdGhfc3lzdGVtX29mZnNldEl1OwYNqkUdgOLMAI0HOgtvZmZzZXRpApB+OwdJIghKU1QGOwhGSSIKVG9reW8GOwhUdTsGDbNFHcDizACN--3f02bc96b451c582679e7fab998f49a36359822d"

なんとタイムゾーンにTokyoを指定したらトークンの長さが結構な長さになってしまいました。

今度はMessageVerifierがどのようにトークンを生成しているか見てみることにしました。

Rails::Application::message_verifier

secretを生成してActiveSupport::MessageVerifierのインスタンスを生成します。

ActiveSupport::MessageVerifier#generate

ここで渡された値を指定されたSerializer(デフォルトではMarshal)でdumpして、結果をBase64でエンコードしています。

とりあえず一番深い場所にあるMarshal#dumpしている部分をタイムゾーンを変えて実行してみました。

pry(main)> Time.zone = 'UTC'
=> "UTC"
pry(main)> Marshal.dump([1, Time.current])
"\x04\b[\ai\x06U: ActiveSupport::TimeWithZone[\bIu:\tTime\r\xABE\x1D\xC0\xBAm[\x03\x06:\tzoneI\"\bUTC\x06:\x06EFI\"\bUTC\x06;\bT@\t"
pry(main)> Time.zone = 'Tokyo'
=> "Tokyo"
pry(main)> Marshal.dump([1, Time.current])
=> "\x04\b[\ai\x06U: ActiveSupport::TimeWithZone[\bIu:\tTime\r\xABE\x1D\xC0\xD2\x85\x1D\x04\a:\tzoneI\"\bUTC\x06:\x06EF:!@_to_time_with_system_offsetIu;\x06\r\xABE\x1D\x80\xD2\x85\x1D\x04\a:\voffseti\x02\x90~;\aI\"\bJST\x06;\bFI\"\n" +
"Tokyo\x06;\bTu;\x06\r\xB4E\x1D\xC0\xD2\x85\x1D\x04"

以前は問題なかったということは、どうやらActiveSupport::TimeWithZoneの挙動が変わったようです。

コミットログを見てみると、どうやらそれらしきものを発見。

Cache to_time to improve performance when comparing

詳細はいまいちわかっていないのですが、どうやらgetlocalした結果をキャッシュするようにしたようです。

そこで追加された変数(@_to_time_with_system_offset)がdumpした時に残っているので、今回のようにトークンの長さが大きく変わってしまったようです。

ActiveSupport::MessageVerifierではなくタイムゾーン関連の変更が原因だったというお話。

Icon kobu medium
Kota Miyake

warning: parser/current is loading parser/ruby24, which recognizes

こちらの記事に対して、別件でwarningがでているがどうやったら止めることができるかわかるか、と言った趣旨のコメントをいただいたきました。

自分も特に気にせずさらっと流していたが、せっかくなのでちょっと調べてみました。

https://github.com/whitequark/parser

説明を読む限りではpure rubyで書かれたrubyパーサーのようです。

そして原因となるwarningを発しているのが以下のソースになります。

https://github.com/whitequark/parser/blob/master/lib/parser/current.rb

どうやらリリース済みの最新のマイナーバージョンが使用されていないとwarningを出すようになっているようです。

直接的にこちらのgemを使用しているわけではないのですが、reekの中で使われており、その際にプロジェクトで使われているrubyのバージョンが古いため、parserが参照しているバージョンと違うぞということでwarningを出しているようです。

reekのmasterブランチのgemspecでまだ2.3.x.xを指しているので、rubyの2.4.0を使っているとwarningが発生するかと思います。

こういったwarningもそのままにせずちゃんとfixさせる、もしくはちゃんと原因を把握しておかないといけないなと思いました。

Icon kobu medium
Kota Miyake

monitを導入する

仕事でも触る機会があったmonitを自分でも使ってみることにしました。

サーバーにmonitが入っていなかったのでインストールするところから。

capistrano-pumaには、既にmonit用のタスクがあるようなのでそちらを使ってみました。

ただ、capistrano-pumaのバグやmonitをsudo権限で動かさないといけない関係上、色々とハマりました。。。

まずはcapistrano-puma自体が最初のデプロイにちゃんと対応できていなかったようです。

そのため、まだmonitで監視を始めていないのにunmonitorを実行としようとしてエラーになってしまいました。

この問題はmasterでは修正されているようです。

https://github.com/seuros/capistrano-puma/commit/373f03a82c16195938cf4b9b06b3b9c3ed52b0b5

仕方がないので、以下の手順で初回の設定を行いました。

1. ローカルでタスクを実行(bundle exec cap production puma:monit:config)して設定ファイルをアップロード

2. 手動でmonitをリロードして監視を開始

設定ファイルの移動とmonitの起動にsudo権限が必要だったのでvisudoでデプロイユーザーがパスワード無しでコマンドを実行できるよう設定しました。(mvの権限は設定ファイル設置後に削除)

とりあえず、これでmonitでpumaのプロセス監視ができるようになりました。