Redmineでトラブル発生!素人が原因を調査して解決するまでにやったことまとめ

仕事で使っているredmineでトラブルが発生したので、原因を突き止めて解決するまでの流れを公開します。
この手順でやれば、非Rubyプログラマでもある程度トラブルシューティングができるようになるかと思います。

ちなみに私は普段PHP/Ethnaで仕事をしていて、Railsの経験はチュートリアルをちょろっとやった程度のレベルです。

事の発端

「あるプロジェクトのチケット一覧画面で、別プロジェクトのチケットも表示されてしまう

これが私が遭遇したトラブルでした。

redmineで複数のプロジェクトを管理していたのですが、チケット一覧を表示しようとすると下記のようなことが起こりました。

http://example.com/projects/foo/issues → プロジェクト"foo"のチケット一覧が出る。→ 問題なし
http://example.com/projects/bar/issues → プロジェクト"foo"および"bar"のチケット一覧が出る。→ なんで!?

この2つのプロジェクトは全くの別物で親子関係はありません。
さあ困りました。

調査開始!

まず、発行しているSQLを見よう!

調べてみると、本番(production)環境でログを表示する方法があるではないですか。

Redmineプラグイン開発 - プラグインでログを出したい

redmine/config/environments/production.rb を開いて、下記を追記。
config.logger = Logger.new(config.log_path)
config.logger.level = Logger::DEBUG
ブラウザからhttp://example.com/projects/bar/issueにアクセスして、
tail -f  redmine/log/production.log 
Processing IssuesController#index (for xx.xx.xx at 2012-04-11 01:25:23) [GET]
  Parameters: {"project_id"=>"bar", "action"=>"index", "controller"=>"issues"}
Rendering template within layouts/base
Rendering issues/index.rhtml
Completed in 352ms (View: 294, DB: 15) | 200 OK [http://example.com/projects/bar/issues]
おお、それっぽいログが吐かれている!
しかし、SQLログが表示されない・・・

調べてみると、どうもアプリを再起動しないと設定が反映されないようです。
Railsのデバッグについて - Redmine Users (japanese) | Google グループ

また、私が動かしているPassenger環境ではクラスファイルがキャッシュされるので、調査中はキャッシュをオフにした方がよさそうです。

先ほどのredmine/config/environments/production.rb を開いて、クラスファイルのキャッシュをオフにします。
config.cache_classes = false
次に、redmine/tmp/restart.txt というファイルを手動で作成します。
ブラウザを再読み込みしてみると・・・

出た!!SQLログ!!
いろいろ出てるSQLログの中から、それっぽいものを見つけました。
どうやらこれが「チケットの一覧」を抽出するSQLのようです。
SELECT `issues`.`id` AS t0_r0,
 `issues`.`tracker_id` AS t0_r1,
 `issues`.`project_id` AS t0_r2,
(中略)
 `versions`.`wiki_page_title` AS t7_r7,
 `versions`.`status` AS t7_r8 
FROM `issues`
LEFT OUTER JOIN `users` ON `users`.id = `issues`.assigned_to_id AND (`users`.`type` = 'User' OR `users`.`type` = 'AnonymousUser' ) 
LEFT OUTER JOIN `issue_statuses` ON `issue_statuses`.id = `issues`.status_id 
LEFT OUTER JOIN `trackers` ON `trackers`.id = `issues`.tracker_id 
LEFT OUTER JOIN `projects` ON `projects`.id = `issues`.project_id 
LEFT OUTER JOIN `enumerations` ON `enumerations`.id = `issues`.priority_id AND (`enumerations`.`type` = 'IssuePriority' ) 
LEFT OUTER JOIN `issue_categories` ON `issue_categories`.id = `issues`.category_id 
LEFT OUTER JOIN `versions` ON `versions`.id = `issues`.fixed_version_id 
WHERE ((issue_statuses.is_closed=0) AND projects.id IN (4,2)
 AND projects.status=1 AND projects.id
 IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='issue_tracking'))
 ORDER BY issues.id DESC LIMIT 0,1000
ここでWHERE句に注目。
projects.id IN (4,2)

なんじゃこりゃ?
プロジェクトIDが2つ書いてあります。(本来欲しいのはprojects.id = 4のみ)
そりゃあプロジェクト2つ分のチケットが表示されるわけだ。

でもなんでプロジェクトIDが2つ指定されているのだろう?

Controllerにロガーを仕込んでみた

さっきのログをよく見ると、冒頭がこうなっています。
Processing IssuesController#index (for 180.0.33.240 at 2012-04-11 01:34:12) [GET]
  Parameters: {"project_id"=>"bar", "action"=>"index", "controller"=>"issues"}
よし、IssuesControllerのindexアクションを見ればいいんだな!

redmine/app/controllers/issues_controller.rb を開きます。
  def index
    retrieve_query
    sort_init(@query.sort_criteria.empty? ? [['id', 'desc']] : @query.sort_criteria)
    sort_update({'id' => "#{Issue.table_name}.id"}.merge(@query.available_columns.inject({}) {|h, c| h[c.name.to_s] = c.sortable; h}))

    if @query.valid?
      limit = per_page_option
      respond_to do |format|
        format.html { }
        format.atom { limit = Setting.feeds_limit.to_i }
        format.csv  { limit = Setting.issues_export_limit.to_i }
        format.pdf  { limit = Setting.issues_export_limit.to_i }
      end
      @issue_count = Issue.count(:include => [:status, :project], :conditions => @query.statement)
      @issue_pages = Paginator.new self, @issue_count, limit, params['page']
      @issues = Issue.find :all, :order => [@query.group_by_sort_order, sort_clause].compact.join(','),
                           :include => [ :assigned_to, :status, :tracker, :project, :priority, :category, :fixed_version ],
                           :conditions => @query.statement,
                           :limit  =>  limit,
                           :offset =>  @issue_pages.current.offset
@がrubyにおけるインスタンス変数らしい。
@queryがどうも怪しい。
これをダンプしたい!でもどうすれば・・・

下記記事に、rails内でデバグログを出力する方法が書いてありました。
Redmineプラグイン開発 - プラグインでログを出したい

よし、logger.debug()を使うんだな!
  def index
    retrieve_query
    sort_init(@query.sort_criteria.empty? ? [['id', 'desc']] : @query.sort_criteria)
    sort_update({'id' => "#{Issue.table_name}.id"}.merge(@query.available_columns.inject({}) {|h, c| h[c.name.to_s] = c.sortable; h}))

    logger.debug("====================");
    logger.debug(@query.statement);
    logger.debug("====================");
このようにデバグログを仕込んで、ブラウザを再読み込みしてみると・・・
====================
  SQL (0.2ms)   SELECT count(*) AS count_all 
FROM `projects` WHERE (((projects.status = 1) AND (projects.id != 4)) 
AND (projects.`lft` >= 3 AND projects.`rgt` <= 4))
(issue_statuses.is_closed=0) AND projects.id = 4 AND projects.status=1 
AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='issue_tracking')
====================
(projects.`lft` >= 3 AND projects.`rgt` <= 4))
なんじゃこりゃ?

たしかにこのSQLなら、プロジェクト"bar"とは関係ないプロジェクト"foo"がひっかかってしまいます。
どうもこのprojects.lftとprojects.rgtが悪さをしてるみたい。

DBを直接覗いてみる

MySQLを直接たたいてみました。
mysql> select id,  parent_id, identifier, status, lft, rgt from projects;
+----+-----------+------------------+--------+------+------+
| id | parent_id | identifier       | status | lft  | rgt  |
+----+-----------+------------------+--------+------+------+
|  1 |      NULL | aaaaa            |      1 |    5 |    6 |
|  2 |      NULL | foo              |      1 |    3 |    2 |
|  4 |      NULL | bar              |      1 |    3 |    4 |
|  7 |      NULL | ccccc            |      1 |    9 |   10 |
+----+-----------+------------------+--------+------+------+
ふむ・・・

lft,rgtについては下記のサイトで解説が書いてありました。

【Redmine】issuesテーブルのlft・rgtって? | Roppi.net
SQLアタマアカデミー:第5回 SQLで木構造を扱う~入れ子集合モデル (1)入れ子集合モデルとは何か |gihyo.jp ... 技術評論社

どうやら、RDBMSで親子関係を表現するテクニックのようです。
よく見ると、上のDBではbarのlft,rgtがfooのlft,rgtより広いから、これによってbarがfooを包含していることになってしまったようです。

なんでこうなったのかはわかりませんが、プロジェクトの設定をいろいろいじってるうちにこうなってしまったのかもしれません。

UPDATE文で直接lftを書き換えてみました。
mysql> update projects set lft = 5 where id = 4;

mysql> select id,  parent_id, identifier, status, lft, rgt from projects;
+----+-----------+------------------+--------+------+------+
| id | parent_id | identifier       | status | lft  | rgt  |
+----+-----------+------------------+--------+------+------+
|  1 |      NULL | aaaaa            |      1 |    5 |    6 |
|  2 |      NULL | foo              |      1 |    3 |    2 |
|  4 |      NULL | bar              |      1 |    5 |    4 |
|  7 |      NULL | ccccc            |      1 |    9 |   10 |
+----+-----------+------------------+--------+------+------+
ブラウザを再読み込みしてみたら、
・・・ビンゴ!!
直りました!!
http://example.com/projects/bar/issues
を開いたときに、barのチケットのみが表示されるようになりました。

めでたしめでたし。(所要時間:2時間くらい)

まとめ

Redmineのトラブルを調査する方法を解説しました。

Ruby/Railsのデバグ環境の充実ぶりに感動です。
素人でも意外と何とかできてしまうものですね。

「求めよ、さらば与えられん」というところでしょうか。
この記事が誰かのお役に立ちますように。
カテゴリ:

人気記事