Redmineバージョンアップ記録

Redmine Advent Calendar jp 2011 の21日目の記事になります。

前回のPOSTで、「（バージョンアップ）移行の顛末は、何かで発表したいなあと思います」と書いておきましたが、今回話題が思いつかなかったことと、本当は勉強会でお話しできるといいのですが、参加自体が難しいので、アドベントカレンダーに便乗して書かせていただきます。

長めになってしまい申し訳ないのですが、こんな流れになっています。

1. 移行前後の実行環境
2. 移行の準備 / 動作確認
3. nginx + unicornについて
4. ログのローテーション
5. 移行後のフォロー
6. まとめ

1. 移行前後の実行環境

移行前は、Redmine 0.9.xを利用していました。

1系が出てからだいぶ経つので、バージョンアップはしたいなあ～と思っていたものの、本体ソースにカスタマイズ分が入っていたり、ユーザが増加していたため、なかなか移行に切り出せませんでした。(管理は別の方の担当だったので)

大きな問題はなかったので、そのまま利用していたのですが、PDF出力の利用が増えるに伴い、ある特定のチケットのPDFを出力しようとするとCPUが回りっぱなしで、あげくにタイムアウトしてしまうという状況が発生するようになりました。

さすがにこれでは困る、ということで、リソースの見直しも含めてバージョンアップの検討に入りました。

2. 移行の準備 / 動作確認

今回はRailsの実行環境も大幅に違います。本番サーバには不足しているライブラリがたくさんありましたが、インターネットからのダウンロードは使えない状況。OSも32bitだったので、別サーバで環境を用意し、DNS切り替えで新環境への移行という方法を取りました。

まずはRedmine0.9に対してカスタマイズした部分の洗い出し、新バージョンでのプラグインの互換性のチェックを行いました。
Redmine本体のバージョンが上がったため機能が向上し、プラグインでカバーする必要が無くなったものもあるので、利用しなくて良さそうなプラグインは削除。管理に役立ちそうなプラグインは追加で導入しました。

また、カスタマイズしていた部分は、出来るだけ自作プラグインや自作テーマという形で置き換えるようにしました。このあたりは、r-labsの記載や既存のソースを参考にさせていただきました。

その上で、どうしても本体をカスタマイズしないといけない部分は、Redmine本家に取り込んでもらえるようにお願いをしたりしました。

問題なくバージョンアップが出来るか、もちろん、テスト環境で本番のデータをコピーして検証をし、ユーザさんにもお願いして不具合の洗い出しを行っています。不具合や要望はRedmineのフォーラムに届け出てもらうようにしました。

最低限の本体へのカスタマイズ（１行だけ）で、あとはプラグインでの対応が可能との目処がついたので、いよいよ本番切り替えの準備。

データの同期とDNSキャッシュのクリアの時間を鑑み、ユーザさんには一定時間Redmineが使えませんよ、とのお知らせをしています。

その上で、移行日までは、正常にマイグレーションや起動ができるか、本番サーバと同じネットワーク上で切り替え予定のサーバを待機させて、定期的にファイル・DBの同期とRedmineのMigration、メッセージの書き換えを行い、読み取り専用で稼働させて、直近のデータを搭載しても問題ないかのチェックを行いました。

こちらはJenkinsを使ってファイル同期 –> DB同期 –> Migration –> PluginのMigration –> unicorn再起動を、移行日時まで３時間おきに行いました。

待機しているRedmineは、バージョンアップ後のサンプルとして公開していました。
その際、Themeやデータがほぼ本番のRedmineと同じため、ユーザさんが混乱しないようになにか目印が必要…と考えて、今回は『バナー表示』をさせるプラグインを自作してみました。

ニュースやチケットだと、そのページにしかメッセージが表示されません。これでは注意を促しにくいということで、プロジェクトメニューの下とフッタに、サイト全体にわたってメッセージを表示させておきました。

3. nginx + unicornについて

Redmineの本体のバージョンアップ以外に、Railsの実行環境も変えています。

今後どう展開するのか分かりませんが、RVMの環境を用意しました。そして、Apache + Passengerから、nginx  + unicornへ乗り換えることにしました。

3-1. 設定はこんな感じ

プロセス数の見積もり等々、未経験だったのでどうしたものか迷いながら、下記のような設定で稼働を開始しました。

1. /etc/rc.d/init.d/unicorn

#!/bin/bash
#
# unicorn_rails_redmine Startup script for unicorn.
#
# chkconfig: - 85 15
# description: redmine on unicorn start/stop script.
#
# set rvm environment valiables.
#
[[ -s "$HOME/.rvm/scripts/rvm" ]] && . "$HOME/.rvm/scripts/rvm" # Load RVM function
set -u
set –e

APP_NAME=redmine
APP_ROOT="/var/service/$APP_NAME"
CNF="$APP_ROOT/config/unicorn.rb"
PID="$APP_ROOT/tmp/pids/unicorn.pid"
ENV=production
UNICORN='/usr/local/rvm/gems/ruby-1.8.7-p352/bin/unicorn_rails'

UNICORN_OPTS="-D -E $ENV -c $CNF"
old_pid="$PID.oldbin"
cd $APP_ROOT || exit 1

sig () {
        test -s "$PID" && kill -$1 `cat $PID`
}

oldsig () {
        test -s $old_pid && kill -$1 `cat $old_pid`
}

case ${1-help} in
start)
        sig 0 && echo >&2 "Already running" && exit 0
        echo "Starting"
        cd $APP_ROOT ; $UNICORN $UNICORN_OPTS
        ;;
stop)
        sig QUIT && echo "Stopping" && exit 0
        echo >&2 "Not running"
        ;;
force-stop)
        sig TERM && echo "Forcing a stop" && exit 0
        echo >&2 "Not running"
        ;;
restart|reload)
        sig USR2 && sleep 5 && oldsig QUIT && echo "Killing old master" `cat $old_pid` && exit 0
        echo >&2 "Couldn't reload, starting instead"
        $UNICORN $UNICORN_OPTS
        ;;
upgrade)
        sig USR2 && echo Upgraded && exit 0
        echo >&2 "Couldn't upgrade, starting instead"
        $UNICORN $UNICORN_OPTS
        ;;
rotate)
        sig USR1 && echo rotated logs OK && exit 0
        echo >&2 "Couldn't rotate logs" && exit 1
        ;;
*)
        echo >&2 "Usage: $0 <start|stop|restart|upgrade|rotate|force-stop>"
        exit 1
        ;;
esac

2. unicorn.rb

$unicorn_user = "redmine"
$unicorn_group = "redmine"
$default_env = "production"

$dev_processes = 4 # dev環境用子プロセス数
$prod_processes = 6 # 本番環境用子プロセス数。リソースに合わせて調整。
$timeout = 60 # タイムアウト秒数。タイムアウトしたslaveは再起動される

listen '/tmp/.unicorn.sock'
stderr_path File.expand_path('log/unicorn.log', ENV['RAILS_ROOT'])
stdout_path File.expand_path('log/unicorn.log', ENV['RAILS_ROOT'])

# Main Config for Unicorn
rails_env = ENV['RAILS_ENV'] || $default_env
worker_processes (rails_env == 'production' ? $prod_processes : $dev_processes)
preload_app true
timeout $timeout

# For RubyEnterpriseEdition: http://www.rubyenterpriseedition.com/faq.html#adapt_apps_for_cow
if GC.respond_to?(:copy_on_write_friendly=)
  GC.copy_on_write_friendly = true
end

before_fork do |server, worker|
  defined?(ActiveRecord::Base) and ActiveRecord::Base.connection.disconnect!

  old_pid = "#{ server.config[:pid] }.oldbin";
  unless old_pid == server.pid
    begin
      Process.kill :QUIT, File.read(old_pid).to_i
    rescue Errno::ENOENT, Errno::ESRCH
    end
  end
end

after_fork do |server, worker|
  defined?(ActiveRecord::Base) and ActiveRecord::Base.establish_connection

  # Ref. http://d.hatena.ne.jp/secondlife/20111006/1317893282
  #GC.disable if RAILS_ENV == 'production'

  begin
    uid, gid = Process.euid, Process.egid
    user, group = $unicorn_user, $unicorn_group
    ENV["HOME"] = "/home/redmine"
    target_uid = Etc.getpwnam(user).uid
    target_gid = Etc.getgrnam(group).gid
    worker.tmp.chown(target_uid, target_gid)
    if uid != target_uid or gid != target_gid
      Process.initgroups(user, target_gid)
      Process::GID.change_privilege(target_gid)
      Process::UID.change_privilege(target_uid)
    end
  rescue
    if RAILS_ENV = "development"
      STDERR.puts "could not change user, oh well"
    else
      raise e
    end
  end
end

3. nginxとの連携部分

upstream unicorn {
  server unix:/tmp/.unicorn.sock;
}

server {
  listen 80;
  root /var/service/redmine-1.2/public;
  access_log /var/log/nginx/redmine-access_log;
  error_log /var/log/nginx/redmine-error.log;
  location / {
#    allow 127.0.0.1;
#    allow 10.142.18.0/24;
#    deny all;
    client_max_body_size 20M;
    if (-f $request_filename) { break; }
    proxy_set_header X-Real-IP  $remote_addr;
    proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
    proxy_set_header Host $http_host;
    proxy_pass http://unicorn;
    proxy_read_timeout 60; # The same to unicorn's timeeout
    proxy_set_header X-FORWARDED-PROTO https;
  }
}

unicornに関しては、Redmineを稼働させている方の記事も沢山あるので、そちらを参考にしていただければと思います…。
また、基本的にこちらのサイトの設定、ソースを参考にさせていただきました。
（本当にありがとうございました！）

• 次世代RailsサーバーUnicornを使ってみた
• RailsサーバUnicornを飼いならす! 運用時の便利技

さて、unicornは、起動とマスタプロセスはrootですが、フォークしたあとはredmineというユーザで実行されます。RAILS_ROOTのOwnerはredmineに設定をして、問題なく稼働。

新しい環境も、メモリが潤沢にあるというわけでは無いので、プロセス数は実メモリ、Swapが起きない範囲で1プロセスあたりが利用できるメモリ、そしてレスポンスを見ながら調整していってます。

また、上記参考サイトのソース (unicorn_manager.rb) を利用させていただき、一定の値までメモリが大きくなったプロセスは再起動させるという処理をcronに組み込みました。

cronの結果は、外部ジョブの実行結果として、Jenkinsに記録をしています。

3-2. 荒ぶるUnicorn!!

nginx + unicornは、なんとかうまく行きそうだったので、調子にのって試したことが１つありました。
それは、こちらの記事を見つけてのこと。

• 例えば GC を止める・Ruby ウェブアプリケーションの高速化

PDFの不具合はバージョンアップでなくなったものの、劇的に早くなった、というわけでは無かったのと、プロジェクトの設定画面を開く際に以前より動作が遅いのが気になりました。そこで、何かカスタマイズできないかな、と思って見つけたのが上記の記事。

高速にするためにユーザからのリクエストを受け付けている間はGCを止める、という設定で、「これ、良いかな～」と安易に考え、unicornのソースをちょっと修正し、再起動をかけてみると…。

もしかすると設定を間違えたのかもしれませんが、変更前は1プロセスあたり100～150MBだったのが、プロセス起動直後、あっという間に各プロセスの実メモリが膨れ上がり、1つあたり600MBくらいになってしまいました！

異変に気が付いた時にはすでにShellの操作もままならない状態に…(^^;;;;
psコマンドを打つだけでも一苦労。

仕方なくOSを再起動させて、あわててunicornのプロセスを停止、ソースを元に戻しました。
この時のログやtop、xxxstat系の記録は取れませんでした…。
あとでOSの監視の記録をチェックしたところ、ディスクIOも凄かったらしく、Swapもガンガン使っていたようです…。

設定ミスのせいかもしれませんが、GCの件はタタリが怖いので何もしないことにしました…。

3-番外. メモリ割り当てが凄く小さくなったケース

せわしなく働き、叩き落されても立ち上がってくれるunicornのプロセスですが、本稼働た後のとある日のログを見ていたら、こんな状況を発見しました。

ちょうどこの時間帯に、他のプロセスが暴走していたらしく、CPUとメモリをガンガン使っていました。
その時のunicornのプロセスの状況を見ると…。

いつもは1プロセスあたり120 ～ 180MBなのですが、この時は、メモリを横取りされてしまい、各プロセスに割当たっているメモリは1ケタ～10MB台になっていました。

いつもの場合、一度メモリが割当たると、Redmineにアクセスが無くてもここまで下がらないのですが、OS内でギリギリの攻防があったらしく、unicornの使っていたメモリは引っぺがされて、実メモリが小さくなっていました…。

unocornのプロセスとメモリの状況は、Jenkinsに記録しているので、その時のログを見るとこんな感じでした。

Started
Temp file is:     /tmp/hudson_wrapper.qGq30101
Jenkins job name:  redmine-spawn
Script being run: /home/redmine/bin/spawn.sh

Using /usr/local/rvm/gems/ruby-1.8.7-p352
fat-memory-process-killer started at 2011-12-19 05:20:04
I, [2011-12-19T05:20:04.072207 #30164]  INFO -- : ----- Start -----
D, [2011-12-19T05:20:04.281365 #30164] DEBUG -- : ** rails_root=/var/service/redmine
D, [2011-12-19T05:20:04.281687 #30164] DEBUG -- : ** threshhold=xxxxMB
I, [2011-12-19T05:20:04.281796 #30164]  INFO -- : Got PIDs: m=18025 c=32494,30147,19979,7791,1840,13869
D, [2011-12-19T05:20:04.282146 #30164] DEBUG -- : ** master-memory:   18025 => 2.37MB
D, [2011-12-19T05:20:04.282214 #30164] DEBUG -- : ** child-memory:    32494 => 1.52MB
D, [2011-12-19T05:20:04.282272 #30164] DEBUG -- : ** child-memory:    30147 => 1.54MB
D, [2011-12-19T05:20:04.282310 #30164] DEBUG -- : ** child-memory:    19979 => 1.57MB
D, [2011-12-19T05:20:04.282363 #30164] DEBUG -- : ** child-memory:     7791 => 15.01MB
D, [2011-12-19T05:20:04.282401 #30164] DEBUG -- : ** child-memory:     1840 => 1.56MB
D, [2011-12-19T05:20:04.282451 #30164] DEBUG -- : ** child-memory:    13869 => 31.35MB
I, [2011-12-19T05:20:04.282483 #30164]  INFO -- : Finish
Start time: 1324239602.460640000
End time:   1324239604.294410000
Elapsed ms: 1833
Finished: SUCCESS

各プロセス、こじんまりしたサイズですね(^^;

問題の処理が（実は失敗していたんですが）終わり、晴れてunicornに割り当て可能なメモリが増えると、すぐにいつも通り1プロセスあたり120 ～ 180MBに戻っていました。

4. ログのローテーション

私は過去にログ (/var) を溢れさせてOSを止めちゃったトラウマがあるので、毎回気にせずにはいられません。大した情報にもなりませんが、自分のために敢えて記録をしておきます…。

Redmineのproduction.logに関しては、config/additional_environment.rbによるローテーションを実施することにしました。(Ref. http://redmine.jp/guide/RedmineInstall/ )

一方、unicorn & nginxのローテーションの設定は、logrotateを利用しました。
設定は下記の通りです。

# nginx
/var/log/nginx/*log {
rotate 6
size=500k
missingok
daily
notifempty
sharedscripts
postrotate
#/sbin/service httpd reload > /dev/null 2>/dev/null || true
[ ! -f /var/run/nginx.pid ] || kill -USR1 `cat /var/run/nginx.pid`
endscript
}

# unicorn
/var/service/redmine/log/unicorn.log {
rotate 6
size=500k
missingok
daily
notifempty
sharedscripts
postrotate
pid=/var/service/redmine/tmp/pids/unicorn.pid
test -s $pid && kill -USR1 "$(cat $pid)"
endscript
}

ひとまずこれでOKですが、基本的にlogrotateはdaily実行なので、多量にログが出るケースはhourlyやもっと細かい頻度で回します。
また、Redmineのメール通知を使っているケースで、localhostにSMTPサーバを持っている場合は、maillogも気を付けましょう。

ログの確認については、@haru_iida さんのLogs プラグインを導入させていただきました。管理しているサーバは直接sshでつながる場所には無いので、Webからログを確認できるのはとても便利！

unicornのログも redmine/log/ 以下に出しているので、併せて確認することができています。

ログを見ていて後から気が付いたことの一つが、unicorn.log に記録され続ける、下記の1行です。

svn: 警告: ファイル '/root/.subversion/servers' を開けません: 許可がありません

Unicornのプロセスはマスタはrootですが、子プロセスはredmineで動きます。多分子プロセスには参照権限無いからだよね、と思い、congfig.ymlを調整してみたりしたのですが、一向にログのこのメッセージが消える気配は無し。

実際のSubversionのリポジトリは参照できるので、単純に servers の設定ファイルだけがうまく読めないよー、とのエラーで実害は無いのですが、どうも気になります。

redmineユーザで動いてるんだから、/home/redmine 以下を見るはずなのに…と思っていたら、こんな記事を発見。どうやら子プロセスの実行ユーザは変わっても、デフォルトの$HOMEは、親プロセスのものを参照してしまうようです。

記事に従って、fork後に ENV["HOME"] = "/home/redmine" の記述を加えたら、晴れてエラーメッセージは無くなりました。

5. 移行後のフォロー

Jenkinsのおかげで、データ移行とMigrationはすんなり実施できました。

移行して２時間ほどは（カンガルーケア、じゃないですが）、上記のBannerの機能を利用し、『バージョンアップしました』という旨のメッセージを表示させて、ユーザさんの注意を促しました。
バージョンアップに関してのChangeLogなどは、NewsとWikiに記載しているので、バナーにはそちらへのリンクを張っておきました。また、私にとっては、Redmineのユーザさんがお客様？みたいなものですし、ちょっとした操作の疑問やカスタマイズのリクエストを受け付けられる場所が欲しいなと思い、全ユーザ対象のプロジェクトを１つ作りました。そのプロジェクトに、バージョンアップのお知らせや、新機能についての解説、ご意見募集用のフォーラムを設置しました。

このフォーラムも、どこにあるか認識してもらえないと利用も進まないので、最近見かける「タブ」にヒントを得て、サイト下部に「Feedbak」のタブを表示させるプラグインを作ってみました。

機能としては本当にシンプルなものなのですが、こうした、Redmineそのものについてのフィードバックを集めやすい仕組みや、全ユーザが利用できるサイトマップ的なものも、作っていけたらなあと思っています。

6. まとめ

本来、単にバージョンアップのためだけにこんなにすることないじゃない、と思われる方はたくさんいらっしゃるかと思います。ただ、私にはなにからなにまで初めてだったり、失敗はできないという状況だったので、Jenkinsに手伝ってもらいながらの予行演習をしておきました。
このおかげで、切り替え時間の見積もりもしやすくなりましたし、カスタマイズ部分をプラグインに切り出したので、今後のバージョンアップがしやすくなったかなあ…と考えています。

そうこうしているうちに、1.3が出てしまいましたね。

本当にバージョンアップしやすくなったのか、の検証はこれからです。
グループアサイン機能と、Wikiも含めたPDFの機能はとても魅力的なので、ユーザさんに早くお届けできるように、なんとか頑張ってみようと思います。

単純に書き連ねただけなので、たいして役にも立ちそうにないのに、とても長くなってしまい、申し訳ありません…。
少なくとも、私の失敗が何かのネタにでもなってくれれば幸いです。

* * *

20日目の記事は、@cointoss1973 さんの、Redmine おすすめの plugin (Hudson plugin)　でした。

そして次の22日目は、@naitohさんになります。どうぞよろしくお願いいたします！