diff --git a/ai-track-docs/logging.md b/ai-track-docs/logging.md index 6e6fb62e7..99f96addd 100644 --- a/ai-track-docs/logging.md +++ b/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= target= argc= status= [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 +``` diff --git a/components/main-chef-wrapper/cmd/observability.go b/components/main-chef-wrapper/cmd/observability.go new file mode 100644 index 000000000..8468c47a0 --- /dev/null +++ b/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 +} diff --git a/components/main-chef-wrapper/cmd/observability_test.go b/components/main-chef-wrapper/cmd/observability_test.go new file mode 100644 index 000000000..b9cf82a64 --- /dev/null +++ b/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) + } +} diff --git a/components/main-chef-wrapper/cmd/passthrough_helpers.go b/components/main-chef-wrapper/cmd/passthrough_helpers.go index 9d986e426..05b8f4e0b 100644 --- a/components/main-chef-wrapper/cmd/passthrough_helpers.go +++ b/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:]) -} \ No newline at end of file + return passThroughWithObservability("workstation_passthrough", dist.WorkstationExec, os.Args[1:]) +} diff --git a/components/main-chef-wrapper/cmd/push.go b/components/main-chef-wrapper/cmd/push.go index eb8d0166a..187dfc5b2 100644 --- a/components/main-chef-wrapper/cmd/push.go +++ b/components/main-chef-wrapper/cmd/push.go @@ -47,10 +47,13 @@ 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 } @@ -58,9 +61,9 @@ https://docs.chef.io/policyfile/ 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:]) }, } diff --git a/components/main-chef-wrapper/cmd/pushArchive.go b/components/main-chef-wrapper/cmd/pushArchive.go index 1ac021a5b..615e23f80 100644 --- a/components/main-chef-wrapper/cmd/pushArchive.go +++ b/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:]) }, }