Railsのバッチログにだけ何故かタイムスタンプが出なくて困った話

前提

環境は以下

	version
Ruby	3.0.0
Rails	6.1

何が起きたか？

該当のアプリケーションはwebとバッチがありました。
webのログは以下の感じ

[INFO] [2021-05-19 14:51:28 +0900] [7bdeb84a-a422-40b3-9a54-65c3248ec863] ログ内容

バッチのログは以下の感じ。

[INFO] ログ内容

バッチ処理にタイムスタンプが出ていない。

原因

log_tagsの設定が原因。
タイムスタンプが出ていなかった時の設定がこちら。

config/initializers/logger_formatter.rb

class Logger
  class Formatter
    def call(severity, time, progname, msg)
      "[#{severity}] #{msg}\n"
    end
  end
end

config/application.rb

logger = ActiveSupport::Logger.new(STDOUT)
logger.formatter = Logger::Formatter.new
config.log_tags  = [ ->(req){ Time.now }, :request_id ]
config.logger = ActiveSupport::TaggedLogging.new(logger)

formatterの方でseverityとmsgを出し、log_tagsの方でtimeとrequest_idを出す設定になっていました。

log_tagsとは

公式リファレンス

config.log_tags = [:uuid, :remote_ip]

が指定できることは分かったがこれが何故バッチ処理側に適用されないのかが分からなかった。

次にたどり着いたのがこちらのブログ
つまりrequestオブジェクトの要素をログに追加するという仕組み。
ブログ内ではuser_agentを指定している。
バッチ処理に関してはrequestオブジェクトが存在しないためこれらの情報がないのでログに出なかったということ。
確かに言われてみればrequest_idも出ていなかった。

解決策

タイムスタンプを出力するのをlog_tagsではなくfomatterの方で設定する。

config/initializers/logger_formatter.rb

class Logger
  class Formatter
    def call(severity, time, progname, msg)
      "[#{severity}] [#{time}] #{msg}\n"
    end
  end
end

config/application.rb

logger = ActiveSupport::Logger.new(STDOUT)
logger.formatter = Logger::Formatter.new
config.log_tags  = [:request_id]
config.logger = ActiveSupport::TaggedLogging.new(logger)

こうすることでwebもバッチも両方ともタイムスタンプが出るようになった。

webのログ

[INFO] [2021-05-19 15:03:47 +0900] [316ce8f4-d059-4336-a954-270e590e74a2] ログ内容

バッチのログ

[INFO] [2021-05-19 15:05:35 +0900] ログ内容

バッチにはrequestオブジェクトがないのでrequest_idが出てないのは正しい。

まとめ

log_tagsに関してあまり詳しい情報がなく調べるのに苦労しました。
調べた記事を読みつつ
「ふぅん？requestの要素が指定できるのか。
user_agentとか出せるのね、なるほどなるほど。
ん？バッチ処理においてuser_agentとか分かるのか？」
っていう思考で解決策にいきつきました。
同じ問題でハマっている人の助けになればと思います。