Option to redirect informal console messages to a file

[wlandau]

Summary

If verbose is > 0, make() outputs progress message()s to the console.

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

In this PR, make(console = "log.txt") appends these messages to the file "log.txt". That way, users can just inspect a log file instead of polling progress(), and we avoid the issues described in futureverse/future#171 (comment).

Note: if you want to suppress color coding characters, you will need to call options(crayon.enabled = FALSE) in your session and possibly make(prework = "options(crayon.enabled = FALSE)").

cc @lorenzwalthert

Related GitHub issues

• Ref: Logging and controlling stdout #400

Checklist

• I have read drake's code of conduct, and I agree to follow its rules.
• I have read the guidelines for contributing.
• I have listed any substantial changes in the development news.
• I have added testthat unit tests to tests/testthat to confirm that any new features or functionality work correctly.
• I have tested this pull request locally with devtools::check()
• This pull request is ready for review.
• I think this pull request is ready to merge.

[lorenzwalthert]

I like your paste @wlandau 👍 😊. So is that approach catching communication issued via message() only or also other output such as output issued with cat()?

[codecov-io]

Codecov Report

Merging #401 into master will not change coverage.
The diff coverage is 100%.

@@          Coverage Diff          @@
##           master   #401   +/-   ##
=====================================
  Coverage     100%   100%           
=====================================
  Files          65     65           
  Lines        5170   5191   +21     
=====================================
+ Hits         5170   5191   +21

Impacted Files	Coverage Δ
R/graph.R	100% <100%> (ø)	⬆️
R/cache.R	100% <100%> (ø)	⬆️
R/console.R	100% <100%> (ø)	⬆️
R/handlers.R	100% <100%> (ø)	⬆️
R/config.R	100% <100%> (ø)	⬆️
R/make.R	100% <100%> (ø)	⬆️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update ecbaa87...01709e4. Read the comment docs.

[wlandau]

@lorenzwalthert, I am not sure I know what you mean. In make(console = NULL) (default), drake uses message(msg) to tell the user about the targets, imports, and checks it goes through (depending on the verbose argument). In make(console = "log.txt"), drake calls write(msg, "log.txt") instead. (See write_to_console().) Overall, drake restricts itself to message(), warning() and stop() to print things. It previously used cat(), but I switched all those calls to message() in late 2017.

[wlandau]

drake also captures messages, warnings, and errors generated by individual targets (see run_command()). These side effects are stored with the rest of the metadata, and you can retrieve them later with diagnose(). drake does not currently capture regular stdout() outputs from print(), cat(), etc.

[lorenzwalthert]

Thanks. Maybe I was not specific enough, so here's the reprex:

library(drake)
futile.logger::flog.appender(futile.logger::appender.file("futile-logger"), 
  name = "default")
#> NULL
options(crayon.enabled = FALSE)
just_some_random_communication <- function(a) {
  cat("cat")
  print("print")
  warning("warning")
  message("message")
  as.integer("L")
  futile.logger::flog.error("This is an error", name = "default")
}

plan <- drake_plan(random = just_some_random_communication(4))
clean()
unlink(c("drake-logger", "futile-logger"))
make(plan, seed = 200, console = "drake-logger")
#> cat[1] "print"
#> Warning in just_some_random_communication(4): warning
#> message
#> Warning in just_some_random_communication(4): NAs introduced by coercion
#> Warning: target random warnings:
#>   warning
#>   NAs introduced by coercion
#> Target random messages:
#>   message
readLines("drake-logger")
#> [1] "target random"
readLines("futile-logger")
#> [1] "ERROR [2018-05-31 23:26:27] This is an error"

I think in principle it would be nice to have the warnings and messages created inside the functions inside the drake plan sent to the logging file too instead of the console. But as I said, it does not seem to be a super pressing issue.

I tried to play around a bit with sink() but I could not figure it out. And capture.output() seems too radical.

[wlandau]

I suppose we could write other messages to the log too, plus warnings and errors. For what it's worth, the log does tell you if a target failed.

[wlandau]

Update: from 2b0fff2, the log file should now catch errors, warnings, and messages from running the user-supplied commands to build targets. Regular output from cat() is not yet captured. Also, non-target warnings and errors from drake itself are not captured in the log file.

Also, if you specify a file with make(console = "log.txt"), crayon characters are suppressed.

[wlandau]

And from 7f603e7, stdout output from cat() etc. is captured too.

library(drake)
futile.logger::flog.appender(futile.logger::appender.file("futile-logger"), 
  name = "default")
#> NULL
options(crayon.enabled = FALSE)
just_some_random_communication <- function(a) {
  cat("cat")
  print("print")
  warning("warning")
  message("message")
  as.integer("L")
  futile.logger::flog.error("This is an error", name = "default")
}
plan <- drake_plan(random = just_some_random_communication(4))
clean()
unlink(c("drake-logger", "futile-logger"))
make(plan, seed = 200, console = "drake-logger")
#> Warning in just_some_random_communication(4): warning
#> message
#> Warning in just_some_random_communication(4): NAs introduced by coercion
#> Warning: target random warnings:
#>   warning
#>   NAs introduced by coercion
cat(readLines("drake-logger"), sep = "\n")
#> target random
#> Warning: target random warnings:
#>   warning
#>   NAs introduced by coercion
#> Target random messages:
#>   message
#> Target random console output:
#>   cat[1] "print"
cat(readLines("futile-logger"), sep = "\n")
#> ERROR [2018-06-01 12:49:27] This is an error

[wlandau]

On second thought, I do not think it is a good idea to capture stdout from the user's calls to print() or cat(). People like to print progress and informally time things with print() statements, and I do not think drake should interfere with this. Reverted in 8817464.

[lorenzwalthert]

Thanks so much @wlandau 😊. I just tried quickly and it works as expected. I can even use the same log file for futile.logger and the terminal output. This is exactly what I wanted. 👍 .

Obviously I can't foresee all use-cases, but it seems to make sense to reserve print() and cat() to be always sent to the console, e.g. for debugging. One could write a wrapper with capture.output() or similar around functions that use cat() and print() in an unexpected manner to keep a clean console.

[wlandau]

Update: in 1a77aae, I changed the console argument to console_log_file. Much clearer this way.