深夜零時にログが止まり、再起動したらまた流れ出した

目標

ファイルを続きから読むコレクターを自分で作り、追記・ローテーション・切り詰めを順に起こしながら、1行も失わず、重複もしないことを番号で確認します。

なぜ重要なのか

コレクターの最初の仕事は、「どこまで読んだか」を記憶することです。ところがバイト位置1つだけを記憶していると、深夜0時のログローテーションで静かに止まります。新しいファイルは小さいのに、記憶している位置のほうが大きいためです。エラーもアラートもないまま数時間が空き、再起動すると再び流れ始めるため、原因も残りません。ローテーションはinodeが変わることで、切り詰めはサイズが読んだ位置より小さくなることで気づきます。両方を見る必要があるのは、ローテーションの方式が2種類あるためです。位置の記録が失われたときの方針も、あらかじめ決めておく必要があります。重複と欠落のどちらを受け入れるかは、タダでは決まりません。

ステップ

/root/lp-tailでpython3 /opt/lab/d5/applog.py logfmt /root/lp-tail/app.log 200 "$(date +%s)" 1を実行し、seq 1から200までのログを作成してください。そしてapp.logを続きから読んで/root/lp-tail/collected.logに追記し、読んだ位置を/root/lp-tail/pos.txtに残すコレクターを作り、1回実行してください。pos.txtにはinode=<정수>とoffset=<정수>の2行が入ります(プレースホルダーは整数です)。
python3 /opt/lab/d5/applog.py logfmt /root/lp-tail/app.log 100 "$(date +%s)" 201でseq 201から300までを追記し、コレクターをもう一度実行してください。収集が終わるとcollected.logの行数が300になっている必要があり、同じseqが2回含まれていてはいけません。
mv /root/lp-tail/app.log /root/lp-tail/app.log.1でローテーションを起こし、python3 /opt/lab/d5/applog.py logfmt /root/lp-tail/app.log 100 "$(date +%s)" 301で新しいファイルにseq 301から400までを書いてください。そしてコレクターを実行し、collected.logが400行になるようにしてください。
copytruncate方式を再現してください。cp /root/lp-tail/app.log /root/lp-tail/app.log.2でコピーし、: > /root/lp-tail/app.logで元のファイルを0に切り詰めたあと、コレクターを1回実行します。そしてpython3 /opt/lab/d5/applog.py logfmt /root/lp-tail/app.log 100 "$(date +%s)" 401でseq 401から500までを書き、コレクターをもう一度実行して、その区間が1つも欠けることなく入ってくるようにしてください。
今のpos.txtのinodeが実際のapp.logのinodeと同じで、offsetがファイルサイズと同じかどうかを確認してください。そして/root/lp-tail/05-pos.txtに3行書きます: pos_inode=<정수>、file_inode=<정수>、offset_equals_size=<yes|no>(プレースホルダーは整数です)。
現在のディレクトリを/root/lp-tail-noposにまるごとコピーし、そこでpos.txtを削除してからコレクターを1回実行してください。そして/root/lp-tail/06-nopos.txtに3行書きます: before=<복사 시점의 collected.log 줄 수>、after=<다시 돌린 뒤 줄 수>、duplicated=<두 값의 차>(プレースホルダーは順に、コピー時点のcollected.logの行数、再実行後の行数、2つの値の差です)。元のディレクトリには手を触れないでください。
元のファイル全体(app.logとローテーションされたファイル)に含まれるseqの集合と、collected.logのseqの集合を比較して、/root/lp-tail/tally.txtに4行書いてください: source=<원본 줄 수>、collected=<수집본 줄 수>、missing=<원본에만 있는 seq 수>、duplicated=<수집본에서 두 번 이상 나온 seq 수>(プレースホルダーは順に、元の行数、収集した行数、元にだけあるseqの数、収集結果で2回以上現れたseqの数です)。
/root/lp-tail/chaos.shを作り、次を順に行うようにしてください: (1)ローテーション(app.logをapp.log.3に移し、新しいファイルにseq 501から550まで)、(2)収集、(3)コピーしてから切り詰め(cp app.log app.log.4のあとに: > app.log)と、その直後の収集、(4)seq 551から600までを書いて再び収集。スクリプトを実行したあと、seq 1から600までがcollected.logに欠けることなく1回ずつ含まれている必要があります。結果を/root/lp-tail/08-chaos.txtに、collected=<정수>、missing=0、duplicated=0の3行で書いてください(プレースホルダーは整数です)。

参考

作業ディレクトリは/root/lp-tailです。このラボは送信先を扱いません。読む側だけを扱います。
ログを作る「アプリケーション」は/opt/lab/d5/applog.pyです。各行にseq=の番号が入っているので、あとで欠落と重複を正確に数えられます。採点ツールはこのファイルを読みません。
コレクターはどの言語で書いても構いません。採点ツールはcollected.logとpos.txtの内容だけを見ます。
stat -c %i <파일>がinodeを、wc -c < <파일>がサイズを教えてくれます(プレースホルダーはファイル名です)。
よくある間違い: 毎回ファイルをまるごと読み直してしまいます。ステップ2で行数が2倍になって表面化します。
よくある間違い: 位置を更新する前に落ちてしまいます。このラボでは扱いませんが、実際のコレクターは送信したあとに位置を書き込み、少なくとも1回の配信を保証します。
このラボの限界: 切り詰めたあとに新しい行がたまり、サイズが古い位置とちょうど同じになると、サイズの比較では切り詰めを見抜けません。そのためコレクターは頻繁に動く必要があり、実際のコレクターはファイル先頭部分の内容も一緒に記憶して、このケースまで見分けます。ここでは、切り詰めた直後に1回動くことでその隙間を避けます。
Fluent Bit: tail入力・Fluentd: 設定ファイル・Kubernetes: クラスターのロギング構造・Vector: コンセプト

アプリのログを作り、最初に1回収集する

/root/lp-tailでpython3 /opt/lab/d5/applog.py logfmt /root/lp-tail/app.log 200 "$(date +%s)" 1を実行し、seq 1から200までのログを作成してください。そしてapp.logを続きから読んで/root/lp-tail/collected.logに追記し、読んだ位置を/root/lp-tail/pos.txtに残すコレクターを作り、1回実行してください。pos.txtにはinode=<정수>とoffset=<정수>の2行が入ります(プレースホルダーは整数です)。

言語は自由です。核心は2つを記憶することです。どのファイルだったか(inode)と、どこまで読んだか(offset)です。stat -c %iでinodeを、wc -cでサイズを確認できます。コレクターは何度実行しても、同じ行を2回書いてはいけません。

追記された行だけを続きから読む

python3 /opt/lab/d5/applog.py logfmt /root/lp-tail/app.log 100 "$(date +%s)" 201でseq 201から300までを追記し、コレクターをもう一度実行してください。収集が終わるとcollected.logの行数が300になっている必要があり、同じseqが2回含まれていてはいけません。

ここでまるごと読み直すコレクターは、600行を作ってしまいます。offsetを正しく使えているか、pos.txtとwc -c app.logを比べてみてください。2つの値が同じになっているはずです。

ローテーション: 同じ名前の別のファイル

mv /root/lp-tail/app.log /root/lp-tail/app.log.1でローテーションを起こし、python3 /opt/lab/d5/applog.py logfmt /root/lp-tail/app.log 100 "$(date +%s)" 301で新しいファイルにseq 301から400までを書いてください。そしてコレクターを実行し、collected.logが400行になるようにしてください。

位置だけを記憶するコレクターは、新しいファイルで読むものを見つけられません。同じ名前だが別のファイルになったことに気づく必要があります。statが教えてくれる値1つで判別できます。気づいたら、新しいファイルを最初から読みます。

切り詰め: inodeはそのままなのに小さくなった

copytruncate方式を再現してください。cp /root/lp-tail/app.log /root/lp-tail/app.log.2でコピーし、: > /root/lp-tail/app.logで元のファイルを0に切り詰めたあと、コレクターを1回実行します。そしてpython3 /opt/lab/d5/applog.py logfmt /root/lp-tail/app.log 100 "$(date +%s)" 401でseq 401から500までを書き、コレクターをもう一度実行して、その区間が1つも欠けることなく入ってくるようにしてください。

今回はinodeがそのままです。inodeだけを見るコレクターは何の変化も感じ取れず、古い位置から読もうとします。ファイルサイズが記憶している位置より小さくなったことが唯一の手がかりです。切り詰めた直後に1回実行する理由があります。コレクターは定期的に動くので、新しい行がたまってサイズが古い位置を再び超えてしまうと、その手がかりさえなくなります。

記憶に何が入っているべきか

今のpos.txtのinodeが実際のapp.logのinodeと同じで、offsetがファイルサイズと同じかどうかを確認してください。そして/root/lp-tail/05-pos.txtに3行書きます: pos_inode=<정수>、file_inode=<정수>、offset_equals_size=<yes|no>(プレースホルダーは整数です)。

stat -c %i app.logとwc -c < app.logを使えば確認できます。2つの値がずれている場合は、コレクターが位置を正しく更新していないということで、次のローテーションで行を失うことになります。

位置の記録が失われると何が起きるか

現在のディレクトリを/root/lp-tail-noposにまるごとコピーし、そこでpos.txtを削除してからコレクターを1回実行してください。そして/root/lp-tail/06-nopos.txtに3行書きます: before=<복사 시점의 collected.log 줄 수>、after=<다시 돌린 뒤 줄 수>、duplicated=<두 값의 차>(プレースホルダーは順に、コピー時点のcollected.logの行数、再実行後の行数、2つの値の差です)。元のディレクトリには手を触れないでください。

cp -a . /root/lp-tail-noposでコピーします。位置の記録がないと、コレクターは「最初から」と「末尾から」のどちらかを選ばなければならず、サンプルのコレクターは最初から読みます。そのため、すでに送った行が再び入ってきます。その数を数えるのがこのステップです。

応用①: 番号で欠落と重複を数える

元のファイル全体(app.logとローテーションされたファイル)に含まれるseqの集合と、collected.logのseqの集合を比較して、/root/lp-tail/tally.txtに4行書いてください: source=<원본 줄 수>、collected=<수집본 줄 수>、missing=<원본에만 있는 seq 수>、duplicated=<수집본에서 두 번 이상 나온 seq 수>(プレースホルダーは順に、元の行数、収集した行数、元にだけあるseqの数、収集結果で2回以上現れたseqの数です)。

seqは各行にseq=00123の形で入っています。grep -o 'seq=[0-9]*'で取り出し、sortとuniqで数えます。欠落と重複がどちらも0であって初めて、コレクターを信頼できます。

応用②: ローテーションと切り詰めが混ざっても1行も失わない

/root/lp-tail/chaos.shを作り、次を順に行うようにしてください: (1)ローテーション(app.logをapp.log.3に移し、新しいファイルにseq 501から550まで)、(2)収集、(3)コピーしてから切り詰め(cp app.log app.log.4のあとに: > app.log)と、その直後の収集、(4)seq 551から600までを書いて再び収集。スクリプトを実行したあと、seq 1から600までがcollected.logに欠けることなく1回ずつ含まれている必要があります。結果を/root/lp-tail/08-chaos.txtに、collected=<정수>、missing=0、duplicated=0の3行で書いてください(プレースホルダーは整数です)。

前のステップで行ったことをスクリプトにまとめます。ローテーションと切り詰めの間に、必ず収集を1回入れてください。ローテーションされたファイルの末尾を読めるチャンスはそのときだけだからです。本物のコレクターがファイルディスクリプターをしばらく保持する理由も同じです。