understanding false negatives

[bbolker]

tl;dr check appears to fail but not reported. Suggestions for what to check/try next are welcome.

Repo is here if anyone wants to experiment.

I am baffled. With the current development version of broom.mixed (GitHub HEAD) installed, fresh install of revdepcheck 1.0.0.9001 via remotes::, revdep_check() (run in the package directory) reports broomExtra as being fine:

✔ broomExtra 4.3.0                       ── E: 0     | W: 0     | N: 0          

but if I examine broom.mixed/revdep/checks/broomExtra/new/broomExtra.Rcheck/00check.log I see that the log ends with the an error. (full log: 00check.log)

Running R CMD check from the command line reproduces the error:

$ R CMD check broomExtra_4.3.0.tar.gz 
[snip snip]
* checking tests ...
  Running ‘spelling.R’
  Running ‘testthat.R’
 ERROR
Running the tests in ‘tests/testthat.R’ failed.
Last 13 lines of output:
  ══ Failed tests ════════════════════════════════════════════════════════════════
  ── Failure (test-grouped_generics.R:68:5): `grouped_glance()` works ────────────
  dim(lmer_df) (`actual`) not equal to c(2L, 7L) (`expected`).
  
    `actual`: 2 8
  `expected`: 2 7
  ── Failure (test-hybrid_generics.R:21:5): hybrid methods works ─────────────────
  dim(glance_performance(lmm_mod, effects = "fixed")) (`actual`) not equal to c(1L, 10L) (`expected`).
  
    `actual`: 1 11
  `expected`: 1 10
  
  [ FAIL 2 | WARN 3 | SKIP 3 | PASS 17 ]
  Error: Test failures
  Execution halted
* checking PDF version of manual ... OK
* DONE

Status: 1 ERROR

On another machine (MacOS/R 4.1.3) the errors are reported properly.

---

Session info:

sessionInfo()
R Under development (unstable) (2022-03-15 r81903)
Platform: x86_64-pc-linux-gnu (64-bit)
Running under: Pop!_OS 21.04

[snip locale, linear algebra stuff]

attached base packages:
[1] stats     graphics  grDevices utils     datasets  methods   base     

other attached packages:
[1] revdepcheck_1.0.0.9001

loaded via a namespace (and not attached):
 [1] progress_1.2.2       clisymbols_1.2.0     xfun_0.30           
 [4] remotes_2.4.2        rematch2_2.1.2       gargle_1.2.0        
 [7] rcmdcheck_1.4.0      cranlike_1.0.2       vctrs_0.3.8         
[10] crancache_0.0.0.9001 yaml_2.3.5           base64enc_0.1-3     
[13] utf8_1.2.2           blob_1.2.2           rlang_1.0.2         
[16] pkgbuild_1.3.1       pillar_1.7.0         glue_1.6.2          
[19] withr_2.5.0          DBI_1.1.2            rappdirs_0.3.3      
[22] bit64_4.0.5          xopen_1.0.0          sessioninfo_1.2.2   
[25] lifecycle_1.0.1      whoami_1.3.0         memoise_2.0.1       
[28] knitr_1.38           callr_3.7.0          fastmap_1.1.0       
[31] ps_1.6.0             curl_4.3.2           fansi_1.0.3         
[34] Rcpp_1.0.8.3         cachem_1.0.6         desc_1.4.1          
[37] debugme_1.1.0        jsonlite_1.8.0       fs_1.5.2            
[40] bit_4.0.4            hms_1.1.1            digest_0.6.29       
[43] processx_3.5.3       parsedate_1.3.0      gmailr_1.0.1        
[46] rprojroot_2.0.2      cli_3.2.0            tools_4.2.0         
[49] magrittr_2.0.2       tibble_3.1.6         RSQLite_2.2.11      
[52] crayon_1.5.0         pkgconfig_2.0.3      ellipsis_0.3.2      
[55] prettyunits_1.1.1    assertthat_0.2.1     httr_1.4.2          
[58] R6_2.5.1             compiler_4.2.0      

[gaborcsardi]

Weird. Is it reproducible?

[bbolker]

In what sense? It is reproducible on this machine. So far I've only tried it on one other platform and it was not reproducible there.

(I spent a Iittle while digging through the code to try to see where output is parsed to detect errors, etc., but the design is too complex for me to be able to do this in a reasonable amount of time/effort ...)

I thought it might conceivably have something to do with the fact that my R packages are in a directory that's symbolic-linked from elsewhere, but copying everything to a different (no-link) place doesn't seem to make any difference.

[gaborcsardi]

My guess would be that it is a bug in the R CMD check output parser, but if I call the parser manually on your file, then it works well:

❯ rcmdcheck::parse_check("~/Downloads/00check.log")
── R CMD check results ───────────────────────────────────────────────────────────── broomExtra 4.3.0 ────
Duration: 0ms

❯ checking tests ... ERROR
  See below...

1 error ✖ | 0 warnings ✔ | 0 notes ✔

Can you try running this on your machine?

Another thing to make sure is that only base and recommended packages are in .Library. I don't think this is that, but that's just a good thing to do, anyway.

[bbolker]

Ah. I suspect that "only base and recommended packages are in .Library" could very well be my problem ... I didn't particularly know that was not-best-practice ... can you explain what the mechanism is for this breaking revdep_check() ... ?

(Is this documented somewhere? I could easily have missed it ...)

[gaborcsardi]

We create two new isolated libraries, one for the checks with the CRAN version and one for the new version of your package. But we can't really isolate them completely if you also have packages installed in .Library.

I don't see how that could cause this issue, though, but I think in general it is good practice to install your packages in a user library, which revdepcheck can then ignore.

[bbolker]

rcmdcheck::parse_check("checks/broomExtra/new/broomExtra.Rcheck/00check.log")

does produce the expected "1 error" output ... does that rule out the "issue is with .Library" hypothesis?

[gaborcsardi]

Can you try to run this check again, with a clean .Library, to see it is reproducible?

revdep_add(, "broomExtra")
revdep_check()

[bbolker]

I've cleaned up my .Library (there are now only 30 pkgs there, they are all base/recommended AFAICT), and nothing in .Library.site.

Another complication is that the previous issue with the broomExtra package is now fixed on CRAN (so doesn't generate an error any more, can't use it as a "positive control").

So I may have fixed the problem by moving extraneous packages out of .Library/.Library.site (out of curiosity, does no-one use --vanilla any more, or if they do how do they handle the use of non-base/recommended packages?), but now I don't have a known-bad example to try ... (I could try to add a 'feature' to the model that broke a downstream package by design, for testing purposes but this seems tricky ...?)

[gaborcsardi]

out of curiosity, does no-one use --vanilla any more, or if they do how do they handle the use of non-base/recommended packages?

Keep your non-core packages at R_LIBS_USER:

❯ R -q -e 'Sys.getenv("R_LIBS_USER")'
> Sys.getenv("R_LIBS_USER")
[1] "~/Library/R/x86_64/4.1/library"

That is available even with --vanilla:

❯ R -q --vanilla -e '.libPaths()'
> .libPaths()
[1] "/Users/gaborcsardi/Library/R/x86_64/4.1/library"
[2] "/Library/Frameworks/R.framework/Versions/4.1/Resources/library"

[bbolker]

(Sometime I will get back to this.)

The reason I didn't use the R_LIBS_USER option is that I was trying not to have a version-specific library ...

FWIW I've managed a bit of a workaround, for now, by hacking my own comparison:

dir <- "~/R/pkgs/lme4git/lme4/revdep"
get_cmd <- function(subdir) sprintf('find %s -wholename "*/%s/*/00check.log" -exec grep -H ERROR {} \\;', dir, subdir)
old_errs <- system(get_cmd("old"), intern = TRUE)
new_errs <- system(get_cmd("new"), intern = TRUE)
## old_errs <- system('find ~/R/pkgs/lme4git/lme4/revdep -wholename "*/old/*/00check.log" -exec grep -H ERROR {} \\;', intern = TRUE)
##new_errs <- system('find ~/R/pkgs/lme4git/lme4/revdep -wholename "*/new/*/00check.log" -exec grep -H ERROR {} \\;', intern = TRUE)

tmpf <- function(x) {
  x <- stringr::str_extract(x, "[[:alpha:]]+.Rcheck.*")
  x <- stringr::str_remove(x, "/00check.log")
  return(x)
}

setdiff(tmpf(new_errs), tmpf(old_errs))