Logging and controlling stdout

[lorenzwalthert]

I am currently experimenting with using drake and logging, in particular futile.logger. I'd like to only see built targets in the console, and direct (most if not) all other output to some logger file. I see that drake::make() has an argument verbose but I don't see how I could use this argument to direct the output to some other stdout. Would you @wlandau be interested in supporting this in drake?

[wlandau]

The verbose argument does not cover redirection. If you set verbose = 1, you will only see built targets (or "All targets are already up to date"). The console output is displayed through message(), so a message sink() or capture.output(make(), type = "message") should help.

[wlandau]

By the way, drake has its own kind of log.

drake_cache_log()
drake_cache_log_file()
make(cache_log_file = TRUE)

This log is a flat file with the fingerprints of the targets. If you track it with version control, you can see which targets change over time.

[lorenzwalthert]

Ok, thanks. I was more looking for a way to write custom log messages to a file, i.e. as checks when I run my plan. With futile.logger, I can do that so I get a log like this, sent to a stdout of choice:

INFO [2018-05-30 17:30:27] Started drake::make() --------------------
INFO [2018-05-30 17:30:29] The following 4 values from variable x will be rounded during the conversion to integer:  1.85914187  0.01774519 -1.79239280  0.15442744
INFO [2018-05-30 17:30:30] Completed drake::make() --------------------

But all output that is not created with a logger goes to the stdout. I think for large projects it would be desirable to have a redirection meachanism, so you can direct all non-logger output to the logger file, although it's not really a must-have I guess.

[wlandau]

You know what, this feature should actually be fairly easy and fairly useful. Regular console output via message() has problems when we use parallel computing (ref: futureverse/future#171 (comment)) and redirecting to a file would solve them for drake.

[krlmlr]

I remember an issue about recording all output as part of processing, so that it can be replayed later. Is this compatible with redirecting to a file?

[wlandau]

Kirill, are you thinking of #212? That would be the more serious type of log that you can inspect with diagnose(). I think the informal console messages that Lorentz is talking about are different:

make(my_plan)
#> target large
#> target small
#> ...

I guess you could just poll progress() or use diagnose() + purrr, but I think it is also nice to have something lighter.

[wlandau]

Implemented in #401 with make(console = "log.txt") and drake_config(console = "log.txt"). Will merge soon.

The messages redirect correctly for make(), but it may take some time be sure the output of drake's many utility functions gets redirected as well.

If you want to suppress crayon's color coding characters, you will need to call options(crayon.enabled = FALSE) in your session and also make(prework = "options(crayon.enabled = FALSE)") if you are using parallel computing.

[wlandau]

Merged and fixed.

[wlandau]

I'm actually starting to have second thoughts about capturing messages. Reasons:

1. A more common request is the ability to use progress bars within targets, which cannot happen if we continue to capture messages. Examples:
   • https://stackoverflow.com/questions/59273524/progress-bar-within-drake-functions
   • https://community.rstudio.com/t/including-a-progress-bar-in-a-drake-plan-step/42516
2. The console_log_file (soon to be deprecated and renamed log_make) is super busy now. Those messages are difficult to parse out, making it less ideal for Option to display stderr output in real time #588.

[HenrikBengtsson]

The future package/framework captures all conditions and relays them in order. However, conditions of class immediateCondition are special - they are let through/relayed as soon as possible (meaning also out of order in parallel processing). The progressr package signals progression conditions that also inherit the above class. Thus, progressr updates work also in parallel.

Other types of updates can/could use this too. For instance, I've proposed to futile.logger to output via special message conditions.

I haven't tried, but I suspect progressr signaling should work with drake using a future backend.

[wlandau]

Thanks for the ideas, Henrik. It is nice to know about immediate relaying in progressr and future. In future specifically, is there anything special I need to do to ensure immediate relaying? In the example below, the two messages appear together after a 2-second delay.

library(future)
plan(multisession)
f <- function() {
  message("first")
  Sys.sleep(2)
  message("second")
}
value(future(f()))
#> first
#> second

Session info

devtools::session_info()
#> ─ Session info ───────────────────────────────────────────────────────────────
#>  setting  value                       
#>  version  R version 3.6.1 (2019-07-05)
#>  os       macOS Mojave 10.14.6        
#>  system   x86_64, darwin15.6.0        
#>  ui       X11                         
#>  language (EN)                        
#>  collate  en_US.UTF-8                 
#>  ctype    en_US.UTF-8                 
#>  tz       America/Indiana/Indianapolis
#>  date     2020-02-13                  
#> 
#> ─ Packages ───────────────────────────────────────────────────────────────────
#>  package     * version    date       lib source                              
#>  assertthat    0.2.1      2019-03-21 [1] CRAN (R 3.6.0)                      
#>  backports     1.1.5      2019-10-02 [1] CRAN (R 3.6.1)                      
#>  callr         3.4.1.9000 2020-02-10 [1] Github (r-lib/callr@fe18b1b)        
#>  cli           2.0.1      2020-01-08 [1] CRAN (R 3.6.0)                      
#>  codetools     0.2-16     2018-12-24 [1] CRAN (R 3.6.1)                      
#>  crayon        1.3.4      2017-09-16 [1] CRAN (R 3.6.0)                      
#>  desc          1.2.0      2019-08-19 [1] Github (r-lib/desc@c860e7b)         
#>  devtools      2.2.1      2019-09-24 [1] CRAN (R 3.6.0)                      
#>  digest        0.6.23.2   2020-01-03 [1] Github (eddelbuettel/digest@199be2e)
#>  ellipsis      0.3.0      2019-09-20 [1] CRAN (R 3.6.0)                      
#>  evaluate      0.14       2019-05-28 [1] CRAN (R 3.6.0)                      
#>  fansi         0.4.1      2020-01-08 [1] CRAN (R 3.6.0)                      
#>  fs            1.3.1      2019-05-06 [1] CRAN (R 3.6.0)                      
#>  future      * 1.16.0     2020-01-16 [1] CRAN (R 3.6.0)                      
#>  globals       0.12.5     2019-12-07 [1] CRAN (R 3.6.0)                      
#>  glue          1.3.1      2019-03-12 [1] CRAN (R 3.6.0)                      
#>  highr         0.8        2019-03-20 [1] CRAN (R 3.6.0)                      
#>  htmltools     0.4.0      2019-10-04 [1] CRAN (R 3.6.0)                      
#>  knitr         1.28       2020-02-06 [1] CRAN (R 3.6.0)                      
#>  listenv       0.8.0      2019-12-05 [1] CRAN (R 3.6.0)                      
#>  magrittr      1.5        2014-11-22 [1] CRAN (R 3.6.0)                      
#>  memoise       1.1.0      2017-04-21 [1] CRAN (R 3.6.0)                      
#>  pkgbuild      1.0.6      2019-10-09 [1] CRAN (R 3.6.0)                      
#>  pkgload       1.0.2      2018-10-29 [1] CRAN (R 3.6.0)                      
#>  prettyunits   1.1.1      2020-01-24 [1] CRAN (R 3.6.1)                      
#>  processx      3.4.2.9000 2020-02-10 [1] Github (r-lib/processx@0e22d55)     
#>  ps            1.3.0      2018-12-21 [1] CRAN (R 3.6.0)                      
#>  R6            2.4.1      2019-11-12 [1] CRAN (R 3.6.1)                      
#>  Rcpp          1.0.3      2019-11-08 [1] CRAN (R 3.6.0)                      
#>  remotes       2.1.0      2019-06-24 [1] CRAN (R 3.6.0)                      
#>  rlang         0.4.4      2020-01-28 [1] CRAN (R 3.6.0)                      
#>  rmarkdown     2.1        2020-01-20 [1] CRAN (R 3.6.1)                      
#>  rprojroot     1.3-2      2018-01-03 [1] CRAN (R 3.6.0)                      
#>  sessioninfo   1.1.1      2018-11-05 [1] CRAN (R 3.6.0)                      
#>  stringi       1.4.5      2020-01-11 [1] CRAN (R 3.6.0)                      
#>  stringr       1.4.0      2019-02-10 [1] CRAN (R 3.6.0)                      
#>  testthat      2.3.1      2019-12-01 [1] CRAN (R 3.6.0)                      
#>  usethis       1.5.1.9000 2019-08-12 [1] Github (r-lib/usethis@b241420)      
#>  withr         2.1.2      2018-03-15 [1] CRAN (R 3.6.0)                      
#>  xfun          0.12       2020-01-13 [1] CRAN (R 3.6.0)                      
#>  yaml          2.2.1      2020-02-01 [1] CRAN (R 3.6.1)                      
#> 
#> [1] /Library/Frameworks/R.framework/Versions/3.6/Resources/library

[wlandau]

For the purposes of this issue, I think we can skip invokeRestarts() here and post-hoc messages depending on the kind of parallel backend the user selects.

[HenrikBengtsson]

is there anything special I need to do to ensure immediate relaying?

Yes, it is only conditions that inherits from immediateCondition that will be relayed asap. All other conditions stay with worker and are only relayed when the future is resolved and value() is called on the future.

Conditions of kind immediateCondition are also special in the sense that they are allowed to be relayed out of order, i.e. if you've got multiple futures they will be relayed in the order as futures are resolved. You typically don't want this behavior of regular messages where user expects them to come in the order as produced and also not interweave with other conditions. The design is that everything will work the same way regardless of how and where things are resolved. This is why the are "flushed" in bulk together (when value() is called).

I only mentioned this to trigger your interest - I think there's some potential in the above condition model also outside of progress updates.

[wlandau]

Thanks, I took another look at immediateMessage() and signalConditions(), and I think I understand a little more about condition mechanism. In regular futures and drake's future backend, I think we can use immediateMessage().

library(future)
plan(multisession)

# From https://github.com/HenrikBengtsson/future/blob/cadebbba3a6905721988fb29c9eb14984deea7c3/tests/immediateCondition.R#L7-L14
immediateMessage <- function(..., domain = NULL, appendLF = TRUE) {
  msg <- .makeMessage(..., domain = domain, appendLF = appendLF)
  call <- sys.call()
  m <- simpleMessage(msg, call)
  class(m) <- c(class(m), "immediateCondition")
  message(m)
  invisible(m)
}

f <- function() {
  immediateMessage("first")
  Sys.sleep(2)
  immediateMessage("second")
}

value(future(f()))

[wlandau]

In fact, it's even easier than immediateMessage() since drake already intercepts messages and warnings. We just need to append the "immediateCondition" class. Fixed in a4baab9. Thanks, Henrik!

drake/R/local_build.R

Lines 179 to 180 in a4baab9

	warning(as_immediate_condition(w))
	invokeRestart("muffleWarning")

drake/R/local_build.R

Lines 186 to 187 in a4baab9

	message(as_immediate_condition(m))
	invokeRestart("muffleMessage")

drake/R/local_build.R

Lines 205 to 208 in a4baab9

	as_immediate_condition <- function(x) {
	class(x) <- c(class(x), "immediateCondition")
	x
	}