Unit tests fail on R-devel: Error (test_build_log_entry.R:69:3): stack trace is correct + Failure (test_build_log_output.R:57:3): log output is correct

[aryoda]

Prof. Brian Ripley sent an email on Tue, 11 May 2021:

Dear maintainer,

Please see the problems shown on
https://cran.r-project.org/web/checks/check_results_tryCatchLog.html.

Please correct before 2021-05-25 to safely retain your package on CRAN.

The CRAN Team

According to the logs the unit tests fail only on R-devel and R patched:

Flavor	Version	Tinstall	Tcheck	Ttotal	Status	Flags
r-devel-linux-x86_64-debian-clang	1.2.1	2.01	35.14	37.15	ERROR
r-devel-linux-x86_64-debian-gcc	1.2.1	1.90	27.48	29.38	ERROR
r-devel-linux-x86_64-fedora-clang	1.2.1			53.43	ERROR
r-devel-linux-x86_64-fedora-gcc	1.2.1			55.68	ERROR
r-devel-windows-ix86+x86_64	1.2.1	6.00	61.00	67.00	ERROR
r-devel-windows-x86_64-gcc10-UCRT	1.2.1				ERROR
r-patched-linux-x86_64	1.2.1	2.32	34.28	36.60	ERROR
r-patched-solaris-x86	1.2.1			67.00	ERROR

The failing unit tests are these three ones:

── Error (test_build_log_entry.R:69:3): stack trace is correct ─────────────────
     Error: invalid 'x' type in 'x && y'
     Backtrace:
     █
     1. └─testthat::expect_equal(...) test_build_log_entry.R:69:2
     2. ├─testthat::compare(act$val, exp$val, ...)
     3. └─testthat:::compare.character(act$val, exp$val, ...)

and

     ── Failure (test_build_log_output.R:52:3): log output is correct ───────────────
     `out2` not equal to `expected2`.

and

   ── Failure (test_build_log_output.R:57:3): log output is correct ───────────────
     `out3` not equal to `expected2`.

[aryoda]

Brodie Gaslam wrote an email on Wed, 12 May 2021 and pointed me to the cause of the problem (thanks a lot for this execellent analysis and work :-)

Dear Juergen,

Your package tryCatchLog has started to fail on CRAN:

This almost certainly due to recent changes to r-devel which change the
display-width treatment of control characters. For example, it used to be
the case that:

nchar("hello\n", type="width")
## 1 6

But now:

nchar("hello\n", type="width")
## 1 5

This is because the trailing newline is now treated as zero width.
Character counts (as opposed to display width calculations) are
unaffected:

nchar("hello\n")
## 1 6

From the documentation for ?nchar we see:

Control characters are given width zero in multi-byte locales, but
are usually given width one in single-byte ones (as their
positions are often undefined and maybe re-used as in CP1252 vs
Latin-1).

It turns out R was incorrectly implementing the "width zero" part.

You are impacted because you use strtrim, which internally uses
similar logic to nchar(, type="width"). ?strtrim also states:

‘Width’ is interpreted as the display width in a monospaced font.
What happens with non-printable characters (such as backspace,
tab) is implementation-dependent and may depend on the locale
(e.g., they may be included in the count or they may be omitted).

This affects tests which involving newlines in the text.

Unfortunately because the width of control characters is not strictly
defined, it is possible that new versions of R, or the current version of
R run in different locales, could produce different outcomes. Thus, to
avoid more headaches from this I would encourage you to update your tests
in such a way that they are not dependent on what the display width of
control characters such as newlines is (or display width at all).

In your specific case it seems you could replace newlines by spaces and
run strtrim on that, possibly recording the character locations of
newlines and re-inserting them if preserving them is important. Or just
use substr which operates on characters and will be unaffected, but will
truncate words.

Best,

Brodie.

[aryoda]

First diagnoses via debugging using R-devel on Ubuntu 20.04:

This problem is no bug in tryCatchLog but caused by the unit tests with changed actual values due to a bug fix in R-devel
(in other word: the curse of extensive unit testing ;-)

── Error (test_build_log_entry.R:69:3): stack trace is correct ─────────────────
     Error: invalid 'x' type in 'x && y'

This misleading error message is caused by a wrong function call parameter in this unit test line:

https://github.com/aryoda/tryCatchLog/blob/master/tests/testthat/test_build_log_entry.R#L69

I forgot the info = and this problem was not occurring until the expect_equal check fails.

The correct syntax is:

expect_equal(log.entry$full.stack.trace, expected_FST, info = "full stack trace")

After fixing this all three unit tests fail for the same reason as described by Brodie above:

Due to the new width counting of (trailing?) new lines which cause a different result then expected before (defined via "old" R versions) as soon as the stack trace string is "cut" to the given width set by

options("width" = 129)

Example (simplified excerpt of a stack trace line of the second failing unit test):

Expected:

    msg <- condit

Actual with R-devel:

    msg <- conditi

Observe that the actual result contains now one more character since the trailing new line is no longer counted as contributing to the width (count) where the output shall be cut if it is longer!

[aryoda]

Approach to fix the failing unit tests:

• I do not want to change the standard R logic of how to calculate print widths
• Therefore I use an if (nchar("hello\n", type = "width") == 5) ... in the unit tests to check for existence of the fix in base R
  and use the according expected values.

[aryoda]

The above approach did not work as expected:

• in R 3.6.1 nchar("hello\n") returns 6 and the old unit tests worked
• in R 4.1.0 nchar("hello\n") still returns 6 but the old unit tests did no longer work because strtrim seems to count newlines differently now
• in R-devel (2021-05-16 r80303) nchar("hello\n") returns 5 and the old unit tests did no longer work because strtrim seems to count newlines differently now

I did not want to introduce 3-way if-branching in the unit tests and decided to increment the maximum value of the maxwidth argument in limitedLabels() from 1000 to 2000 so that unit test strings are no longer cut at a certain position which is different depending on the R version.

Now the units do work again on the above R versions.

[aryoda]

I have submitted the new package version 1.2.3 at CRAN today

[aryoda]

After fixing an moved link and re-submitting the package as version 1.2.4 the updated version is on CRAN now since 10 minutes :-)

https://cran.r-project.org/web/packages/tryCatchLog/index.html

Thanks a lot again to Brodie Gaslam for his valuable work to narrow down the cause of the problems, this really saved me a lot of time :-)

[aryoda]

See release 1.2.4:

https://github.com/aryoda/tryCatchLog/releases/tag/v1.2.4_CRAN