Redmineでトラブル発生！素人が原因を調査して解決するまでにやったことまとめ
http://example.com/projects/foo/issues → プロジェクト"foo"のチケット一覧が出る。→ 問題なし
http://example.com/projects/bar/issues → プロジェクト"foo"および"bar"のチケット一覧が出る。→ なんで！？
この２つのプロジェクトは全くの別物で親子関係はありません。
さあ困りました。
調査開始！
まず、発行しているSQLを見よう！調べてみると、本番(production)環境でログを表示する方法があるではないですか。
Redmineプラグイン開発 - プラグインでログを出したい
redmine/config/environments/production.rb を開いて、下記を追記。
config.logger = Logger.new(config.log_path)
config.logger.level = Logger::DEBUG
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
ブラウザを再読み込みしてみると・・・
出た！！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
projects.id IN (4,2)
なんじゃこりゃ？
プロジェクトIDが２つ書いてあります。(本来欲しいのはprojects.id = 4のみ)
そりゃあプロジェクト２つ分のチケットが表示されるわけだ。
でもなんでプロジェクトIDが２つ指定されているのだろう？
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"}
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
@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')
====================なんじゃこりゃ？
たしかにこの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のチケットのみが表示されるようになりました。
めでたしめでたし。（所要時間：２時間くらい）
まとめ
Redmineのトラブルを調査する方法を解説しました。Ruby/Railsのデバグ環境の充実ぶりに感動です。
素人でも意外と何とかできてしまうものですね。
「求めよ、さらば与えられん」というところでしょうか。
この記事が誰かのお役に立ちますように。