tweak log output

- remove time
- remove attrs unless level is debug
- replace $DEV_VERSION
- add acceptance test for --debug

acceptance/bundle/debug/databricks.yml

@@ -0,0 +1,2 @@
+bundle:
+  name: debug

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

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

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!

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

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'

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
 
 

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:

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:

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:

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) {

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")