Get all R code which is run when running

Question

Suppose I have a bunch of R code in a script and I want to log all the R code which is run from the .GlobalEnv to a flat file or a database together with the errors and warning messages. I could write a simple logme function as follows or make it a bit more complex to also fetch the errors by changing options(error = mylogginfunction)

mylogfile <- tempfile()
logme <- function(x){
  mode <- "at"
  if(!file.exists(mylogfile)){
    mode <- "wt"
  }
  myconn <- file(mylogfile, mode)
  writeLines(x, myconn)
  close(myconn)
  invisible()
}

logme(sprintf("%s: started some yadayada, ", Sys.time()))
x <- 10
x * 7
logme(sprintf("%s: done with yadayada", Sys.time()))

## Get the log
cat(readLines(mylogfile))

The log prints out: 2015-05-14 17:24:31: started some yadayada, 2015-05-14 17:24:31: done with yadayada

But what I would like to have is that the logfile writes down the expressions which were executed without me having to write a wrapper around each statement. I would like the log to look like. 2015-05-14 17:24:31: started some yadayada, x <- 10, x * 7 2015-05-14 17:24:31: done with yadayada

So my question is, how do I fetch what is being executed by R so that I can store the executed expressions in a log/database. And without having to write a function call before each expression (as in myhandler(x <- 10); myhandler(x * 10)). Any help on this?

Answer 1

For catching input commands you could use addTaskCallback

mylogfile <- tempfile()
addTaskCallback(
    function(...) { 
        expr <- deparse(as.expression(...)[[1]]) # it could handled better...
        cat(expr, file=mylogfile, append=TRUE, sep="\n")
        # or cat(sprintf("[%s] %s", Sys.time(), expr),...) if you want timestamps
        TRUE
    }
    ,name="logger"
)

x <- 10
x * 7

removeTaskCallback("logger")

Then result is:

cat(readLines(mylogfile), sep="\n")
... addTaskCallback definition ...
x <- 10
x * 7

But what you get is parsed expression, which means that line

x+1;b<-7;b==2

will be logged as

x + 1
b <- 7
b == 2

In addition:

• output will not be logged, in particular message or warning shown in console
• in case of error logging will not be triggered, so you need separate function to handle it

Answer 2

This is probably to simple to work in every case, but you can try with this:

Define myhandler as:

myhandler <- function(x, file = stdout()) {
  expr <- substitute(x)
  for(e_line in as.list(expr)) {
    cat( file = file, as.character(Sys.time()), capture.output(e_line), "\n")
    eval(e_line, envir = parent.frame())
  }
}

Use it with your code inside the brackets:

myhandler({

  a <- 1
  a <- a + 1
  print(a)

})

Result:

# 2015-05-14 18:46:34 `{` 
# 2015-05-14 18:46:34 a <- 1 
# 2015-05-14 18:46:34 a <- a + 1 
# 2015-05-14 18:46:34 print(a) 
# [1] 2

Answer 3

I confess that I don't really get what "to have the running expressions in the same process available as where the R commands are run" means when we chatted a bit in the comments. However, I expanded what I had in mind. You can create a logGenerator.R file with the following lines:

logGenerator<-function(sourcefile,log) {
  ..zz <- file(log, open = "at")
  sink(..zz)
  sink(..zz, type = "message")
  on.exit({
    sink(type="message")
    sink()
    close(..zz)
  })
  ..x<-parse(sourcefile)
  for (..i in 1:length(..x)) {
    cat(as.character(Sys.time()),"\n")
    cat(as.character(..x[..i]),"\n")
    ..y<-eval(..x[..i])
  }
}

This function takes as arguments the source file and the log file names. This script will take an R file and will log the time at which each instruction is executed. Then it records the expression on the same log file. Every output directed to the stdout() and the error messages are directed to the log file. You obviously don't have to modify in any way your source file.