log a backtrace for tuning issues

[simonpcouch]

Was too excited to wait until Monday to finish this PR.😝

This PR aims to provide a better entry point to debugging tuning issues. Closes #873, but takes a slightly different approach than what's recommended there. Instead of surfacing one additional error context header (i.e. Error in log(): ...), this PR proposes attaching a traceback to errors and warnings and then logging it in the notes column. The example from that issue:

# Create sample data
library(tidymodels)

set.seed(123)
num_samples <- 100
outcome <- rnorm(num_samples, mean = 50, sd = 10)
categorical_predictor <- as.factor(sample(letters[1:4], num_samples, replace = TRUE))

# Create dataframe
df <- data.frame(
  Outcome = outcome,
  Categorical_Predictor = categorical_predictor
)

new_row <- data.frame(
  Outcome = 55,
  Categorical_Predictor = "problem"
)

# Add the new row to the dataframe
df <- rbind(new_row, df)

lr_full_preprocessing <- 
  recipe(Outcome ~ ., data = df) %>%
  # novel categories
  step_novel(all_nominal_predictors())

lr_full <- linear_reg() %>%
  set_engine("lm")

lr_full_wf <- workflow() %>%
  add_recipe(lr_full_preprocessing, blueprint = hardhat::default_recipe_blueprint(allow_novel_levels = FALSE)) %>%
  add_model(lr_full)

set.seed(123)  # for reproducibility
folds <- vfold_cv(df, v = 2, repeats = 1)

lr_full_fit_rs <- lr_full_wf %>% 
  fit_resamples(folds)
#> → A | error:   factor Categorical_Predictor has new levels new
#> There were issues with some computations   A: x1
#> There were issues with some computations   A: x1
#> 

collect_notes(lr_full_fit_rs)
#> # A tibble: 1 × 5
#>   id    location                                  type  note          trace     
#>   <chr> <chr>                                     <chr> <chr>         <list>    
#> 1 Fold1 preprocessor 1/1, model 1/1 (predictions) error factor Categ… <rlng_trc>

collect_notes(lr_full_fit_rs)$trace[[1]]
#>      ▆
#>   1. ├─lr_full_wf %>% fit_resamples(folds)
#>   2. ├─tune::fit_resamples(., folds)
#>   3. ├─tune:::fit_resamples.workflow(., folds)
#>   4. │ └─tune:::resample_workflow(...)
#>   5. │   └─tune:::tune_grid_workflow(...)
#>   6. │     └─tune:::tune_grid_loop(...)
#>   7. │       └─tune (local) fn_tune_grid_loop(...)
#>   8. │         └─tune:::tune_grid_loop_impl(...)
#>   9. │           └─rlang::with_env(...)
#>  10. ├─base::suppressPackageStartupMessages(...)
#>  11. │ └─base::withCallingHandlers(expr, packageStartupMessage = function(c) tryInvokeRestart("muffleMessage"))
#>  12. ├─for_each %op% ...
#>  13. │ └─e$fun(obj, substitute(ex), parent.frame(), e$data)
#>  14. │   ├─base::tryCatch(...)
#>  15. │   │ └─base (local) tryCatchList(expr, classes, parentenv, handlers)
#>  16. │   │   └─base (local) tryCatchOne(expr, names, parentenv, handlers[[1L]])
#>  17. │   │     └─base (local) doTryCatch(return(expr), name, parentenv, handler)
#>  18. │   ├─base::tryCatch(eval(xpr, envir = envir), error = function(e) e)
#>  19. │   │ └─base (local) tryCatchList(expr, classes, parentenv, handlers)
#>  20. │   │   └─base (local) tryCatchOne(expr, names, parentenv, handlers[[1L]])
#>  21. │   │     └─base (local) doTryCatch(return(expr), name, parentenv, handler)
#>  22. │   └─base::eval(xpr, envir = envir)
#>  23. │     └─base::eval(xpr, envir = envir)
#>  24. │       └─tune (local) fn_tune_grid_loop_iter_safely(...)
#>  25. │         └─tune (local) fn_tune_grid_loop_iter_wrapper(...)
#>  26. │           ├─base::withCallingHandlers(...)
#>  27. │           ├─base::tryCatch(...)
#>  28. │           │ └─base (local) tryCatchList(expr, classes, parentenv, handlers)
#>  29. │           │   └─base (local) tryCatchOne(expr, names, parentenv, handlers[[1L]])
#>  30. │           │     └─base (local) doTryCatch(return(expr), name, parentenv, handler)
#>  31. │           └─tune (local) fn(...)
#>  32. │             ├─tune::.catch_and_log(...)
#>  33. │             │ └─tune:::catcher(.expr)
#>  34. │             │   └─rlang::try_fetch(...)
#>  35. │             │     ├─base::tryCatch(...)
#>  36. │             │     │ └─base (local) tryCatchList(expr, classes, parentenv, handlers)
#>  37. │             │     │   └─base (local) tryCatchOne(expr, names, parentenv, handlers[[1L]])
#>  38. │             │     │     └─base (local) doTryCatch(return(expr), name, parentenv, handler)
#>  39. │             │     └─base::withCallingHandlers(...)
#>  40. │             └─tune:::predict_model(...)
#>  41. │               └─tune:::predict_wrapper(model, x_vals, type_iter, eval_time)
#>  42. │                 └─rlang::eval_tidy(cl)
#>  43. ├─parsnip::predict.model_fit(...)
#>  44. │ ├─parsnip::predict_numeric(...)
#>  45. │ └─parsnip::predict_numeric.model_fit(...)
#>  46. │   └─rlang::eval_tidy(pred_call)
#>  47. ├─stats::predict(...)
#>  48. ├─stats::predict.lm(...)
#>  49. │ ├─stats::model.frame(Terms, newdata, na.action = na.action, xlev = object$xlevels)
#>  50. │ └─stats::model.frame.default(...)
#>  51. │   └─base::stop(...)
#>  52. └─base::.handleSimpleError(...)
#>  53.   └─rlang (local) h(simpleError(msg, call))

^{Created on 2024-03-23 with reprex v2.1.0}

This is likely more aimed at advanced users (and developers), but I think will be a gamechanger for quickly debug()ging into the right functions or spotting the right bit of context that tips me off to what the actual issue is.

[simonpcouch]

Note that traces are a tibble subclass.

Each row in the output of this function is a given place in evaluating a resample fold, e.g. Fold1 preprocessor 1/1, model 1/1 (predictions).

It's possible to have more than one warning appear in a given model fit or prediction or metric calculation, so we collapse messages (see above) into one string in that case. For traces, we could just pass all of list(wrn_traces), but that would mean that, to be type-stable, we'd have to list(list(err_cnd$trace)) for errors.

Said another way, right now, to extract the second logged trace, you could write collect_notes()$trace[[2]]. If we supplied all of the warning traces in this line and changed the format for errors to be type-stable, you'd have to write collect_notes()$trace[[2]][[1]]. This [[-fu feels contrary to the point of the collect_*() functions.

This approach banks on the fact that it's likely not useful to have a backtrace for each warning that occurs in a single call to e.g. predict.xgb(); the first is sufficient to help you drop into the right environment to track down an issue.

[hfrick]

I'd go with clarity over completeness here and only use the first trace as suggested. If we later realize that this does not get us to a useful debugging point often enough, we can still extend it.

[EmilHvitfeldt]

I LOVE IT!

I had it in my personal todo to tell you tomorrow that I wanted you to look at saving the trace back!

[hfrick]

On board with it! 🐾

[hfrick]

I'd go with clarity over completeness here and only use the first trace as suggested. If we later realize that this does not get us to a useful debugging point often enough, we can still extend it.

[github-actions]

This pull request has been automatically locked. If you believe you have found a related problem, please file a new issue (with a reprex: https://reprex.tidyverse.org) and link to this issue.