log_warnings() etc. not compatible with profvis

[jat255]

Thanks for this great package! As a python native dabbling with R, it's great to find something so ergonomic for logging. This isn't really an issue per se, but more of an FYI that if you try to run code with one of the log_warnings(), log_errors(), etc. functions active from inside of a profvis profiling session, you'll get the following error:

Error in globalCallingHandlers(warning = function(m) { :
  should not be called with handlers on the stack
Calls: profvis ... ..stacktraceon.. -> <Anonymous> -> globalCallingHandlers
Execution halted

It's probably not urgent to find a workaround, but a note in the documentation might be helpful for others who come across this as a surprise.

[daroczig]

Thanks for this ticket -- unfortunately, I'm aware: https://twitter.com/daroczig/status/1339592432036409347

The problem is that you cannot register global calling handlers in quite a few cases, eg pkg load time or even in tryCatch -- and seems like neither from profvis (due to the same issue).

I will keep looking for a solution, but meanwhile, your suggestion makes a lot of sense and will note this in the docs.

[nlarusstone]

Echoing my appreciation for a nice package! Just wanted to hop in this issue to say that I'm also seeing this when trying to run tests using testthat and my (imperfect) workaround was just to drop the log_errors call into an if block so that it doesn't trigger when loading the file during testing.

if (getOption("run.main", default = TRUE)) {
  log_errors()
  ...
}

[DavZim]

I just ran into the same issue using logger and log_errors() in a targets pipeline. Otherwise a great package!

[Qile0317]

Recently also came across this issue - I came up with the following hack fix that overrides the message, warning, and stop functions with new definitions that also logs the outputs:

library(rlang)

makeMsgWarnStopAlsoLog <- function() {

    dotParamInputIsOneCondition <- function(...) {
        ...length() == 1L && inherits(..1, "condition")
    }

    message <- function (..., domain = NULL, appendLF = TRUE, logLvl = logger::INFO) {
        cond <- if (dotParamInputIsOneCondition(...)) {
            if (nargs() > 1L) warning("additional arguments ignored in message()")
            ..1
        } else {
            msg <- .makeMessage(..., domain = domain, appendLF = appendLF)
            if (!is.null(logLvl)) try(logger::log_level(logLvl, msg), silent = TRUE)
            call <- sys.call()
            simpleMessage(msg, call)
        }
        defaultHandler <- function(c) {
            cat(conditionMessage(c), file = stderr(), sep = "")
        }
        withRestarts({
            signalCondition(cond)
            defaultHandler(cond)
        }, muffleMessage = function() NULL)
        invisible()
    }

    warning <- function(
        ...,
        call. = TRUE,
        immediate. = FALSE,
        noBreaks. = FALSE,
        domain = NULL,
        logLvl = logger::WARN
    ) {
        if (dotParamInputIsOneCondition(...)) {
            cond <- ..1
            if (nargs() > 1L) 
                cat(gettext("additional arguments ignored in warning()"),
                    "\n", sep = "", file = stderr())
            message <- conditionMessage(cond)
            call <- conditionCall(cond)
            withRestarts({
                .Internal(.signalCondition(cond, message, call))
                .Internal(.dfltWarn(message, call))
            }, muffleWarning = function() NULL)
            if (!is.null(logLvl)) try(logger::log_level(logLvl, message), silent = TRUE)
            return(invisible(message))
        }
        msg <- .makeMessage(..., domain = domain)
        if (!is.null(logLvl)) try(logger::log_level(logLvl, msg), silent = TRUE)
        .Internal(warning(call., immediate., noBreaks., msg))
    }

    stop <- function(..., call. = TRUE, domain = NULL, logLvl = logger::ERROR) {
        if (dotParamInputIsOneCondition(...)) {
            cond <- ..1
            if (nargs() > 1L) 
                warning("additional arguments ignored in stop()")
            message <- conditionMessage(cond)
            call <- conditionCall(cond)
            try(logger::log_fatal(message), silent = TRUE)
            .Internal(.signalCondition(cond, message, call))
            .Internal(.dfltStop(message, call))
        }
        else {
            msg <- .makeMessage(..., domain = domain)
            if (!is.null(logLvl)) try(logger::log_level(logLvl, msg), silent = TRUE)
            .Internal(stop(call., msg))
        }
    }

    rlang::env_unlock(env = asNamespace("base"))
    rlang::env_binding_unlock(env = asNamespace("base"))
    sapply(c("message", "warning", "stop"), function(funcName)
        base::assign(funcName, eval(parse(text = funcName)), envir = asNamespace("base")))
    rlang::env_binding_lock(env = asNamespace("base"))
    rlang::env_lock(asNamespace("base"))
}

This won't work for instances where some function calls these functions with the base:: namespace, but so far it seems that the most packages I've worked with has not done this. This also doesn't cover all cases, and there still are some errors and warnings that slip by.

It's also possible to undo this with another function that does the same rlang namespace manipulation.