Chapter 9 Debugging and testing drake projects

This chapter is a guide to debugging and testing drake projects.

9.1 Dependencies

drake automatically detects dependency relationships among your targets and imports. While this is convenient most of the time, it can lead to some pitfalls. This section describes techniques to understand you project’s dependency structure and diagnose and debug issues.

9.1.1 Visualize your dependency graph.

To avoid frustration early on, please use drake’s dependency graph visualizations to see how the steps of your workflow fit together. drake resolves the dependency relationships in the graph by analyzing the code in your commands and the functions in your environment.

load_mtcars_example()
config <- drake_config(my_plan)
# Hover, click, drag, zoom, and pan. See args 'from' and 'to'.
vis_drake_graph(config, width = "100%", height = "500px")

9.1.2 Check specific dependency information.

With the deps_code() function, you can see for yourself how drake detects first-order dependencies from code.

print(simulate)
## function (n) 
## {
##     data <- random_rows(data = mtcars, n = n)
##     data.frame(x = data$wt, y = data$mpg)
## }

deps_code(simulate)
## $globals
## [1] "random_rows" "mtcars"      "data.frame"

# knitr_in() makes sure your target depends on `report.Rmd`
# and any dependencies loaded with loadd() and readd()
# in the report's active code chunks.
cat(my_plan$command[1])
## knit(knitr_in("report.Rmd"), file_out("report.md"), quiet = TRUE)

deps_code(my_plan$command[1])
## $globals
## [1] "knit"
## 
## $loadd
## [1] "large"
## 
## $readd
## [1] "small"                  "coef_regression2_small"
## 
## $knitr_in
## [1] "\"report.Rmd\""
## 
## $file_out
## [1] "\"report.md\""

cat(my_plan$command[nrow(my_plan)])
## suppressWarnings(summary(regression2_large))$coefficients

deps_code(my_plan$command[nrow(my_plan)])
## $globals
## [1] "suppressWarnings"  "summary"           "regression2_large"

With deps_target(), you can see the dependencies that drake has already detected for your targets and imports.

deps_target("simulate", config)
## $globals
## [1] "random_rows"

deps_target("small", config)
## $globals
## [1] "simulate"

deps_target("report", config)
## $loadd
## [1] "large"
## 
## $readd
## [1] "small"                  "coef_regression2_small"
## 
## $knitr_in
## [1] "\"report.Rmd\""
## 
## $file_out
## [1] "\"report.md\""

And with tracked(), you can list all the reproducibly tracked objects and files.

tracked(config)
##  [1] "\"report.md\""          "\"report.Rmd\""        
##  [3] "coef_regression1_large" "coef_regression1_small"
##  [5] "coef_regression2_large" "coef_regression2_small"
##  [7] "large"                  "random_rows"           
##  [9] "reg1"                   "reg2"                  
## [11] "regression1_large"      "regression1_small"     
## [13] "regression2_large"      "regression2_small"     
## [15] "report"                 "simulate"              
## [17] "small"                  "summ_regression1_large"
## [19] "summ_regression1_small" "summ_regression2_large"
## [21] "summ_regression2_small"

9.1.3 Outdated targets and missing dependencies

missed() shows any imports missing from your environment

missed(config) # Nothing is missing right now.
## character(0)

outdated() reports any targets that are outdated.

outdated(config)
##  [1] "coef_regression1_large" "coef_regression1_small"
##  [3] "coef_regression2_large" "coef_regression2_small"
##  [5] "large"                  "regression1_large"     
##  [7] "regression1_small"      "regression2_large"     
##  [9] "regression2_small"      "report"                
## [11] "small"                  "summ_regression1_large"
## [13] "summ_regression1_small" "summ_regression2_large"
## [15] "summ_regression2_small"

make(my_plan)
## target large
## target small
## target regression1_large
## target regression2_large
## target regression1_small
## target regression2_small
## target summ_regression1_large
## target coef_regression1_large
## target summ_regression2_large
## target coef_regression2_large
## target summ_regression1_small
## target coef_regression1_small
## target coef_regression2_small
## target summ_regression2_small
## target report

outdated(config)
## character(0)

9.1.4 But why are my targets out of date?

drake has the option to produce a cache log with the fingerprint of every target and import.

head(drake_cache_log())
## # A tibble: 6 x 3
##   hash             type   name                  
##   <chr>            <chr>  <chr>                 
## 1 c7e850cdf32cafe0 target "\"report.md\""       
## 2 a2e1a7be9a4b1a24 import "\"report.Rmd\""      
## 3 4e6e4d4c0bcda263 target coef_regression1_large
## 4 5ad25785a84e0cac target coef_regression1_small
## 5 b2662785d55b28c1 target coef_regression2_large
## 6 23c66b36be56905b target coef_regression2_small

We highly recommend that you automatically produce a cache log file on every make() and put it under version control with the rest of your project.

make(my_plan, cache_log_file = "cache_log.txt")
## All targets are already up to date.

read.table("cache_log.txt", nrows = 6, header = TRUE)
##               hash   type                   name
## 1 c7e850cdf32cafe0 target              report.md
## 2 a2e1a7be9a4b1a24 import             report.Rmd
## 3 4e6e4d4c0bcda263 target coef_regression1_large
## 4 5ad25785a84e0cac target coef_regression1_small
## 5 b2662785d55b28c1 target coef_regression2_large
## 6 23c66b36be56905b target coef_regression2_small

Suppose we go back and add input checking to one of our functions.

print(random_rows)
## function (data, n) 
## {
##     data[sample.int(n = nrow(data), size = n, replace = TRUE), 
##         ]
## }
## <bytecode: 0xdba1948>

random_rows <- function(data, n){
  stopifnot(n > 0)
  data[sample.int(n = nrow(data), size = n, replace = TRUE), ]
}

Then, we forget to run make() again, and we leave the the project for several months. When we come back, all our targets are suddenly out of date.

outdated(config)
##  [1] "coef_regression1_large" "coef_regression1_small"
##  [3] "coef_regression2_large" "coef_regression2_small"
##  [5] "large"                  "regression1_large"     
##  [7] "regression1_small"      "regression2_large"     
##  [9] "regression2_small"      "report"                
## [11] "small"                  "summ_regression1_large"
## [13] "summ_regression1_small" "summ_regression2_large"
## [15] "summ_regression2_small"

At first, we may not know why all our targets are outdated. But we can generate another cache log and check any hashes that changed. Our call to outdated() already re-cached the imports, so any changed imports will show up in the new log file.

drake_cache_log_file(file = "cache_log2.txt")

system2("diff", "cache_log.txt cache_log2.txt", stdout = TRUE) %>%
  cat(sep = "\n")
## Warning in system2("diff", "cache_log.txt cache_log2.txt", stdout = TRUE):
## running command ''diff' cache_log.txt cache_log2.txt' had status 1
## 9c9
## < 44b898f3c687ee02 import random_rows
## ---
## > a2ed0494ada81cff import random_rows
## 17c17
## < 4acbf8bf5b7452c9 import simulate
## ---
## > 0f44eb1457517517 import simulate

Now, we see that random_rows() has changed since last time, and we have a new dependency stopifnot(). simulate() shows up in the changes too, but only because random_rows() is nested in the body of simulate(). If we revert random_rows() to its original state, all our targets are up to date again.

random_rows <- function(data, n){
  data[sample.int(n = nrow(data), size = n, replace = TRUE), ]
}

outdated(config)
## character(0)

drake_cache_log_file(file = "cache_log3.txt")

system2("diff", "cache_log.txt cache_log3.txt", stdout = TRUE)
## character(0)

9.2 Diagnose failures.

drake records diagnostic metadata on all your targets, including the latest errors, warnings, messages, and other bits of context.

f <- function(x){
  if (x < 0){
    stop("`x` cannot be negative.")
  }
  x
}
bad_plan <- drake_plan(
  a = 12,
  b = -a,
  my_target = f(b)
)

bad_plan
## # A tibble: 3 x 2
##   target    command
##   <chr>     <chr>  
## 1 a         12     
## 2 b         -a     
## 3 my_target f(b)

withr::with_message_sink(
  new = stdout(),
  make(bad_plan)
)
## target a
## target b
## target my_target
## fail my_target
## Error: Target `my_target` failed. Call `diagnose(my_target)` for details. Error message:
##   `x` cannot be negative.
## Warning: No message sink to remove.

failed(verbose = FALSE) # from the last make() only
## [1] "my_target"

# See also warnings and messages.
error <- diagnose(my_target, verbose = FALSE)$error

error$message
## [1] "`x` cannot be negative."

error$call
## f(b)

str(error$calls) # View the traceback.
## List of 8
##  $ : language local({     f(b) ...
##  $ : language eval.parent(substitute(eval(quote(expr), envir)))
##  $ : language eval(expr, p)
##  $ : language eval(expr, p)
##  $ : language eval(quote({     f(b) ...
##  $ : language eval(quote({     f(b) ...
##  $ : language f(b)
##  $ : language stop("`x` cannot be negative.")
##   ..- attr(*, "srcref")= 'srcref' int [1:8] 3 5 3 35 5 35 3 3
##   .. ..- attr(*, "srcfile")=Classes 'srcfilecopy', 'srcfile' <environment: 0x164bd780>

To figure out what went wrong, you could try to build the failed target interactively. To do that, simply call drake_build() or drake_debug(). These functions first call loadd(deps = TRUE) to load any missing dependencies (see the replace argument here) and then build your target. drake_build() simply runs the command, and drake_debug() runs the command in debug mode using debugonce().

# Pretend we just opened a new R session.
library(drake)

# Unloads target `b`.
config <- drake_config(plan = bad_plan)
## Unloading targets from environment:
##   a
##   b

# my_target depends on b.
"b" %in% ls()
## [1] FALSE

# Try to build my_target until the error is fixed.
# Skip all that pesky work checking dependencies.
drake_build(my_target, config = config) # See also drake_debug().
## target my_target
## fail my_target
## Error: Target `my_target` failed. Call `diagnose(my_target)` for details. Error message:
##   `x` cannot be negative.

# The target failed, but the dependency was loaded.
"b" %in% ls()
## [1] TRUE

# What was `b` again?
b
## [1] -12

# How was `b` used?
diagnose(my_target)$message
## NULL

diagnose(my_target)$call
## NULL

f
## function(x){
##   if (x < 0){
##     stop("`x` cannot be negative.")
##   }
##   x
## }

# Aha! The error was in f(). Let's fix it and try again.
f <- function(x){
  x <- abs(x)
  if (x < 0){
    stop("`x` cannot be negative.")
  }
  x
}

# Now it works!
# Since you called make() previously, `config` is read from the cache
# if you do not supply it.
drake_build(my_target) # See also drake_debug().
## target my_target

readd(my_target)
## [1] 12

9.3 Timeouts and retries

See the timeout, cpu, elapsed, and retries argument to make().

clean(verbose = FALSE)
f <- function(...){
  Sys.sleep(1)
}
debug_plan <- drake_plan(x = 1, y = f(x))
debug_plan
## # A tibble: 2 x 2
##   target command
##   <chr>  <chr>  
## 1 x      1      
## 2 y      f(x)

withr::with_message_sink(
  stdout(),
  make(debug_plan, timeout = 1e-3, retries = 2)
)
## Warning: Argument `timeout` is deprecated. Use `elapsed` and/or `cpu`
## instead.

## Warning: Argument `timeout` is deprecated. Use `elapsed` and/or `cpu`
## instead.
## target x
## target y
## Warning: No message sink to remove.

To tailor these settings to each individual target, create new timeout, cpu, elapsed, or retries columns in your workflow plan. These columns override the analogous arguments to make().

clean(verbose = FALSE)
debug_plan$timeout <- c(1e-3, 2e-3)
debug_plan$retries <- 1:2

debug_plan
## # A tibble: 2 x 4
##   target command timeout retries
##   <chr>  <chr>     <dbl>   <int>
## 1 x      1         0.001       1
## 2 y      f(x)      0.002       2

withr::with_message_sink(
  new = stdout(),
  make(debug_plan, timeout = Inf, retries = 0)
)
## Warning: Argument `timeout` is deprecated. Use `elapsed` and/or `cpu`
## instead.

## Warning: Argument `timeout` is deprecated. Use `elapsed` and/or `cpu`
## instead.
## target x
## target y
## Warning: No message sink to remove.

9.4 Consider hasty mode

In hasty mode, drake acts as a job scheduler without watching dependencies. In other words, make(parallelism = "hasty") always runs all the targets, and computational overhead is dramatically reduced. Because it helps deploy targets much faster, hasty mode may be a nice way to test a workflow before running it in production. Read more here.

9.5 More help

Please also see the compendium of cautionary notes, which addresses drake’s known edge cases, pitfalls, and weaknesses that may or may not be fixed in future releases. For the most up-to-date information on unhandled edge cases, please visit the issue tracker, where you can submit your own bug reports as well. Be sure to search the closed issues too, especially if you are not using the most up-to-date development version.

Copyright Eli Lilly and Company