Revisit elastic-package test command output (#2756)

mrodm · web-flow · commit 8fc0b3f8ec4e · 2025-07-25T10:14:08.000+02:00
This PR reviews the output shown by the elastic-package test command.
It was mainly focused on test system in Pull Requests builds as well as
Serverless builds.
diff --git a/internal/builder/external_fields.go b/internal/builder/external_fields.go
@@ -78,7 +78,7 @@ func resolveExternalFields(packageRoot, destinationDir string) error {
 				return err
 			}
 		} else {
-			logger.Debugf("%s: source file hasn't been changed", rel)
+			logger.Tracef("%s: source file hasn't been changed", rel)
 		}
 	}
 
diff --git a/internal/compose/compose.go b/internal/compose/compose.go
@@ -204,7 +204,7 @@ func NewProject(name string, paths ...string) (*Project, error) {
 	if ver.Major() < 2 {
 		return nil, fmt.Errorf("required Docker Compose v2, found %s", ver.String())
 	}
-	logger.Debugf("Determined Docker Compose version: %v", ver)
+	logger.Tracef("Determined Docker Compose version: %v", ver)
 
 	v, ok = os.LookupEnv(DisableVerboseOutputComposeEnv)
 	if ok && strings.ToLower(v) != "false" {
@@ -348,7 +348,7 @@ func (p *Project) Logs(ctx context.Context, opts CommandOptions) ([]byte, error)
 func (p *Project) WaitForHealthy(ctx context.Context, opts CommandOptions) error {
 	// Read container IDs
 	args := p.baseArgs()
-	args = append(args, "ps", "-a", "-q")
+	args = append(args, "ps", "-a", "--format", "{{.ID}}")
 
 	var b bytes.Buffer
 	if err := p.runDockerComposeCmd(ctx, dockerComposeOptions{args: args, env: opts.Env, stdout: &b}); err != nil {
@@ -359,34 +359,35 @@ func (p *Project) WaitForHealthy(ctx context.Context, opts CommandOptions) error
 	defer stop()
 
 	containerIDs := strings.Fields(b.String())
+	logger.Debugf("Wait for healthy containers: %s", strings.Join(containerIDs, ","))
 	for {
 		// NOTE: healthy must be reinitialized at each iteration
 		healthy := true
 
-		logger.Debugf("Wait for healthy containers: %s", strings.Join(containerIDs, ","))
 		descriptions, err := docker.InspectContainers(containerIDs...)
 		if err != nil {
 			return err
 		}
 
 		for _, d := range descriptions {
+			dockerID := fmt.Sprintf("%.*s", 12, d.ID) // Ensure it is always 12 characters long
 			switch {
 			// No healthcheck defined for service
 			case d.State.Status == "running" && d.State.Health == nil:
-				logger.Debugf("Container %s (%s) status: %s (no health status)", d.Config.Labels.ComposeService, d.ID, d.State.Status)
+				logger.Debugf("Container %s (%s) status: %s (no health status)", d.Config.Labels.ComposeService, dockerID, d.State.Status)
 				// Service is up and running and it's healthy
 			case d.State.Status == "running" && d.State.Health.Status == "healthy":
-				logger.Debugf("Container %s (%s) status: %s (health: %s)", d.Config.Labels.ComposeService, d.ID, d.State.Status, d.State.Health.Status)
+				logger.Debugf("Container %s (%s) status: %s (health: %s)", d.Config.Labels.ComposeService, dockerID, d.State.Status, d.State.Health.Status)
 				// Container started and finished with exit code 0
 			case d.State.Status == "exited" && d.State.ExitCode == 0:
-				logger.Debugf("Container %s (%s) status: %s (exit code: %d)", d.Config.Labels.ComposeService, d.ID, d.State.Status, d.State.ExitCode)
+				logger.Debugf("Container %s (%s) status: %s (exit code: %d)", d.Config.Labels.ComposeService, dockerID, d.State.Status, d.State.ExitCode)
 				// Container exited with code > 0
 			case d.State.Status == "exited" && d.State.ExitCode > 0:
-				logger.Debugf("Container %s (%s) status: %s (exit code: %d)", d.Config.Labels.ComposeService, d.ID, d.State.Status, d.State.ExitCode)
-				return fmt.Errorf("container (ID: %s) exited with code %d", d.ID, d.State.ExitCode)
+				logger.Debugf("Container %s (%s) status: %s (exit code: %d)", d.Config.Labels.ComposeService, dockerID, d.State.Status, d.State.ExitCode)
+				return fmt.Errorf("container (ID: %s) exited with code %d", dockerID, d.State.ExitCode)
 			// Any different status is considered unhealthy
 			default:
-				logger.Debugf("Container %s (%s) status: unhealthy", d.Config.Labels.ComposeService, d.ID)
+				logger.Debugf("Container %s (%s) status: unhealthy", d.Config.Labels.ComposeService, dockerID)
 				healthy = false
 			}
 		}
diff --git a/internal/compose/compose_other.go b/internal/compose/compose_other.go
@@ -45,7 +45,7 @@ func (p *Project) runDockerComposeCmd(ctx context.Context, opts dockerComposeOpt
 		return fmt.Errorf("failed to start command with pseudo-tty: %w", err)
 	}
 	defer ptty.Close()
-	logger.Debugf("running command: %s", cmd)
+	logger.Tracef("running command: %s", cmd)
 
 	io.Copy(stderr, ptty)
 
diff --git a/internal/docker/docker.go b/internal/docker/docker.go
@@ -69,7 +69,7 @@ func Pull(image string) error {
 		cmd.Stderr = os.Stderr
 	}
 
-	logger.Debugf("run command: %s", cmd)
+	logger.Tracef("run command: %s", cmd)
 	err := cmd.Run()
 	if err != nil {
 		return fmt.Errorf("running docker command failed: %w", err)
@@ -83,7 +83,7 @@ func ContainerID(containerName string) (string, error) {
 	errOutput := new(bytes.Buffer)
 	cmd.Stderr = errOutput
 
-	logger.Debugf("output command: %s", cmd)
+	logger.Tracef("output command: %s", cmd)
 	output, err := cmd.Output()
 	if err != nil {
 		return "", fmt.Errorf("could not find \"%s\" container (stderr=%q): %w", containerName, errOutput.String(), err)
@@ -102,7 +102,7 @@ func ContainerIDsWithLabel(key, value string) ([]string, error) {
 	errOutput := new(bytes.Buffer)
 	cmd.Stderr = errOutput
 
-	logger.Debugf("output command: %s", cmd)
+	logger.Tracef("output command: %s", cmd)
 	output, err := cmd.Output()
 	if err != nil {
 		return []string{}, fmt.Errorf("error getting containers with label \"%s\" (stderr=%q): %w", label, errOutput.String(), err)
@@ -117,7 +117,7 @@ func InspectNetwork(network string) ([]NetworkDescription, error) {
 	errOutput := new(bytes.Buffer)
 	cmd.Stderr = errOutput
 
-	logger.Debugf("output command: %s", cmd)
+	logger.Tracef("output command: %s", cmd)
 	output, err := cmd.Output()
 	if err != nil {
 		return nil, fmt.Errorf("could not inspect the network (stderr=%q): %w", errOutput.String(), err)
@@ -148,7 +148,7 @@ func ConnectToNetworkWithAlias(containerID, network string, aliases []string) er
 	errOutput := new(bytes.Buffer)
 	cmd.Stderr = errOutput
 
-	logger.Debugf("run command: %s", cmd)
+	logger.Tracef("run command: %s", cmd)
 	if err := cmd.Run(); err != nil {
 		return fmt.Errorf("could not attach container to the stack network (stderr=%q): %w", errOutput.String(), err)
 	}
@@ -164,7 +164,7 @@ func InspectContainers(containerIDs ...string) ([]ContainerDescription, error) {
 	errOutput := new(bytes.Buffer)
 	cmd.Stderr = errOutput
 
-	logger.Debugf("output command: %s", cmd)
+	logger.Tracef("output command: %s", cmd)
 	output, err := cmd.Output()
 	if err != nil {
 		return nil, fmt.Errorf("could not inspect containers (stderr=%q): %w", errOutput.String(), err)
@@ -184,7 +184,7 @@ func Copy(containerName, containerPath, localPath string) error {
 	errOutput := new(bytes.Buffer)
 	cmd.Stderr = errOutput
 
-	logger.Debugf("run command: %s", cmd)
+	logger.Tracef("run command: %s", cmd)
 	if err := cmd.Run(); err != nil {
 		return fmt.Errorf("could not copy files from the container (stderr=%q): %w", errOutput.String(), err)
 	}
diff --git a/internal/fleetserver/client.go b/internal/fleetserver/client.go
@@ -113,7 +113,7 @@ func (c *Client) httpRequest(ctx context.Context, method, resourcePath string, r
 	u := base.JoinPath(rel.EscapedPath())
 	u.RawQuery = rel.RawQuery
 
-	logger.Debugf("%s %s", method, u)
+	logger.Tracef("%s %s", method, u)
 
 	req, err := http.NewRequestWithContext(ctx, method, u.String(), reqBody)
 	if err != nil {
diff --git a/internal/fleetserver/status.go b/internal/fleetserver/status.go
@@ -29,7 +29,7 @@ func (c *Client) Status(ctx context.Context) (*Status, error) {
 	if err != nil {
 		return nil, fmt.Errorf("could not build URL: %w", err)
 	}
-	logger.Debugf("GET %s", statusURL)
+	logger.Tracef("GET %s", statusURL)
 	req, err := c.httpRequest(ctx, "GET", statusURL, nil)
 	if err != nil {
 		return nil, err
diff --git a/internal/kibana/agents.go b/internal/kibana/agents.go
@@ -139,6 +139,7 @@ func (c *Client) waitUntilPolicyAssigned(ctx context.Context, a Agent, p Policy)
 	ticker := time.NewTicker(waitForPolicyAssignedRetryPeriod)
 	defer ticker.Stop()
 
+	logger.Debugf("Wait until the policy (ID: %s, revision: %d) is assigned to the agent (ID: %s)...", p.ID, p.Revision, a.ID)
 	for {
 		agent, err := c.getAgent(ctx, a.ID)
 		if err != nil {
@@ -152,7 +153,6 @@ func (c *Client) waitUntilPolicyAssigned(ctx context.Context, a Agent, p Policy)
 			break
 		}
 
-		logger.Debugf("Wait until the policy (ID: %s, revision: %d) is assigned to the agent (ID: %s)...", p.ID, p.Revision, a.ID)
 		select {
 		case <-ctx.Done():
 			if errors.Is(ctx.Err(), context.DeadlineExceeded) {
diff --git a/internal/kibana/client.go b/internal/kibana/client.go
@@ -189,7 +189,7 @@ func (c *Client) newRequest(ctx context.Context, method, resourcePath string, re
 	u := base.JoinPath(rel.EscapedPath())
 	u.RawQuery = rel.RawQuery
 
-	logger.Debugf("%s %s", method, u)
+	logger.Tracef("%s %s", method, u)
 
 	req, err := http.NewRequestWithContext(ctx, method, u.String(), reqBody)
 	if err != nil {
diff --git a/internal/serverless/client.go b/internal/serverless/client.go
@@ -57,7 +57,6 @@ func NewClient(opts ...ClientOption) (*Client, error) {
 	if host != "" {
 		c.host = host
 	}
-	logger.Debugf("Using Elastic Cloud URL: %s", c.host)
 	return c, nil
 }
 
@@ -110,7 +109,7 @@ func (c *Client) newRequest(ctx context.Context, method, resourcePath string, re
 	u := base.JoinPath(rel.EscapedPath())
 	u.RawQuery = rel.RawQuery
 
-	logger.Debugf("%s %s", method, u)
+	logger.Tracef("%s %s", method, u)
 
 	req, err := http.NewRequestWithContext(ctx, method, u.String(), reqBody)
 	if err != nil {
@@ -191,11 +190,11 @@ func (c *Client) EnsureProjectInitialized(ctx context.Context, project *Project)
 		}
 
 		if status != "initialized" {
-			logger.Debugf("project not initialized, status: %s", status)
+			logger.Debugf("project %s not initialized (status: %s)", project.ID, status)
 			timer.Reset(time.Second * 5)
 			continue
 		}
-
+		logger.Debugf("project %s initialized", project.ID)
 		return nil
 	}
 }
diff --git a/internal/stack/dump.go b/internal/stack/dump.go
@@ -46,7 +46,11 @@ type DumpResult struct {
 
 // Dump function exports stack data and dumps them as local artifacts, which can be used for debug purposes.
 func Dump(ctx context.Context, options DumpOptions) ([]DumpResult, error) {
-	logger.Debugf("Dump Elastic stack data")
+	targetPathLogMessage := ""
+	if options.Output != "" {
+		targetPathLogMessage = fmt.Sprintf(" (location: %s)", options.Output)
+	}
+	logger.Debugf("Dump Elastic stack data%s", targetPathLogMessage)
 
 	results, err := dumpStackLogs(ctx, options)
 	if err != nil {
@@ -56,12 +60,6 @@ func Dump(ctx context.Context, options DumpOptions) ([]DumpResult, error) {
 }
 
 func dumpStackLogs(ctx context.Context, options DumpOptions) ([]DumpResult, error) {
-	logger.Debugf("Dump stack logs (location: %s)", options.Output)
-	err := os.RemoveAll(options.Output)
-	if err != nil {
-		return nil, fmt.Errorf("can't remove output location: %w", err)
-	}
-
 	localServices := &localServicesManager{
 		profile: options.Profile,
 	}
@@ -78,6 +76,11 @@ func dumpStackLogs(ctx context.Context, options DumpOptions) ([]DumpResult, erro
 
 	var logsPath string
 	if options.Output != "" {
+		err := os.RemoveAll(options.Output)
+		if err != nil {
+			return nil, fmt.Errorf("can't remove output location: %w", err)
+		}
+
 		logsPath = filepath.Join(options.Output, "logs")
 		err = os.MkdirAll(logsPath, 0755)
 		if err != nil {
@@ -91,7 +94,6 @@ func dumpStackLogs(ctx context.Context, options DumpOptions) ([]DumpResult, erro
 		if len(options.Services) > 0 && !slices.Contains(options.Services, serviceName) {
 			continue
 		}
-
 		logger.Debugf("Dump stack logs for %s", serviceName)
 
 		content, err := dockerComposeLogsSince(ctx, serviceName, options.Profile, options.Since)
diff --git a/internal/testrunner/runners/system/runner.go b/internal/testrunner/runners/system/runner.go
@@ -115,7 +115,7 @@ func (r *runner) SetupRunner(ctx context.Context) error {
 
 	// Install the package before creating the policy, so we control exactly what is being
 	// installed.
-	logger.Debug("Installing package...")
+	logger.Info("Installing package...")
 	resourcesOptions := resourcesOptions{
 		// Install it unless we are running the tear down only.
 		installedPackage: !r.runTearDown,
@@ -131,7 +131,7 @@ func (r *runner) SetupRunner(ctx context.Context) error {
 // TearDownRunner cleans up any global test runner resources. It must be called
 // after the test runner has finished executing all its tests.
 func (r *runner) TearDownRunner(ctx context.Context) error {
-	logger.Debug("Uninstalling package...")
+	logger.Info("Uninstalling package...")
 	resourcesOptions := resourcesOptions{
 		// Keep it installed only if we were running setup, or tests only.
 		installedPackage: r.runSetup || r.runTestsOnly,
diff --git a/internal/testrunner/runners/system/tester.go b/internal/testrunner/runners/system/tester.go
@@ -1335,7 +1335,7 @@ func (r *tester) prepareScenario(ctx context.Context, config *testConfig, stackC
 }
 
 func (r *tester) setupService(ctx context.Context, config *testConfig, serviceOptions servicedeployer.FactoryOptions, svcInfo servicedeployer.ServiceInfo, agentInfo agentdeployer.AgentInfo, agentDeployed agentdeployer.DeployedAgent, policy *kibana.Policy, state ServiceState) (servicedeployer.DeployedService, servicedeployer.ServiceInfo, error) {
-	logger.Debug("setting up service...")
+	logger.Info("Setting up service...")
 	if r.runTearDown || r.runTestsOnly {
 		svcInfo.Test.RunID = state.ServiceRunID
 		svcInfo.OutputDir = state.ServiceOutputDir
@@ -1380,7 +1380,7 @@ func (r *tester) setupService(ctx context.Context, config *testConfig, serviceOp
 		if service == nil {
 			return nil
 		}
-		logger.Debug("tearing down service...")
+		logger.Info("Tearing down service...")
 		if err := service.TearDown(ctx); err != nil {
 			return fmt.Errorf("error tearing down service: %w", err)
 		}
@@ -1399,7 +1399,7 @@ func (r *tester) setupAgent(ctx context.Context, config *testConfig, state Servi
 	if r.runTearDown || r.runTestsOnly {
 		agentRunID = state.AgentRunID
 	}
-	logger.Debug("setting up independent Elastic Agent...")
+	logger.Info("Setting up independent Elastic Agent...")
 	agentInfo, err := r.createAgentInfo(policy, config, agentRunID)
 	if err != nil {
 		return nil, agentdeployer.AgentInfo{}, err
@@ -1426,7 +1426,7 @@ func (r *tester) setupAgent(ctx context.Context, config *testConfig, state Servi
 		if agentDeployer == nil {
 			return nil
 		}
-		logger.Debug("tearing down agent...")
+		logger.Info("Tearing down agent...")
 		if err := agentDeployed.TearDown(ctx); err != nil {
 			return fmt.Errorf("error tearing down agent: %w", err)
 		}
@@ -1708,7 +1708,11 @@ func (r *tester) runTest(ctx context.Context, config *testConfig, stackConfig st
 		return result.WithSkip(skip)
 	}
 
-	logger.Debugf("running test with configuration '%s'", config.Name())
+	if r.testFolder.DataStream != "" {
+		logger.Infof("Running test for data_stream %q with configuration '%s'", r.testFolder.DataStream, config.Name())
+	} else {
+		logger.Infof("Running test with configuration '%s'", config.Name())
+	}
 
 	scenario, err := r.prepareScenario(ctx, config, stackConfig, svcInfo)
 	if err != nil {

Original file line number	Diff line number	Diff line change
`@@ -78,7 +78,7 @@ func resolveExternalFields(packageRoot, destinationDir string) error {`
`78`	`78`	`return err`
`79`	`79`	`}`
`80`	`80`	`} else {`
`81`		`- logger.Debugf("%s: source file hasn't been changed", rel)`
	`81`	`+ logger.Tracef("%s: source file hasn't been changed", rel)`
`82`	`82`	`}`
`83`	`83`	`}`
`84`	`84`
Original file line number	Diff line number	Diff line change
`@@ -45,7 +45,7 @@ func (p *Project) runDockerComposeCmd(ctx context.Context, opts dockerComposeOpt`
`45`	`45`	`return fmt.Errorf("failed to start command with pseudo-tty: %w", err)`
`46`	`46`	`}`
`47`	`47`	`defer ptty.Close()`
`48`		`- logger.Debugf("running command: %s", cmd)`
	`48`	`+ logger.Tracef("running command: %s", cmd)`
`49`	`49`
`50`	`50`	`io.Copy(stderr, ptty)`
`51`	`51`
Original file line number	Diff line number	Diff line change
`@@ -29,7 +29,7 @@ func (c Client) Status(ctx context.Context) (Status, error) {`
`29`	`29`	`if err != nil {`
`30`	`30`	`return nil, fmt.Errorf("could not build URL: %w", err)`
`31`	`31`	`}`
`32`		`- logger.Debugf("GET %s", statusURL)`
	`32`	`+ logger.Tracef("GET %s", statusURL)`
`33`	`33`	`req, err := c.httpRequest(ctx, "GET", statusURL, nil)`
`34`	`34`	`if err != nil {`
`35`	`35`	`return nil, err`
Original file line number	Diff line number	Diff line change
`@@ -57,7 +57,6 @@ func NewClient(opts ...ClientOption) (*Client, error) {`
`57`	`57`	`if host != "" {`
`58`	`58`	`c.host = host`
`59`	`59`	`}`
`60`		`- logger.Debugf("Using Elastic Cloud URL: %s", c.host)`
`61`	`60`	`return c, nil`
`62`	`61`	`}`
`63`	`62`
`@@ -110,7 +109,7 @@ func (c *Client) newRequest(ctx context.Context, method, resourcePath string, re`
`110`	`109`	`u := base.JoinPath(rel.EscapedPath())`
`111`	`110`	`u.RawQuery = rel.RawQuery`
`112`	`111`
`113`		`- logger.Debugf("%s %s", method, u)`
	`112`	`+ logger.Tracef("%s %s", method, u)`
`114`	`113`
`115`	`114`	`req, err := http.NewRequestWithContext(ctx, method, u.String(), reqBody)`
`116`	`115`	`if err != nil {`
`@@ -191,11 +190,11 @@ func (c Client) EnsureProjectInitialized(ctx context.Context, project Project)`
`191`	`190`	`}`
`192`	`191`
`193`	`192`	`if status != "initialized" {`
`194`		`- logger.Debugf("project not initialized, status: %s", status)`
	`193`	`+ logger.Debugf("project %s not initialized (status: %s)", project.ID, status)`
`195`	`194`	`timer.Reset(time.Second * 5)`
`196`	`195`	`continue`
`197`	`196`	`}`
`198`		`-`
	`197`	`+ logger.Debugf("project %s initialized", project.ID)`
`199`	`198`	`return nil`
`200`	`199`	`}`
`201`	`200`	`}`