- 2023年7月8日、Vivaldi SocialのMastodonインスタンスで古いユーザーアカウントが消え、最終的に198個のアカウントが単一のリモートアカウントにマージされる事故が発生した
- 直接の削除や攻撃ではなく、Mastodonのアカウントマージ動作と、Vivaldi SocialのMakaraベースのPostgreSQLレプリケーション構成が重なり、処理順序がずれたことが原因だった
- アカウントは削除されたように見えたが、ユーザー名が再割り当てされ、アバターやヘッダー画像も一緒に消えていたため、問題はMastodonアプリケーション内部の動作に絞り込まれた
- 運用チームはDB全体のロールバックを準備しつつ、選択的な復旧スクリプトも並行して作成し、アカウント、投稿、フォロー、フォロワー、関係データを復元した
- Mastodon v4.1.5には、SidekiqワーカーでのMakara使用を防ぐ修正と、アカウントマージの順序修正が含まれており、レプリケーションDBを使うサーバー運用者はワーカーの読み取り経路を点検すべきである
198個のアカウントが消えた週末の事故
- 2023年7月8日土曜日17:25 CESTごろ、Vivaldi Socialのタブが再ログインを求め、ログイン後にホームタイムラインが空の状態であることが確認された
- 別のシステム管理者アカウントでも同じ症状が現れ、データベースを確認したところ、影響を受けたアカウントは削除された後、ユーザーが再ログインするたびに新規アカウントのように再作成されていた
- Vivaldi Socialには金曜日23:00 UTCの夜間バックアップがあり、運用チームは復旧可能性を確認するためバックアップファイルのコピーを開始した
- 通常のMastodonアカウント削除ではユーザー名が永久に予約され再利用されないが、今回の事故では同じユーザー名が再割り当てされており、通常の削除ではなかった
削除は進行中だった
- 当初はIDが142未満の古いアカウントが消えていたが、19:10にはIDが217未満のアカウントまで消えており、削除が進行中であることが判明した
- 19:18にMastodon開発者へ支援を要請し、Renaudが応答した後、ClaireとEugenも調査に加わった
- 19:20にMastodonのDockerインスタンス群を再起動すると削除は止まり、データベース上で最も小さいアカウントIDは236になった
- 事故期間中に削除またはマージされたアカウントは、最終的に198個と確認された
攻撃ではなくアプリケーション動作に絞り込み
- 運用チームとMastodon開発者は、
UserCleanupSchedulerが「未確認」のアカウントを削除した可能性を確認したが、削除されたユーザーがそのクエリ条件に該当し得なかったため除外した
- 事故の48時間前にMastodon 4.1.3へアップグレードしていたため、v4.1.2とv4.1.3の間の変更や、Vivaldiが公開した変更点まで調査したが、関連する原因は見つからなかった
- ファイルシステム上で、削除されたアカウントのアバターとヘッダー画像も一緒に消えており、単純なDB直接削除ではなく、Mastodonアプリケーションが削除動作を実行したことが確認された
- ログとファイルシステムから侵入や攻撃の痕跡を探したが証拠はなく、Mastodon v4.1.3のセキュリティ修正に関連するエクスプロイトの可能性も確認されなかった
- 土曜夜にはアカウント削除動作に関するログを追加するパッチをデプロイし、00:29 CESTにパッチ版がデプロイされた後、チームは休息を取った
決定的な手がかり：1つのリモートアカウントに集まった投稿
- 日曜日13:56、Vivaldiのセキュリティ専門家YngveのプロフィールページがHTTP 500エラーを返す現象が報告され、このアカウントは198個の削除アカウントには含まれていなかった
- ログには同じリモートMastodonインスタンスの同じアカウントが繰り返し現れており、本文ではこれを
social.example.comのアカウントとして仮名化している
- そのリモートアカウントのステータスを照会したクエリは17,600行を返した
- 14:43には、削除されたすべてのアカウントのすべてのステータスが、
social.example.comの1人のユーザーへ再割り当てされていたことが、バックアップとの比較で確認された
- 15:00以降、
AccountMergingWorkerのログ、Railsコンソール、追加のDBクエリを通じて、アカウントマージワーカーがすべてのアカウントを1つのリモートアカウントへマージしていたという仮説が強まった
根本原因：アカウントマージとPostgreSQLレプリケーション遅延
- Vivaldi SocialはPostgreSQLの2サーバーレプリケーション構成を使用しており、ワーカープロセスがMakaraを通じてスタンバイサーバーからデータベース読み取りを実行できる状態だった
- Claireが17:28に示した事故シナリオは次のとおり
- Vivaldi Socialが
social.example.comから届いたアカウント名変更通知を受信する
- 新しいアカウントがデータベースに作成される際、
URIフィールドがnullとして入る
- その後、新しいアカウントの
URIがリモートアカウントの正しい値に設定される
- Redisを通じて、既存アカウントから新アカウントへデータをマージする
AccountMergingWorkerの実行が予約される
- データベースのレプリケーション遅延により、
URI設定とワーカー実行予約の順序が、実際の読み取り時点でずれる
- Mastodonインスタンスのすべてのローカルアカウントは
URI値がnullであるため、ワーカーが同じURI値を持つアカウントを新しいリモートアカウントへマージする際、すべてのローカルアカウントがマッチした
- 開発者たちは、データベース負荷が高まりレプリケーション遅延が長くなると、このような事象が起きやすくなると見た
- 運用チームとMastodon開発者は、この構成が根本原因である可能性が非常に高いと判断した
パッチと設定変更
- 原因が絞り込まれた後、運用チームはデータ復旧に集中し、Claireは再発防止パッチを書くことにした
- Hliniはパッチを適用し、もはや推奨されていないレプリケーション構成を変更する作業を担当した
- 17:58のデプロイ中に問題が発生し、その週末で唯一の全面ダウンタイムがあり、18:18にVivaldi Socialは再び稼働した
- 18:44にはパッチと設定変更が正常にデプロイされ、同じ事故は再発しないと判断された
復旧：全体ロールバックではなく選択的復元
- 当初はデータベース全体のロールバックを検討したが、既知のパフォーマンス問題のため、バックアップ
.dumpを.sqlへ変換し、54GBのテキストファイルを修正する必要がある複雑な手順が必要だった
- 運用チームは全体復元手順と選択的復元を並行して進めた
- Hliniは54GBの
.sqlファイルを修正し、全体復元の準備を進めた
- Thomasは削除されたアカウントと関連データを復元するスクリプトを書いた
- スクリプト作成中、PDOクエリのパラメータバインディングを参照として扱ってしまうミスがあり、Ísakがこれを見つけた
- 23:04には、影響を受けた198人のuser、account、identityレコードを修正する最初の部分が完成した
- 23:55には、status、follows、followers、関係データなどを事故前の状態へ戻す選択的復旧スクリプトが完成した
選択的復旧の完了と後続修正
- データベースの関係制約のため、復旧は2段階で進められた
- まず198人全員のuser/account/identityレコードを復旧する
- その後、残りの関係データを復旧する
- 一部ユーザーが事故後に再ログインしてフォローを設定したケースでは重複キーエラーが発生し、スクリプトは復元不能な既存レコードを削除し、より新しいレコードを保持するよう修正された
- 月曜日01:27 CESTにスクリプトの最後の処理が終わり、01:40にはホームフィードの再インデックスが完了した
- 結果として198個のアカウントのホームフィードが復旧し、全体ロールバックは不要になった
- 月曜日と火曜日には、後続の問題がさらに修正された
- ユーザー名に記号が含まれる6個のアカウントのログイン問題
- 198個のアカウントのWeb設定データ消失
- フォロワー数・投稿数などのプロフィールカウンターの誤り
- 誤ったデータがあった4個のアカウント
Mastodonの公式修正
- Mastodon開発者は、Makaraベースのレプリケーション構成でMastodonを使うリスクを他のサーバー運用者に知らせた
- このような構成はVivaldi Socialのような大規模インスタンスでなければ検討されにくく、まれなケースだと整理された
- Mastodon v4.1.5には、今回の事故に関連する2つの修正が含まれている
UTC基準の事故タイムライン
- 土曜日15:15：外部インスタンスからアカウント名変更メッセージがVivaldi Socialへ伝達され、誤ったアカウントマージ処理が始まる
- 土曜日15:25：事故の最初の兆候が観測される
- 土曜日17:20：Dockerコンテナ再起動後、アカウントマージ処理が停止する。15:15から17:20の間に合計198個のアカウントが削除・マージされる
- 日曜日13:00：考えられる根本原因を特定する
- 日曜日14:25：根本原因を確認する
- 日曜日21:55：データ復旧を開始する
- 日曜日23:27：データ復旧を完了する
- 月曜日10:40：ユーザー名に記号が含まれる6個のアカウントを修正する
- 月曜日11:05：失われたWeb設定データを復元する
- 火曜日15:31：誤ったカウンター値を修正する
- 火曜日16:01：誤ったデータがあった4個のアカウントを修正する
1件のコメント
Hacker Newsのコメント
すばらしい振り返りで、特に睡眠不足のような人的コストが複雑な障害対応にどれほど大きく影響するかもよく描かれていた
いちばん目を引いたのは、「新しいアカウントがURIフィールドにnull値を持ったままデータベースに作成された」というくだり
データベース関連の事後分析を見るたび、ほとんどいつもNULLが事故現場の近くに潜んでいる。NULLが犯人でなくても、常に尋問対象には入れるべき
助言するなら、NULLをセンチネル値として頼らず、可能ならデータベースでそもそも許可しないほうがよい。利点があるように見えても、数年後にデータモデルの意味が変わり、一見無害そうな文がNULLまたはNOT NULLを期待した結果、予想外の結果を生む見つけにくいバグで相殺されがち
今回の件は競合状態だったが、ローカルアカウントとリモートアカウントを型で明確に区別していれば処理順は重要ではなかったかもしれず、アカウント統合コードもより狭い範囲に限定できたはず
Nullはデータとして完全に有効な値であり、そのように扱うべき。ブール値に-1を使ったり、文字列に空値を使ったりするようなデフォルト値は、NULLなら実行時エラーになっていたシステムを見かけ上は動くようにできるが、それはシステムが期待どおりに動いているという意味ではなく、単に静かになるだけ
NULLを覆い隠したくなる誘惑は理解できるが、「ない」も「ある」と同じくらいデータの有効な状態であり、システムは一般にそれを受け入れるよう書かれるべき
この場合、問題はデータベースのNULLではなく、アプリケーション層のNULLだと思う
NULLが一種のMaybeモナドのように強制的に処理しなければならない値なら、最終的には処理することになり、考えることになる。空文字列であれ、使っている言語のnull文字列であれ、自作の特殊な標識値であれ、大差はない
多くの場合、実装者はまずGit式のマージコンフリクトが求める懸念事項と相互作用の要件を思い浮かべ、その出発点から問題領域に合った単純化の仮定を立てるべき
Mastodonのソース https://github.com/mastodon/mastodon/blob/main/app/workers/a...を見ると、マージ要求を開始した側から非同期マージ実行者へ渡す「どのIDからマージするか」の明示的なリストすらないように見え、このようなことが起きるのは時間の問題だったように思える
Mastodonへの批判ではない。自分でもはるかにひどい競合状態のあるマージロジックを書き、その被害も受けた。実際、https://opencollective.com/mastodon のようなボランティアプロジェクトにこうした機能が存在すること自体が驚きだ。それでも警戒すべき事例ではある
さらに深く言えば、現実は雑然としていて、データベースは現実が雑然としているという理由で処理を拒否できないため、NULLは避けられない。たとえば敬称、前置称号、後置称号をモデル化し、そのデータで完全なあいさつ文を作りたいとしよう。少なくとも後置称号がない人はいる。NULLを保存しなくても、あいさつ文を作るために使うJOINの結果としてNULLを得ることになる
特定のNULL値は排除できても、現実では「該当なし」や「不明」がしばしば有効な値であるという事実は排除できず、データベースはそれを扱わなければならない
ここで共感できる流れは、「データベース全体のバックアップがあるから全体復元すればよい」から始まり、「全体復元は難しく、ダウンタイムと副作用がある」となり、さらに「賢く欠けたデータだけを部分的に復元できそうだ」となって、手作業で進めるうちに妙なエラーに遭遇し、結局その場で作った選択的復元をデプロイし、最後に欠けていたデータ5件を片付ける、という過程。6件目を見落としていないことを願いつつ
誰がバックアップ/復元を練習しても、毎回こういう流れになる。結局、バックアップイメージからどのデータを戻すかは常にアプリケーションレベルで決めなければならないことになる
ただ、この場合は何が問題だったのかよく分からない。最後の正常なバックアップから全部復元すれば、その間に投稿された一部の投稿が消えてしまって残念ではあるが、手作業や不確実性の代わりに即座に解決できる方法ではある
Mastodon開発チームのRenaud、Claire、Eugenが期待以上に助けてくれたというくだりが印象的
VivaldiがMastodonに資金援助しているのかは分からず、スポンサーのページでも名前を見つけられなかった。そうでないなら、今回の件をきっかけにVivaldiやMastodonを使う他の企業がスポンサー支援やサポート契約を検討してくれるとよい
スポンサー支援は受け付けており、実際に大きな影響がある。プロジェクトにフルタイムの人員がいることは非常に重要だが、現在技術側には創設者のEugenのほか、フルタイム開発者1人とDevOps担当者1人しかいない
久しぶりに読んだ事後分析の中ではかなり良い部類だった
2番と3番がアトミックに処理されないのは問題のように感じる。もちろん、そうするのが自明ではない理由はあるのだろうが、コードはまだ見ていないので、いつか見てみる必要がある
アトミックにするのは自明だったように見える
以前はその必要がなかっただけ。アトミックでなくても問題にならない、つまり誰かが sidekiq を古いデータベースサーバー、つまりレプリカに接続するという悪い設定をしない限りは、という意味。ここではその設定が主な問題に見える
初めて巨大な SQL ダンプを復元しなければならなかったとき、vim がそれを読み込もうとして実際にセグメンテーションフォルトを起こすのを見て忘れられない
そのとき split(1)、つまりファイルを断片に分ける魔法を発見した。大きなダンプをテーブルごとのファイルに分割した
もちろんテーブル1つでも巨大になり得るが、少なくともファイルがより均一になり、sed や awk のような別のツールでクエリを変換しやすくなる
ただし、データを復元するためにダンプを編集しなければならない時点で、復元手順に何か大きな問題がある。もちろん実際にその状況に置かれたときには、そういう知識はあまり役に立たない
回避策は Python スクリプトを書いてすべてを段階的に処理し、共通のプレフィックスごとにファイルをサブディレクトリへ移動するというものだった
「Claire がログ項目の完全なスタックトレースを要求し、ログからそれも抽出できた」という部分で眉が上がった
これは深いブードゥー魔術か、コードや設定が Xeon を 286 相当にしてしまっているのかのどちらかだ。リクエストごとにメガバイト単位になるのでは？
Ruby on Rails のデフォルト動作。500 や不明なエラーが起きるとスタックトレースを出力し、内容は行番号とファイルパス程度
かなり設計の悪い Rails アプリを運用しているが、今確認したところ 500 ひとつのスタックトレースは 5KiB だった。500 エラーはおよそ1時間に1回だけなので、1日でも 1MiB 未満
コールスタックを手元に置いておくのは、実際には性能面でかなり問題ない。Java のデフォルトの例外動作も、例外ごとにスタックトレースを一緒に持ち上げるもので、出力しなくてもそうだが、Java アプリケーションは普通に動く。いずれにせよ戻り方を知る必要があるのでコールスタックは持っており、追加で必要な情報はファイル名と行番号のデバッグシンボルだけ。Ruby は言語の性質上、その情報がどのみち必要になる
「Mastodon インスタンスのすべてのローカルアカウントは URI フィールドが null 値だったため、すべて一致した」というのはどうして可能なのか？
NULL = NULL は FALSE と評価される。SQL は3値論理、正確には Kleene の弱い3値論理を使い、NULL にどんな演算子を適用しても NULL になる
URI 列に NULL 値があるアカウントがどうやってクエリにマッチしたのか分からない。NULL は NULL と等しいとは比較されない。これはひどいRails の魔法なのか？
ユーザー名に記号がある6人のユーザーがログインできず、復旧スクリプトのミスのため簡単に直せたというくだりを見ると、UTF-8 がまた一仕事したという感じがする