renv::status() not showing reason for "The project is out-of-sync message"

[dbrandt2012]

I'm using renv to manage packages used in creating a custom package for my company. The library is stored within the project at '~R/XXX/renv/library/'. The root and cache are located elsewhere in a shared folder on the RStudio servers.

I upgraded renv from 0.17.3 to 1.0.0, recorded the new version in the lockfile, reactived renv, and restarted my environment. Previously, when starting a new session I would receive the normal message:

* Project '~/R/XXX' loaded. [renv 0.17.3]

Now after upgrading to renv 1.0.0 I receive the following at start up:

- Project '~/R/XXX' loaded. [renv 1.0.0]
- The project is out-of-sync -- use `renv::status()` for details.
Warning message:
renv took longer than expected (20 seconds) to activate the sandbox.

The sandbox can be disabled by setting:

    RENV_CONFIG_SANDBOX_ENABLED = FALSE

within an appropriate start-up .Renviron file.

See `?renv::config` for more details. 

renv::status() and renv::restore() reported no issues whether RENV_CONFIG_SANDBOX_ENABLED was set to TRUE or FALSE, although startup was significantly faster when not using the sandbox. I didn't notice any delays at startup in renv 0.17.3 like I am now.

[kevinushey]

Thanks for the bug report! I haven't been able to reproduce the sandbox warning yet. Does it reproduce consistently for you?

Are you able to share the project sources wherein you're seeing the issue with status()?

[dbrandt2012]

@kevinushey the sandbox issue is consistent for me. I do have a TON of packages in the library so I may need to remove any unused packages.

Which project sources would be useful? I'll try to figure out how to share a compliant reprex.

[salim-b]

I get the sandbox warning – without the out-of-sync notice – on a selfhosted RStudio server instance, but not locally. The R startup output from the server:

- Project '~/git_repos/ipsa_paper' loaded. [renv 1.0.0]
Warning message:
renv took longer than expected (20 seconds) to activate the sandbox.

The sandbox can be disabled by setting:

    RENV_CONFIG_SANDBOX_ENABLED = FALSE

within an appropriate start-up .Renviron file.

See `?renv::config` for more details. 

[kevinushey]

I think this is related to the renv watchdog -- the issue likely also goes away if you use

RENV_CONFIG_WATCHDOG_ENABLED = FALSE

in your project .Renviron. I need to figure out what the underlying trigger here is, but I noticed this happening in a project that was using renv 0.17.3 after it was upgraded to renv 1.0.0.

[kevinushey]

Which project sources would be useful? I'll try to figure out how to share a compliant reprex.

The most ideal case would be to share a project on GitHub wherein I can reproduce the issue by following some steps after cloning the repository.

[salim-b]

I think this is related to the renv watchdog -- the issue likely also goes away if you use

RENV_CONFIG_WATCHDOG_ENABLED = FALSE

in your project .Renviron.

I guess you're right about the watchdog being the culprit. Setting RENV_WATCHDOG_ENABLED=FALSE makes the warning disappear (same as setting RENV_CONFIG_SANDBOX_ENABLED=FALSE). But note that the environment variable is called RENV_WATCHDOG_ENABLED, not RENV_CONFIG_WATCHDOG_ENABLED. 😉

Also there is no documentation about the watchdog on https://rstudio.github.io/renv/ ... what are the consequences of disabling it?

I need to figure out what the underlying trigger here is, but I noticed this happening in a project that was using renv 0.17.3 after it was upgraded to renv 1.0.0.

Would it help if I provide you a public Git repo where the issue currently occurs to clone and inspect it?

[kevinushey]

Also there is no documentation about the watchdog on https://rstudio.github.io/renv/ ... what are the consequences of disabling it?

The watchdog is used to ensure that file locks are deleted if an R process crashes unexpectedly. Without the watchdog process running, you might end up with R processes hanging for some period of time if they see "stale" file locks left behind by an R process that exited unexpectedly.

Would it help if I provide you a public Git repo where the issue currently occurs to clone and inspect it?

That would be perfect.

[salim-b]

@kevinushey Thanks for the explanation!

An renv project where the issue currently occurs is found under input/report/ in this public GitLab repository. I've disabled the renv watchog in the .Rprofile file to avoid the startup delay. Just remove that line and the issue occurs – but as mentioned not on every machine, I could only observe it on our RStudio server instance so far. But I could grant you access to that server if it would help :)

[kevinushey]

Thanks! I tried reproducing but everything looks okay on my end:

- Project '~/scratch/rdb.report/input/report' loaded. [renv 1.0.0]
- The library is already synchronized with the lockfile.
✔ Restoring renv state done. Ready to go. [664ms]
> renv::status()
No issues found -- the project is in a consistent state.

This was after cloning the project and then using renv::restore() to restore the project library.

Can you reproduce from a terminal R session (rather than RStudio)? One thing you could try would be adding this to your .Rprofile, before renv/activate.R is sourced:

setHook("renv::autoload", function(...) {
  debug(renv:::renv_load_report_synchronized)
})

Then, after stepping through a bit with n, could share the contents of the info object after it's created from calling renv::status(); e.g. with saveRDS(info, file = "info.rds") and sharing the created info.rds file. Or perhaps jsonlite::toJSON(info, force = TRUE) if sharing a JSON text file is more straightforward.

You might need to run the aforementioned hook in a terminal rather than RStudio; RStudio might not play well with debug hooks set up on startup.

[salim-b]

I tried reproducing but everything looks okay on my end:

Yes, that's also what I observe locally. The renv startup delay and warning message only appears on the RStudio server.

---

I've retrieved the info object on the RStudio server using the debug hook as you suggested. It gave the same result from both RStudio as well as from a system terminal.

info object as JSON (prettified; from server)

But there is no startup delay and warning message when running from the terminal. It only happens in RStudio.

The whole server config (excl. sensitive stuff) is found in this GitLab repo if relevant (see the Dockerfile).

---

When I retrieve the info object the same way on my local machine (where no renv startup delay and warning happens at all), the info object shows some differences in R packages that are installed by the Debian package r-recommended (foreign, KernSmooth, Matrix, mgcv, spatial):

info object as JSON (prettified; local)

[salim-b]

Just a small update: Issue stays the same with renv v1.0.1.

With RENV_WATCHDOG_ENABLED = TRUE and the new setting RENV_STARTUP_DIAGNOSTICS = TRUE, the output looks like this on the RStudio server instance (issue still doesn't occur on my local machine):

Restarting R session...

- renv took 0.005 secs to run the autoloader.
- Profile: /tmp/RtmpsCNM2i/renv-startup-47d19ed98c4.Rprof
$by.self
[1] self.time  self.pct   total.time total.pct 
<0 rows> (or 0-length row.names)

$by.total
[1] total.time total.pct  self.time  self.pct  
<0 rows> (or 0-length row.names)

$sample.interval
[1] 0.02

$sampling.time
[1] 0

- Project '~/git_repos/rdb.report/input/report' loaded. [renv 1.0.1]
Warning message:
renv took longer than expected (10 seconds) to activate the sandbox.

The sandbox can be disabled by setting:

    RENV_CONFIG_SANDBOX_ENABLED = FALSE

within an appropriate start-up .Renviron file.

See `?renv::config` for more details. 

[kevinushey]

the output looks like this on the RStudio server instance (issue still doesn't occur on my local machine):

By any chance does the issue go away if you install renv 1.0.1 into your user library as well as the project library?

[salim-b]

By any chance does the issue go away if you install renv 1.0.1 into your user library as well as the project library?

Yes, indeed! Is this intended behaviour?

[kevinushey]

It's not, but at least now I know where the issue lies -- thank you!

[kevinushey]

Thinking again, I believe this issue should be resolved by abe8125. I'll be pushing a patch release of renv shortly, so the upcoming patch will pick up that fix.

If you're willing to test, you could try:

1. Removing renv from your user library,
2. Installing the development version of renv in your project library,
3. Running the test once more to see if you see the sandbox delay.

[salim-b]

Awesome, thank you! I can confirm that the patch resolves the issue. ☺️

[kevinushey]

Fantastic; thanks for reporting back! I've submitted renv 1.0.2 to CRAN so if all goes well that fix should be available shortly.

[salim-b]

@kevinushey Sorry to be the bearer of bad news again, but I think renv 1.0.2 still didn't fully resolve the renv took longer than expected (10 seconds) to activate the sandbox issue: Now it occurs when rendering a Quarto document in an RStudio background job (i.e. quarto::quarto_render(as_job = TRUE)) in a project that uses renv 1.0.2. This now happens regardless whether a matching renv version is installed globally (i.e. in the user library) or not.

[kevinushey]

@salim-b, thanks for the bug report -- this is unfortunate. I can reproduce with:

code <- quote(1 + 1)
script <- tempfile("example-", fileext = ".R")
writeLines(deparse(code), con = script)
rstudioapi::jobRunScript(script, name = "test", workingDir = getwd())

within an renv project. I'm going to investigate further.

[kevinushey]

I believe ac7126d should fix this issue; would you be able to confirm? Sorry again for the trouble :-/

[salim-b]

I believe ac7126d should fix this issue; would you be able to confirm?

Thanks for the fast response and fix! It seems fine now.