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 = datasets::mtcars, n = n)
#>     data.frame(x = data$wt, y = data$mpg)
#> }

deps_code(simulate)
#> # A tibble: 5 x 2
#>   name             type      
#>   <chr>            <chr>     
#> 1 data.frame       globals   
#> 2 mpg              globals   
#> 3 wt               globals   
#> 4 random_rows      globals   
#> 5 datasets::mtcars namespaced

# 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.
my_plan$command[[1]]
#> knit(knitr_in("report.Rmd"), file_out("report.md"), quiet = TRUE)

deps_code(my_plan$command[[1]])
#> # A tibble: 6 x 2
#>   name                   type    
#>   <chr>                  <chr>   
#> 1 knit                   globals 
#> 2 large                  loadd   
#> 3 small                  readd   
#> 4 coef_regression2_small readd   
#> 5 report.md              file_out
#> 6 report.Rmd             knitr_in

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

deps_code(my_plan$command[[nrow(my_plan)]])
#> # A tibble: 4 x 2
#>   name              type   
#>   <chr>             <chr>  
#> 1 summary           globals
#> 2 suppressWarnings  globals
#> 3 regression2_large globals
#> 4 coefficients      globals

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

deps_target("simulate", config)
#> # A tibble: 2 x 2
#>   name             type      
#>   <chr>            <chr>     
#> 1 random_rows      globals   
#> 2 datasets::mtcars namespaced

deps_target("small", config)
#> # A tibble: 1 x 2
#>   name     type   
#>   <chr>    <chr>  
#> 1 simulate globals

deps_target("report", config)
#> # A tibble: 5 x 2
#>   name                   type    
#>   <chr>                  <chr>   
#> 1 large                  loadd   
#> 2 small                  readd   
#> 3 coef_regression2_small readd   
#> 4 report.md              file_out
#> 5 report.Rmd             knitr_in

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

tracked(config)
#>  [1] "coef_regression1_large" "coef_regression1_small"
#>  [3] "coef_regression2_large" "coef_regression2_small"
#>  [5] "large"                  "datasets::mtcars"      
#>  [7] "file report.Rmd"        "file report.md"        
#>  [9] "random_rows"            "reg1"                  
#> [11] "reg2"                   "regression1_large"     
#> [13] "regression1_small"      "regression2_large"     
#> [15] "regression2_small"      "report"                
#> [17] "simulate"               "small"                 
#> [19] "summ_regression1_large" "summ_regression1_small"
#> [21] "summ_regression2_large" "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 4e6e4d4c0bcda263 target coef_regression1_large
#> 2 5ad25785a84e0cac target coef_regression1_small
#> 3 b2662785d55b28c1 target coef_regression2_large
#> 4 23c66b36be56905b target coef_regression2_small
#> 5 7b6504d4c0dcceab target large                 
#> 6 f4b89e63bc92af79 import datasets::mtcars

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 4e6e4d4c0bcda263 target coef_regression1_large
#> 2 5ad25785a84e0cac target coef_regression1_small
#> 3 b2662785d55b28c1 target coef_regression2_large
#> 4 23c66b36be56905b target coef_regression2_small
#> 5 7b6504d4c0dcceab target                  large
#> 6 f4b89e63bc92af79 import       datasets::mtcars

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: 0xbf90d30>

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
#> 10c10
#> < db84c9f752635a13 import random_rows
#> ---
#> > 089a5c1023c1c51a import random_rows
#> 18c18
#> < f4d57e5ba38b744b import simulate
#> ---
#> > 739a28336ceb4da2 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>     <expr> 
#> 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.

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: 0x12b38f90>

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)

# 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] FALSE

# What was `b` again?
b
#> Error in eval(expr, envir, enclos): object 'b' not found

# 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, config) # See also drake_debug().
#> target my_target

readd(my_target)
#> [1] 12

9.3 Timeouts and retries

See the elapsed, cpu, 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>  <expr> 
#> 1 x      1      
#> 2 y      f(x)

withr::with_message_sink(
  stdout(),
  make(debug_plan, elapsed = 1e-3, retries = 2)
)
#> target x
#> target y
#> retry y: 1 of 2
#> retry y: 2 of 2
#> fail y
#> Error: Target `y` failed. Call `diagnose(y)` for details. Error message:
#>   reached elapsed time limit

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

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

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

withr::with_message_sink(
  new = stdout(),
  make(debug_plan, elapsed = Inf, retries = 0)
)
#> target x
#> target y
#> fail y
#> Error: Target `y` failed. Call `diagnose(y)` for details. Error message:
#>   reached elapsed time limit

9.4 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