diff --git a/docs/release-control/v6/internal/subsystems/monitoring.md b/docs/release-control/v6/internal/subsystems/monitoring.md index 03ba7b9505..2405e31b85 100644 --- a/docs/release-control/v6/internal/subsystems/monitoring.md +++ b/docs/release-control/v6/internal/subsystems/monitoring.md @@ -17,6 +17,23 @@ ## Purpose +### Ended backup jobs do not supply missing guest verdicts + +For multi-guest vzdump jobs, only an explicit guest finish or failure line +establishes that guest's result. If the parent has ended but its returned log +has no guest verdict, the synthetic task is `unknown`, not failed, successful +or still running. Parent failure/OK status and terminal log markers cannot +substitute for a guest result. Explicit results for other guests remain intact. +The job's attribution stays incomplete and retryable until every observed guest +has an explicit result and the existing contiguous, bounded terminal-log checks +pass. An ordinary later complete read repairs the result under the same task +identity; only then may a finished log be cached as final. + +`TestVzdumpGuestResult*` covers ended/running jobs, truncated/gapped/capped logs, +explicit mixed results, retries and cache finalisation through the real poller, +state JSON and recovery mapper. These are offline log fixtures, not native backup +execution, archive availability, guest thaw or filesystem-liveness proof. + ### Native TrueNAS SCALE CPU uses the reported aggregate `reporting.realtime` may place its aggregate at `fields.cpu.cpu.usage`, diff --git a/internal/monitoring/backup_task_history.go b/internal/monitoring/backup_task_history.go index 9c38cbf6d6..896ac7764d 100644 --- a/internal/monitoring/backup_task_history.go +++ b/internal/monitoring/backup_task_history.go @@ -14,7 +14,8 @@ import ( // A short HTTP response alone does not establish that a multi-guest log was // complete or understood. Require contiguous lines from the start, a terminal -// marker and at least one attributed guest before qualifying the parent job. +// marker and an explicit result for every attributed guest before qualifying +// the parent job. An ended parent cannot fill in a missing guest verdict. func backupGuestLogComplete(job models.BackupTask, lines []proxmox.TaskLogLine, guests []models.BackupTask) bool { if job.EndTime.IsZero() || len(lines) == 0 || len(lines) >= 20000 || len(guests) == 0 { return false @@ -24,6 +25,11 @@ func backupGuestLogComplete(job models.BackupTask, lines []proxmox.TaskLogLine, return false } } + for _, guest := range guests { + if guest.Status != "OK" && guest.Status != "error" { + return false + } + } last := strings.TrimSpace(lines[len(lines)-1].Text) return last == "TASK OK" || strings.HasPrefix(last, "TASK ERROR:") || strings.HasPrefix(last, "TASK WARNINGS:") } diff --git a/internal/monitoring/backup_task_history_test.go b/internal/monitoring/backup_task_history_test.go index 54e62d3fe9..b16fc611de 100644 --- a/internal/monitoring/backup_task_history_test.go +++ b/internal/monitoring/backup_task_history_test.go @@ -2,7 +2,11 @@ package monitoring import ( "context" + "crypto/sha256" + "encoding/json" "fmt" + "os" + "sort" "testing" "time" @@ -10,6 +14,7 @@ import ( "github.com/rcourtman/pulse-go-rewrite/internal/models" "github.com/rcourtman/pulse-go-rewrite/internal/recovery" recoverymanager "github.com/rcourtman/pulse-go-rewrite/internal/recovery/manager" + proxmoxmapper "github.com/rcourtman/pulse-go-rewrite/internal/recovery/mapper/proxmox" "github.com/rcourtman/pulse-go-rewrite/pkg/proxmox" "github.com/stretchr/testify/require" ) @@ -21,11 +26,11 @@ type historyPVEClient struct { func TestBackupHistoryGuestLogRequiresCompleteAttribution(t *testing.T) { job := models.BackupTask{EndTime: time.Now()} - guests := []models.BackupTask{{VMID: 100}} - lines := []proxmox.TaskLogLine{{LineNumber: 1, Text: "INFO: Starting Backup of VM 100 (qemu)"}, {LineNumber: 2, Text: "TASK OK"}} + guests := []models.BackupTask{{VMID: 100, Status: "OK"}} + lines := testLogLines("INFO: Starting Backup of VM 100 (qemu)", "INFO: Finished Backup of VM 100 (00:01:00)", "TASK OK") require.True(t, backupGuestLogComplete(job, lines, guests)) require.False(t, backupGuestLogComplete(job, lines, nil)) - require.False(t, backupGuestLogComplete(job, lines[:1], guests)) + require.False(t, backupGuestLogComplete(job, lines[:2], guests)) lines[0].LineNumber = 2 require.False(t, backupGuestLogComplete(job, lines, guests)) lines[0].LineNumber = 1 @@ -98,3 +103,182 @@ func TestBackupHistoryTruncationDoesNotHideAnotherNodesFailure(t *testing.T) { require.False(t, collection.Complete) require.Equal(t, "collection_failed", collection.Reason) } + +func vzdumpGuestResultFixture() (models.BackupTask, []proxmox.TaskLogLine) { + start := time.Date(2026, 10, 24, 2, 0, 0, 0, time.UTC) + job := models.BackupTask{ID: "site-" + testJobUPID, Instance: "site", Node: "pve1", Type: "vzdump", Status: "OK", StartTime: start, EndTime: start.Add(10 * time.Minute)} + return job, testLogLines( + "INFO: Starting Backup of VM 101 (qemu)", + "INFO: Finished Backup of VM 101 (00:01:00)", + "INFO: Starting Backup of VM 102 (lxc)", + "ERROR: Backup of VM 102 failed - storage unavailable", + "INFO: Starting Backup of VM 103 (qemu)", + ) +} + +func assertVzdumpGuestResults(t *testing.T, tasks []models.BackupTask, last string) { + t.Helper() + require.Len(t, tasks, 3) + sort.Slice(tasks, func(i, j int) bool { return tasks[i].VMID < tasks[j].VMID }) + require.Equal(t, "OK", tasks[0].Status, "explicit success must survive another guest's missing verdict") + require.Equal(t, "error", tasks[1].Status, "explicit failure must not be hidden as unknown") + require.Equal(t, "storage unavailable", tasks[1].Error) + require.Equal(t, last, tasks[2].Status) + points := proxmoxmapper.FromPVEBackupTasks(tasks, nil) + require.Len(t, points, 3) + require.Equal(t, recovery.OutcomeSuccess, points[0].Outcome) + require.Equal(t, recovery.OutcomeFailed, points[1].Outcome) + wantOutcome := recovery.OutcomeUnknown + if last == "OK" { + wantOutcome = recovery.OutcomeSuccess + } else if last == "running" { + wantOutcome = recovery.OutcomeRunning + } + require.Equal(t, wantOutcome, points[2].Outcome) + for i, task := range tasks { + require.Equal(t, recovery.KindOther, points[i].Kind, "task results are not restore artifacts") + require.Equal(t, "site", task.Instance) + require.Equal(t, "pve1", task.Node) + require.Equal(t, "site-"+testJobUPID+fmt.Sprintf("-vm%d", task.VMID), task.ID) + } +} + +func TestVzdumpGuestResultMissingVerdictIsUnknown(t *testing.T) { + for _, status := range []string{"OK", "job errors", "unexpected status", "WARNINGS: 1"} { + for _, shape := range []string{"prefix", "gapped", "capped", "terminal-ok", "terminal-error", "terminal-warning"} { + t.Run(status+"/"+shape, func(t *testing.T) { + job, lines := vzdumpGuestResultFixture() + job.Status = status + switch shape { + case "gapped": + lines[2].LineNumber++ + case "capped": + for len(lines) < 20000 { + lines = append(lines, proxmox.TaskLogLine{LineNumber: int64(len(lines) + 1), Text: "INFO: progress"}) + } + case "terminal-ok": + lines = append(lines, proxmox.TaskLogLine{LineNumber: 6, Text: "TASK OK"}) + case "terminal-error": + lines = append(lines, proxmox.TaskLogLine{LineNumber: 6, Text: "TASK ERROR: job errors"}) + case "terminal-warning": + lines = append(lines, proxmox.TaskLogLine{LineNumber: 6, Text: "TASK WARNINGS: 1"}) + } + tasks := parseVzdumpJobLog(job, testJobUPID, lines) + assertVzdumpGuestResults(t, tasks, "unknown") + require.Equal(t, "backup job ended without an observed guest result", tasks[2].Error) + require.Equal(t, job.EndTime, tasks[2].EndTime, "ended parent must not leave a guest apparently running") + require.False(t, backupGuestLogComplete(job, lines, tasks), "missing verdict must remain retryable even with a terminal marker") + }) + } + } +} + +func TestVzdumpGuestResultRunningStillRunning(t *testing.T) { + job, lines := vzdumpGuestResultFixture() + job.EndTime = time.Time{} + tasks := parseVzdumpJobLog(job, testJobUPID, lines) + assertVzdumpGuestResults(t, tasks, "running") + require.Empty(t, tasks[2].Error) + require.True(t, tasks[2].EndTime.IsZero()) + require.False(t, backupGuestLogComplete(job, lines, tasks)) +} + +func TestVzdumpGuestResultCompleteLogStillRequiresEveryVerdict(t *testing.T) { + job, lines := vzdumpGuestResultFixture() + lines = append(lines, proxmox.TaskLogLine{LineNumber: 6, Text: "TASK ERROR: job errors"}) + for _, status := range []string{"unknown", "running", ""} { + t.Run(status, func(t *testing.T) { + guests := []models.BackupTask{{VMID: 101, Status: "OK"}, {VMID: 102, Status: "error"}, {VMID: 103, Status: status}} + require.False(t, backupGuestLogComplete(job, lines, guests)) + }) + } +} + +func TestVzdumpGuestResultExplicitVerdictsKeepLogBounds(t *testing.T) { + for _, shape := range []string{"complete-ok", "complete-error", "complete-warning", "missing-terminal", "gapped", "capped"} { + t.Run(shape, func(t *testing.T) { + job, lines := vzdumpGuestResultFixture() + lines = append(lines, proxmox.TaskLogLine{LineNumber: 6, Text: "INFO: Finished Backup of VM 103 (00:02:00)"}) + terminal := "TASK OK" + if shape == "complete-error" { + terminal = "TASK ERROR: job errors" + } else if shape == "complete-warning" { + terminal = "TASK WARNINGS: 1" + } + if shape == "capped" { + for len(lines) < 19999 { + lines = append(lines, proxmox.TaskLogLine{LineNumber: int64(len(lines) + 1), Text: "INFO: progress"}) + } + } + if shape != "missing-terminal" { + lines = append(lines, proxmox.TaskLogLine{LineNumber: int64(len(lines) + 1), Text: terminal}) + } + if shape == "gapped" { + lines[0].LineNumber = 2 + } + tasks := parseVzdumpJobLog(job, testJobUPID, lines) + assertVzdumpGuestResults(t, tasks, "OK") + require.Equal(t, shape == "complete-ok" || shape == "complete-error" || shape == "complete-warning", backupGuestLogComplete(job, lines, tasks)) + }) + } +} + +func TestVzdumpGuestResultPollRetriesUnknownUntilExplicitResult(t *testing.T) { + job, lines := vzdumpGuestResultFixture() + client := &jobBackupTaskClient{task: proxmox.Task{UPID: testJobUPID, Node: job.Node, Type: "vzdump", Status: job.Status, StartTime: job.StartTime.Unix(), EndTime: job.EndTime.Unix()}, logLines: lines} + m := &Monitor{state: models.NewState()} + other := models.BackupTask{ID: "another-instance", Instance: "other", VMID: 103, Status: "error"} + m.state.UpdateBackupTasksForInstance("other", []models.BackupTask{other}) + frames := map[string]any{} + capture := func(phase, last string, complete bool) { + t.Helper() + m.pollBackupTasks(context.Background(), "site", client) + snapshot := m.state.GetSnapshot().PVEBackups + var guests []models.BackupTask + var parents []models.BackupTask + for _, task := range snapshot.BackupTasks { + if task.Instance == "other" { + require.Equal(t, other, task, "poll must not cross instance scope") + } else if task.VMID > 0 { + guests = append(guests, task) + } else { + parents = append(parents, task) + } + } + require.Len(t, snapshot.BackupTasks, 5) + assertVzdumpGuestResults(t, guests, last) + points := proxmoxmapper.FromPVEBackupTasks(snapshot.BackupTasks, nil) + m.qualifyBackupGuestTaskDetails("site", parents, map[string]string{job.ID: testJobUPID}, points) + for _, point := range points { + if point.ID == "pve-task:"+job.ID { + require.Equal(t, complete, point.Details["guestTaskDetailsComplete"]) + } + } + entry := m.vzdumpJobTaskCache["site|"+testJobUPID] + require.Equal(t, complete, entry.historyComplete) + require.Equal(t, complete, entry.final) + for _, task := range guests { + require.False(t, task.ObservedAt.IsZero()) + } + frames[phase] = map[string]any{"pve": map[string]any{"data": snapshot}, "points": points, "complete": complete, "log_requests": client.logRequests} + } + capture("prefix", "unknown", false) + client.logLines = append(client.logLines, proxmox.TaskLogLine{LineNumber: 6, Text: "TASK ERROR: job errors"}) + capture("terminal-unresolved", "unknown", false) + client.logLines = append(lines, proxmox.TaskLogLine{LineNumber: 6, Text: "INFO: Finished Backup of VM 103 (00:02:00)"}, proxmox.TaskLogLine{LineNumber: 7, Text: "TASK WARNINGS: 1"}) + capture("resolved", "OK", true) + client.logLines = nil // final logs are immutable; no new read should happen + capture("cached", "OK", true) + require.Equal(t, 3, client.logRequests) + if os.Getenv("PULSE_VZDUMP_RESULT_EXPORT") == "1" { + sources := map[string]string{} + for _, file := range []string{"monitor_backups.go", "backup_task_history.go"} { + data, err := os.ReadFile(file) + require.NoError(t, err) + sources["internal/monitoring/"+file] = fmt.Sprintf("%x", sha256.Sum256(data)) + } + data, err := json.Marshal(map[string]any{"runtime": sources, "observed_at": job.EndTime.Add(time.Hour), "frames": frames}) + require.NoError(t, err) + t.Log("VZDUMP_RESULT_PRODUCER=" + string(data)) + } +} diff --git a/internal/monitoring/monitor_backup_job_tasks_test.go b/internal/monitoring/monitor_backup_job_tasks_test.go index e51d26e8dd..77f55a8468 100644 --- a/internal/monitoring/monitor_backup_job_tasks_test.go +++ b/internal/monitoring/monitor_backup_job_tasks_test.go @@ -113,7 +113,7 @@ func TestParseVzdumpJobLogRunningJob(t *testing.T) { } } -func TestParseVzdumpJobLogJobDiedMidGuest(t *testing.T) { +func TestParseVzdumpJobLogEndedWithoutGuestVerdict(t *testing.T) { start := time.Date(2026, 7, 25, 2, 0, 0, 0, time.UTC) jobTask := models.BackupTask{ ID: "pve-cluster-" + testJobUPID, @@ -132,8 +132,8 @@ func TestParseVzdumpJobLogJobDiedMidGuest(t *testing.T) { if len(tasks) != 1 { t.Fatalf("expected 1 synthetic guest task, got %d", len(tasks)) } - if tasks[0].Status != "error" || tasks[0].Error == "" { - t.Errorf("guest in dead job = %+v, want status error with message", tasks[0]) + if tasks[0].Status != "unknown" || tasks[0].Error != "backup job ended without an observed guest result" { + t.Errorf("guest without a verdict = %+v, want unknown with an evidence explanation", tasks[0]) } if !tasks[0].EndTime.Equal(jobTask.EndTime) { t.Errorf("guest end = %v, want parent end time", tasks[0].EndTime) diff --git a/internal/monitoring/monitor_backups.go b/internal/monitoring/monitor_backups.go index 0a76cc92a8..dcc5043933 100644 --- a/internal/monitoring/monitor_backups.go +++ b/internal/monitoring/monitor_backups.go @@ -2606,11 +2606,12 @@ func parseVzdumpJobLog(jobTask models.BackupTask, upid string, logLines []proxmo sec := sections[vmid] if jobFinished { if sec.status == "running" { - // The job ended without a per-guest verdict; treat as failed - // so the guest doesn't look covered by a backup that never - // completed. - sec.status = "error" - sec.errMsg = "backup job ended before guest backup completed" + // The parent ended, but the returned log may be truncated or + // missing a guest verdict. Neither a failed nor an OK parent + // establishes this guest's result. Keep explicit finish/failure + // lines above authoritative; do not invent either outcome here. + sec.status = "unknown" + sec.errMsg = "backup job ended without an observed guest result" } if sec.end.IsZero() { sec.end = jobTask.EndTime