Atusy's blogエラーログはエラーでユーザーに影響が発生した時に、何が起きたか記録する重要な情報源です。特にどこで問題が起きたか特定を容易にするトレースバックはログに欠かせません。ログをとらなくてもエラーは表示されるよと思いの方も、ログを使うとエラーの発生時刻は関連情報を同時に記録できるので、覚えていて損はないです。
ちなみにインタラクティブな用途であれば、options(error = traceback)を設定しておけば、簡単にトレースバックを取得できますが、tryCatchすると挙動が変わったりするのでイマイチ頼りづらいです。ということで、どうやってエラーハンドリングすればいいか考えてみたいと思います。
options(error = traceback) # ここでログを出す実装すればよさそうに見える
f <- function() {
g()
}
g <- function() {
stop("ERROR")
}
# 素の呼び出しはトレースバック出る
f()
#> Error in g() : ERROR
#> 3: stop("ERROR") at #2
#> 2: g() at #2
#> 1: f()
# tryCatchするとトレースバックがでない
tryCatch(f(), error = function(e) {})
#> NULLPythonであればtry-exceptを使って簡単に実現できます。
import sys
import structlog
logger = structlog.get_logger(__name__) # logging.getLogger(__name__) でもOK
try:
raise Exception("ERROR")
except Exception:
logger.error("Error occured", exc_info=True)
#> 2025-03-19 20:30:31 [error ] Error occured
#> Traceback (most recent call last):
#> File "<省略>/demo.py", line 8, in <module>
#> raise Exception("ERROR")
#> Exception: ERROR一方Rで同じようにしてもterashimさんの解説の通り、まともなトレースバックは得られません。
tryCatch() の条件ハンドラで traceback(1) を実行しても、元のコールスタックを抜け出しているので有益な情報は得られません。
（Rの条件ハンドリングを理解する）
tryCatch(
{
stop("ERROR")
},
error = function(e) {
tb <- capture.output(traceback(6))
print(head(tb, 15))
}
)
#> [1] "40: tryCatchList(expr, classes, parentenv, handlers)"
#> [2] "39: tryCatch({"
#> [3] " stop(\"ERROR\")"
#> [4] " }, error = function(e) {"
#> [5] " tb <- capture.output(traceback(6))"
#> [6] " print(head(tb, 15))"
#> [7] " })"
#> [8] "38: eval(expr, envir)"
#> [9] "37: eval(expr, envir)"
#> [10] "36: withVisible(eval(expr, envir))"
#> [11] "35: withCallingHandlers(code, message = function (cnd) "
#> [12] " {"
#> [13] " watcher$capture_plot_and_output()"
#> [14] " if (on_message$capture) {"
#> [15] " watcher$push(cnd)"しかたないので、同じくterashimさんが解説していらっしゃる通り、withCallingHandlersを使う必要があります。しれっとJSONによる構造化ログを使ってますが、なんだそれという方はぜひ私のJapan.R 2024の発表資料をご覧ください（Happy Structured Logging in R）。
withCallingHandlers(
{
stop("ERROR")
},
error = function(e) {
tb <- capture.output(traceback(6))
logger::log_info(
"Error occured",
traceback = paste(
head(tb, 15),
collapse = "\n"
)
)
}
)
#> {"time":"2025-03-19 15:37:10","level":"INFO","1":"Error occured","traceback":"40: stop(\"ERROR\")\n39: withCallingHandlers({\n stop(\"ERROR\")\n }, error = function(e) {\n tb <- capture.output(traceback(6))\n logger::log_info(\"Error occured\", traceback = paste(head(tb, \n 15), collapse = \"\\n\"))\n })\n38: eval(expr, envir)\n37: eval(expr, envir)\n36: withVisible(eval(expr, envir))\n35: withCallingHandlers(code, message = function (cnd) \n {\n watcher$capture_plot_and_output()\n if (on_message$capture) {"}
#> Error in withCallingHandlers({: ERRORエラーの発生はwithCallingHandlersの処理完了後なので、エラーの後処理をしたい場合は更にtryCatchで囲ってください。たとえば、複数のパラメータを処理する場合に、特定のパラメータでのエラーを記録するケースが考えられます。この場合、他のパラメータは引き続き試せるので、エラーを無視する処理を入れることがあります。
for (param in c("foo", "bar", "buzz")) {
logger::log_info(message = "Start processing", param = param)
tryCatch(
{
withCallingHandlers(
{
if (param == "bar") {
stop("ERROR")
}
},
error = function(e) {
# パラメータの処理失敗はユーザー影響があるのでエラーログ
tb <- capture.output(traceback(6))
logger::log_error(
message = e$message,
traceback = paste(
tb,
collapse = "\n"
),
param = param
)
}
)
},
error = function(e) {} # tryCatchでエラーを無視する
)
logger::log_info(message = "End processing", param = param)
}
#> {"time":"2025-03-19 15:37:10","level":"INFO","message":"Start processing","param":"foo"}
#> {"time":"2025-03-19 15:37:10","level":"INFO","message":"End processing","param":"foo"}
#> {"time":"2025-03-19 15:37:10","level":"INFO","message":"Start processing","param":"bar"}
#> {"time":"2025-03-19 15:37:10","level":"ERROR","message":"ERROR","traceback":"44: stop(\"ERROR\")\n43: withCallingHandlers({\n if (param == \"bar\") {\n stop(\"ERROR\")\n }\n }, error = function(e) {\n tb <- capture.output(traceback(6))\n logger::log_error(message = e$message, traceback = paste(tb, \n collapse = \"\\n\"), param = param)\n })\n42: doTryCatch(return(expr), name, parentenv, handler)\n41: tryCatchOne(expr, names, parentenv, handlers[[1L]])\n40: tryCatchList(expr, classes, parentenv, handlers)\n39: tryCatch({\n withCallingHandlers({\n if (param == \"bar\") {\n stop(\"ERROR\")\n }\n }, error = function(e) {\n tb <- capture.output(traceback(6))\n logger::log_error(message = e$message, traceback = paste(tb, \n collapse = \"\\n\"), param = param)\n })\n }, error = function(e) {\n })\n38: eval(expr, envir)\n37: eval(expr, envir)\n36: withVisible(eval(expr, envir))\n35: withCallingHandlers(code, message = function (cnd) \n {\n watcher$capture_plot_and_output()\n if (on_message$capture) {\n watcher$push(cnd)\n }\n if (on_message$silence) {\n invokeRestart(\"muffleMessage\")\n }\n }, warning = function (cnd) \n {\n if (getOption(\"warn\") >= 2 || getOption(\"warn\") < 0) {\n return()\n }\n watcher$capture_plot_and_output()\n if (on_warning$capture) {\n cnd <- sanitize_call(cnd)\n watcher$push(cnd)\n }\n if (on_warning$silence) {\n invokeRestart(\"muffleWarning\")\n }\n }, error = function (cnd) \n {\n watcher$capture_plot_and_output()\n cnd <- sanitize_call(cnd)\n watcher$push(cnd)\n switch(on_error, continue = invokeRestart(\"eval_continue\"), \n stop = invokeRestart(\"eval_stop\"), error = invokeRestart(\"eval_error\", \n cnd))\n })\n34: eval(call)\n33: eval(call)\n32: with_handlers({\n for (expr in tle$exprs) {\n ev <- withVisible(eval(expr, envir))\n watcher$capture_plot_and_output()\n watcher$print_value(ev$value, ev$visible, envir)\n }\n TRUE\n }, handlers)\n31: doWithOneRestart(return(expr), restart)\n30: withOneRestart(expr, restarts[[1L]])\n29: withRestartList(expr, restarts[-nr])\n28: doWithOneRestart(return(expr), restart)\n27: withOneRestart(withRestartList(expr, restarts[-nr]), restarts[[nr]])\n26: withRestartList(expr, restarts[-nr])\n25: doWithOneRestart(return(expr), restart)\n24: withOneRestart(withRestartList(expr, restarts[-nr]), restarts[[nr]])\n23: withRestartList(expr, restarts)\n22: withRestarts(with_handlers({\n for (expr in tle$exprs) {\n ev <- withVisible(eval(expr, envir))\n watcher$capture_plot_and_output()\n watcher$print_value(ev$value, ev$visible, envir)\n }\n TRUE\n }, handlers), eval_continue = function() TRUE, eval_stop = function() FALSE, \n eval_error = function(cnd) {\n signalCondition(cnd)\n stop(cnd)\n })\n21: evaluate::evaluate(...)\n20: evaluate(code, envir = env, new_device = FALSE, keep_warning = if (is.numeric(options$warning)) TRUE else options$warning, \n keep_message = if (is.numeric(options$message)) TRUE else options$message, \n stop_on_error = if (is.numeric(options$error)) options$error else {\n if (options$error && options$include) \n 0L\n else 2L\n }, output_handler = knit_handlers(options$render, options))\n19: in_dir(input_dir(), expr)\n18: in_input_dir(evaluate(code, envir = env, new_device = FALSE, \n keep_warning = if (is.numeric(options$warning)) TRUE else options$warning, \n keep_message = if (is.numeric(options$message)) TRUE else options$message, \n stop_on_error = if (is.numeric(options$error)) options$error else {\n if (options$error && options$include) \n 0L\n else 2L\n }, output_handler = knit_handlers(options$render, options)))\n17: eng_r(options)\n16: block_exec(params)\n15: call_block(x)\n14: process_group(group)\n13: withCallingHandlers(if (tangle) process_tangle(group) else process_group(group), \n error = function(e) if (xfun::pkg_available(\"rlang\", \"1.0.0\")) rlang::entrace(e))\n12: xfun:::handle_error(withCallingHandlers(if (tangle) process_tangle(group) else process_group(group), \n error = function(e) if (xfun::pkg_available(\"rlang\", \"1.0.0\")) rlang::entrace(e)), \n function(loc) {\n setwd(wd)\n write_utf8(res, output %n% stdout())\n paste0(\"\\nQuitting from lines \", loc)\n }, if (labels[i] != \"\") sprintf(\" [%s]\", labels[i]), get_loc)\n11: process_file(text, output)\n10: knitr::knit(knit_input, knit_output, envir = envir, quiet = quiet)\n9: rmarkdown::render(input, \"blogdown::html_page\", output_file = output, \n envir = globalenv(), quiet = quiet, run_pandoc = !to_md, \n clean = !to_md)\n8: (function (input, output, to_md = file_ext(output) != \"html\", \n quiet = TRUE) \n {\n options(htmltools.dir.version = FALSE, rmarkdown.knit.ext = \"md~\")\n setwd(dirname(input))\n input = basename(input)\n if (to_md) \n options(bookdown.output.markdown = TRUE)\n res = rmarkdown::render(input, \"blogdown::html_page\", output_file = output, \n envir = globalenv(), quiet = quiet, run_pandoc = !to_md, \n clean = !to_md)\n x = read_utf8(res)\n if (to_md) \n x = process_markdown(res, x)\n unlink(res)\n x\n })(\"content/post/2025/2025-03-19-log-error-on-R/index.Rmd\", \"index.html~\", \n FALSE, TRUE)\n7: do.call(f, x[[2]], envir = globalenv())\n6: eval(quote({\n if (length(a <- commandArgs(TRUE)) != 3) stop(\"The number of arguments passed to Rscript should be 3.\")\n on.exit(if (!file.exists(a[2])) saveRDS(geterrmessage(), \n a[3]))\n x = readRDS(a[1])\n f = x[[1]]\n if (is.character(f)) f = eval(parse(text = f), envir = globalenv())\n r = do.call(f, x[[2]], envir = globalenv())\n saveRDS(r, a[2])\n }), new.env())\n5: eval(quote({\n if (length(a <- commandArgs(TRUE)) != 3) stop(\"The number of arguments passed to Rscript should be 3.\")\n on.exit(if (!file.exists(a[2])) saveRDS(geterrmessage(), \n a[3]))\n x = readRDS(a[1])\n f = x[[1]]\n if (is.character(f)) f = eval(parse(text = f), envir = globalenv())\n r = do.call(f, x[[2]], envir = globalenv())\n saveRDS(r, a[2])\n }), new.env())\n4: eval(expr, p)\n3: eval(expr, p)\n2: eval.parent(substitute(eval(quote(expr), envir)))\n1: local({\n if (length(a <- commandArgs(TRUE)) != 3) \n stop(\"The number of arguments passed to Rscript should be 3.\")\n on.exit(if (!file.exists(a[2])) saveRDS(geterrmessage(), \n a[3]))\n x = readRDS(a[1])\n f = x[[1]]\n if (is.character(f)) \n f = eval(parse(text = f), envir = globalenv())\n r = do.call(f, x[[2]], envir = globalenv())\n saveRDS(r, a[2])\n })","param":"bar"}
#> {"time":"2025-03-19 15:37:10","level":"INFO","message":"End processing","param":"bar"}
#> {"time":"2025-03-19 15:37:10","level":"INFO","message":"Start processing","param":"buzz"}
#> {"time":"2025-03-19 15:37:10","level":"INFO","message":"End processing","param":"buzz"}また、プログラム内でエラーハンドリングが抜けていたケースを検知するには、処理全体をtryCatchとwithCallingHandlersで囲んでおけばよさそうです。
withCallingHandlersでエラーを記録し、tryCatchでエラー発生時にプログラムを強制終了させます。
tryCatchしなかった場合、ログに記録済みのエラーが表示されて冗長になるので、q()しておきましょう。
# ログの設定
logger::log_appender(logger::appender_stdout)
logger::log_formatter(logger::formatter_json)
logger::log_layout(
logger::layout_json_parser(fields = c("time", "level")),
)
# メイン処理の定義
main <- function() {
# なにか処理
stop("UNIMPLEMENTED")
}
# メイン処理の実行
tryCatch(
{
withCallingHandlers(
{
main()
},
error = function(e) {
# エラー処理
# `main`のエラーは致命的なので、ERRORレベルではなくFATALレベルにしておく
# 更に外側のtryCatchでプログラムを終了する
traceback <- paste(capture.output(traceback(6)), collapse = "\n")
logger::log_fatal(
message = "Unhandled error occurred",
error = e$message,
traceback = traceback
)
}
)
},
error = function(e) {
# 終了処理
q(save = "no", status = 1)
}
)
#> {"time":"2025-03-19 15:37:10","level":"FATAL","message":"Unhandled error occurred","error":"UNIMPLEMENTED","traceback":"46: .handleSimpleError(function (e) \n {\n traceback <- paste(capture.output(traceback(6)), collapse = \"\\n\")\n logger::log_fatal(message = \"Unhandled error occurred\", error = e$message, \n traceback = traceback)\n }, \"UNIMPLEMENTED\", base::quote(main()))\n45: stop(\"UNIMPLEMENTED\")\n44: main()\n43: withCallingHandlers({\n main()\n }, error = function(e) {\n traceback <- paste(capture.output(traceback(6)), collapse = \"\\n\")\n logger::log_fatal(message = \"Unhandled error occurred\", error = e$message, \n traceback = traceback)\n })\n42: doTryCatch(return(expr), name, parentenv, handler)\n41: tryCatchOne(expr, names, parentenv, handlers[[1L]])\n40: tryCatchList(expr, classes, parentenv, handlers)\n39: tryCatch({\n withCallingHandlers({\n main()\n }, error = function(e) {\n traceback <- paste(capture.output(traceback(6)), collapse = \"\\n\")\n logger::log_fatal(message = \"Unhandled error occurred\", \n error = e$message, traceback = traceback)\n })\n }, error = function(e) {\n q(save = \"no\", status = 1)\n })\n38: eval(expr, envir)\n37: eval(expr, envir)\n36: withVisible(eval(expr, envir))\n35: withCallingHandlers(code, message = function (cnd) \n {\n watcher$capture_plot_and_output()\n if (on_message$capture) {\n watcher$push(cnd)\n }\n if (on_message$silence) {\n invokeRestart(\"muffleMessage\")\n }\n }, warning = function (cnd) \n {\n if (getOption(\"warn\") >= 2 || getOption(\"warn\") < 0) {\n return()\n }\n watcher$capture_plot_and_output()\n if (on_warning$capture) {\n cnd <- sanitize_call(cnd)\n watcher$push(cnd)\n }\n if (on_warning$silence) {\n invokeRestart(\"muffleWarning\")\n }\n }, error = function (cnd) \n {\n watcher$capture_plot_and_output()\n cnd <- sanitize_call(cnd)\n watcher$push(cnd)\n switch(on_error, continue = invokeRestart(\"eval_continue\"), \n stop = invokeRestart(\"eval_stop\"), error = invokeRestart(\"eval_error\", \n cnd))\n })\n34: eval(call)\n33: eval(call)\n32: with_handlers({\n for (expr in tle$exprs) {\n ev <- withVisible(eval(expr, envir))\n watcher$capture_plot_and_output()\n watcher$print_value(ev$value, ev$visible, envir)\n }\n TRUE\n }, handlers)\n31: doWithOneRestart(return(expr), restart)\n30: withOneRestart(expr, restarts[[1L]])\n29: withRestartList(expr, restarts[-nr])\n28: doWithOneRestart(return(expr), restart)\n27: withOneRestart(withRestartList(expr, restarts[-nr]), restarts[[nr]])\n26: withRestartList(expr, restarts[-nr])\n25: doWithOneRestart(return(expr), restart)\n24: withOneRestart(withRestartList(expr, restarts[-nr]), restarts[[nr]])\n23: withRestartList(expr, restarts)\n22: withRestarts(with_handlers({\n for (expr in tle$exprs) {\n ev <- withVisible(eval(expr, envir))\n watcher$capture_plot_and_output()\n watcher$print_value(ev$value, ev$visible, envir)\n }\n TRUE\n }, handlers), eval_continue = function() TRUE, eval_stop = function() FALSE, \n eval_error = function(cnd) {\n signalCondition(cnd)\n stop(cnd)\n })\n21: evaluate::evaluate(...)\n20: evaluate(code, envir = env, new_device = FALSE, keep_warning = if (is.numeric(options$warning)) TRUE else options$warning, \n keep_message = if (is.numeric(options$message)) TRUE else options$message, \n stop_on_error = if (is.numeric(options$error)) options$error else {\n if (options$error && options$include) \n 0L\n else 2L\n }, output_handler = knit_handlers(options$render, options))\n19: in_dir(input_dir(), expr)\n18: in_input_dir(evaluate(code, envir = env, new_device = FALSE, \n keep_warning = if (is.numeric(options$warning)) TRUE else options$warning, \n keep_message = if (is.numeric(options$message)) TRUE else options$message, \n stop_on_error = if (is.numeric(options$error)) options$error else {\n if (options$error && options$include) \n 0L\n else 2L\n }, output_handler = knit_handlers(options$render, options)))\n17: eng_r(options)\n16: block_exec(params)\n15: call_block(x)\n14: process_group(group)\n13: withCallingHandlers(if (tangle) process_tangle(group) else process_group(group), \n error = function(e) if (xfun::pkg_available(\"rlang\", \"1.0.0\")) rlang::entrace(e))\n12: xfun:::handle_error(withCallingHandlers(if (tangle) process_tangle(group) else process_group(group), \n error = function(e) if (xfun::pkg_available(\"rlang\", \"1.0.0\")) rlang::entrace(e)), \n function(loc) {\n setwd(wd)\n write_utf8(res, output %n% stdout())\n paste0(\"\\nQuitting from lines \", loc)\n }, if (labels[i] != \"\") sprintf(\" [%s]\", labels[i]), get_loc)\n11: process_file(text, output)\n10: knitr::knit(knit_input, knit_output, envir = envir, quiet = quiet)\n9: rmarkdown::render(input, \"blogdown::html_page\", output_file = output, \n envir = globalenv(), quiet = quiet, run_pandoc = !to_md, \n clean = !to_md)\n8: (function (input, output, to_md = file_ext(output) != \"html\", \n quiet = TRUE) \n {\n options(htmltools.dir.version = FALSE, rmarkdown.knit.ext = \"md~\")\n setwd(dirname(input))\n input = basename(input)\n if (to_md) \n options(bookdown.output.markdown = TRUE)\n res = rmarkdown::render(input, \"blogdown::html_page\", output_file = output, \n envir = globalenv(), quiet = quiet, run_pandoc = !to_md, \n clean = !to_md)\n x = read_utf8(res)\n if (to_md) \n x = process_markdown(res, x)\n unlink(res)\n x\n })(\"content/post/2025/2025-03-19-log-error-on-R/index.Rmd\", \"index.html~\", \n FALSE, TRUE)\n7: do.call(f, x[[2]], envir = globalenv())\n6: eval(quote({\n if (length(a <- commandArgs(TRUE)) != 3) stop(\"The number of arguments passed to Rscript should be 3.\")\n on.exit(if (!file.exists(a[2])) saveRDS(geterrmessage(), \n a[3]))\n x = readRDS(a[1])\n f = x[[1]]\n if (is.character(f)) f = eval(parse(text = f), envir = globalenv())\n r = do.call(f, x[[2]], envir = globalenv())\n saveRDS(r, a[2])\n }), new.env())\n5: eval(quote({\n if (length(a <- commandArgs(TRUE)) != 3) stop(\"The number of arguments passed to Rscript should be 3.\")\n on.exit(if (!file.exists(a[2])) saveRDS(geterrmessage(), \n a[3]))\n x = readRDS(a[1])\n f = x[[1]]\n if (is.character(f)) f = eval(parse(text = f), envir = globalenv())\n r = do.call(f, x[[2]], envir = globalenv())\n saveRDS(r, a[2])\n }), new.env())\n4: eval(expr, p)\n3: eval(expr, p)\n2: eval.parent(substitute(eval(quote(expr), envir)))\n1: local({\n if (length(a <- commandArgs(TRUE)) != 3) \n stop(\"The number of arguments passed to Rscript should be 3.\")\n on.exit(if (!file.exists(a[2])) saveRDS(geterrmessage(), \n a[3]))\n x = readRDS(a[1])\n f = x[[1]]\n if (is.character(f)) \n f = eval(parse(text = f), envir = globalenv())\n r = do.call(f, x[[2]], envir = globalenv())\n saveRDS(r, a[2])\n })"}
#> NULLたぶんこんな感じなんだけどしんどい……。
ENJOY!!
この記事は Osaka.R朝もくの時間で書きました。こういう場があると、やる気がわいていいですね。主にオンラインで活動しているので、大阪以外にお住いの方もぜひ！