Line number, and full and compact stack trace tracking in the log.

[camult]

Hi,

Is there a way to retrieve the current line number when the log is called? I've been using the logger with the following layout.

logLayout <- "{node} \t {user} \t {pid} \t {time} \t {fn} \t {level} \t {msg}\n"

I wonder if there would be a way to do something like:

logLayout <- "{node} \t {user} \t {pid} \t {time} \t {fn} \t {level} \t {line} \t {msg}\n"

Thank you.

[GitHunter0]

It would be nice to track not only the line number but also the source file path.

[camult]

I've created a few functions to get the information I need with the format I want. See the code below, where I am using the "tryCatchLog" package.

It would be nice to have it as an option instead of calling a function.

.Packages <- c("data.table", "logger", "magrittr", "glue", "rlang", "tryCatchLog", "stringi")
invisible(suppressWarnings(suppressPackageStartupMessages(lapply(.Packages, library, character.only = TRUE))))
options(
  tryCatchLog.write.error.dump.file = FALSE,
  tryCatchLog.silent.messages = FALSE,
  tryCatchLog.silent.warnings = TRUE,
  include.full.call.stack = TRUE,
  keep.source.pkgs = TRUE,
  keep.source = TRUE
)

traceError <- function() {
  traceErrorFUN <- function(e) {
    log_tbl <- tryCatchLog::last.tryCatchLog.result()
    setDT(log_tbl)
    if (nrow(log_tbl) > 0) {
      if (any("ERROR" %in% log_tbl[["severity"]])) {
        error_message <- gsub(
          pattern = "#",
          replacement = " - Quitting from line ", 
          x = grep(
            pattern = "R#",
            x = stri_split_fixed(
              str = gsub(
                pattern = "\\s+",
                replacement = " ",
                x = trimws(
                  x = gsub(
                    pattern = "\\:.*",
                    replacement = "",
                    x = tail(
                      x = stri_split_fixed(
                        str = log_tbl[severity == "ERROR", trimws(compact.stack.trace)],
                        pattern = "\n"
                      )[[1]],
                      n = 1
                    )
                  )
                )
              ),
              pattern = " "
            )[[1]],
            value = TRUE
          )
        )
        log_fatal("An ERROR occurred when running the function {error_message}")
        quit("no")
      }
    }
  }
}
traceWarning <- function() {
  function(w) {
    log_tbl <- tryCatchLog::last.tryCatchLog.result()
    setDT(log_tbl)
    if (nrow(log_tbl) > 0) {
      if (any("WARN" %in% log_tbl[["severity"]])) {
        warning_message <- gsub(
          pattern = "#",
          replacement = " - Line ", 
          x = grep(
            pattern = "R#",
            x = stri_split_fixed(
              str = gsub(
                pattern = "\\s+",
                replacement = " ",
                x = trimws(
                  x = gsub(
                    pattern = "\\:.*",
                    replacement = "",
                    x = tail(
                      x = stri_split_fixed(
                        str = log_tbl[severity == "WARN", trimws(compact.stack.trace)],
                        pattern = "\n"
                      )[[1]],
                      n = 1
                    )
                  )
                )
              ),
              pattern = " "
            )[[1]],
            value = TRUE
          )
        )
        log_debug("WARNING message alert when running the function {warning_message}")
      }
    }
  }
}
trace_log <- function(out2eval) {
  tryCatchLog(
    out2eval,
    error = traceError(),
    warning = traceWarning()
  )
  if (!is.null(out2eval)) {
    return(out2eval)
  }
  invisible("")
}
log2file <- function(severity.level, msg) {
  if (is.na(msg)) {
    msg <- ""
  }
  stopifnot(!is.null(severity.level))
  stopifnot(severity.level %in% c("ERROR", "WARN"))
  stopifnot(is.character(msg))
  log.time <- format(Sys.time(), "%Y-%m-%d %H:%M:%S")
  res <- sprintf("%s [%s] %s\n", severity.level, log.time, msg)
  if (severity.level == "ERROR") {
    cat(res, file = "error.log")
  }
  if (severity.level == "WARN") {
    cat(res, file = "warning.log")
  }
  invisible("")
}

#-------------------------------------------------------------------------------------------#
# Set Error and Warning stack Messages
#-------------------------------------------------------------------------------------------#
set.logging.functions(
  error.log.func = function(msg) log2file("ERROR", msg),
  warn.log.func = function(msg) log2file("WARN", msg),
  info.log.func = invisible
)

Then, I just need to pipe any function to the trace_log(), like:

Error Message

log("a") %>% trace_log() 

It saves a file called "error.log" with the following information on it.

ERROR [2022-09-23 15:22:20] non-numeric argument to mathematical function

Compact call stack:
  1 log("1") %>% trace_log()
  2 #2: tryCatchLog(out2eval, error = traceError(), warning = traceWarning())
  3 #2: .handleSimpleError(function (c) 

Full call stack:
  1 log("1") %>% trace_log()
  2 trace_log(.)
  3 #2: tryCatchLog(out2eval, error = traceError(), warning = traceWarning())
  4 tryCatch(withCallingHandlers(expr, condition = cond.handler), ..., finally = finally)
  5 tryCatchList(expr, classes, parentenv, handlers)
  6 tryCatchOne(tryCatchList(expr, names[-nh], parentenv, handlers[-nh]), names[nh], parentenv, handlers[[nh]])
  7 doTryCatch(return(expr), name, parentenv, handler)
  8 tryCatchList(expr, names[-nh], parentenv, handlers[-nh])
  9 tryCatchOne(expr, names, parentenv, handlers[[1]])
  10 doTryCatch(return(expr), name, parentenv, handler)
  11 withCallingHandlers(expr, condition = cond.handler)
  12 #2: .handleSimpleError(function (c) 
    {
        if (inherits(c, "condition") && !inherits(c, c("error", "warning", "message", "interrupt"))) {
            if (is.null

Warning Message

log(-1) %>% trace_log() 

It saves a file called "warning.log" with the following information on it.

WARN [2022-09-23 15:20:00] NaNs produced

Compact call stack:
  1 log(-1) %>% trace_log()
  2 #2: tryCatchLog(out2eval, error = traceError(), warning = traceWarning())
  3 #2: .signalSimpleWarning("NaNs produced", base::quote(log(-1)))

Full call stack:
  1 log(-1) %>% trace_log()
  2 trace_log(.)
  3 #2: tryCatchLog(out2eval, error = traceError(), warning = traceWarning())
  4 tryCatch(withCallingHandlers(expr, condition = cond.handler), ..., finally = finally)
  5 tryCatchList(expr, classes, parentenv, handlers)
  6 tryCatchOne(tryCatchList(expr, names[-nh], parentenv, handlers[-nh]), names[nh], parentenv, handlers[[nh]])
  7 doTryCatch(return(expr), name, parentenv, handler)
  8 tryCatchList(expr, names[-nh], parentenv, handlers[-nh])
  9 tryCatchOne(expr, names, parentenv, handlers[[1]])
  10 doTryCatch(return(expr), name, parentenv, handler)
  11 withCallingHandlers(expr, condition = cond.handler)
  12 #2: .signalSimpleWarning("NaNs produced", base::quote(log(-1)))
  13 withRestarts({
        .Internal(.signalCondition(simpleWarning(msg, call), msg, call))
        .Internal(.dfltWarn(msg, call))
    }, muffleWarning = function() NULL)
  14 withOneRestart(expr, restarts[[1]])
  15 doWithOneRestart(return(expr), restart)

[GitHunter0]

It would be nice to track not only the line number but also the source file path.

Regarding the path, one could use this.path() from package this.path