Test error output in expect_message()

[krlmlr]

with update of golden files to show the problem. Demo of the problem #380 tries to solve.

[hadley]

Why don't I see the problem when running from the console?

with_reporter("summary", test_that("abc", expect_message(f(), NA)))
#> 1
#> Warnings ------------------------------------------------------------------------------------------------
#> 1. abc (@expect-output.R#145) - w
#> 
#> Failed --------------------------------------------------------------------------------------------------
#> 1. Failure: abc --------------------------------------------------------------------------------------------#> -
#> f() showed 1 message.
#> *  m

[krlmlr]

This is what I see in current master (06f1a36):

> f <- function(x) stop("e")
> with_reporter("summary", test_that("abc", expect_message(f(), NA)))

Failed -----------------------------------------------------------------------------------------------------------------------------
1. Error: abc (@expect-output.R#145) ---------------------------------------------------------------------------------------------------
e
1: expect_message(f(), NA)
2: evaluate_promise(object, capture_warnings = FALSE) at /home/muelleki/git/R/testthat/R/expect-output.R:145
3: with_sink(temp, withCallingHandlers(withVisible(code), warning = handle_warning, message = handle_message)) at /home/muelleki/git/R/testthat/R/evaluate-promise.R:56
4: withCallingHandlers(withVisible(code), warning = handle_warning, message = handle_message) at /home/muelleki/git/R/testthat/R/evaluate-promise.R:87
5: withVisible(code)
6: f()
7: stop("e") at :1

DONE ===============================================================================================================================

[krlmlr]

> devtools::session_info()
Session info ---------------------------------------------------------------------------------------------------------------------------
 setting  value                       
 version  R version 3.2.3 (2015-12-10)
 system   x86_64, linux-gnu           
 ui       RStudio (0.99.875)          
 language en_US:en                    
 collate  en_US.UTF-8                 
 tz       <NA>                        
 date     2016-03-04                  

Packages -------------------------------------------------------------------------------------------------------------------------------
 package   * version     date       source                            
 crayon      1.3.1       2015-07-13 CRAN (R 3.2.3)                    
 devtools    1.10.0.9000 2016-03-03 local                             
 digest      0.6.9       2016-01-08 CRAN (R 3.2.3)                    
 lazyeval    0.1.10      2015-01-02 CRAN (R 3.2.3)                    
 magrittr  * 1.6         2016-03-03 local                             
 memoise     1.0.0       2016-01-29 CRAN (R 3.2.3)                    
 praise      1.0.0       2015-08-11 CRAN (R 3.2.3)                    
 R6          2.1.2       2016-01-26 CRAN (R 3.2.3)                    
 Rcpp        0.12.3      2016-01-10 CRAN (R 3.2.3)                    
 roxygen2    5.0.1       2015-11-11 CRAN (R 3.2.3)                    
 rsconnect   0.4.1.11    2016-02-18 Github (rstudio/rsconnect@2419667)
 stringi     1.0-1       2015-10-22 CRAN (R 3.2.3)                    
 stringr     1.0.0       2015-04-30 CRAN (R 3.2.3)                    
 testthat  * 0.11.0.9000 <NA>       local                             
 ulimit      0.0-3       2016-03-03 local                             
 withr       1.0.1       2016-02-04 CRAN (R 3.2.3)                    

[hadley]

This is correct behaviour, right?

with_reporter("summary", test_that("", expect_message(warning("A"), NA)))
#> .
#> Warnings ------------------------------------------------------------------------------------------------
#> 1.  (@expect-output.R#145) - A
#> 
#> DONE ====================================================================================================

with_reporter("summary", test_that("", expect_message(stop("A"), NA)))
#> Failed --------------------------------------------------------------------------------------------------
#> 1. Error:  (@expect-output.R#145) #> ---------------------------------------------------------------------------
#> A
#> 1: expect_message(stop("A"), NA)
#> 2: evaluate_promise(object, capture_warnings = FALSE) at #> /Users/hadley/Documents/devtools/testthat/R/expect-output.R:145
#> 3: with_sink(temp, withCallingHandlers(withVisible(code), warning = handle_warning, message = #> handle_message)) at /Users/hadley/Documents/devtools/testthat/R/evaluate-promise.R:56
#> 4: withCallingHandlers(withVisible(code), warning = handle_warning, message = handle_message) at #> /Users/hadley/Documents/devtools/testthat/R/evaluate-promise.R:87
#> 5: withVisible(code)
#> 6: stop("A")
#> 
#> DONE ====================================================================================================

i.e. the error message and warning are captured and printed even within evaluate_promise().

So is the problem only seen in the reporters test, where we have another sink in play? (Because of the capture.output())

[krlmlr]

Capturing and printing at end is not the problem here; showing the progress indicators is. The progress output misses a W and a 1, respectively, which are shown by #380. The output by the reporter is captured by evaluate_promise(), the following test fails (see 51df2e8 for the output):

with_reporter("summary", {
  test_that("", expect_output(expect_false(FALSE), NA))
})

NB: #380 works here, too: 1150225 .

[hadley]

Ok, got it. Now I can reliably reproduce the problem, I'll think about some other approaches.