diff --git a/cmd/virtwork/main.go b/cmd/virtwork/main.go index 3259bf1..39740bf 100644 --- a/cmd/virtwork/main.go +++ b/cmd/virtwork/main.go @@ -7,8 +7,8 @@ import ( "context" "errors" "fmt" + "log/slog" "os" - "strings" "time" "github.com/spf13/cobra" @@ -21,6 +21,7 @@ import ( "github.com/opdev/virtwork/internal/cluster" "github.com/opdev/virtwork/internal/config" "github.com/opdev/virtwork/internal/constants" + "github.com/opdev/virtwork/internal/logging" "github.com/opdev/virtwork/internal/resources" "github.com/opdev/virtwork/internal/vm" "github.com/opdev/virtwork/internal/wait" @@ -176,6 +177,10 @@ func runE(cmd *cobra.Command, args []string) error { return fmt.Errorf("loading config: %w", err) } + // Initialize logger + verbose, _ := cmd.Flags().GetBool("verbose") + logger := logging.NewLogger(cmd.OutOrStdout(), verbose) + // Initialize auditor auditor, err := initAuditor(cmd, cfg) if err != nil { @@ -376,7 +381,7 @@ func runE(cmd *cobra.Command, args []string) error { // Dry-run: print specs and return if cfg.DryRun { - if err := printDryRun(plans); err != nil { + if err := printDryRun(logger, plans); err != nil { return err } _ = auditor.CompleteExecution(ctx, execID, "success", "") @@ -396,7 +401,7 @@ func runE(cmd *cobra.Command, args []string) error { }); err != nil { return fmt.Errorf("ensuring namespace %q: %w", cfg.Namespace, err) } - _, _ = fmt.Fprintf(cmd.OutOrStdout(), "Namespace %s ensured\n", cfg.Namespace) + logger.Info("namespace ensured", slog.String("namespace", cfg.Namespace)) // Create services before VMs (DNS must resolve for client VMs) servicesCreated := 0 @@ -425,7 +430,9 @@ func runE(cmd *cobra.Command, args []string) error { return fmt.Errorf("creating service for %q: %w", name, err) } servicesCreated++ - _, _ = fmt.Fprintf(cmd.OutOrStdout(), "Service %s created\n", svc.Name) + logger.Info("service created", + slog.String("service_name", svc.Name), + slog.String("namespace", svc.Namespace)) _, _ = auditor.RecordResource(ctx, execID, audit.ResourceRecord{ ResourceType: "Service", @@ -456,7 +463,9 @@ func runE(cmd *cobra.Command, args []string) error { } plans[i].vmSpec.CloudInitSecretName = secretName secretsCreated++ - _, _ = fmt.Fprintf(cmd.OutOrStdout(), "Secret %s created\n", secretName) + logger.Info("secret created", + slog.String("secret_name", secretName), + slog.String("namespace", cfg.Namespace)) _, _ = auditor.RecordResource(ctx, execID, audit.ResourceRecord{ ResourceType: "Secret", @@ -479,7 +488,10 @@ func runE(cmd *cobra.Command, args []string) error { }) return fmt.Errorf("creating VM %q: %w", p.vmName, err) } - _, _ = fmt.Fprintf(cmd.OutOrStdout(), "VM %s created\n", p.vmName) + logger.Info("vm created", + slog.String("vm_name", p.vmName), + slog.String("namespace", cfg.Namespace), + slog.String("workload", p.component)) wlID := auditWorkloadIDs[p.component] _, _ = auditor.RecordVM(ctx, execID, wlID, audit.VMRecord{ @@ -507,15 +519,18 @@ func runE(cmd *cobra.Command, args []string) error { // Wait for readiness if cfg.WaitForReady { timeout := time.Duration(cfg.ReadyTimeoutSeconds) * time.Second - _, _ = fmt.Fprintf(cmd.OutOrStdout(), "Waiting for %d VMs to become ready (timeout: %s)...\n", - len(vmNames), timeout) - results := wait.WaitForAllVMsReady(ctx, c, vmNames, cfg.Namespace, + logger.Info("waiting for VMs to become ready", + slog.Int("vm_count", len(vmNames)), + slog.Duration("timeout", timeout)) + results := wait.WaitForAllVMsReady(ctx, c, logger, vmNames, cfg.Namespace, timeout, constants.DefaultPollInterval) failures := 0 for name, err := range results { if err != nil { - _, _ = fmt.Fprintf(cmd.ErrOrStderr(), "VM %s: %v\n", name, err) + logger.Error("vm readiness check failed", + slog.String("vm_name", name), + slog.String("error", err.Error())) failures++ _ = auditor.RecordEvent(ctx, execID, audit.EventRecord{ EventType: "vm_timeout", @@ -532,7 +547,7 @@ func runE(cmd *cobra.Command, args []string) error { if failures > 0 { return fmt.Errorf("%d of %d VMs failed; %w", failures, len(vmNames), ErrReadinessCheck) } - _, _ = fmt.Fprintf(cmd.OutOrStdout(), "All %d VMs ready\n", len(vmNames)) + logger.Info("all VMs ready", slog.Int("vm_count", len(vmNames))) } // Mark all workloads as created @@ -545,7 +560,7 @@ func runE(cmd *cobra.Command, args []string) error { err = nil // clear for defer // Print summary - printSummary(cmd, len(plans), servicesCreated, secretsCreated, cfg, runID) + printSummary(logger, len(plans), servicesCreated, secretsCreated, cfg, runID) return nil } @@ -556,6 +571,10 @@ func cleanupE(cmd *cobra.Command, args []string) error { return fmt.Errorf("loading config: %w", err) } + // Initialize logger + verbose, _ := cmd.Flags().GetBool("verbose") + logger := logging.NewLogger(cmd.OutOrStdout(), verbose) + // Initialize auditor auditor, err := initAuditor(cmd, cfg) if err != nil { @@ -568,13 +587,9 @@ func cleanupE(cmd *cobra.Command, args []string) error { ctx := context.Background() // Start audit execution - dryRunBanner := "" cmdName := "cleanup" if cfg.DryRun { - // Log the command being executed cmdName = "cleanup --dry-run" - // Add banner if '--dry-run' option is passed - dryRunBanner = "--- Dry Run ---\n" } execID, _, err := auditor.StartExecution(ctx, cmdName, cfg) @@ -624,17 +639,16 @@ func cleanupE(cmd *cobra.Command, args []string) error { _ = auditor.CompleteExecution(ctx, execID, "success", "") err = nil // clear for defer - _, _ = fmt.Fprintf(cmd.OutOrStdout(), "%sCleanup complete: %d VMs deleted, %d services deleted, %d secrets deleted", - dryRunBanner, result.VMsDeleted, result.ServicesDeleted, result.SecretsDeleted) - if result.NamespaceDeleted { - _, _ = fmt.Fprintf(cmd.OutOrStdout(), ", namespace deleted") - } - _, _ = fmt.Fprintln(cmd.OutOrStdout()) + logger.Info("cleanup complete", + slog.Bool("dry_run", cfg.DryRun), + slog.Int("vms_deleted", result.VMsDeleted), + slog.Int("services_deleted", result.ServicesDeleted), + slog.Int("secrets_deleted", result.SecretsDeleted), + slog.Bool("namespace_deleted", result.NamespaceDeleted)) if len(result.Errors) > 0 { - _, _ = fmt.Fprintf(cmd.ErrOrStderr(), "Warnings (%d):\n", len(result.Errors)) for _, e := range result.Errors { - _, _ = fmt.Fprintf(cmd.ErrOrStderr(), " - %v\n", e) + logger.Warn("cleanup warning", slog.String("error", e.Error())) } } @@ -642,8 +656,8 @@ func cleanupE(cmd *cobra.Command, args []string) error { } // printDryRun outputs VM specs in YAML without connecting to a cluster. -func printDryRun(plans []vmPlan) error { - _, _ = fmt.Printf("--- Dry Run ---\nTotal VMs to create: %d\n\n", len(plans)) +func printDryRun(logger *slog.Logger, plans []vmPlan) error { + logger.Info("dry run mode", slog.Int("total_vms", len(plans))) for _, p := range plans { vmObj := vm.BuildVMSpec(*p.vmSpec) @@ -651,34 +665,19 @@ func printDryRun(plans []vmPlan) error { if err != nil { return fmt.Errorf("marshaling VM spec for %q: %w", p.vmName, err) } + // Output YAML to stdout for dry-run inspection _, _ = fmt.Printf("# VM: %s (workload: %s)\n%s\n%s\n", p.vmName, p.component, string(data), "---") } return nil } -// printSummary outputs a deployment summary table. -func printSummary(cmd *cobra.Command, vmCount, svcCount, secCount int, cfg *config.Config, runID string) { - summaryTemplate := `%s -Deployment Summary -%s -Run ID: %s -Namespace: %s -VMs created: %d -Services: %d -Secrets: %d -Image: %s -%s` - _, _ = fmt.Fprintf( - cmd.OutOrStdout(), - summaryTemplate, - strings.Repeat("=", 50), - strings.Repeat("=", 50), - runID, - cfg.Namespace, - vmCount, - svcCount, - secCount, - cfg.ContainerDiskImage, - strings.Repeat("=", 50), - ) +// printSummary outputs a deployment summary. +func printSummary(logger *slog.Logger, vmCount, svcCount, secCount int, cfg *config.Config, runID string) { + logger.Info("deployment summary", + slog.String("run_id", runID), + slog.String("namespace", cfg.Namespace), + slog.Int("vms_created", vmCount), + slog.Int("services_created", svcCount), + slog.Int("secrets_created", secCount), + slog.String("container_image", cfg.ContainerDiskImage)) } diff --git a/cmd/virtwork/main_test.go b/cmd/virtwork/main_test.go index 31863ba..8d786bc 100644 --- a/cmd/virtwork/main_test.go +++ b/cmd/virtwork/main_test.go @@ -23,6 +23,7 @@ import ( "github.com/opdev/virtwork/internal/cluster" "github.com/opdev/virtwork/internal/config" "github.com/opdev/virtwork/internal/constants" + "github.com/opdev/virtwork/internal/logging" "github.com/opdev/virtwork/internal/resources" "github.com/opdev/virtwork/internal/vm" "github.com/opdev/virtwork/internal/wait" @@ -498,7 +499,9 @@ var _ = Describe("Run orchestration", func() { noWait := true if !noWait { - results := wait.WaitForAllVMsReady(ctx, c, []string{"vm1"}, constants.DefaultNamespace, + buf := &bytes.Buffer{} + logger := logging.NewLogger(buf, false) + results := wait.WaitForAllVMsReady(ctx, c, logger, []string{"vm1"}, constants.DefaultNamespace, time.Duration(600)*time.Second, constants.DefaultPollInterval) Expect(results).NotTo(BeNil()) } diff --git a/internal/logging/logging.go b/internal/logging/logging.go new file mode 100644 index 0000000..2fd30fb --- /dev/null +++ b/internal/logging/logging.go @@ -0,0 +1,25 @@ +// Copyright 2026 Red Hat +// SPDX-License-Identifier: Apache-2.0 + +package logging + +import ( + "io" + "log/slog" +) + +// NewLogger creates a new structured logger with JSON output. +// If verbose is true, the logger uses Debug level; otherwise Info level. +func NewLogger(w io.Writer, verbose bool) *slog.Logger { + level := slog.LevelInfo + if verbose { + level = slog.LevelDebug + } + + opts := &slog.HandlerOptions{ + Level: level, + } + + handler := slog.NewJSONHandler(w, opts) + return slog.New(handler) +} diff --git a/internal/logging/logging_test.go b/internal/logging/logging_test.go new file mode 100644 index 0000000..dce4671 --- /dev/null +++ b/internal/logging/logging_test.go @@ -0,0 +1,89 @@ +// Copyright 2026 Red Hat +// SPDX-License-Identifier: Apache-2.0 + +package logging_test + +import ( + "bytes" + "encoding/json" + "log/slog" + "testing" + + . "github.com/onsi/ginkgo/v2" + . "github.com/onsi/gomega" + + "github.com/opdev/virtwork/internal/logging" +) + +func TestLogging(t *testing.T) { + RegisterFailHandler(Fail) + RunSpecs(t, "Logging Suite") +} + +var _ = Describe("NewLogger", func() { + var buf *bytes.Buffer + + BeforeEach(func() { + buf = &bytes.Buffer{} + }) + + Context("when verbose is false", func() { + It("should create a logger with Info level", func() { + logger := logging.NewLogger(buf, false) + Expect(logger).NotTo(BeNil()) + + // Log at debug level - should not appear + logger.Debug("debug message") + Expect(buf.String()).To(BeEmpty()) + + // Log at info level - should appear + buf.Reset() + logger.Info("info message") + Expect(buf.String()).To(ContainSubstring("info message")) + }) + + It("should output JSON format", func() { + logger := logging.NewLogger(buf, false) + logger.Info("test message", slog.String("key", "value")) + + var logEntry map[string]interface{} + err := json.Unmarshal(buf.Bytes(), &logEntry) + Expect(err).NotTo(HaveOccurred()) + Expect(logEntry["msg"]).To(Equal("test message")) + Expect(logEntry["key"]).To(Equal("value")) + }) + }) + + Context("when verbose is true", func() { + It("should create a logger with Debug level", func() { + logger := logging.NewLogger(buf, true) + Expect(logger).NotTo(BeNil()) + + // Log at debug level - should appear + logger.Debug("debug message") + Expect(buf.String()).To(ContainSubstring("debug message")) + + // Verify debug level in JSON + var logEntry map[string]interface{} + err := json.Unmarshal(buf.Bytes(), &logEntry) + Expect(err).NotTo(HaveOccurred()) + Expect(logEntry["level"]).To(Equal("DEBUG")) + }) + }) + + It("should support structured fields", func() { + logger := logging.NewLogger(buf, false) + logger.Info("vm created", + slog.String("vm_name", "test-vm"), + slog.String("namespace", "test-ns"), + slog.Int("cpu_cores", 4), + ) + + var logEntry map[string]interface{} + err := json.Unmarshal(buf.Bytes(), &logEntry) + Expect(err).NotTo(HaveOccurred()) + Expect(logEntry["vm_name"]).To(Equal("test-vm")) + Expect(logEntry["namespace"]).To(Equal("test-ns")) + Expect(logEntry["cpu_cores"]).To(BeNumerically("==", 4)) + }) +}) diff --git a/internal/wait/wait.go b/internal/wait/wait.go index a609961..1c2861d 100644 --- a/internal/wait/wait.go +++ b/internal/wait/wait.go @@ -7,6 +7,7 @@ import ( "context" "errors" "fmt" + "log/slog" "sync" "time" @@ -23,6 +24,7 @@ var ErrVMTimeout = errors.New("timeout waiting for VM") func WaitForVMReady( ctx context.Context, c client.Client, + logger *slog.Logger, name, namespace string, timeout, interval time.Duration, ) error { @@ -43,7 +45,9 @@ func WaitForVMReady( if !apierrors.IsNotFound(err) { return fmt.Errorf("getting VMI %s/%s: %w", namespace, name, err) } - fmt.Printf("VM %s: VMI not yet created, retrying...\n", name) + logger.Debug("VMI not yet created, retrying", + slog.String("vm_name", name), + slog.String("namespace", namespace)) select { case <-ctx.Done(): return fmt.Errorf("context cancelled waiting for VM %s/%s: %w", namespace, name, ctx.Err()) @@ -70,6 +74,7 @@ func WaitForVMReady( func WaitForAllVMsReady( ctx context.Context, c client.Client, + logger *slog.Logger, names []string, namespace string, timeout, interval time.Duration, @@ -82,7 +87,7 @@ func WaitForAllVMsReady( wg.Add(1) go func(vmName string) { defer wg.Done() - err := WaitForVMReady(ctx, c, vmName, namespace, timeout, interval) + err := WaitForVMReady(ctx, c, logger, vmName, namespace, timeout, interval) mu.Lock() results[vmName] = err mu.Unlock() diff --git a/internal/wait/wait_integration_test.go b/internal/wait/wait_integration_test.go index dd26ddd..ada0df9 100644 --- a/internal/wait/wait_integration_test.go +++ b/internal/wait/wait_integration_test.go @@ -7,6 +7,7 @@ package wait_test import ( "context" + "log/slog" "time" . "github.com/onsi/ginkgo/v2" @@ -42,12 +43,12 @@ var _ = Describe("WaitForVMReady [integration]", Label("slow"), func() { vmObj := vm.BuildVMSpec(opts) Expect(vm.CreateVM(ctx, c, vmObj)).To(Succeed()) - err := wait.WaitForVMReady(ctx, c, "wait-vm-0", namespace, 5*time.Minute, 5*time.Second) + err := wait.WaitForVMReady(ctx, c, slog.Default(), "wait-vm-0", namespace, 5*time.Minute, 5*time.Second) Expect(err).NotTo(HaveOccurred()) }) It("should return error on timeout for nonexistent VM", func() { - err := wait.WaitForVMReady(ctx, c, "nonexistent-vm", namespace, 10*time.Second, 2*time.Second) + err := wait.WaitForVMReady(ctx, c, slog.Default(), "nonexistent-vm", namespace, 10*time.Second, 2*time.Second) Expect(err).To(HaveOccurred()) }) }) @@ -76,7 +77,7 @@ var _ = Describe("WaitForAllVMsReady [integration]", Label("slow"), func() { Expect(vm.CreateVM(ctx, c, vm.BuildVMSpec(opts))).To(Succeed()) } - results := wait.WaitForAllVMsReady(ctx, c, + results := wait.WaitForAllVMsReady(ctx, c, slog.Default(), []string{"wait-multi-0", "wait-multi-1"}, namespace, 5*time.Minute, 5*time.Second) @@ -86,7 +87,7 @@ var _ = Describe("WaitForAllVMsReady [integration]", Label("slow"), func() { }) It("should report per-VM errors for nonexistent VMs", func() { - results := wait.WaitForAllVMsReady(ctx, c, + results := wait.WaitForAllVMsReady(ctx, c, slog.Default(), []string{"nonexistent-0", "nonexistent-1"}, namespace, 10*time.Second, 2*time.Second) diff --git a/internal/wait/wait_test.go b/internal/wait/wait_test.go index 52c06c0..60aceef 100644 --- a/internal/wait/wait_test.go +++ b/internal/wait/wait_test.go @@ -4,7 +4,9 @@ package wait_test import ( + "bytes" "context" + "log/slog" "sync/atomic" "time" @@ -17,6 +19,7 @@ import ( "sigs.k8s.io/controller-runtime/pkg/client/interceptor" "github.com/opdev/virtwork/internal/cluster" + "github.com/opdev/virtwork/internal/logging" "github.com/opdev/virtwork/internal/wait" ) @@ -24,10 +27,13 @@ var _ = Describe("WaitForVMReady", func() { var ( ctx context.Context scheme = cluster.NewScheme() + logger *slog.Logger ) BeforeEach(func() { ctx = context.Background() + buf := &bytes.Buffer{} + logger = logging.NewLogger(buf, true) }) It("should return nil when immediately ready", func() { @@ -42,7 +48,7 @@ var _ = Describe("WaitForVMReady", func() { } c := fake.NewClientBuilder().WithScheme(scheme).WithObjects(vmi).Build() - err := wait.WaitForVMReady(ctx, c, "ready-vm", "default", 5*time.Second, 10*time.Millisecond) + err := wait.WaitForVMReady(ctx, c, logger, "ready-vm", "default", 5*time.Second, 10*time.Millisecond) Expect(err).NotTo(HaveOccurred()) }) @@ -78,7 +84,7 @@ var _ = Describe("WaitForVMReady", func() { }). Build() - err := wait.WaitForVMReady(ctx, c, "eventual-vm", "default", 5*time.Second, 10*time.Millisecond) + err := wait.WaitForVMReady(ctx, c, logger, "eventual-vm", "default", 5*time.Second, 10*time.Millisecond) Expect(err).NotTo(HaveOccurred()) Expect(callCount.Load()).To(BeNumerically(">=", int32(3))) }) @@ -95,7 +101,7 @@ var _ = Describe("WaitForVMReady", func() { } c := fake.NewClientBuilder().WithScheme(scheme).WithObjects(vmi).Build() - err := wait.WaitForVMReady(ctx, c, "stuck-vm", "default", 50*time.Millisecond, 10*time.Millisecond) + err := wait.WaitForVMReady(ctx, c, logger, "stuck-vm", "default", 50*time.Millisecond, 10*time.Millisecond) Expect(err).To(HaveOccurred()) Expect(err).To(MatchError(wait.ErrVMTimeout)) }) @@ -103,7 +109,7 @@ var _ = Describe("WaitForVMReady", func() { It("should retry when VMI not found and eventually timeout", func() { c := fake.NewClientBuilder().WithScheme(scheme).Build() - err := wait.WaitForVMReady(ctx, c, "nonexistent", "default", 50*time.Millisecond, 10*time.Millisecond) + err := wait.WaitForVMReady(ctx, c, logger, "nonexistent", "default", 50*time.Millisecond, 10*time.Millisecond) Expect(err).To(HaveOccurred()) Expect(err).To(MatchError(wait.ErrVMTimeout)) }) @@ -129,7 +135,7 @@ var _ = Describe("WaitForVMReady", func() { }). Build() - err := wait.WaitForVMReady(ctx, c, "delayed-vm", "default", 5*time.Second, 10*time.Millisecond) + err := wait.WaitForVMReady(ctx, c, logger, "delayed-vm", "default", 5*time.Second, 10*time.Millisecond) Expect(err).NotTo(HaveOccurred()) Expect(callCount.Load()).To(BeNumerically(">=", int32(3))) }) @@ -149,7 +155,7 @@ var _ = Describe("WaitForVMReady", func() { cancelCtx, cancel := context.WithCancel(ctx) cancel() // Cancel immediately - err := wait.WaitForVMReady(cancelCtx, c, "cancel-vm", "default", 5*time.Second, 10*time.Millisecond) + err := wait.WaitForVMReady(cancelCtx, c, logger, "cancel-vm", "default", 5*time.Second, 10*time.Millisecond) Expect(err).To(HaveOccurred()) }) }) @@ -158,10 +164,13 @@ var _ = Describe("WaitForAllVMsReady", func() { var ( ctx context.Context scheme = cluster.NewScheme() + logger *slog.Logger ) BeforeEach(func() { ctx = context.Background() + buf := &bytes.Buffer{} + logger = logging.NewLogger(buf, true) }) It("should poll all VMs concurrently", func() { @@ -188,6 +197,7 @@ var _ = Describe("WaitForAllVMsReady", func() { results := wait.WaitForAllVMsReady( ctx, c, + logger, []string{"vm-1", "vm-2"}, "default", 5*time.Second, @@ -214,6 +224,7 @@ var _ = Describe("WaitForAllVMsReady", func() { results := wait.WaitForAllVMsReady( ctx, c, + logger, []string{"good-vm", "bad-vm"}, "default", 50*time.Millisecond, @@ -227,7 +238,7 @@ var _ = Describe("WaitForAllVMsReady", func() { It("should handle empty names list", func() { c := fake.NewClientBuilder().WithScheme(scheme).Build() - results := wait.WaitForAllVMsReady(ctx, c, []string{}, "default", 5*time.Second, 10*time.Millisecond) + results := wait.WaitForAllVMsReady(ctx, c, logger, []string{}, "default", 5*time.Second, 10*time.Millisecond) Expect(results).To(BeEmpty()) }) })