monolog(RotatingFileHandler)のログ出力エラーに対してプルリク作成してみた
概要
- Lumenを使ったAPIサーバで日別にログ出力している（日付ごとにディレクトリを分けてログ出力している）
- 数年間のシステム運用をしている中で、特に問題なくログ出力できていた
- ある日、ログ出力できないというエラーが発生したので、調査内容をまとめる
エラーについて
- 「Could not be opened: failed to open stream: No such file or directory in」というエラーが発生する
- エラーメッセージで調べると、ログ出力周りの権限が不正とかばかりで、数年間運用している自分の環境とは要因が別と判断
- 日付が変わった直後のタイミングでエラーが発生する傾向がある
結論
- 日付が変わったときに、新しい日付のディレクトリが存在しなくエラーとなっている。
エラーが発生するケース
原因（コード）
- RotatingFileHandler の write関数内では、出力するログの日時を条件にローテートが必要か判定している。必要な場合には、現在開いているファイルをクローズしてから改めてログ出力処理をするような流れとなっている。このときにクローズするファイルというのは、LumenではHTTPリクエストを受けて対象のControllerを生成し、初めてログ出力するときにファイルが開かれ、HTTPレスポンスが返されるまでは、開いたファイルを利用している。この辺は、〜Handler（今回はRotatingFileHandler）のインスタンスを保持していることで制御している。
- RotatingFileHandler の write関数では、親クラスであるStreamHandler の wriite関数が呼ばれる。StreamHandler の write関数では、初回ログ出力時であれば出力先のディレクトリやファイルを生成し、既にファイルが開かれていれば、そのままファイルにログ出力するという流れになっている。初回ログ出力時にディレクトリを作成するのは、同一クラス内のcreateDir というprivate関数が呼ばれて処理される。createDir関数では、最初に、dirCreatedというクラス変数を条件に既に作成済み（true）であればすぐにreturnするような分岐となっている。このdirCreatedというクラス変数は、privateで宣言されており、trueが入るタイミング（値が変更されるタイミング）は、createDir関数の一番最後のみ。
原因（説明）
- 日付が変わる前にログ出力したときは、RotatingFileHandlerを保持して再利用する仕組みとなっている。（都度、ファイルを開いて書き込んで閉じるだと、パフォーマンスに悪いため、このような実装になっていると思われる）
- ログに書き込むタイミングで、ログ出力時間を見て、ローテートするべきかどうかの判定処理は正常に動いている（RotatingFileHandler#write）
- StreamHandlerのcreateDir関数では、一度ディレクトリが作成されると、dirCreatedというフラグがtrueに変わるため、RotatingFileHandlerを再利用している間は新しいディレクトリが作成できない処理になっている
- RotatingFileHandler#writeでローテートが必要と判断したら、dirCreatedというフラグも下げて、新しい日付のディレクトリを作成できるようにする必要がある
プルリクエスト
- StreamHandler の close関数でdirCreatedのフラグを下げるプルリクを作成してみた。レスなどの反応があると嬉しい。対応としては、dirCreatedをprotectedにして、RotatingFileHandlerから変更するのと迷ったけど、まずは様子見してみたいと思う。
- 英語での説明がかなり自信がないけど、、、
