fix(hooks): include hook output in the error when a hook fails

A failing service hook returns only its exit code: dependency failed to start: db hook exited with status 1 The output that explains why is not there, and for a hook running without a listener it does not exist anywhere: runHook created the exec with AttachStdout/AttachStderr false, so the daemon discarded both streams and runWaitExec only polled for the exit code. There was nothing left to look at afterwards. Now stdout and stderr are always attached, and the last lines of them are kept in a bounded buffer. On non-zero exit that tail goes into the error: db hook exited with status 1: SQLSTATE[42S02]: Base table or view not found A successful hook is unchanged - output goes to the listener as before, nothing is added anywhere. With a listener the lines still stream out, the buffer just tees them. The buffer keeps the last 10 lines and 2 KiB, drops the oldest content and never short-writes, so a chatty hook cannot block on it and cannot grow it. runWaitExec is removed: it existed only for the unattached branch, and that branch is what threw the output away. Signed-off-by: Deniss Solnce <[email protected]>
2026-10-12 02:13:08 +00:00 · 2026-08-19 15:08:25 +02:00
parent 8b654eba78
commit f8ed846e4d
2 changed files with 266 additions and 44 deletions
@@ -20,7 +20,7 @@ import (
 	"context"
 	"fmt"
 	"io"
-	"time"
+	"strings"

 	"github.com/compose-spec/compose-go/v2/types"
 	"github.com/moby/moby/api/pkg/stdcopy"
@@ -31,36 +31,50 @@ import (
 	"github.com/docker/compose/v5/pkg/utils"
 )

+const (
+	// hookOutputTailLines and hookOutputTailBytes bound how much of a failing
+	// hook's output is kept for the error message.
+	hookOutputTailLines = 10
+	hookOutputTailBytes = 2048
+)
+
 func (s *composeService) runHook(ctx context.Context, ctr container.Summary, service types.ServiceConfig, hook types.ServiceHook, listener api.ContainerEventListener) error {
-	wOut := utils.GetWriter(func(line string) {
-		listener(api.ContainerEvent{
-			Type:    api.HookEventLog,
-			Source:  getContainerNameWithoutProject(ctr) + " ->",
-			ID:      ctr.ID,
-			Service: service.Name,
-			Line:    line,
+	// The output of a hook is the only explanation of why it failed, so keep the
+	// tail of it even when no listener is attached: the exec used to run
+	// unattached in that case, the daemon discarded both streams, and the caller
+	// was left with a bare exit code. Only surfaced on failure, and bounded.
+	tail := newOutputTail(hookOutputTailLines, hookOutputTailBytes)
+
+	var out io.Writer = tail
+
+	if listener != nil {
+		wOut := utils.GetWriter(func(line string) {
+			listener(api.ContainerEvent{
+				Type:    api.HookEventLog,
+				Source:  getContainerNameWithoutProject(ctr) + " ->",
+				ID:      ctr.ID,
+				Service: service.Name,
+				Line:    line,
+			})
 		})
-	})
-	defer wOut.Close() //nolint:errcheck
+		defer wOut.Close() //nolint:errcheck
+
+		out = io.MultiWriter(wOut, tail)
+	}

-	detached := listener == nil
 	exec, err := s.apiClient().ExecCreate(ctx, ctr.ID, client.ExecCreateOptions{
 		User:         hook.User,
 		Privileged:   hook.Privileged,
 		Env:          ToMobyEnv(hook.Environment),
 		WorkingDir:   hook.WorkingDir,
 		Cmd:          hook.Command,
-		AttachStdout: !detached,
-		AttachStderr: !detached,
+		AttachStdout: true,
+		AttachStderr: true,
 	})
 	if err != nil {
 		return err
 	}

-	if detached {
-		return s.runWaitExec(ctx, exec.ID, service, listener)
-	}
-
 	attachOptions := client.ExecAttachOptions{
 		TTY: service.Tty,
 	}
@@ -71,6 +85,7 @@ func (s *composeService) runHook(ctx context.Context, ctr container.Summary, ser
 			Height: height,
 		}
 	}
+
 	attach, err := s.apiClient().ExecAttach(ctx, exec.ID, attachOptions)
 	if err != nil {
 		return err
@@ -78,9 +93,9 @@ func (s *composeService) runHook(ctx context.Context, ctr container.Summary, ser
 	defer attach.Close()

 	if service.Tty {
-		_, err = io.Copy(wOut, attach.Reader)
+		_, err = io.Copy(out, attach.Reader)
 	} else {
-		_, err = stdcopy.StdCopy(wOut, wOut, attach.Reader)
+		_, err = stdcopy.StdCopy(out, out, attach.Reader)
 	}
 	if err != nil {
 		return err
@@ -91,37 +106,73 @@ func (s *composeService) runHook(ctx context.Context, ctr container.Summary, ser
 		return err
 	}
 	if inspected.ExitCode != 0 {
+		if output := tail.String(); output != "" {
+			return fmt.Errorf("%s hook exited with status %d: %s", service.Name, inspected.ExitCode, output)
+		}
+
 		return fmt.Errorf("%s hook exited with status %d", service.Name, inspected.ExitCode)
 	}
 	return nil
 }

-func (s *composeService) runWaitExec(ctx context.Context, execID string, service types.ServiceConfig, listener api.ContainerEventListener) error {
-	_, err := s.apiClient().ExecStart(ctx, execID, client.ExecStartOptions{
-		Detach: listener == nil,
-		TTY:    service.Tty,
-	})
-	if err != nil {
-		return err
+// outputTail keeps the last lines written to it, bounded by a line and a byte
+// count. Writes past the limit are accepted and the oldest content is dropped,
+// so a chatty hook is never blocked by a full buffer. It is written from a
+// single goroutine (stdcopy or io.Copy) and read after that copy returned.
+type outputTail struct {
+	maxLines int
+	maxBytes int
+	lines    []string
+	partial  strings.Builder
+}
+
+func newOutputTail(maxLines, maxBytes int) *outputTail {
+	return &outputTail{maxLines: maxLines, maxBytes: maxBytes}
+}
+
+func (t *outputTail) Write(p []byte) (int, error) {
+	for _, b := range p {
+		if b != '\n' {
+			// Cap the line being assembled, so a hook printing megabytes without
+			// a newline cannot grow this buffer without bound.
+			if t.partial.Len() < t.maxBytes {
+				t.partial.WriteByte(b)
+			}
+
+			continue
+		}
+
+		t.pushLine(t.partial.String())
+		t.partial.Reset()
 	}

-	// We miss a ContainerExecWait API
-	tick := time.NewTicker(100 * time.Millisecond)
-	for {
-		select {
-		case <-ctx.Done():
-			return nil
-		case <-tick.C:
-			inspect, err := s.apiClient().ExecInspect(ctx, execID, client.ExecInspectOptions{})
-			if err != nil {
-				return nil
-			}
-			if !inspect.Running {
-				if inspect.ExitCode != 0 {
-					return fmt.Errorf("%s hook exited with status %d", service.Name, inspect.ExitCode)
-				}
-				return nil
-			}
-		}
+	return len(p), nil
+}
+
+// pushLine appends a line and drops the oldest one when the limit is reached.
+func (t *outputTail) pushLine(line string) {
+	line = strings.TrimRight(line, "\r")
+	if strings.TrimSpace(line) == "" {
+		return
+	}
+
+	t.lines = append(t.lines, line)
+	if len(t.lines) > t.maxLines {
+		t.lines = t.lines[len(t.lines)-t.maxLines:]
 	}
 }
+
+// String returns the kept output, newest content last, trimmed to maxBytes.
+func (t *outputTail) String() string {
+	lines := t.lines
+	if partial := strings.TrimSpace(t.partial.String()); partial != "" {
+		lines = append(append([]string{}, lines...), partial)
+	}
+
+	output := strings.TrimSpace(strings.Join(lines, "\n"))
+	if len(output) > t.maxBytes {
+		output = output[len(output)-t.maxBytes:]
+	}
+
+	return output
+}
@@ -19,8 +19,12 @@
 package compose

 import (
+	"context"
+	"encoding/binary"
+	"io"
 	"net"
 	"os"
+	"strings"
 	"testing"

 	"github.com/compose-spec/compose-go/v2/types"
@@ -114,3 +118,170 @@ func TestRunHook_ConsoleSize(t *testing.T) {
 		})
 	}
 }
+
+// writeStdcopyFrame writes payload as one multiplexed frame, the format
+// stdcopy.StdCopy reads when the service has no TTY.
+func writeStdcopyFrame(w io.Writer, stream byte, payload string) error {
+	header := make([]byte, 8)
+	header[0] = stream
+	binary.BigEndian.PutUint32(header[4:], uint32(len(payload)))
+
+	if _, err := w.Write(header); err != nil {
+		return err
+	}
+
+	_, err := io.WriteString(w, payload)
+
+	return err
+}
+
+// TestRunHook_FailureIncludesOutput verifies that the error of a failing hook
+// carries the tail of what the hook printed. The exit code alone does not say
+// why it failed, and for a detached hook the output used to be discarded by the
+// daemon, leaving no way to find out at all.
+func TestRunHook_FailureIncludesOutput(t *testing.T) {
+	tests := []struct {
+		name     string
+		listener api.ContainerEventListener
+	}{
+		{name: "with listener", listener: func(api.ContainerEvent) {}},
+		{name: "without listener", listener: nil},
+	}
+
+	for _, tc := range tests {
+		t.Run(tc.name, func(t *testing.T) {
+			mockCtrl := gomock.NewController(t)
+			defer mockCtrl.Finish()
+
+			mockAPI := mocks.NewMockAPIClient(mockCtrl)
+			mockCli := mocks.NewMockCli(mockCtrl)
+			mockCli.EXPECT().Client().Return(mockAPI).AnyTimes()
+			mockCli.EXPECT().Err().Return(streams.NewOut(os.Stderr)).AnyTimes()
+			mockCli.EXPECT().Out().Return(streams.NewOut(os.Stdout)).AnyTimes()
+
+			service := types.ServiceConfig{Name: "db"}
+			hook := types.ServiceHook{Command: []string{"/migrate.sh"}}
+			ctr := container.Summary{ID: "container123"}
+
+			// Both streams must be attached, otherwise the daemon drops the output.
+			mockAPI.EXPECT().
+				ExecCreate(gomock.Any(), "container123", gomock.Any()).
+				DoAndReturn(func(_ context.Context, _ string, options client.ExecCreateOptions) (client.ExecCreateResult, error) {
+					assert.Check(t, options.AttachStdout, "stdout must be attached")
+					assert.Check(t, options.AttachStderr, "stderr must be attached")
+
+					return client.ExecCreateResult{ID: "exec123"}, nil
+				})
+
+			serverConn, clientConn := net.Pipe()
+
+			go func() {
+				assert.NilError(t, writeStdcopyFrame(serverConn, 1, "migrating\n"))
+				assert.NilError(t, writeStdcopyFrame(serverConn, 2, "SQLSTATE[42S02]: table not found\n"))
+				serverConn.Close() //nolint:errcheck
+			}()
+
+			mockAPI.EXPECT().
+				ExecAttach(gomock.Any(), "exec123", gomock.Any()).
+				Return(client.ExecAttachResult{
+					HijackedResponse: client.NewHijackedResponse(clientConn, ""),
+				}, nil)
+
+			mockAPI.EXPECT().
+				ExecInspect(gomock.Any(), "exec123", gomock.Any()).
+				Return(client.ExecInspectResult{ExitCode: 1}, nil)
+
+			s, err := NewComposeService(mockCli)
+			assert.NilError(t, err)
+
+			err = s.(*composeService).runHook(t.Context(), ctr, service, hook, tc.listener)
+			assert.ErrorContains(t, err, "db hook exited with status 1")
+			assert.ErrorContains(t, err, "SQLSTATE[42S02]: table not found")
+		})
+	}
+}
+
+// TestRunHook_SuccessKeepsOutputOut verifies a successful hook stays silent: its
+// output belongs to the listener, not to an error nobody returns.
+func TestRunHook_SuccessKeepsOutputOut(t *testing.T) {
+	mockCtrl := gomock.NewController(t)
+	defer mockCtrl.Finish()
+
+	mockAPI := mocks.NewMockAPIClient(mockCtrl)
+	mockCli := mocks.NewMockCli(mockCtrl)
+	mockCli.EXPECT().Client().Return(mockAPI).AnyTimes()
+	mockCli.EXPECT().Err().Return(streams.NewOut(os.Stderr)).AnyTimes()
+	mockCli.EXPECT().Out().Return(streams.NewOut(os.Stdout)).AnyTimes()
+
+	var lines []string
+
+	listener := func(event api.ContainerEvent) {
+		lines = append(lines, event.Line)
+	}
+
+	serverConn, clientConn := net.Pipe()
+
+	go func() {
+		assert.NilError(t, writeStdcopyFrame(serverConn, 1, "all good\n"))
+		serverConn.Close() //nolint:errcheck
+	}()
+
+	mockAPI.EXPECT().
+		ExecCreate(gomock.Any(), "container123", gomock.Any()).
+		Return(client.ExecCreateResult{ID: "exec123"}, nil)
+	mockAPI.EXPECT().
+		ExecAttach(gomock.Any(), "exec123", gomock.Any()).
+		Return(client.ExecAttachResult{
+			HijackedResponse: client.NewHijackedResponse(clientConn, ""),
+		}, nil)
+	mockAPI.EXPECT().
+		ExecInspect(gomock.Any(), "exec123", gomock.Any()).
+		Return(client.ExecInspectResult{ExitCode: 0}, nil)
+
+	s, err := NewComposeService(mockCli)
+	assert.NilError(t, err)
+
+	err = s.(*composeService).runHook(t.Context(),
+		container.Summary{ID: "container123"},
+		types.ServiceConfig{Name: "db"},
+		types.ServiceHook{Command: []string{"/migrate.sh"}},
+		listener)
+	assert.NilError(t, err)
+	assert.DeepEqual(t, lines, []string{"all good"})
+}
+
+func TestOutputTail(t *testing.T) {
+	t.Run("keeps only the last lines", func(t *testing.T) {
+		tail := newOutputTail(2, 1024)
+		_, err := tail.Write([]byte("one\ntwo\nthree\n"))
+		assert.NilError(t, err)
+		assert.Equal(t, tail.String(), "two\nthree")
+	})
+
+	t.Run("keeps a line without trailing newline", func(t *testing.T) {
+		tail := newOutputTail(5, 1024)
+		_, err := tail.Write([]byte("no newline here"))
+		assert.NilError(t, err)
+		assert.Equal(t, tail.String(), "no newline here")
+	})
+
+	t.Run("drops blank lines", func(t *testing.T) {
+		tail := newOutputTail(3, 1024)
+		_, err := tail.Write([]byte("\n\nreal\n\n"))
+		assert.NilError(t, err)
+		assert.Equal(t, tail.String(), "real")
+	})
+
+	t.Run("bounds bytes and keeps accepting writes", func(t *testing.T) {
+		tail := newOutputTail(10, 16)
+
+		n, err := tail.Write([]byte(strings.Repeat("x", 4096)))
+		assert.NilError(t, err)
+		assert.Equal(t, n, 4096, "a full buffer must not short-write, it would block the hook")
+
+		_, err = tail.Write([]byte("\nlast line\n"))
+		assert.NilError(t, err)
+		assert.Check(t, len(tail.String()) <= 16, "output must stay within the byte limit")
+		assert.Check(t, strings.HasSuffix(tail.String(), "last line"), "the newest output must survive")
+	})
+}