string difference not visible due to "elided lines"

[pohly]

Sometimes I get output where the relevant difference between two strings is not shown because one or both get truncated with elided lines. Example:

        -           SystemErr: Inverse(simplify, string(
        -               """
        -               > Enter [BeforeEach] e2e - cleanup_test.go:54 <time>
        -               INFO: before
        -               < Exit [BeforeEach] e2e - cleanup_test.go:54 <time>
        -               > Enter [BeforeEach] e2e - set up framework | framework.go:xxx <time>
        -               STEP: Creating a kubernetes client - framework.go:xxx <time>
        -               INFO: >>> kubeConfig: yyy/kube.config
        -               STEP: Building a namespace api object, basename test-namespace - framework.go:xxx <time>
        -               INFO: Skipping waiting for service account
        -               < Exit [BeforeEach] e2e - set up framework | framework.go:xxx <time>
        -               > Enter [BeforeEach] e2e - cleanup_test.go:98 <time>
        -               INFO: extension before
        -               < Exit [BeforeEach] e2e - cleanup_test.go:98 <time>
        -               > Enter [BeforeEach] e2e - cleanup_test.go:62 <time>
        -               INFO: before #1
        -               < Exit [BeforeEach] e2e - cleanup_test.go:62 <time>
        -               > Enter [BeforeEach] e2e - cleanup_test.go:66 <time>
        -               INFO: before #2
        -               < Exit [BeforeEach] e2e - cleanup_test.go:66 <time>
        -               > Enter [It] works - cleanup_test.go:81 <time>
        -               [FAILED] failure
        -               In [It] at: cleanup_test.go:90 <time>
        -               < Exit [It] works - cleanup_test.go:81 <time>
        -               > Enter [AfterEach] e2e - cleanup_test.go:99 <time>
        -               INFO: extension after
        -               < Exit [AfterEach] e2e - cleanup_test.go:99 <time>
        -               > Enter [AfterEach] e2e - cleanup_test.go:70 <time>
        -               INFO: after #1
        -               < Exit [AfterEach] e2e - cleanup_test.go:70 <time>
        -               > Enter [AfterEach] e2e - cleanup_test.go:77 <time>
        -               INFO: after #2
        -               < Exit [AfterEach] e2e - cleanup_test.go:77 <time>
        -               """
        -           )),
        +           SystemErr: Inverse(simplify, string(
        +               """
        +               > Enter [BeforeEach] e2e - cleanup_test.go:54 <time>
        +               INFO: before
        +               < Exit [BeforeEach] e2e - cleanup_test.go:54 <time>
        +               > Enter [BeforeEach] e2e - set up framework | framework.go:xxx <time>
        +               STEP: Creating a kubernetes client - framework.go:xxx <time>
        +               INFO: >>> kubeConfig: yyy/kube.config
        +               STEP: Building a namespace api object, basename test-namespace - framework.go:xxx <time>
        +               INFO: Skipping waiting for service account
        +               < Exit [BeforeEach] e2e - set up framework | framework.go:xxx <time>
        +               > Enter [BeforeEach] e2e - cleanup_test.go:98 <time>
        +               INFO: extension before
        +               < Exit [BeforeEach] e2e - cleanup_test.go:98 <time>
        +               > Enter [BeforeEach] e2e - cleanup_test.go:62 <time>
        +               INFO: before #1
        +               < Exit [BeforeEach] e2e - cleanup_test.go:62 <time>
        +               > Enter [BeforeEach] e2e - cleanup_test.go:66 <time>
        +               INFO: before #2
        +               < Exit [BeforeEach] e2e - cleanup_test.go:66 <time>
        +               > Enter [It] works - cleanup_test.go:81 <time>
        +               [FAILED] failure
        +               In [It] at: cleanup_test.go:90 <time>
        +               < Exit [It] works - cleanup_test.go:81 <time>
        +               > Enter [AfterEach] e2e - cleanup_test.go:99 <time>
        +               INFO: extension after
        +               < Exit [AfterEach] e2e - cleanup_test.go:99 <time>
        +               > Enter [AfterEach] e2e - cleanup_test.go:70 <time>
        +               INFO: after #1
        +               < Exit [AfterEach] e2e - cleanup_test.go:70 <time>
        +               > Enter [AfterEach] e2e - cleanup_test.go:77 <time>
        +               INFO: after #2
        +               < Exit [AfterEach] e2e - cleanup_test.go:77 <time>
        +               ... // 27 elided lines
        +               """
        +           )),

In this example, I started with the expected string set to empty, copied as much of the actual string as possible, and then repeated. But because not all of it was shown, I am missing some lines. I was hoping to get a diff with the missing lines, but the heuristics apparently decided to just show both strings.

The simplify function does some string->string replacement to get rid of some line numbers and time stamps.

It's not entirely clear to me why this happens. I tried to reproduce it with exactly these strings and without a transformer, but then it worked as expected (showed a diff). I also tried with a transformer, with the same result.

[pohly]

My stand-alone tests were done in Go playground. The actual test above lives in a PR for Kubernetes master, which currently uses go-cmp v0.5.9.

[pohly]

The workaround for this is to split strings into []string at line breaks. I'm not doing that in the PR because I like the output less, but it has the necessary code commented out, just in case that it is needed.

[dsnet]

This does seem like a bug in the reporter heuristics in how it determines what context to show. Can you provide a simple reproduction that I can run that reproduces this?

[pohly]

I tried to come up with a simpler reproducer, but so far without luck. I'll keep trying...

[dsnet]

Thanks for looking into it. I tried to perform a repro with just the snippet you gave and it seemed to work properly. I could only test with the string as it appears after the transformation. I wonder if the transformer is somehow messing with the cmp reporter logic.

Just as a sanity check, make sure you're using the latest version of cmp. I have chased down bug reports in cmp before that turned out to be fixed in the latest version.

[pohly]

It's the combination of embedding inside a struct and using a transformer which triggers it. Here's a reproducer:

```golang package main import ( "fmt" "strings" "github.com/google/go-cmp/cmp" "github.com/google/go-cmp/cmp/cmpopts" "github.com/onsi/ginkgo/v2/reporters" ) func main() { expected := strings.Repeat("hello\n", 50) actual := expected + "world\n" // Works. // fmt.Println(cmp.Diff(expected, actual, // cmpopts.AcyclicTransformer("simplify", func(in string) string { // return in // }), // )) expectedSuite := reporters.JUnitTestSuite{ TestCases: []reporters.JUnitTestCase{ { Name: "[It] e2e works", SystemErr: expected, }, }, } actualSuite := reporters.JUnitTestSuite{ TestCases: []reporters.JUnitTestCase{ { Name: "[It] e2e works", SystemErr: actual, }, }, } // Works. // fmt.Println(cmp.Diff(expectedSuite, actualSuite)) fmt.Println(cmp.Diff(expectedSuite, actualSuite, cmpopts.AcyclicTransformer("simplify", func(in string) string { return in }), )) } ```

Output:

``` go run .   reporters.JUnitTestSuite{    ... // 8 identical fields    Timestamp: Inverse(simplify, string("")),    Properties: {},    TestCases: []reporters.JUnitTestCase{    {    ... // 6 identical fields    Failure: nil,    SystemOut: Inverse(simplify, string("")), -  SystemErr: Inverse(simplify, string( -  """ -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  hello -  ... // 19 elided lines -  """ -  )), +  SystemErr: Inverse(simplify, string( +  """ +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  hello +  ... // 20 elided lines +  """ +  )),    },    },   } Compilation finished at Mon Nov 14 20:06:47 ```

The number of lines is irrelevant, it also stops doing the diff for less lines. It just chose a high number to demonstrate that the output then doesn't show the actual difference anymore.

[pohly]

cmp is at 0.5.9, the latest.