parallel processing and logger

[xtimbeau]

Hi, do you have any recommandation for logging parallel processing ? I can't make your logger work in parallel which is a pity because it's a good logging solution ! Ideally, it would work with future (so with furrr) and log in the same file with thread information added to the timestamp.

[daroczig]

Can you please elaborate on "I can't make your logger work in parallel"? I have not run into any issues so far while using logger eg in mclapply on a daily basis.

[xtimbeau]

I am using future and furrr so, the main parellel function is future_apply. I pass either the same logfile or a disctint logfile to processes, and I use log_info inside the function passed as an arg to future_map. There are lines in the log file, but empty.

here is an example. The log displays to the console. If you change plan to plan(sequential), then it works as expected.

library(logger)
library(furrr)

logfile <- "test.log"
file.create(logfile)
log_appender(appender_file(logfile))
plan(multiprocess)
future_map(1:8,
           ~{s <- stringr::str_c("hello ", future:::session_uuid()[[1]])
           log_info(s)})

[daroczig]

Sorry, but this is still not enough info to reproduce the problem, eg this works perfectly fine on my computer. Can you please post your devtools::session_info()?

[xtimbeau]

sure:

- Session info ------------------------------------------------------------------------------------------------------------------
 setting  value                       
 version  R version 4.0.3 (2020-10-10)
 os       Windows 10 x64              
 system   x86_64, mingw32             
 ui       RStudio                     
 language (EN)                        
 collate  French_France.1252          
 ctype    French_France.1252          
 tz       Europe/Paris                
 date     2020-11-02                  

- Packages ----------------------------------------------------------------------------------------------------------------------
 package     * version date       lib source                             
 assertthat    0.2.1   2019-03-21 [1] CRAN (R 4.0.3)                     
 backports     1.1.10  2020-09-15 [1] CRAN (R 4.0.3)                     
 callr         3.5.1   2020-10-13 [1] CRAN (R 4.0.3)                     
 cli           2.1.0   2020-10-12 [1] CRAN (R 4.0.3)                     
 clisymbols    1.2.0   2017-05-21 [1] CRAN (R 4.0.3)                     
 crayon        1.3.4   2017-09-16 [1] CRAN (R 4.0.3)                     
 desc          1.2.0   2018-05-01 [1] CRAN (R 4.0.3)                     
 devtools      2.3.2   2020-09-18 [1] CRAN (R 4.0.3)                     
 digest        0.6.27  2020-10-24 [1] CRAN (R 4.0.3)                     
 ellipsis      0.3.1   2020-05-15 [1] CRAN (R 4.0.3)                     
 fansi         0.4.1   2020-01-08 [1] CRAN (R 4.0.3)                     
 fs            1.5.0   2020-07-31 [1] CRAN (R 4.0.3)                     
 glue          1.4.2   2020-08-27 [1] CRAN (R 4.0.3)                     
 magrittr      1.5     2014-11-22 [1] CRAN (R 4.0.3)                     
 memoise       1.1.0   2017-04-21 [1] CRAN (R 4.0.3)                     
 memuse        4.1-0   2020-02-17 [1] CRAN (R 4.0.3)                     
 pkgbuild      1.1.0   2020-07-13 [1] CRAN (R 4.0.3)                     
 pkgload       1.1.0   2020-05-29 [1] CRAN (R 4.0.3)                     
 prettyunits   1.1.1   2020-01-24 [1] CRAN (R 4.0.3)                     
 processx      3.4.4   2020-09-03 [1] CRAN (R 4.0.3)                     
 prompt        1.0.0   2020-10-27 [1] Github (gaborcsardi/prompt@b332c42)
 ps            1.4.0   2020-10-07 [1] CRAN (R 4.0.3)                     
 R6            2.5.0   2020-10-28 [1] CRAN (R 4.0.3)                     
 remotes       2.2.0   2020-07-21 [1] CRAN (R 4.0.3)                     
 rlang         0.4.8   2020-10-08 [1] CRAN (R 4.0.3)                     
 rprojroot     1.3-2   2018-01-03 [1] CRAN (R 4.0.3)                     
 rstudioapi    0.11    2020-02-07 [1] CRAN (R 4.0.3)                     
 sessioninfo   1.1.1   2018-11-05 [1] CRAN (R 4.0.3)                     
 testthat      3.0.0   2020-10-31 [1] CRAN (R 4.0.3)                     
 usethis       1.6.3   2020-09-17 [1] CRAN (R 4.0.3)                     
 withr         2.3.0   2020-09-22 [1] CRAN (R 4.0.3)                     

[1] C:/Users/82261/Rlibs/4.0.3
[2] C:/Program Files/R/R-4.0.3/library

[daroczig]

Ah, I see -- on Windows and inside of RStudio, I think:

[ONE-TIME WARNING] Forked processing ('multicore') is disabled in future (>= 1.13.0) when running R from RStudio, because it is considered unstable. Because of this, plan("multicore") will fall back to plan("sequential"), and plan("multiprocess") will fall back to plan("multisession") - not plan("multicore") as in the past. For more details, how to control forked processing or not, and how to silence this warning in future R sessions, see ?future::supportsMulticore 

So future actually starts new processes and not setting up the logger there. Move your log_appender inside the code that is running in the subprocesses, or somehow make sure that the logger package's namespace is passed down to the child processes.

I hope this answers your question, so closing the ticket, but let me know if you see any issues with logger.

[xtimbeau]

thanks, I managed to make it work the way you suggest. I found a way to identify the process and to log it concurrently in the same logfile. May be that could be made inside the logger package ? would be a nice add-on. Best,

[daroczig]

identify the process and to log it concurrently in the same logfile

I think this has been available for a long time via configuring the layout function to log the pid as per https://github.com/daroczig/logger/blob/master/R/layouts.R#L14