feat: adopt structured logging (log/slog) for observability

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,61 +639,45 @@ 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()))
 		}
 	}
 
 	return nil
 }
 
 // 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)
 		data, err := sigyaml.Marshal(vmObj)
 		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))
 }

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())
 			}

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)
+}

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))
+	})
+})