Capture and report the supervised Stalwart process's output

A dry run against a real 0.15.5 instance failed with:

    recovery mode did not come up: http://127.0.0.1:8081/ did not become
    reachable within 1m0s: connect: connection refused

Stalwart had explained itself immediately - "Failed to bind to [::]:8080:
Address already in use" - into a pipe nothing was reading. Diagnosing a
one-line problem took several rounds because the tool threw away the only
evidence. Anything that reports a supervised process failing has to be able
to say why.

Process now captures the child's combined stdout and stderr into a bounded
buffer (64 KiB, keeping the most recent output, with truncation marked
rather than silent - a dead server's reason is at the end of its log), and
exposes it via Output(). recovery.Run appends it to both the startup-timeout
and settings-apply failures, and validate.BootCheck to its boot failure.

Fixes a second bug found while testing the first: Stop returned early when
Signal reported the process had already exited, so cmd.Wait was never
called. Wait is what reaps the child AND waits for the goroutines copying
its output - so the output was discarded in exactly the case where it
matters most, the server dying on its own. os.ErrProcessDone is now treated
as "already gone, still reap it".

The test reproduces the original failure shape: hold the port, start the
helper, let the health check time out, and assert the child's own bind
error survived. Confirmed against the smoke VM too - the same run now ends
with Stalwart's "Address already in use (os error 98)" printed inside the
tool's error.

internal/recovery/process.go

@@ -5,13 +5,50 @@ package recovery
 
 import (
 	"context"
+	"errors"
 	"fmt"
 	"os"
 	"os/exec"
+	"sync"
 	"syscall"
 	"time"
 )
 
+// maxCapturedOutput bounds what Process keeps from the child's stdout and
+// stderr. Stalwart logs continuously once it is up, so this keeps the most
+// recent output rather than the whole session - which is also what a
+// failure needs, since the reason a server died is at the end of its log.
+const maxCapturedOutput = 64 << 10
+
+// outputBuffer collects the child process's combined output for use in
+// error messages. exec.Cmd writes to it from its own goroutine while the
+// supervising goroutine may read it, hence the mutex.
+type outputBuffer struct {
+	mu        sync.Mutex
+	buf       []byte
+	truncated bool
+}
+
+func (b *outputBuffer) Write(p []byte) (int, error) {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	b.buf = append(b.buf, p...)
+	if len(b.buf) > maxCapturedOutput {
+		b.buf = b.buf[len(b.buf)-maxCapturedOutput:]
+		b.truncated = true
+	}
+	return len(p), nil
+}
+
+func (b *outputBuffer) String() string {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	if b.truncated {
+		return "...(earlier output truncated)...\n" + string(b.buf)
+	}
+	return string(b.buf)
+}
+
 // ProcessOptions configures how the target binary is launched.
 type ProcessOptions struct {
 	BinaryPath string
@@ -39,8 +76,27 @@ type ProcessOptions struct {
 // child process, so a caller can start it, wait for it to become healthy,
 // interact with it, and stop it again - without ever touching a real
 // systemd unit or Docker container. See ARCHITECTURE.md §4.4.
+//
+// It captures the child's output. That is not a nicety: a smoke test
+// against a real 0.15.5 instance spent several rounds diagnosing a recovery
+// boot that failed because port 8080 was already in use, and the tool
+// reported only "connection refused" after a 60-second timeout - while
+// Stalwart had printed "Failed to bind to [::]:8080: Address already in
+// use" immediately, to a pipe nothing was reading. Anything that reports a
+// supervised process failing must be able to say why.
 type Process struct {
 	cmd    *exec.Cmd
+	output *outputBuffer
+}
+
+// Output returns what the child has written to stdout and stderr so far,
+// most-recent-first-truncated if it exceeded maxCapturedOutput. Safe to
+// call at any point, including before Start and after Stop.
+func (p *Process) Output() string {
+	if p.output == nil {
+		return ""
+	}
+	return p.output.String()
 }
 
 // Start launches the binary. It returns as soon as the OS has started the
@@ -58,6 +114,9 @@ func (p *Process) Start(ctx context.Context, o ProcessOptions) error {
 
 	cmd := exec.CommandContext(ctx, o.BinaryPath, "--config", o.ConfigPath)
 	cmd.Env = append(os.Environ(), env...)
+	p.output = &outputBuffer{}
+	cmd.Stdout = p.output
+	cmd.Stderr = p.output
 	if err := cmd.Start(); err != nil {
 		return fmt.Errorf("recovery: start %s: %w", o.BinaryPath, err)
 	}
@@ -74,7 +133,12 @@ func (p *Process) Stop(gracePeriod time.Duration) error {
 	if p.cmd == nil || p.cmd.Process == nil {
 		return nil
 	}
-	if err := p.cmd.Process.Signal(syscall.SIGTERM); err != nil {
+	// A process that already exited on its own still has to be reaped:
+	// cmd.Wait is what collects its status and, crucially, waits for the
+	// goroutines copying its output into our buffer. Returning early here
+	// would discard that output in exactly the case where it matters most -
+	// the server died by itself and its log says why.
+	if err := p.cmd.Process.Signal(syscall.SIGTERM); err != nil && !errors.Is(err, os.ErrProcessDone) {
 		return fmt.Errorf("recovery: signal process (pid %d): %w", p.cmd.Process.Pid, err)
 	}
 

internal/recovery/process_test.go

@@ -9,6 +9,7 @@ import (
 	"net"
 	"os"
 	"path/filepath"
+	"strings"
 	"testing"
 	"time"
 )
@@ -105,3 +106,73 @@ func TestWaitForHealthyTimesOut(t *testing.T) {
 		t.Fatal("WaitForHealthy should time out when nothing is listening")
 	}
 }
+
+// The bug this guards against cost several rounds of diagnosis against a
+// real Stalwart: recovery mode failed because port 8080 was already in use,
+// Stalwart said exactly that immediately, and the tool discarded it and
+// reported only a 60-second timeout and "connection refused". The helper
+// process here fails the same way - it can't bind its port and says so on
+// stderr before exiting.
+func TestProcessCapturesOutputFromAFailedStart(t *testing.T) {
+	// Occupy the port first, so the child's bind fails exactly as
+	// Stalwart's did.
+	ln, err := net.Listen("tcp", "127.0.0.1:0")
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer ln.Close()
+	port := fmt.Sprint(ln.Addr().(*net.TCPAddr).Port)
+
+	proc := &Process{}
+	if err := proc.Start(context.Background(), ProcessOptions{
+		BinaryPath: os.Args[0],
+		ExtraEnv: []string{
+			"STALWART_MIGRATOR_TEST_HELPER=1",
+			"STALWART_MIGRATOR_TEST_PORT=" + port,
+		},
+	}); err != nil {
+		t.Fatalf("Start: %v", err)
+	}
+
+	// Poll a port nothing is listening on, exactly as the real flow does:
+	// the tool waits for a listener that never appears while the child is
+	// busy failing and saying why.
+	err = WaitForHealthy(context.Background(), nil, "http://127.0.0.1:1/", time.Second)
+	if err == nil {
+		t.Fatal("WaitForHealthy should not have succeeded against an unreachable URL")
+	}
+	_ = proc.Stop(5 * time.Second)
+
+	got := proc.Output()
+	if !strings.Contains(got, "fake stalwart: listen:") {
+		t.Errorf("captured output = %q, want the child's own bind failure - without it a caller can only report a timeout", got)
+	}
+}
+
+func TestProcessOutputIsSafeBeforeStartAndAfterStop(t *testing.T) {
+	proc := &Process{}
+	if got := proc.Output(); got != "" {
+		t.Errorf("Output() before Start = %q, want empty", got)
+	}
+	if err := proc.Stop(time.Second); err != nil {
+		t.Errorf("Stop on an unstarted process: %v", err)
+	}
+}
+
+// A long-lived server would otherwise grow this buffer without bound.
+func TestOutputBufferKeepsTheMostRecentOutput(t *testing.T) {
+	b := &outputBuffer{}
+	for i := 0; i < 4000; i++ {
+		fmt.Fprintf(b, "line %d filler filler filler filler filler\n", i)
+	}
+	got := b.String()
+	if len(got) > maxCapturedOutput+64 {
+		t.Errorf("buffer grew to %d bytes, want it bounded near %d", len(got), maxCapturedOutput)
+	}
+	if !strings.Contains(got, "line 3999") {
+		t.Error("the most recent output was dropped; a failure's reason is at the end of the log")
+	}
+	if !strings.Contains(got, "truncated") {
+		t.Error("truncation should be visible, not silent")
+	}
+}

internal/recovery/recovery.go

@@ -9,6 +9,7 @@ import (
 	"encoding/hex"
 	"fmt"
 	"net/http"
+	"strings"
 	"time"
 
 	"github.com/LINUXexpert-org/stalwart-migrator/internal/checkpoint"
@@ -87,13 +88,13 @@ func Run(ctx context.Context, store *checkpoint.Store, rs *checkpoint.RunState,
 			startupTimeout = 60 * time.Second
 		}
 		if healthErr := WaitForHealthy(ctx, opts.HTTPClient, opts.ListenURL, startupTimeout); healthErr != nil {
-			return checkpoint.StepOutcome{}, fmt.Errorf("recovery mode did not come up: %w", healthErr)
+			return checkpoint.StepOutcome{}, fmt.Errorf("recovery mode did not come up: %w%s", healthErr, outputSuffix(proc))
 		}
 
 		if applyErr := ApplyAll(ctx, ApplyOptions{
 			CLIBinaryPath: opts.CLIBinaryPath, URL: opts.ListenURL, User: opts.AdminUser, Password: password,
 		}, opts.ApplyFiles); applyErr != nil {
-			return checkpoint.StepOutcome{}, fmt.Errorf("settings apply failed: %w", applyErr)
+			return checkpoint.StepOutcome{}, fmt.Errorf("settings apply failed: %w%s", applyErr, outputSuffix(proc))
 		}
 
 		return checkpoint.StepOutcome{
@@ -108,3 +109,16 @@ func Run(ctx context.Context, store *checkpoint.Store, rs *checkpoint.RunState,
 	report.Results = append(report.Results, CheckResult{Name: "recovery-cycle", Status: StatusOK, Detail: outcome.Detail})
 	return report, nil
 }
+
+// outputSuffix renders a supervised process's captured output for
+// appending to an error, or nothing if it produced none. The server's own
+// words are usually the whole diagnosis - a bind conflict, a rejected
+// config value - and without them the caller is left guessing at a
+// timeout.
+func outputSuffix(proc *Process) string {
+	out := strings.TrimSpace(proc.Output())
+	if out == "" {
+		return " (the process produced no output)"
+	}
+	return fmt.Sprintf("\n--- output from the supervised Stalwart process ---\n%s\n--- end of output ---", out)
+}

internal/validate/bootcheck.go

@@ -7,6 +7,7 @@ import (
 	"context"
 	"fmt"
 	"net/http"
+	"strings"
 	"time"
 
 	"github.com/LINUXexpert-org/stalwart-migrator/internal/checkpoint"
@@ -80,7 +81,12 @@ func BootCheck(ctx context.Context, o BootCheckOptions) (detail string, result *
 		timeout = 30 * time.Second
 	}
 	if healthErr := recovery.WaitForHealthy(ctx, o.HTTPClient, o.ListenURL, timeout); healthErr != nil {
-		return "", nil, fmt.Errorf("migrated instance did not come up under a normal (non-recovery-mode) boot: %w", healthErr)
+		out := strings.TrimSpace(proc.Output())
+		if out == "" {
+			out = "(the process produced no output)"
+		}
+		return "", nil, fmt.Errorf("migrated instance did not come up under a normal (non-recovery-mode) boot: %w\n"+
+			"--- output from the supervised Stalwart process ---\n%s\n--- end of output ---", healthErr, out)
 	}
 	detail = fmt.Sprintf("migrated instance booted normally (not in recovery mode) and answered at %s", o.ListenURL)