GHCP -- Run: Ex9 Observability

ai-track-docs/logging.md

@@ -138,3 +138,56 @@ go run . show-config -v 2>verbose.log
 
 When `test-config` is run with `-v`, the structured event is emitted to stderr by `chef-automate-collect`.
 In deployed environments, view this in command stderr logs (for example, CI step logs, container stderr stream, or host process logs that collect stderr).
+
+## Main Chef Wrapper Command Observability (Run Ex9)
+
+### Scope
+
+Folder: `components/main-chef-wrapper/cmd`
+
+Related files instrumented:
+
+- `passthrough_helpers.go`
+- `push.go`
+- `pushArchive.go`
+
+### Pattern
+
+Dominant folder pattern for operational output is stderr logging with clear prefixes (`ERROR:`).
+For Ex9, command execution instrumentation uses a consistent info line on stderr:
+
+```text
+INFO: op=<operation> target=<binary> argc=<N> status=<start|success|error> [error="..."]
+```
+
+Implementation source:
+
+- `observability.go`
+
+Design choices:
+
+- Logs only operation metadata and argument count (`argc`) to avoid leaking argument values.
+- Emits `start`, then `success` or `error` for each passthrough boundary.
+- Keeps command-level instrumentation consistent across rollout and non-rollout entry points.
+
+### Validation Instructions
+
+Run from repository root:
+
+```sh
+cd components/main-chef-wrapper
+go test ./cmd -run 'TestValidateRolloutSetupContract|TestBuildObservationLineDoesNotLeakArgs|TestEmitCommandObservationWritesConsistentInfoLine|TestEmitCommandObservationIncludesErrorDetails' -count=1 -v
+```
+
+Sample output includes lines like:
+
+```text
+sample-observation-line: INFO: op=push_archive target=chef argc=3 status=success
+```
+
+To review broader side effects in this subsystem:
+
+```sh
+cd components/main-chef-wrapper
+go test ./cmd ./integration ./lib
+```

components/main-chef-wrapper/cmd/observability.go

@@ -0,0 +1,37 @@
+package cmd
+
+import (
+	"fmt"
+	"os"
+	"path/filepath"
+)
+
+func buildObservationLine(operation string, targetPath string, args []string, status string, err error) string {
+	target := "-"
+	if targetPath != "" {
+		target = filepath.Base(targetPath)
+	}
+
+	line := fmt.Sprintf("INFO: op=%s target=%s argc=%d status=%s", operation, target, len(args), status)
+	if err != nil {
+		line = fmt.Sprintf("%s error=%q", line, err.Error())
+	}
+
+	return line
+}
+
+func emitCommandObservation(operation string, targetPath string, args []string, status string, err error) {
+	fmt.Fprintln(os.Stderr, buildObservationLine(operation, targetPath, args, status, err))
+}
+
+func passThroughWithObservability(operation string, targetPath string, args []string) error {
+	emitCommandObservation(operation, targetPath, args, "start", nil)
+	err := Runner.PassThroughCommand(targetPath, "", args)
+	if err != nil {
+		emitCommandObservation(operation, targetPath, args, "error", err)
+		return err
+	}
+
+	emitCommandObservation(operation, targetPath, args, "success", nil)
+	return nil
+}

components/main-chef-wrapper/cmd/observability_test.go

@@ -0,0 +1,80 @@
+package cmd
+
+import (
+	"errors"
+	"io"
+	"os"
+	"strings"
+	"testing"
+)
+
+func captureStderrForObservability(t *testing.T) (func(), func() string) {
+	t.Helper()
+
+	originalStderr := os.Stderr
+	r, w, err := os.Pipe()
+	if err != nil {
+		t.Fatalf("failed to create stderr pipe: %v", err)
+	}
+
+	os.Stderr = w
+
+	restore := func() {
+		_ = w.Close()
+		os.Stderr = originalStderr
+	}
+
+	readOutput := func() string {
+		b, err := io.ReadAll(r)
+		if err != nil {
+			t.Fatalf("failed to read stderr output: %v", err)
+		}
+		_ = r.Close()
+		return strings.TrimSpace(string(b))
+	}
+
+	return restore, readOutput
+}
+
+func TestBuildObservationLineDoesNotLeakArgs(t *testing.T) {
+	line := buildObservationLine("push", "/opt/chef-workstation/bin/chef", []string{"push", "POLICY_GROUP", "sensitive-token"}, "start", nil)
+
+	if !strings.Contains(line, "INFO: op=push") {
+		t.Fatalf("expected info operation in line, got %q", line)
+	}
+	if !strings.Contains(line, "target=chef") {
+		t.Fatalf("expected target binary name in line, got %q", line)
+	}
+	if !strings.Contains(line, "argc=3") {
+		t.Fatalf("expected argument count in line, got %q", line)
+	}
+	if strings.Contains(line, "sensitive-token") {
+		t.Fatalf("expected args to remain redacted from line, got %q", line)
+	}
+}
+
+func TestEmitCommandObservationWritesConsistentInfoLine(t *testing.T) {
+	restore, readOutput := captureStderrForObservability(t)
+	emitCommandObservation("push_archive", "/usr/local/bin/chef", []string{"push-archive", "group", "archive.tgz"}, "success", nil)
+	restore()
+
+	got := readOutput()
+	t.Logf("sample-observation-line: %s", got)
+	if !strings.HasPrefix(got, "INFO: op=push_archive target=chef argc=3 status=success") {
+		t.Fatalf("unexpected observation line: %q", got)
+	}
+}
+
+func TestEmitCommandObservationIncludesErrorDetails(t *testing.T) {
+	restore, readOutput := captureStderrForObservability(t)
+	emitCommandObservation("push_rollout_report", "automate-collect", []string{"report-new-rollout"}, "error", errors.New("command failed"))
+	restore()
+
+	got := readOutput()
+	if !strings.Contains(got, "status=error") {
+		t.Fatalf("expected status=error in observation line, got %q", got)
+	}
+	if !strings.Contains(got, `error="command failed"`) {
+		t.Fatalf("expected error details in observation line, got %q", got)
+	}
+}

components/main-chef-wrapper/cmd/passthrough_helpers.go

@@ -8,9 +8,9 @@ import (
 )
 
 func passThroughAnalyzeCommand(_ *cobra.Command, _ []string) error {
-	return Runner.PassThroughCommand(dist.AnalyzeExec, "", os.Args[1:])
+	return passThroughWithObservability("analyze_passthrough", dist.AnalyzeExec, os.Args[1:])
 }
 
 func passThroughWorkstationCommand(_ *cobra.Command, _ []string) error {
-	return Runner.PassThroughCommand(dist.WorkstationExec, "", os.Args[1:])
-}
+	return passThroughWithObservability("workstation_passthrough", dist.WorkstationExec, os.Args[1:])
+}

components/main-chef-wrapper/cmd/push.go

@@ -47,20 +47,23 @@ https://docs.chef.io/policyfile/
 	RunE: func(cmd *cobra.Command, args []string) error {
 		allArgs := os.Args[1:]
 		if isRollOutEnabled() {
+			emitCommandObservation("push_rollout_validation", "", nil, "start", nil)
 			if !ValidateRolloutSetup() { // roll-out is enabled but setup not complete, we don't do anything
+				emitCommandObservation("push_rollout_validation", "", nil, "error", errors.New("required rollout environment variables are not set"))
 				return errors.New("Policy roll-out is enabled but required variables are not set")
 			}
-			err := Runner.PassThroughCommand(dist.WorkstationExec, "", allArgs)
+			emitCommandObservation("push_rollout_validation", "", nil, "success", nil)
+			err := passThroughWithObservability("push_workstation", dist.WorkstationExec, allArgs)
 			if err != nil {
 				return err
 			}
 			serverURL := strings.TrimSpace(os.Getenv("CHEF_AC_SERVER_URL"))
 			serverUser := strings.TrimSpace(os.Getenv("CHEF_AC_SERVER_USER"))
 			allArgs := []string{"report-new-rollout", "-g", allArgs[1], "-l", allArgs[2],
 				"-s", serverURL, "-u", serverUser}
-			return Runner.PassThroughCommand(dist.AutomateCollectExec, "", allArgs)
+			return passThroughWithObservability("push_rollout_report", dist.AutomateCollectExec, allArgs)
 		}
-		return Runner.PassThroughCommand(dist.WorkstationExec, "", os.Args[1:])
+		return passThroughWithObservability("push", dist.WorkstationExec, os.Args[1:])
 	},
 }
 

components/main-chef-wrapper/cmd/pushArchive.go

@@ -43,7 +43,7 @@ https://docs.chef.io/policyfile/
 	DisableFlagParsing: true,
 
 	RunE: func(cmd *cobra.Command, args []string) error {
-		return Runner.PassThroughCommand(dist.WorkstationExec, "", os.Args[1:])
+		return passThroughWithObservability("push_archive", dist.WorkstationExec, os.Args[1:])
 	},
 }