Error handling and debugging

Lesson 9 — R Programming

Lesson 9 of 12 Intermediate ~75 min

Learning objectives

  • Read a traceback and locate the actual failure
  • Use browser(), debug() and RStudio breakpoints effectively
  • Signal errors, warnings and messages with the right condition
  • Catch and handle conditions with tryCatch() and withCallingHandlers()
  • Write informative errors with cli and rlang::abort()
  • Add logging that survives an unattended batch run

The three conditions

Condition Function Execution Use for
Message message() / cli_alert_info() Continues Progress, informational output
Warning warning() / cli_warn() Continues Something suspicious but recoverable
Error stop() / cli_abort() Halts Cannot proceed correctly

The choice matters. A warning in an unattended batch job scrolls past unread. If a condition means the output is wrong, it must be an error.

check_dates <- function(start, end) {
  if (any(end < start, na.rm = TRUE)) {
    stop("End date precedes start date")       # wrong data — must stop
  }
  if (any(is.na(start))) {
    warning("Some start dates are missing")    # handled downstream — warn
  }
  message("Checked ", length(start), " records")
  invisible(TRUE)
}

Reading an error

adsl |> mutate(bmi = weight / (height/100)^2)
#> Error in `mutate()`:
#> i In argument: `bmi = weight/(height/100)^2`.
#> Caused by error:
#> ! object 'weight' not found
#> Run `rlang::last_trace()` to see where the error occurred.

Modern tidyverse errors tell you the verb, the argument and the cause. Read from the bottom: object 'weight' not found — the column is called WEIGHT.

traceback()
#> 5: stop("...")
#> 4: my_derive(data)
#> 3: process_domain(x)
#> 2: run_study(config)
#> 1: source("run.R")

Read a traceback bottom to top: 1 is what you called, 5 is where it broke. Your own function is usually the highest-numbered frame you recognise — start there, not in the library internals.

rlang::last_trace()          # richer, with tidyverse context
rlang::last_trace(drop = FALSE)   # include internal frames

Interactive debugging

browser()

Insert it and run. Execution pauses and you get a console inside the function’s environment:

derive_bmi <- function(data) {
  browser()                     # execution stops here
  data |> mutate(BMI = WEIGHT / (HEIGHT/100)^2)
}

At the Browse[1]> prompt:

Command Does
n Next line
s Step into the function call
f Finish the current loop or function
c Continue to the next breakpoint or the end
Q Quit debugging
where Show the call stack
any R code Evaluate in the current environment

The last row is the important one: you can inspect and modify anything.

Conditional breakpoints:

for (i in seq_along(subjects)) {
  if (subjects[i] == "STUDY-001-0042") browser()
  process(subjects[i])
}

debug() and friends

debug(my_function)      # browser() on every call
undebug(my_function)
debugonce(my_function)  # just the next call — usually what you want

debug(dplyr::mutate)    # works on package functions too

Post-mortem

options(error = recover)     # on error, choose a frame to inspect
# ... run the failing code ...
options(error = NULL)        # turn it off

recover presents a menu of frames; pick the one in your code and you land in a browser with that frame’s variables intact. This is the fastest way to debug an error you cannot reproduce on demand.

In RStudio, Debug → On Error → Break in Code does the same thing through the UI, and clicking in the gutter sets a breakpoint without editing the file.

Handling conditions

tryCatch()

result <- tryCatch(
  {
    read_sas("data/raw/dm.sas7bdat")
  },
  error = function(e) {
    cli::cli_warn("Falling back to CSV: {conditionMessage(e)}")
    read_csv("data/raw/dm.csv")
  },
  warning = function(w) {
    cli::cli_inform("Warning during read: {conditionMessage(w)}")
    NULL
  },
  finally = {
    cli::cli_inform("Import attempt complete")
  }
)

tryCatch() exits the protected block when a handler fires. That is right for errors and wrong for warnings — a warning handler means the rest of the expression never runs.

withCallingHandlers()

Use this when you want to observe a condition and let execution continue:

withCallingHandlers(
  {
    for (f in files) process(f)
  },
  warning = function(w) {
    log_warning(conditionMessage(w))
    invokeRestart("muffleWarning")   # suppress it, keep going
  }
)

The distinction in one line: tryCatch() catches and unwinds; withCallingHandlers() handles in place and continues.

try() and possibly()

x <- try(risky_operation(), silent = TRUE)
if (inherits(x, "try-error")) {
  # handle
}

# Cleaner, from purrr
safe_op <- purrr::possibly(risky_operation, otherwise = NA)

Writing good errors

A bad error:

stop("Invalid input")

A good one says what happened, what was expected, and what to do:

library(cli)

validate_adsl <- function(data) {
  required <- c("USUBJID", "TRT01P", "SAFFL", "AGE")
  missing  <- setdiff(required, names(data))

  if (length(missing) > 0) {
    cli_abort(c(
      "{.arg data} is not a valid ADSL dataset.",
      "x" = "Missing required variable{?s}: {.var {missing}}.",
      "i" = "Available variables: {.var {head(names(data), 10)}}{cli::qty(ncol(data))}{?/ and more}.",
      "i" = "Check the ADSL specification in {.path specs/adsl.xlsx}."
    ))
  }

  dupes <- data$USUBJID[duplicated(data$USUBJID)]
  if (length(dupes) > 0) {
    cli_abort(c(
      "ADSL must have one row per subject.",
      "x" = "Found {length(dupes)} duplicate USUBJID value{?s}.",
      "i" = "First few: {.val {head(unique(dupes), 5)}}."
    ))
  }

  invisible(data)
}

cli conventions:

  • First line: the problem, in the imperative or descriptive
  • "x" bullets: what specifically is wrong
  • "i" bullets: context and how to fix it
  • {.arg}, {.var}, {.path}, {.val}, {.fn} for semantic styling
  • {?s} for automatic pluralisation based on the preceding vector

Custom condition classes

For errors that callers need to handle programmatically:

abort_missing_var <- function(missing) {
  rlang::abort(
    message = paste0("Missing variables: ", paste(missing, collapse = ", ")),
    class   = "study_missing_var_error",
    missing = missing
  )
}

tryCatch(
  validate_adsl(bad_data),
  study_missing_var_error = function(e) {
    # e$missing is available programmatically
    cli::cli_inform("Deriving {length(e$missing)} missing variable{?s} instead")
    derive_missing(bad_data, e$missing)
  }
)

This is how you build a pipeline that can recover from specific, anticipated problems while still failing hard on unexpected ones.

Defensive programming

derive_change <- function(data) {
  stopifnot(
    "data must be a data frame"       = is.data.frame(data),
    "AVAL must be present"            = "AVAL" %in% names(data),
    "BASE must be present"            = "BASE" %in% names(data),
    "AVAL must be numeric"            = is.numeric(data$AVAL)
  )

  out <- data |> mutate(CHG = AVAL - BASE)

  # Postcondition — did we do what we said?
  stopifnot(
    "row count changed unexpectedly" = nrow(out) == nrow(data),
    "CHG has unexpected missingness" =
      sum(is.na(out$CHG)) == sum(is.na(data$AVAL) | is.na(data$BASE))
  )

  out
}

Postconditions are underused. Asserting that a derivation did not change the row count, or that a join did not create missing values, catches the class of bug that produces plausible-looking but wrong output.

Logging for batch runs

Interactive debugging is not available at 3 a.m. on a validation server.

library(logger)

log_appender(appender_tee("logs/run.log"))
log_threshold(INFO)
log_layout(layout_glue_generator(
  "{level} [{format(time, '%Y-%m-%d %H:%M:%S')}] {msg}"
))

run_domain <- function(domain) {
  log_info("Starting {domain}")
  t0 <- Sys.time()

  result <- tryCatch(
    process_domain(domain),
    error = function(e) {
      log_error("{domain} failed: {conditionMessage(e)}")
      NULL
    }
  )

  log_info("Finished {domain} in {round(difftime(Sys.time(), t0, units = 'secs'), 1)}s")
  result
}

Log at the boundaries: what started, what finished, how many rows, how long. Do not log inside inner loops — a 400 MB log file is not diagnostic.

Also record the environment at the top of every run:

log_info("R version: {R.version.string}")
log_info("Packages: {paste(names(sessionInfo()$otherPkgs), collapse = ', ')}")
writeLines(capture.output(sessionInfo()), "logs/sessionInfo.txt")

Common mistakes

Mistake Consequence Fix
warning() where the result is wrong Bad output ships Use stop()
suppressWarnings() around a whole block Hides real problems Scope it to one call
Reading traceback top-down Debugging library internals Read bottom-up
tryCatch() with a warning handler Rest of the block never runs withCallingHandlers()
Errors without context Nobody can fix them cli_abort() with x and i bullets
No postconditions Silent wrong results stopifnot() after the derivation
print() left in production code Noise in logs cli_inform() behind a verbosity flag

Exercise 9.1 — Improve an error message

Rewrite this to produce a useful error.

merge_data <- function(x, y) {
  if (!"USUBJID" %in% names(x)) stop("bad input")
  if (!"USUBJID" %in% names(y)) stop("bad input")
  merge(x, y, by = "USUBJID")
}
Show solution 
library(cli); library(dplyr)

merge_data <- function(x, y, key = "USUBJID") {
  if (!is.data.frame(x)) {
    cli_abort("{.arg x} must be a data frame, not {.obj_type_friendly {x}}.")
  }
  if (!is.data.frame(y)) {
    cli_abort("{.arg y} must be a data frame, not {.obj_type_friendly {y}}.")
  }

  for (nm in c("x", "y")) {
    dat <- get(nm)
    if (!key %in% names(dat)) {
      cli_abort(c(
        "Join key {.var {key}} not found in {.arg {nm}}.",
        "x" = "{.arg {nm}} has {ncol(dat)} column{?s}.",
        "i" = "Columns present: {.var {head(names(dat), 8)}}.",
        "i" = "Did you mean {.var {names(dat)[which.min(adist(key, names(dat)))]}}?"
      ))
    }
  }

  if (anyDuplicated(y[[key]]) > 0) {
    n_dup <- sum(duplicated(y[[key]]))
    cli_warn(c(
      "{.arg y} has duplicate keys; the result will have more rows than {.arg x}.",
      "i" = "{n_dup} duplicate {.var {key}} value{?s} found."
    ))
  }

  out <- left_join(x, y, by = key)

  cli_inform("Joined {nrow(x)} x {nrow(y)} rows -> {nrow(out)} rows.")
  out
}
The adist() suggestion is a nice touch — when someone passes a data frame with SUBJID instead of USUBJID, the error names the likely intended column.

Exercise 9.2 — Debug this function

It should return the mean change from baseline per parameter. It returns NaN for some parameters. Find out why using debugging tools rather than by reading.

mean_change <- function(data) {
  data |>
    filter(!is.na(CHG)) |>
    summarise(mean_chg = mean(CHG), .by = PARAMCD)
}
Show solution

Investigation, not inspection:

debugonce(mean_change)
mean_change(adlb)

# At the browser prompt:
Browse[1]> nrow(data)
#> [1] 4896
Browse[1]> data |> count(PARAMCD)
#> # A tibble: 5 x 2
#>   PARAMCD     n
#> 1 ALT       1224
#> 2 AST       1224
#> 3 BILI      1224
#> 4 CREAT     1224
#> 5 GGT          0     <- suspicious
Browse[1]> data |> filter(PARAMCD == "GGT") |> summarise(n_chg = sum(!is.na(CHG)))
#> [1] 0

GGT has rows but every CHG is NA — because no baseline record exists for that parameter, so BASE is NA and CHG = AVAL - BASE is NA throughout. After filter(!is.na(CHG)), the group has zero rows, and mean(numeric(0)) is NaN.

Two fixes, addressing different problems:

# 1. Make the emptiness visible rather than producing NaN
mean_change <- function(data) {
  out <- data |>
    summarise(
      n        = sum(!is.na(CHG)),
      mean_chg = if (any(!is.na(CHG))) mean(CHG, na.rm = TRUE) else NA_real_,
      .by      = PARAMCD
    )

  empty <- out$PARAMCD[out$n == 0]
  if (length(empty) > 0) {
    cli::cli_warn(c(
      "No non-missing change values for {length(empty)} parameter{?s}.",
      "i" = "Affected: {.val {empty}}.",
      "i" = "Check that baseline records exist for these parameters."
    ))
  }
  out
}
# 2. Fix the real problem upstream — assert baselines exist
stopifnot(
  "every parameter must have a baseline record" =
    adlb |>
      summarise(has_base = any(AVISITN == 0), .by = PARAMCD) |>
      pull(has_base) |>
      all()
)
The lesson: NaN from mean() almost always means an empty group, and an empty group almost always means a filter removed more than you expected. The debugger finds this in thirty seconds; reading the code does not.

Exercise 9.3 — Resilient batch processing

Write process_all(domains) that processes each domain, continues past failures, logs everything to a file, and at the end returns a summary tibble of domain, status, rows and elapsed time.

Show solution 
library(purrr); library(dplyr); library(cli)

process_all <- function(domains, log_file = "logs/run.log") {
  fs::dir_create(fs::path_dir(log_file))
  con <- file(log_file, open = "a")
  on.exit(close(con), add = TRUE)

  log_line <- function(...) {
    msg <- paste0(format(Sys.time(), "%Y-%m-%d %H:%M:%S"), " | ", ...)
    writeLines(msg, con)
    cli_inform(msg)
  }

  log_line("Run started. R ", getRversion())

  results <- map(domains, function(d) {
    t0 <- Sys.time()
    log_line("START ", d)

    out <- tryCatch(
      {
        res <- process_domain(d)
        log_line("OK    ", d, " (", nrow(res), " rows)")
        list(status = "success", rows = nrow(res), message = NA_character_, data = res)
      },
      error = function(e) {
        log_line("FAIL  ", d, ": ", conditionMessage(e))
        list(status = "error", rows = NA_integer_,
             message = conditionMessage(e), data = NULL)
      }
    )

    out$elapsed <- as.numeric(difftime(Sys.time(), t0, units = "secs"))
    out$domain  <- d
    out
  })

  summary_tbl <- results |>
    map(\(r) tibble(domain = r$domain, status = r$status,
                    rows = r$rows, elapsed_s = round(r$elapsed, 2),
                    message = r$message)) |>
    list_rbind()

  n_fail <- sum(summary_tbl$status == "error")
  log_line("Run complete. ", nrow(summary_tbl) - n_fail, " succeeded, ", n_fail, " failed.")

  if (n_fail > 0) {
    cli_warn(c(
      "{n_fail} domain{?s} failed.",
      "x" = "{.val {summary_tbl$domain[summary_tbl$status == 'error']}}",
      "i" = "See {.path {log_file}} for details."
    ))
  }

  attr(summary_tbl, "data") <- map(results, "data") |> set_names(domains) |> compact()
  summary_tbl
}

process_all(c("dm", "ae", "lb", "vs"))
#> # A tibble: 4 x 5
#>   domain status  rows elapsed_s message
#>   <chr>  <chr>  <int>     <dbl> <chr>
#> 1 dm     success  306      0.42 NA
#> 2 ae     success 1847      1.13 NA
#> 3 lb     error     NA      0.08 Column `LBSTRESN` can't be converted...
#> 4 vs     success  918      0.61 NA

Design points:

  • on.exit(close(con)) guarantees the log file is closed even if the function errors — always pair resource acquisition with on.exit().
  • Both a machine-readable summary tibble and a human-readable log.
  • The function returns normally even when domains fail, but warns — so an interactive user sees it, and a caller can check any(status == "error").
  • Data is attached as an attribute so the summary prints cleanly.
For a validation environment you would additionally record sessionInfo() and a checksum of each input file.

Recap

  • Error when the result would be wrong; warn only when it is genuinely recoverable
  • Read tracebacks bottom-up and start at your own code
  • debugonce() is the default debugging tool; browser() for conditional stops
  • tryCatch() unwinds; withCallingHandlers() observes and continues
  • cli_abort() with x and i bullets turns an error into a fix
  • Assert postconditions — row counts and missingness — after every derivation
  • Log at boundaries and record sessionInfo() for every batch run

Next: Testing with testthat.

Back to top