appender_file does not find the log file when called from within a function

[rwarnung]

appender_file does not find the log file when called from within a function

Reproducible example The following code prepares logging to the console and logging to a file.

.start_logger = function(){
     unloadNamespace('logger')
     library('logger')
     my_logfile <- tempfile()
     ### file
     logger::log_threshold('DEBUG', index = 1)
     logger::log_appender(appender_file(my_logfile), index = 1)
     
     ### console ----
     log_threshold('INFO', index = 2)
     logger::log_appender(appender_console, index = 2)
     
     logger::log_with_separator("start calculation")
     logger::log_tictoc('main', namespace = 'main')
     log_separator()
 return(my_logfile)
 }

I want to call that function with

my_logfile = .start_logger()

I face 2 interesting issues:

1. If I run the code in a fresh session outside of a function, then the file where I want to log to can not be found. If I run the code inside of a function, I get the following error from the call of logger::log_with_separator("start calculation")

Error in force(file) : object 'my_logfile' not found

If I run the code without the function, then the logging works:

unloadNamespace('logger')
library('logger')
my_logfile <- tempfile()

logger::log_threshold('DEBUG', index = 1)
logger::log_appender(appender_file(my_logfile), index = 1)

### console ----
log_threshold('INFO', index = 2)
logger::log_appender(appender_console, index = 2)

logger::log_with_separator("start calculation")
logger::log_tictoc('main', namespace = 'main')
log_separator()

2. If I have run the code outside of a function successfully once, then also the version with starting the logger inside of a function works.

I have discussed this here on stackoverflow.

The solutions are:

1. Define my_logfile in the global environment via my_logfile <- tempfile()
2. As proposed by user MrFlick answering my question on SO: avoid lazy evalution using do.call: logger::log_appender(do.call("appender_file", list(my_logfile)), index = 1)

**

I am wondering why I need the stated work around for the fileappender. Is this a known bug or am I doing something wrong? Thank you!

**

``` r sessionInfo()

R version 4.1.2 (2021-11-01) Platform: x86_64-w64-mingw32/x64 (64-bit) Running under: Windows Server x64 (build 14393)

Matrix products: default

locale: [1] LC_COLLATE=English_United States.1252 LC_CTYPE=English_United States.1252 LC_MONETARY=English_United States.1252 [4] LC_NUMERIC=C
LC_TIME=English_United States.1252

attached base packages: [1] stats graphics grDevices utils
datasets methods base

other attached packages: [1] logger_0.3.0

loaded via a namespace (and not attached): [1] compiler_4.1.2 tools_4.1.2 glue_1.7.0

</details>

[daroczig]

Thanks for the report -- it was a scoping issue in some of the helper functions. the above commit should fix it, but I'd appreciate if you can check.

[rwarnung]

@daroczig Hi, thank you for looking into that quickly. I reinstalled from the dev version from github using emotes::install_github('daroczig/logger'). However, the error ist still the same ... Is there any further information that I can provide?

[daroczig]

Hm, there was an update in the logger call as well that I removed last minute .. looking into it, thanks for reporting back.

[hadley]

This appears to be fixed with dev logger:

library('logger')

start_logger <- function() {
  ### file
  my_logfile <- tempfile()
  log_threshold('DEBUG', index = 1)
  log_appender(appender_file(my_logfile), index = 1)
  
  ### console ----
  log_threshold('INFO', index = 2)
  log_appender(appender_stdout, index = 2)
  
  log_with_separator("start calculation")
  log_tictoc('main', namespace = 'main')
  log_separator()
  
  my_logfile
}
path <- start_logger()
#> INFO [2024-08-08 15:55:06] 
#> INFO [2024-08-08 15:55:06] 
#> INFO [2024-08-08 15:55:06] =====================================================
#> INFO [2024-08-08 15:55:06] = start calculation                                 =
#> INFO [2024-08-08 15:55:06] 
#> INFO [2024-08-08 15:55:06] =====================================================
#> INFO [2024-08-08 15:55:06] global timer tic 0 secs -- main
#> INFO [2024-08-08 15:55:06] 
#> INFO [2024-08-08 15:55:06] =====================================================
writeLines(readLines(path))
#> INFO [2024-08-08 15:55:06] =====================================================
#> INFO [2024-08-08 15:55:06] = start calculation                                 =
#> INFO [2024-08-08 15:55:06] =====================================================
#> INFO [2024-08-08 15:55:06] global timer tic 0 secs -- main
#> INFO [2024-08-08 15:55:06] =====================================================

<sup>Created on 2024-08-08 with reprex v2.1.0</sup>

[daroczig]

Thanks a ton, @hadley :bow: