弊社は自社R&Dの一環で、外部の求人サイトから求人データを自動で集める仕組みを運用しています。夜間は差分(新着・更新分)だけを取り、週に1回だけ全件をクロールして「今も掲載中のID一覧」を作り直します。掲載が終わった求人は、この一覧に無いものとして毎晩自動で削除する設計です。
削除は取り消せない操作なので、安全装置を1つ入れてあります。その晩に消える予定の件数が、保存している全件の3割を超えたら、削除を実行せず見送るというものです。9月22日から27日にかけて、この装置が6晩連続で発火しました。実測と、真因が分かるまでの経緯をそのまま書きます。
疑った原因は「取得件数が少ない」。実測すると違っていた
削除見送りが続いた時点で、最初に疑ったのは「その晩の取得件数そのものが少ないのではないか」という仮説でした。夜間の差分取得は --days 3 で直近3日分を取り直す設計で、実測すると3,600〜4,100件。9月17〜19日の正常時(3,656〜4,340件)とほぼ同じ水準でした。
夜間の取得は正常に動いていました。 疑いは外れです。
真因:週1回しか作らない「現役一覧」が、途中で切れたクロールで上書きされていた
週次の全件クロールの実測(実行ログ)を時系列で並べます。
| 日付 | 取得ユニーク数 | サイト申告の全件数 | 捕捉率 |
|---|---|---|---|
| 9/01 | 67,313件 | 131,872件 | 51.0% |
| 9/07 | 101,121件 | 133,333件 | 75.8% |
| 9/14 | 103,716件 | 137,012件 | 75.7% |
| 9/21 | 26,595件 | 140,731件 | 18.9% |
| 9/27 | 11,666件 | 145,004件 | 8.0% |
9月21日のクロールは、ページ1071で「次へ」ボタンが検出できず、そこで止まっていました。捕捉率が正常時の4分の1にも届かない26,595件だったにもかかわらず、当時のガードは「1,000件未満なら一覧を更新しない」という粗い基準しか持っておらず、26,595件はこれを素通りして「現役ID一覧」を上書きしました。
この時点で保存件数は19,983件。新しい(壊れた)一覧と一致するのは5,786件だけになり、残り14,197件(71%)が「一覧に無い=掲載終了」と判定され、削除対象になりました。 3割の安全装置は正しく発火し続け、9月22日から6晩、削除を止め続けていました。安全装置自体は設計どおりに動いていたことになります。
もう1つのバグ:消える前から、消える運命だった求人がある
調べる過程で、別の不具合も見つかりました。9月14日から20日の実行記録を見ると、その晩に新しく追加した件数と、その晩に削除した件数がほぼ同数という状態が続いていました。
- 追加4,026件 → 削除4,016件
- 追加4,340件 → 削除4,320件
保存件数はこの間13,4xx件でほぼ横ばいでした。原因は現役一覧が週1回(日曜夜)しか作り直されないことです。その週の途中で新しく公開された求人は、次の日曜まで一覧に載りようがありません。 ところが毎晩の削除判定は「一覧に無い=終了」と読んでしまうため、公開されたばかりの求人をその晩のうちに削除していました。
実際、今回の削除対象14,197件のうち5,404件は9月21日以降に公開された求人でした。一覧が作られる前に生まれたものが、一覧に無いことを理由に消される対象になっていたということです。
直したこと、そして直後にもう一度落ちた捕捉率
コード側に2つの修正を入れました(この時点で削除は未実行のまま)。
- 週次一覧の上書き条件を厳格化:申告全件数の6割未満、または前回一覧の7割未満しか取れていない場合は上書きしない(正常時の捕捉率は約76%)
- 削除判定の除外条件を追加:一覧の作成時刻から1日以内に更新・公開されたものは、一覧に無くても削除対象から外す
この2つを適用して同じデータで削除対象を数え直すと、14,197件(71%)から8,209件(41%)まで下がりました。それでも3割の安全装置は依然として超えており、修正後の一覧のままでも削除は見送られる計算です。
修正を入れた直後の9月27日、週次クロールが再び走りましたが、捕捉率はさらに悪化して8.0%(11,666件/申告145,004件)でした。 ただし今回は新しい6割ガードが効き、ログにはこう残っています。
11,666件は申告total 145,004件の6割未満(途中打ち切りの疑い)。現役ID一覧は更新しない
一覧は更新されず、壊れたデータが本番に伝わることはありませんでした。9月27日から29日にかけての夜間更新は3晩とも正常に完走し、保存件数は59,492件→59,806件→59,976件と、減るのではなく素直に増えています。
まだ分かっていないこと
- なぜ週次クロールが途中で切れるのか、原因は未特定です。 「同じアカウントで別のログインが起きてセッションが切られた」「描画の遅延で次ページボタンの検出に失敗し、それを正常終了として扱ってしまった」の2つの仮説があり、9月28日時点で調査が割り当てられていますが、本稿執筆時点(9月29日)で結果は出ていません
- 9月14〜20日に消えた新着(合計21,489件)は自動では戻りません。 差分取得の窓(3日)を過ぎたものは次の夜間更新では拾えないため、週次の全件取得結果を保存側へ合流させる経路が別途必要です。この経路自体は9月27日に条件つきで承認されていますが、着手条件(週次クロールが申告数の6割以上で完走すること)を2週連続で満たせておらず、着手できていません
「取得件数が少ない」という最初の仮説は、原因を1つの数字(当日の件数)だけで見ていたために外しました。実際に効いていたのは、頻度の違う2つの処理(毎晩の差分と毎週の全件)の間で、片方が壊れたときにもう片方がそれをそのまま信じてしまうという構造でした。安全装置は仕事をしましたが、それは症状を止めただけで、原因を教えてはくれません。原因を見つけるには、結局ログを日付ごとに並べ直して実測するしかありませんでした。