Option to display stderr output in real time

[ashiklom]

(Sorry if this has already been addressed. I looked for an answer in the issues and documentation, but couldn't find anything.)

For long-running targets, it would be nice to be able to look for diagnostic messages/progress bars in the stderr stream in real time. Currently, drake::make withholds all stderr output until a target is built and then prints it out all at once, which is useful for parallel workflows, but not ideal for sequential, interactive workflows.

For example:

library(drake)
stopifnot(requireNamespace("progress"))

drake::clean(destroy = TRUE)

f1 <- function() {
  message("Running...")
  Sys.sleep(2)
  message("Still going...")
  Sys.sleep(2)
  message("Done")
  ":)"
}

f2 <- function() {
  n <- 3
  pb <- progress::progress_bar$new(total = 3)
  message("Starting...")
  for (i in seq_len(n)) {
    pb$tick()
    Sys.sleep(1)
  }
  ":)"
}

plan <- drake_plan(
  a = f1(),
  b = f2()
)
conf <- drake_config(plan)
make(plan, verbose = 4)

It would be nice to see the Going... and Still going... messages as target a is being built, and especially nice to see the progress bar as target b is being built.

It's worth noting that print statements and base R's txtProgressBar both work as expected because they use stdout. Only stderr is being redirected.

[wlandau]

I think the most relevant threads are #212, #400, #401, futureverse/future#25, and futureverse/future#171. As you alluded to, some modes of parallel execution interfere with stderr, so drake takes special measures to capture it and print it later.

It is possible to still print messages in real time. The quickest fix is to remove the call to capture.output(type = "message") in with_handling().

drake/R/run.R

Lines 19 to 36 in 69ec117

	with_handling <- function(target, meta, config) {
	warnings <- messages <- NULL
	capture.output(
	meta$time_command <- system.time(
	withCallingHandlers(
	value <- with_call_stack(target = target, config = config),
	warning = function(w) {
	warnings <<- c(warnings, w$message)
	},
	message = function(m) {
	msg <- gsub(pattern = "\n$", replacement = "", x = m$message)
	messages <<- c(messages, msg)
	}
	),
	gcFirst = FALSE # for performance
	),
	type = "message"
	)

However, this causes messages to print twice.

#> make(plan, targets = "a")
target a
Running...
Still going...
Done
Target a messages:
  Running...
  Still going...
  Done

@lorenzwalthert, what do you think? Are real-time messages worth messy duplication?

[ashiklom]

Personally, I would be perfectly happy with an additional logical argument (capture_message = TRUE by default) that comes with the explicit caveat that, if FALSE, messages will print twice (and maybe even with another caveat that it only works for sequential execution). Or, more more directly (and flexibly), perhaps just expose the type argument to capture.output (set to "message" by default)? That would accommodate my use case of wanting messages to print in real time, as well as the opposite use case of suppressing not just stderr but also stdout (e.g. print).

Just spitballing here, but an idea for down the road would be to allow this to be set on a target-by-target basis. I could definitely envision cases where I want the output of some steps to be suppressed and others to be verbose.

[wlandau]

Good ideas. In the case of drake, however, I am resistant to adding additional customization for a low-ish priority feature like this. One of my major development goals for 2019 is to simplify the internals. When it comes to something cosmetic like printing, I would rather aim for a compromise that mostly works everywhere and meets the most important needs.

[wlandau]

I think I found a compromise. In bc06e8c, stderr is still delayed in the console, but it prints to console_log_file in real time.

library(drake)
drake::clean(destroy = TRUE)

f1 <- function() {
  message("Running...")
  warning("warning 1")
  Sys.sleep(5)
  message("Still going...")
  warning("warning 2")
  Sys.sleep(5)
  message("Done")
  warning("warning 3")
  stop(":)")
}

plan <- drake_plan(a = f1())

make(plan, console_log_file = "log.txt")
#> target a
#> Warning: target a warnings:
#>   warning 1
#>   warning 2
#>   warning 3
#> Target a messages:
#>   Running...
#>   Still going...
#>   Done
#> fail a
#> Error: Target `a` failed. Call `diagnose(a)` for details. Error message:
#>   :)
#> In addition: Warning messages:
#> 1: In f1() : warning 1
#> 2: In f1() : warning 2
#> 3: In f1() : warning 3

cat(readLines("log.txt"), sep = "\n")
#> target a
#> Running...
#> Warning: warning 1
#> Still going...
#> Warning: warning 2
#> Done
#> Warning: warning 3
#> fail a
#> Error: Target `a` failed. Call `diagnose(a)` for details. Error message:
#>   :)

[ashiklom]

This looks great, thanks for the quick fix!

For the record, with the new fix, to have the messages print to the console in real time, I can run this as: make(plan, console_log_file = stdout()).

[wlandau]

Glad this works for you. And thanks for the tip about stdout(). I will add a note in the documentation.

Some final remarks: due to tidyverse/reprex#118 and related issues, reprexes print messages twice. I believe this was still an issue even before bc06e8c. Using withr::with_message_sink() instead of capture.output(type = "message") does remove the duplication, but then users cannot define their own message sinks in their commands. (You can nest calls to capture.output(type = "message"), but not nested calls to withr::with_message_sink()). So for now, I plan to leave the existing solution as is.

library(drake)
knitr::opts_chunk$set(message = FALSE)
drake::clean(destroy = TRUE)

f1 <- function() {
  message("Running...")
  warning("warning 1")
  Sys.sleep(5)
  message("Still going...")
  warning("warning 2")
  Sys.sleep(5)
  message("Done")
  warning("warning 3")
  stop(":)")
}

plan <- drake_plan(a = f1())
make(plan, console_log_file = "log.txt")
#> target a
#> Running...
#> Warning in f1(): warning 1
#> Still going...
#> Warning in f1(): warning 2
#> Done
#> Warning in f1(): warning 3
#> Warning: target a warnings:
#>   warning 1
#>   warning 2
#>   warning 3
#> Target a messages:
#>   Running...
#>   Still going...
#>   Done
#> fail a
#> Error: Target `a` failed. Call `diagnose(a)` for details. Error message:
#>   :)
cat(readLines("log.txt"), sep = "\n")
#> target a
#> Running...
#> Warning: warning 1
#> Still going...
#> Warning: warning 2
#> Done
#> Warning: warning 3
#> fail a
#> Error: Target `a` failed. Call `diagnose(a)` for details. Error message:
#>   :)

Created on 2018-11-28 by the reprex package (v0.2.1)

[lorenzwalthert]

Sometimes you just wait and other people solve things so your (uninformed) opinion is not needed :-)

[lorenzwalthert]

futureverse/future#25 is now resolved. Does this affect this issue?

[wlandau]

That's good news. I will let you know once I have a chance to try it.

[wlandau]

drake still captures warnings and messages independently of future, so I did not expect anything to change there. What I did want to check was the handling of stdout. As it turns out, future still does not relay stdout. So nothing has changed on drake's side.