webエンジニアの日常

RubyやPython, JSなど、IT関連の記事を書いています

railsのログローテーションで新しくファイルが作られないときにやったこと

はじめに

railsアプリのログを毎日ローテーションしようと開発環境で試したいたときにはまってしまったので、その解決方法を書いておきます。

開発環境は、

windows7vagrant上にcentosをたてて、railsアプリを動かしている。

ソースコードwindows上にあって、vagrantとフォルダを同期させている。

という感じです。

railsでログを毎日ローテーションさせるには、

  config.logger = Logger.new("log/development.log", "daily")

とすればのですが、、、

日付をまたいだところでdevelopment.logへの書き込みは行われず、development.log.20170728みたいなファイルも作られませんでした。

何が起きていたか

railsではログを標準出力へ出していくのと同時に、development.logへログを書き出していきます。

上記のように毎日ローテーションする設定になっていると、日付をまたいで、その日はじめてのログを書き込むタイミングで、development.logがdevelopment.log.20170728みたいな日付入りのファイル名へリネームされます。

次に新しくdevelopment.logが作られ、ログは常にdevelopment.logという名前のファイルへ書き込まれていきます。

エラーが起こっていたのは、ここ

development.logがdevelopment.log.20170728みたいな日付入りのファイル名へリネーム

このタイミングで

log rotation inter-process lock failed. Text file busy @ rb_file_s_rename - (log/development.log, log/development.log.20170728)

というエラーが出ていました。

その後、ログをファイルへ書き出そうとすると、

log writing failed. closed stream

というエラーが表示されます。

解決方法

調べたところ、windowsvagrantとファイルを同期していることで、常にファイルが参照されている状態になっていて、リネームしようとすると、Text File busyになってしまうのが原因のようです。

解決策1 ~ vagrantとの同期方法をrsyncにする ~

MinGWrsyncsshをインストールして)Vagrantfileの同期ファイルを設定しているところで同期のタイプをrsyncにするとエラーが出ずにローテーション出来るようです。

これは、rsyncvagrant up, vagrant reloadなどのタイミングで実行され、常にファイルを監視していないためです。

vagrantfileは以下のようにtype: “rsync"を追加します。

  config.vm.synced_folder ".", "/vagrant/rails_app", create: true, owner: "vagrant", group: "vagrant", type: "rsync"

私も最初この方法を試してみましたが、いろいろなところで引っかかり、vagrant upが出来るようになるまで予想以上に時間がかかりました。最終的にrails sでエラーが出てあきらめました。

解決策2 ~同期しないようにする~

結局シンプルに悪さの元である同期をしないようにしました。

vagrant側の同期ディレクトリが/vagrant/rails_appだとすると、

cd ~
cp -r /vagrant/rails_app .

です。

この状態でアプリを動かして、日付をまたぐと、ちゃんとdevelopment.log.20170728という名前のファイルができていました。

ただし、ログの設定を変えて試すときは、またコピーして試さないといけないので、100%の解決では無いです。 (注) あくまでも今の設定でローテーションできるかどうか試すだけです。