From 37bd8218389f01d68fa3dc5b1c8b1d9eb663f202 Mon Sep 17 00:00:00 2001 From: Lionel Henry Date: Fri, 2 Sep 2022 09:58:06 +0200 Subject: [PATCH] Record backtraces for 5 first warnings --- R/conditions.R | 9 +- R/mutate.R | 6 + tests/testthat/_snaps/conditions.md | 290 ++++++++++++++++++++++++++++ tests/testthat/_snaps/mutate.md | 14 +- tests/testthat/test-conditions.R | 36 ++++ tests/testthat/test-mutate.r | 5 +- 6 files changed, 344 insertions(+), 16 deletions(-) diff --git a/R/conditions.R b/R/conditions.R index 1319eec3ed..a259cf9740 100644 --- a/R/conditions.R +++ b/R/conditions.R @@ -265,13 +265,18 @@ new_dplyr_warning <- function(data) { warning_cnd( message = msg, parent = data$cnd, - call = data$call + call = data$call, + trace = data$cnd$trace ) } #' @export print.dplyr_last_warnings <- function(x, ...) { - print(unstructure(x), ...) + # Opt into experimental grayed out tree + local_options( + "rlang:::trace_display_tree" = TRUE + ) + print(unstructure(x), ..., simplify = "none") remaining <- attr(x, "remaining") if (remaining) { diff --git a/R/mutate.R b/R/mutate.R index d8fd981de5..277a45421f 100644 --- a/R/mutate.R +++ b/R/mutate.R @@ -260,6 +260,12 @@ mutate_cols <- function(.data, dots, caller_env, error_call = caller_env()) { ) }, warning = function(w) { + # Don't entrace more than 5 warnings because this is very costly + if (is_null(w$trace) && length(warnings) <= 5) { + # The frame skipping assumes a regular `base::warning()` stack. + # Also works with warnings emitted from C with `Rf_warning()`. + w$trace <- trace_back(bottom = sys.frame(-5)) + } new <- cnd_data( cnd = w, error_ctxt, diff --git a/tests/testthat/_snaps/conditions.md b/tests/testthat/_snaps/conditions.md index 8d15d3fa9e..89b473d967 100644 --- a/tests/testthat/_snaps/conditions.md +++ b/tests/testthat/_snaps/conditions.md @@ -244,6 +244,19 @@ Problem while computing `x = f()`. Caused by warning in `f()`: ! msg + --- + Backtrace: + x + 1. +-dplyr::mutate(df, x = f()) + 2. +-dplyr:::mutate.data.frame(df, x = f()) + 3. | \-dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) + 4. | +-base::withCallingHandlers(...) + 5. | \-(function() {... + 6. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 7. | \-mask$eval_all_mutate(quo) + 8. | \-dplyr (local) eval() + 9. \-dplyr (local) f() + 10. \-base::warning("msg") --- @@ -266,6 +279,19 @@ Problem in group 1: id = 1 while computing `x = f()`. Caused by warning in `f()`: ! msg + --- + Backtrace: + x + 1. +-dplyr::mutate(group_by(df, id), x = f()) + 2. +-dplyr:::mutate.data.frame(group_by(df, id), x = f()) + 3. | \-dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) + 4. | +-base::withCallingHandlers(...) + 5. | \-(function() {... + 6. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 7. | \-mask$eval_all_mutate(quo) + 8. | \-dplyr (local) eval() + 9. \-dplyr (local) f() + 10. \-base::warning("msg") [[2]] @@ -273,6 +299,19 @@ Problem in group 2: id = 2 while computing `x = f()`. Caused by warning in `f()`: ! msg + --- + Backtrace: + x + 1. +-dplyr::mutate(group_by(df, id), x = f()) + 2. +-dplyr:::mutate.data.frame(group_by(df, id), x = f()) + 3. | \-dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) + 4. | +-base::withCallingHandlers(...) + 5. | \-(function() {... + 6. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 7. | \-mask$eval_all_mutate(quo) + 8. | \-dplyr (local) eval() + 9. \-dplyr (local) f() + 10. \-base::warning("msg") --- @@ -295,6 +334,19 @@ Problem in row 1 while computing `x = f()`. Caused by warning in `f()`: ! msg + --- + Backtrace: + x + 1. +-dplyr::mutate(rowwise(df), x = f()) + 2. +-dplyr:::mutate.data.frame(rowwise(df), x = f()) + 3. | \-dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) + 4. | +-base::withCallingHandlers(...) + 5. | \-(function() {... + 6. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 7. | \-mask$eval_all_mutate(quo) + 8. | \-dplyr (local) eval() + 9. \-dplyr (local) f() + 10. \-base::warning("msg") [[2]] @@ -302,6 +354,19 @@ Problem in row 2 while computing `x = f()`. Caused by warning in `f()`: ! msg + --- + Backtrace: + x + 1. +-dplyr::mutate(rowwise(df), x = f()) + 2. +-dplyr:::mutate.data.frame(rowwise(df), x = f()) + 3. | \-dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) + 4. | +-base::withCallingHandlers(...) + 5. | \-(function() {... + 6. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 7. | \-mask$eval_all_mutate(quo) + 8. | \-dplyr (local) eval() + 9. \-dplyr (local) f() + 10. \-base::warning("msg") --- @@ -333,6 +398,25 @@ Problem while computing `g = f():n()`. Caused by warning in `f()`: ! msg + --- + Backtrace: + x + 1. +-dplyr::mutate(...) + 2. +-dplyr::group_by(...) + 3. +-dplyr::mutate(rowwise(group_by(df, g = f():n())), x = f()) + 4. +-dplyr::rowwise(group_by(df, g = f():n())) + 5. +-dplyr::group_by(df, g = f():n()) + 6. +-dplyr:::group_by.data.frame(df, g = f():n()) + 7. | \-dplyr::group_by_prepare(...) + 8. | \-dplyr:::add_computed_columns(...) + 9. | \-dplyr:::mutate_cols(...) + 10. | +-base::withCallingHandlers(...) + 11. | \-(function() {... + 12. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 13. | \-mask$eval_all_mutate(quo) + 14. | \-dplyr (local) eval() + 15. \-dplyr (local) f() + 16. \-base::warning("msg") [[2]] @@ -340,6 +424,21 @@ Problem in row 1 while computing `x = f()`. Caused by warning in `f()`: ! msg + --- + Backtrace: + x + 1. +-dplyr::mutate(...) + 2. +-dplyr::group_by(...) + 3. +-dplyr::mutate(rowwise(group_by(df, g = f():n())), x = f()) + 4. +-dplyr:::mutate.data.frame(...) + 5. | \-dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) + 6. | +-base::withCallingHandlers(...) + 7. | \-(function() {... + 8. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 9. | \-mask$eval_all_mutate(quo) + 10. | \-dplyr (local) eval() + 11. \-dplyr (local) f() + 12. \-base::warning("msg") [[3]] @@ -347,6 +446,21 @@ Problem in row 2 while computing `x = f()`. Caused by warning in `f()`: ! msg + --- + Backtrace: + x + 1. +-dplyr::mutate(...) + 2. +-dplyr::group_by(...) + 3. +-dplyr::mutate(rowwise(group_by(df, g = f():n())), x = f()) + 4. +-dplyr:::mutate.data.frame(...) + 5. | \-dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) + 6. | +-base::withCallingHandlers(...) + 7. | \-(function() {... + 8. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 9. | \-mask$eval_all_mutate(quo) + 10. | \-dplyr (local) eval() + 11. \-dplyr (local) f() + 12. \-base::warning("msg") [[4]] @@ -354,6 +468,19 @@ Problem in group 1: id = 1 while computing `x = f()`. Caused by warning in `f()`: ! msg + --- + Backtrace: + x + 1. +-dplyr::mutate(...) + 2. +-dplyr:::mutate.data.frame(...) + 3. | \-dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) + 4. | +-base::withCallingHandlers(...) + 5. | \-(function() {... + 6. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 7. | \-mask$eval_all_mutate(quo) + 8. | \-dplyr (local) eval() + 9. \-dplyr (local) f() + 10. \-base::warning("msg") [[5]] @@ -361,6 +488,19 @@ Problem in group 2: id = 2 while computing `x = f()`. Caused by warning in `f()`: ! msg + --- + Backtrace: + x + 1. +-dplyr::mutate(...) + 2. +-dplyr:::mutate.data.frame(...) + 3. | \-dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) + 4. | +-base::withCallingHandlers(...) + 5. | \-(function() {... + 6. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 7. | \-mask$eval_all_mutate(quo) + 8. | \-dplyr (local) eval() + 9. \-dplyr (local) f() + 10. \-base::warning("msg") --- @@ -390,6 +530,19 @@ Problem in row 1 while computing `x = f()`. Caused by warning in `f()`: ! msg + --- + Backtrace: + x + 1. +-dplyr::mutate(rowwise(df), x = f()) + 2. +-dplyr:::mutate.data.frame(rowwise(df), x = f()) + 3. | \-dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) + 4. | +-base::withCallingHandlers(...) + 5. | \-(function() {... + 6. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 7. | \-mask$eval_all_mutate(quo) + 8. | \-dplyr (local) eval() + 9. \-dplyr (local) f() + 10. \-base::warning("msg") Message ... with 1 more warning. @@ -426,8 +579,145 @@ Problem in row 1 while computing `x = f()`. Caused by warning in `f()`: ! msg + --- + Backtrace: + x + 1. +-dplyr::mutate(rowwise(df), x = f()) + 2. +-dplyr:::mutate.data.frame(rowwise(df), x = f()) + 3. | \-dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) + 4. | +-base::withCallingHandlers(...) + 5. | \-(function() {... + 6. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 7. | \-mask$eval_all_mutate(quo) + 8. | \-dplyr (local) eval() + 9. \-dplyr (local) f() + 10. \-base::warning("msg") Message ... with 4 more warnings. i Use `dplyr_last_warnings(n = ...)` to show more. +# complex backtraces with base and rlang warnings + + Code + foo() + Condition + Warning: + There was 1 warning in a `group_by()` step. + ! foo + Warning: + There were 3 warnings in a `mutate()` step. + The first warning was: + ! foo + i Run `dplyr::dplyr_last_warnings()` to see the 2 remaining warnings. + Output + # A tibble: 3 x 2 + # Groups: x [1] + id x + + 1 1 1 + 2 2 1 + 3 3 1 + Code + dplyr_last_warnings() + Output + [[1]] + + Warning in `group_by()`: + Problem while computing `x = f(1):n()`. + Caused by warning in `h()`: + ! foo + --- + Backtrace: + x + 1. +-dplyr (local) foo() + 2. | \-dplyr (local) bar() + 3. | +-dplyr::mutate(group_by(df, x = f(1):n()), x = f(1, base = FALSE)) + 4. | +-dplyr::group_by(df, x = f(1):n()) + 5. | \-dplyr:::group_by.data.frame(df, x = f(1):n()) + 6. | \-dplyr::group_by_prepare(...) + 7. | \-dplyr:::add_computed_columns(...) + 8. | \-dplyr:::mutate_cols(...) + 9. | +-base::withCallingHandlers(...) + 10. | \-(function() {... + 11. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 12. | \-mask$eval_all_mutate(quo) + 13. | \-dplyr (local) eval() + 14. \-dplyr (local) f(1) + 15. \-dplyr (local) g(...) + 16. \-dplyr (local) h(...) + 17. \-base::warning("foo") + + [[2]] + + Warning in `mutate()`: + Problem in group 1: x = 1 while computing `x = f(1, base = FALSE)`. + Caused by warning: + ! foo + --- + Backtrace: + x + 1. +-dplyr (local) foo() + 2. | \-dplyr (local) bar() + 3. | +-dplyr::mutate(group_by(df, x = f(1):n()), x = f(1, base = FALSE)) + 4. | \-dplyr:::mutate.data.frame(...) + 5. | \-dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) + 6. | +-base::withCallingHandlers(...) + 7. | \-(function() {... + 8. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 9. | \-mask$eval_all_mutate(quo) + 10. | \-dplyr (local) eval() + 11. \-dplyr (local) f(1, base = FALSE) + 12. \-dplyr (local) g(...) + 13. \-dplyr (local) h(...) + 14. \-rlang::warn("foo") + + [[3]] + + Warning in `mutate()`: + Problem in group 2: x = 2 while computing `x = f(1, base = FALSE)`. + Caused by warning: + ! foo + --- + Backtrace: + x + 1. +-dplyr (local) foo() + 2. | \-dplyr (local) bar() + 3. | +-dplyr::mutate(group_by(df, x = f(1):n()), x = f(1, base = FALSE)) + 4. | \-dplyr:::mutate.data.frame(...) + 5. | \-dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) + 6. | +-base::withCallingHandlers(...) + 7. | \-(function() {... + 8. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 9. | \-mask$eval_all_mutate(quo) + 10. | \-dplyr (local) eval() + 11. \-dplyr (local) f(1, base = FALSE) + 12. \-dplyr (local) g(...) + 13. \-dplyr (local) h(...) + 14. \-rlang::warn("foo") + + [[4]] + + Warning in `mutate()`: + Problem in group 3: x = 3 while computing `x = f(1, base = FALSE)`. + Caused by warning: + ! foo + --- + Backtrace: + x + 1. +-dplyr (local) foo() + 2. | \-dplyr (local) bar() + 3. | +-dplyr::mutate(group_by(df, x = f(1):n()), x = f(1, base = FALSE)) + 4. | \-dplyr:::mutate.data.frame(...) + 5. | \-dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) + 6. | +-base::withCallingHandlers(...) + 7. | \-(function() {... + 8. | \-dplyr:::mutate_col(dots[[i]], .data, mask, new_columns) + 9. | \-mask$eval_all_mutate(quo) + 10. | \-dplyr (local) eval() + 11. \-dplyr (local) f(1, base = FALSE) + 12. \-dplyr (local) g(...) + 13. \-dplyr (local) h(...) + 14. \-rlang::warn("foo") + + diff --git a/tests/testthat/_snaps/mutate.md b/tests/testthat/_snaps/mutate.md index 948478bd5b..d21ee28544 100644 --- a/tests/testthat/_snaps/mutate.md +++ b/tests/testthat/_snaps/mutate.md @@ -56,21 +56,15 @@ # mutate() deals with 0 groups (#5534) Code - invisible(mutate(df, y = max(x))) + mutate(df, y = max(x)) Condition Warning: There was 1 warning in a `mutate()` step. ! no non-missing arguments to max; returning -Inf - Code - dplyr_last_warnings() Output - [[1]] - - Warning in `mutate()`: - Problem while computing `y = max(x)`. - Caused by warning in `max()`: - ! no non-missing arguments to max; returning -Inf - + # A tibble: 0 x 2 + # Groups: x [0] + # ... with 2 variables: x , y # mutate() give meaningful errors diff --git a/tests/testthat/test-conditions.R b/tests/testthat/test-conditions.R index c3d7342ddc..53d5e04aea 100644 --- a/tests/testthat/test-conditions.R +++ b/tests/testthat/test-conditions.R @@ -67,6 +67,10 @@ test_that("errors during dots collection are not enriched (#6178)", { }) test_that("warnings are collected for `dplyr_last_warnings()`", { + local_options( + rlang_trace_format_srcrefs = FALSE + ) + df <- tibble(id = 1:2) f <- function() { warning("msg") @@ -134,3 +138,35 @@ test_that("warnings are collected for `dplyr_last_warnings()`", { dplyr_last_warnings(n = 1) }) }) + +test_that("complex backtraces with base and rlang warnings", { + local_options( + rlang_trace_format_srcrefs = FALSE + ) + reset_dplyr_warnings() + + df <- tibble(id = 1:3) + + f <- function(...) g(...) + g <- function(...) h(...) + h <- function(x, base = TRUE) { + if (base) { + warning("foo") + } else { + warn("foo") + } + x + } + + foo <- function() bar() + bar <- function() { + df |> + group_by(x = f(1):n()) |> + mutate(x = f(1, base = FALSE)) + } + + expect_snapshot({ + foo() + dplyr_last_warnings() + }) +}) diff --git a/tests/testthat/test-mutate.r b/tests/testthat/test-mutate.r index 443edf1a20..108e87a694 100644 --- a/tests/testthat/test-mutate.r +++ b/tests/testthat/test-mutate.r @@ -525,11 +525,8 @@ test_that("mutate() deals with 0 groups (#5534)", { data.frame(x = numeric(), y = numeric()) %>% group_by(x) ) - reset_dplyr_warnings() - expect_snapshot({ - invisible(mutate(df, y = max(x))) - dplyr_last_warnings() + mutate(df, y = max(x)) }) })