Always print warnings and errors; clean up format (#2213)

## Changes
- Print warnings and errors by default.
- Fix ErrAlreadyPrinted not to be logged at Error level.
- Format log messages as "Warn: message" instead of "WARN" to make it
more readable and in-line with the rest of the output.
- Only print attributes (pid, mutator, etc) and time when the overall
level is debug (so --debug output has not changed much).

## Tests
- Existing acceptance tests show how warning messages appear in various
test case.
- Added new test for `--debug` output.
- Add sort_lines.py helper to avoid dependency on 'sort' which is
locale-sensitive.

acceptance/bin/sort_lines.py

@@ -0,0 +1,10 @@
+#!/usr/bin/env python3
+"""
+Helper to sort lines in text file. Similar to 'sort' but no dependence on locale or presence of 'sort' in PATH.
+"""
+
+import sys
+
+lines = sys.stdin.readlines()
+lines.sort()
+sys.stdout.write("".join(lines))

acceptance/bundle/debug/databricks.yml

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

acceptance/bundle/debug/out.stderr.parallel.txt

@@ -0,0 +1,15 @@
+10:07:59 Debug: ApplyReadOnly pid=12345 mutator=validate mutator (read-only)=parallel
+10:07:59 Debug: ApplyReadOnly pid=12345 mutator=validate mutator (read-only)=parallel mutator (read-only)=fast_validate(readonly)
+10:07:59 Debug: ApplyReadOnly pid=12345 mutator=validate mutator (read-only)=parallel mutator (read-only)=fast_validate(readonly) mutator (read-only)=parallel
+10:07:59 Debug: ApplyReadOnly pid=12345 mutator=validate mutator (read-only)=parallel mutator (read-only)=fast_validate(readonly) mutator (read-only)=parallel mutator (read-only)=validate:SingleNodeCluster
+10:07:59 Debug: ApplyReadOnly pid=12345 mutator=validate mutator (read-only)=parallel mutator (read-only)=fast_validate(readonly) mutator (read-only)=parallel mutator (read-only)=validate:artifact_paths
+10:07:59 Debug: ApplyReadOnly pid=12345 mutator=validate mutator (read-only)=parallel mutator (read-only)=fast_validate(readonly) mutator (read-only)=parallel mutator (read-only)=validate:job_cluster_key_defined
+10:07:59 Debug: ApplyReadOnly pid=12345 mutator=validate mutator (read-only)=parallel mutator (read-only)=fast_validate(readonly) mutator (read-only)=parallel mutator (read-only)=validate:job_task_cluster_spec
+10:07:59 Debug: ApplyReadOnly pid=12345 mutator=validate mutator (read-only)=parallel mutator (read-only)=validate:files_to_sync
+10:07:59 Debug: ApplyReadOnly pid=12345 mutator=validate mutator (read-only)=parallel mutator (read-only)=validate:folder_permissions
+10:07:59 Debug: ApplyReadOnly pid=12345 mutator=validate mutator (read-only)=parallel mutator (read-only)=validate:validate_sync_patterns
+10:07:59 Debug: Path /Workspace/Users/[USERNAME]/.bundle/debug/default/files has type directory (ID: 0) pid=12345 mutator=validate mutator (read-only)=parallel mutator (read-only)=validate:files_to_sync
+10:07:59 Debug: non-retriable error:  pid=12345 mutator=validate mutator (read-only)=parallel mutator (read-only)=validate:files_to_sync sdk=true
+< {} pid=12345 mutator=validate mutator (read-only)=parallel mutator (read-only)=validate:files_to_sync sdk=true
+< {} pid=12345 mutator=validate mutator (read-only)=parallel mutator (read-only)=validate:files_to_sync sdk=true
+< } pid=12345 mutator=validate mutator (read-only)=parallel mutator (read-only)=validate:files_to_sync sdk=true

acceptance/bundle/debug/out.stderr.txt

@@ -0,0 +1,92 @@
+10:07:59 Info: start pid=12345 version=[DEV_VERSION] args="[CLI], bundle, validate, --debug"
+10:07:59 Debug: Found bundle root at [TMPDIR] (file [TMPDIR]/databricks.yml) pid=12345
+10:07:59 Debug: Apply pid=12345 mutator=load
+10:07:59 Info: Phase: load pid=12345 mutator=load
+10:07:59 Debug: Apply pid=12345 mutator=load mutator=seq
+10:07:59 Debug: Apply pid=12345 mutator=load mutator=seq mutator=EntryPoint
+10:07:59 Debug: Apply pid=12345 mutator=load mutator=seq mutator=scripts.preinit
+10:07:59 Debug: No script defined for preinit, skipping pid=12345 mutator=load mutator=seq mutator=scripts.preinit
+10:07:59 Debug: Apply pid=12345 mutator=load mutator=seq mutator=ProcessRootIncludes
+10:07:59 Debug: Apply pid=12345 mutator=load mutator=seq mutator=ProcessRootIncludes mutator=seq
+10:07:59 Debug: Apply pid=12345 mutator=load mutator=seq mutator=VerifyCliVersion
+10:07:59 Debug: Apply pid=12345 mutator=load mutator=seq mutator=EnvironmentsToTargets
+10:07:59 Debug: Apply pid=12345 mutator=load mutator=seq mutator=ComputeIdToClusterId
+10:07:59 Debug: Apply pid=12345 mutator=load mutator=seq mutator=InitializeVariables
+10:07:59 Debug: Apply pid=12345 mutator=load mutator=seq mutator=DefineDefaultTarget(default)
+10:07:59 Debug: Apply pid=12345 mutator=load mutator=seq mutator=PythonMutator(load)
+10:07:59 Debug: Apply pid=12345 mutator=load mutator=seq mutator=validate:unique_resource_keys
+10:07:59 Debug: Apply pid=12345 mutator=load mutator=seq mutator=SelectDefaultTarget
+10:07:59 Debug: Apply pid=12345 mutator=load mutator=seq mutator=SelectDefaultTarget mutator=SelectTarget(default)
+10:07:59 Debug: Apply pid=12345 mutator=<func>
+10:07:59 Debug: Apply pid=12345 mutator=initialize
+10:07:59 Info: Phase: initialize pid=12345 mutator=initialize
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=validate:AllResourcesHaveValues
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=RewriteSyncPaths
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=SyncDefaultPath
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=SyncInferRoot
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=PopulateCurrentUser
+10:07:59 Debug: GET /api/2.0/preview/scim/v2/Me
+< HTTP/1.1 200 OK
+< {
+<   "id": "[USERID]",
+<   "userName": "[USERNAME]"
+< } pid=12345 mutator=initialize mutator=seq mutator=PopulateCurrentUser sdk=true
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=LoadGitDetails
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=ApplySourceLinkedDeploymentPreset
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=DefineDefaultWorkspaceRoot
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=ExpandWorkspaceRoot
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=DefaultWorkspacePaths
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=PrependWorkspacePrefix
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=RewriteWorkspacePrefix
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=SetVariables
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=PythonMutator(init)
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=PythonMutator(load_resources)
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=PythonMutator(apply_mutators)
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=ResolveVariableReferences
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=ResolveResourceReferences
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=ResolveVariableReferences
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=MergeJobClusters
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=MergeJobParameters
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=MergeJobTasks
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=MergePipelineClusters
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=MergeApps
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=CaptureSchemaDependency
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=CheckPermissions
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=SetRunAs
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=OverrideCompute
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=ConfigureDashboardDefaults
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=ConfigureVolumeDefaults
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=ProcessTargetMode
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=ApplyPresets
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=DefaultQueueing
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=ExpandPipelineGlobPaths
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=ConfigureWSFS
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=TranslatePaths
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=PythonWrapperWarning
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=apps.Validate
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=ValidateSharedRootPermissions
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=ApplyBundlePermissions
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=FilterCurrentUserFromPermissions
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=metadata.AnnotateJobs
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=metadata.AnnotatePipelines
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=terraform.Initialize
+10:07:59 Debug: Using Terraform from DATABRICKS_TF_EXEC_PATH at [TERRAFORM] pid=12345 mutator=initialize mutator=seq mutator=terraform.Initialize
+10:07:59 Debug: Using Terraform CLI config from DATABRICKS_TF_CLI_CONFIG_FILE at [DATABRICKS_TF_CLI_CONFIG_FILE] pid=12345 mutator=initialize mutator=seq mutator=terraform.Initialize
+10:07:59 Debug: Environment variables for Terraform: ...redacted... pid=12345 mutator=initialize mutator=seq mutator=terraform.Initialize
+10:07:59 Debug: Apply pid=12345 mutator=initialize mutator=seq mutator=scripts.postinit
+10:07:59 Debug: No script defined for postinit, skipping pid=12345 mutator=initialize mutator=seq mutator=scripts.postinit
+10:07:59 Debug: Apply pid=12345 mutator=validate
+10:07:59 Debug: GET /api/2.0/workspace/get-status?path=/Workspace/Users/[USERNAME]/.bundle/debug/default/files
+< HTTP/1.1 404 Not Found
+10:07:59 Debug: POST /api/2.0/workspace/mkdirs
+> {
+>   "path": "/Workspace/Users/[USERNAME]/.bundle/debug/default/files"
+> }
+< HTTP/1.1 200 OK
+10:07:59 Debug: GET /api/2.0/workspace/get-status?path=/Workspace/Users/[USERNAME]/.bundle/debug/default/files
+< HTTP/1.1 200 OK
+< {
+<   "object_type": "DIRECTORY",
+<   "path": "/Workspace/Users/[USERNAME]/.bundle/debug/default/files"
+10:07:59 Info: completed execution pid=12345 exit_code=0

acceptance/bundle/debug/output.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,4 @@
+$CLI bundle validate --debug 2> full.stderr.txt
+grep -vw parallel full.stderr.txt > out.stderr.txt
+grep -w parallel full.stderr.txt | sort_lines.py > out.stderr.parallel.txt
+rm full.stderr.txt

acceptance/bundle/debug/test.toml

@@ -0,0 +1,18 @@
+LocalOnly = true
+
+[[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=12345'
+
+[[Repls]]
+Old = '\d\d:\d\d:\d\d'
+New = '10:07:59'
+
+[[Repls]]
+Old = '\\'
+New = '/'

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
 
 
@@ -25,6 +27,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
 
 
@@ -39,11 +42,15 @@ 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": "."
 }
 
 >>> 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": "."
 }
@@ -54,6 +61,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
 
 
@@ -63,6 +71,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/git-permerror/test.toml

@@ -1,4 +1,4 @@
-Badness = "Warning logs not shown; inferred flag is set to true incorrect; bundle_root_path is not correct"
+Badness = "inferred flag is set to true incorrect; bundle_root_path is not correct; Warn and Error talk about the same; Warn goes to stderr, Error goes to stdout (for backward compat); Warning about permissions repeated twice"
 
 [GOOS]
 # This test relies on chmod which does not work on Windows

bundle/artifacts/upload.go

@@ -29,7 +29,7 @@ func (m *cleanUp) Apply(ctx context.Context, b *bundle.Bundle) diag.Diagnostics
 	// We intentionally ignore the error because it is not critical to the deployment
 	err := client.Delete(ctx, ".", filer.DeleteRecursively)
 	if err != nil {
-		log.Errorf(ctx, "failed to delete %s: %v", uploadPath, err)
+		log.Debugf(ctx, "failed to delete %s: %v", uploadPath, err)
 	}
 
 	err = client.Mkdir(ctx, ".")

bundle/mutator.go

@@ -42,7 +42,7 @@ func Apply(ctx context.Context, b *Bundle, m Mutator) diag.Diagnostics {
 	// such that they are not logged multiple times.
 	// If this is done, we can omit this block.
 	if err := diags.Error(); err != nil {
-		log.Errorf(ctx, "Error: %s", err)
+		log.Debugf(ctx, "Error: %s", err)
 	}
 
 	return diags

bundle/mutator_read_only.go

@@ -22,7 +22,7 @@ func ApplyReadOnly(ctx context.Context, rb ReadOnlyBundle, m ReadOnlyMutator) di
 	log.Debugf(ctx, "ApplyReadOnly")
 	diags := m.Apply(ctx, rb)
 	if err := diags.Error(); err != nil {
-		log.Errorf(ctx, "Error: %s", err)
+		log.Debugf(ctx, "Error: %s", err)
 	}
 
 	return diags

cmd/root/root.go

@@ -114,10 +114,15 @@ func Execute(ctx context.Context, cmd *cobra.Command) error {
 		if err == nil {
 			logger.Info("completed execution",
 				slog.String("exit_code", "0"))
-		} else {
+		} else if errors.Is(err, ErrAlreadyPrinted) {
-			logger.Error("failed execution",
+			logger.Debug("failed execution",
 				slog.String("exit_code", "1"),
-				slog.String("error", err.Error()))
+			)
+		} else {
+			logger.Info("failed execution",
+				slog.String("exit_code", "1"),
+				slog.String("error", err.Error()),
+			)
 		}
 	}
 

libs/flags/log_level_flag.go

@@ -25,7 +25,7 @@ type LogLevelFlag struct {
 
 func NewLogLevelFlag() LogLevelFlag {
 	return LogLevelFlag{
-		l: log.LevelDisabled,
+		l: log.LevelWarn,
 	}
 }
 

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, log.LevelWarn, f.Level())
-	assert.Equal(t, "disabled", f.String())
+	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.levelTrace = h.sprintf(ttyColorLevelTrace, "%s", "Trace:")
-	h.levelDebug = h.sprintf(ttyColorLevelDebug, "%5s", "DEBUG")
+	h.levelDebug = h.sprintf(ttyColorLevelDebug, "%s", "Debug:")
-	h.levelInfo = h.sprintf(ttyColorLevelInfo, "%5s", "INFO")
+	h.levelInfo = h.sprintf(ttyColorLevelInfo, "%s", "Info:")
-	h.levelWarn = h.sprintf(ttyColorLevelWarn, "%5s", "WARN")
+	h.levelWarn = h.sprintf(ttyColorLevelWarn, "%s", "Warn:")
-	h.levelError = h.sprintf(ttyColorLevelError, "%5s", "ERROR")
+	h.levelError = h.sprintf(ttyColorLevelError, "%s", "Error:")
 	return h
 }
 
@@ -185,33 +185,41 @@ 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()))
+
+	if h.opts.Level.Level() <= slog.LevelDebug {
+		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.
+	if h.opts.Level.Level() <= slog.LevelDebug {
-	goas := h.goas
+
-	if r.NumAttrs() == 0 {
+		// Handle state from WithGroup and WithAttrs.
-		// If the record has no Attrs, remove groups at the end of the list; they are empty.
+		goas := h.goas
-		for len(goas) > 0 && goas[len(goas)-1].group != "" {
+		if r.NumAttrs() == 0 {
-			goas = goas[:len(goas)-1]
+			// 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)
+		for _, goa := range goas {
-		} else {
+			if goa.group != "" {
-			for _, a := range goa.attrs {
+				state.openGroup(goa.group)
-				state.appendAttr(a)
+			} else {
+				for _, a := range goa.attrs {
+					state.appendAttr(a)
+				}
 			}
 		}
-	}
 
-	// Add attributes from the record.
+		// Add attributes from the record.
-	r.Attrs(func(a slog.Attr) bool {
+		r.Attrs(func(a slog.Attr) bool {
-		state.appendAttr(a)
+			state.appendAttr(a)
-		return true
+			return true
-	})
+		})
+
+	}
 
 	// Add newline.
 	state.append("\n")