はじめに
動画を毎日、自動で書き出して、自動で上げています。人が触るのは止まったときだけ、というつもりで組みました。
ある日、進み方がおかしいことに気づきました。1日1日分進むはずのものが、1日あたり0.4日分しか進んでいないのです。
止まってはいません。エラーも出ていません。ログを見ても異常がありません。それでも進んでいませんでした。
原因は、発火する時刻でした。たった1行の設定です。
この記事は、自動投稿を組んだあとに実際に起きたことの記録です。うまく動かす方法ではなく、静かに壊れる形を先に知っておくための記事です。
書いてあるのは全部、私が踏んだものです。数字はすべて実測値で、日付を書いたものはその時点の値です。
コードは出てきません。「どのライブラリを使うか」の話でもありません。組んだあとに何が起きるかだけを書きました。
第1章 発火時刻を1つ間違えると、毎日0本になる
いちばん高くついた失敗から書きます。
自動実行の発火時刻を、日本時間の14時に設定していました。深夜を避け、朝の混雑も避けた、無難な時刻のつもりでした。
ところが、使っているAPIの利用枠は太平洋時間の深夜0時にリセットします。日本時間に直すと、夏時間なら16時、冬時間なら17時です。
つまり、こういうことが起きていました。
（実行／太平洋時間での換算／結果）
毎日、昨日の空の枠を叩きに行って、2秒で諦めていました。
手で叩いた日だけ進んでいたので、平均すると1日0.4日分。この数字がずっと不思議でした。
対策は発火時刻を後ろにずらすだけです。ただし、16時30分では足りません。 冬時間になるとリセットが17時になるので、同じ事故が再発します。17時30分なら通年で安全側です。
ここで書いておきたいのは、時刻そのものではありません。
この規則は、すでに自分の手元に書いてありました。
4か月前に別のプロジェクトで同じことを整理して、「16時30分が最適。理由はAPIのリセット直後だから」と記録に残していました。設定ファイルの雛形まで作ってありました。
このプロジェクトだけが、その雛形を使わずに手で書かれていました。
問題は「規則が無かった」ではありません。規則が守られていないことに、誰も気づかなかったことです。
自動実行を新しく仕込むときは、雛形をコピーする。手で書かない。 これだけで防げました。
そして、もう1つ。同じ地雷が、まだ他の2つの自動実行に残っていました。片方は10時30分発火、もう片方は12時発火です。どちらも太平洋時間では前日にあたります。
いまは1日3本しか上げていないので、枠を使い切る前に終わっています。だから顕在化していません。 本数を増やした瞬間に、同じ止まり方をします。
「いまは動いている」は「正しい」ではありません。 負荷が上がった瞬間に露出する誤りが、静かに待っていることがあります。
なぜ4か月も気づかなかったのか、という話も書いておきます。
私は「動いているか」しか見ていませんでした。 自動実行の一覧を叩けば、登録されていることは分かります。エラー通知も来ません。だから動いていると判断していました。
見るべきだったのは、「何本入ったか」です。
これは1行で数えられます。上がった本数を数えて、期待値と比べるだけです。それをしていれば、初日に分かりました。0本だったのですから。
「動いている」と「仕事をしている」は別物です。 自動化の監視は、前者ではなく後者を見ないと意味がありません。
第2章 「ログが無い」は「動いていない」ではない
原因を探すとき、私は最初にログを見ました。そして間違った結論を出して、正しい仮説を一度取り下げました。
見ていたのは、設定ファイルで指定した標準出力と標準エラーのファイルです。開いたら、権限まわりのエラーが4行だけ入っていました。「これが原因か」と思いました。
その4行は、3か月前のものでした。
ファイルの更新日時を見ていませんでした。
なぜ古いままだったか。実行を包んでいるシェルスクリプトが、自分でログファイル名を組み立てて、日付入りの別ファイルに書いていたからです。設定ファイル側で指定した出力先には、何も流れていませんでした。
日付入りのログを開いたら、そこには止まった理由がはっきり書いてありました。
教訓は2つです。
一、ログを読むときは、必ず更新日時を確認する。
古いデータを新しいと思い込む。これは私が同じ調査の中で2回やった失敗です。もう1回は、フィードのブラウザキャッシュを掴んで「11日間止まっている」と誤報しました。実際は1回分でした。
二、まずシェルスクリプトを読んで、どこにログを書いているかを確かめる。
包んでいる層が自分でログを書いている場合、設定ファイルの指定は空振りします。「ログが無い＝動いていない」と判断すると、まるごと間違えます。
はじめに
動画を毎日、自動で書き出して、自動で上げています。人が触るのは止まったときだけ、というつもりで組みました。
ある日、進み方がおかしいことに気づきました。1日1日分進むはずのものが、1日あたり0.4日分しか進んでいないのです。
止まってはいません。エラーも出ていません。ログを見ても異常がありません。それでも進んでいませんでした。
原因は、発火する時刻でした。たった1行の設定です。
この記事は、自動投稿を組んだあとに実際に起きたことの記録です。うまく動かす方法ではなく、静かに壊れる形を先に知っておくための記事です。
書いてあるのは全部、私が踏んだものです。数字はすべて実測値で、日付を書いたものはその時点の値です。
コードは出てきません。「どのライブラリを使うか」の話でもありません。組んだあとに何が起きるかだけを書きました。
第1章 発火時刻を1つ間違えると、毎日0本になる
いちばん高くついた失敗から書きます。
自動実行の発火時刻を、日本時間の14時に設定していました。深夜を避け、朝の混雑も避けた、無難な時刻のつもりでした。
ところが、使っているAPIの利用枠は太平洋時間の深夜0時にリセットします。日本時間に直すと、夏時間なら16時、冬時間なら17時です。
つまり、こういうことが起きていました。
（実行／太平洋時間での換算／結果）
14時00分（自動実行） 前日の22時 前日の枠。使い切り済み → 0本
18時11分（手で叩いた） 当日の2時11分 新しい枠 → 22本成功
毎日、昨日の空の枠を叩きに行って、2秒で諦めていました。
手で叩いた日だけ進んでいたので、平均すると1日0.4日分。この数字がずっと不思議でした。
対策は発火時刻を後ろにずらすだけです。ただし、16時30分では足りません。 冬時間になるとリセットが17時になるので、同じ事故が再発します。17時30分なら通年で安全側です。
ここで書いておきたいのは、時刻そのものではありません。
この規則は、すでに自分の手元に書いてありました。
4か月前に別のプロジェクトで同じことを整理して、「16時30分が最適。理由はAPIのリセット直後だから」と記録に残していました。設定ファイルの雛形まで作ってありました。
このプロジェクトだけが、その雛形を使わずに手で書かれていました。
問題は「規則が無かった」ではありません。規則が守られていないことに、誰も気づかなかったことです。
自動実行を新しく仕込むときは、雛形をコピーする。手で書かない。 これだけで防げました。
そして、もう1つ。同じ地雷が、まだ他の2つの自動実行に残っていました。片方は10時30分発火、もう片方は12時発火です。どちらも太平洋時間では前日にあたります。
いまは1日3本しか上げていないので、枠を使い切る前に終わっています。だから顕在化していません。 本数を増やした瞬間に、同じ止まり方をします。
「いまは動いている」は「正しい」ではありません。 負荷が上がった瞬間に露出する誤りが、静かに待っていることがあります。
なぜ4か月も気づかなかったのか、という話も書いておきます。
私は「動いているか」しか見ていませんでした。 自動実行の一覧を叩けば、登録されていることは分かります。エラー通知も来ません。だから動いていると判断していました。
見るべきだったのは、「何本入ったか」です。
これは1行で数えられます。上がった本数を数えて、期待値と比べるだけです。それをしていれば、初日に分かりました。0本だったのですから。
「動いている」と「仕事をしている」は別物です。 自動化の監視は、前者ではなく後者を見ないと意味がありません。
第2章 「ログが無い」は「動いていない」ではない
原因を探すとき、私は最初にログを見ました。そして間違った結論を出して、正しい仮説を一度取り下げました。
見ていたのは、設定ファイルで指定した標準出力と標準エラーのファイルです。開いたら、権限まわりのエラーが4行だけ入っていました。「これが原因か」と思いました。
その4行は、3か月前のものでした。
ファイルの更新日時を見ていませんでした。
なぜ古いままだったか。実行を包んでいるシェルスクリプトが、自分でログファイル名を組み立てて、日付入りの別ファイルに書いていたからです。設定ファイル側で指定した出力先には、何も流れていませんでした。
日付入りのログを開いたら、そこには止まった理由がはっきり書いてありました。
教訓は2つです。
一、ログを読むときは、必ず更新日時を確認する。
古いデータを新しいと思い込む。これは私が同じ調査の中で2回やった失敗です。もう1回は、フィードのブラウザキャッシュを掴んで「11日間止まっている」と誤報しました。実際は1回分でした。
二、まずシェルスクリプトを読んで、どこにログを書いているかを確かめる。
包んでいる層が自分でログを書いている場合、設定ファイルの指定は空振りします。「ログが無い＝動いていない」と判断すると、まるごと間違えます。