feat: implement image customizer live output with filtering (#339)

* feat: implement image customizer live output with filtering

* Address copilot feedback

* Address feedback

* Update comments

* Remove a few more info messages

* Allow empty workDir and logsDir in project again - and move the defaults to image specific use case

* Fix change after rebasing

---------

Co-authored-by: George Mileka <gmileka@outlook.com>

Author: George Mileka

internal/app/azldev/cmds/image/imageutils.go

@@ -4,18 +4,27 @@
 package image
 
 import (
+	"context"
 	"errors"
 	"fmt"
 	"path"
+	"path/filepath"
 	"strings"
+	"time"
 
 	"github.com/microsoft/azldev/internal/app/azldev"
+	"github.com/microsoft/azldev/internal/projectgen"
 	"github.com/microsoft/azldev/internal/utils/docker"
 )
 
 const (
+	logFileTimeFormat        = "20060102-150405"
 	imageCustomizerCustomize = "customize"
 	imageCustomizerInject    = "inject-files"
+	// The Image Customizer log always goes to a debug-level log file - regardless
+	// of the log level set for azldev.
+	// The log level set for azldev controls what is shown on the console.
+	defaultLogLevel = "debug"
 )
 
 type imageCustomizerOptions struct {
@@ -28,17 +37,6 @@ type imageCustomizerOptions struct {
 	packageSnapshotTime      string
 }
 
-func getLogLevel(env *azldev.Env) string {
-	switch {
-	case env.Verbose():
-		return "debug"
-	case env.Quiet():
-		return "error"
-	default:
-		return "info"
-	}
-}
-
 func getImageCustomizerImageFormats() []string {
 	// This is temporarily hardcoded until there is a dynamic way of getting the supported formats.
 	// Tracking Item: https://dev.azure.com/mariner-org/polar/_workitems/edit/15309
@@ -54,7 +52,7 @@ func getImageCustomizerImageFormatsString() string {
 }
 
 func buildDockerArgs(
-	buildDir, configDir, inputImageDir, outputPathDir string, rpmSources []rpmSourceInfo,
+	buildDir, configDir, inputImageDir, logsDir, outputPathDir string, rpmSources []rpmSourceInfo,
 ) []string {
 	args := []string{
 		"run", "--rm",
@@ -63,6 +61,7 @@ func buildDockerArgs(
 		"-v", buildDir + ":" + buildDir + docker.MountRWOption,
 		"-v", configDir + ":" + configDir + docker.MountROOption,
 		"-v", inputImageDir + ":" + inputImageDir + docker.MountROOption,
+		"-v", logsDir + ":" + logsDir + docker.MountRWOption,
 		"-v", outputPathDir + ":" + outputPathDir + docker.MountRWOption,
 		"-v", "/dev:/dev",
 	}
@@ -106,7 +105,7 @@ func buildRpmSourcesInfo(rpmSources []string) []rpmSourceInfo {
 }
 
 func buildImageCustomizerArgs(
-	options *imageCustomizerOptions, buildDir, logLevel, logColor string, rpmSources []rpmSourceInfo,
+	options *imageCustomizerOptions, buildDir, logFile, logLevel, logColor string, rpmSources []rpmSourceInfo,
 ) []string {
 	args := []string{
 		"--build-dir", buildDir,
@@ -116,6 +115,7 @@ func buildImageCustomizerArgs(
 		"--output-path", options.outputPath,
 		"--log-level", logLevel,
 		"--log-color", logColor,
+		"--log-file", logFile,
 	}
 
 	for _, rpmSource := range rpmSources {
@@ -145,27 +145,44 @@ func runImageCustomizerContainer(
 		return errors.New("the Image Customizer container tag is not set in the project configuration")
 	}
 
+	// Because buildDir and logsDir will be mapped to the container, they
+	// cannot be empty.
 	buildDir := env.WorkDir()
+	if buildDir == "" {
+		buildDir = filepath.Join(env.ProjectDir(), projectgen.DefaultWorkDir)
+	}
+
+	logsDir := env.LogsDir()
+	if logsDir == "" {
+		logsDir = filepath.Join(env.ProjectDir(), projectgen.DefaultLogDir)
+	}
+
 	configDir := path.Dir(options.configFile)
 	inputImageDir := path.Dir(options.imageFile)
 	outputPathDir := path.Dir(options.outputPath)
 
+	timestamp := time.Now().Format(logFileTimeFormat)
+	logFile := path.Join(logsDir, fmt.Sprintf("image-customizer-%s.log", timestamp))
+	logMarkers := getImageCustomizerInfoMarkers()
+
+	env.Event("Saving detailed logs to: " + logFile)
+
 	rpmSourcesInfo := buildRpmSourcesInfo(options.rpmSources)
 
-	dockerArgs := buildDockerArgs(buildDir, configDir, inputImageDir, outputPathDir, rpmSourcesInfo)
+	dockerArgs := buildDockerArgs(buildDir, configDir, inputImageDir, logsDir, outputPathDir, rpmSourcesInfo)
 
 	imageCustomizerArgs := buildImageCustomizerArgs(
-		options, buildDir, getLogLevel(env), string(env.ColorMode()), rpmSourcesInfo,
+		options, buildDir, logFile, defaultLogLevel, string(env.ColorMode()), rpmSourcesInfo,
 	)
 
-	output, err := docker.RunDocker(env.Context(), env, dockerArgs, containerTag, command, imageCustomizerArgs)
+	_, err := docker.RunDocker(env.Context(), env, dockerArgs, containerTag, command, imageCustomizerArgs, logFile,
+		func(_ context.Context, line string) {
+			filterImageCustomizerOutput(env, line, logMarkers)
+		},
+	)
 	if err != nil {
-		fmt.Printf("%s\n", output)
-
-		return fmt.Errorf("failed to customize image:\n%w", err)
+		return fmt.Errorf("failed to customize image: %w", err)
 	}
 
-	fmt.Printf("%s\n", output)
-
 	return nil
 }

internal/app/azldev/cmds/image/logging.go

@@ -0,0 +1,122 @@
+// Copyright (c) Microsoft Corporation.
+// Licensed under the MIT License.
+
+package image
+
+import (
+	"regexp"
+	"strings"
+
+	"github.com/microsoft/azldev/internal/app/azldev"
+)
+
+// infoPackageListRegex is compiled once at package initialization to extract
+// package lists from log messages that contain "packages: [...]" patterns.
+var infoPackageListRegex = regexp.MustCompile(`packages:\s*\[(.*?)\]`)
+
+// We need a filtering mechanism because the Image Customizer 'info' log level
+// is still more verbose than we want for normal azldev usage - where we want
+// to display just the title of the main operations being performed.
+//
+// To achieve that, we define an 'allow list' of substrings that indicate
+// that a log message is important enough to show to the user in normal mode.
+// If the user runs azldev in verbose mode, we show all messages.
+//
+// The downside to this approach is that if new operations are added to the
+// Image Customizer, we may need to update this list to ensure they are shown.
+//
+// We have https://dev.azure.com/mariner-org/polar/_workitems/edit/15516 to
+// track toning down its output and then removing this filtering from azldev.
+func getImageCustomizerInfoMarkers() []string {
+	return []string{
+		"Converting input image",
+		"Regenerate initramfs file",
+		"Creating full OS initrd",
+		"Creating bootstrap initrd for",
+		"Creating squashfs",
+		"Installing files to empty image",
+		"Creating UKIs",
+		"Customizing partitions",
+		"Setting file SELinux labels",
+		"Provisioning verity",
+		"Running script",
+		"Removing packages",
+		"Installing packages",
+		"Updating packages",
+		"Writing:",
+	}
+}
+
+// extractMessage extracts the message content from a log line.
+// A typical log line from the Image Customizer looks like this:
+// time="2025-09-24T20:02:34Z" level=info msg="<message>"
+// time="2025-09-24T20:02:34Z" level=debug msg="<message>".
+func extractMessage(line string) string {
+	const (
+		prefix = " msg=\""
+		suffix = `"`
+	)
+
+	start := strings.Index(line, prefix)
+	if start == -1 {
+		return ""
+	}
+
+	end := strings.LastIndex(line, suffix)
+	if end == -1 || end <= start+len(prefix) {
+		return ""
+	}
+
+	return line[start+len(prefix) : end]
+}
+
+// doesMessageContainPackages checks if the log message indicates that one or
+// more packages are being installed, removed, or updated.
+// A typical log message might look like:
+// "Installing packages: [package1 package2 ...]"
+// "Removing packages: []" (no packages)
+// "Updating packages: [package1]".
+func doesMessageContainPackages(message string) bool {
+	const (
+		expectedRegexMatches = 2
+	)
+
+	matches := infoPackageListRegex.FindStringSubmatch(message)
+	if len(matches) < expectedRegexMatches {
+		// expectedRegexMatches is 2: one for the full match, one for the capture group.
+		return false // No match or no content group
+	}
+
+	return len(matches[1]) > 0
+}
+
+func filterImageCustomizerOutput(env *azldev.Env, line string, logMarkers []string) {
+	message := extractMessage(line)
+	if message == "" {
+		return
+	}
+
+	switch {
+	case env.Quiet():
+	case env.Verbose():
+		env.Event(message)
+	default:
+		// Default behavior: only show certain "info" messages.
+		for _, logMarker := range logMarkers {
+			if strings.Contains(message, logMarker) {
+				// We don't display 'Installing packages:' if there are
+				// no packages actually being installed.
+				// Same for 'Removing packages:' and 'Updating packages:'.
+				if strings.Contains(message, " packages:") {
+					if !doesMessageContainPackages(message) {
+						return
+					}
+				}
+
+				env.Event(message)
+
+				return
+			}
+		}
+	}
+}

internal/projectgen/projectgen.go

@@ -18,8 +18,8 @@ import (
 
 const (
 	defaultIntermediateOutputDir = "build"
-	defaultLogDir                = "build/logs"
-	defaultWorkDir               = "build/work"
+	DefaultLogDir                = "build/logs"
+	DefaultWorkDir               = "build/work"
 	defaultOutputDir             = "out"
 
 	defaultFilePerms = 0o644
@@ -108,8 +108,8 @@ func GenerateBasicConfig(projectName string) projectconfig.ConfigFile {
 		SchemaURI: projectconfig.DefaultSchemaURI,
 		Project: &projectconfig.ProjectInfo{
 			Description: projectName,
-			LogDir:      defaultLogDir,
-			WorkDir:     defaultWorkDir,
+			LogDir:      DefaultLogDir,
+			WorkDir:     DefaultWorkDir,
 			OutputDir:   defaultOutputDir,
 		},
 

internal/utils/docker/docker.go

@@ -42,8 +42,12 @@ func validateDockerArgs(dockerArgs []string) error {
 	return nil
 }
 
+// RunDocker runs a docker command with the specified arguments and returns the
+// stdout output as a string. It can also capture output from a log file (logFile)
+// in real-time, filter it (logFilter) and send it to the console.
 func RunDocker(ctx context.Context, cmdFactory opctx.CmdFactory, dockerArgs []string,
-	containerTag string, command string, commandArgs []string,
+	containerTag string, command string, commandArgs []string, logFile string,
+	logFilter func(context.Context, string),
 ) (string, error) {
 	err := validateDockerArgs(dockerArgs)
 	if err != nil {
@@ -77,6 +81,11 @@ func RunDocker(ctx context.Context, cmdFactory opctx.CmdFactory, dockerArgs []st
 		return "", fmt.Errorf("failed to wrap the 'docker' command:\n%w", err)
 	}
 
+	err = cmd.AddRealTimeFileListener(logFile, logFilter)
+	if err != nil {
+		return "", fmt.Errorf("failed to add docker log listeners: %w", err)
+	}
+
 	err = cmd.Run(ctx)
 	if err != nil {
 		return stdout.String(), fmt.Errorf("failed to execute 'docker' command:\n%w, stderr: %s", err, stderr.String())