revdep_check should fail gracefully when it times out & tell the user to increase timeout

[gavinsimpson]

When doing reverse dependency checks of my gratia package, revdep_check() times out as soon as the installation of all packages needed to check the dependencies and gratia is completed. This is what I see:

> revdepcheck::revdep_check(num_workers = 4)                                                
── INIT ───────────────────────────────────────────────────────────────── Computing revdeps ──
── INSTALL ───────────────────────────────────────────────────────────────────── 2 versions ──
Installing CRAN version of gratia
Installing DEV version of gratia
Installing 8 packages: Rcpp, colorspace, fansi, vctrs, isoband, BH, stringr, tidyr
── CHECK ─────────────────────────────────────────────────────────────────────── 2 packages ──
[0/2] 00:10:29 | ETA:  ?s | (1) dsfa [I]OK: 2                                               
BROKEN: 0
Total time: 11 min
── REPORT ────────────────────────────────────────────────────────────────────────────────────
Writing summary to 'revdep/README.md'
Writing problems to 'revdep/problems.md'
Writing failures to 'revdep/failures.md'
Writing CRAN report to 'revdep/cran.md'
Warning message:
call dbDisconnect() when finished working with a connection

There's nothing there to indicate it timed out and actually didn't do any checks.

I would be nice for the user if revdep_check() mentioned it timed out and didn't proceed as if it had actually done something.

Also, revdep_check() isn't cleaning up after itself when it times out, as evidenced by the warning message.

This is with

─ Session info ─────────────────────────────────────────────────────────────────────────────
 setting  value
 version  R version 4.2.2 Patched (2022-11-10 r83330)
 os       Ubuntu 20.04.5 LTS
 system   x86_64, linux-gnu
 ui       X11
 language en_GB:en
 collate  en_GB.UTF-8
 ctype    en_GB.UTF-8
 tz       Europe/Copenhagen
 date     2023-01-28
 pandoc   2.5 @ /usr/bin/pandoc

─ Packages ─────────────────────────────────────────────────────────────────────────────────
 package     * version    date (UTC) lib source
 assertthat    0.2.1      2019-03-21 [1] RSPM (R 4.2.0)
 base64enc     0.1-3      2015-07-28 [1] RSPM (R 4.2.0)
 bit           4.0.5      2022-11-15 [1] RSPM (R 4.2.2)
 bit64         4.0.5      2020-08-30 [1] RSPM (R 4.2.0)
 blob          1.2.3      2022-04-10 [1] RSPM (R 4.2.0)
 cachem        1.0.6      2021-08-19 [1] RSPM (R 4.2.0)
 callr         3.7.3      2022-11-02 [1] RSPM (R 4.2.2)
 cli           3.6.0      2023-01-09 [1] RSPM (R 4.2.2)
 clisymbols    1.2.0      2017-05-21 [1] RSPM (R 4.2.0)
 crancache     0.0.0.9001 2021-11-04 [1] Github (r-lib/crancache@7ea4e47)
 cranlike      1.0.2      2018-11-26 [1] RSPM (R 4.2.0)
 crayon        1.5.2      2022-09-29 [1] RSPM (R 4.2.1)
 curl          5.0.0      2023-01-12 [1] RSPM (R 4.2.2)
 DBI           1.1.3      2022-06-18 [1] RSPM (R 4.2.0)
 debugme       1.1.0      2017-10-22 [1] RSPM (R 4.2.0)
 desc          1.4.2      2022-09-08 [1] RSPM (R 4.2.1)
 digest        0.6.31     2022-12-11 [1] RSPM (R 4.2.2)
 ellipsis      0.3.2      2021-04-29 [1] RSPM (R 4.2.0)
 fansi         1.0.4      2023-01-22 [1] RSPM (R 4.2.2)
 fastmap       1.1.0      2021-01-25 [1] RSPM (R 4.2.0)
 fs            1.6.0      2023-01-23 [1] RSPM (R 4.2.2)
 gargle        1.2.1      2022-09-08 [1] RSPM (R 4.2.1)
 glue          1.6.2      2022-02-24 [1] RSPM (R 4.2.0)
 gmailr        1.0.1      2021-11-30 [1] RSPM (R 4.2.0)
 hms           1.1.2      2022-08-19 [1] RSPM (R 4.2.1)
 httr          1.4.4      2022-08-17 [1] RSPM (R 4.2.1)
 jsonlite      1.8.4      2022-12-06 [1] RSPM (R 4.2.2)
 knitr         1.42       2023-01-25 [1] CRAN (R 4.2.2)
 lifecycle     1.0.3      2022-10-07 [1] CRAN (R 4.2.1)
 magrittr      2.0.3      2022-03-30 [1] RSPM (R 4.2.0)
 memoise       2.0.1      2021-11-26 [1] RSPM (R 4.2.0)
 parsedate     1.3.1      2022-10-27 [1] RSPM (R 4.2.2)
 pillar        1.8.1      2022-08-19 [1] RSPM (R 4.2.1)
 pkgbuild      1.4.0      2022-11-27 [1] RSPM (R 4.2.2)
 pkgconfig     2.0.3      2019-09-22 [1] RSPM (R 4.2.0)
 prettyunits   1.1.1      2020-01-24 [1] RSPM (R 4.2.0)
 processx      3.8.0      2022-10-26 [1] RSPM (R 4.2.2)
 progress      1.2.2      2019-05-16 [1] RSPM (R 4.2.0)
 ps            1.7.2      2022-10-26 [1] RSPM (R 4.2.2)
 R6            2.5.1      2021-08-19 [1] RSPM (R 4.2.0)
 rappdirs      0.3.3      2021-01-31 [1] RSPM (R 4.2.0)
 rcmdcheck     1.4.0      2021-09-27 [1] RSPM (R 4.2.0)
 Rcpp          1.0.10     2023-01-22 [1] RSPM (R 4.2.2)
 rematch2      2.1.2      2020-05-01 [1] RSPM (R 4.2.0)
 remotes       2.4.2      2021-11-30 [1] RSPM (R 4.2.0)
 revdepcheck * 1.0.0.9001 2022-01-23 [1] Github (r-lib/revdepcheck@b855323)
 rlang         1.0.6      2022-09-24 [1] RSPM (R 4.2.1)
 rprojroot     2.0.3      2022-04-02 [1] RSPM (R 4.2.0)
 RSQLite       2.2.20     2022-12-22 [1] RSPM (R 4.2.2)
 sessioninfo   1.2.2      2021-12-06 [1] RSPM (R 4.2.0)
 tibble        3.1.8      2022-07-22 [1] RSPM (R 4.2.1)
 utf8          1.2.2      2021-07-24 [1] RSPM (R 4.2.0)
 vctrs         0.5.2      2023-01-23 [1] RSPM (R 4.2.2)
 whoami        1.3.0      2019-03-19 [1] RSPM (R 4.2.0)
 withr         2.5.0      2022-03-03 [1] RSPM (R 4.2.0)
 xfun          0.36       2022-12-21 [1] RSPM (R 4.2.2)
 xopen         1.0.0      2018-09-17 [1] RSPM (R 4.2.0)
 yaml          2.3.7      2023-01-23 [1] RSPM (R 4.2.2)

 [1] /home/au690221/R/x86_64-pc-linux-gnu-library/4.2
 [2] /usr/local/lib/R/site-library
 [3] /usr/lib/R/site-library
 [4] /usr/lib/R/library

────────────────────────────────────────────────────────────────────────────────────────────

[maksymiuks]

I'd like to escalate this issue, as after looking through the code base some parts of this functionality look buggy and/or contradictory to what the documentation says.

Let's start with the timeout, in general, this is what the documentation says:

revdepcheck/R/revdepcheck.R

Lines 39 to 40 in a52c7cb

	#' @param timeout Maximum time to wait (in seconds) for `R CMD check` to
	#' complete. Default is 10 minutes.

it clearly says that timeout is applied to the R CMD check only, however currently by how run_event_loop function is designed (https://github.com/r-lib/revdepcheck/blob/main/R/event-loop.R#L62) timeout is applied to all revdepcheck steps (executed during revdepcheck:::revdep_run), in particular, it also could be applied to the deps_installing step. It should either be clearly stated that timeout is applied to all steps, not only R CMD Check or review the code base and exclude other steps than "checking" from timeout.

However, it is not the only issue with the timeout I've identified. Let's take a look at the event loop fragment and check_for_timeouts function

revdepcheck/R/event-loop.R

Lines 60 to 64 in a52c7cb

	while (1) {
	"!DEBUG event loop iteration, `length(state$workers)` workers"
	check_for_timeouts(state)
	if (are_we_done(state)) break;
	state$progress_bar$tick(0, tokens = list(packages = checking_now(state)))

revdepcheck/R/event-loop.R

Lines 83 to 93 in a52c7cb

	check_for_timeouts <- function(state) {
	now <- Sys.time()
	for (w in state$workers) {
	if (now - w$process$get_start_time() > state$options$timeout &&
	w$process$is_alive()) {
	"!DEBUG Killing worker for package `w$package`"
	w$killed <- TRUE
	w$process$kill(close_connections = FALSE)
	}
	}
	}

We see thatcheck_for_timeouts does not return anything, and even if it did, it is not assigned in the event loop, meaning information that the worker was killed (https://github.com/r-lib/revdepcheck/blob/main/R/event-loop.R#L89) is completely lost as in this case assignment happens to the copy of the state list. This creates a nightmare to debug because later in the deps_install_done timeout cannot be gracefully handled:

revdepcheck/R/deps-install.R

Lines 115 to 124 in a52c7cb

	rresult <- if (isTRUE(worker$killed)) {
	"Process was killed while installing dependencies"
	status <- "TIMEOUT"
	} else {
	status <- "PREPERROR"
	tryCatch(
	worker$process$get_result(),
	error = function(e) conditionMessage(e)
	)
	}

as value worker$killed does not exist so we end up with "PREPERROR" what clearly indicated timeout was not an issue (as got to the else statement) and additionally leaves {"class":["list"],"object":{"stdout":[""],"stderr":[""],"errormsg":["! callr subprocess failed: could not start R, exited with non-zero status, has crashed or was killed"]}} as error message in the sqlite db which also does not help as the same error would be shown for other problems like potential memory issues for instance.

The bug is easy to fix. The only thing required is to make check_for_timeouts return an altered state object and in the event loop assign that to the state variable.

That being said I fully support the previous suggestion to not mark timed-out packages as DONE. It creates a false positive assumption that everything was all right and the only indicator that potentially none of the packages run is README.md or raw sql results.

I'm happy to help with MR to address this issue if you agree with my findings.