Getting
Things Logged

Gergely Daróczi

@daroczig

dummy slide

$ whoami

$ whoami

$ whoami

Welcome to prod!

What is “production”?

  • 2006: calling R scripts from PHP (both reading from MySQL) to generate custom plots on surveys in a homepage for interactive use
  • 2008: automated/batch R scripts to generate thousands of pages of crosstables, ANOVA and plots from SPSS with pdflatex
  • 2011: web application combining Ruby on Rails, pandoc and RApache providing reports in plain English for survey analysis (NoSQL databases, vertical scaling, security, central error tracking etc)
  • 2012: plain RApache web application for NLP and network analysis
  • 2015: standardizing the data infrastructure of a fintech startup to use R both in bath jobs and stream processing (ETL, reporting, fraud detection, daily operations, customer communication etc)
  • 2017: redesign, monitor and scale the DS infrastructure of an adtech startup for batch training and live scoring

What is “production”?

Using in R in a non-interactive way:

  • R scripts are scheduled to run without manual intervention (eg CRON or upstream job trigger, API request)
  • need for a standard, eg containerized environment (eg R and package versions, OS packages, .Rprofile etc)
  • security! (safeguarded production environment, SQL injection, AppArmor, encrypted credentials etc)
  • the output of the jobs are recorded and monitored (eg error handler for ErrBit, CloudWatch logs or Splunk etc), alerts and notifications
  • if an error occurs, usually there is no other way to figure out what happened then looking at the recorded job output, so better log than sorry

Motivation

What has just happened?

$ Rscript super_important_business_stuff.R
Error in l[[x]] : subscript out of bounds
Calls: g -> f
Execution halted
Error in .subset2(x, i, exact = exact) : subscript out of bounds
Execution halted

Poor man’s progress bar

for (i in 1:100) {
    ## do something slow
    print(i)
}
N <- 42
for (i in 1:N) {
    ## do something slow
    print(paste(
        Sys.time(), '|',
        i, 'out of', N,
        '=', round(i / N * 100), '%'))
    flush.console()
}

Poor man’s progress bar

[1] "2019-09-15 00:05:34 | 1 out of 42 = 2 %"
[1] "2019-09-15 00:05:35 | 2 out of 42 = 5 %"
[1] "2019-09-15 00:05:35 | 3 out of 42 = 7 %"
[1] "2019-09-15 00:05:36 | 4 out of 42 = 10 %"
[1] "2019-09-15 00:05:36 | 5 out of 42 = 12 %"
[1] "2019-09-15 00:05:37 | 6 out of 42 = 14 %"
[1] "2019-09-15 00:05:37 | 7 out of 42 = 17 %"
[1] "2019-09-15 00:05:38 | 8 out of 42 = 19 %"
[1] "2019-09-15 00:05:38 | 9 out of 42 = 21 %"
[1] "2019-09-15 00:05:39 | 10 out of 42 = 24 %"
[1] "2019-09-15 00:05:39 | 11 out of 42 = 26 %"
[1] "2019-09-15 00:05:40 | 12 out of 42 = 29 %"
[1] "2019-09-15 00:05:40 | 13 out of 42 = 31 %"
[1] "2019-09-15 00:05:41 | 14 out of 42 = 33 %"
[1] "2019-09-15 00:05:41 | 15 out of 42 = 36 %"
[1] "2019-09-15 00:05:42 | 16 out of 42 = 38 %"
[1] "2019-09-15 00:05:42 | 17 out of 42 = 40 %"
Error in .subset2(x, i, exact = exact) : subscript out of bounds
Execution halted

Logging progress to file

sink('/var/log/foobar.log', append = TRUE, split = TRUE)
N <- 42
for (i in 1:N) {
    ## do something slow
    print(paste(Sys.time(), '|', i, 'out of', N, '=', round(i / N * 100), '%'))
}
logfile <- '/var/log/foobar.log'
for (i in 1:N) {
    ## do something slow
    cat(
       paste(Sys.time(), '|', i, 'out of', N, '=', round(i / N * 100), '%'),
       file = logfile, append = TRUE)
}
log <- function(message, logfile = '/var/log/foobar.log') {
    cat(paste(Sys.time(), '|', message),
        file = logfile, append = TRUE)
}

Failing to log to file

mclapply(1:N, function(n) {
    ## do something slow
    log(paste(i, 'out of', N, '=', round(i / N * 100), '%'))
}
[1] "2019-09-15 00:05:34 | 1 out of 42 = 2 %"
[1] "2019-09-15 00:05:35 | 2 out of 42 = 5 %"
[1] "2019-09-15 00:05:39 | 10 out of 42 = 24 %"
[1] "2019-09-15 00:05:35 | 3 out of 42 = 7 %"
[1] "2019-09-15 00:05:39 | 11 out of 42 = 26 %"
[1] "2019-09-15 00:05:36 | 4 out of 42 = 10 %"
[1] "2019-09-15 00:05:37 | 7 out of 42 = 17 %"
[1] "2019-09-15 00:05:38 | 8 out of 42 = 19 %"
[1] "2019-09-15 00:05:40 | 12 out of 42 = 29 %"[1] "2019-09-15 00:05:36 | 5 out of 42 = 12 %"
[1] "2019-09-15 00:05:37 | 16 out of 42 = 19 %"
[1] "2019-09-15 00:05:38 | 13 out of 42 = 31 %"
[1] "2019-09-15 00:05:37 | 19 out of 42 = 45 %"
[1] "2019-09-15 00:05:38 | 22 out of 42 = 52 %"
[1] "2019-09-15 00:05:37 | 28 out of 42 = 67 %"
[1] "2019-09-15 00:05:38 | 21 out of 42 = 50 %"
[1] "2019-09-15 00:05:37 | 26 out of 42 = 62 %"
[1] "2019-09-15 00:05:38 | 24 out of 42 = 57 %"
Error in .subset2(x, i, exact = exact) : subscript out of bounds
Execution halted

Other logging packages

Source: When my co-worker wants to simplify code …

Logging packages on CRAN

> library(data.table)
> packages <- data.table(available.packages())
> ## avoid analog, logit, (archeo|bio|genea|hydro|topo|...)logy
> packages[grepl('(?<!ana)log(?![it|y])', Package, perl = TRUE), Package]

 [1] "adjustedcranlogs"     "bayesloglin"          "blogdown"
 [4] "CommunityCorrelogram" "cranlogs"             "efflog"
 [7] "eMLEloglin"           "futile.logger"        "gemlog"
[10] "gglogo"               "ggseqlogo"            "homologene"
[13] "lifelogr"             "log4r"                "logbin"
[16] "logconcens"           "logcondens"           "logcondens.mode"
[19] "logcondiscr"          "logger"               "logging"
[22] "loggit"               "loggle"               "logKDE"
[25] "loglognorm"           "logmult"              "lognorm"
[28] "logNormReg"           "logOfGamma"           "logspline"
[31] "lolog"                "luzlogr"              "md.log"
[34] "mdir.logrank"         "mpmcorrelogram"       "PhylogeneticEM"
[37] "phylogram"            "plogr"                "poilog"
[40] "rChoiceDialogs"       "reactlog"             "rmetalog"
[43] "robustloggamma"       "rsyslog"              "shinylogs"
[46] "ssrm.logmer"          "svDialogs"            "svDialogstcltk"
[49] "tabulog"              "tidylog"              "wavScalogram"