Rでログを取る場合どうしていますか？インタラクティブなデータ分析ならprintやcatでもよいのですが、バッチ処理を行うような場合は、print文に現在時刻を含んだり、コンソールだけではなくファイルにも出力したりしたいところです。

Pythonなら標準ライブラリのloggingやサードバーティーのloguruなどがありますが、同じようにRでもloggerを使いたいですね。

便利なロガーパッケージのloggerを紹介します。Pythonのloggingに近いインタフェースをしているので¹、loggingを使ったことがあればすんなり使えるのではないかと思います。

環境

• R 4.3.1
• logger 0.2.2

インストール

インストールはこちらです。

# CRANからインストールする場合
install.packages("logger")

# GitHubからインストールする場合
remotes::install_github("daroczig/logger")

library(logger)

基本的な使い方

コンソールに表示するだけであれば、以下で使うことができます。最初にlogger::log_thresholdでログを出力する閾値を定めます。

logのlevelは高い順にfatal > error > warn > success > info > debug > traceです。（参考）

log_threshold(INFO)

log_info("info")
#> INFO [2023-10-04 02:38:37] info
log_warn("warn")
#> WARN [2023-10-04 02:38:37] warn
# DEBUGはINFOより下のlevelなので表示されない
log_debug("debug")

デフォルトではlogger::log_formatter(logger::formatter_glue)が設定されているため、glue::glueを使わなくてもglueの記法で変数を展開したり関数を評価したりできます。

x <- 1
log_info("x is {x}")
#> INFO [2023-10-04 02:38:37] x is 1
log_info("x + 1 is {x + 1}")
#> INFO [2023-10-04 02:38:37] x + 1 is 2

ログの出力先は、logger::log_appenderの引数appenderで設定することができます。デフォルトではlogger::log_appender(appender=logger::appender_console)が設定されていますので、デフォルト設定のままコンソールに出力するだけであればlogger::log_appenderは不要です。

logger::log_appenderの引数appenderにappender_で始まる関数を渡すことで、出力先を変えることができます。

以下のようにすれば、コンソールとファイルに同時に出力することもできます²。

file_path <- tempfile()
log_appender(appender_console)
log_appender(appender_file(file=file_path))

log_threshold(INFO)

log_info("info")

appender_で始まる出力先を設定する関数は他にも色々ありますが、logger::appender_slackで出力先をSlackにすることができるのが嬉しいポイントですね。内部ではslackr::slackr_msgを呼んでいるようです。バッチ処理が正常に終了したとき、あるいはエラーが出たときだけSlackに通知したいということがよくあります。

出力先ごとに出し分ける

loggerパッケージにはnamespaceとindexという概念があります。前者はloggerの名前空間（logger::log_appenderのデフォルト値は"global"）、後者は同一のnamespaceの中でのloggerのindexです（デフォルト値は1）。

namespaceは関数内でのログをメイン処理から分けるような場合などに使います。indexを活用すると、以下のようにコンソールとファイルで別々のlog levelの閾値を設定するようなこともできます。

file_path <- tempfile()
log_appender(appender_console, namespace="global", index=1)
log_appender(appender_file(file=file_path), namespace="global", index=2)

# コンソールにはINFO以上、ファイルにはDEBUG以上でログを出力する
log_threshold(INFO, namespace="global", index=1)
log_threshold(DEBUG, namespace="global", index=2)

log_info("info")
log_debug("debug")
log_trace("trace")

readLines(file_path)
#> [1] "INFO [2023-10-04 02:38:37] info"   "DEBUG [2023-10-04 02:38:37] debug"

なお、同一のnamespaceとindexにlogger::appender_consoleのコンソール出力とlogger::appender_fileのファイル出力を行う場合は、logger::appender_teeというエイリアスが使えます。

log_appender(appender_tee(file=file_path), namespace="global", index=1)

ログフォーマットをカスタマイズする

logのlayoutをlogger::log_layoutの引数layoutに指定すればOKです。

例えば、logger::layout_jsonでjsonの形式にできます。

file_path <- tempfile()
log_appender(appender_console)
log_threshold(INFO)

log_layout(layout_json())
log_info("info")

フォーマットをカスタマイズすることもできます。logger::layout_glue_generatorでは、glueの記法でカスタマイズすることができます。ログレベル（level）や時刻（time）、メッセージ（msg）などいくつかの変数が組み込まれています。変数の一覧はこちらにあります。

file_path <- tempfile()
log_appender(appender_file(file=file_path))
log_threshold(INFO)

my_layout <- layout_glue_generator(
  format="{level} | {format(time, '%Y-%m-%dT%H:%M:%S+09:00')} | {msg}"
)
log_layout(my_layout)

log_info("info")

readLines(file_path)
#> [1] "INFO | 2023-10-04T02:38:37+09:00 | info"

おわりに

これくらいを抑えておけばひとまず使えるかと思います。vignetteが充実しているので詳細はvignetteをご覧ください。

Reference

• GitHub - daroczig/logger
• vignette