Chapter 9 Debugging and testing drake projects

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

9.0.1 Start small

If your workflow is large, consider running a downsized version to debug and test things first. That way, you can find the bugs early on without wasting as much time. Create a test plan with drake_plan(max_expand = SMALL_NUMBER) before scaling up to the full set of targets. See this section on plans for details.

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() # from https://github.com/wlandau/drake-examples/tree/master/mtcars
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.

drake_cache_log()
#> # A tibble: 22 x 3
#>    hash             type   name                  
#>    <chr>            <chr>  <chr>                 
#>  1 ecb4739b594986b9 target coef_regression1_large
#>  2 599bea898e306775 target coef_regression1_small
#>  3 44bfee4c258a76d7 target coef_regression2_large
#>  4 b5502b9c62933484 target coef_regression2_small
#>  5 d87293dd4d012762 target large                 
#>  6 f4b89e63bc92af79 import datasets::mtcars      
#>  7 7a456ee58df699be import file report.Rmd       
#>  8 6153acbb3f1070de target file report.md        
#>  9 db84c9f752635a13 import random_rows           
#> 10 21935c86f12692e2 import reg1                  
#> # … with 12 more rows
filter(drake_cache_log(), type == "import")
#> # A tibble: 6 x 3
#>   hash             type   name            
#>   <chr>            <chr>  <chr>           
#> 1 f4b89e63bc92af79 import datasets::mtcars
#> 2 7a456ee58df699be import file report.Rmd 
#> 3 db84c9f752635a13 import random_rows     
#> 4 21935c86f12692e2 import reg1            
#> 5 69ade4b78f15a3f9 import reg2            
#> 6 f4d57e5ba38b744b import simulate

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.csv")
#> All targets are already up to date.

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

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 cache log.

read_csv("cache_log.csv", col_types = cols()) %>%
  left_join(drake_cache_log(), by = "name") %>%
  filter(hash.x != hash.y) %>%
  select(name, hash.x, hash.y, -type.x, -type.y)
#> # A tibble: 2 x 3
#>   name        hash.x           hash.y          
#>   <chr>       <chr>            <chr>           
#> 1 random_rows db84c9f752635a13 089a5c1023c1c51a
#> 2 simulate    f4d57e5ba38b744b 739a28336ceb4da2

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 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), ]
}

print(outdated(config))
#> character(0)

read_csv("cache_log.csv", col_types = cols()) %>%
  left_join(drake_cache_log(), by = "name") %>%
  filter(hash.x != hash.y) %>%
  select(name, hash.x, hash.y, -type.x, -type.y)
#> # A tibble: 0 x 3
#> # … with 3 variables: name <chr>, hash.x <chr>, hash.y <chr>

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 = 0L) # from the last make() only
#> [1] "my_target"

# See also warnings and messages.
error <- diagnose(my_target, verbose = 0L)$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)), new.env())
#>  $ : language eval(quote(f(b)), new.env())
#>  $ : 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: 0x1ccc4f58>

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
#> }
#> <bytecode: 0xce056e0>

# 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 = 0L)
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

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 = 0L)
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
#> 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

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