Logging in R and C++ (Rcpp) code

If you are interested in learning how to use a logger in R and Rcpp code, while setting the loglevel dynamically in the R world, read on.

The R logger is defined in the futile.logger package. This package is unfortunately not actively maintained (more on this later), nevertheless it's useful and easy to use. The logger used in the C++ code is defined in the RcppSpdlog package.

The C++ logger can be quickly set up:

// C++ part
void setLoggerCpp()
{
  //https://cran.r-project.org/web/packages/RcppSpdlog/vignettes/introduction.html
  std::string logname = "TheLogger";
  auto sp = spdlog::get(logname);
  if (sp == nullptr)
  {
    sp = spdlog::r_sink_mt(logname);
  }
  spdlog::set_default_logger(sp);
  
  //https://github.com/gabime/spdlog/wiki/3.-Custom-formatting
  //https://spdlog.docsforge.com/v1.x/3.custom-formatting/#pattern-flags
  spdlog::set_pattern("%l [%Y-%m-%d %H:%M:%S][thread %t] %v");
}

For details, please follow the url's.

While used in a package, the C++ logger can be set while loading the package:

# R part
.onLoad <- function(libname, pkgname) {
  setLoggerCpp();
}

The logging level can be set like this:
 

// C++ part
void setLogLevelCpp(const std::string &name)
{
  spdlog::set_level(spdlog::level::from_str(name));
}

The logging levels of the two packages (futile.logger and RcppSpdlog) differ a bit, that is why I used the following mapping:

# R part
set_log_level <- function()
{
  r_cpp_levels <- list(
    TRACE = "trace",
    DEBUG = "debug",
    INFO = "info",
    WARN = "warning",
    ERROR = "error",
    FATAL = "critical"
  )
  current_log_level <- futile.logger::flog.threshold()
  message("curent_log_level: ", current_log_level)
  setLogLevelCpp(r_cpp_levels[[current_log_level]])
}

This allows me to set the logging in the R code, which then affects the C++ logging.

For example, assuming the following dummy C++ function:

// [[Rcpp::export]]
void doSomethingCpp()
{
  spdlog::debug("doSomethingCpp - start");
  
  std::vector<int> v = {1, 2, 3};
  
  // https://github.com/fmtlib/fmt
  spdlog::info("v: [{}]", fmt::join(v, ", "));
  
  // https://github.com/gabime/spdlog/blob/v1.x/example/example.cpp
  spdlog::stopwatch sw;
  std::this_thread::sleep_for(std::chrono::milliseconds(123));
  spdlog::info("Stopwatch: {} seconds", sw);
}

I get the following:
 

futile.logger::flog.threshold(futile.logger::DEBUG)
logging.example::set_log_level()
logging.example::do_something()
# INFO [2021-08-01 16:59:03] do_something
# curent_log_level: DEBUG
# debug [2021-08-01 16:59:03][thread 7180] doSomethingCpp - start
# info [2021-08-01 16:59:03][thread 7180] v: [1, 2, 3]
# info [2021-08-01 16:59:03][thread 7180] Stopwatch: 0.123133933 seconds

futile.logger::flog.threshold(futile.logger::INFO)
logging.example::set_log_level()
logging.example::do_something()
# INFO [2021-08-01 17:00:01] do_something
# curent_log_level: INFO
# info [2021-08-01 17:00:01][thread 7180] v: [1, 2, 3]
# info [2021-08-01 17:00:01][thread 7180] Stopwatch: 0.123299367 seconds

As you can see, the debug message is not shown anymore, since the log level is INFO.

The complete code can be found here: logging.example git repository (@codeberg).

As I mentioned in the beginning, the futile.logger package is not actively maintained anymore. However, this  package served me well until now.

One thing that might be helpful to know is that the futile.logger uses sprintf by default to format the messages:

futile.logger::flog.info("golden ratio: %f", 0.618)
# INFO [2021-08-01 17:07:14] golden ratio: 0.618000

You might find it more useful to use glue to format the message:
 

# https://github.com/zatonovo/futile.logger/blob/master/R/layout.R
layout.glue <- function(level, msg, id='', ...)
{
  if (!requireNamespace("glue", quietly=TRUE))
    stop("layout.glue requires glue. Please install it.", call.=FALSE)
  msg <- do.call(glue::glue, c(msg, list(...)), envir = parent.frame(3))
  futile.logger::layout.simple(level, msg)
}
futile.logger::flog.layout(layout.glue)

golden_ratio <- 0.618
glue::glue("golden ratio: {golden_ratio}")
# golden ratio: 0.618
futile.logger::flog.info("golden ratio: {golden_ratio}")
# INFO [2021-08-01 17:13:45] golden ratio: 0.618

For a more recent R logging package, you might want to have a look at the logger package.

I didn't want to shave the yak, so I stick to futile.logger for my purposes.

https://sketchplanations.com/yak-shaving

Note: code tested with R version 4.1.0, futile.logger version 1.4.3, Rcpp version 1.0.7, RcppSpdlog version 0.0.6, glue version 1.4.2.

Make a promise. Show up. Do the work. Repeat.