9月18日の夜、ライセンスサーバーの管理画面を開いたら、一覧が空になっていました。
Rapls AI Chatbot Pro の購入者のライセンスが、十数件あるはずの場所です。
データを入れている JSON ファイルを見に行くと、サイズは 947 バイトでした。
先に、分かったことを並べておきます。
消えた原因は、同時に届いた2つのリクエストの競合でした。
片方がファイルを書き直している途中に、もう片方がそれを読み、「空」として扱って保存し直した。
それを許していたのは、読めないファイルを空と見なす初期値と、ロックなしでファイル全体を上書きする保存方式です。
しかも、同じ仕組みのサーバーが4つあるうち、3つはすでに対策済みでした。直していなかった1つで、この事故が起きています。
戻せたのは、資料が別々の場所に残っていたからでした。
管理画面から書き出した CSV、開発機に残っていた古いコピー、Stripe の決済データ、Xserver の自動バックアップ。
どれか1つだけでは、完全には戻りませんでした。
以下は、その夜から翌日の0時過ぎまでに確かめたことの記録です。
947バイトに残っていたもの
947 バイトのファイルは、壊れてはいませんでした。
JSON として正しく読めます。中身は空のライセンス一覧と、ログが数件だけ。
消えた後の最初の記録は、サーバー時刻 22:47:30 のダウンロードでした。
この日は、Pro 1.9.6 を配信した日です。
各サイトから更新確認とダウンロードが来ていました。
配信が原因だとまでは言えません。ただ、リクエストが重なりやすい時間帯だったことは確かです。
購入者のサイトで、Pro は止まったのか
一番先に確かめたのは、ここでした。
ライセンスが消えたなら、購入者のサイトで Pro の機能が止まっているかもしれない。
止まっていませんでした。
ライセンスの有効・無効は、データファイルではなく、キーとメールアドレスの署名で判定しています。
データが消えても、キーそのものは正しいと判定される。
それに、各サイトから1日1回届く確認は、記録が見つからなければその場で作り直す作りでした。
設計したときに、ここまで考えていたわけではありません。
データファイルに頼らずに判定できるほうが単純だった、というだけです。
結果として、その単純さに助けられました。
戻らなかったのは、バックアップ時点から消失までの2日ぶんの細かな記録、たとえば最終アクセス時刻の更新くらいでした。
その間の新規購入はありません。Stripe の最後の決済は 9/14 で、返金もゼロでした。
どうやって消えたか
ライセンスサーバーは PHP 1ファイルで、データは JSON ファイル1つにまとめています。
ライセンス、登録サイト、失効リスト、ログ、管理画面のセッションまで、全部この1ファイルです。
危なかったのは3点でした。
まず、読めないときの扱いです。
ファイルがない、読めない、JSON として壊れている。どの場合も、エラーにせず空の配列を返していました。
| 1 2 3 4 | $data = json_decode( @file_get_contents( $file ), true ); if ( ! is_array( $data ) ) { $data = array(); // 読めなければ「空」から始める } |
それから、保存の仕方です。
file_put_contents() でファイル全体を書き直すだけで、排他ロックも、一時ファイルからの差し替えもありませんでした。
最後に、書き込む頻度です。
保存処理の呼び出しは 20 か所。1日1回の確認も、アクセス記録を残すためにファイル全体を書き直していました。
この3つが揃うと、こうなります。
リクエスト A がファイルを書き直している。その瞬間、中身は一瞬空になる。
そこへリクエスト B が来て読む。読めないので空として扱う。
B は「空＋自分のログ1行」を保存する。全ライセンスが消える。
947 バイトのファイルは、まさにこの「空＋ログ数件」の形でした。
余談ですが、この構図には見覚えがありました。
先週書いた PDF のサムネイルが真っ白になる件です。
あちらは、古い Ghostscript が描けなかったページを白紙として返し、受け取った側がそのまま保存していました。
こちらは、読めなかったファイルを空として扱い、そのまま保存していた。
失敗が成功の形をして返ってくる、という点で同じです。自分でそう書いた翌週に、自分のサーバーで同じことをしていました。
本当に、それで全部消えるのか
「たぶん競合だろう」で止めたくありませんでした。
見立てが違っていたら、直しても再発します。
ローカルで同じ条件を作りました。
ライセンス 200 件のデータを用意して、「読む → 1件追記 → 保存」するプロセスを 300 個同時に走らせる。
| 残ったライセンス | 取りこぼした更新 | 残ったファイル | |
|---|---|---|---|
| 修正前（1回目） | 0 / 200 | 288〜295 件 | 257〜552 バイト |
| 修正前（2回目） | 0 / 200 | 〃 | 〃 |
| 修正前（3回目） | 0 / 200 | 〃 | 〃 |
| 修正後 | 200 / 200 | 0 件 | 正常 |
修正前のコードは、3回とも全件が消えました。
残ったのは数百バイトのファイル。サーバーで見つかった 947 バイトと同じ状態です。
ここで原因を確定と判断しました。
全件消えるとは、思っていませんでした。
何件か取りこぼす程度だろうと見ていました。3回続けて 0 が並んだのを見て、この夜まで無事だったほうが不思議に思えてきました。
戻す前に、直す
復旧より先に、サーバーを直しました。
直さずにデータだけ戻すと、同じ競合でまた消えます。
直し方は、自分で考えたものではありません。
Prime Cache のライセンスサーバーに入っていた設計を、そのまま移植しました。
同じ仕組みのサーバー4つのうち、Prime Cache、PDF Image Creator、Passkey の3つは、とっくにロックと安全な書き換えが入っていたからです。
対策を作ったときに、横に展開しきれていなかった。消えたのは、取り残された1つでした。
移植した内容は、こうです。
まず、1回のリクエストのあいだ、別のロック用ファイルを flock で専有する。同時に来たリクエストは順番待ちになります。
それから、一度でも保存したことがあるサーバーでは、ファイルがない・空・壊れている場合にエラーを返す。空として上書きしない。
保存は一時ファイルに書いてから名前を変えて差し替える。書きかけのファイルを読まれることがなくなります。
新しく足したのが、日次の自動コピーです。その日の最初の変更の前に、データを日付つきで複製して、14日分残す。
最後に、待ち時間を減らすために、国判定の外部問い合わせはロックの前に済ませ、約 16MB の ZIP を送る前にはロックを外すようにしました。
順番待ちが発生しても、1日1回の確認と、ときどきの有効化しか来ないサーバーです。実用上の問題はありません。
4つの資料から組み立てる
Xserver のバックアップを取り寄せているあいだに、手元の資料から仮のデータを組み立てました。
| 資料 | 取れた情報 |
|---|---|
| 管理画面の CSV 書き出し（9/16） | 全ライセンス、メールアドレス、種別、登録サイト、最終アクセス |
| 開発機に残っていた 7/23 のコピー | 購入者名の一部、正確な発行時刻、7/23 までのアクセス履歴 |
| Stripe の決済データ | 購入者名、決済時刻、返金の有無 |
CSV は、何かのときのためにと2日前に書き出していたものです。
7/23 のコピーは、開発中に手元へ持ってきたまま忘れていました。
どちらも、バックアップのつもりで残したものではありません。
発行時刻は、Stripe で埋まりました。
ライセンスは決済の直後に自動で発行されるので、決済時刻（UTC）を日本時間に直すと、CSV の発行日と一致します。
7/23 以降に発行されたぶんの時刻は、これで補えました。
Stripe の決済すべてに対応するライセンスがあることも、ここで確かめられました。
CSV を書き出した後に新規購入がない、という確認にもなっています。
組み立てたデータは、そのまま使いませんでした。
サーバーと同じ判定処理、つまり署名の検証に全件かけて、全件が通ることを確かめてから入れています。
手で組み立てたデータは、どこかで1文字ずれていても気づけないからです。
Xserver の自動バックアップ
本復旧は、Xserver の自動バックアップから行いました。
Xserver は、サーバー上のデータを過去14日分、自動でバックアップしています。サーバーパネルから取得を申し込めます。
使ってみて分かったことが、いくつかあります。
取得する範囲は、ライセンスサーバーのフォルダだけに絞りました。ファイル数が少ないほど早く終わります。
取得したデータは /userbackup に置かれ、24時間で自動的に削除されます。取れたら、すぐダウンロードしておく必要があります。
所要時間の公式な目安は、見つけられませんでした。データ量とファイル数、そのときのサーバーの負荷しだいのようです。
9/19 の0時ごろにバックアップが届き、中身を検証しました。
JSON として正常。署名の検証は全件通過。メール・種別・登録サイトは、仮復旧データと全件一致。
購入者名、正確な発行時刻、数百件のアクセス履歴は、仮復旧データより完全でした。
最終版は、バックアップを土台にしました。
そこへ、消失後に書き込まれたログ 8 件と、管理画面のログイン状態だけを仮復旧データから足しています。
仮復旧データは、結局ほとんど使いませんでした。
それでも作ってよかったと思っています。バックアップが届くまでの数時間、「最悪でもここまでは戻せる」という線が手元にあったので、落ち着いて原因を追えました。
ホスティングのバックアップだけでは足りない
今回、Xserver のバックアップに助けられたのは事実です。
ただ、14日で消えます。取得にも手間と時間がかかる。気づくのが2週間遅れていたら、この手段は使えませんでした。
だから、サーバー自身が日次のコピーを残すようにしました。
ホスティングのバックアップは最後の手段で、最初に手が届く場所には、自分で置いたコピーがあるべきでした。
restic で同じ日の世代が消える件を書いたときも、似たことを考えていました。
バックアップがあることと、戻したい時点のものが残っていることは、別の話です。
9月19日の管理画面
0時を少し過ぎたころ、管理画面の一覧をもう一度開きました。
十数件のライセンスが、発行時刻と購入者名つきで並んでいます。
データファイルのサイズを見ると、947 バイトから、数十キロバイトに戻っていました。
4つのサーバーは、これで全部同じ設計になっています。
次に直すものが出てきたら、今度は4つ同時に直します。
関連記事
- PDFのサムネイルが真っ白になる。エラーはどこにも出ない ── 失敗が成功の形で返ってくる、同じ構図の別件です
- WP-CLI が全部落ちた。原因は自分のプラグインが読み込んでいた Composer だった ── 動かないときに道連れにしない、という話です
- restic で同じ日の世代が消える｜keep-within と launchd の設定 ── バックアップがあることと、戻したい時点が残っていることの違いです
コメント