I-003: job timeout reaper closes AwaitingCSR/AwaitingApproval gap

Add 11th always-on scheduler loop that transitions jobs stuck in AwaitingCSR (default 24h TTL) or AwaitingApproval (default 168h TTL) to Failed. I-001's retry loop then auto-promotes eligible Failed jobs back to Pending. No new status enum, no schema migration. - JobRepository.ListTimedOutAwaitingJobs with per-status cutoff WHERE - JobService.ReapTimedOutJobs mirrors RetryFailedJobs structure - Scheduler jobTimeoutLoop with atomic.Bool idempotency guard, 2m per-tick context, WaitGroup shutdown drain - Config: CERTCTL_JOB_TIMEOUT_INTERVAL (10m), CERTCTL_JOB_AWAITING_CSR_TIMEOUT (24h), CERTCTL_JOB_AWAITING_APPROVAL_TIMEOUT (168h) - Audit event per transition: actor=system, actorType=System, action=job_timeout, details={old_status, new_status, timeout_reason, age_hours} - 14 new tests: 3 config, 7 service, 4 scheduler
2026-06-14 12:19:05 +00:00 · 2026-04-19 01:04:56 +00:00
parent 4bc8b3e723
commit 1ee77c89f8
12 changed files with 1020 additions and 14 deletions
@@ -6,6 +6,8 @@ import (
 	"errors"
 	"log/slog"
 	"os"
+	"strings"
+	"sync"
 	"testing"
 	"time"

@@ -576,3 +578,356 @@ func TestJobService_RetryFailedJobs_NoAuditServiceOK(t *testing.T) {
 		t.Errorf("expected status Pending after retry, got %s", got)
 	}
 }
+
+// =============================================================================
+// ReapTimedOutJobs Tests (I-003 coverage closure)
+// =============================================================================
+
+func TestJobService_ReapTimedOutJobs_AwaitingCSRTransitionsAndAudits(t *testing.T) {
+	ctx := context.Background()
+
+	now := time.Now()
+	job := &domain.Job{
+		ID:            "job-reap-csr-1",
+		Type:          domain.JobTypeRenewal,
+		CertificateID: "cert-001",
+		Status:        domain.JobStatusAwaitingCSR,
+		CreatedAt:     now.Add(-36 * time.Hour), // 36 hours old
+		ScheduledAt:   now,
+	}
+	jobRepo := &mockJobRepo{
+		Jobs:          map[string]*domain.Job{job.ID: job},
+		StatusUpdates: make(map[string]domain.JobStatus),
+	}
+
+	svc, auditRepo := newTestJobServiceWithAudit(jobRepo)
+
+	if err := svc.ReapTimedOutJobs(ctx, 24*time.Hour, 168*time.Hour); err != nil {
+		t.Fatalf("ReapTimedOutJobs failed: %v", err)
+	}
+
+	// Check the job was updated by retrieving from the mock's Jobs map
+	updatedJob := jobRepo.Jobs[job.ID]
+	if updatedJob.Status != domain.JobStatusFailed {
+		t.Fatalf("expected job %s status Failed after timeout, got %s", job.ID, updatedJob.Status)
+	}
+
+	// LastError should be set
+	if job.LastError == nil || !strings.Contains(*job.LastError, "timed out in AwaitingCSR after 24h") {
+		t.Errorf("expected LastError containing 'timed out in AwaitingCSR after 24h', got %v", job.LastError)
+	}
+
+	// Audit event should be recorded
+	if len(auditRepo.Events) != 1 {
+		t.Fatalf("expected 1 audit event, got %d", len(auditRepo.Events))
+	}
+
+	ev := auditRepo.Events[0]
+	if ev.Action != "job_timeout" {
+		t.Errorf("expected action job_timeout, got %s", ev.Action)
+	}
+	if ev.Actor != "system" {
+		t.Errorf("expected actor system, got %s", ev.Actor)
+	}
+	if ev.ActorType != domain.ActorTypeSystem {
+		t.Errorf("expected actor type System, got %s", ev.ActorType)
+	}
+	if ev.ResourceType != "job" {
+		t.Errorf("expected resource type job, got %s", ev.ResourceType)
+	}
+	if ev.ResourceID != job.ID {
+		t.Errorf("expected resource ID %s, got %s", job.ID, ev.ResourceID)
+	}
+
+	// Verify audit details
+	var details map[string]interface{}
+	if err := json.Unmarshal(ev.Details, &details); err != nil {
+		t.Fatalf("failed to decode audit event details: %v", err)
+	}
+	if got, want := details["old_status"], string(domain.JobStatusAwaitingCSR); got != want {
+		t.Errorf("expected details.old_status=%s, got %v", want, got)
+	}
+	if got, want := details["new_status"], string(domain.JobStatusFailed); got != want {
+		t.Errorf("expected details.new_status=%s, got %v", want, got)
+	}
+	if got, want := details["timeout_reason"], "csr_timeout"; got != want {
+		t.Errorf("expected details.timeout_reason=%s, got %v", want, got)
+	}
+	ageHours, ok := details["age_hours"].(float64)
+	if !ok {
+		t.Errorf("expected details.age_hours to be float64, got %T", details["age_hours"])
+	} else if ageHours < 35 {
+		t.Errorf("expected age_hours > 35, got %f", ageHours)
+	}
+}
+
+func TestJobService_ReapTimedOutJobs_AwaitingApprovalTransitionsAndAudits(t *testing.T) {
+	ctx := context.Background()
+
+	now := time.Now()
+	job := &domain.Job{
+		ID:            "job-reap-approval-1",
+		Type:          domain.JobTypeRenewal,
+		CertificateID: "cert-002",
+		Status:        domain.JobStatusAwaitingApproval,
+		CreatedAt:     now.Add(-200 * time.Hour), // 200 hours old
+		ScheduledAt:   now,
+	}
+	jobRepo := &mockJobRepo{
+		Jobs:          map[string]*domain.Job{job.ID: job},
+		StatusUpdates: make(map[string]domain.JobStatus),
+	}
+
+	svc, auditRepo := newTestJobServiceWithAudit(jobRepo)
+
+	if err := svc.ReapTimedOutJobs(ctx, 24*time.Hour, 168*time.Hour); err != nil {
+		t.Fatalf("ReapTimedOutJobs failed: %v", err)
+	}
+
+	// Check the job was updated
+	updatedJob := jobRepo.Jobs[job.ID]
+	if updatedJob.Status != domain.JobStatusFailed {
+		t.Fatalf("expected job %s status Failed after timeout, got %s", job.ID, updatedJob.Status)
+	}
+
+	// LastError should be set
+	if updatedJob.LastError == nil || !strings.Contains(*updatedJob.LastError, "timed out in AwaitingApproval after 168h") {
+		t.Errorf("expected LastError containing 'timed out in AwaitingApproval after 168h', got %v", updatedJob.LastError)
+	}
+
+	// Audit event details
+	if len(auditRepo.Events) != 1 {
+		t.Fatalf("expected 1 audit event, got %d", len(auditRepo.Events))
+	}
+
+	ev := auditRepo.Events[0]
+	var details map[string]interface{}
+	if err := json.Unmarshal(ev.Details, &details); err != nil {
+		t.Fatalf("failed to decode audit event details: %v", err)
+	}
+	if got, want := details["timeout_reason"], "approval_timeout"; got != want {
+		t.Errorf("expected details.timeout_reason=%s, got %v", want, got)
+	}
+	ageHours, ok := details["age_hours"].(float64)
+	if !ok {
+		t.Errorf("expected details.age_hours to be float64, got %T", details["age_hours"])
+	} else if ageHours < 199 {
+		t.Errorf("expected age_hours > 199, got %f", ageHours)
+	}
+}
+
+func TestJobService_ReapTimedOutJobs_SkipsJobsWithinTTL(t *testing.T) {
+	ctx := context.Background()
+
+	now := time.Now()
+	job := &domain.Job{
+		ID:            "job-within-ttl",
+		Type:          domain.JobTypeRenewal,
+		CertificateID: "cert-003",
+		Status:        domain.JobStatusAwaitingCSR,
+		CreatedAt:     now.Add(-1 * time.Hour), // Only 1 hour old (within 24h TTL)
+		ScheduledAt:   now,
+	}
+	jobRepo := &mockJobRepo{
+		Jobs:          map[string]*domain.Job{job.ID: job},
+		StatusUpdates: make(map[string]domain.JobStatus),
+	}
+
+	svc, auditRepo := newTestJobServiceWithAudit(jobRepo)
+
+	if err := svc.ReapTimedOutJobs(ctx, 24*time.Hour, 168*time.Hour); err != nil {
+		t.Fatalf("ReapTimedOutJobs failed: %v", err)
+	}
+
+	// Job should NOT transition (still AwaitingCSR)
+	if job.Status != domain.JobStatusAwaitingCSR {
+		t.Fatalf("expected job status to remain AwaitingCSR, got %s", job.Status)
+	}
+
+	// No audit events should be recorded
+	if len(auditRepo.Events) != 0 {
+		t.Fatalf("expected 0 audit events, got %d", len(auditRepo.Events))
+	}
+}
+
+func TestJobService_ReapTimedOutJobs_HandlesBothStatusesInOneSweep(t *testing.T) {
+	ctx := context.Background()
+
+	now := time.Now()
+	csr := &domain.Job{
+		ID:            "job-sweep-csr",
+		Type:          domain.JobTypeRenewal,
+		CertificateID: "cert-csr",
+		Status:        domain.JobStatusAwaitingCSR,
+		CreatedAt:     now.Add(-36 * time.Hour),
+		ScheduledAt:   now,
+	}
+	approval := &domain.Job{
+		ID:            "job-sweep-approval",
+		Type:          domain.JobTypeRenewal,
+		CertificateID: "cert-approval",
+		Status:        domain.JobStatusAwaitingApproval,
+		CreatedAt:     now.Add(-200 * time.Hour),
+		ScheduledAt:   now,
+	}
+	jobRepo := &mockJobRepo{
+		Jobs: map[string]*domain.Job{
+			csr.ID:      csr,
+			approval.ID: approval,
+		},
+		StatusUpdates: make(map[string]domain.JobStatus),
+	}
+
+	svc, auditRepo := newTestJobServiceWithAudit(jobRepo)
+
+	if err := svc.ReapTimedOutJobs(ctx, 24*time.Hour, 168*time.Hour); err != nil {
+		t.Fatalf("ReapTimedOutJobs failed: %v", err)
+	}
+
+	// Both jobs should transition to Failed
+	csrUpdated := jobRepo.Jobs[csr.ID]
+	if csrUpdated.Status != domain.JobStatusFailed {
+		t.Fatalf("expected CSR job status Failed, got %s", csrUpdated.Status)
+	}
+	approvalUpdated := jobRepo.Jobs[approval.ID]
+	if approvalUpdated.Status != domain.JobStatusFailed {
+		t.Fatalf("expected approval job status Failed, got %s", approvalUpdated.Status)
+	}
+
+	// Two audit events should be recorded
+	if len(auditRepo.Events) != 2 {
+		t.Fatalf("expected 2 audit events, got %d", len(auditRepo.Events))
+	}
+
+	// Verify each event has the correct timeout_reason
+	for _, ev := range auditRepo.Events {
+		var details map[string]interface{}
+		if err := json.Unmarshal(ev.Details, &details); err != nil {
+			t.Fatalf("failed to decode details: %v", err)
+		}
+		if ev.ResourceID == csr.ID && details["timeout_reason"] != "csr_timeout" {
+			t.Errorf("CSR job: expected timeout_reason=csr_timeout, got %v", details["timeout_reason"])
+		}
+		if ev.ResourceID == approval.ID && details["timeout_reason"] != "approval_timeout" {
+			t.Errorf("approval job: expected timeout_reason=approval_timeout, got %v", details["timeout_reason"])
+		}
+	}
+}
+
+func TestJobService_ReapTimedOutJobs_NoAuditServiceOK(t *testing.T) {
+	ctx := context.Background()
+
+	now := time.Now()
+	job := &domain.Job{
+		ID:            "job-no-audit",
+		Type:          domain.JobTypeRenewal,
+		CertificateID: "cert-004",
+		Status:        domain.JobStatusAwaitingCSR,
+		CreatedAt:     now.Add(-36 * time.Hour),
+		ScheduledAt:   now,
+	}
+	jobRepo := &mockJobRepo{
+		Jobs:          map[string]*domain.Job{job.ID: job},
+		StatusUpdates: make(map[string]domain.JobStatus),
+	}
+
+	// Create service WITHOUT calling SetAuditService
+	svc := newTestJobService(jobRepo)
+
+	// Should not panic and should still transition the job
+	if err := svc.ReapTimedOutJobs(ctx, 24*time.Hour, 168*time.Hour); err != nil {
+		t.Fatalf("ReapTimedOutJobs failed without audit service: %v", err)
+	}
+
+	// Job should still transition to Failed
+	updatedJob := jobRepo.Jobs[job.ID]
+	if updatedJob.Status != domain.JobStatusFailed {
+		t.Fatalf("expected job status Failed without audit service, got %s", updatedJob.Status)
+	}
+}
+
+func TestJobService_ReapTimedOutJobs_ContinuesOnIndividualUpdateFailure(t *testing.T) {
+	ctx := context.Background()
+
+	now := time.Now()
+	jobA := &domain.Job{
+		ID:            "job-fail-update-a",
+		Type:          domain.JobTypeRenewal,
+		CertificateID: "cert-a",
+		Status:        domain.JobStatusAwaitingCSR,
+		CreatedAt:     now.Add(-36 * time.Hour),
+		ScheduledAt:   now,
+	}
+	jobB := &domain.Job{
+		ID:            "job-fail-update-b",
+		Type:          domain.JobTypeRenewal,
+		CertificateID: "cert-b",
+		Status:        domain.JobStatusAwaitingCSR,
+		CreatedAt:     now.Add(-48 * time.Hour),
+		ScheduledAt:   now,
+	}
+	jobRepo := &mockJobRepo{
+		Jobs: map[string]*domain.Job{
+			jobA.ID: jobA,
+			jobB.ID: jobB,
+		},
+		StatusUpdates:    make(map[string]domain.JobStatus),
+		UpdateErrorByID:  make(map[string]error),
+		UpdateErrorByIDMu: sync.Mutex{},
+	}
+	// Make Update fail only for jobA
+	jobRepo.UpdateErrorByIDMu.Lock()
+	jobRepo.UpdateErrorByID[jobA.ID] = errors.New("db connection lost")
+	jobRepo.UpdateErrorByIDMu.Unlock()
+
+	svc, auditRepo := newTestJobServiceWithAudit(jobRepo)
+
+	// Should not propagate individual Update errors
+	if err := svc.ReapTimedOutJobs(ctx, 24*time.Hour, 168*time.Hour); err != nil {
+		t.Fatalf("ReapTimedOutJobs should not propagate individual errors, got: %v", err)
+	}
+
+	// Both jobs have their status modified in memory (the service modifies before Update),
+	// so both will be Failed. What matters is that jobA's audit failed, so only jobB audited.
+	jobAAfter := jobRepo.Jobs[jobA.ID]
+	jobBAfter := jobRepo.Jobs[jobB.ID]
+	if jobAAfter.Status != domain.JobStatusFailed || jobBAfter.Status != domain.JobStatusFailed {
+		t.Fatalf("expected both jobs status Failed (modified before Update), got A=%s B=%s", 
+			jobAAfter.Status, jobBAfter.Status)
+	}
+
+	// Only one audit event (from jobB, since jobA's Update failed and thus no audit for it)
+	if len(auditRepo.Events) != 1 {
+		t.Fatalf("expected 1 audit event (only jobB succeeded), got %d", len(auditRepo.Events))
+	}
+	if auditRepo.Events[0].ResourceID != jobB.ID {
+		t.Errorf("expected audit event for jobB, got event for %s", auditRepo.Events[0].ResourceID)
+	}
+}
+
+func TestJobService_ReapTimedOutJobs_RepoErrorPropagates(t *testing.T) {
+	ctx := context.Background()
+
+	jobRepo := &mockJobRepo{
+		Jobs:              make(map[string]*domain.Job),
+		ListTimedOutErr:   errors.New("database down"),
+		StatusUpdates:     make(map[string]domain.JobStatus),
+		UpdateErrorByIDMu: sync.Mutex{},
+	}
+
+	svc, auditRepo := newTestJobServiceWithAudit(jobRepo)
+
+	err := svc.ReapTimedOutJobs(ctx, 24*time.Hour, 168*time.Hour)
+	if err == nil {
+		t.Fatalf("expected ReapTimedOutJobs to propagate repo error, got nil")
+	}
+
+	if !strings.Contains(err.Error(), "database down") {
+		t.Errorf("expected error to contain 'database down', got: %v", err)
+	}
+
+	// No audit events should be recorded when repo fails
+	if len(auditRepo.Events) != 0 {
+		t.Fatalf("expected 0 audit events after repo error, got %d", len(auditRepo.Events))
+	}
+}