クリアコードの結城です。

先日、動画でバグ報告する方法の中で例として挙げていたmacOS版Firefoxのサイドバーの操作に関するバグですが、最終的には原因の特定とパッチの提出にまで至る事ができました。このエントリでは当該バグの調査の過程を辿りながら、macOS上のFirefoxにおいてマルチプロセスが絡む部分やドラッグ＆ドロップに関わる部分のデバッグをどのように進めたかの一例をご紹介します。

問題の概要

当該バグはツリー型タブというアドオンに寄せられた報告に端を発しています。このアドオンはFirefoxのサイドバー内でタブバーの代替となるUIを提供するという物で、項目をクリックするとタブが切り替わり、ドラッグ＆ドロップでタブを並べ替える事もできます。このサイドバーパネル上において「セッション復元後にまだ読み込まれていないタブをドラッグしようとするとドラッグできず、また、それ以後サイドバー内で一切のドラッグ操作が行えなくなる」という現象が発生する、というのが報告の要旨でした。

報告者の方と連絡を取りながら調査を進めた結果、この問題はmacOSでのみ発生するらしいという事と、アドオン側で可能と思われる対策を講じても現象を回避できない、Firefox自体のバグに起因する問題であるらしいという事が分かりました。当該アドオンの実装を参考に最小のテストケースを作成して検証した結果、確かに現象を再現できたため、Firefox自体のバグとしてBugzillaに報告しました。またその過程において、上記の再現手順の他に以下の事も事が分かりました。

• サイドバーの内容（＝アドオンが提供するコンテンツ）が別プロセスで動作している時だけ現象が再現する。

• 既にセッションが完全に復元された状態のタブでは、現象は再現しない。

• 現象発生時は、dragstartイベントは発生するが、その後に発生するはずのdragover、dragenter、dragleave、dragendの各イベントは発生しない。

調査前の時点での見立て

本格的に調査を始める前に、この時点で分かっていた情報から、Firefoxの内部で何が起こりどうしてこの問題が起こっているのかという事について、いくつかの仮説を立てました。

• 仮説1：タブを切り替えてセッション復元処理が行われる時に、親プロセスと子プロセス群との間の「繋ぎ替え」が発生し、サイドバーのプロセスが「アクティブな子プロセス」でなくなるせいで、サイドバーのプロセスから親プロセスにドラッグ操作が伝わらなくなる。

• 仮説2：タブを切り替えてセッション復元処理が行われる時に、ドラッグ＆ドロップの処理に対して何らかの割り込みをかけるせいで、「何らかのフラグ」が内部で立ってしまい、以後ドラッグ＆ドロップのイベントが発生しなくなる。

ただ、そもそも一連の処理に関わる実装がどのような設計になっているのか、「繋ぎ替え」や「フラグ」とここで呼んでいるような物が実際にあるのかどうかも、この時点では不明なままでした。これらはあくまで、過去の経験に基づく推測での見立てとなります。

また、筆者はmacOSのネイティブアプリ開発の知見を全く持っていないという問題もありました。筆者はWindows版のFirefoxの低レイヤ部分の調査は若干経験しているものの、macOSネイティブの開発経験は皆無です。今回のように特定プラットフォームでしか発生しない問題は、そのプラットフォーム向けのコード（WindowsではWin32 API、LinuxではGTK+、macOSではCocoa APIを使う部分）を調査する必要が出てきます。調査対象の事を全く知らない状態での手探りの調査は泥沼化しがちですので、これは大きなリスクです。

そのリスクを回避するために「macOSアプリでのドラッグ＆ドロップはどのように実装するのか」という事を先に勉強してから調査に臨むというやり方もあります。しかしながら、今回の調査に必要な知識がその知識体系のどのあたりに存在しているかは全く予想が付きませんし、そこまでガッツリとmacOSでの開発を学びたいという訳でもありません¹。そもそもこれは「解決できれば儲け物だが、自身がmacOSユーザーではないので究極的には直らなくても困らない問題」という性質の物でしたので、失敗に終わったとしてもそれほどダメージは無いと言えます。ですので、知見の不足には一旦目を瞑って、Mozilla製品でのクロスプラットフォームな開発の知識だけを元に調査していく事にしました。

調査の出発点を探す

全く手がかりがない所から調査を行うのは、Firefoxほどの規模のソフトウェアではほぼ不可能です。そこで、ここまでに分かっていた事からヒントになりそうな要素はないかを検討してみました。

成功ケースと失敗ケースの両方の再現手順がはっきりしているという事は、その両者で起こっている事を子細に比較していけば、現象が起こる原因が分かる可能性は高いと考えられます。一連の操作の中で「共通してこのモジュールのこのメソッドが呼ばれている」という部分が特定できれば、そこを手がかりにして調査範囲を広げていけるはずです。

ここで着目したのは、正常な場合でも異常な場合でもDOMのdragstartイベントは発行されているという点でした。Firefoxの内部ではこういったDOMイベントの名前は定数で定義されていますので、その定数を伴ってイベントを初期化したり発行したりしていそうな所を特定できれば、そこを起点に調査を進められます。

"dragstart"という文字列でざっとソースコード内を検索してみた所、dragstartを定数として定義しているらしい箇所がすぐに見つかりました。ここで、このイベント名は他の箇所からeDragStartという定数名で参照されているらしいという事が分かりました。

次に、eDragStartという定数名でソースコード内を検索してみた所、自動テスト用に擬似的にイベントを生成しているらしい箇所に混ざって、EventStateManagerというモジュールの中でイベントを生成しているらしい箇所が1箇所だけ見つかりました。この処理が含まれているのはEventStateManager::GenerateDragGesture()というメソッドでしたので、メソッド名から見ても、どうやらドラッグ＆ドロップの操作が行われた時には必ずここを通過すると考えて良さそうです。

同様にeDragOverという定数名でソースコード内を検索した結果、成功ケースにおける「dragoverイベントが発行されるのはここ」という場所も特定できました²。

ところで、今回の問題は厳密に言うと、以下の2つの現象が起こっています。

• セッション復元後にまだ読み込まれていないタブをドラッグしようとするとドラッグできない。（最初の問題）

• それ以後、サイドバー内で一切のドラッグ操作が行えなくなる。（2回目以降の問題）

2つの現象は「タブをドラッグできない」「どちらもdragstartイベントだけが発行される」という症状は共通していますが、原因が同じかどうかは分かりません。ただ、再現が容易なのは2つ目の現象の方（1つ目の現象が再現したら、以後は何度やっても2つ目の現象が起こる事になるので）なので、先にこちらの方から原因を調べる事にしました。こちらの原因が分かれば、今度はそれが「その原因となっている状況を引き起こした犯人＝1つ目の現象の原因」を特定する手がかりとなります。

低レベルのログを収集する

Firefoxには環境変数を指定する事でモジュール単位の低レベルのログを収集する機能があるため、成功ケースと失敗ケースの両方についてこのモジュールのログを取得して比較すれば、何か分かるかも知れません。この方法であれば、子プロセスが出力したログもそれぞれ個別に収集する事ができます。

低レベルのログを収集するには、macOSではターミナルを使います。Firefoxのアプリケーションファイルはファイルシステム上はフォルダ（ディレクトリ）になっているので、以下のようにして環境変数を設定して実行します。

$ MOZ_LOG=timestamp,sync,nsCocoaWidget:5 MOZ_LOG_FILE=~/debug.log /Applications/Nightly.app/Contents/MacOS/firefox

環境変数MOZ_LOGには、ログを取得したいモジュール名とログレベルを:で繋げたものを、,区切りのリストとして指定します。このようにしてFirefoxを起動すると、メインプロセスのログがMOZ_LOG_FILEで指定した名前のファイルに出力され、子プロセスのログはdebug.log.child-1のような名前で同じ位置に出力されます。ログ出力が始まった状態から、ターミナルの新しいタブでtail -F debug.log*と実行すれば、それぞれのログに出力される内容をリアルタイムで見る事もできます。

しかし、先程特定した「成功時と失敗で共通して呼ばれているモジュール」であったEventStateManager.cppのソース内をlogで検索してみても、ログ出力を行っているらしきコードは見つかりませんでした。また、dragoverイベントが発行される契機になっている処理の方についてはnsCocoaWidgetというログモジュールでログを収集できましたが、こちらは成功ケースのログしか出力されず、しかも知りたい核心部分の処理が全て終わった後の時点のログでした。これではログを取っても調査の役には立ちません。

モジュール単位でのログが役に立たないとなると、何か別の方法で「成功ケースと失敗ケースのそれぞれで、内部的に何が起こっているのか」を調べる必要があります。

デバッグビルドとデバッガを使用した調査

このような場面で使えるツールの1つがデバッガです。問題が発生するケース・期待通りに動くケースで必ずこの行を通る、という事がはっきり分かっている場合には、デバッガ上でそこにブレークポイントを仕掛けておく事で、処理を一時停止して各変数の値を詳細に見る事ができます。また、そこから1行ずつ処理を進めて流れをじっくり追うという事（ステップ実行）もできます。

デバッグビルドの準備

ただ、デバッガを使うにはmacOS版Firefoxのデバッグ用ビルドが必要です。オフィシャルに公開されているバイナリは無い様子でしたので、「Firefox macOS debug」と検索して出てきたMDNのmacOSでのデバッグ手順の解説とビルド手順の解説を見ながら自分でデバッグビルドを作成することにしました。

• macOS版FirefoxのビルドのためにはXcodeが必要です。しかし、調査に使える環境はmacOS 10.12 Sierraだったため、App Storeにある最新のmacOS向けのXcodeはインストールできませんでした。そこで「Xcode for old macOS」などのキーワードで検索して見つかった情報を参考に、開発者向けのページからXcodeの旧バージョンをダウンロードしてインストールしました。

• Homebrewなどのツール類については、解説にある通りbootstrap.pyを使って一括インストールする事ができました。

  • 初期設定時に選択するビルド対象は、Artifact Buildではないデスクトップ版Firefoxとしました。Artifact Buildとは、ビルド済みバイナリをダウンロードしてきて使う事によって、ビルドに要する時間を短縮できるという特殊なビルドです。しかし、今回はバイナリ部分をデバッグ用にビルドしたいので、Artifact Buildは不適当という事になります。

• 既にNightlyで現象を再現できていたので、cloneするリポジトリはNightlyに対応する https://hg.mozilla.org/mozilla-central/ を使いました。

解説の通りに進めてデバッグビルドができた時点で³、./mach runでテスト実行してみました。最適化がなされないためなのかデバッグビルドだからなのか、一挙手一投足がもたつく程に非常に低速ではありますが、一応動く事は動いているため、準備が整った事にして次の行程に進みます。

ブレークポイントの設定とステップ実行

macOSでのデバッグ手順解説に記載の通りに準備した上で、Xcodeの「Product」メニューから「Run」を選ぶと、デバッグビルドのFirefoxが起動します。

ブレークポイントを設定するためには、まずXcodeの左ペインのフォルダーアイコンをクリックし、ソースコードのファイル一覧から「ここで処理を止めたい」という処理が含まれているファイル（今回は dom/events/EventStateManager.cpp ）を選択します。 右上のペインにソースコードが表示されますので、止めたい処理の行番号をクリックします。すると、行番号の部分に青いマークが付きます。これをブレークポイントといい、Xcode経由で起動したデバッグビルドのFirefoxの内部で処理がこの行に到達すると、処理がその場所で止まってXcodeに制御が移るようになります。

ブレークポイントで処理が止まった後は、左のペインの内容が関数呼び出しのスタック表示に切り替わり、ソースコードが表示されているペインの左下ペインには停止位置での各変数の値が表示されます。

この時には、ツールバー上の各ボタンで以下の操作を行えます。

• Deactivate breakpoints：全てのブレークポイントを一時的に無効化する。もう一度クリックすると、ブレークポイントを有効化する。

• Continue program execution：次のブレークポイントまで処理を一気に進める（ブレークポイントでの一時停止を解いて、通常の実行に戻す）

• Step over：処理をソースコード上で1行分次に進める（ステップ実行）。

• Step into：関数の呼び出し行において、関数の中に入る（呼ばれた関数の1行目からステップ実行を行う）。

• Step out：関数の外に出る（現在ステップ実行中の処理を関数の最終行またはreturnに到達するまで進めて、呼び出し元の関数で元の関数が呼ばれている行からステップ実行を行う）。

変数の値を調べても有用な情報を見付けられなかった場合には、ステップ実行を繰り返したり、別の位置にブレークポイントを設定したり、ブレークポイントを削除⁴したりして、解析を続けていきます。同じ箇所で「期待通りの結果が得られている時の内部状態」と「問題が起こっている時の内部状態」を詳細に比較していけば、「何が原因で、処理が期待と異なる方向に進んでいってしまったのか」を明らかにできるというわけです。

ただ、実際には各変数の値はツリー構造になっていて、奥の奥の方に原因が潜んでいるという場合も多々あるため、余程「ここをピンポイントで調べたい」という事が事前にはっきり分かっている場合でもない限りは、この方法で一発で原因を見付けるというのは難しいです。今回の調査でも、闇雲に調べるだけでは残念ながら決定打となる情報に辿り着く事はできませんでした。

期待外れだったのは、成功ケースで実際にdragoverイベントが発行されている場面の詳細を調べられなかったという点です。この処理はCocoaに対して登録しておくイベントハンドラのような関数の中にあり、Cocoaから通知されたイベントをトリガーに実行されるため、ここにブレークポイントを置いても（関数呼び出しのスタックが切れてしまっているので）デバッガでは処理の呼び出し元を辿る事ができないのです。「成功ケースと失敗ケースで明らかに異なる部分」が目の前にあるにも関わらず、そこからは何の情報も得られないという、非常に残念な結末でした。

ただ、ここまでの調査過程で以下の事は分かりました。

• 成功ケースでは親プロセス側で認識できたドラッグデータ（アドオンで定義したdragstartイベントのリスナにおいて、event.dataTransfer.setData()で追加したデータ）の個数が1以上になっているが、失敗ケースでは0になっている。子プロセス側で設定したはずのドラッグデータが親プロセスからは認識されていない。そのため、EventStateManager::DoDefaultDragStart()がfalseを返して終了する形となっており、ドラッグセッションを開始するnsDragService::InvokeDragSessionWithImage()が呼ばれていない。

• このドラッグデータはEventStateManager::DetermineDragTargetAndDefaultData() →nsContentAreaDragDrop::GetDragData() →DragDataProducer::Produce() →TabParent::AddInitialDnDDataTo() でTabParentのmInitialDataTransferItemsというメンバ変数の値を取得する形で初期化されている。

• TabParentのmInitialDataTransferItemsの値は、TabParent::RecvInvokeDragSession()で設定されている。このメソッドは、プロセス間通信でPBrowser::Msg_InvokeDragSession__IDというメッセージを受け取った時に実行されている。

  • この時のIPC周りのコードは自動生成されているため、デバッガでブレークポイントを設定できない。

• PBrowser::Msg_InvokeDragSession__IDというメッセージは、子プロセス側でnsDragServiceProxy::InvokeDragSessionImpl()が呼ばれた時に（IPC周りの自動生成されたコードを経由して）親プロセスに向けて送出される模様。

以上の通り、成功するケースでは子プロセス側のInvokeDragSessionと親プロセス側のInvokeDragSessionが両方とも期待通りに処理されるのに対し、失敗するケースでは親プロセス側のInvokeDragSessionに到達する前に（ドラッグデータが0個という事で）処理が終わってしまっている、という事が分かりました。という事は、失敗ケースでは「子プロセスが送ったメッセージを何らかの理由で親プロセスが受け取れていない」か、もしくは「子プロセスがそもそもそのメッセージを送出していない」かのどちらかであるという事が言えます。

標準出力・標準エラー出力に現れるメッセージの監視

状況の把握のためにPBrowser::Msg_InvokeDragSession__IDというメッセージやその他のメッセージを親プロセスが受け取れているかどうかを調べたいと思ってコードを見ていると、TabParent::RecvInvokeDragSession()の呼び出し元箇所にmozilla::ipc::LogMessageForProtocol("PBrowserParent",...というコードがある事に気付きました。関数の定義を調べてみた所、これはデバッグビルドの実行時にMOZ_IPC_MESSAGE_LOGという環境変数にPBrowserParentまたは1が設定されている時に、fputsで標準エラー出力にログメッセージを出力するという物であることが分かりました。このログメッセージが現れるかどうかを調べれば、上記のIPCのメッセージを親プロセスが受け取っているかどうかが分かります。

fputsで直接標準出力や標準エラー出力に出力されたメッセージは、MOZ_LOGで収集するログには出力されません。ではどこを見ればよいかというと、Xcodeの右下のペインです。標準出力や標準エラー出力に出力されたメッセージは、ここで確認する事ができます。

デバッグ実行時の環境変数は、Xcodeのメニューの「Product」→「Scheme」→「Edit Scheme」→「Run」→「Environment Variables」で設定できます。ここでMOZ_IPC_MESSAGE_LOGにPBrowserParentを設定して再度デバッグ実行して確認した所、成功ケースでは上記のログメッセージが出るのに対し失敗ケースでは出なかったという事から、親プロセス側がPBrowser::Msg_InvokeDragSession__IDというメッセージを受け取れていないという事が分かりました。

そうなると今度は、子プロセス側がIPCのメッセージを送出しているにも関わらず親プロセスが受け取れていない（IPCの仕組みの中での問題）のか、それとも子プロセス側でnsBaseDragService::InvokeDragSession()が実行されていないかのどちらかという点が問題になります。

任意のログを任意のタイミングで出力させる

ここで子プロセス側の処理に対してデバッガでブレークポイントを設定できればよかったのですが、弊社調査環境では何故か、MDNのマルチプロセス有効時のデバッグに関する説明通りに設定しているにも関わらず、設定したブレークポイントで処理を止める事ができないという状況でした。処理の流れを追いたい肝心のモジュールは前述した通りMOZ_LOGでの指定でログを出力してくれないため、これでは調査のしようがありません。

そのため、ここで初めてカスタムログに頼る事にしました。

MOZ_LOGで出力されるログは既存の物以外に、全く新しくログを出力する事もできます。C++製コンポーネントの開発に関わる人向けにMOZ_LOGで出力可能なログをC++製のモジュール内で定義する手順の説明が用意されていますので、これを参考に、EventStateManager.cppの冒頭で以下のようなログモジュールを定義するようにしました。

using mozilla::LogLevel;
static mozilla::LazyLogModule sEventStateManagerLog("EventStateManager");

その上で、ここまでに調査した範囲の中で特定していたドラッグを開始するかどうかの判定を何段階も行っている関数において、returnする直前にMOZ_LOG(sEventStateManagerLog, LogLevel::Info, ("DoDefaultDragStart - no drag service"));のような行を追加して、ログを見ればどのreturnで関数が終了したのかを分かるようにしました。

このようにして収集したログを調べて分かったのは、2回目以降の失敗ケースにおいては「現在進行中のドラッグセッションがまだあるならば、新たなドラッグセッションは開始しない」という判断の結果親プロセス側でドラッグセッションが開始されていない、という事でした。

つまり、1回目の失敗ケースから2回目以降の失敗ケースにかけての間では以下の事が起こっていたと考えられます。

• 成功ケースや1回目の失敗ケースでは、子プロセス側では通常通りにドラッグセッションが開始されている。

• その処理が親プロセスに引き継がれるまでの処理のどこかに問題があって、「子プロセスはドラッグセッションが開始されているが、親プロセスはドラッグセッションが始まっていない(終了した)と認識している」状態が発生した。

• 本来であれば子プロセス側のドラッグセッションを終了させるための処理が行われるはずなのに、この一連の処理がどこかの時点で中断されてしまったために、子プロセス側のドラッグセッショが終了処理が呼ばれず、ゾンビドラッグセッションが残留してしまっている。

• このゾンビドラッグセッションがあるせいで、親プロセスでドラッグセッションが開始されなくなっている。

ここまでで分かった事をまとめて、1回目の失敗ケースの原因を探る

ここまでの調査で、2回目以降の失敗ケースは「1回目の失敗ケースにおいて、子プロセス側のドラッグセッションが開始されたにも関わらず、親プロセス側ではドラッグセッションが開始されなかったために、子プロセス側で残ってしまったゾンビドラッグセッション」が原因で発生している事が分かりました。

そうなると今度は、1回目の失敗ケースで何故ゾンビドラッグセッションができてしてしまうのか、何故親プロセス側でドラッグセッションを開始できなかったのか（処理が中断されたのか）、という事を明らかにしなくてはいけません。

現時点までで、1回目の失敗ケースでは子プロセスから親プロセスへドラッグデータがきちんと引き渡されているという事が分かっています。そうなると、「ドラッグデータは受け取れているが、ドラッグセッションを開始できない」という状況が発生する条件は、一体何なのでしょうか？

以上の事を念頭に置きながら関連モジュールのコードを眺めていると、各プラットフォームで共通のドラッグセッション開始のための処理であるnsBaseDragService::InvokeDragSession()から呼び出されるmacOS版固有のnsDragService::InvokeDragSessionImpl()の実装の冒頭に、何らかの条件が満たされなかった時にNS_ERROR_FAILUREというエラーコードを返却するというコードがある事に気がつきました。

さらにその先を読み進めていくとbeginDraggingSessionWithItemsというCocoaのAPIを呼んでいる箇所があります。調べてみると、beginDraggingSessionWithItemsはまさにドラッグセッションを開始するためのCocoaのAPIであると書かれています。

ここまで分かってやっと、失敗ケースでdragoverイベントを発行するためのコードが何故呼ばれないかの謎が解けました。このコードはCocoaでのドラッグセッションが進行中である場合に呼ばれるdraggingUpdateというイベントハンドラの中にありますが、ドラッグセッションが開始されていなければ当然これらのイベントハンドラも呼ばれないという訳です。つまり最初から、beginDraggingSessionWithItemsの呼び出しに至るまでのコードパスを調査すればよかったのでした。Cocoa APIの知識を持たない状態で調査を始めたために、ひどく遠回りをしてしまった事になります。

ともあれ、これで調査が必要な範囲はだいぶ絞り込めました。今度はbeginDraggingSessionWithItemsが呼ばれなくなるパターンの分岐に絞ってMOZ_LOGを仕込んで再びログを収集してみた所、1回目の失敗ケースはまさに先程見付けたNS_ERROR_FAILUREを返す分岐に入っている、という事が分かりました。

その分岐に入る条件はgLastDragViewというグローバル変数が空である事で、これは意味としては、「どのビューでドラッグが開始されたか分からなければ、ドラッグセッションを開始せずにエラーを返す」という事です。

そこでこの変数に値を代入している箇所を検索した所、変数の初期化時を除くと、Cocoa API用のmouseDraggedというイベントハンドラの中でのみ値を設定している事が分かりました。具体的には、4728行目で「そのビュー自身」を代入し、イベントの処理を挟んだわずか10行後にnilを再代入しているという状況でした。そこでこの前後に絞ってMOZ_LOGをさらに仕込んで調査した所、成功ケースと失敗ケースでは非同期処理の実行順が異なっており、そのせいで失敗ケースでは、ドラッグが開始されたビューが分かるより前にドラッグセッションを開始しようとしてドラッグセッションを開始できずにいるらしいという事が分かりました。

詳しい人の意見を聞いてみる

Cocoa APIまわりの非同期処理の話になると、ますますこちらに知見がないため、これ以上の調査は難しく思えます。そこで一旦、識者に意見を求めてみる事にしました。

調査対象にしているファイルのコミット履歴を見ると、複数人が関与している様子が窺えます。この時に注目するのは、コミットした人やパッチを書いた人ではなく、パッチのレビューを行った人です。

パッチが投入されるまでの流れを見ると分かりますが、パッチのコミット自体はcheckin-neededという目印に沿って作業担当者が行っているだけなので、コミットした人は必ずしもそのモジュールのエキスパートという訳ではありません。また、パッチを書いた人もたまたま関わっただけの協力者という立場である可能性があります。それらに比べると、レビューはある程度の知見がないとできないため、複数のパッチでレビュー担当者として指名されている人ほど、信頼できる識者である可能性が高くなります。

Bugzillaではコメントを追記する時に「needinfo」という情報を設定できます。これはバグの報告者など他の人に情報を求める、つまり質問するときに使われる機能です。「Need more information from...」というラベルのチェックボックスをONにして、質問先の種別を「other」にし、上記の方法であたりを付けた識者の人のメールアドレスを入力して投稿すれば、これで「質問されている」という事がその人に通知されます。

数日待った所、その方が反応して下さり、「それぞれのケースのスタックトレースを収集してみてはどうか」というようなコメントを頂けました。

スタックトレースはXcodeのメイン画面の左ペインに表示されますが、これをそのままコピーする事はできません。文字列としてコピーできる形でスタックトレースを取得するには、ブレークポイントで処理を止めた状態でXcodeのウィンドウ右下のペインのコンソールの「(lldb)」と表示されている箇所（これが実はプロンプトになっています）にbtというコマンドを入力して実行すると、コンソール内にスタックトレースの情報が出力されます。これを選択してコピー＆ペーストすれば、スタックトレースを容易に収集できます。

この方法でスタックトレースを収集してじっくり比較してみた所、成功ケースではCocoa APIのmouseDraggedハンドラからそのまま呼び出しが続いているのに対し、失敗ケースではそうなっておらず、RefreshDriverTimer::Tickなどのメソッドの呼び出しが親となっていたという事が分かりました。

成功ケースでも失敗ケースでもmouseDraggedから全ての処理が始まっているとばかり思い込んでいたため、これは盲点でした。

どうやら、何らかの条件に合致した場合には、ドラッグ時のイベントの処理が実際には後のイベントループに回されており、その場合は必要な情報であるgLastDragViewが既に失われてしまっているのでドラッグセッションを開始できない、という事がこの問題の根本的な発生原因である模様です。このような状況は、元々同期処理で書かれていた物を後から非同期処理の形に改修したというような場面でよく見られる物です。Firefoxは現在、体感的なパフォーマンスの向上のための改良が続いていますので、その中でそういった事が起こる事は十分にあり得そうです。

パッチの作成

ともかく、原因が分かったことでようやく問題を修正する段階に移れます。

ここまでの調査で分かった原因からは、以下のような改修案が考えられます。

1. gLastDragViewをすぐにnilで破棄してしまわずに、ドラッグイベントの処理が終了するまで待ってから破棄するようにする。

2. gLastDragViewに相当する情報をイベントの情報の一部として引き回す、または保持しておき、後のイベントループで続きが処理される時にその情報を参照するようにする。

1の方法は非常に単純なやり方です。確実にこの問題は直りますが、gLastDragViewがメモリ上に保持される期間が長くなるため、メモリリークや、ドラッグ開始操作として認識されて欲しくない物が誤ってドラッグ開始操作として扱われてしまうといった新しい別の問題の原因になる恐れがあります。

2は、そういった副作用の恐れがない安全な方法に思えます。一般的にはこちらの方針で改修を行う事が望ましいと言えるでしょう。ただ、今回はこの方針を取るのがためらわれる理由があります。それは、gLastDragViewを設定している箇所や参照している箇所がmacOS固有の実装の中であるのに対し、設定箇所から参照箇所までの間に通過する処理はほとんど全てクロスプラットフォームな実装であるという点です。クロスプラットフォームな実装の中に特定プラットフォーム向けのコードを入れるという変更はあまり行儀が良いとは言えず、また、その中には非同期処理の基盤的な実装も含まれていたため、変更の影響が想像以上に広い範囲に及ぶ恐れがあります。副作用の恐れがないはずの方法の方が、実際にはリスクが大きいという困った状況です。

以上の検討結果を踏まえ、1の方が調査が必要な範囲は狭い（macOS固有の実装だけに変更が閉じる）と考えられたため、まずはその前提で影響範囲を調査・検討しました。その結果、想定外のタイミングでドラッグセッションの開始処理が呼ばれてしまう事は理論上あり得ないという結論に至ったため、実際に1の方針でパッチを作成しました。しかし安全であると言い切れる確証は持てなかったため、前のコメントで紹介して頂けた別のこの件に詳しい方にneedinfoで意見を求めてみる事にしました。

時間はかかったものの無事にその方にパッチを見て頂けて、方針はこれで問題ないというコメントと、追加で修正が必要な箇所（コメント形式で書かれた説明文が実装と食い違うようになるため、それらも併せて更新する必要がある）の指摘を頂きました。現在は、その指摘に基づいて更新したパッチを再提出してレビューを待っているという状況です。この後特に問題がなければ、パッチが取り込まれるまでの流れなどで紹介ている通りに進行してマージに至ると期待されます⁵。

まとめ

以上、プロセス間通信やmacOSでのドラッグ＆ドロップといった箇所の実装を調査して、バグの原因を特定しパッチを提出するまでの一通りの経緯をご紹介しました。

最終的なパッチは実質的には1行削除・2行追加しただけの内容ですが、そこに辿り着くまでの調査にはかなりの時間を要する結果となってしまいました。要因の1つに、Cocoa APIを使ったmacOSネイティブアプリにおけるドラッグ＆ドロップの実装の一般的な作法を知らないまま調査を進めた事がある事は否めず、その部分の調査をスキップする選択をしたという調査初期の判断ミスが悔やまれます。

この記事で述べた情報そのものが直接的に役に立つ場面はあまり無いと思われますが、未知の部分が大きい調査対象に取り組む際の様々なアプローチの仕方や、調査方針の見直しのタイミングなど、メタな部分で知見を得るための資料、あるいは「しくじり先生」的な反面教師として参考にしていただけると、この紆余曲折の記録も無駄にはならないのではないかと思っております。

OSSの利点の1つとして、今回のように、不可解なトラブルに遭遇した場合でも第三者の立場で詳細な調査を実施できる余地があるという点が挙げられます。本体の開発チームは通常のリリースに向けての作業に注力している事が多く、今回の問題のように希な条件下でしか発生しない・一般のユーザーに与える影響の小さい問題の解決はどうしても後回しになってしまいがちです⁶。しかし、その問題に遭遇した当事者にとってはまさに今直面している問題で、ともすれば死活問題ともなり得ます。そのような場合でもただ待つだけ以上の事ができるというのは、OSSならではの事と言えるでしょう。

当社は、そのようにOSS開発により積極的に関われるようになりたい人を支援するOSS Gateという取り組みを支援しています。このエントリを見て「普段使っているOSSに自分でもフィードバックできるのか！　自分もやってみたい！」と新鮮な驚きを感じた方や、「そうそう、こんな感じで調査するんだよね。このやり方が分からなくて困ってる人を手助けできればいいんだけど……」とお考えの方は、ぜひワークショップへの参加をご検討下さい。

また、当社ではFirefoxやThunderbirdの他、Fluentd、Groonga等のOSSの法人利用において発生する様々なトラブルや不具合について有償でのサポートサービスを提供しており、このエントリに記載しているようなソースコードレベルでの調査も承っております。業務上でのOSSの利用でお困りの場合、お問い合わせフォームよりお問い合わせ下さい。

ツイートする

フォローする