daroczig / daroczig/logger

FR: appender_immediate?

Open
#229 0 comments 1 reaction 0 assignees View on GitHub
bug
Dominant language
HTML
Stars
323
Forks
46
Avg merge
1d 21h
Merged PRs (30d)
1

Description

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:

```r
### 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 :-)

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.