(fix) reformat subprocess output for consistent logging during update

Old kubebuilder binaries executed during update were outputting
level=info msg= format. Now captures and reformats to INFO/WARN/ERROR
style for consistent user experience.

Assisted-by: Cursor

Author: camilamacedo86

cmd/cmd.go

@@ -36,7 +36,9 @@ import (
 	helmv1alpha1 "sigs.k8s.io/kubebuilder/v4/pkg/plugins/optional/helm/v1alpha"
 )
 
-func init() {
+// Run bootstraps & runs the CLI
+func Run() {
+	// Initialize custom logging handler FIRST - applies to ALL CLI operations
 	opts := logging.HandlerOptions{
 		SlogOpts: slog.HandlerOptions{
 			Level: slog.LevelInfo,
@@ -45,10 +47,6 @@ func init() {
 	handler := logging.NewHandler(os.Stdout, opts)
 	logger := slog.New(handler)
 	slog.SetDefault(logger)
-}
-
-// Run bootstraps & runs the CLI
-func Run() {
 	// Bundle plugin which built the golang projects scaffold with base.go/v4 and kustomize/v2 plugins
 	gov4Bundle, _ := plugin.NewBundleWithOptions(plugin.WithName(golang.DefaultNameQualifier),
 		plugin.WithVersion(plugin.Version{Number: 4}),

pkg/cli/alpha/generate.go

@@ -20,21 +20,8 @@ import (
 	"github.com/spf13/cobra"
 
 	"sigs.k8s.io/kubebuilder/v4/pkg/cli/alpha/internal"
-	"sigs.k8s.io/kubebuilder/v4/pkg/logging"
 )
 
-func init() {
-	// Initialize consistent logging for alpha commands
-	opts := logging.HandlerOptions{
-		SlogOpts: slog.HandlerOptions{
-			Level: slog.LevelInfo,
-		},
-	}
-	handler := logging.NewHandler(os.Stdout, opts)
-	logger := slog.New(handler)
-	slog.SetDefault(logger)
-}
-
 // NewScaffoldCommand returns a new scaffold command, providing the `kubebuilder alpha generate`
 // feature to re-scaffold projects and assist users with updates.
 //

pkg/cli/alpha/internal/generate.go

@@ -19,7 +19,7 @@ package internal
 import (
 	"errors"
 	"fmt"
-	log "log/slog"
+	"log/slog"
 	"os"
 	"os/exec"
 	"strings"
@@ -56,17 +56,17 @@ func (opts *Generate) Generate() error {
 		}
 		opts.OutputDir = cwd
 		if _, err = os.Stat(opts.OutputDir); err == nil {
-			log.Warn("Using current working directory to re-scaffold the project")
-			log.Warn("This directory will be cleaned up and all files removed before the re-generation")
+			slog.Warn("Using current working directory to re-scaffold the project")
+			slog.Warn("This directory will be cleaned up and all files removed before the re-generation")
 
 			// Ensure we clean the correct directory
-			log.Info("Cleaning directory", "dir", opts.OutputDir)
+			slog.Info("Cleaning directory", "dir", opts.OutputDir)
 
 			// Use an absolute path to target files directly
 			cleanupCmd := fmt.Sprintf("rm -rf %s/*", opts.OutputDir)
 			err = util.RunCmd("Running cleanup", "sh", "-c", cleanupCmd)
 			if err != nil {
-				log.Error("Cleanup failed", "error", err)
+				slog.Error("Cleanup failed", "error", err)
 				return fmt.Errorf("cleanup failed: %w", err)
 			}
 
@@ -77,7 +77,7 @@ func (opts *Generate) Generate() error {
 			)
 			err = util.RunCmd("Running cleanup", "sh", "-c", cleanupCmd)
 			if err != nil {
-				log.Error("Cleanup failed", "error", err)
+				slog.Error("Cleanup failed", "error", err)
 				return fmt.Errorf("cleanup failed: %w", err)
 			}
 		}
@@ -123,13 +123,13 @@ func (opts *Generate) Generate() error {
 
 	// Run make targets to ensure the project is properly set up.
 	// These steps are performed on a best-effort basis: if any of the targets fail,
-	// we log a warning to inform the user, but we do not stop the process or return an error.
+	// we slog a warning to inform the user, but we do not stop the process or return an error.
 	// This is to avoid blocking the migration flow due to non-critical issues during setup.
 	targets := []string{"manifests", "generate", "fmt", "vet", "lint-fix"}
 	for _, target := range targets {
 		err := util.RunCmd(fmt.Sprintf("Running make %s", target), "make", target)
 		if err != nil {
-			log.Warn("make target failed", "target", target, "error", err)
+			slog.Warn("make target failed", "target", target, "error", err)
 		}
 	}
 
@@ -220,7 +220,7 @@ func migrateGrafanaPlugin(s store.Store, src, des string) error {
 	var grafanaPlugin struct{}
 	err := s.Config().DecodePluginConfig(plugin.KeyFor(v1alpha.Plugin{}), grafanaPlugin)
 	if errors.As(err, &config.PluginKeyNotFoundError{}) {
-		log.Info("Grafana plugin not found, skipping migration")
+		slog.Info("Grafana plugin not found, skipping migration")
 		return nil
 	} else if err != nil {
 		return fmt.Errorf("failed to decode grafana plugin config: %w", err)
@@ -241,7 +241,7 @@ func migrateAutoUpdatePlugin(s store.Store) error {
 	var autoUpdatePlugin struct{}
 	err := s.Config().DecodePluginConfig(plugin.KeyFor(autoupdate.Plugin{}), autoUpdatePlugin)
 	if errors.As(err, &config.PluginKeyNotFoundError{}) {
-		log.Info("Auto Update plugin not found, skipping migration")
+		slog.Info("Auto Update plugin not found, skipping migration")
 		return nil
 	} else if err != nil {
 		return fmt.Errorf("failed to decode autoupdate plugin config: %w", err)
@@ -259,7 +259,7 @@ func migrateDeployImagePlugin(s store.Store) error {
 	var deployImagePlugin v1alpha1.PluginConfig
 	err := s.Config().DecodePluginConfig(plugin.KeyFor(v1alpha1.Plugin{}), &deployImagePlugin)
 	if errors.As(err, &config.PluginKeyNotFoundError{}) {
-		log.Info("Deploy-image plugin not found, skipping migration")
+		slog.Info("Deploy-image plugin not found, skipping migration")
 		return nil
 	} else if err != nil {
 		return fmt.Errorf("failed to decode deploy-image plugin config: %w", err)
@@ -300,7 +300,7 @@ func getInitArgs(s store.Store) []string {
 	// Replace outdated plugins and exit after the first replacement
 	for i, plg := range plugins {
 		if newPlugin, exists := outdatedPlugins[plg]; exists {
-			log.Warn("We checked that your PROJECT file is configured with deprecated layout. "+
+			slog.Warn("We checked that your PROJECT file is configured with deprecated layout. "+
 				"However, we will try our best to re-generate the project using new one",
 				"deprecated_layout", plg,
 				"new_layout", newPlugin)
@@ -503,8 +503,8 @@ func hasHelmPlugin(cfg store.Store) bool {
 		if errors.As(err, &config.PluginKeyNotFoundError{}) {
 			return false
 		}
-		// Log other errors if needed
-		log.Error("error decoding Helm plugin config", "error", err)
+		// slog other errors if needed
+		slog.Error("error decoding Helm plugin config", "error", err)
 		return false
 	}
 

pkg/cli/alpha/internal/update/helpers/git_commands.go

@@ -19,7 +19,7 @@ package helpers
 import (
 	"errors"
 	"fmt"
-	log "log/slog"
+	"log/slog"
 	"os/exec"
 )
 
@@ -30,7 +30,7 @@ func CommitIgnoreEmpty(msg, ctx string) error {
 		var ee *exec.ExitError
 		if errors.As(err, &ee) && ee.ExitCode() == 1 {
 			// nothing to commit
-			log.Info("No changes to commit", "context", ctx, "message", msg)
+			slog.Info("No changes to commit", "context", ctx, "message", msg)
 			return nil
 		}
 		return fmt.Errorf("git commit failed (%s): %w", ctx, err)

pkg/cli/alpha/internal/update/update.go

@@ -17,12 +17,15 @@ limitations under the License.
 package update
 
 import (
+	"bufio"
 	"bytes"
 	"errors"
 	"fmt"
+	"io"
 	log "log/slog"
 	"os"
 	"os/exec"
+	"regexp"
 	"strings"
 	"time"
 
@@ -503,10 +506,26 @@ func runAlphaGenerate(tempDir, version string) error {
 	tempBinaryPath := tempDir + "/kubebuilder"
 	cmd := exec.Command(tempBinaryPath, "alpha", "generate")
 	cmd.Env = envWithPrefixedPath(tempDir)
-	cmd.Stdout = os.Stdout
-	cmd.Stderr = os.Stderr
 
-	if err := cmd.Run(); err != nil {
+	// Capture and reformat subprocess output to match our logging style
+	stdout, err := cmd.StdoutPipe()
+	if err != nil {
+		return fmt.Errorf("failed to create stdout pipe: %w", err)
+	}
+	stderr, err := cmd.StderrPipe()
+	if err != nil {
+		return fmt.Errorf("failed to create stderr pipe: %w", err)
+	}
+
+	if err := cmd.Start(); err != nil {
+		return fmt.Errorf("failed to start alpha generate: %w", err)
+	}
+
+	// Forward output while reformatting old-style logs
+	go forwardAndReformat(stdout, false)
+	go forwardAndReformat(stderr, true)
+
+	if err := cmd.Wait(); err != nil {
 		return fmt.Errorf("failed to run alpha generate: %w", err)
 	}
 
@@ -515,6 +534,51 @@ func runAlphaGenerate(tempDir, version string) error {
 	return nil
 }
 
+// forwardAndReformat reads from a subprocess stream and reformats old-style logging to new style
+func forwardAndReformat(reader io.Reader, isStderr bool) {
+	scanner := bufio.NewScanner(reader)
+
+	// Regex to match old-style log format: level=info msg="message"
+	logPattern := regexp.MustCompile(`^level=(\w+)\s+msg="?([^"]*)"?(.*)$`)
+
+	for scanner.Scan() {
+		line := scanner.Text()
+
+		// Check if this line matches the old log format
+		if matches := logPattern.FindStringSubmatch(line); matches != nil {
+			level := strings.ToUpper(matches[1])
+			message := matches[2]
+			rest := matches[3]
+
+			// Convert to new format based on level
+			switch level {
+			case "INFO":
+				log.Info(message + rest)
+			case "WARN", "WARNING":
+				log.Warn(message + rest)
+			case "ERROR":
+				log.Error(message + rest)
+			case "DEBUG":
+				log.Debug(message + rest)
+			default:
+				// Fallback: print as-is to appropriate stream
+				if isStderr {
+					fmt.Fprintln(os.Stderr, line)
+				} else {
+					fmt.Println(line)
+				}
+			}
+		} else {
+			// Not a log line, print as-is to appropriate stream
+			if isStderr {
+				fmt.Fprintln(os.Stderr, line)
+			} else {
+				fmt.Println(line)
+			}
+		}
+	}
+}
+
 func envWithPrefixedPath(dir string) []string {
 	env := os.Environ()
 	prefix := "PATH="

pkg/cli/alpha/update.go

@@ -24,21 +24,8 @@ import (
 	"github.com/spf13/cobra"
 
 	"sigs.k8s.io/kubebuilder/v4/pkg/cli/alpha/internal/update"
-	"sigs.k8s.io/kubebuilder/v4/pkg/logging"
 )
 
-func init() {
-	// Initialize consistent logging for alpha commands
-	opts := logging.HandlerOptions{
-		SlogOpts: slog.HandlerOptions{
-			Level: slog.LevelInfo,
-		},
-	}
-	handler := logging.NewHandler(os.Stdout, opts)
-	logger := slog.New(handler)
-	slog.SetDefault(logger)
-}
-
 // NewUpdateCommand creates and returns a new Cobra command for updating Kubebuilder projects.
 func NewUpdateCommand() *cobra.Command {
 	opts := update.Update{}