Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Failure to build chapter doesn't immediately stop book from building #920

Closed
hadley opened this issue Jul 31, 2020 · 19 comments · Fixed by r-lib/rlang#1053
Closed

Failure to build chapter doesn't immediately stop book from building #920

hadley opened this issue Jul 31, 2020 · 19 comments · Fixed by r-lib/rlang#1053

Comments

@hadley
Copy link
Member

hadley commented Jul 31, 2020

Instead, it fails later when assembling the entire book. For example, in Mastering Shiny if the scaling-test.Rmd chapter has an error, the build process completes but gives a less informative error:

Error in file(con, "r") : cannot open the connection
Calls: <Anonymous> ... mapply -> <Anonymous> -> read_utf8 -> readLines -> file
In addition: Warning message:
In file(con, "r") :
  cannot open file 'scaling-testing.md': No such file or directory
Warning message:
In file.rename(unlist(meta)[move], files_md[move]) :
  cannot rename file 'scaling-testing.md' to '_book/scaling-testing.md', reason 'No such file or directory'

And then to find the source of the error I have to scroll up through a very large amount of output to find:

label: unnamed-chunk-2
Quitting from lines 11-12 (scaling-testing.Rmd) 
Error in eval(expr, envir, enclos) : !
Calls: local ... handle -> withCallingHandlers -> withVisible -> eval -> eval

It would be better to fail earlier.

@hadley
Copy link
Member Author

hadley commented Oct 17, 2020

Just to give you a sense of how annoying this is. Here's a link to a ~3,000 line log file I need to scroll through to figure out why the book failed to build: https://gist.github.com/hadley/04f96d091364fdd198031e078cdb1b1e

@cderv
Copy link
Collaborator

cderv commented Oct 19, 2020

When I try to compile the mastering shiny book, I encounter some errors and it stops the rendering process at basic.Rmd chapter. See here: https://gist.github.com/cderv/fa5c3a105a90a783a5e4defadfcb3499

If I try with bookdown demo book by introducing an error in 02-literature.Rmd for example, it will stop the rendering of the book at this chapter without processing any further.

So it seems it is not something generic about bookdown, and could be specific to a setup.

I was wondering if this was interactive vs non-interactive but running

Rscript.exe -e "bookdown::render_book('index.Rmd', 'bookdown::gitbook')"

in terminal also throws the error at the chapter rendering, and do not build the whole book.

Did I miss anything ? Is this is happening for you no matter the book ?

@hadley
Copy link
Member Author

hadley commented Oct 19, 2020

I normally run the book via RStudio, which generates rmarkdown::render_site(output_format = 'bookdown::pdf_book', encoding = 'UTF-8'). But even if I run bookdown::render_book("index.Rmd", "bookdown::gitbook"), it still continues when I introduce an error in an early chapter.

[master] > packageVersion("bookdown")
[1] ‘0.21’
[master] > packageVersion("rmarkdown")
[1] ‘2.4.4’
[master] > packageVersion("knitr")
[1] ‘1.30’

I have the same problem with R4DS.

@cderv
Copy link
Collaborator

cderv commented Oct 19, 2020

I can't reproduce this unfortunatly - I tried on Windows and on Ubuntu with the Mastering Shiny book by cloning the repo. Everytime I have an error within one the file, it stops the rendering at that file. I tried with render_book and with render_site
It does not process the all book. I don't have a Mac to try but I don't see why this would be OS related.

Steps I did

  • I clone the mastering shiny book
  • I installed all the dependencies
  • I added a chunk in introduction.Rmd under ## What is Shiny ?
```{r}
stop('Creating an error to test issue #920')
```
  • I ran rmarkdown::render_site(output_format = 'bookdown::pdf_book', encoding = 'UTF-8')

here is the whole result I got in the console

> rmarkdown::render_site(output_format = 'bookdown::pdf_book', encoding = 'UTF-8')


processing file: index.Rmd
  |......................................................................| 100%
   inline R code fragments


output file: index.knit.md



processing file: introduction.Rmd
  |....                                                                  |   6%
  ordinary text without R code

  |........                                                              |  11%
label: unnamed-chunk-1 (with options) 
List of 1
 $ include: logi FALSE

  |............                                                          |  17%
  ordinary text without R code

  |................                                                      |  22%
label: unnamed-chunk-2
Quitting from lines 10-11 (introduction.Rmd) 
Error in eval(expr, envir, enclos) : Creating an error to test issue #920
Calls: local ... handle -> withCallingHandlers -> withVisible -> eval -> eval

Execution halted
Error in Rscript_render(f, render_args, render_meta, add1, add2) : 
  Failed to compile introduction.Rmd

Unfortunatly, without being able to reproduce, I will have a hard time looking further - I wonder why I don't encounter this behavior if you have it in two books.

I have this

packageVersion("bookdown")
#> [1] '0.21'
packageVersion("rmarkdown")
#> [1] '2.4.6'
packageVersion("knitr")
#> [1] '1.30'

Do you have special config regarding error in a Rprofile or else ? Could we try to reproduce this in an example using the bookdown-demo example that is simple book ? That may be easier to isolate the issue.

@hadley
Copy link
Member Author

hadley commented Oct 19, 2020

That was useful, thanks! It also failed for me when run with R --vanilla. A bit of experimentation with my .Rprofile found that the problem was:

options(error = rlang::entrace)

I use this to give better tracebacks for base errors, so it would be nice to figure out why this breaks knitr. I'm happy to look into it if you can point me to the code responsible for generating the "Execution halted" error.

@hadley
Copy link
Member Author

hadley commented Oct 19, 2020

I wonder if the root cause is using system() for running code in another process — in callr, I think we automatically bubble up the error message into the parent process so you can access the full trace back.

@cderv
Copy link
Collaborator

cderv commented Oct 19, 2020

Thanks, I'll investigate further with that option activated. I'll get back to you.

@cderv
Copy link
Collaborator

cderv commented Oct 19, 2020

Regarding the Execution halted, I believe this comes from R here:
https://github.com/wch/r-source/blob/a48c6bea1353ce9b79beee0022a19ceeae822162/src/main/main.c#L342

Bookdown call Rscript using system2() to run an R script render_one.R that will call the rmarkdown::render(). Traceback is

> traceback()
8: stop("Failed to compile ", file)
7: Rscript_render(f, render_args, render_meta, add1, add2)
6: render_new_session(files, main, config, output_format, clean, 
       envir, ...)
5: render_book("index.Rmd", output_format = output_format, envir = envir)
4: render_book_script(output_format, envir, quiet)
3: in_dir(input, render_book_script(output_format, envir, quiet))
2: generator$render(input_file = input_file, output_format = output_format, 
       envir = envir, quiet = quiet)
1: rmarkdown::render_site(output_format = "bookdown::pdf_book", 
       encoding = "UTF-8")

That would mean the use of rlang::entrace prevent the error to halt the execution of Rscript and from bookdown point of view the Rscript_render call did not fail.

Could this be the source of the error ?

@yihui
Copy link
Member

yihui commented Oct 19, 2020

I wonder if the root cause is using system() for running code in another process

It is indeed a system() call, and it should thrown an error if the exit status is non-zero. My current guess is that your setting affected the exit status, and it became 0 even if there was an error. I'm not familiar with rlang::entrace, so I'm not sure.

@cderv
Copy link
Collaborator

cderv commented Oct 19, 2020

I can now reproduce by using options(error = rlang::entrace) if I put it in my .Rprofile. That is because bookdown calls Rscript that will load the site files.

I think we narrowed down the issue now. @hadley you know better rlang::entrace, do you see why it happens this way ?

@cderv
Copy link
Collaborator

cderv commented Oct 19, 2020

And here is the reprex of the underlying issue in bookdown

res <- xfun::Rscript(
  shQuote(c("--vanilla", "-e", 'stop("An error")'))
)
res
#> [1] 1
res <- xfun::Rscript(
  shQuote(c("--vanilla", "-e", 'options(error = rlang::entrace); stop("An error")'))
)
res
#> [1] 0

Created on 2020-10-19 by the reprex package (v0.3.0.9001)

First case throws 1 as a result, hence bookdown knows there is an error. Second throws 0 as a result, so bookdown does not know there is an error.

@cderv
Copy link
Collaborator

cderv commented Oct 19, 2020

Last precision: this is not an issue with only system() or system2(). Here is what I got if I use callr::rscript which uses processx::run

temp_r <- tempfile()
xfun::write_utf8(c('stop("An error")'), temp_r)

# will error
res <- callr::rscript(temp_r, "--vanilla")
#> Error: An error
#> Execution halted
#> Error in (function (command = NULL, args = character(), error_on_status = TRUE, : System command 'Rscript' failed, exit status: 1, stdout & stderr were printed

# res was not created
res
#> Error in eval(expr, envir, enclos): object 'res' not found

temp_r <- tempfile()
xfun::write_utf8(c('options(error = rlang::entrace)', 'stop("An error")'), temp_r)
# will not error on our console
res <- callr::rscript(temp_r, "--vanilla")
#> Error: An error
str(res)
#> List of 5
#>  $ status : int 0
#>  $ stdout : chr ""
#>  $ stderr : chr "Error: An error\n"
#>  $ timeout: logi FALSE
#>  $ command: chr [1:3] "/usr/lib/R/bin/Rscript" "/tmp/RtmpV57zmp/file24f25c9e5c96" "--vanilla"

Created on 2020-10-19 by the reprex package (v0.3.0.9001)

First case without rlang, rscript is correctly throwing an error that callr throws to us. Second case, there is no error thrown in R but Rscript was indeed with an error.

@cderv
Copy link
Collaborator

cderv commented Oct 19, 2020

Same in terminal also in Ubuntu

$ /usr/lib/R/bin/Rscript --vanilla  -e "stop('An error')"
Error: An error
Execution halted
$ /usr/lib/R/bin/Rscript --vanilla  -e "options(error = rlang::entrace);stop('An error')"
Error: An error

@hadley
Copy link
Member Author

hadley commented Oct 19, 2020

Yeah, it's ok with callr::r() which is why we haven't noticed this before:

callr::r(function() {
  options(error = rlang::entrace)
  stop("Hi!")
})
#> Error: callr subprocess failed: Hi!

Created on 2020-10-19 by the reprex package (v0.3.0.9001)

I'll figure out what's going on on the entrace side.

@hadley
Copy link
Member Author

hadley commented Oct 19, 2020

(If you run callr::r() interactively, you'll notice that it allows you to get at the traceback of the failure in the child process)

@cderv
Copy link
Collaborator

cderv commented Oct 20, 2020

Oh I did not know that. That is insteresting ! It is clearly useful for debugging. Thanks for sharing.

lionel- added a commit to lionel-/rlang that referenced this issue Oct 20, 2020
lionel- added a commit to r-lib/rlang that referenced this issue Oct 20, 2020
* Preserve exit status when `entrace()` is used as handler

Fixes rstudio/bookdown#920
Closes #1052

* Fix error status in covr

```
out$status not equal to 1L.
1/1 mismatches
[1] 124 - 1 == 123
```

* `system2()` does not have a `timeout` argument in R < 3.5

* Skip test on R < 3.3
@lionel-
Copy link

lionel- commented Oct 20, 2020

Unlike calling handlers, options(error = ) handlers do not have a concept of declining to handle an error. So R sets the status to 0 when such a handler is set.

rlang::entrace() now removes itself from options(error = ) in non-interactive sessions to work around this.

@cderv
Copy link
Collaborator

cderv commented Oct 22, 2020

Thanks @lionel- ! I confirm this is now working from bookdown.
Thanks for the report @hadley.

@cderv cderv closed this as completed Oct 22, 2020
netbsd-srcmastr pushed a commit to NetBSD/pkgsrc that referenced this issue Jan 1, 2021
# rlang 0.4.9

## Breaking changes

* Dropped support for the R 3.2 series.


## New features

* `inject()` evaluates its argument with `!!`, `!!!`, and `{{`
  support.

* New `enquo0()` and `enquos0()` operators for defusing function
  arguments without automatic injection (unquotation).

* `format_error_bullets()` is no longer experimental. The `message`
  arguments of `abort()`, `warn()`, and `inform()` are automatically
  passed to that function to make it easy to create messages with
  regular, info, and error bullets. See `?format_error_bullets` for
  more information.

* New `zap_srcref()` function to recursively remove source references
  from functions and calls.

* A new compat file for the zeallot operator `%<-%` is now available
  in the rlang repository.

* New `%<~%` operator to define a variable lazily.

* New `env_browse()` and `env_is_browsed()` functions. `env_browse()`
  is equivalent to evaluating `browser()` within an environment. It
  sets the environment to be persistently browsable (or unsets it if
  `value = FALSE` is supplied).

* Functions created from quosures with `as_function()` now print in a
  more user friendly way.

* New `rlang_print_backtrace` C callable for debugging from C
  interpreters (#1059).


## Bugfixes and improvements

* The `.data` pronoun no longer skips functions (#1061). This solves a
  dplyr issue involving rowwise data frames and list-columns of
  functions (tidyverse/dplyr#5608).

* `as_data_mask()` now intialises environments of the correct size to
  improve efficiency (#1048).

* `eval_bare()`, `eval_tidy()` (#961), and `with_handlers()` (#518)
  now propagate visibility.

* `cnd_signal()` now ignores `NULL` inputs.

* Fixed bug that prevented splicing a named empty vector with the
  `!!!` operator (#1045).

* The exit status of is now preserved in non-interactive sessions when
  `entrace()` is used as an `options(error = )` handler (#1052,
  rstudio/bookdown#920).

* `next` and `break` are now properly deparsed as nullary operators.


# rlang 0.4.8

* Backtraces now include native stacks (e.g. from C code) when the
  [winch](https://r-prof.github.io/winch/) package is installed and
  `rlang_trace_use_winch` is set to `TRUE` (@krlmlr).

* Compatibility with upcoming testthat 3 and magrittr 2 releases.

* `get_env()` now returns the proper environment with primitive
  functions, i.e. the base namespace rather than the base environment
  (r-lib/downlit#32).

* `entrace()` no longer handles non-rlang errors that carry a
  backtrace. This improves compatibility with packages like callr.

* Backtraces of unhandled errors are now displayed without truncation
  in non-interactive sessions (#856).

* `is_interactive()` no longer consults "rstudio.notebook.executing"
  option (#1031).
@github-actions
Copy link

This old thread has been automatically locked. If you think you have found something related to this, please open a new issue by following the issue guide (https://yihui.org/issue/), and link to this old issue if necessary.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Apr 21, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants