OpenPNE 3

3.4.12.1 から 3.6beta10 へバージョンアップしたところ、以下のようなエラーが発生。

  SQLSTATE[HY000]: General error: 1005 Can't create table 'openpne34121.#sql-64c_60fd' (errno: 121). Failing Query: "ALTER TABLE ashiato ADD CONSTRAINT ashiato_member_id_to_member_id FOREIGN KEY (member_id_to) REFERENCES member(id) ON DELETE SET NULL". Failing Query: ALTER TABLE ashiato ADD CONSTRAINT ashiato_member_id_to_member_id FOREIGN KEY (member_id_to) REFERENCES member(id) ON DELETE SET NULL

再度バージョンアップを行いましたが、問題なくバージョンアップできました。
クリーンな状態でのテストなので、プラグインのインストール状況などによって再現するものだと思われます。

2系から3.4系へのアップグレードの中で、intro_friend テーブルへのデータ移行は行われないため、
2系から3.4系へのアップグレードは原因では無いと考えています。

今後の調査としてまず、3.4系のなかで紹介文関連のデータの不整合が起こる可能性がある前提で、
OpenPNE, opIntroFriendPlugin のバージョンアップ時にエラーを再現できるか調べ問題箇所を洗い出す予定です。

PNE3については2.12.20からバージョンアップして現在が3.4.9.2
プラグインについては

opMessagePlugin 0.9.1
opCommunityTopicPlugin 0.9.8
opOpenSocialPlugin 1.2.2
opAction2MailPlugin
opAshiatoPlugin 0.9.0
opDiaryPlugin 1.3.0.1
opWebAPIPlugin 0.4.0(無効)
opBlogPlugin 0.9.0（無効）
opAlbumPlugin 0.9.3
opAuthOpenIDPlugin 1.1.1
opAuthMailAddressPlugin 1.2.1
opAuthMobileUIDPlugin 1.0.0
がはいってます

アップデート先はたしか3.6の２～３月時点での最新のものでした。

アップデート手順はOpenPNE本体のなかのドキュメント（OpenPNE3_Version_Up_Guide.txt）のとおりに行いました。
./symfony doctrine:build-modelでエラーが発生しました。（おそらく制約違反なので２系から引き継いだデータのうち、退会者のデータが３では退会時に削除されるものがのこってしまっているためメンバーIDからメンバー情報を引けずにエラーになる？

とのことなので、同バージョンでのアップデート手順を検証、
intro_friend テーブル(外部キー制約含む)が存在する状態でアップデートを行うと当該エラーが発生することを確認しました。

直近の調査方針

• http://redmine.openpne.jp/issues/1950#note-10 などから（なんらか誤ったバージョンアップ手順もしくはプラグインインストール手順によって） intro_friend テーブルがすでに存在することが原因である可能性を仮定していることが伺えますが、この前提には無理があるように思います。 openpne:migrate のタイミングでインストールされたプラグインに関するテーブルは Doctrine_Export::exportSortedClassesSql() で生成される SQL を実行することによって作られることになります。このとき、常に CREATE TABLE 文の実行からおこなわれるように SQL が組み立てられます（当たり前ですが）。ですので、この可能性を前提とした場合、 CREATE TABLE の時点ですでにエラーになっていなければいけないはずですが、報告にはそのような記述が見当たりません。仮に OpenPNE が最後に発生した SQL エラーのみを報告しているというバグがあれば別ですが、そうでなければ intro_friend テーブルが存在する可能性を仮定した調査はとりあえずおこなわないようにします。
• OpenPNE 3 へのコンバータが適切でない member_relationship のデータを残しうる可能性がないかどうか、もしくは intro_friend テーブルが現実的でない外部キー制約を定義している可能性はないかどうかについて検討します。

http://redmine.openpne.jp/issues/1950#note-13 の 1 点目について補足ですが、旧バージョンで（バンドルされていない） opIntroFriendPlugin をインストールしていたとしても、このプラグインがバンドルされているバージョンにアップデートした際にエラーが発生することは通常ありません。これは、 OpenPNE 3 側でプラグインのインストールをすでにおこなったかどうかの情報を管理しているためです。

OpenPNE 2 側データの不整合に起因する問題の検討¶

openpne:upgrade-from-2 タスクにおける member_relationship テーブルのインポート時に外部キー制約に違反するデータが格納される可能性として、 OpenPNE 2 側の c_friend, c_friend_confirm, c_access_block に存在しないメンバーのデータが残っているというものが考えられます。

このようなデータを作りうるものとして、

• メンバー削除時にこれらのデータが削除されない
• アクセスブロック時に存在しないメンバーを指定できる
• フレンド申請時に存在しないメンバーを指定できる

が考えられます。

OpenPNE 2 では外部キー制約を使用しておらず、プログラムでのチェックのみに頼っているため、プログラムの実装不備などがありえた場合に、不正なメンバー ID 等が入りうる可能性は充分に考えられます。

そこで、これらの可能性についてひとつひとつ検討していきます。

メンバー削除処理に問題がありうるかどうか¶

メンバー削除処理はPC、携帯、管理画面で共通の関数を使っておこなわれますが、この関数内の c_friend, c_friend_confirm, c_access_block の削除に関わる処理は正しく実装されています。また、この実装は追跡できる限りで OpenPNE 2.3.0 から変化していません。

関数キャッシュの影響を受けるような場所でもなく、実際の削除処理では DELETE 文を発行しているだけなので、スレーブ遅延の影響も考えられません。

アクセスブロックに問題がありうるかどうか¶

PC と携帯で共通化されたアクセスブロックの追加処理には、追加対象として渡されたメンバー ID の一覧のうち、実際に存在するもののみを抽出して処理しており、存在しないメンバーが追加される可能性はなさそうです。

また、この処理は追跡できる限りで OpenPNE 2.3.0 から変わっていません。

フレンド申請処理に問題がありうるかどうか¶

処理を確認したところ、 * OpenPNE 2 のフレンド申請は do アクションを直で POST することで存在しないメンバーに対しておこなうことができる * ことを確認しました。

意図的に発生させるほかにも、フレンド申請しようとしたタイミングで相手が退会した場合にこのような状況になることが考えられます。

フレンド登録処理に問題がありうるかどうか¶

フレンド申請処理の実装に問題があり、 c_friend_confirm.c_member_from が存在しないメンバー ID になるようなことがあれば、存在しないメンバーをフレンドとする関係ができあがることになりますが、いまのところそのような状況になりうる実装は見つかっていません。

本件の原因調査等の報告について、取り急ぎ、以下に、転載いたします。

さて、本題の 3.6 へのバージョンアップのエラーについてですが、今のところ「OpenPNE 3 のバグではない」という可能性が非常に高いのではないかと見ています。
（OpenPNE 2 からのアップグレード後で、かつベータ版へのアップグレードという背景から勝手にミスリードされてしまい、この判断に行き着くまでに遠回りしてしまいました……）

以下にこの判断の理由を述べます。

■ 1) General error: 1005 Can't create table .... (errno: 121) というエラーメッセージが出力されている

　このエラーメッセージについては http://dev.mysql.com/doc/refman/5.1/ja/innodb-error-codes.html で解説されています。

> テーブルを作成できません。もしエラー メッセージが errno 150を参照していたら、外部キー制約が正しく形成さられなかった為にテーブル作成は失敗しました。もしエラー メッセージが errno -1を参照していたら、テーブルが内部 InnoDB テーブルの名前と一致するカラム名を含んでいる為にテーブル作成はおそらく失敗したでしょう。 

　しかし、 errno が 121 であるときの原因についてはマニュアルに一切記述されていません（そもそもテーブルの作成操作ではありませんが）。そこで、 MySQL のソースコードを確認することにしました。
　その結果、すでに存在するキーを書き込もうとした場合に発生するエラーであるらしいことが確認できました（追試のために、駆け足気味ですが本メールの末尾に調査中のメモを残しますので参考にしていただければと思います）。

　また、 MySQL のフォーラムの検索結果から、このエラーメッセージに対する質問を確認することができますので、こちらも参考にしてください。
　http://forums.mysql.com/search.php?22,search=errno+121,author=,page=1,match_type=ALL,match_dates=365,match_forum=ALL,match_threads=

■ 2) エラーメッセージが出たタイミングが ALTER TABLE 時点である

　そもそも、外部キー制約に違反するデータがあることが原因だった場合、作成した直後の、レコードがなにも挿入されていないテーブルに対する ALTER TABLE によってエラーとなるのは不自然です。

このことから、まず、 DB に存在するデータが起因する問題ではないらしいことが推測できます。

そうなると、 1) にて説明しているような、重複する外部キー制約名を生成するバグが OpenPNE 3 に存在している可能性も考えられますが、仮にそのようなバグがあった場合、私どもの再現作業でそのような現象を一度も確認できないというのも妙な話です。

貴テスト環境で再現性のある現象であるというところが非常に引っかかるところですが、以上の考察と、他ユーザからの同様の報告が来ていないこと、 OpenPNE 3.6 で運用している SNS で intro_friend テーブルの外部キー制約に起因するトラブルが確認できていないことなどを受け、「OpenPNE 3 のバグの可能性」から一度離れ、「OpenPNE 3 のバグではない可能性」を疑うべきだと判断しました。

この判断を裏付ける決定的な材料になると思われるのが、前回のメールでお伺いした「SHOW ENGINE INNODB STATUS」の実行結果なのですが、現状ご提供いただくことが難しいとのことですので、確たる材料がない状態ではありますがこのような判断をさせていただくことにしました。 OpenPNE 3 のバグではない可能性が高くなってきたことと、直近でこれ以上詳細の情報をいただくのが難しいという現状、前述の考察などを考慮し、いままで「OpenPNE 3.6.0 までに修正しなければならないバグ」ということで優先度をある程度高めて進めていました本件について、「OpenPNE 3.6.0 のリリースまでに解決すること」を必須とはしないようにしたいと思います。

この判断は、私たちが本件に今後取り組まないということを意味するものではないことを念のため申し添えておきます。なんらかのきっかけで OpenPNE や MySQL などに新しい原因となり得る事柄が発覚したり、 SHOW ENGINE INNODB STATUS の実行結果のご提供などにより新しい判断材料が得られ次第、調査を継続していきたいと思います。

なお、エラーメッセージから考えられる可能性として、 intro_friend_member_id_to_member_relationship_member_id_to という外部キーがすでに（バックアップ用のテーブルなど）他のテーブルに存在している、もしくは MySQL がなんらかの理由で他テーブルもしくはこのテーブルのインデックス管理用ファイルの削除に失敗したなどといったことが考えられます。次回バージョンアップの検証をしていただく際には、この点あわせてご確認いただければと思います。

■付録■ 1) の事実を確認した際の調査メモ

※確認に用いた MySQL のソースコードは 5.1.58 のもの
※InnoDB Plugin を *使用しておらず* 、従来の InnoDB を用いていることが前提

　エラーコード 121 は include/my_base.h で定義されており、以下のように Dupplicate key on write （書き込み時の重複キー）とコメントされています。

　http://bazaar.launchpad.net/~mysql/mysql-server/mysql-5.1/view/head:/include/my_base.h#L380
　377:#define HA_ERR_FOUND_DUPP_KEY    121    /* Dupplicate key on write */

　ただし、この定数が InnoDB で用いられているわけではありません。 InnoDB では別のエラーコードを持っており、 convert_error_code_to_mysql() で InnoDB 側エラーコードから MySQL 側エラーコードに変換をおこなうようです。 InnoDB における HA_ERR_FOUND_DUPP_KEY に相当するエラーメッセージは DB_DUPLICATE_KEY となります。

　ここまでで、ストレージエンジンが InnoDB の場合における errno の原因を調査するためには DB_DUPLICATE_KEY を代入、もしくは返り値にとる箇所を調べればよいことになります。実は、そのような箇所は、 storage/innobase/row/row0ins.c の以下の 3 箇所のみしかありません。

　1724: err = DB_DUPLICATE_KEY; // (row_ins_scan_sec_index_for_duplicate() 内)
　1843: err = DB_DUPLICATE_KEY; // (row_ins_duplicate_error_in_clust() 内)
　1885: err = DB_DUPLICATE_KEY; // (row_ins_duplicate_error_in_clust() 内)

　row_ins_scan_sec_index_for_duplicate() は、非 PRIMARY KEY ではないか、非 UNIQUE かつ非 NOT NULL なインデックス（clustered index でないインデックス）が重複して作られようとしていないかどうかを確認する関数のようです。今回のエラーは clustered index が対象のものですので、この関数は検証対象から外します。

　row_ins_duplicate_error_in_clust() は、 row_ins_dupl_error_with_rec() によって挿入しようとしている clustered index が（外部キー管理用の MySQL の内部辞書テーブルに）すでに存在しているかどうかの確認をおこない、すでに存在している場合に DB_DUPLICATE_KEY を返す実装になっています。
　さて、この row_ins_duplicate_error_in_clust() についてですが、クライアントから ALTER TABLE 文が発行された場合に、サーバが mysql_alter_table() 関数を処理する過程でコールされることが確認できました。以下、手元の環境で確認した際のバックトレースの抜粋です。

#0  row_ins_duplicate_error_in_clust (*snip*) at row0ins.c:1778
#1  0x00000001005fa93b in row_ins_index_entry_low (*snip*) at row0ins.c:2035
#2  0x00000001005fb04f in row_ins_index_entry (*snip*) at row0ins.c:2172
(*snip*)
#9  0x00000001005cc4bf in que_eval_sql (*snip*, sql=*snip* "PROCEDURE P () IS\nBEGIN\nINSERT INTO SYS_FOREIGN VALUES(:id, :for_name, :ref_name, :n_cols);\nEND;\n", reserve_dict_mutex=0, trx=*snip*) at que0que.c:1425
#10 0x00000001005253f1 in dict_foreign_eval_sql (*snip*, sql=*snip* "PROCEDURE P () IS\nBEGIN\nINSERT INTO SYS_FOREIGN VALUES(:id, :for_name, :ref_name, :n_cols);\nEND;\n", table=*snip*, foreign=*snip*, trx=*snip*) at dict0crea.c:1322
#11 0x0000000100525938 in dict_create_add_foreign_to_dictionary (*snip*) at dict0crea.c:1448
#12 0x0000000100525b43 in dict_create_add_foreigns_to_dictionary (*snip*) at dict0crea.c:1517
(*snip*)
#17 0x00000001000487fc in handler::ha_create (*snip*) at handler.cc:3463
#18 0x000000010004bd0b in ha_create_table (*snip*) at handler.cc:3670
#19 0x00000001003bff81 in rea_create_table (*snip*) at unireg.cc:526
#20 0x000000010037254a in mysql_create_table_no_lock (*snip*) at sql_table.cc:4271
#21 0x0000000100375b4c in mysql_alter_table (*snip*)

　ここまでで、「ALTER TABLE 文によって row_ins_duplicate_error_in_clust() が実行されうること」と「InnoDB では row_ins_duplicate_error_in_clust() と row_ins_scan_sec_index_for_duplicate() によって DB_DUPLICATE_KEY (HA_ERR_FOUND_DUPP_KEY) のエラーメッセージが発行されうること」、そして「row_ins_duplicate_error_in_clust() ではすでに存在する clustered index を作成しようとした場合にエラーとなること」確認できました。