【ログ分離】 アプリケーションのリファクタまでが改善です
はじめに
TROCCO のログデータを DB から分離する活動のお話です。
すでにアーキテクチャの刷新については触れたため、以下にある実装面での負債の解消について触れようと思います。
また前回触れなかった Native sidecar containers について今回触れます。
クラス設計
BaseLogger を定義し、ログ保存時にログレベルごとに呼び出し可能なメソッドを定義しました。
ログの保存では K8s の環境では Vector を利用しますが、ローカル環境で Docker Compose を利用する場合は、Vector を利用できないため S3 クライアントで直接アップロードする必要があります。
そのため BaseLogger を基底クラスとして、Vector によるログの転送を前提としてファイルにログを出力するクラスと、S3 クライアントで直接アップロードするクラスの2種類を定義しました。
BaseLogger
add_log でログの保存処理を行うようにしているため、継承先で実装が異なるため実装を強制するようにしています。
def add_log(message)
raise NotImplementedError
end
S3ViaFileLogger
インスタンス変数の log_file
でログを保存するローカルファイルのパスを指定します。
ログを 実行ログ
と エラーログ
で分けたい場合などに動的に値を決めます。
add_log ではファイルへログ追記する処理を実装しました。
def add_log(message)
File.open(@log_file, "ab+") do |f|
f.write(msg)
end
S3DirectLogger
インスタンス変数には、S3 の保存先を決定するための情報である job の値を指定します。
また S3 へ直接ログをアップロードするため client も初期化します。
add_log では S3 クライアントを利用してアップロードします。
def add_log(message)
@s3.put_log(
key: "#{@job_id}-#{Time.current.strftime('%H-%M-%S')}.log",
body: msg,
)
end
ログの表示
ここまでは S3 へのアップロードとダウンロードについてでしたが、ブラウザに表示する箇所についてもリファクタや色々な考慮事項があったので残しておきます。
フロントエンドは React への移行を行なっていることもあり、Rails に比べリファクタ画筆よな箇所は少なかったです。
DB との併用
分離以前に DB に保存したログは依然として DB に保存されています。
S3 へ既存のログを移動する作業は、さすがに効率が悪いため行なっていません。
Rails を利用しているため、model にログを取得するロジックを定義しました。
例えばデータマートジョブであれば model/datamart_job.rb にメソッドを追加します。
model のログを保存してあるカラムに対応するフィールドが nil の場合は S3 から取得するという処理を挟むだけです。
def log
log || S3Client.new.fetch_log(id)
end
非同期でログを転送していることに対する対策
TROCCO のジョブ画面では、実行ログをリアルタイムに表示するために一定間隔でログをポーリングしています。
そしてジョブが正常/異常に関わらず終了した場合にはポーリングを停止します。
一方、ジョブの処理側では、Vector がローカルのログファイルの差分を見て5秒おきに S3 へ内容をアップロードするアーキテクチャになっています。
そのためジョブの終了のタイミングとアップロードのタイミング次第では、ログは保存されているが一部表示されないことが起こりえます。
画面をリロードすることで表示されますが、ジョブの終了後もポーリングを少しの間継続することで、これまで通りリアルタイムな表示を可能にしています。
(基盤の話) Native sidecar contaiers について
リアーキテクチャの方で Vector のプロセスがメインコンテナの終了後に残ってしまうため、CronJob で定期削除していると書きました。
ただその際少し触れた K8s の Native sidecar containers を利用することで、Lifecycle フックとの合わせ技で削除処理をシンプルにできたので紹介します。
Native sidecar の終了プロセス
メインコンテナの終了後に SIGTERM が送られることでメインコンテナの後に終了します。
これにより CronJob の自前での準備から解放されました。
ただ SIGTERM のタイミングは制御することができないです。
したがって TROCCO にそのまま導入すると、Vector が5秒おきのログのアップロードを行う前に Vector のプロセスが終了してしまいログが欠損してしまいます。
Lifecycle Hooks の利用
ログの欠損の回避のために PreStop の利用が考えられます。
ただメインコンテナでは終了ステータスが正常なため PreStop は利用できないため、ジョブの実行後にログの書き込みを待つことを制御できません。
しかし、Native sidecar については SIGTERM により終了されるため、PreStop を設定することが可能となっています。
そのため Vector の PreStop に sleep
を仕込むことでこれを回避できました。
Vector の Graceful shutdown
Lifecycle Hooks を利用して終了タイミングを調整できましたが、sleep
を仕込むことなく Vector の機能でなんとかできないかも探っていました。
Vector も SIGTERM 受信後にデフォルトで60秒の Graceful shutdown を設定することができます。
ただ挙動が安定しないため K8s 側で制御をすることにしました。
Disk buffers should close at shut-down · Issue #19600 · vectordotdev/vector
まとめ
これで無事ログを DB から分離することができました。
アプリケーション側でログの扱いについて考慮しないとならないことが多くありましたが、全体を通してみると DB の運用コストと料金、パフォーマンスの改善をするに至れました。
また細かいところなので触れていませんでしたが、BaseLogger を起点とする各クラスを経由してログを保存するように処理を統一することができました。
ログ保存処理が各所に散らばっていると修正ミスや、フォーマットのずれにつながるため、アプリケーションの保守性の観点でも意義があったと思います。
また Native sidecar が Beta 版になり EKS で利用可能となったことも大きかったです。
ボトルネックとなっていたサイドカーの終了箇所をシンプルにすることができました。
似たようなお悩みを抱えている方は是非お試しください。
We are hiring
TROCCO を開発する primeNumber では、一緒に信頼性向上を実現してくれる SRE を絶賛募集中です!
まずはカジュアル面談でお会いしましょう 🙏
信頼性向上が選ばれる理由になる、裁量の大きいSRE【データ分析基盤総合支援SaaS TROCCO®/地方フルリモート有】
Discussion