From bd1820492bb661cd5e79052e20ec13f47f327acc Mon Sep 17 00:00:00 2001
From: Denis Bilenko <denis.bilenko@databricks.com>
Date: Fri, 24 Jan 2025 19:45:05 +0100
Subject: [PATCH] tweak log output

- remove time
- remove attrs unless level is debug
- replace $DEV_VERSION
- add acceptance test for --debug
---
 acceptance/acceptance_test.go                 |  1 +
 acceptance/bundle/debug/databricks.yml        |  2 +
 .../bundle/debug/out.stderr.parallel.txt      | 12 +++
 acceptance/bundle/debug/out.stderr.txt        | 86 +++++++++++++++++++
 acceptance/bundle/debug/out.stdout.txt        |  7 ++
 acceptance/bundle/debug/output.txt            |  0
 acceptance/bundle/debug/script                |  3 +
 acceptance/bundle/debug/test.toml             |  8 ++
 acceptance/bundle/git-permerror/output.txt    |  9 ++
 .../bundle/templates/dbt-sql/output.txt       |  1 +
 .../templates/default-python/output.txt       |  1 +
 .../bundle/templates/default-sql/output.txt   |  1 +
 libs/flags/log_level_flag_test.go             |  4 +-
 libs/log/handler/friendly.go                  | 55 ++++++------
 libs/testdiff/replacement.go                  |  6 ++
 15 files changed, 168 insertions(+), 28 deletions(-)
 create mode 100644 acceptance/bundle/debug/databricks.yml
 create mode 100644 acceptance/bundle/debug/out.stderr.parallel.txt
 create mode 100644 acceptance/bundle/debug/out.stderr.txt
 create mode 100644 acceptance/bundle/debug/out.stdout.txt
 create mode 100644 acceptance/bundle/debug/output.txt
 create mode 100644 acceptance/bundle/debug/script
 create mode 100644 acceptance/bundle/debug/test.toml

diff --git a/acceptance/acceptance_test.go b/acceptance/acceptance_test.go
index e48bd9908..7f3cc2db0 100644
--- a/acceptance/acceptance_test.go
+++ b/acceptance/acceptance_test.go
@@ -124,6 +124,7 @@ func testAccept(t *testing.T, InprocessMode bool, singleTest string) int {
 	testdiff.PrepareReplacementsUser(t, &repls, *user)
 	testdiff.PrepareReplacementsWorkspaceClient(t, &repls, workspaceClient)
 	testdiff.PrepareReplacementsUUID(t, &repls)
+	testdiff.PrepareReplacementsDevVersion(t, &repls)
 
 	testDirs := getTests(t)
 	require.NotEmpty(t, testDirs)
diff --git a/acceptance/bundle/debug/databricks.yml b/acceptance/bundle/debug/databricks.yml
new file mode 100644
index 000000000..2c9dd3c90
--- /dev/null
+++ b/acceptance/bundle/debug/databricks.yml
@@ -0,0 +1,2 @@
+bundle:
+  name: debug
diff --git a/acceptance/bundle/debug/out.stderr.parallel.txt b/acceptance/bundle/debug/out.stderr.parallel.txt
new file mode 100644
index 000000000..87530b84c
--- /dev/null
+++ b/acceptance/bundle/debug/out.stderr.parallel.txt
@@ -0,0 +1,12 @@
+< } pid=00000 mutator=validate mutator (read-only)=parallel mutator (read-only)=validate:files_to_sync sdk=true
+Debug: ApplyReadOnly pid=00000 mutator=validate mutator (read-only)=parallel
+Debug: ApplyReadOnly pid=00000 mutator=validate mutator (read-only)=parallel mutator (read-only)=fast_validate(readonly)
+Debug: ApplyReadOnly pid=00000 mutator=validate mutator (read-only)=parallel mutator (read-only)=fast_validate(readonly) mutator (read-only)=parallel
+Debug: ApplyReadOnly pid=00000 mutator=validate mutator (read-only)=parallel mutator (read-only)=fast_validate(readonly) mutator (read-only)=parallel mutator (read-only)=validate:SingleNodeCluster
+Debug: ApplyReadOnly pid=00000 mutator=validate mutator (read-only)=parallel mutator (read-only)=fast_validate(readonly) mutator (read-only)=parallel mutator (read-only)=validate:artifact_paths
+Debug: ApplyReadOnly pid=00000 mutator=validate mutator (read-only)=parallel mutator (read-only)=fast_validate(readonly) mutator (read-only)=parallel mutator (read-only)=validate:job_cluster_key_defined
+Debug: ApplyReadOnly pid=00000 mutator=validate mutator (read-only)=parallel mutator (read-only)=fast_validate(readonly) mutator (read-only)=parallel mutator (read-only)=validate:job_task_cluster_spec
+Debug: ApplyReadOnly pid=00000 mutator=validate mutator (read-only)=parallel mutator (read-only)=validate:files_to_sync
+Debug: ApplyReadOnly pid=00000 mutator=validate mutator (read-only)=parallel mutator (read-only)=validate:folder_permissions
+Debug: ApplyReadOnly pid=00000 mutator=validate mutator (read-only)=parallel mutator (read-only)=validate:validate_sync_patterns
+Debug: Path  has type directory (ID: 1001) pid=00000 mutator=validate mutator (read-only)=parallel mutator (read-only)=validate:files_to_sync
diff --git a/acceptance/bundle/debug/out.stderr.txt b/acceptance/bundle/debug/out.stderr.txt
new file mode 100644
index 000000000..d128e599e
--- /dev/null
+++ b/acceptance/bundle/debug/out.stderr.txt
@@ -0,0 +1,86 @@
+Info: start pid=00000 version=$DEV_VERSION args="$CLI, bundle, validate, --debug"
+Debug: Found bundle root at $TMPDIR (file $TMPDIR/databricks.yml) pid=00000
+Debug: Apply pid=00000 mutator=load
+Info: Phase: load pid=00000 mutator=load
+Debug: Apply pid=00000 mutator=load mutator=seq
+Debug: Apply pid=00000 mutator=load mutator=seq mutator=EntryPoint
+Debug: Apply pid=00000 mutator=load mutator=seq mutator=scripts.preinit
+Debug: No script defined for preinit, skipping pid=00000 mutator=load mutator=seq mutator=scripts.preinit
+Debug: Apply pid=00000 mutator=load mutator=seq mutator=ProcessRootIncludes
+Debug: Apply pid=00000 mutator=load mutator=seq mutator=ProcessRootIncludes mutator=seq
+Debug: Apply pid=00000 mutator=load mutator=seq mutator=VerifyCliVersion
+Debug: Apply pid=00000 mutator=load mutator=seq mutator=EnvironmentsToTargets
+Debug: Apply pid=00000 mutator=load mutator=seq mutator=ComputeIdToClusterId
+Debug: Apply pid=00000 mutator=load mutator=seq mutator=InitializeVariables
+Debug: Apply pid=00000 mutator=load mutator=seq mutator=DefineDefaultTarget(default)
+Debug: Apply pid=00000 mutator=load mutator=seq mutator=PythonMutator(load)
+Debug: Apply pid=00000 mutator=load mutator=seq mutator=validate:unique_resource_keys
+Debug: Apply pid=00000 mutator=load mutator=seq mutator=SelectDefaultTarget
+Debug: Apply pid=00000 mutator=load mutator=seq mutator=SelectDefaultTarget mutator=SelectTarget(default)
+Debug: Apply pid=00000 mutator=<func>
+Debug: Apply pid=00000 mutator=initialize
+Info: Phase: initialize pid=00000 mutator=initialize
+Debug: Apply pid=00000 mutator=initialize mutator=seq
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=validate:AllResourcesHaveValues
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=RewriteSyncPaths
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=SyncDefaultPath
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=SyncInferRoot
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=InitializeWorkspaceClient
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=PopulateCurrentUser
+Debug: GET /api/2.0/preview/scim/v2/Me
+< HTTP/1.1 200 OK
+< {
+<   "userName": "$USERNAME"
+< } pid=00000 mutator=initialize mutator=seq mutator=PopulateCurrentUser sdk=true
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=LoadGitDetails
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=ApplySourceLinkedDeploymentPreset
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=DefineDefaultWorkspaceRoot
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=ExpandWorkspaceRoot
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=DefaultWorkspacePaths
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=PrependWorkspacePrefix
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=RewriteWorkspacePrefix
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=SetVariables
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=PythonMutator(init)
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=PythonMutator(load_resources)
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=PythonMutator(apply_mutators)
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=ResolveVariableReferences
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=ResolveResourceReferences
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=ResolveVariableReferences
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=MergeJobClusters
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=MergeJobParameters
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=MergeJobTasks
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=MergePipelineClusters
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=MergeApps
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=CaptureSchemaDependency
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=CheckPermissions
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=SetRunAs
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=OverrideCompute
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=ConfigureDashboardDefaults
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=ConfigureVolumeDefaults
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=ProcessTargetMode
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=ApplyPresets
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=DefaultQueueing
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=ExpandPipelineGlobPaths
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=ConfigureWSFS
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=TranslatePaths
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=PythonWrapperWarning
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=apps.Validate
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=ValidateSharedRootPermissions
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=ApplyBundlePermissions
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=FilterCurrentUserFromPermissions
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=metadata.AnnotateJobs
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=metadata.AnnotatePipelines
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=terraform.Initialize
+Debug: Using Terraform from DATABRICKS_TF_EXEC_PATH at $TMPHOME pid=00000 mutator=initialize mutator=seq mutator=terraform.Initialize
+Debug: DATABRICKS_TF_CLI_CONFIG_FILE is not defined pid=00000 mutator=initialize mutator=seq mutator=terraform.Initialize
+Debug: Environment variables for Terraform: ...redacted... pid=00000 mutator=initialize mutator=seq mutator=terraform.Initialize
+Debug: Apply pid=00000 mutator=initialize mutator=seq mutator=scripts.postinit
+Debug: No script defined for postinit, skipping pid=00000 mutator=initialize mutator=seq mutator=scripts.postinit
+Debug: Apply pid=00000 mutator=validate
+Debug: GET /api/2.0/workspace/get-status?path=/Workspace/Users/$USERNAME/.bundle/debug/default/files
+< HTTP/1.1 200 OK
+< {
+<   "object_id": 1001,
+<   "object_type": "DIRECTORY",
+<   "resource_id": "1001"
+Info: completed execution pid=00000 exit_code=0
diff --git a/acceptance/bundle/debug/out.stdout.txt b/acceptance/bundle/debug/out.stdout.txt
new file mode 100644
index 000000000..df4765946
--- /dev/null
+++ b/acceptance/bundle/debug/out.stdout.txt
@@ -0,0 +1,7 @@
+Name: debug
+Target: default
+Workspace:
+  User: $USERNAME
+  Path: /Workspace/Users/$USERNAME/.bundle/debug/default
+
+Validation OK!
diff --git a/acceptance/bundle/debug/output.txt b/acceptance/bundle/debug/output.txt
new file mode 100644
index 000000000..e69de29bb
diff --git a/acceptance/bundle/debug/script b/acceptance/bundle/debug/script
new file mode 100644
index 000000000..b0e5f4503
--- /dev/null
+++ b/acceptance/bundle/debug/script
@@ -0,0 +1,3 @@
+$CLI bundle validate --debug > out.stdout.txt 2> full.stderr.txt
+grep -vw parallel full.stderr.txt > out.stderr.txt
+grep -w parallel full.stderr.txt | sort > out.stderr.parallel.txt
diff --git a/acceptance/bundle/debug/test.toml b/acceptance/bundle/debug/test.toml
new file mode 100644
index 000000000..401f48494
--- /dev/null
+++ b/acceptance/bundle/debug/test.toml
@@ -0,0 +1,8 @@
+[[Repls]]
+# The keys are unsorted and also vary per OS
+Old = 'Environment variables for Terraform: ([A-Z_ ,]+) '
+New = 'Environment variables for Terraform: ...redacted... '
+
+[[Repls]]
+Old = 'pid=[0-9]+'
+New = 'pid=00000'
diff --git a/acceptance/bundle/git-permerror/output.txt b/acceptance/bundle/git-permerror/output.txt
index 2b52134ab..c0214ca60 100644
--- a/acceptance/bundle/git-permerror/output.txt
+++ b/acceptance/bundle/git-permerror/output.txt
@@ -3,6 +3,7 @@
 >>> chmod 000 .git
 
 >>> $CLI bundle validate
+Warn: failed to read .git: unable to load repository specific gitconfig: open config: permission denied
 Error: unable to load repository specific gitconfig: open config: permission denied
 
 Name: git-permerror
@@ -16,6 +17,7 @@ Found 1 error
 Exit code: 1
 
 >>> $CLI bundle validate -o json
+Warn: failed to read .git: unable to load repository specific gitconfig: open config: permission denied
 Error: unable to load repository specific gitconfig: open config: permission denied
 
 
@@ -26,6 +28,7 @@ Exit code: 1
 }
 
 >>> withdir subdir/a/b $CLI bundle validate -o json
+Warn: failed to read .git: unable to load repository specific gitconfig: open config: permission denied
 Error: unable to load repository specific gitconfig: open config: permission denied
 
 
@@ -41,12 +44,16 @@ Exit code: 1
 >>> chmod 000 .git/HEAD
 
 >>> $CLI bundle validate -o json
+Warn: failed to load current branch: open HEAD: permission denied
+Warn: failed to load latest commit: open HEAD: permission denied
 {
   "bundle_root_path": ".",
   "inferred": true
 }
 
 >>> withdir subdir/a/b $CLI bundle validate -o json
+Warn: failed to load current branch: open HEAD: permission denied
+Warn: failed to load latest commit: open HEAD: permission denied
 {
   "bundle_root_path": ".",
   "inferred": true
@@ -58,6 +65,7 @@ Exit code: 1
 >>> chmod 000 .git/config
 
 >>> $CLI bundle validate -o json
+Warn: failed to read .git: unable to load repository specific gitconfig: open config: permission denied
 Error: unable to load repository specific gitconfig: open config: permission denied
 
 
@@ -68,6 +76,7 @@ Exit code: 1
 }
 
 >>> withdir subdir/a/b $CLI bundle validate -o json
+Warn: failed to read .git: unable to load repository specific gitconfig: open config: permission denied
 Error: unable to load repository specific gitconfig: open config: permission denied
 
 
diff --git a/acceptance/bundle/templates/dbt-sql/output.txt b/acceptance/bundle/templates/dbt-sql/output.txt
index 972c7e152..a04047faa 100644
--- a/acceptance/bundle/templates/dbt-sql/output.txt
+++ b/acceptance/bundle/templates/dbt-sql/output.txt
@@ -22,6 +22,7 @@ Workspace:
 Validation OK!
 
 >>> $CLI bundle validate -t prod
+Warn: target with 'mode: production' should specify an explicit 'targets.prod.git' configuration
 Name: my_dbt_sql
 Target: prod
 Workspace:
diff --git a/acceptance/bundle/templates/default-python/output.txt b/acceptance/bundle/templates/default-python/output.txt
index 5493ac2cf..8c925e568 100644
--- a/acceptance/bundle/templates/default-python/output.txt
+++ b/acceptance/bundle/templates/default-python/output.txt
@@ -20,6 +20,7 @@ Workspace:
 Validation OK!
 
 >>> $CLI bundle validate -t prod
+Warn: target with 'mode: production' should specify an explicit 'targets.prod.git' configuration
 Name: my_default_python
 Target: prod
 Workspace:
diff --git a/acceptance/bundle/templates/default-sql/output.txt b/acceptance/bundle/templates/default-sql/output.txt
index fe0139093..d07e90c69 100644
--- a/acceptance/bundle/templates/default-sql/output.txt
+++ b/acceptance/bundle/templates/default-sql/output.txt
@@ -22,6 +22,7 @@ Workspace:
 Validation OK!
 
 >>> $CLI bundle validate -t prod
+Warn: target with 'mode: production' should specify an explicit 'targets.prod.git' configuration
 Name: my_default_sql
 Target: prod
 Workspace:
diff --git a/libs/flags/log_level_flag_test.go b/libs/flags/log_level_flag_test.go
index 11a50bc45..c81f90d18 100644
--- a/libs/flags/log_level_flag_test.go
+++ b/libs/flags/log_level_flag_test.go
@@ -10,8 +10,8 @@ import (
 
 func TestLogLevelFlagDefault(t *testing.T) {
 	f := NewLogLevelFlag()
-	assert.Equal(t, log.LevelDisabled, f.Level())
-	assert.Equal(t, "disabled", f.String())
+	assert.Equal(t, log.LevelWarn, f.Level())
+	assert.Equal(t, "warn", f.String())
 }
 
 func TestLogLevelFlagSetValid(t *testing.T) {
diff --git a/libs/log/handler/friendly.go b/libs/log/handler/friendly.go
index 33b88a9e2..8bd8c6e5b 100644
--- a/libs/log/handler/friendly.go
+++ b/libs/log/handler/friendly.go
@@ -53,11 +53,11 @@ func NewFriendlyHandler(out io.Writer, opts *Options) slog.Handler {
 
 	// Cache (colorized) level strings.
 	// The colors to use for each level are configured in `colors.go`.
-	h.levelTrace = h.sprintf(ttyColorLevelTrace, "%5s", "TRACE")
-	h.levelDebug = h.sprintf(ttyColorLevelDebug, "%5s", "DEBUG")
-	h.levelInfo = h.sprintf(ttyColorLevelInfo, "%5s", "INFO")
-	h.levelWarn = h.sprintf(ttyColorLevelWarn, "%5s", "WARN")
-	h.levelError = h.sprintf(ttyColorLevelError, "%5s", "ERROR")
+	h.levelTrace = h.sprintf(ttyColorLevelTrace, "%s", "Trace:")
+	h.levelDebug = h.sprintf(ttyColorLevelDebug, "%s", "Debug:")
+	h.levelInfo = h.sprintf(ttyColorLevelInfo, "%s", "Info:")
+	h.levelWarn = h.sprintf(ttyColorLevelWarn, "%s", "Warn:")
+	h.levelError = h.sprintf(ttyColorLevelError, "%s", "Error:")
 	return h
 }
 
@@ -185,33 +185,36 @@ func (s *handleState) appendAttr(a slog.Attr) {
 // Handle implements slog.Handler.
 func (h *friendlyHandler) Handle(ctx context.Context, r slog.Record) error {
 	state := h.handleState()
-	state.append(h.sprintf(ttyColorTime, "%02d:%02d:%02d ", r.Time.Hour(), r.Time.Minute(), r.Time.Second()))
 	state.appendf("%s ", h.coloredLevel(r))
 	state.append(h.sprint(ttyColorMessage, r.Message))
 
-	// Handle state from WithGroup and WithAttrs.
-	goas := h.goas
-	if r.NumAttrs() == 0 {
-		// If the record has no Attrs, remove groups at the end of the list; they are empty.
-		for len(goas) > 0 && goas[len(goas)-1].group != "" {
-			goas = goas[:len(goas)-1]
-		}
-	}
-	for _, goa := range goas {
-		if goa.group != "" {
-			state.openGroup(goa.group)
-		} else {
-			for _, a := range goa.attrs {
-				state.appendAttr(a)
+	if h.opts.Level.Level() <= slog.LevelDebug {
+
+		// Handle state from WithGroup and WithAttrs.
+		goas := h.goas
+		if r.NumAttrs() == 0 {
+			// If the record has no Attrs, remove groups at the end of the list; they are empty.
+			for len(goas) > 0 && goas[len(goas)-1].group != "" {
+				goas = goas[:len(goas)-1]
+			}
+		}
+		for _, goa := range goas {
+			if goa.group != "" {
+				state.openGroup(goa.group)
+			} else {
+				for _, a := range goa.attrs {
+					state.appendAttr(a)
+				}
 			}
 		}
-	}
 
-	// Add attributes from the record.
-	r.Attrs(func(a slog.Attr) bool {
-		state.appendAttr(a)
-		return true
-	})
+		// Add attributes from the record.
+		r.Attrs(func(a slog.Attr) bool {
+			state.appendAttr(a)
+			return true
+		})
+
+	}
 
 	// Add newline.
 	state.append("\n")
diff --git a/libs/testdiff/replacement.go b/libs/testdiff/replacement.go
index b512374a3..cb966684a 100644
--- a/libs/testdiff/replacement.go
+++ b/libs/testdiff/replacement.go
@@ -23,6 +23,7 @@ var (
 	uuidRegex        = regexp.MustCompile(`[a-fA-F0-9]{8}-[a-fA-F0-9]{4}-[a-fA-F0-9]{4}-[a-fA-F0-9]{4}-[a-fA-F0-9]{12}`)
 	numIdRegex       = regexp.MustCompile(`[0-9]{3,}`)
 	privatePathRegex = regexp.MustCompile(`(/tmp|/private)(/.*)/([a-zA-Z0-9]+)`)
+	devVersionRegex  = regexp.MustCompile(`0\.0\.0-dev\+[a-f0-9]{10,16}`)
 )
 
 type Replacement struct {
@@ -211,3 +212,8 @@ func PrepareReplacementsTemporaryDirectory(t testutil.TestingT, r *ReplacementsC
 	t.Helper()
 	r.append(privatePathRegex, "/tmp/.../$3")
 }
+
+func PrepareReplacementsDevVersion(t testutil.TestingT, r *ReplacementsContext) {
+	t.Helper()
+	r.append(devVersionRegex, "$$DEV_VERSION")
+}