FR: appender_immediate?

[r2evans]

Up front, I'm willing to write this and submit a PR, I'm just wondering if you're amenable.

Background: getting messages out of a future::multisession cluster works, but messages only appear when the task is relatively complete. I can get them out of each task by changing the appender to appender_stdout (apparently console/stderr don't work), though delayed.

Code shown in the movies:

### BOTH -------------------------------------------------------------
library(logger)
library(future)
plan(multisession, workers=2)

### FIRST ------------------------------------------------------------
expr1 <- function() {
  log_formatter(formatter_json)
  log_layout(layout_json_parser(fields = c("time", "level", "pid")))
  log_appender(appender_stdout)
}

log_info("start")
x %<-% { expr1(); log_info("in x"); Sys.sleep(2); log_info("x ", Sys.getpid()); Sys.sleep(2); 3.14 }
y %<-% { expr1(); log_info("in y"); Sys.sleep(2); log_info("y ", Sys.getpid()); Sys.sleep(2); 2.71 }
z %<-% { expr1(); log_info("in z"); Sys.sleep(2); log_info("y ", Sys.getpid()); Sys.sleep(2); 1.62 }
log_info("all three submitted")
log_info("x+y", x+y)
log_info("z", z)

### SECOND -----------------------------------------------------------
# adapted from https://github.com/futureverse/progressr/issues/176
appender_immediate <- function(lines) {
  msg <- .makeMessage(paste(format(Sys.time()), lines), domain = NULL, appendLF = TRUE)
  call <- sys.call()
  cond <- simpleMessage(msg, call)
  class(cond) <- c(class(cond), "immediateCondition")
  message(cond)
  cond
}
attr(appender_immediate, "generator") <- quote(appender_immediate())
expr2 <- function() {
  log_formatter(formatter_json)
  log_layout(layout_json_parser(fields = c("time", "level", "pid")))
  log_appender(appender_immediate)
}

log_info("start")
x %<-% { expr2(); log_info("in x"); Sys.sleep(2); log_info("x ", Sys.getpid()); Sys.sleep(2); 3.14 }
y %<-% { expr2(); log_info("in y"); Sys.sleep(2); log_info("y ", Sys.getpid()); Sys.sleep(2); 2.71 }
z %<-% { expr2(); log_info("in z"); Sys.sleep(2); log_info("y ", Sys.getpid()); Sys.sleep(2); 1.62 }
log_info("all three submitted")
log_info("x+y", x+y)
log_info("z", z)

When I source the first block using the normal appender_stdout in the workers, you can see that their messages are both delayed and easily out of order. (This is not the fault of logger.)

logger_immediate_1.mp4

When I restart the R session and use appender_immediate, then it becomes much more responsive.

logger_immediate_2.mp4

Clearly the appender_immediate needs to be cleaned up so that it will deal with different formatters. (Yes, I realize I'm doubling the time displayed in the logs ... I just realized that as I'm typing.) The code above is a starting-point, quickly adapting Henrik's immediateMessage suggestion from futureverse/progressr#176.

Side note: the use of future's "immediateMessage" class works with multisession but does not work with mirai_multisession. That version of it has the advantage of not-blocking the z %<-% assignment above, instead just queueing it for eventual execution. There are likely other advantages of it over vanilla multisession. I've asked Henrik if there is the ability to add the immediacy to the future.mirai package here futureverse/future.mirai#17. Getting that implemented won't change the need or execution of this FR, it'll just make it usable in another environment clustering environment :-)