Report the build's own error and refuse daemons too old for BuildKit (closes #234)

A build whose output ends in Docker's error line now fails with that
error, instead of going on to inspect a tag that was never created. The
build output is written to the deployment log before the failure is
recorded, so the log ends in order. Before building, upaas compares the
daemon's API version with 1.39 (Docker Engine 18.09), the first that
builds with BuildKit without experimental mode, and fails the deploy on
an older daemon instead of letting it use the legacy builder. The
README's Compose section gives the update command and the Docker Engine
versions builds need.
Disclosure: merged after a rebase that changed only TODO.md; the review gated this tree on the current next.

Model: opus-5-5
Co-authored-by: clawbot <sneak+clawbot@sneak.cloud>

internal/docker/client.go

@@ -21,6 +21,7 @@ import (
 	"github.com/docker/docker/api/types/image"
 	"github.com/docker/docker/api/types/mount"
 	"github.com/docker/docker/api/types/network"
+	"github.com/docker/docker/api/types/versions"
 	"github.com/docker/docker/client"
 	"github.com/docker/docker/pkg/archive"
 	"github.com/docker/docker/pkg/jsonmessage"
@@ -61,6 +62,15 @@ var ErrInvalidBranch = errors.New("invalid branch name")
 // ErrInvalidCommitSHA is returned when a commit SHA is not a valid hex string.
 var ErrInvalidCommitSHA = errors.New("invalid commit SHA")
 
+// ErrBuildKitUnavailable is returned when the Docker daemon is too old to
+// build with BuildKit.
+var ErrBuildKitUnavailable = errors.New("BuildKit is unavailable on the Docker daemon")
+
+// minBuildKitAPIVersion is the API version of Docker Engine 18.09, the first
+// that builds with BuildKit when asked to without experimental mode. Older
+// daemons refuse the request or silently use the legacy builder.
+const minBuildKitAPIVersion = "1.39"
+
 // validBranchRe matches safe git branch names.
 var validBranchRe = regexp.MustCompile(`^[a-zA-Z0-9._/\-]+$`)
 
@@ -595,6 +605,20 @@ func (c *Client) performBuild(
 	ctx context.Context,
 	opts BuildImageOptions,
 ) (ImageID, error) {
+	server, err := c.docker.ServerVersion(ctx)
+	if err != nil {
+		return "", fmt.Errorf("failed to get Docker version: %w", err)
+	}
+
+	if versions.LessThan(server.APIVersion, minBuildKitAPIVersion) {
+		return "", fmt.Errorf(
+			"%w: Docker Engine %s (API %s) is older than 18.09 (API %s); "+
+				"upgrade Docker Engine",
+			ErrBuildKitUnavailable, server.Version, server.APIVersion,
+			minBuildKitAPIVersion,
+		)
+	}
+
 	// Create tar archive of build context
 	tarArchive, err := archive.TarWithOptions(opts.ContextDir, &archive.TarOptions{})
 	if err != nil {
@@ -660,7 +684,8 @@ const scannerMaxBufferSize = 1024 * 1024 // 1MB
 // newline-delimited JSON. BuildKit's progress arrives encoded in
 // "moby.buildkit.trace" messages; these are decoded and written as plain
 // text, as "docker build --progress=plain" shows it. Other lines, such as
-// build errors, are written unchanged.
+// build errors, are written unchanged. Docker ends a failed build with a line
+// carrying the error; it is returned once the output is written.
 func (c *Client) streamBuildOutput(
 	ctx context.Context,
 	body io.Reader,
@@ -690,6 +715,8 @@ func (c *Client) streamBuildOutput(
 	buf := make([]byte, 0, scannerInitialBufferSize)
 	scanner.Buffer(buf, scannerMaxBufferSize)
 
+	var buildErr error
+
 	for scanner.Scan() {
 		line := scanner.Bytes()
 
@@ -708,6 +735,10 @@ func (c *Client) streamBuildOutput(
 			continue
 		}
 
+		if err == nil && msg.Error != nil {
+			buildErr = msg.Error
+		}
+
 		// One write per line, so it is not split by the display's output.
 		_, _ = fmt.Fprintf(out, "%s\n", line)
 	}
@@ -720,7 +751,7 @@ func (c *Client) streamBuildOutput(
 		return fmt.Errorf("failed to read build output: %w", scanErr)
 	}
 
-	return nil
+	return buildErr
 }
 
 func (c *Client) performClone(

internal/docker/validation_test.go

@@ -271,6 +271,8 @@ func TestPerformBuildUsesBuildKit(t *testing.T) {
 	srv := httptest.NewServer(http.HandlerFunc(
 		func(w http.ResponseWriter, r *http.Request) {
 			switch {
+			case strings.HasSuffix(r.URL.Path, "/version"):
+				_, _ = w.Write([]byte(`{"Version":"27.3.1","ApiVersion":"1.47"}`))
 			case strings.HasSuffix(r.URL.Path, "/build"):
 				if r.URL.Query().Get("version") != "2" {
 					http.Error(w, "not a BuildKit build", http.StatusBadRequest)
@@ -314,3 +316,82 @@ func TestPerformBuildUsesBuildKit(t *testing.T) {
 		t.Errorf("build log is missing the build step:\n%s", buildLog.String())
 	}
 }
+
+// TestPerformBuildFails runs builds that fail against a fake Docker API and
+// checks that each returns its own error and that no image is inspected
+// afterwards.
+func TestPerformBuildFails(t *testing.T) {
+	t.Parallel()
+
+	tests := []struct {
+		name        string
+		engine      string // Docker Engine version the fake daemon reports
+		apiVersion  string // API version the fake daemon reports
+		buildOutput string
+		wantErr     string
+	}{
+		{
+			name:       "build step fails",
+			engine:     "27.3.1",
+			apiVersion: "1.47",
+			buildOutput: `{"stream":"Step 1/1 : RUN false\n"}` + "\n" +
+				`{"errorDetail":{"message":"exit code: 1"},"error":"exit code: 1"}`,
+			wantErr: "exit code: 1",
+		},
+		{
+			name:       "daemon too old for BuildKit",
+			engine:     "18.06.3-ce",
+			apiVersion: "1.38",
+			wantErr: "BuildKit is unavailable on the Docker daemon: " +
+				"Docker Engine 18.06.3-ce (API 1.38) is older than 18.09 (API 1.39); " +
+				"upgrade Docker Engine",
+		},
+		{
+			// The build step's own error shows the build went ahead.
+			name:       "daemon at API 1.39 builds",
+			engine:     "18.09.9",
+			apiVersion: "1.39",
+			buildOutput: `{"stream":"Step 1/1 : RUN false\n"}` + "\n" +
+				`{"errorDetail":{"message":"exit code: 1"},"error":"exit code: 1"}`,
+			wantErr: "exit code: 1",
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			t.Parallel()
+
+			srv := httptest.NewServer(http.HandlerFunc(
+				func(w http.ResponseWriter, r *http.Request) {
+					switch {
+					case strings.HasSuffix(r.URL.Path, "/version"):
+						_, _ = fmt.Fprintf(w, `{"Version":%q,"ApiVersion":%q}`,
+							tt.engine, tt.apiVersion)
+					case strings.HasSuffix(r.URL.Path, "/build"):
+						_, _ = w.Write([]byte(tt.buildOutput))
+					default:
+						t.Errorf("unexpected request to %s", r.URL.Path)
+					}
+				},
+			))
+			t.Cleanup(srv.Close)
+
+			dockerAPI, err := client.NewClientWithOpts(
+				client.WithHost("tcp://" + srv.Listener.Addr().String()),
+			)
+			if err != nil {
+				t.Fatal(err)
+			}
+
+			c := &Client{docker: dockerAPI, log: slog.Default()}
+
+			_, err = c.performBuild(t.Context(), BuildImageOptions{
+				ContextDir: t.TempDir(),
+				Tags:       []string{"upaas-test:1"},
+			})
+			if err == nil || err.Error() != tt.wantErr {
+				t.Errorf("got error %v, want %q", err, tt.wantErr)
+			}
+		})
+	}
+}

internal/service/deploy/deploy.go

@@ -923,7 +923,6 @@ func (svc *Service) buildImage(
 
 	// Create log writer that flushes build output to deployment logs every second
 	logWriter := newDeploymentLogWriter(ctx, deployment)
-	defer logWriter.Close()
 
 	// BuildImage creates a tar archive from the local filesystem,
 	// so it needs the container path where files exist, not the host path.
@@ -933,6 +932,10 @@ func (svc *Service) buildImage(
 		Tags:           []string{imageTag},
 		LogWriter:      logWriter,
 	})
+
+	// Write the rest of the build output to the log before the result.
+	logWriter.Close()
+
 	if err != nil {
 		svc.notify.NotifyBuildFailed(ctx, app, deployment, err)
 		svc.failDeployment(

internal/service/deploy/deploy_build_test.go

@@ -0,0 +1,91 @@
+package deploy_test
+
+import (
+	"context"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"os"
+	"strings"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"go.uber.org/fx/fxtest"
+
+	"sneak.berlin/go/upaas/internal/config"
+	"sneak.berlin/go/upaas/internal/database"
+	"sneak.berlin/go/upaas/internal/docker"
+	"sneak.berlin/go/upaas/internal/logger"
+	"sneak.berlin/go/upaas/internal/models"
+	"sneak.berlin/go/upaas/internal/service/deploy"
+)
+
+// TestBuildImageLogsBuildErrorBeforeDeployError runs a build that fails
+// against a fake Docker API and checks that the deploy fails with the
+// build's own error, which the deployment log shows before the deploy's.
+func TestBuildImageLogsBuildErrorBeforeDeployError(t *testing.T) {
+	t.Parallel()
+
+	srv := httptest.NewServer(http.HandlerFunc(
+		func(w http.ResponseWriter, r *http.Request) {
+			w.Header().Set("Content-Type", "application/json")
+
+			switch {
+			case strings.HasSuffix(r.URL.Path, "/containers/create"):
+				_, _ = w.Write([]byte(`{"Id":"gitcontainer"}`))
+			case strings.HasSuffix(r.URL.Path, "/version"):
+				_, _ = w.Write([]byte(`{"Version":"27.3.1","ApiVersion":"1.47"}`))
+			case strings.HasSuffix(r.URL.Path, "/build"):
+				_, _ = w.Write([]byte(`{"stream":"Step 1/1 : RUN false\n"}` + "\n" +
+					`{"errorDetail":{"message":"exit code: 1"},"error":"exit code: 1"}`))
+			default:
+				// The steps of the git clone, which succeeds.
+				_, _ = w.Write([]byte(`{}`))
+			}
+		},
+	))
+	t.Cleanup(srv.Close)
+
+	log := slog.New(slog.NewTextHandler(os.Stderr, nil))
+	lifecycle := fxtest.NewLifecycle(t)
+
+	dockerClient, err := docker.New(lifecycle, docker.Params{
+		Logger: logger.NewForTest(log),
+		Config: &config.Config{DockerHost: "tcp://" + srv.Listener.Addr().String()},
+	})
+	require.NoError(t, err)
+
+	lifecycle.RequireStart()
+	t.Cleanup(lifecycle.RequireStop)
+
+	db := database.NewTestDatabase(t)
+	ctx := context.Background()
+
+	app := models.NewApp(db)
+	app.ID = "buildapp-id"
+	app.Name = "buildapp"
+	app.Branch = "main"
+	require.NoError(t, app.Save(ctx))
+
+	deployment := models.NewDeployment(db)
+	deployment.AppID = app.ID
+	require.NoError(t, deployment.Save(ctx))
+
+	dataDir := t.TempDir()
+	cfg := &config.Config{DataDir: dataDir, HostDataDir: dataDir}
+
+	// The service has no notify service: the app has no ntfy topic and no
+	// Slack webhook, so the build failure notification sends nothing.
+	svc := deploy.NewTestServiceWithConfig(log, cfg, dockerClient)
+
+	_, err = svc.BuildImage(ctx, app, deployment)
+	require.EqualError(t, err, "failed to build image: exit code: 1")
+
+	logs := deployment.Logs.String
+	buildError := strings.Index(logs, "ERROR: exit code: 1")
+	deployError := strings.Index(logs, "ERROR: failed to build image: exit code: 1")
+
+	require.NotEqual(t, -1, buildError, logs)
+	assert.Less(t, buildError, deployError, logs)
+}

internal/service/deploy/export_test.go

@@ -100,6 +100,15 @@ func (svc *Service) RecordDeployedImage(
 	return svc.recordDeployedImage(ctx, app, deployment, imageID)
 }
 
+// BuildImage exposes buildImage for testing.
+func (svc *Service) BuildImage(
+	ctx context.Context,
+	app *models.App,
+	deployment *models.Deployment,
+) (docker.ImageID, error) {
+	return svc.buildImage(ctx, app, deployment)
+}
+
 // BuildContainerOptionsExported exposes buildContainerOptions for testing.
 func (svc *Service) BuildContainerOptionsExported(
 	ctx context.Context,