結論
config.log_tags = [:request_id]
しといて、 (Rails5ではデフォルトで設定されている。 Rails4以前は :uuid )
ActiveSupport::TaggedLogging.new(Logger.new('log/my_great_module.log'))
を好きなだけ書く。
状況
そもそもログファイル複数ってどうなのよ一本化しろよ fluentd とかしろよ、という正論はさておき、世の中にはどうしても立ち向かわねばならない状況というものがあります。
大きなシステムのあちこちのモジュールで個別にログファイル出力してるんだけど、アクセスが集中するとタイムスタンプだけで対応を読むのは限界があり、なんかリクエスト毎に固有キーかなんかで grep 出来たらいいのになと
そこで X-Request-ID
X-Request-ID ヘッダというのは、個々のリクエストに固有のユニークな文字列で、 nginx や apache が付けてくれたり、誰も付けなければ rails が付けたりします。誰が付与するかはこの際どうでもよくて、 rails の action が動く時点では既に付与されており、 request.uuid で取得することができます。
なので、すべてのログ出力に request.uuid をセットで吐き出すようにすれば、複数のログファイルを跨いで「このリクエストに関連する全てのログを横断的に見たい」というようなことが grep で簡単に実現できるわけです。
すべてのログ出力に request.uuid をセットで吐き出すようにすれば。。。
なんかうまいことこれをやる方法はないだろうか、というわけで検索すると
config.log_tags = [:uuid]
これだーー！これこそ私の求めていたものださすが rails 様、我々愚民の望みなど全てお見通しなのだッッッと一瞬歓喜するわけですがいやちょっと待て。
私の rails プロジェクトではあちこちで Logger.new('my_great_module.log') みたいなことをしているのだが、 log_tags を設定するだけでこれら全てで uuid が吐き出されるようになるなんていう不思議な事はもちろん起きそうになく、実際起きない。
ところでこの log_tags ってのはどういう仕組なのだろう？と探していくと rack の塔をいくつか登って以下のコードにたどり着きます。
Rails.logger が tagged メソッドを持っていればそれを呼んでくれる、とな。
この tagged というメソッドで検索をかけると ActiveSupport::TaggedLogging が見つかりまして、とりあえず、デフォルトの Rails.logger は tagged に対応している、ということと、自前で
Logger を初期化するときには
ActiveSupport::TaggedLogging.new(Logger.new("log/#{Rails.env}.log"))
といようにデコレートすれば良いということがわかります。
とりあえずこれで、 Rails.logger を使う限りは RequestId が自動的に付与される仕組みがわかったわけですが、じゃあこの Rails.logger.tagged を拡張して、自前の Logger インスタンス全部の tagged をコールしてくれるように改造すれば、と考え始めた所でふとあることに気づく。
こいつ、スレッドローカル変数を使っている。。。？
そうなのです。あるスレッド内のどれか1つの ActiveSupport::TaggedLogging インスタンスがタグ付けされれば、同じスレッドの全てのインスタンスは自動的にタグ付けされる仕組みになっていたのでした。
(railsはnode.jsのようなイベントドリブンモデルではないので、あるスレッドがリクエストを受け取ったら、レスポンスを返すまで他のリクエストの処理に関わることはない)
で、リクエスト毎に前述の Rack::Logger が Rails.logger に対してタグ付けを自動的にしてくれるので、Rails.logger だけは忘れずに TaggedLogging でデコレートしておき、あとは好きな場所で好きなだけ Logger インスタンスを作り、uuid つけたいログには TaggedLogging でデコレートしてやれば、その全てに自動的に RequestId を付与することが出来る、というわけでした。
さすが rails 様。
おまけ
RequestId長すぎ。6文字もあればいいでしょ。
config.log_tags = [->(req){req.uuid.first(6)}]