errors aren't able to be quieted using `purrr` adverbs

[brianwdavis]

I have a function that I'm logging that occasionally fails badly due to external data sources. I handle it by using purrr::safely and retrying that item later. Usually that means that this function won't print anything to the console, just skip over that item. However, using this package, the deeply hidden stop(...) calls instead manage to print to the log anyway.

Is there any way to avoid this? Is this something for the purrr developers to fix?

library(loggit)
#> Warning: package 'loggit' was built under R version 3.6.2
#> 
#> Attaching package: 'loggit'
#> The following objects are masked from 'package:base':
#> 
#>     message, stop, warning
noisy_fn <- function(x) {
  if (x < 5) {message(x)}
  if (x >= 5) {stop(x)}
  x
}

purrr::map(3:6, purrr::safely(noisy_fn))
#> {"timestamp": "2020-05-25T23:23:54-0400", "log_lvl": "INFO", "log_msg": "3"}
#> 3
#> {"timestamp": "2020-05-25T23:23:54-0400", "log_lvl": "INFO", "log_msg": "4"}
#> 4
#> {"timestamp": "2020-05-25T23:23:54-0400", "log_lvl": "ERROR", "log_msg": "5"}
#> {"timestamp": "2020-05-25T23:23:54-0400", "log_lvl": "ERROR", "log_msg": "6"}
#> [[1]]
#> [[1]]$result
#> [1] 3
#> 
#> [[1]]$error
#> NULL
#> 
#> 
#> [[2]]
#> [[2]]$result
#> [1] 4
#> 
#> [[2]]$error
#> NULL
#> 
#> 
#> [[3]]
#> [[3]]$result
#> NULL
#> 
#> [[3]]$error
#> <simpleError in stop(x): 5>
#> 
#> 
#> [[4]]
#> [[4]]$result
#> NULL
#> 
#> [[4]]$error
#> <simpleError in stop(x): 6>
purrr::map(3:6, purrr::possibly(noisy_fn, otherwise = NA))
#> {"timestamp": "2020-05-25T23:23:54-0400", "log_lvl": "INFO", "log_msg": "3"}
#> 3
#> {"timestamp": "2020-05-25T23:23:54-0400", "log_lvl": "INFO", "log_msg": "4"}
#> 4
#> {"timestamp": "2020-05-25T23:23:54-0400", "log_lvl": "ERROR", "log_msg": "5"}
#> {"timestamp": "2020-05-25T23:23:54-0400", "log_lvl": "ERROR", "log_msg": "6"}
#> [[1]]
#> [1] 3
#> 
#> [[2]]
#> [1] 4
#> 
#> [[3]]
#> [1] NA
#> 
#> [[4]]
#> [1] NA

^{Created on 2020-05-25 by the reprex package (v0.3.0)}

---

To be clear, in both examples above, I'd expect the INFO messages to print since that's part of the "normal" flow, but not the ERROR messages. Below is the output if I don't use the loggit library:

purrr::map(3:6, purrr::safely(noisy_fn))
#> 3
#> 4
#> [[1]]
#> [[1]]$result
#> [1] 3
#> 
#> [[1]]$error
#> NULL
#> 
#> 
#> [[2]]
#> [[2]]$result
#> [1] 4
#> 
#> [[2]]$error
#> NULL
#> 
#> 
#> [[3]]
#> [[3]]$result
#> NULL
#> 
#> [[3]]$error
#> <simpleError in .f(...): 5>
#> 
#> 
#> [[4]]
#> [[4]]$result
#> NULL
#> 
#> [[4]]$error
#> <simpleError in .f(...): 6>
purrr::map(3:6, purrr::possibly(noisy_fn, otherwise = NA))
#> 3
#> 4
#> [[1]]
#> [1] 3
#> 
#> [[2]]
#> [1] 4
#> 
#> [[3]]
#> [1] NA
#> 
#> [[4]]
#> [1] NA

^{Created on 2020-05-25 by the reprex package (v0.3.0)}

[ryapric]

Man seeing that reprex footer is so cool! I never get the chance to use it!

It looks to me that you need to add echo = FALSE to the loggit::<message()|stop()> calls (whichever you want to suppress). I'm able to replicate your second output as follows:

library(loggit)
#> 
#> Attaching package: 'loggit'
#> The following objects are masked from 'package:base':
#> 
#>     message, stop, warning

noisy_fn <- function(x) {
  if (x < 5) {message(x, echo = FALSE)}
  if (x >= 5) {base::stop(x, echo = FALSE)}
  x
}

purrr::map(3:6, purrr::safely(noisy_fn))
#> 3
#> 4
#> [[1]]
#> [[1]]$result
#> [1] 3
#> 
#> [[1]]$error
#> NULL
#> 
#> 
#> [[2]]
#> [[2]]$result
#> [1] 4
#> 
#> [[2]]$error
#> NULL
#> 
#> 
#> [[3]]
#> [[3]]$result
#> NULL
#> 
#> [[3]]$error
#> <simpleError in .f(...): 5FALSE>
#> 
#> 
#> [[4]]
#> [[4]]$result
#> NULL
#> 
#> [[4]]$error
#> <simpleError in .f(...): 6FALSE>

purrr::map(3:6, purrr::possibly(noisy_fn, otherwise = NA))
#> 3
#> 4
#> [[1]]
#> [1] 3
#> 
#> [[2]]
#> [1] 4
#> 
#> [[3]]
#> [1] NA
#> 
#> [[4]]
#> [1] NA

^{Created on 2020-05-25 by the reprex package (v0.3.0)}

Is that what you were looking for?

[brianwdavis]

This is an easy fix for functions I control, like the noisy_fn in the example. But external functions that you're trying to quiet with the adverbs that won't work.

Also this only changes the printing to the screen, it's still showing up in the logs.

library(loggit)
#> Warning: package 'loggit' was built under R version 3.6.2
#> 
#> Attaching package: 'loggit'
#> The following objects are masked from 'package:base':
#> 
#>     message, stop, warning
noisy_fn <- function(x) {
  if (x < 5) {message(x, echo = F)}
  if (x >= 5) {stop(x, echo = F)}
  x
}

purrr::map(3:6, purrr::safely(noisy_fn))
#> 3
#> 4
#> [[1]]
#> [[1]]$result
#> [1] 3
#> 
#> [[1]]$error
#> NULL
#> 
#> 
#> [[2]]
#> [[2]]$result
#> [1] 4
#> 
#> [[2]]$error
#> NULL
#> 
#> 
#> [[3]]
#> [[3]]$result
#> NULL
#> 
#> [[3]]$error
#> <simpleError in stop(x, echo = F): 5>
#> 
#> 
#> [[4]]
#> [[4]]$result
#> NULL
#> 
#> [[4]]$error
#> <simpleError in stop(x, echo = F): 6>
purrr::map(3:6, purrr::possibly(noisy_fn, otherwise = NA))
#> 3
#> 4
#> [[1]]
#> [1] 3
#> 
#> [[2]]
#> [1] 4
#> 
#> [[3]]
#> [1] NA
#> 
#> [[4]]
#> [1] NA

read_logs()
#>                  timestamp log_lvl log_msg
#> 1 2020-05-26T09:46:41-0400    INFO       3
#> 2 2020-05-26T09:46:41-0400    INFO       4
#> 3 2020-05-26T09:46:41-0400   ERROR       5
#> 4 2020-05-26T09:46:41-0400   ERROR       6
#> 5 2020-05-26T09:46:41-0400    INFO       3
#> 6 2020-05-26T09:46:41-0400    INFO       4
#> 7 2020-05-26T09:46:41-0400   ERROR       5
#> 8 2020-05-26T09:46:41-0400   ERROR       6

^{Created on 2020-05-26 by the reprex package (v0.3.0)}

The more I think about this the more I think it might be an intractable problem, because you're writing to the log at the time the message happens, not after it's returned to its parent.

[ryapric]

Hmm, maybe I'm misunderstanding the same full scope of possibilities you're seeing. But, if it's the log you're also wanting to suppress, you can either make the stop() call be base::stop() directly, or pass the .loggit = FALSE option to loggit::stop() as well as echo = FALSE. The latter will prevent both the echo and the log write. But if you're using both options like that, it should be identical to base::stop() anyway.

[brianwdavis]

This and the other issue I filed (#14) are both related to this idea of controlling output from unknowable sources. This particular behavior (errors showing up even though I used purrr::safely or purrr::quietly) will only be observed when it's a function where I've written the call to message or stop myself, so it's really not that important (because as you note, I could add echo = FALSE to keep it from showing up).