Collect warnings and add `dplyr_last_warnings()` #6443

lionel- · 2022-09-01T10:23:00Z

Branched from #6438.

Warnings within mutate steps are now collected instead of being enriched right away.
The new function dplyr_last_warnings() returns enriched warnings, the first 20 by default.
Enriched warnings are now chained so as to keep a reference to the verb within which they were emitted.

f <- function(x) {
  warning("foo")
  x
}

df <- tibble(id = 1:100)

df |>
  rowwise() |>
  mutate(x = f(1))
#> # A tibble: 100 × 2
#> # Rowwise:
#>      id     x
#>   <int> <dbl>
#> 1     1     1
#> 2     2     1
#> 3     3     1
#> 4     4     1
#> # … with 96 more rows
#> # ℹ Use `print(n = ...)` to see more rows
#> Warning message:
#> There were 100 warnings in `mutate()`.
#> ℹ Run `dplyr::dplyr_last_warnings()` to see them.

dplyr_last_warnings(3)
#> [[1]]
#> <warning/rlang_warning>
#> Warning in `mutate()`:
#> Problem in row 1 while computing `x = f(1)`.
#> Caused by warning in `f()`:
#> ! foo
#>
#> [[2]]
#> <warning/rlang_warning>
#> Warning in `mutate()`:
#> Problem in row 2 while computing `x = f(1)`.
#> Caused by warning in `f()`:
#> ! foo
#>
#> [[3]]
#> <warning/rlang_warning>
#> Warning in `mutate()`:
#> Problem in row 3 while computing `x = f(1)`.
#> Caused by warning in `f()`:
#> ! foo
#>
#> ... with 97 more warnings.
#> ℹ Use `dplyr_last_warnings(n = ...)` to show more.

The other way we could handle long lists of warnings is by detecting if there are more than 10 or 20. If that's the case, suggest to run head(dplyr_last_warnings()), otherwise just dplyr_last_warnings(). On hindsight I think that would make things simpler internally and for users.

lionel- · 2022-09-01T10:23:46Z

DESCRIPTION

@@ -30,6 +30,7 @@ BugReports: https://github.com/tidyverse/dplyr/issues
 Depends: 
    R (>= 3.4.0)
 Imports: 
+    cli (>= 3.3.0),


This PR uses cli right away to use features like pluralisation. Also I think it's better to write new code with cli right away since porting existing code is so tricky.

R/aaa.R

R/conditions.R

lionel- · 2022-09-01T10:26:14Z

R/conditions.R

+}
+
+# rlang should export this routine
+error_call <- function(call) {


This is a hack to get the result of rlang:::error_call(), which has special behaviour compared to frame_call(), for instance with S3 methods.

Tracked in r-lib/rlang#1474.

hadley

Also need to do the same thing with summarise? e.g.

library(dplyr, warn.conflicts = FALSE)

df <- tibble(id = 1:100, x = NA)
df |> 
  group_by(id) |> 
  summarise(y = min(x, na.rm = TRUE))

R/aaa.R

R/context.R

hadley · 2022-09-01T12:39:40Z

Playing around with this a bit, I think it's probably worth showing maybe 1 warning by default? i.e. instead of:

#> Warning message:
#> There were 2 warnings in `mutate()`.
#> ℹ Run `dplyr::dplyr_last_warnings()` to see them.

Something like:

#> Warning message:
#> There were warnings in `mutate()`.
#> The first warning was:
...
#> ℹ Run `dplyr::dplyr_last_warnings()` to see the remaining 1 warning.

lionel- · 2022-09-01T12:43:12Z

Also need to do the same thing with summarise?

We don't currently enrich warnings in summarise, but it should be easy to add. I guess we should make sure all grouped evals collect warnings? This seems better scoped for a second PR though.

Playing around with this a bit, I think it's probably worth showing maybe 1 warning by default

Good idea.

lionel- · 2022-09-01T16:42:31Z

With the last commit:

If there is only one warning, just emit it enriched.
If there are multiple warnings, just show the first one unenriched (because we already mention the call in the outer warning).

f <- function(x) {
  warning("foo")
  x
}
df <- tibble(id = 1:3)

df |>
   group_by(x = f(1):n()) |>
   mutate(x = f(1))
#> # A tibble: 3 × 2
#> # Groups:   x [1]
#>      id     x
#>   <int> <dbl>
#> 1     1     1
#> 2     2     1
#> 3     3     1
#> Warning messages:
#> 1: In group_by() : Problem while computing `x = f(1):n()`.
#> Caused by warning in `f()`:
#> ! foo
#> 2: There were 3 warnings in `mutate()`.
#> The first warning was:
#> ! foo
#> ℹ Run `dplyr::dplyr_last_warnings()` to see the 2 remaining warnings.

This is a bit messy because of the way our warning conditions interact with base display, but that's not too bad.

hadley · 2022-09-01T19:39:49Z

The display of the one and two warning case feels rather different:

Can we make them more similar? Maybe the 1 warning case could just be:

Warning message:
There was 1 warning in `mutate()`.
! foo

i.e. drop the "the first warning" and "run ..." lines.

How hard would it be to make dplyr_last_warnings() show the warning backtraces?

lionel- · 2022-09-02T07:09:17Z

@hadley Much better, thanks!

The problem with capturing backtraces is that it's very costly. We could do it for the first 5 warnings though. I've also changed:

in `group_by()`.

to

in a `group_by()` step.

Just as a reminder that there could be multiple group-by steps to look for. Is this helpful?

df |>
  rowwise() |>
  mutate(x = f(1))
#> # A tibble: 100 × 2
#> # Rowwise:
#>      id     x
#>   <int> <dbl>
#> 1     1     1
#> 2     2     1
#> 3     3     1
#> 4     4     1
#> # … with 96 more rows
#> # ℹ Use `print(n = ...)` to see more rows
#> Warning message:
#> There were 100 warnings in a `mutate()` step.
#> The first warning was:
#> ! foo
#> ℹ Run `dplyr::dplyr_last_warnings()` to see the 99 remaining warnings.

df |>
  group_by(x = f(1):n()) |>
  mutate(x = f(1))
#> # A tibble: 3 × 2
#> # Groups:   id [3]
#>      id     x
#>   <int> <dbl>
#> 1     1     1
#> 2     2     1
#> 3     3     1
#> Warning messages:
#> 1: There was 1 warning in a `group_by()` step.
#> ! foo
#> 2: There were 3 warnings in a `mutate()` step.
#> The first warning was:
#> ! foo
#> ℹ Run `dplyr::dplyr_last_warnings()` to see the 2 remaining warnings.

lionel- · 2022-09-02T08:32:20Z

With the last commit, we now entrace the first 5 warnings. We also only display 5 warnings by default instead of 20, so that:

It's less confusing why some warnings have backtraces and others don't.
We show less output, since backtraces take up so much space.
The interesting output (with backtraces) is at the end near the prompt.

The display opts into the new tree backtrace style with grayed out inner parts.

df <- tibble(id = 1:2)

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))
}

foo()
#> # A tibble: 2 × 2
#> # Groups:   x [1]
#>      id     x
#>   <int> <dbl>
#> 1     1     1
#> 2     2     1
#> Warning messages:
#> 1: There was 1 warning in a `group_by()` step.
#> ! foo
#> 2: There were 2 warnings in a `mutate()` step.
#> The first warning was:
#> ! foo
#> ℹ Run `dplyr::dplyr_last_warnings()` to see the 1 remaining warning.

dplyr_last_warnings()
#> [[1]]
#> <warning/rlang_warning>
#> Warning in `group_by()`:
#> Problem while computing `x = f(1):n()`.
#> Caused by warning in `h()`:
#> ! foo
#> ---
#> Backtrace:
#>      ▆
#>   1. ├─utils (local) .ess.command(...)
#>   2. │ ├─base::withCallingHandlers(interrupt = restart, withVisible(expr))
#>   3. │ └─base::withVisible(expr)
#>   4. ├─base::local(...)
#>   5. │ └─base::eval.parent(substitute(eval(quote(expr), envir)))
#>   6. │   └─base::eval(expr, p)
#>   7. │     └─base::eval(expr, p)
#>   8. ├─base::eval(...)
#>   9. │ └─base::eval(...)
#>  10. │   └─global foo()
#>  11. │     └─global bar()
#>  12. │       ├─dplyr::mutate(group_by(df, x = f(1):n()), x = f(1, base = FALSE))
#>  13. │       ├─dplyr::group_by(df, x = f(1):n())
#>  14. │       └─dplyr:::group_by.data.frame(df, x = f(1):n()) at dplyr/R/group-by.r:135:2
#>  15. │         └─dplyr::group_by_prepare(...) at dplyr/R/group-by.r:140:2
#>  16. │           └─dplyr:::add_computed_columns(...) at dplyr/R/group-by.r:215:2
#>  17. │             └─dplyr:::mutate_cols(...) at dplyr/R/group-by.r:253:6
#>  18. │               ├─base::withCallingHandlers(...) at dplyr/R/mutate.R:239:2
#>  19. │               └─(function() {... at dplyr/R/mutate.R:239:2
#>  20. │                 └─dplyr:::mutate_col(i, .data, dots, mask, new_columns) at dplyr/R/mutate.R:244:6
#>  21. │                   └─mask$eval_all_mutate(quo) at dplyr/R/mutate.R:371:8
#>  22. │                     └─dplyr (local) eval() at dplyr/R/data-mask.R:69:6
#>  23. └─global f(1)
#>  24.   └─global g(...)
#>  25.     └─global h(...)
#>  26.       └─base::warning("foo")
#>
#> [[2]]
#> <warning/rlang_warning>
#> Warning in `mutate()`:
#> Problem in group 1: x = 1 while computing `x = f(1, base = FALSE)`.
#> Caused by warning:
#> ! foo
#> ---
#> Backtrace:
#>      ▆
#>   1. ├─utils (local) .ess.command(...)
#>   2. │ ├─base::withCallingHandlers(interrupt = restart, withVisible(expr))
#>   3. │ └─base::withVisible(expr)
#>   4. ├─base::local(...)
#>   5. │ └─base::eval.parent(substitute(eval(quote(expr), envir)))
#>   6. │   └─base::eval(expr, p)
#>   7. │     └─base::eval(expr, p)
#>   8. ├─base::eval(...)
#>   9. │ └─base::eval(...)
#>  10. │   └─global foo()
#>  11. │     └─global bar()
#>  12. │       ├─dplyr::mutate(group_by(df, x = f(1):n()), x = f(1, base = FALSE))
#>  13. │       └─dplyr:::mutate.data.frame(...) at dplyr/R/mutate.R:146:2
#>  14. │         └─dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) at dplyr/R/mutate.R:175:2
#>  15. │           ├─base::withCallingHandlers(...) at dplyr/R/mutate.R:239:2
#>  16. │           └─(function() {... at dplyr/R/mutate.R:239:2
#>  17. │             └─dplyr:::mutate_col(i, .data, dots, mask, new_columns) at dplyr/R/mutate.R:244:6
#>  18. │               └─mask$eval_all_mutate(quo) at dplyr/R/mutate.R:371:8
#>  19. │                 └─dplyr (local) eval() at dplyr/R/data-mask.R:69:6
#>  20. └─global f(1, base = FALSE)
#>  21.   └─global g(...)
#>  22.     └─global h(...)
#>  23.       └─rlang::warn("foo")
#>
#> [[3]]
#> <warning/rlang_warning>
#> Warning in `mutate()`:
#> Problem in group 2: x = 2 while computing `x = f(1, base = FALSE)`.
#> Caused by warning:
#> ! foo
#> ---
#> Backtrace:
#>      ▆
#>   1. ├─utils (local) .ess.command(...)
#>   2. │ ├─base::withCallingHandlers(interrupt = restart, withVisible(expr))
#>   3. │ └─base::withVisible(expr)
#>   4. ├─base::local(...)
#>   5. │ └─base::eval.parent(substitute(eval(quote(expr), envir)))
#>   6. │   └─base::eval(expr, p)
#>   7. │     └─base::eval(expr, p)
#>   8. ├─base::eval(...)
#>   9. │ └─base::eval(...)
#>  10. │   └─global foo()
#>  11. │     └─global bar()
#>  12. │       ├─dplyr::mutate(group_by(df, x = f(1):n()), x = f(1, base = FALSE))
#>  13. │       └─dplyr:::mutate.data.frame(...) at dplyr/R/mutate.R:146:2
#>  14. │         └─dplyr:::mutate_cols(.data, dplyr_quosures(...), caller_env = caller_env()) at dplyr/R/mutate.R:175:2
#>  15. │           ├─base::withCallingHandlers(...) at dplyr/R/mutate.R:239:2
#>  16. │           └─(function() {... at dplyr/R/mutate.R:239:2
#>  17. │             └─dplyr:::mutate_col(i, .data, dots, mask, new_columns) at dplyr/R/mutate.R:244:6
#>  18. │               └─mask$eval_all_mutate(quo) at dplyr/R/mutate.R:371:8
#>  19. │                 └─dplyr (local) eval() at dplyr/R/data-mask.R:69:6
#>  20. └─global f(1, base = FALSE)
#>  21.   └─global g(...)
#>  22.     └─global h(...)
#>  23.       └─rlang::warn("foo")

lionel- · 2022-09-02T08:50:55Z

I've also renamed dplyr_last_warnings() to last_dplyr_warnings(). This namespaces it inside last_ for autocompletion.

R/conditions.R

NEWS.md

R/conditions.R

NEWS.md

R/conditions.R

R/mutate.R

tests/testthat/_snaps/conditions.md

DavisVaughan

Not sure if you are done, but I gave the changes a look and they look nice

I'm assuming you are planning on doing summarise() in another PR

R/conditions.R

DavisVaughan · 2022-09-20T20:02:57Z

tests/testthat/_snaps/conditions.md

-       10.   \-base::warning("msg")
+          x
+       1. +-dplyr::mutate(df, x = f())
+       2. \-dplyr:::mutate.data.frame(df, x = f())


This looks a lot nicer!

DavisVaughan · 2022-09-20T20:12:21Z

R/context.R

@@ -96,15 +96,44 @@ group_labels_details <- function(keys) {
  }), ", ")


We should probably backtick the {name} = {value} result in group_labels_details() here so it shows up a little better in the error message. Fine if you don't want to do that here

Fixes #6005 Fixes #6236

Co-authored-by: Hadley Wickham <[email protected]>

- If there is only one warning, just emit it. - If there are multiple warnings, just show the first one.

To namespace it in `last_` for autocompletion

lionel- mentioned this pull request Sep 1, 2022

Export error_call() r-lib/rlang#1474

Closed

lionel- commented Sep 1, 2022

View reviewed changes

lionel- requested review from hadley and DavisVaughan and removed request for hadley September 1, 2022 10:31

hadley reviewed Sep 1, 2022

View reviewed changes

R/aaa.R Outdated Show resolved Hide resolved

R/context.R Outdated Show resolved Hide resolved

R/context.R Outdated Show resolved Hide resolved

hadley approved these changes Sep 2, 2022

View reviewed changes

R/conditions.R Outdated Show resolved Hide resolved

DavisVaughan approved these changes Sep 2, 2022

View reviewed changes

lionel- force-pushed the simplify-mutate-cols branch from 14688d9 to ff7bdfb Compare September 8, 2022 09:25

lionel- changed the base branch from simplify-mutate-cols to main September 8, 2022 09:34

lionel- force-pushed the warnings-collection branch from 4eb5df8 to 57dd573 Compare September 8, 2022 09:35

lionel- force-pushed the warnings-collection branch 2 times, most recently from 6bfa6bf to 9d87a64 Compare September 20, 2022 16:16

DavisVaughan approved these changes Sep 20, 2022

View reviewed changes

lionel- force-pushed the warnings-collection branch from 9d87a64 to cb3fd73 Compare September 21, 2022 06:59

lionel- and others added 7 commits September 21, 2022 08:59

Collect warnings and add dplyr_last_warnings()

c83a292

Fixes #6005 Fixes #6236

Use maybe_restart()

d186b65

Apply suggestions from code review

1db6c14

Co-authored-by: Hadley Wickham <[email protected]>

Assign the at build-time

cd839a2

Move signal_warnings() to conditions.R

0f688a6

Preview warnings

8f0724c

- If there is only one warning, just emit it. - If there are multiple warnings, just show the first one.

Tweak display of warnings

91102cf

lionel- added 16 commits September 21, 2022 08:59

Record backtraces for 5 first warnings

6e63112

Only show first 5 warnings

3852fd9

Rename dplyr_last_warnings() to last_dplyr_warnings()

f89606f

To namespace it in `last_` for autocompletion

Record exactly 5 backtraces

c6fa184

Update snapshots

9f54ab1

Move the definition to dplyr.R

b446a7f

Simplify dots_expr() into dot_as_label()

1979652

Add comment about error_call_forced

88d0393

Make last_dplyr_warnings() clickable

83b711b

Suggest a specific number of warnings to view more

e9f3f8d

Show context in warning previews

5801551

Apply suggestions from code review

6738fb0

Simplify backtraces of warnings

219a10c

Mark last_dplyr_warnings() as internal

716acc1

Use magrittr pipe

4acbaee

Skip backtrace tests on old R versions

104bddf

lionel- force-pushed the warnings-collection branch from cb3fd73 to 104bddf Compare September 21, 2022 06:59

lionel- merged commit 4abc428 into main Sep 21, 2022

lionel- deleted the warnings-collection branch September 21, 2022 07:00

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Collect warnings and add `dplyr_last_warnings()` #6443

Collect warnings and add `dplyr_last_warnings()` #6443

lionel- commented Sep 1, 2022

lionel- Sep 1, 2022

lionel- Sep 1, 2022

hadley left a comment

hadley commented Sep 1, 2022

lionel- commented Sep 1, 2022

lionel- commented Sep 1, 2022

hadley commented Sep 1, 2022

lionel- commented Sep 2, 2022

lionel- commented Sep 2, 2022

lionel- commented Sep 2, 2022

DavisVaughan left a comment

DavisVaughan Sep 20, 2022

DavisVaughan Sep 20, 2022

		@@ -96,15 +96,44 @@ group_labels_details <- function(keys) {
		}), ", ")

Collect warnings and add dplyr_last_warnings() #6443

Collect warnings and add dplyr_last_warnings() #6443

Conversation

lionel- commented Sep 1, 2022

lionel- Sep 1, 2022

Choose a reason for hiding this comment

lionel- Sep 1, 2022

Choose a reason for hiding this comment

hadley left a comment

Choose a reason for hiding this comment

hadley commented Sep 1, 2022

lionel- commented Sep 1, 2022

lionel- commented Sep 1, 2022

hadley commented Sep 1, 2022

lionel- commented Sep 2, 2022

lionel- commented Sep 2, 2022

lionel- commented Sep 2, 2022

DavisVaughan left a comment

Choose a reason for hiding this comment

DavisVaughan Sep 20, 2022

Choose a reason for hiding this comment

DavisVaughan Sep 20, 2022

Choose a reason for hiding this comment

Collect warnings and add `dplyr_last_warnings()` #6443

Collect warnings and add `dplyr_last_warnings()` #6443