Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

string difference not visible due to "elided lines" #311

Open
pohly opened this issue Nov 14, 2022 · 7 comments
Open

string difference not visible due to "elided lines" #311

pohly opened this issue Nov 14, 2022 · 7 comments
Labels
reporter Improvements in the difference reporter

Comments

@pohly
Copy link

pohly commented Nov 14, 2022

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
Copy link
Author

pohly commented Nov 14, 2022

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
Copy link
Author

pohly commented Nov 14, 2022

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
Copy link
Collaborator

dsnet commented Nov 14, 2022

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
Copy link
Author

pohly commented Nov 14, 2022

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

@dsnet
Copy link
Collaborator

dsnet commented Nov 14, 2022

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
Copy link
Author

pohly commented Nov 14, 2022

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

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
Copy link
Author

pohly commented Nov 14, 2022

cmp is at 0.5.9, the latest.

@dsnet dsnet added the reporter Improvements in the difference reporter label Jan 12, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
reporter Improvements in the difference reporter
Projects
None yet
Development

No branches or pull requests

2 participants