pixa/internal/handlers/client_gone_internal_test.go

package handlers

import (
	"bytes"
	"context"
	"encoding/json"
	"log/slog"
	"net/http"
	"net/http/httptest"
	"slices"
	"testing"

	"github.com/go-chi/chi/v5/middleware"
	"sneak.berlin/go/pixa/internal/httpfetcher"
	"sneak.berlin/go/pixa/internal/imagerequest"
)

// heldFetcher sends on started when a fetch begins, and holds the fetch until
// release is closed. It then fails the fetch as an upstream error.
type heldFetcher struct {
	started chan struct{}
	release chan struct{}
}

// Fetch sends on f.started, waits for f.release to be closed, and returns
// httpfetcher.ErrUpstreamError.
func (f heldFetcher) Fetch(
	context.Context, imagerequest.Source,
) (*httpfetcher.FetchResult, error) {
	f.started <- struct{}{}

	<-f.release

	return nil, httpfetcher.ErrUpstreamError
}

// readLogLines decodes the JSON log lines in logs.
func readLogLines(t *testing.T, logs *bytes.Buffer) []map[string]any {
	t.Helper()

	t.Logf("logged:\n%s", logs.String())

	var lines []map[string]any

	dec := json.NewDecoder(logs)
	for dec.More() {
		var line map[string]any

		err := dec.Decode(&line)
		if err != nil {
			t.Fatalf("decoding log line: %v", err)
		}

		lines = append(lines, line)
	}

	return lines
}

// TestImageRoutes_ClientGoneAnswers499 checks that both image routes answer
// 499 to a request whose client goes away while its image is being made. A
// first request's fetch is held, so the image is being made, and a second
// request for the same image waits for it until its client goes away. The
// second request must be logged once at info level with its request ID and
// the source host and path. Nothing may be logged at error level.
func TestImageRoutes_ClientGoneAnswers499(t *testing.T) {
	t.Parallel()

	const requestID = "test-request-id"

	for route, imageURL := range photoURLsByRoute() {
		t.Run(route, func(t *testing.T) {
			t.Parallel()

			var logs bytes.Buffer

			fetcher := heldFetcher{started: make(chan struct{}), release: make(chan struct{})}
			h, routes := newRoutesFetchingThrough(t, fetcher,
				slog.New(slog.NewJSONHandler(&logs, nil)))
			target := imageURL(t, h)

			firstDone := make(chan struct{})

			go func() {
				defer close(firstDone)

				sendGet(t, routes, target)
			}()

			<-fetcher.started

			ctx, cancel := context.WithCancel(context.WithValue(t.Context(),
				middleware.RequestIDKey, requestID))
			rec := httptest.NewRecorder()
			secondDone := make(chan struct{})

			go func() {
				defer close(secondDone)

				routes.ServeHTTP(rec, httptest.NewRequestWithContext(
					ctx, http.MethodGet, target, nil))
			}()

			// The fetch is still held, so the second request can end only
			// because its client went away
			cancel()
			<-secondDone

			close(fetcher.release)
			<-firstDone

			if rec.Code != statusClientClosedRequest {
				t.Errorf("status = %d, want %d", rec.Code, statusClientClosedRequest)
			}

			var clientGoneLines int

			for _, line := range readLogLines(t, &logs) {
				if line["level"] == slog.LevelError.String() {
					t.Errorf("logged at error level: %v", line["msg"])
				}

				if line["level"] == slog.LevelInfo.String() &&
					line["msg"] == "client went away before the image was ready" &&
					line["request_id"] == requestID &&
					line["host"] == signedHost &&
					line["path"] == photoPath {
					clientGoneLines++
				}
			}

			if clientGoneLines != 1 {
				t.Errorf("info line naming the request logged %d times, want 1",
					clientGoneLines)
			}
		})
	}
}

// TestImageRoutes_CanceledWithLiveRequestAnswers500 checks that both image
// routes answer 500, logged as "failed to get image" at error level, for an
// image service error that wraps context.Canceled while the request's own
// context is live. Its client has not gone away, so the cancellation is
// pixa's own failure.
func TestImageRoutes_CanceledWithLiveRequestAnswers500(t *testing.T) {
	t.Parallel()

	for route, imageURL := range photoURLsByRoute() {
		t.Run(route, func(t *testing.T) {
			t.Parallel()

			var logs bytes.Buffer

			h, routes := newRoutesFetchingThrough(t,
				failingFetcher{err: context.Canceled},
				slog.New(slog.NewJSONHandler(&logs, nil)))

			rec := sendGet(t, routes, imageURL(t, h))
			if rec.Code != http.StatusInternalServerError {
				t.Errorf("status = %d, want %d",
					rec.Code, http.StatusInternalServerError)
			}

			if !slices.ContainsFunc(readLogLines(t, &logs),
				func(line map[string]any) bool {
					return line["level"] == slog.LevelError.String() &&
						line["msg"] == "failed to get image"
				}) {
				t.Error(`no "failed to get image" line logged at error level`)
			}
		})
	}
}