[help] Unable to use logger when branching

[philiporlando]

Help

• I understand and agree to https://books.ropensci.org/targets/help.html.

Description

I'm experiencing an issue with using the {logger} package in combination with a branching target. The issue does not occur if I remove the branching pattern and restart my session.

I have some utility functions defined in a standalone R script that look like this:

# R/log-utils.R
`%>%` <- magrittr::`%>%`

set_logger <- function(log_file, log_dir = "./log", overwrite = TRUE) {
  if (!fs::dir_exists(log_dir)) {
    fs::dir_create(log_dir)
  }
  name <- log_file %>%
    fs::path_file() %>%
    fs::path_ext_remove()
  log_file <- fs::path(log_dir, glue::glue("{name}.log"))
  if (overwrite & fs::file_exists(log_file)) {
    message("Overwriting existing log file...")
    fs::file_delete(log_file)
  }
  logger::log_threshold(logger::TRACE)
  logger::log_appender(logger::appender_tee(log_file))
  return(log_file %>% fs::path_abs() %>% invisible())
}

test_logger <- function(set_log, i) {
  logger::log_info("{Sys.time()} this is a log for branch {i}...")  
}

My main targets file looks like this:

#_targets.R

library(targets)

controller <- crew::crew_controller_local(
  workers = future::availableCores() - 1,
  seconds_idle = 3
)

# Set target options:
tar_option_set(
  packages = c("logger"),
  format = "qs",
  controller = controller,
  garbage_collection = TRUE,
  memory = "transient",
  iteration = "vector"
)

source("R/log-utils.R")

list(
  tar_target(
    set_log, {
      set_logger("_targets.log", overwrite = TRUE)
      TRUE
    }
  ),
  tar_target(
    test_log_directly, {
      set_log # Establish dependency
      logger::log_info("{Sys.time()} this is a single log!")
    }
  ),
  tar_target(
    branches,
    {
      1:10
    }
  ),
  tar_target(
    test_log_with_branching,
    test_logger(set_log, i=branches),
    pattern = map(branches)
  )
)

The above example runs without error, but no logs are actually being written to the ./log directory:

> targets::tar_make()
✔ skipped target branches
✔ skipped target set_log
▶ dispatched branch test_log_from_function_f01a3e41
▶ dispatched branch test_log_from_function_09380a2a
▶ dispatched branch test_log_from_function_793701ec
▶ dispatched branch test_log_from_function_64f4179f
▶ dispatched branch test_log_from_function_eeab6b1e
▶ dispatched branch test_log_from_function_e25d26ba
▶ dispatched branch test_log_from_function_42209826
▶ dispatched branch test_log_from_function_9e6cbe62
▶ dispatched branch test_log_from_function_aa995969
▶ dispatched branch test_log_from_function_29a2bc1e
▶ dispatched target test_log_directly
● completed branch test_log_from_function_f01a3e41 [0.021 seconds]
● completed branch test_log_from_function_793701ec [0.02 seconds]
● completed branch test_log_from_function_09380a2a [0.021 seconds]
● completed branch test_log_from_function_aa995969 [0.001 seconds]
● completed target test_log_directly [0.001 seconds]
● completed branch test_log_from_function_eeab6b1e [0.022 seconds]
● completed branch test_log_from_function_e25d26ba [0.019 seconds]
● completed branch test_log_from_function_9e6cbe62 [0.019 seconds]
● completed branch test_log_from_function_42209826 [0.015 seconds]
● completed branch test_log_from_function_64f4179f [0.018 seconds]
● completed branch test_log_from_function_29a2bc1e [0.014 seconds]
● completed pattern test_log_from_function
▶ completed pipeline [3.97 seconds]

Logger is working as expected if the pattern argument is removed. However, I had to call tar_destroy() and rstudioapi::restartSession() before running the below example. Otherwise, it seemed like it was stuck with the previous issue that I encountered when branching, and no logs would be written to disk...

#_targets.R

library(targets)

controller <- crew::crew_controller_local(
  workers = future::availableCores() - 1,
  seconds_idle = 3
)

# Set target options:
tar_option_set(
  packages = c("logger"),
  format = "qs",
  controller = controller,
  garbage_collection = TRUE,
  memory = "transient",
  iteration = "vector"
)

source("R/log-utils.R")

list(
  tar_target(
    set_log, {
      set_logger("_targets.log", overwrite = TRUE)
      TRUE
    }
  ),
  tar_target(
    test_log_directly, {
      set_log # Establish dependency
      logger::log_info("{Sys.time()} this is a single log!")
    }
  ),
  tar_target(
    test_log_without_branching,
    test_logger(set_log, i=1)
  )
)

> tar_make()
▶ dispatched target set_log
▶ dispatched target branches
● completed target set_log [0.047 seconds]
▶ dispatched target test_log_without_branching
● completed target branches [0.007 seconds]
▶ dispatched target test_log_directly
● completed target test_log_without_branching [0.002 seconds]
● completed target test_log_directly [0.002 seconds]
▶ completed pipeline [2.576 seconds]

Here is what the contents of my log file look like:

#./log/_targets.log
INFO [2024-01-03 22:22:40] 2024-01-03 22:22:40 this is a log for branch 1...
INFO [2024-01-03 22:22:40] 2024-01-03 22:22:40 this is a single log!

A complete reprex including an renv.lock file is available here.

Any troubleshooting support here is greatly appreciated. Please let me know if you have any questions or need me to help clarify. Thank you!

[wlandau]

This happens because the crew worker processes don't know about the settings you specified using logger::log_appender(). If you call set_logger(your_log_file, overwrite = FALSE) inside test_logger(), the log and all the expected lines seem to show up. Since your targets are running in parallel, it is good practice to use separate logs so the processes do not compete for access to a single file. The behavior in those cases is unpredictable: https://www.techtarget.com/searchstorage/definition/race-condition#:~:text=Race%20conditions%20are%20most%20commonly,common%20issue%20for%20multithreaded%20applications.

[wlandau]

crew_controller_local() is the local launcher plugin.

By the way: in wlandau/crew@4dba22a I added new arguments local_log_directory and local_log_join to implement built-in logging in crew_controller_local(). You get a log file for each worker instance, which should be fewer files to wrangle than one per branch.

[philiporlando]

Awesome, I look forward to trying out these new features soon!

[philiporlando]

@wlandau, I'm starting to implement crew_controller_local() with the local_log_directory param and it's working seamlessly with the logger calls that I'm making within each target! Thanks for adding this feature!

One thing I could still use some input on is how to use the name param. Is it possible to tell crew_controller_local() to write separate log files that correspond to the name of each target? Are there any other best practices here that you can recommend to help me keep track of my log files?

Thanks again for the support with this!

[wlandau]

I'm starting to implement crew_controller_local() with the local_log_directory param and it's working seamlessly with the logger calls that I'm making within each target!

Glad to hear that part is working. I just submitted an update to crew on CRAN with this feature.

One thing I could still use some input on is how to use the name param.

The name argument of crew_controller_local() applies to the controller as a whole, not to individual workers or tasks. So not really a useful lever here.

Is it possible to tell crew_controller_local() to write separate log files that correspond to the name of each target?

crew helps set up worker-specific log files, but I don't have plans to implement that for task-specific ones. To create a separate file for each target, you could revert to the logger stuff earlier in our conversation. Alternatively, if you just want to know which part of a worker log file corresponds which target, you could have each target call print(targets::tar_name()).

[philiporlando]

I really appreciate how quickly you updated crew to handle logging. This is a game changer for me!

Thanks for clarifying the name parameter within crew_crontoller_local(). After spending some more time with it, I think the default log names are plenty useful in their current form. I just got into the habit of cleaning up stale log files before debugging like this:

log_files <- list.files("./log", pattern = "\\.log$", full.names = TRUE)
purrr::walk(log_files, function(f) {
  unlink(f)
})

Then, instead of calling tar_make() on the entire pipeline, I would isolate the problematic nodes, for example: tar_make(specific_target_name). This would only create a handful of log files. As for branching targets, I could usually sift through the most recent files to find what I was looking for.

Thanks again for the helpful feedback!