tests/knitr.R mismatch

[jangorecki]

reported on CRAN now. https://cran.r-project.org/web/checks/check_results_data.table.html
none of the commits mentioned in 1.16.2 issue seems to be providing the fix, so likely the issue is still there (fyi @TysonStanley )

    Comparing ‘knitr.Rout’ to ‘knitr.Rout.save’ ...28,38d27
  < ```
  < 
  < ```
  < ##        x     y     z
  < ##    <int> <int> <int>
  < ## 1:     1     4     7
  < ## 2:     2     5     8
  < ## 3:     3     6     9
  < ```
  < 
  < ``` r
  52,62d40
  < ```
  < 
  < ```
  < ##        x     y     z     a
  < ##    <int> <int> <int> <int>
  < ## 1:     1     4    10     1
  < ## 2:     2     5    11     1
  < ## 3:     3     6    12     1
  < ```
  < 
  < ``` r

[MichaelChirico]

Copying @TysonStanley 's comment here:

Looks like the difference is that DT[, z := 7:9] is printing in the knitr output.

  < ##        x     y     z
  < ##    <int> <int> <int>
  < ## 1:     1     4     7
  < ## 2:     2     5     8
  < ## 3:     3     6     9

[MichaelChirico]

Copying Tyson's next comment here too:

Not sure why it's not showing up in CI checks at all. It's a note on Linux and windows on CRAN and it showed up on MacOS for me here.

[MichaelChirico]

I'm not reproducing it locally, and we don't see it on GHA nor on GitLab CI logs. Makes it a lot tougher to debug.

@TysonStanley, can you confirm your R, knitr and data.table versions where you're seeing the issue? And maybe try doing trace(data.table:::shouldPrint, at=3, quote(message("ret=", ret))) and check the output of the knitr test again?

[TysonStanley]

Only happens when I'm accessing R directly in the terminal but this is what happened when I inserted that code into the .Rmd before knitting:

``` r
require(data.table)              # print?
trace(data.table:::shouldPrint, at=3, quote(message("ret=", ret)))
```

```
## [1] "shouldPrint"
```

``` r
DT = data.table(x=1:3, y=4:6)    # no
DT                               # yes
```

```
## Tracing shouldPrint(x) step 3
```

```
##        x     y
##    <int> <int>
## 1:     1     4
## 2:     2     5
## 3:     3     6
```

``` r
DT[, z := 7:9]                   # no
```

```
## Tracing shouldPrint(x) step 3
```

```
##        x     y     z
##    <int> <int> <int>
## 1:     1     4     7
## 2:     2     5     8
## 3:     3     6     9
```

``` r
print(DT[, z := 10:12])          # yes
```

```
## Tracing shouldPrint(x) step 3
```

```
##        x     y     z
##    <int> <int> <int>
## 1:     1     4    10
## 2:     2     5    11
## 3:     3     6    12
```

``` r
if (1 < 2) DT[, a := 1L]         # no
```

```
## Tracing shouldPrint(x) step 3
```

```
##        x     y     z     a
##    <int> <int> <int> <int>
## 1:     1     4    10     1
## 2:     2     5    11     1
## 3:     3     6    12     1
```

``` r
DT                               # yes
```

```
## Tracing shouldPrint(x) step 3
```

```
##        x     y     z     a
##    <int> <int> <int> <int>
## 1:     1     4    10     1
## 2:     2     5    11     1
## 3:     3     6    12     1
```
Some text.

The DT[, z := 10:12] definitely triggers shouldPrint(x). Is there more information I can extract? Should I set verbose = TRUE for these as well?

[MichaelChirico]

@TysonStanley ah, it looks like the ret= part is not printing to the right place. What about using cat(sprintf("ret=%s\n", ret)) instead of message()?

[TysonStanley]

``` r
require(data.table)              # print?
trace(data.table:::shouldPrint, at=3, quote(cat(sprintf("ret=%s\n", ret))))
```

```
## [1] "shouldPrint"
```

``` r
DT = data.table(x=1:3, y=4:6)    # no
DT                               # yes
```

```
## Tracing shouldPrint(x) step 3 
## ret=TRUE
##        x     y
##    <int> <int>
## 1:     1     4
## 2:     2     5
## 3:     3     6
```

``` r
DT[, z := 7:9]                   # no
```

```
## Tracing shouldPrint(x) step 3 
## ret=FALSE
##        x     y     z
##    <int> <int> <int>
## 1:     1     4     7
## 2:     2     5     8
## 3:     3     6     9
```

``` r
print(DT[, z := 10:12])          # yes
```

```
## Tracing shouldPrint(x) step 3 
## ret=FALSE
##        x     y     z
##    <int> <int> <int>
## 1:     1     4    10
## 2:     2     5    11
## 3:     3     6    12
```

``` r
if (1 < 2) DT[, a := 1L]         # no
```

```
## Tracing shouldPrint(x) step 3 
## ret=FALSE
##        x     y     z     a
##    <int> <int> <int> <int>
## 1:     1     4    10     1
## 2:     2     5    11     1
## 3:     3     6    12     1
```

``` r
DT                               # yes
```

```
## Tracing shouldPrint(x) step 3 
## ret=TRUE
##        x     y     z     a
##    <int> <int> <int> <int>
## 1:     1     4    10     1
## 2:     2     5    11     1
## 3:     3     6    12     1
```
Some text.

[aitap]

It looks like it's caused by an upgrade of something in the knitr stack. Reinstalling recursive dependencies of data.table made it possible to reproduce locally for me.

print.data.table performs additional tests on sys.calls() if shouldPrint returns FALSE:

data.table/R/print.data.table.R

Lines 24 to 41 in bb9faf6

	if (!shouldPrint(x)) {
	# := in [.data.table sets .global$print=address(x) to suppress the next print i.e., like <- does. See FAQ 2.22 and README item in v1.9.5
	# The issue is distinguishing "> DT" (after a previous := in a function) from "> DT[,foo:=1]". To print.data.table(), there
	# is no difference. Now from R 3.2.0 a side effect of the very welcome and requested change to avoid silent deep copy is that
	# there is now no longer a difference between > DT and > print(DT). So decided that DT[] is now needed to guarantee print; simpler.
	# This applies just at the prompt. Inside functions, print(DT) will of course print.
	# Other options investigated (could revisit): Cstack_info(), .Last.value gets set first before autoprint, history(), sys.status(),
	# topenv(), inspecting next statement in caller, using clock() at C level to timeout suppression after some number of cycles
	SYS = sys.calls()
	if (length(SYS) <= 2L || # "> DT" auto-print or "> print(DT)" explicit print (cannot distinguish from R 3.2.0 but that's ok)
	( length(SYS) >= 3L && is.symbol(thisSYS <- SYS[[length(SYS)-2L]][[1L]]) &&
	as.character(thisSYS) == 'source') || # suppress printing from source(echo = TRUE) calls, #2369
	( length(SYS) > 3L && is.symbol(thisSYS <- SYS[[length(SYS)-3L]][[1L]]) &&
	as.character(thisSYS) %chin% mimicsAutoPrint ) ) {
	return(invisible(x))
	# is.symbol() temp fix for #1758.
	}
	}

Adding

trace(data.table:::print.data.table, quote(print(SYS)), at = list(c(5,3,3)))

...yields:

``` r
if (1 < 2) DT[, a := 1L]         # no
```

```
## Tracing print.data.table(value) step 5,3,3
<snip>
## [[30]]
## handler$value(value, visible)
##
## [[31]]
## fun(x, options = options)
##
## [[32]]
## withVisible(knit_print(x, ...))
##
## [[33]]
## knit_print(x, ...)
##
## [[34]]
## knit_print.default(x, ...)
##
## [[35]]
## normal_print(x)
##
## [[36]]
## render(x, visible = TRUE, envir = parent.frame())
##
## [[37]]
## evalq(print(value), envir = print_env)
##
## [[38]]
## evalq(print(value), envir = print_env)
##
## [[39]]
## print(value)
##
## [[40]]
## print.data.table(value)
##
##        x     y     z     a
##    <int> <int> <int> <int>
## 1:     1     4    10     1
## 2:     2     5    11     1
## 3:     3     6    12     1
```

Here, length(SYS) is very much > 3, but the symbol at length(SYS)-2 is not source, nor the one at length(SYS)-3 is %chin% data.table:::mimicsAutoPrint (which is knit_print.default).

Previously, the stack looked differently and, indeed, knit_print.default was present at position length(SYS)-3:

## [[23]]
## withVisible(value_fun(ev$value, ev$visible))
##
## [[24]]
## value_fun(ev$value, ev$visible)
##
## [[25]]
## fun(x, options = options)
##
## [[26]]
## withVisible(knit_print(x, ...))
##
## [[27]]
## knit_print(x, ...)
##
## [[28]]
## knit_print.default(x, ...)
##
## [[29]]
## normal_print(x)
##
## [[30]]
## print(x)
##
## [[31]]
## print.data.table(x)

Time to add more knitr workarounds?

[tdhock]

fixed by #6563