Annoying condition messages from rlang (deprecated as_character) logged while using dplyr arrange and group_by functions

SessionInfo

R version 4.0.3 (2020-10-10)
Platform: x86_64-conda-linux-gnu (64-bit)
Running under: Ubuntu 20.04.1 LTS
attached base packages:
[1] stats graphics grDevices utils datasets methods base

other attached packages:
[1] tryCatchLog_1.2.1 dplyr_1.0.2

loaded via a namespace (and not attached):
[1] rstudioapi_0.13 magrittr_2.0.1 tidyselect_1.1.0 lattice_0.20-41 R6_2.5.0 rlang_0.4.9 fansi_0.4.1
[8] tools_4.0.3 grid_4.0.3 utf8_1.1.4 cli_2.2.0 lambda.r_1.2.4 futile.logger_1.4.3 ellipsis_0.3.1
[15] assertthat_0.2.1 tibble_3.0.4 lifecycle_0.2.0 crayon_1.3.4 Matrix_1.2-18 purrr_0.3.4 formatR_1.7
[22] vctrs_0.3.5 futile.options_1.0.1 glue_1.4.2 compiler_4.0.3 pillar_1.4.7 generics_0.1.0 pkgconfig_2.0.3

Observation:
When using a tryCatchLog or tryCatch function with arrange from dplyr , it throws annoying INFO messages :

library(dplyr)
library(tryCatchLog)

temp <- c(2, 19.5, 25.8, 6, 32.8, 50.5, 25.3, 40.2)
description <- c("low", "medium", "medium", "low", "medium", "high", "low", "high")
season <- c("winter", "spring", "winter", "summer", "autumn", "summer", "spring", "summer")
year <- c(2020L, 2019L, 2020L, 2019L, 2020L, 2019L, 2019L, 2020L)
weather_info <- data.frame(
    temp = temp,
    description = description,
    season = season,
    year = year,
    stringsAsFactors = FALSE
)

tryCatchLog(
    weather_info %>% arrange(season, temp)
)

Output :

INFO [2021-01-06 23:13:26] [INFO] as_character() is deprecated as of rlang 0.4.0
Please use vctrs::vec_cast() instead.

Compact call stack:
1 tryCatchLog(arrange(weather_info, season, temp))
2 tryCatchLog.R#326: tryCatch(withCallingHandlers(expr, condition = cond.handler), ..., finally = finally)
3 tryCatchLog.R#326: withCallingHandlers(expr, condition = cond.handler)
4 tryCatchLog.R#326: arrange(weather_info, season, temp)

Full call stack:
1 tryCatchLog(arrange(weather_info, season, temp))
2 tryCatchLog.R#326: tryCatch(withCallingHandlers(expr, condition = cond.handler), ..., finally = finally)
3 tryCatchList(expr, classes, parentenv, handlers)
4 tryCatchLog.R#326: withCallingHandlers(expr, condition = cond.handler)
5 tryCatchLog.R#326: arrange(weather_info, season, temp)
6 arrange.data.frame(weather_info, season, temp)
7 arrange_rows(.data, dots)
8 withCallingHandlers({
transmute(new_data_frame(.data), !!!quosures)
}, error = function(cnd) {
if (inherits(cnd, "dplyr:::mutate_erro
9 transmute(new_data_frame(.data), !!!quosures)
10 transmute.data.frame(new_data_frame(.data), !!!quosures)
11 mutate(.data, ..., .keep = "none")
12 mutate.data.frame(.data, ..., .keep = "none")
13 dplyr_col_modify(.data, cols)
14 dplyr_col_modify.data.frame(.data, cols)
15 as_utf8_character(names2(out))
16 as_character(x)
17 signal_deprecated_cast("as_character")
18 signal_soft_deprecated(env = env, c(sprintf("%s() is deprecated as of rlang 0.4.0", fn), "Please use vctrs::vec_cast() instead."))
19 rlang::signal(msg, "lifecycle_soft_deprecated")
20 cnd_signal(cnd)
21 withRestarts(rlang_muffle = function() NULL, signalCondition(x))
22 withOneRestart(expr, restarts[[1]])
23 doWithOneRestart(return(expr), restart)
24 signalCondition(x)

temp description season year
1 32.8 medium autumn 2020
2 19.5 medium spring 2019
3 25.3 low spring 2019
4 6.0 low summer 2019
5 40.2 high summer 2020
6 50.5 high summer 2019
7 2.0 low winter 2020
8 25.8 medium winter 2020

Expected behaviour:
Do not throw deprecation INFO warnings messages when using arrange function from dplyr .

Postscript :
When using other functions from dplyr package such as select or filter .. , it doesn't throw INFO warnings messages and works fine .

[aryoda]

Thanks for your excellent issue report incl. a perfect reproducible example!

The reason for this "chattiness" is the rlang package used by dplyr.

I have already opened an rlang issue:

r-lib/rlang#1082

Since the fix seems to be easy I probably should send a PR myself to rlang...

Until then there is a workaround to switch off the deprecation infos of rlang:

options(lifecycle_disable_warnings = TRUE, lifecycle_verbose_soft_deprecation = FALSE)

[tkharrat]

Observation:
Somehow related to this issue, the use of dplyr::group_by() also generates an annoying empty info message. If I take the same example as before and just change arrange with a group_by() operation, I get the following:

library(dplyr)
library(tryCatchLog)

options(dplyr.summarise.inform = FALSE)
options(lifecycle_disable_warnings = TRUE,
        lifecycle_verbose_soft_deprecation = FALSE)
options(lifecycle_verbosity = "quiet")

temp <- c(2, 19.5, 25.8, 6, 32.8, 50.5, 25.3, 40.2)
description <- c("low", "medium", "medium", "low", "medium", "high", "low", "high")
season <- c("winter", "spring", "winter", "summer", "autumn", "summer", "spring", "summer")
year <- c(2020L, 2019L, 2020L, 2019L, 2020L, 2019L, 2019L, 2020L)
weather_info <- data.frame(
    temp = temp,
    description = description,
    season = season,
    year = year,
    stringsAsFactors = FALSE
)

tryCatchLog(
    x <- weather_info %>% group_by(.data$description)
)

Output:

Using futile.logger for logging...
INFO [2021-01-07 10:06:49] [INFO] 

Compact call stack:
  1 source("test_dplyr.R")
  2 test_dplyr.R#21: tryCatchLog(x <- weather_info %>% group_by(.data$descripti
  3 tryCatchLog.R#326: tryCatch(withCallingHandlers(expr, condition = cond.hand
  4 tryCatchLog.R#326: withCallingHandlers(expr, condition = cond.handler)
  5 tryCatchLog.R#326: weather_info %>% group_by(.data$description)

Full call stack:
  1 source("test_dplyr.R")
  2 withVisible(eval(ei, envir))
  3 eval(ei, envir)
  4 eval(ei, envir)
  5 test_dplyr.R#21: tryCatchLog(x <- weather_info %>% group_by(.data$descripti
  6 tryCatchLog.R#326: tryCatch(withCallingHandlers(expr, condition = cond.hand
  7 tryCatchList(expr, classes, parentenv, handlers)
  8 tryCatchLog.R#326: withCallingHandlers(expr, condition = cond.handler)
  9 tryCatchLog.R#326: weather_info %>% group_by(.data$description)
  10 group_by(., .data$description)
  11 group_by.data.frame(., .data$description)
  12 grouped_df(groups$data, groups$group_names, .drop)
  13 compute_groups(data, vars, drop = drop)
  14 signal("", class = "dplyr_regroup")
  15 cnd_signal(cnd)
  16 withRestarts(rlang_muffle = function() NULL, signalCondition(x))
  17 withOneRestart(expr, restarts[[1]])
  18 doWithOneRestart(return(expr), restart)
  19 signalCondition(x)

I think this is related to the signal("", class = "dplyr_regroup") in line 47 in the dplyr code.

Note that if I run the same code outside the tryCatchLog() block, nothing is outputted.

Expected behaviour:
Do not capture empty signal messages inside tryCatchLog() blocks.

[aryoda]

@tkharrat Good observation, not even my proposed workaround does help here :-(

Note that if I run the same code outside the tryCatchLog() block, nothing is outputted.

Currently I do not yet understand how dplyr uses rlang to hide the signals thrown via signal

I guess that the signal is thrown and later captured + hidden in dplyr (or rlang) but
since tryCatchLog uses withCallingHandlers the signals are captured immediately when they are thrown
and therefor also logged... Challenging...

I will dig into the issue this weekend (I hope)...

[aryoda]

Issue analysis results (wip):

Summary

The annoying messages are caused by non-standard conditions (sub classes of condition)
which are logged in tryCatchLog since April 2020.

Standard R does not write non-standard conditions to the console (no output) which explains the different behaviour between a direct call and a call within tryCatchLog().

Analysis details

1. tryCatchLog introduced the logging of non-standard conditions (conditions with a sub class of condition) in April 2020 via FR Support logging of non-standard (custom) conditions #45

2. dplyr uses rlang to throw non-standard conditions (derived from class condition) in both above cases:

   19 rlang::signal(msg, "lifecycle_soft_deprecated")
   signal of class: [1] "lifecycle_soft_deprecated" "condition"

   and

   14 signal("", class = "dplyr_regroup")
   signal of class: [1] "dplyr_regroup" "condition"

   Note: The signal "dplyr_regroup" was introduced for performance measuring in Jan 2020 (issue 4751 in tidyverse/dplyr)

3. Standard R does not output non-standard conditions, eg. this is silent:

   rlang::signal("", class = "dplyr_regroup")

Possible fixes

1. [my favorite] Disable logging of non-standard conditions by default in tryCatchLog and introduce an option to enable it
   (+ perhaps an option to provide a positive list of all condition classes to be logged)
2. [not my favorite] Add an option to provide a list of condition sub classes to be ignored by tryCatchLog
3. [not my favorite] Blacklist condition logging of well-known R packages that are too chatty
4. [not my favorite] Change the logging level of conditions from INFO to DEBUG (requires to introduce this new logging level)
5. TODO...

Furthermore another option to specify the severity level of non-standard conditions could be introduced (eg. together with new log level functions like "debug" and "trace").

[vwrobel]

Hi, this package is very usefull in a project where I do a lot of dplyr::group_by. Hence the logs end up being very verbose. Is that appropriate to propose a PR for the "favorite fix" when I have time?

[aryoda]

Oh yes, PRs are always welcome an sorry for not having fixed this annoying issue sooner.

Which implementation would you suggest (I am open for discussions!).

Currently I still prefer an implementation that changes the current tryCatchLog function semantics by disabling the logging of non-standard conditions by default and introduce an function parameter at the end to make it possible to enable it as needed

Furthermore perhaps a possiblilty to provide a positive list of all condition classes to be logged would be great.

How about this signature and semantics:

tryCatchLog <- function(expr,
                        ...,
                        execution.context.msg      = "",
                        finally = NULL,
                        write.error.dump.file           = getOption("tryCatchLog.write.error.dump.file", FALSE),
                        write.error.dump.folder       = getOption("tryCatchLog.write.error.dump.folder", "."),
                        silent.warnings                   = getOption("tryCatchLog.silent.warnings", FALSE),
                        silent.messages                 = getOption("tryCatchLog.silent.messages", FALSE),
                        include.full.call.stack          = getOption("tryCatchLog.include.full.call.stack", TRUE),
                        include.compact.call.stack = getOption("tryCatchLog.include.compact.call.stack", TRUE),
                        logged.conditions               = getOption("tryCatchLog.logged.conditions", NA)
) {

with these allowed values for logged.conditions:

NA = do not log any condition
"" = do log all conditions
vector of strings = log only conditions whose class name is contained in this vector

Other suggestions and discussions welcome!

[vwrobel]

Your proposal is excellent! I will take some time to propose a PR by this week-end. Have a good day.

[aryoda]

THX a lot for your support!

BTW: I am still not sure if it would be more consistent to use NA to log all conditions and "" to log no condition (providing a vector is a white list then)...

[aryoda]

FYI:

Implementation proposal via pull request #67 by @vwrobel.

I have merged the PR int a feature branch with the same name in this repo and am working on it now...