at-container-registry/scanner/internal/e2e/stuck_test.go

package e2e

import (
	"bytes"
	"crypto/sha256"
	"fmt"
	"io"
	"sync"
	"testing"
	"time"

	scanner "atcr.io/scanner"
	"atcr.io/scanner/internal/mockhold"
)

// Scenarios for the "the scanner gets stuck and never finishes" report.
//
// Everything here is a characterization test: it asserts what the scanner does
// today, and the comment says where that is wrong. Nothing asserts the fixed
// behaviour, so the suite stays green for whoever is working next door.
//
// Every scenario in this file is built so no job ever reaches a successful
// result: each one fails on a blob download instead. That was originally
// forced on them (a successful scan used to panic the test binary on
// worker.go's unconditional result.Summary dereference) and is now simply what
// keeps them focused on the dispatch and reconnect behaviour under test.
//
// The hold-side counterparts are in pkg/hold/pds/scan_broadcaster_stuck_test.go.

// stuckSource is a BlobSource that can stall, delay, and selectively 404, and
// records enough about each Open for a test to tell serial downloads from
// concurrent ones.
//
// Blobs it does hold are served as junk bytes. Nothing verifies that a
// downloaded blob hashes to the digest that asked for it (buildOCILayout writes
// whatever arrives straight to blobs/sha256/<hex>), so junk is enough to make a
// download "succeed" and move the pipeline on to the next one.
type stuckSource struct {
	mu        sync.Mutex
	opens     []time.Time
	perDigest map[string]int
	active    int
	maxActive int

	// delay is slept inside Open, before answering.
	delay time.Duration
	// gate, when non-nil, blocks Open until it is closed.
	gate chan struct{}
	// have lists digests to answer with junk bytes. Anything else 404s.
	have map[string]int
}

func newStuckSource() *stuckSource {
	return &stuckSource{
		perDigest: make(map[string]int),
		have:      make(map[string]int),
	}
}

// gated makes every Open block until Release is called.
func (s *stuckSource) gated() *stuckSource {
	s.gate = make(chan struct{})
	return s
}

// slow makes every Open take d before answering.
func (s *stuckSource) slow(d time.Duration) *stuckSource {
	s.delay = d
	return s
}

// servingJunk registers n junk bytes for download and returns the digest that
// names them. Anything not registered answers 404.
//
// The digest is derived from the content rather than from a scenario label,
// which it has to be: the scanner hashes what arrives and refuses bytes that
// are not what the descriptor said, so a source can no longer answer an
// arbitrary digest with arbitrary bytes.
func (s *stuckSource) servingJunk(n int) string {
	digest := digestOf(bytes.Repeat([]byte("x"), n))
	s.have[mockhold.DigestHex(digest)] = n
	return digest
}

// Release unblocks a gated source. Safe to call more than once, and always
// registered as a cleanup: httptest.Server.Close waits for in-flight requests,
// so a gate that is never opened deadlocks the teardown.
func (s *stuckSource) Release() {
	s.mu.Lock()
	defer s.mu.Unlock()
	if s.gate != nil {
		select {
		case <-s.gate:
		default:
			close(s.gate)
		}
	}
}

func (s *stuckSource) Open(digest string) (io.ReadCloser, int64, error) {
	hex := mockhold.DigestHex(digest)

	s.mu.Lock()
	s.opens = append(s.opens, time.Now())
	s.perDigest[hex]++
	s.active++
	if s.active > s.maxActive {
		s.maxActive = s.active
	}
	gate := s.gate
	delay, size := s.delay, s.have[hex]
	_, served := s.have[hex]
	s.mu.Unlock()

	defer func() {
		s.mu.Lock()
		s.active--
		s.mu.Unlock()
	}()

	if gate != nil {
		select {
		case <-gate:
		case <-time.After(90 * time.Second):
			// Safety net: a test that forgets to Release must fail on its own
			// assertions rather than wedging the whole package.
		}
	}
	if delay > 0 {
		time.Sleep(delay)
	}

	if !served {
		return nil, 0, fmt.Errorf("%w: %s", mockhold.ErrBlobNotFound, digest)
	}
	return io.NopCloser(bytes.NewReader(bytes.Repeat([]byte("x"), size))), int64(size), nil
}

func (s *stuckSource) openCount() int {
	s.mu.Lock()
	defer s.mu.Unlock()
	return len(s.opens)
}

func (s *stuckSource) countFor(digest string) int {
	s.mu.Lock()
	defer s.mu.Unlock()
	return s.perDigest[mockhold.DigestHex(digest)]
}

func (s *stuckSource) peakConcurrency() int {
	s.mu.Lock()
	defer s.mu.Unlock()
	return s.maxActive
}

// waitForOpens blocks until the source has been asked for at least n blobs.
func (s *stuckSource) waitForOpens(t *testing.T, n int, timeout time.Duration) {
	t.Helper()

	deadline := time.Now().Add(timeout)
	for time.Now().Before(deadline) {
		if s.openCount() >= n {
			return
		}
		time.Sleep(5 * time.Millisecond)
	}
	t.Fatalf("only %d blob opens after %s, wanted %d", s.openCount(), timeout, n)
}

// stuckDigest builds a well-formed digest from a label so each synthetic job has
// its own blobs and the accounting is unambiguous.
func stuckDigest(label string) string {
	sum := sha256.Sum256([]byte(label))
	return fmt.Sprintf("sha256:%x", sum)
}

// stuckJob builds an ordinary-looking image job: one config, n tar layers.
// skipReason waves it through, so the pipeline runs for real.
func stuckJob(label string, layers int) *scanner.ScanJob {
	job := &scanner.ScanJob{
		ManifestDigest: stuckDigest(label + "/manifest"),
		Repository:     label,
		Tag:            "latest",
		UserDID:        "did:plc:example",
		UserHandle:     "user.example.com",
		HoldDID:        "did:web:hold.example.com",
		Tier:           "deckhand",
		Config: scanner.BlobDescriptor{
			Digest:    stuckDigest(label + "/config"),
			Size:      64,
			MediaType: "application/vnd.oci.image.config.v1+json",
		},
	}
	for i := 0; i < layers; i++ {
		job.Layers = append(job.Layers, scanner.BlobDescriptor{
			Digest:    stuckDigest(fmt.Sprintf("%s/layer/%d", label, i)),
			Size:      1024,
			MediaType: "application/vnd.oci.image.layer.v1.tar+gzip",
		})
	}
	return job
}

// stuckWaitForDials blocks until the mock hold has accepted at least n connections.
func stuckWaitForDials(t *testing.T, h *Harness, n int, timeout time.Duration) {
	t.Helper()

	deadline := time.Now().Add(timeout)
	for time.Now().Before(deadline) {
		if len(h.Hold.Dials()) >= n {
			return
		}
		time.Sleep(20 * time.Millisecond)
	}
	t.Fatalf("only %d dials after %s, wanted %d", len(h.Hold.Dials()), timeout, n)
}

// stuckTerminalFor reports the first result/error/skipped message for a seq, if any.
func stuckTerminalFor(h *Harness, seq int64) (mockhold.Message, bool) {
	for _, m := range h.Hold.Transcript() {
		if m.Seq == seq && (m.Type == "result" || m.Type == "error" || m.Type == "skipped") {
			return m, true
		}
	}
	return mockhold.Message{}, false
}

// TestStuckJobBlocksEveryJobBehindIt is the first and simplest way scanning
// stops: one job that never finishes, and a worker pool with nothing to
// interrupt it.
//
// A job that hangs holds the only worker (scanner.workers defaults to 1), and
// every job behind it sits in the priority queue having already been acked.
// The blocking itself is not a bug — one worker runs one scan — and this test
// pins its shape.
//
// What has changed is that it now ends. scanner.job_timeout bounds the job
// (8 minutes by default, under the hold's 10), so the head of the line is
// eventually failed and the queue moves; deadline_test.go asserts that with a
// deadline short enough to watch. Here the default is in force and the window
// is seconds, so the blocking is what is visible.
//
// One stage is still outside the deadline: stereoscope's img.Read() takes no
// context, so a layer that decompresses pathologically slowly overruns and the
// job ends when extraction does. vuln.max_image_size is the bound on that one.
func TestStuckJobBlocksEveryJobBehindIt(t *testing.T) {
	src := newStuckSource().gated()
	h := Start(t, src)
	t.Cleanup(src.Release)

	stuck, err := h.Hold.SendJob(stuckJob("stuck", 1))
	if err != nil {
		t.Fatalf("send stuck job: %v", err)
	}
	src.waitForOpens(t, 1, 10*time.Second)

	behind, err := h.Hold.SendJob(stuckJob("behind", 1))
	if err != nil {
		t.Fatalf("send second job: %v", err)
	}

	// The hold is told the second job is under way immediately: the scanner
	// acks on receipt, before it even reaches the queue.
	if _, err := h.Hold.WaitForMessage(func(m mockhold.Message) bool {
		return m.Seq == behind && m.Type == "ack"
	}, 5*time.Second); err != nil {
		t.Fatalf("second job was never acked: %v", err)
	}

	// And then nothing happens to it, because the only worker is wedged.
	if _, err := h.Hold.WaitForMessage(func(m mockhold.Message) bool {
		return m.Seq == behind && m.Type != "ack"
	}, 2*time.Second); err == nil {
		t.Fatal("the queued job finished while the first job was stuck; " +
			"head-of-line blocking is gone, update this test")
	}

	if n := src.openCount(); n != 1 {
		t.Errorf("blob opens = %d, want 1: only the stuck job should have "+
			"started downloading", n)
	}
	if _, ok := stuckTerminalFor(h, stuck); ok {
		t.Error("the stuck job reported a terminal message while its download " +
			"was still hanging")
	}
	t.Logf("seq %d acked and queued, seq %d holding the only worker, no "+
		"deadline on either", behind, stuck)

	// Let both unwind so the mock's teardown does not block on the open request.
	src.Release()
	h.AwaitTerminal(t, stuck, 30*time.Second)
	h.AwaitTerminal(t, behind, 30*time.Second)
}

// TestAcksLandLongBeforeTheWorkDoes quantifies the ack timing gap from the
// scanner's side, and pins the message that closes it.
//
// The scanner acks in handleFrame the moment a job is decoded, before
// queue.Enqueue. That has not changed and should not: the ack means "I have
// it". What it never meant is "a worker is on it", and the hold used to have
// no other signal — handleAck left assigned_at at the dispatch time and the
// ten-minute processing deadline was measured from there, so the deadline
// covered queueing. With scanner.workers=1 and a JobCooldown of 10 seconds,
// job N cannot start earlier than 10*(N-1) seconds after the burst is acked
// even if every scan were instant, so job 61 in a burst was past the hold's
// deadline before a worker touched it. The queue is 100 deep.
//
// A worker now sends 'started' when it dequeues, and the hold measures the
// scanning deadline from that. This test sends a burst and shows the shape
// that makes the two messages different signals: every ack lands up front,
// while the starts are spread across the whole drain.
func TestAcksLandLongBeforeTheWorkDoes(t *testing.T) {
	const burst = 6

	src := newStuckSource().slow(300 * time.Millisecond)
	h := Start(t, src)

	var seqs []int64
	for i := 0; i < burst; i++ {
		seq, err := h.Hold.SendJob(stuckJob(fmt.Sprintf("burst-%d", i), 1))
		if err != nil {
			t.Fatalf("send job %d: %v", i, err)
		}
		seqs = append(seqs, seq)
	}

	// Wait for every ack.
	for _, seq := range seqs {
		if _, err := h.Hold.WaitForMessage(func(m mockhold.Message) bool {
			return m.Seq == seq && m.Type == "ack"
		}, 10*time.Second); err != nil {
			t.Fatalf("seq %d was never acked: %v", seq, err)
		}
	}

	// Then for every job to actually finish.
	for _, seq := range seqs {
		h.AwaitTerminal(t, seq, 60*time.Second)
	}

	var firstAck, lastAck, firstStart, lastStart, firstTerminal, lastTerminal time.Time
	starts := 0
	for _, m := range h.Hold.Transcript() {
		switch m.Type {
		case "ack":
			if firstAck.IsZero() {
				firstAck = m.At
			}
			lastAck = m.At
		case "started":
			starts++
			if firstStart.IsZero() {
				firstStart = m.At
			}
			lastStart = m.At
		default:
			if firstTerminal.IsZero() {
				firstTerminal = m.At
			}
			lastTerminal = m.At
		}
	}

	if starts != burst {
		t.Fatalf("%d 'started' messages for %d jobs: without one per job the "+
			"hold is back to measuring its scanning deadline from dispatch",
			starts, burst)
	}
	if !lastAck.Before(firstTerminal) {
		t.Fatalf("the last ack (%s) did not precede the first terminal message (%s)",
			lastAck, firstTerminal)
	}

	ackSpread := lastAck.Sub(firstAck)
	startSpread := lastStart.Sub(firstStart)
	drain := lastTerminal.Sub(lastAck)
	perJob := drain / burst

	// The point of the pair: the acks are a burst, the starts are the drain.
	// Any deadline measured from the ack is measuring the queue.
	if startSpread <= ackSpread {
		t.Errorf("starts spread over %s and acks over %s; the two signals are "+
			"not distinguishable in this run, so the test proves nothing",
			startSpread.Round(time.Millisecond), ackSpread.Round(time.Millisecond))
	}
	if !lastStart.After(lastAck) {
		t.Errorf("the last start (%s) did not follow the last ack (%s)",
			lastStart, lastAck)
	}

	t.Logf("%d jobs acked within %s of each other, started over %s, and took "+
		"%s to drain (%s per job at a %s cooldown)",
		burst, ackSpread.Round(time.Millisecond), startSpread.Round(time.Millisecond),
		drain.Round(time.Millisecond), perJob.Round(time.Millisecond), testJobCooldown)
	t.Logf("measured from dispatch, at the production cooldown of 10s this "+
		"same burst would take %s to drain", (perJob+10*time.Second)*burst)

	// The arithmetic that used to make this a bug, kept as an assertion so a
	// change to either constant shows up here. It is now the bound on the
	// fallback budget a hold applies to a scanner that sends no 'started', not
	// on healthy work.
	const holdScanningDeadline = 10 * time.Minute
	const productionCooldown = 10 * time.Second
	if ceiling := int(holdScanningDeadline / productionCooldown); ceiling != 60 {
		t.Errorf("a burst of more than %d jobs cannot be drained inside the "+
			"hold's scanning deadline even with free scans; that number moved",
			ceiling)
	}
}

// TestBlobDownloadsAreSerialSoTheirTimeoutsAdd shows why client.httpClient's
// own timeout was never a bound on a job, and so why the job needs its own.
//
// buildOCILayout fetches the config and then every layer in sequence, each
// through client.httpClient, whose Timeout is 5 minutes and applies per
// request. A manifest with 19 layers therefore had a worst case of 20 x 5
// minutes before the job failed, ten times the hold's ten-minute scanning
// deadline. The serial shape asserted below has not changed; what bounds it
// now is scanner.job_timeout, which every one of these requests carries as its
// context, so the sum stops at the job budget rather than at 20 times the
// per-request one.
func TestBlobDownloadsAreSerialSoTheirTimeoutsAdd(t *testing.T) {
	job := stuckJob("serial", 3)

	// Config and the first two layers download and verify; the third keeps its
	// label-derived digest, which the source does not have, so it 404s and the
	// job fails there rather than reaching Syft. The sizes differ so the three
	// served blobs are three distinct digests.
	src := newStuckSource().slow(100 * time.Millisecond)
	job.Config.Digest, job.Config.Size = src.servingJunk(64), 64
	job.Layers[0].Digest, job.Layers[0].Size = src.servingJunk(65), 65
	job.Layers[1].Digest, job.Layers[1].Size = src.servingJunk(66), 66

	h := Start(t, src)

	start := time.Now()
	seq, err := h.Hold.SendJob(job)
	if err != nil {
		t.Fatalf("send job: %v", err)
	}
	msg := h.AwaitTerminal(t, seq, 60*time.Second)
	elapsed := time.Since(start)

	if msg.Type != "error" {
		t.Fatalf("want error, got %s (%s%s)", msg.Type, msg.Error, msg.Reason)
	}
	if n := src.openCount(); n != 4 {
		t.Errorf("blob opens = %d, want 4 (config + 3 layers)", n)
	}
	if peak := src.peakConcurrency(); peak != 1 {
		t.Errorf("peak concurrent downloads = %d, want 1: downloads within a "+
			"job are serial", peak)
	}
	if elapsed < 4*100*time.Millisecond {
		t.Errorf("job took %s, less than the sum of its four downloads", elapsed)
	}

	t.Logf("4 serial downloads took %s; the per-request client timeout still "+
		"adds up across them, and the job's context is what caps the total",
		elapsed.Round(time.Millisecond))
}

// TestReDispatchAfterDisconnectScansTheSameImageTwice proves the duplicate-scan
// prediction.
//
// The hold's Unsubscribe flips the dropped scanner's assigned and processing
// rows back to 'pending', and drainPendingJobs hands them to the next
// connection (pinned in
// pkg/hold/pds/scan_broadcaster_stuck_test.go:TestScanUnsubscribe_ReoffersAJobTheScannerIsStillRunning).
// Nothing tells the scanner's worker pool the socket went away: the job it was
// running is still running, and the re-offered copy is enqueued again with no
// dedupe by seq or digest.
//
// With two workers that is two concurrent downloads of the same blob, which the
// per-digest request count and the source's peak concurrency both show.
func TestReDispatchAfterDisconnectScansTheSameImageTwice(t *testing.T) {
	src := newStuckSource().gated()
	h := Start(t, src, WithWorkers(2))
	t.Cleanup(src.Release)

	job := stuckJob("duplicated", 1)
	seq, err := h.Hold.SendJob(job)
	if err != nil {
		t.Fatalf("send job: %v", err)
	}
	src.waitForOpens(t, 1, 10*time.Second)

	// The scanner is mid-download when the socket dies.
	h.Hold.DropConnections(mockhold.DropAbrupt)
	stuckWaitForDials(t, h, 2, 15*time.Second)

	// What drainPendingJobs does on the new connection: the same seq again.
	again := stuckJob("duplicated", 1)
	again.Seq = seq
	if _, err := h.Hold.SendJob(again); err != nil {
		t.Fatalf("re-send job: %v", err)
	}

	src.waitForOpens(t, 2, 15*time.Second)

	if n := src.countFor(job.Config.Digest); n < 2 {
		t.Errorf("config blob fetched %d times, want 2: the re-offered job was "+
			"deduplicated somewhere", n)
	}
	if peak := src.peakConcurrency(); peak < 2 {
		t.Errorf("peak concurrent downloads = %d, want 2: the duplicate ran "+
			"after the original rather than alongside it", peak)
	}
	t.Logf("seq %d is being downloaded by two workers at once; neither knows "+
		"about the other and both will report a result", seq)

	src.Release()
	h.AwaitTerminal(t, seq, 30*time.Second)
}

// TestResultComputedWhileTheSocketIsDownIsLost covers the last way a job goes
// quiet: the scanner finishes, and its answer goes nowhere.
//
// client.sendJSON guards only on `c.conn == nil`, and nothing ever nils conn —
// connectOnce sets it on dial and the read loop just returns on error. So a
// terminal message computed between a disconnect and the next dial is written
// to a closed connection, WriteJSON fails, sendJSON logs it and returns. Ack,
// SendResult, SendError and SendSkipped all return no error, so the worker has
// no way to know and no path to retry: it moves straight on to the next job.
//
// The hold, meanwhile, put the row back to 'pending' when the scanner dropped,
// so the work is simply done twice — and the second copy is the one that counts.
// The loss window is the reconnect backoff, a flat 5 seconds (Connect's comment
// claims exponential backoff to 30s; the code sleeps 5s and the cursor variable
// it declares is never assigned).
func TestResultComputedWhileTheSocketIsDownIsLost(t *testing.T) {
	src := newStuckSource().gated()
	h := Start(t, src)
	t.Cleanup(src.Release)

	seq, err := h.Hold.SendJob(stuckJob("lost", 1))
	if err != nil {
		t.Fatalf("send job: %v", err)
	}
	src.waitForOpens(t, 1, 10*time.Second)

	if _, err := h.Hold.WaitForMessage(func(m mockhold.Message) bool {
		return m.Seq == seq && m.Type == "ack"
	}, 5*time.Second); err != nil {
		t.Fatalf("job was never acked: %v", err)
	}

	// Kill the socket, then let the job finish. The worker computes its answer
	// with nowhere to send it.
	h.Hold.DropConnections(mockhold.DropAbrupt)
	src.Release()

	// Give the worker time to finish and write into the dead conn, then wait
	// for the reconnect so we can show nothing is re-sent afterwards either.
	stuckWaitForDials(t, h, 2, 15*time.Second)
	time.Sleep(500 * time.Millisecond)

	if msg, ok := stuckTerminalFor(h, seq); ok {
		t.Fatalf("the hold received a %s for seq %d after all; sendJSON now "+
			"survives a dropped socket, update this test", msg.Type, seq)
	}
	if n := h.Queue.Len(); n != 0 {
		t.Errorf("scanner queue holds %d jobs; the lost job was requeued, "+
			"update this test", n)
	}
	t.Logf("seq %d was scanned to completion and its outcome discarded; the "+
		"hold will only notice via its own ten-minute processing timeout", seq)

	// The connection is healthy again — the loss was silent, not fatal.
	if _, err := h.Hold.SendJob(stuckJob("after-reconnect", 1)); err != nil {
		t.Fatalf("hold could not dispatch after the reconnect: %v", err)
	}
}