cnd_message() is called twice in rlang::abort() within reprex::reprex()

[Ilia-Kosenkov]

Disclaimer: I do understand this is an experimental feature, but to me this looks like an exceptionally important feature for package maintainers and users of {rlang}.

rlang::abort() allows throwing errors of a derived type with additional data attached to them. This is great for extensibility, as consumers of {rlang} can define their own error class and provide some generics to improve error printing. At the same time, consumers can rely on {ralng}'s formatting methods for rlang_error, which print out additional info like backtraces, parents, etc.

Right now, the suggested approach is to implement S3 generics rlang::cnd_header(), rlang::cnd_body(), rlang::cnd_footer() for a derived type to improve printing.
The default implementation used for formatting ralgn_error seems to just return the $message field in cnd_header.default().
So, if one would like to print additional info (e.g., using metadata attached as fields to the thrown error), all the logic can be put in, say, cnd_header().

At this point, I assume that S3 can be used to implement a proper 'virtual' method using something like

cnd_header.my_error <- function(cnd, ...) paste(NextMethod(), custom_message(cnd), sep = "\n")

The expected behavior is that when printed, my_error will display both its $message field through default implementation and some additional info.

Here is a reprex with inheritance. I copy-paste the output:

Code

cnd_header.a <- function(cnd, ...)  paste(NextMethod(), "A", sep = "\n")
cnd_header.b <- function(cnd, ...)  paste(NextMethod(), "B", sep = "\n")
err <- tryCatch(rlang::abort("Original message", c("b", "a")), error = identity)
print(err)
summary(err)

Regular output

<error/b>
Original message
A
B
Backtrace:
 1. base::source(...)
 5. base::tryCatch(...)
 6. base:::tryCatchList(expr, classes, parentenv, handlers)
 7. base:::tryCatchOne(expr, names, parentenv, handlers[[1L]])
 8. base:::doTryCatch(return(expr), name, parentenv, handler)
<error/b>
Original message
A
B
Backtrace:
    x
 1. +-base::source(...)
 2. | +-base::withVisible(eval(ei, envir))
 3. | \-base::eval(ei, envir)
 4. |   \-base::eval(ei, envir)
 5. \-base::tryCatch(...)
 6.   \-base:::tryCatchList(expr, classes, parentenv, handlers)
 7.     \-base:::tryCatchOne(expr, names, parentenv, handlers[[1L]])
 8.       \-base:::doTryCatch(return(expr), name, parentenv, handler)

However, this is what happens if instead this same snippet is executed using {reprex}:

Reprex

cnd_header.a <- function(cnd, ...)  paste(NextMethod(), "A", sep = "\n")
cnd_header.b <- function(cnd, ...)  paste(NextMethod(), "B", sep = "\n")
err <- tryCatch(rlang::abort("Original message", c("b", "a")), error = identity)
print(err)
#> <error/b>
#> Original message
#> A
#> B
#> A
#> B
#> Backtrace:
#>  1. base::tryCatch(...)
#>  2. base:::tryCatchList(expr, classes, parentenv, handlers)
#>  3. base:::tryCatchOne(expr, names, parentenv, handlers[[1L]])
#>  4. base:::doTryCatch(return(expr), name, parentenv, handler)
summary(err)
#> <error/b>
#> Original message
#> A
#> B
#> A
#> B
#> Backtrace:
#>     x
#>  1. \-base::tryCatch(...)
#>  2.   \-base:::tryCatchList(expr, classes, parentenv, handlers)
#>  3.     \-base:::tryCatchOne(expr, names, parentenv, handlers[[1L]])
#>  4.       \-base:::doTryCatch(return(expr), name, parentenv, handler)

^{Created on 2021-05-14 by the reprex package (v2.0.0)}

The messages written by derived methods actually repeat themselves twice. I spent a lot of time trying to understand what is going on. The problem can be understood if a traceback is printed from the derived formatting method:

With traces

cnd_header.with_trace <- function(cnd, ...) {
  print("Printing trace:")
  print(rlang::trace_back())
  paste(NextMethod(), "with_trace", sep = "\n")
}
rlang::abort("rlang", "with_trace")
#> [1] "Printing trace:"
#>      x
#>   1. \-rlang::abort("rlang", "with_trace")
#>   2.   \-rlang:::signal_abort(cnd)
#>   3.     +-base::conditionMessage(cnd)
#>   4.     \-rlang:::conditionMessage.rlang_error(cnd)
#>   5.       \-rlang::cnd_message(c)
#>   6.         +-rlang:::paste_line(cnd_header(cnd), cnd_body(cnd), cnd_footer(cnd))
#>   7.         | \-rlang::chr(...)
#>   8.         |   \-rlang::dots_values(...)
#>   9.         +-rlang::cnd_header(cnd)
#>  10.         \-global::cnd_header.with_trace(cnd)
#> [1] "Printing trace:"
#>      x
#>   1. \-rlang::abort("rlang", "with_trace")
#>   2.   \-rlang:::signal_abort(cnd)
#>   3.     \-base::stop(fallback)
#>   4.       +-base::conditionMessage(cond)
#>   5.       \-rlang:::conditionMessage.rlang_error(cond)
#>   6.         \-rlang::cnd_message(c)
#>   7.           +-rlang:::paste_line(cnd_header(cnd), cnd_body(cnd), cnd_footer(cnd))
#>   8.           | \-rlang::chr(...)
#>   9.           |   \-rlang::dots_values(...)
#>  10.           +-rlang::cnd_header(cnd)
#>  11.           \-global::cnd_header.with_trace(cnd)
#> Error: rlang
#> with_trace
#> with_trace
#> [1] "Printing trace:"
#>      x
#>   1. +-base::tryCatch(...)
#>   2. | \-base:::tryCatchList(expr, classes, parentenv, handlers)
#>   3. |   +-base:::tryCatchOne(...)
#>   4. |   | \-base:::doTryCatch(return(expr), name, parentenv, handler)
#>   5. |   \-base:::tryCatchList(expr, names[-nh], parentenv, handlers[-nh])
#>   6. |     \-base:::tryCatchOne(expr, names, parentenv, handlers[[1L]])
#>   7. |       \-base:::doTryCatch(return(expr), name, parentenv, handler)
#>   8. +-base::withCallingHandlers(...)
#>   9. +-base::saveRDS(...)
#>  10. +-base::do.call(...)
#>  11. +-(function (what, args, quote = FALSE, envir = parent.frame()) ...
#>  12. \-(function (input) ...
#>  13.   \-rmarkdown::render(input, quiet = TRUE, envir = globalenv(), encoding = "UTF-8")
#>  14.     \-knitr::knit(knit_input, knit_output, envir = envir, quiet = quiet)
#>  15.       \-knitr:::process_file(text, output)
#>  16.         +-base::withCallingHandlers(...)
#>  17.         +-knitr:::process_group(group)
#>  18.         \-knitr:::process_group.block(group)
#>  19.           \-knitr:::call_block(x)
#>  20.             \-knitr:::block_exec(params)
#>  21.               \-knitr:::eng_r(options)
#>  22.                 +-knitr:::in_dir(...)
#>  23.                 \-knitr:::evaluate(...)
#>  24.                   \-evaluate::evaluate(...)
#>  25.                     \-evaluate:::evaluate_call(...)
#>  26.                       +-evaluate:::timing_fn(...)
#>  27.                       \-evaluate:::handle(...)
#>  28.                         \-base::try(f, silent = TRUE)
#>  29.                           \-base::tryCatch(...)
#>  30.                             \-base:::tryCatchList(expr, classes, parentenv, handlers)
#>  31.                               \-base:::tryCatchOne(expr, names, parentenv, handlers[[1L]])
#>  32.                                 \-value[[3L]](cond)
#>  33.                                   +-base::paste0(prefix, conditionMessage(e), "\n")
#>  34.                                   +-base::conditionMessage(e)
#>  35.                                   \-rlang:::conditionMessage.rlang_error(e)
#>  36.                                     \-rlang::cnd_message(c)
#>  37.                                       +-rlang:::paste_line(cnd_header(cnd), cnd_body(cnd), cnd_footer(cnd))
#>  38.                                       | \-rlang::chr(...)
#>  39.                                       |   \-rlang::dots_values(...)
#>  40.                                       +-rlang::cnd_header(cnd)
#>  41.                                       \-global::cnd_header.with_trace(cnd)

^{Created on 2021-05-14 by the reprex package (v2.0.0)}

For some reason, when executed with {reprex}, the cnd_message() gets called twice, and its results are accumulated.
This is likely the place the first time cnd_message() is called via conditionMessage.rlang_error().

rlang/R/cnd-abort.R

Lines 198 to 210 in bda055d

	if (is_interactive()) {
	# Generate the error message, possibly with a backtrace or reminder
	fallback$message <- paste_line(
	conditionMessage(cnd),
	format_onerror_backtrace(cnd)
	)
	fallback$rlang_entraced <- TRUE
	} else {
	file <- peek_option("rlang:::error_pipe") %||% stderr()
	msg <- conditionMessage(cnd)
	fallback$message <- msg
	cat("Error: ", msg, "\n", sep = "", file = file)

The message gets formatted and written to the $message field of fallback.
And then the second trace originates from here:

rlang/R/cnd-abort.R

Lines 220 to 222 in bda055d

	stop(fallback)
	}

Where cnd_message() gets called on an already modified fallback, so the message is duplicated. And this behavior somehow depends on how it's being executed.

This seems to occur in rlang::abort() and rlang:::signal_abort() (perhaps in the base signalCondition()).
If an error condition is simply created using rlang::error_cnd(), things work just fine.

Only creation

cnd_header.with_trace <- function(cnd, ...) {
  print("Printing trace:")
  print(rlang::trace_back())
  paste(NextMethod(), "with_trace", sep = "\n")
}
rlang::error_cnd(message = "rlang", class = "with_trace") -> err
print(err)
#> [1] "Printing trace:"
#>      x
#>   1. +-base::print(err)
#>   2. \-rlang:::print.rlang_error(err)
#>   3.   +-rlang:::cat_line(...)
#>   4.   | +-base::cat(paste_line(..., .trailing = .trailing), file = file)
#>   5.   | \-rlang:::paste_line(..., .trailing = .trailing)
#>   6.   |   \-rlang::chr(...)
#>   7.   |     \-rlang::dots_values(...)
#>   8.   +-base::format(x, simplify = simplify, fields = fields, ...)
#>   9.   \-rlang:::format.rlang_error(...)
#>  10.     +-rlang:::as_rlang_error_message(conditionMessage(x))
#>  11.     | \-rlang:::strip_trailing_newline(message)
#>  12.     +-base::conditionMessage(x)
#>  13.     \-rlang:::conditionMessage.rlang_error(x)
#>  14.       \-rlang::cnd_message(c)
#>  15.         +-rlang:::paste_line(cnd_header(cnd), cnd_body(cnd), cnd_footer(cnd))
#>  16.         | \-rlang::chr(...)
#>  17.         |   \-rlang::dots_values(...)
#>  18.         +-rlang::cnd_header(cnd)
#>  19.         \-global::cnd_header.with_trace(cnd)
#> <error/with_trace>
#> rlang
#> with_trace

^{Created on 2021-05-14 by the reprex package (v2.0.0)}

[lionel-]

This is only the case within reprex::reprex() because of an interaction with: https://github.com/tidyverse/reprex/blob/d6b12e446bcafe104f3ef762ef0d562148b7f072/R/reprex_document.R#L137

I'm not sure we'll get around to fixing that soon but I'll have a look in case something obvious is missing.

[Ilia-Kosenkov]

@lionel-,
Thanks for the update, it is good to know that it happens only with {reprex}.

[jennybc]

Does this have any bearing on tidyverse/reprex#230?

In general, once you merge this @lionel-, I would love for you to look at reprex's options and tell me what you think is most appropriate:

https://github.com/tidyverse/reprex/blob/d6b12e446bcafe104f3ef762ef0d562148b7f072/R/reprex_document.R#L133-L142

[lionel-]

Unfortunately this doesn't help with tidyverse/reprex#230, we still need some calling-handler hook in evaluate and knitr to entrace the base errors. Is this something that I should bump on my priority list?

Regarding the relevant rlang options for reprex following these changes, I'll open an issue after I have fixed #932.

[jennybc]

Thanks!

Unfortunately this doesn't help with tidyverse/reprex#230, we still need some calling-handler hook in evaluate and knitr to entrace the base errors. Is this something that I should bump on my priority list?

No special priority for me or reprex, no.