Keep missing vzdump guest verdicts unknown

An ended parent job does not establish the result of a guest whose log section has no verdict. Preserve explicit results, leave missing results unknown and keep unqualified job logs retryable until attribution is complete. Cover parser, poll/cache, served state and recovery mapping with offline fixtures.

Change-source: pulse-maintainer
This commit is contained in:
pulse-triage[bot]
2026-10-24 06:56:44 +01:00
parent 4505c00250
commit 93bcdbbd7c
5 changed files with 220 additions and 12 deletions
@@ -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`,
+7 -1
View File
@@ -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:")
}
+187 -3
View File
@@ -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))
}
}
@@ -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)
+6 -5
View File
@@ -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