Improve test output to include correct location (#2058)

## Changes
- Add t.Helper() in testcli-related helpers, this ensures that output is
attributed correctly to test case and not to the helper.
- Modify testlcli.Run() to run process in foreground. This is needed for
t.Helper to work.
- Extend a few assertions with message to help attribute it to proper
helper where needed.

## Tests
Manually reviewed test output.

Before:

```
+ go test --timeout 3h -v -run TestDefaultPython/3.9 ./integration/bundle/
=== RUN   TestDefaultPython
=== RUN   TestDefaultPython/3.9
    workspace.go:26: aws
    golden.go:14: run args: [bundle, init, default-python, --config-file, config.json]
    runner.go:206: [databricks stderr]:
    runner.go:206: [databricks stderr]: Welcome to the default Python template for Databricks Asset Bundles!
...
    testdiff.go:23:
                Error Trace:    /Users/denis.bilenko/work/cli/libs/testdiff/testdiff.go:23
                                                        /Users/denis.bilenko/work/cli/libs/testdiff/golden.go:43
                                                        /Users/denis.bilenko/work/cli/internal/testcli/golden.go:23
                                                        /Users/denis.bilenko/work/cli/integration/bundle/init_default_python_test.go:92
                                                        /Users/denis.bilenko/work/cli/integration/bundle/init_default_python_test.go:45
...
```

After:

```
+ go test --timeout 3h -v -run TestDefaultPython/3.9 ./integration/bundle/
=== RUN   TestDefaultPython
=== RUN   TestDefaultPython/3.9
    init_default_python_test.go:51: CLOUD_ENV=aws
    init_default_python_test.go:92:   args: bundle, init, default-python, --config-file, config.json
    init_default_python_test.go:92: stderr:
    init_default_python_test.go:92: stderr: Welcome to the default Python template for Databricks Asset Bundles!
...
    init_default_python_test.go:92:
                Error Trace:    /Users/denis.bilenko/work/cli/libs/testdiff/testdiff.go:24
                                                        /Users/denis.bilenko/work/cli/libs/testdiff/golden.go:46
                                                        /Users/denis.bilenko/work/cli/internal/testcli/golden.go:23
                                                        /Users/denis.bilenko/work/cli/integration/bundle/init_default_python_test.go:92
                                                        /Users/denis.bilenko/work/cli/integration/bundle/init_default_python_test.go:45
...
```

integration/internal/acc/workspace.go

@@ -21,9 +21,10 @@ type WorkspaceT struct {
 }
 
 func WorkspaceTest(t testutil.TestingT) (context.Context, *WorkspaceT) {
+	t.Helper()
 	loadDebugEnvIfRunFromIDE(t, "workspace")
 
-	t.Log(testutil.GetEnvOrSkipTest(t, "CLOUD_ENV"))
+	t.Logf("CLOUD_ENV=%s", testutil.GetEnvOrSkipTest(t, "CLOUD_ENV"))
 
 	w, err := databricks.NewWorkspaceClient()
 	require.NoError(t, err)
@@ -41,9 +42,10 @@ func WorkspaceTest(t testutil.TestingT) (context.Context, *WorkspaceT) {
 
 // Run the workspace test only on UC workspaces.
 func UcWorkspaceTest(t testutil.TestingT) (context.Context, *WorkspaceT) {
+	t.Helper()
 	loadDebugEnvIfRunFromIDE(t, "workspace")
 
-	t.Log(testutil.GetEnvOrSkipTest(t, "CLOUD_ENV"))
+	t.Logf("CLOUD_ENV=%s", testutil.GetEnvOrSkipTest(t, "CLOUD_ENV"))
 
 	if os.Getenv("TEST_METASTORE_ID") == "" {
 		t.Skipf("Skipping on non-UC workspaces")
@@ -67,19 +69,21 @@ func UcWorkspaceTest(t testutil.TestingT) (context.Context, *WorkspaceT) {
 }
 
 func (t *WorkspaceT) TestClusterID() string {
+	t.Helper()
 	clusterID := testutil.GetEnvOrSkipTest(t, "TEST_BRICKS_CLUSTER_ID")
 	err := t.W.Clusters.EnsureClusterIsRunning(t.ctx, clusterID)
-	require.NoError(t, err)
+	require.NoError(t, err, "Unexpected error from EnsureClusterIsRunning for clusterID=%s", clusterID)
 	return clusterID
 }
 
 func (t *WorkspaceT) RunPython(code string) (string, error) {
+	t.Helper()
 	var err error
 
 	// Create command executor only once per test.
 	if t.exec == nil {
 		t.exec, err = t.W.CommandExecution.Start(t.ctx, t.TestClusterID(), compute.LanguagePython)
-		require.NoError(t, err)
+		require.NoError(t, err, "Unexpected error from CommandExecution.Start(clusterID=%v)", t.TestClusterID())
 
 		t.Cleanup(func() {
 			err := t.exec.Destroy(t.ctx)
@@ -88,7 +92,7 @@ func (t *WorkspaceT) RunPython(code string) (string, error) {
 	}
 
 	results, err := t.exec.Execute(t.ctx, code)
-	require.NoError(t, err)
+	require.NoError(t, err, "Unexpected error from Execute(%v)", code)
 	require.NotEqual(t, compute.ResultTypeError, results.ResultType, results.Cause)
 	output, ok := results.Data.(string)
 	require.True(t, ok, "unexpected type %T", results.Data)

internal/testcli/golden.go

@@ -3,7 +3,6 @@ package testcli
 import (
 	"context"
 	"fmt"
-	"strings"
 
 	"github.com/databricks/cli/internal/testutil"
 	"github.com/databricks/cli/libs/testdiff"
@@ -11,7 +10,7 @@ import (
 )
 
 func captureOutput(t testutil.TestingT, ctx context.Context, args []string) string {
-	t.Logf("run args: [%s]", strings.Join(args, ", "))
+	t.Helper()
 	r := NewRunner(t, ctx, args...)
 	stdout, stderr, err := r.Run()
 	assert.NoError(t, err)
@@ -19,11 +18,13 @@ func captureOutput(t testutil.TestingT, ctx context.Context, args []string) stri
 }
 
 func AssertOutput(t testutil.TestingT, ctx context.Context, args []string, expectedPath string) {
+	t.Helper()
 	out := captureOutput(t, ctx, args)
 	testdiff.AssertOutput(t, ctx, out, fmt.Sprintf("Output from %v", args), expectedPath)
 }
 
 func AssertOutputJQ(t testutil.TestingT, ctx context.Context, args []string, expectedPath string, ignorePaths []string) {
+	t.Helper()
 	out := captureOutput(t, ctx, args)
 	testdiff.AssertOutputJQ(t, ctx, out, fmt.Sprintf("Output from %v", args), expectedPath, ignorePaths)
 }

internal/testcli/runner.go

@@ -69,6 +69,7 @@ func consumeLines(ctx context.Context, wg *sync.WaitGroup, r io.Reader) <-chan s
 }
 
 func (r *Runner) registerFlagCleanup(c *cobra.Command) {
+	r.Helper()
 	// Find target command that will be run. Example: if the command run is `databricks fs cp`,
 	// target command corresponds to `cp`
 	targetCmd, _, err := c.Find(r.args)
@@ -230,13 +231,48 @@ func (r *Runner) RunBackground() {
 }
 
 func (r *Runner) Run() (bytes.Buffer, bytes.Buffer, error) {
-	r.RunBackground()
+	r.Helper()
-	err := <-r.errch
+	var stdout, stderr bytes.Buffer
-	return r.stdout, r.stderr, err
+	ctx := cmdio.NewContext(r.ctx, &cmdio.Logger{
+		Mode:   flags.ModeAppend,
+		Reader: bufio.Reader{},
+		Writer: &stderr,
+	})
+
+	cli := cmd.New(ctx)
+	cli.SetOut(&stdout)
+	cli.SetErr(&stderr)
+	cli.SetArgs(r.args)
+
+	r.Logf("  args: %s", strings.Join(r.args, ", "))
+
+	err := root.Execute(ctx, cli)
+	if err != nil {
+		r.Logf(" error: %s", err)
+	}
+
+	if stdout.Len() > 0 {
+		// Make a copy of the buffer such that it remains "unread".
+		scanner := bufio.NewScanner(bytes.NewBuffer(stdout.Bytes()))
+		for scanner.Scan() {
+			r.Logf("stdout: %s", scanner.Text())
+		}
+	}
+
+	if stderr.Len() > 0 {
+		// Make a copy of the buffer such that it remains "unread".
+		scanner := bufio.NewScanner(bytes.NewBuffer(stderr.Bytes()))
+		for scanner.Scan() {
+			r.Logf("stderr: %s", scanner.Text())
+		}
+	}
+
+	return stdout, stderr, err
 }
 
 // Like [require.Eventually] but errors if the underlying command has failed.
 func (r *Runner) Eventually(condition func() bool, waitFor, tick time.Duration, msgAndArgs ...any) {
+	r.Helper()
 	ch := make(chan bool, 1)
 
 	timer := time.NewTimer(waitFor)
@@ -269,12 +305,14 @@ func (r *Runner) Eventually(condition func() bool, waitFor, tick time.Duration,
 }
 
 func (r *Runner) RunAndExpectOutput(heredoc string) {
+	r.Helper()
 	stdout, _, err := r.Run()
 	require.NoError(r, err)
 	require.Equal(r, cmdio.Heredoc(heredoc), strings.TrimSpace(stdout.String()))
 }
 
 func (r *Runner) RunAndParseJSON(v any) {
+	r.Helper()
 	stdout, _, err := r.Run()
 	require.NoError(r, err)
 	err = json.Unmarshal(stdout.Bytes(), &v)
@@ -291,7 +329,7 @@ func NewRunner(t testutil.TestingT, ctx context.Context, args ...string) *Runner
 }
 
 func RequireSuccessfulRun(t testutil.TestingT, ctx context.Context, args ...string) (bytes.Buffer, bytes.Buffer) {
-	t.Logf("run args: [%s]", strings.Join(args, ", "))
+	t.Helper()
 	r := NewRunner(t, ctx, args...)
 	stdout, stderr, err := r.Run()
 	require.NoError(t, err)
@@ -299,6 +337,7 @@ func RequireSuccessfulRun(t testutil.TestingT, ctx context.Context, args ...stri
 }
 
 func RequireErrorRun(t testutil.TestingT, ctx context.Context, args ...string) (bytes.Buffer, bytes.Buffer, error) {
+	t.Helper()
 	r := NewRunner(t, ctx, args...)
 	stdout, stderr, err := r.Run()
 	require.Error(t, err)

internal/testutil/interface.go

@@ -24,4 +24,6 @@ type TestingT interface {
 	Setenv(key, value string)
 
 	TempDir() string
+
+	Helper()
 }

libs/testdiff/golden.go

@@ -19,22 +19,25 @@ import (
 var OverwriteMode = os.Getenv("TESTS_OUTPUT") == "OVERWRITE"
 
 func ReadFile(t testutil.TestingT, ctx context.Context, filename string) string {
+	t.Helper()
 	data, err := os.ReadFile(filename)
 	if os.IsNotExist(err) {
 		return ""
 	}
-	assert.NoError(t, err)
+	assert.NoError(t, err, "Failed to read %s", filename)
 	// On CI, on Windows \n in the file somehow end up as \r\n
 	return NormalizeNewlines(string(data))
 }
 
 func WriteFile(t testutil.TestingT, filename, data string) {
+	t.Helper()
 	t.Logf("Overwriting %s", filename)
 	err := os.WriteFile(filename, []byte(data), 0o644)
-	assert.NoError(t, err)
+	assert.NoError(t, err, "Failed to write %s", filename)
 }
 
 func AssertOutput(t testutil.TestingT, ctx context.Context, out, outTitle, expectedPath string) {
+	t.Helper()
 	expected := ReadFile(t, ctx, expectedPath)
 
 	out = ReplaceOutput(t, ctx, out)
@@ -49,6 +52,7 @@ func AssertOutput(t testutil.TestingT, ctx context.Context, out, outTitle, expec
 }
 
 func AssertOutputJQ(t testutil.TestingT, ctx context.Context, out, outTitle, expectedPath string, ignorePaths []string) {
+	t.Helper()
 	expected := ReadFile(t, ctx, expectedPath)
 
 	out = ReplaceOutput(t, ctx, out)
@@ -69,6 +73,7 @@ var (
 )
 
 func ReplaceOutput(t testutil.TestingT, ctx context.Context, out string) string {
+	t.Helper()
 	out = NormalizeNewlines(out)
 	replacements := GetReplacementsMap(ctx)
 	if replacements == nil {
@@ -136,6 +141,7 @@ func GetReplacementsMap(ctx context.Context) *ReplacementsContext {
 }
 
 func PrepareReplacements(t testutil.TestingT, r *ReplacementsContext, w *databricks.WorkspaceClient) {
+	t.Helper()
 	// in some clouds (gcp) w.Config.Host includes "https://" prefix in others it's really just a host (azure)
 	host := strings.TrimPrefix(strings.TrimPrefix(w.Config.Host, "http://"), "https://")
 	r.Set(host, "$DATABRICKS_HOST")
@@ -167,6 +173,7 @@ func PrepareReplacements(t testutil.TestingT, r *ReplacementsContext, w *databri
 }
 
 func PrepareReplacementsUser(t testutil.TestingT, r *ReplacementsContext, u iam.User) {
+	t.Helper()
 	// There could be exact matches or overlap between different name fields, so sort them by length
 	// to ensure we match the largest one first and map them all to the same token
 	names := []string{

libs/testdiff/testdiff.go

@@ -18,9 +18,10 @@ func UnifiedDiff(filename1, filename2, s1, s2 string) string {
 }
 
 func AssertEqualTexts(t testutil.TestingT, filename1, filename2, expected, out string) {
+	t.Helper()
 	if len(out) < 1000 && len(expected) < 1000 {
 		// This shows full strings + diff which could be useful when debugging newlines
-		assert.Equal(t, expected, out)
+		assert.Equal(t, expected, out, "%s vs %s", filename1, filename2)
 	} else {
 		// only show diff for large texts
 		diff := UnifiedDiff(filename1, filename2, expected, out)
@@ -29,6 +30,7 @@ func AssertEqualTexts(t testutil.TestingT, filename1, filename2, expected, out s
 }
 
 func AssertEqualJQ(t testutil.TestingT, expectedName, outName, expected, out string, ignorePaths []string) {
+	t.Helper()
 	patch, err := jsondiff.CompareJSON([]byte(expected), []byte(out))
 	if err != nil {
 		t.Logf("CompareJSON error for %s vs %s: %s (fallback to textual comparison)", outName, expectedName, err)