Regression in expect_message between v1.1.0 and v1.2.0

[jozefhajnala]

It seems that there is a regression in expect_message() as it now only captures the first message produced by the tested call: 220c8bf#diff-db01a1b7dcaea272eccac3b208c64a64R481.

As can be seen from this reproducible example:

With tinytest version 1.1.0 - works as expected (captures both messages):

docker run --rm -it r-base Rscript -e " \
 download.file('https://cran.r-project.org/src/contrib/Archive/tinytest/tinytest_1.1.0.tar.gz', destfile = 'tinytest_1.1.0.tar.gz')
 install.packages('tinytest_1.1.0.tar.gz', repos = NULL)
 foo <- function() { message('one'); message('two'); 1 };
 tinytest::expect_message(foo(), 'one')
 tinytest::expect_message(foo(), 'two')
"

relevant output:

----- PASSED      : <-->
 call| tinytest::expect_message(foo(), "one") 
----- PASSED      : <-->
 call| tinytest::expect_message(foo(), "two") 

Whereas with tinytest 1.2.0 (captures only the first message):

docker run --rm -it r-base Rscript -e " \
 download.file('https://cran.r-project.org/src/contrib/tinytest_1.2.0.tar.gz', destfile = 'tinytest_1.2.0.tar.gz')
 install.packages('tinytest_1.2.0.tar.gz', repos = NULL)
 foo <- function() { message('one'); message('two'); 1 };
 tinytest::expect_message(foo(), 'one')
 tinytest::expect_message(foo(), 'two')
"

relevant output:

----- PASSED      : <-->
 call| tinytest::expect_message(foo(), "one") 
----- FAILED[xcpt]: <-->
 call| tinytest::expect_message(foo(), "two")
 diff| The message message
 diff| 'one
 diff| '
 diff| does not match pattern 'two' 

[markvanderloo]

Thanks for reporting Jozef,

The old version of expect_message() also caught output written to stdout which was inaccurate, so now there's a function expect_stdout.

I'll have a look what's the best way to take care of this. tbh this was an effect of the old implementation that was unintended, but I can see its use.

[jozefhajnala]

Thanks for reporting Jozef,

The old version of expect_message() also caught output written to stdout which was inaccurate, so now there's a function expect_stdout.

I'll have a look what's the best way to take care of this. tbh this was an effect of the old implementation that was unintended, but I can see its use.

Thanks for the quick reply! Indeed the issue can be seen in a bit more generic way because of how tryCatch() is used, e.g.

foo <- function() { warning('zero'); message('one'); 1 }
tinytest::expect_message(foo(), 'one')

Will fail, but at least in my understanding and opinion, it should not fail, as the test does not ask anything about warnings, it merely asks whether there is a message that contains 'one' in it arising as an effect of the call.

FWIW, in case this is of interest, I believe testthat's behavior is like so:

foo <- function() { warning('zero'); message('one'); message('two'); 1 }

testthat::expect_message(foo(), 'one')  # Does not fail (warning is shown)
testthat::expect_message(foo(), 'two')  # Does not fail (warning is shown)
testthat::expect_warning(foo(), 'zero') # Does not fail (messages are shown)

[rfhb]

Hi and thanks for tinytest -

(a.) a minimally reproducible example of a test that fails since 1.2.0 is,

tinytest::expect_message(
  {
    message("catch_one")
    message("catch_two")
  },
  pattern = "two"
)

(b.) happy to try to find a fix and submit a PR, but can you confirm the expected behaviour is that all messages emitted by the expression current in expect_message(current, pattern, ...) should be checked against the pattern? This would be in analogy to testthat.

From a quick glance, this is related to no more using sink() in order to separate other sources (cat, print, ...). Perhaps unexpectedly, the message handler as used in tryCatch() in the expect_message function only checks the first message. Possibly, a restart or some other extension of tryCatch() is needed.

Just to flag that this breaking change in 1.2.0 is breaking testing of some of my packages, with a retraction from CRAN looming if not fixed ...

[markvanderloo]

Ok, should be fixed in d8ae400.

If you could give it a quick spin I'd be grateful. I need to run rev dep tests and update so more informative diff messages are created. Otherwise the main semantics should be ok now. I will push to CRAN asap (tomorrow or early this week-ish if all checks out)

[rfhb]

Thanks a lot for rapid work! Works well for me. Issue #51 could be closed for me.

[jozefhajnala]

Thank you, this also fixes my package's R CMD check unit tests failure!
Thanks for the quick fix! Any idea when this could be re-submitted to CRAN?

[markvanderloo]

I will try to resubmit within 3 days. It will probably take a manual intervention at CRAN because of the short time between 1.2.0 and 1.2.1. If you post the names of your packages that are in trouble because of the regression then I can communicate this to the CRAN team.

[rfhb]

Thanks again - my package ctrdata is affected. CRAN maintainers left me time until 2020-05-30, which should suffice without intervention.

[jozefhajnala]

On my end it is languageserversetup (https://cran.r-project.org/package=languageserversetup)
Link to check results: https://cran.r-project.org/web/checks/check_results_languageserversetup.html

I have only until May 20, so a fast (re)submission would help.

Thanks again for the fix!

[markvanderloo]

Cheers again!

All lights are green: revdeps check OK and rhub::check_for_cran() as well.

I just want to re-read and improve the diff messages a bit b/c they become a bit more involved with explicit multi-message testing. I will resubmit tomorrow (on the 18th).

[markvanderloo]

tinytest 1.2.1 is accepted on CRAN. No manual intervention necessary.

What I advise you to do, is to respond to CRAN, with me in cc, stating that the errors in your package were due to a tinytest regression. Now that tinytest 1.2.1 is on CRAN the errors should disappear in the coming days. You can add that we've been in touch and that we've tested the solution.

I'm closing the issue now. Thanks again for your contributions!