Run tryCatchLog in scheduled script - Rscript only gives first level

[Toniiiio]

Thanks for the great package.

I have troubles using the package within scheduled scripts.

Reproducible code:

library(tryCatchLog)
library(futile.logger)

wrapper <- function(b) {
  dd(b)
}

dd <- function(r) {
  sum("a" * r)
}


flog.appender(appender.file("my_app.log"))
tryCatchLog(wrapper(2), error = function(e) print(e))

I will run it twice:

• within R --> works
• with Rscript --> does not give full traceback

Log would read:

(First part refers to output from R and the second for the RScript call. Note that the second call is not complete.

ERROR [2020-04-21 22:45:09] [ERROR] nicht-numerisches Argument für binären Operator

Compact call stack:
  1 tryCatchLog(wrapper(2), error = function(e) print(e))
  2 #2: c(b)
  3 #2: .handleSimpleError(function (c) 


ERROR [2020-04-21 22:46:55] [ERROR] nicht-numerisches Argument für binären Operator

Compact call stack:
  1 tryCatchLog(wrapper(2), error = function(e) print(e))

Same holds for a call with R CMD BATCH.

Goal would be tun run a scheduled script and log the traceback with a custom format (e.g. using futile.logger).

Edit: SessionInfo

R version 3.6.3 (2020-02-29)
Platform: x86_64-w64-mingw32/x64 (64-bit)
Running under: Windows >= 8 x64 (build 9200)

Matrix products: default

locale:
[1] LC_COLLATE=German_Germany.1252  LC_CTYPE=German_Germany.1252    LC_MONETARY=German_Germany.1252
[4] LC_NUMERIC=C                    LC_TIME=German_Germany.1252    

attached base packages:
[1] stats     graphics  grDevices utils     datasets  methods   base     

other attached packages:
[1] futile.logger_1.4.3 tryCatchLog_1.1.6  

loaded via a namespace (and not attached):
[1] compiler_3.6.3       formatR_1.7          tools_3.6.3          lambda.r_1.2.4       futile.options_1.0.1

[aryoda]

Thanks for reporting the issue!

Can you please add your sessionInfo() here + the command line you are using to call the code via Rscript?

Side note: Overwriting R's default c() function may cause unexpected side-effects.

[Toniiiio]

Thanks for the very fast response!
sry, for the forgotten sessioninfo, i made an edit. Command line tool is Windows CMD.
I also reproduced the issue on Linux raspberrypi 4.19.97-v7l+ armv7l, R 3.5.2. I can also add the sessionInfo if it does get too much here.

Just to be sure, i changed to funciton name form c to dd. Does not matter to me as it is just dummy code for reproducibility.

[aryoda]

My first analysis (tested with the CRAN and dev version of tryCatchLog:

The compact stack traces throws away all (function) calls that do not have a source code reference and and if you look at the full stack trace it is complete.

Since you are calling R via Rscript or R CMD BATCH there are no source code references by default (for performance reasons?) it must be enabled manually, eg. via this best practice code:

Rscript -e "options(keep.source = TRUE); source('issue_56_Rscript_traceback.R')"

logs

ERROR [2020-04-22 09:10:39] [ERROR] non-numeric argument to binary operator

Compact call stack:
  1 source("issue_56_Rscript_traceback.R")
  2 issue_56_Rscript_traceback.R#15: tryCatchLog(wrapper(2), error = function(e
  3 issue_56_Rscript_traceback.R#5: dd(b)
  4 issue_56_Rscript_traceback.R#9: .handleSimpleError(function (c) 

This is document somehow deeply in the help for ?tryCatchLog but perhaps I could make this important little details more obvious eg. when tryCatchLog is loaded via

keep.source=FALSE - logged call stacks will not have source code references and the compact call stack will show only the first call

I really care for user and usability feed-back so
I welcome further proposals on how to avoid this trap since it really is not obvious.

PS Here the compact and full call stack when called without source code references via Rscript issue_56_Rscript_traceback.R which shows that the compact call stack throws away all calls without source code refs and leaves only the first call (while the full stack trace is still correct):

ERROR [2020-04-22 09:09:50] [ERROR] non-numeric argument to binary operator

Compact call stack:
  1 tryCatchLog(wrapper(2), error = function(e) print(e))

Full call stack:
  1 tryCatchLog(wrapper(2), error = function(e) print(e))
  2 tryCatch(withCallingHandlers(expr, error = cond.handler, warning = cond.han
  3 tryCatchList(expr, classes, parentenv, handlers)
  4 tryCatchOne(expr, names, parentenv, handlers[[1]])
  5 doTryCatch(return(expr), name, parentenv, handler)
  6 withCallingHandlers(expr, error = cond.handler, warning = cond.handler, mes
  7 wrapper(2)
  8 dd(b)
  9 .handleSimpleError(function (c) 
    {
        call.stack <- sys.calls()

[Toniiiio]

Sry for not reading ?tryCatchLog carefully enough. I can reproduce that using options(keep.source = TRUE) works on Windows and Debian for the referenced versions. So for me the issue would closed. Thanks again for the very fast replies.

Concerning usability:

When using packages that requires customization (e.g. here custom logging format with futile.logger), but are used multiple times across projects (same logging format across projects), we usually write a wrapper package anyway. So my next attempt would be to include the option settings there as well.

My first thought would be that the usage of Rscript / R CMD BATCH would be the default when logging is required. Because in interactive sessions, the (extensive) interactive debugging options of RStudio can be used. If i schedule my scripts i cant use these anymore so i switch to logging. Then i require a traceback and get aware of your great pacakge. So, i guess, it would be great for future package users to have a section about scheduling scripts / Rscript and the usage of options(keep.source = TRUE). I am also happy to contribute such a section.

[aryoda]

Thanks a lot for your feed-back, I will put your recommendations about batch usages onto my documentation TODO list (#48).