logger icon indicating copy to clipboard operation
logger copied to clipboard

FR: appender_immediate?

Open r2evans opened this issue 11 months ago • 0 comments

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.)

https://github.com/user-attachments/assets/f5ceccf8-c981-4269-b69f-2724ab2eec78

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

https://github.com/user-attachments/assets/3046fab4-301a-4bfe-bf21-3c00ea511c99

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 https://github.com/futureverse/progressr/issues/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 https://github.com/futureverse/future.mirai/issues/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 :-)

r2evans avatar Jan 31 '25 17:01 r2evans