Look twice before saying a probe failed, and say conditions in machine names (hq issue 277)

D2 raised a resolver urgent on one query that timed out while its machine was loaded, and its summary carried the resolver's address and socket text, so the operator channel withheld the whole alert. - D2 asks every question up to three times, all at once; a resolver that answers nothing is held for the next run and raised urgent when two runs in a row find it silent. A wrong answer is still raised at once. - Findings a single look can be wrong about carry Confirm: raised on the second look in a row, kept while open, never cleared-and-reraised. Used by D2 silence, D3 (also asks discovery twice), D6 behind, D9, D13 unmeasured, probe-failed of the doctor, and blind watchdog rows. - Probe seat asks (D8, D13) are asked again when the bus brought no answer. - Summaries name machines and say things in words; addresses, paths, domains and raw errors move to the evidence (D2, D5, D8, D9, D13, S12). - internal/outward mirrors the messenger's content rule, allowing the mesh's machine names; the keeper rewords a summary that would be withheld and keeps it whole in the evidence; a TestMain lint fails the suite on any raised or linted finding that would be withheld.
2026-10-06 18:40:33 +02:00
parent 7aa98e64ce
commit 8e8712e352
16 changed files with 1215 additions and 85 deletions
@@ -140,6 +140,19 @@ func awaitingPush(node string, foreseen []string, since time.Time, waited time.D
 // probeResolvers is D2: every holder of the mesh's resolver answers each machine's name with its
 // address for IPv4, and with no address and no error for IPv6 — NODATA, not NXDOMAIN, which musl
 // takes as final (issue 262).
+//
+// **One unanswered question is not a resolver that does not answer** (novox/hq issue 277). D2 raised a
+// resolver urgent on one query that timed out while its machine was loaded — a push applying, a build
+// starting twenty containers — and thirty asked right after were answered at once. So every question is
+// asked up to resolverTries times, a little apart, and all of them at once rather than one after
+// another; a resolver that answered none of a question's tries is held back (Confirm) and raised, urgent,
+// when the next run finds it not answering too. A resolver that *answered wrongly* — another address,
+// NXDOMAIN for IPv6, an IPv6 address — said so on every try that answered, and is raised at once: that is
+// an answer, not the absence of one.
+//
+// **Said in machine names** (ADR 0234 §6): the summary names the resolver's machine and the machine
+// asked about; the names with their domain, the resolver's address and the socket's words are the
+// evidence.
 func probeResolvers(ctx context.Context, d *doctor) ([]conditions.Observation, error) {
 	inv := d.open.inventory
 	shelf, err := inv.Catalogue(ctx)
@@ -158,46 +171,206 @@ func probeResolvers(ctx context.Context, d *doctor) ([]conditions.Observation, e
 	if err != nil {
 		return nil, err
 	}
-	suffix := overlay.Suffix()
-	var out []conditions.Observation
+	return askEveryResolver(ctx, resolvers, places, overlay.Suffix()), nil
+}
+
+// resolverQuestion is one question D2 asks one resolver, and what came of it.
+type resolverQuestion struct {
+	holder, at string
+	place      inventory.Overlay
+	kind       dnsmessage.Type
+	asked      resolverAsked
+}
+
+// askEveryResolver asks every resolver about every machine, every question at once, and says what each
+// resolver got wrong or did not answer.
+func askEveryResolver(ctx context.Context, resolvers map[string]string, places []inventory.Overlay,
+	suffix string) []conditions.Observation {
+	var questions []*resolverQuestion
 	for holder, at := range resolvers {
-		var wrong []string
 		for _, p := range places {
 			if p.Address == "" {
 				continue
 			}
-			name := p.Name + "." + suffix
-			v4, rcode, err := askResolver(ctx, at, name, dnsmessage.TypeA)
-			switch {
-			case err != nil:
-				wrong = append(wrong, fmt.Sprintf("%s for %s: %v", "A", name, err))
-				continue
-			case rcode != dnsmessage.RCodeSuccess:
-				wrong = append(wrong, fmt.Sprintf("%s answered %s for %s (A)", holder, rcode, name))
-			case !slices.Contains(v4, p.Address):
-				wrong = append(wrong, fmt.Sprintf("%s answered %v for %s (A), not %s", holder, v4, name, p.Address))
+			for _, kind := range []dnsmessage.Type{dnsmessage.TypeA, dnsmessage.TypeAAAA} {
+				questions = append(questions, &resolverQuestion{holder: holder, at: at, place: p, kind: kind})
 			}
-			v6, rcode, err := askResolver(ctx, at, name, dnsmessage.TypeAAAA)
-			switch {
-			case err != nil:
-				wrong = append(wrong, fmt.Sprintf("%s for %s: %v", "AAAA", name, err))
-			case rcode != dnsmessage.RCodeSuccess:
-				wrong = append(wrong, fmt.Sprintf("%s answered %s for %s (AAAA), not NODATA: a musl machine "+
-					"takes that as no such name", holder, rcode, name))
-			case len(v6) > 0:
-				wrong = append(wrong, fmt.Sprintf("%s answered %v for %s (AAAA); the mesh has no IPv6 addresses", holder, v6, name))
-			}
-		}
-		if len(wrong) > 0 {
-			node := strings.TrimSuffix(holder, "."+suffix)
-			out = append(out, conditions.Observation{Scope: conditions.ScopeSeat, ID: "mesh-dns-resolver." + node,
-				Token: "wrong", Machine: node, Severity: conditions.Urgent,
-				Summary: fmt.Sprintf("the mesh's resolver on %s does not answer machine names as it must: %s",
-					node, wrong[0]),
-				Said: strings.Join(wrong, "; ")})
 		}
 	}
-	return sortedFound(out), nil
+	var wg sync.WaitGroup
+	for _, q := range questions {
+		wg.Add(1)
+		go func(q *resolverQuestion) {
+			defer wg.Done()
+			name := q.place.Name + "." + suffix
+			q.asked = askResolverPatiently(ctx, q.at, name, q.kind, func(addresses []string, rcode dnsmessage.RCode) bool {
+				if q.kind == dnsmessage.TypeA {
+					return rcode == dnsmessage.RCodeSuccess && slices.Contains(addresses, q.place.Address)
+				}
+				return rcode == dnsmessage.RCodeSuccess && len(addresses) == 0
+			})
+		}(q)
+	}
+	wg.Wait()
+
+	type verdict struct {
+		wrong, unanswered, said []string
+		asked                   int
+	}
+	byHolder := map[string]*verdict{}
+	for _, q := range questions {
+		v := byHolder[q.holder]
+		if v == nil {
+			v = &verdict{}
+			byHolder[q.holder] = v
+		}
+		v.asked++
+		words, said := q.judged(suffix)
+		switch {
+		case said == "":
+		case q.asked.answered:
+			v.wrong = append(v.wrong, words)
+			v.said = append(v.said, said)
+		default:
+			v.unanswered = append(v.unanswered, words)
+			v.said = append(v.said, said)
+		}
+	}
+	var out []conditions.Observation
+	for holder, v := range byHolder {
+		if len(v.said) == 0 {
+			continue
+		}
+		sort.Strings(v.wrong)
+		sort.Strings(v.unanswered)
+		sort.Strings(v.said)
+		node := strings.TrimSuffix(holder, "."+suffix)
+		o := conditions.Observation{Scope: conditions.ScopeSeat, ID: "mesh-dns-resolver." + node,
+			Token: "wrong", Machine: node, Severity: conditions.Urgent, Said: strings.Join(v.said, "; ")}
+		if len(v.wrong) > 0 {
+			o.Summary = fmt.Sprintf("the mesh's resolver on %s does not answer machine names as it must: %s%s", node,
+				v.wrong[0], andMore(len(v.wrong)-1))
+		} else {
+			// Nothing but silence: held for the next run, which raises it if the resolver is still silent.
+			o.Confirm = true
+			o.Summary = fmt.Sprintf("the mesh's resolver on %s does not answer: %d of the %d question(s) about the "+
+				"machines' names went unanswered, each asked %d times — the first, %s", node, len(v.unanswered), v.asked,
+				resolverTries, v.unanswered[0])
+		}
+		out = append(out, o)
+	}
+	return sortedFound(out)
+}
+
+// andMore is ", and n more" for n other things; nothing for none.
+func andMore(n int) string {
+	if n <= 0 {
+		return ""
+	}
+	return fmt.Sprintf(", and %d more", n)
+}
+
+// family is a question's kind as the mesh says it.
+func family(kind dnsmessage.Type) string {
+	if kind == dnsmessage.TypeAAAA {
+		return "IPv6"
+	}
+	return "IPv4"
+}
+
+// rcodeWords is a resolver's answer code as a person reads it, with the name a resolver's log uses.
+func rcodeWords(rcode dnsmessage.RCode) string {
+	switch rcode {
+	case dnsmessage.RCodeNameError:
+		return "no such name (NXDOMAIN)"
+	case dnsmessage.RCodeServerFailure:
+		return "a failure (SERVFAIL)"
+	case dnsmessage.RCodeRefused:
+		return "a refusal (REFUSED)"
+	case dnsmessage.RCodeFormatError:
+		return "a format error (FORMERR)"
+	case dnsmessage.RCodeNotImplemented:
+		return "not implemented (NOTIMP)"
+	}
+	return strings.TrimPrefix(rcode.String(), "RCode")
+}
+
+// judged is a question's outcome: in words, naming machines only, for a summary; and in full — the
+// name with its domain, the addresses, the socket's words — for the evidence. Both empty when it was
+// answered as it must be.
+func (q *resolverQuestion) judged(suffix string) (words, said string) {
+	a, node, name := q.asked, q.place.Name, q.place.Name+"."+suffix
+	about := fmt.Sprintf("%s's %s address", node, family(q.kind))
+	switch {
+	case a.right:
+		return "", ""
+	case !a.answered:
+		return about, fmt.Sprintf("%s for %s: no answer from %s in %d tries: %s", q.kind, name, q.at, a.tries,
+			oneLine(errors.Join(a.errs...).Error()))
+	case a.rcode != dnsmessage.RCodeSuccess && q.kind == dnsmessage.TypeAAAA:
+		return fmt.Sprintf("it answered %s for %s, not NODATA: a musl machine takes that as no such name",
+				rcodeWords(a.rcode), about),
+			fmt.Sprintf("%s answered %s for %s (AAAA), not NODATA", q.at, a.rcode, name)
+	case a.rcode != dnsmessage.RCodeSuccess:
+		return fmt.Sprintf("it answered %s for %s", rcodeWords(a.rcode), about),
+			fmt.Sprintf("%s answered %s for %s (A)", q.at, a.rcode, name)
+	case q.kind == dnsmessage.TypeAAAA:
+		return fmt.Sprintf("it answered an IPv6 address for %s; the mesh has none", node),
+			fmt.Sprintf("%s answered %v for %s (AAAA); the mesh has no IPv6 addresses", q.at, a.addresses, name)
+	}
+	return fmt.Sprintf("it answered %s with another address than the mesh gave %s", about, node),
+		fmt.Sprintf("%s answered %v for %s (A), not %s", q.at, a.addresses, name, q.place.Address)
+}
+
+// How patiently D2 asks: each question up to resolverTries times, each try waiting resolverWithin for
+// its answer, the tries resolverPause apart and that pause doubled each time. Every question is asked at
+// once, so a resolver that answers nothing costs the run about seven seconds, within probeWithin.
+var (
+	resolverTries  = 3
+	resolverWithin = 2 * time.Second
+	resolverPause  = 250 * time.Millisecond
+)
+
+// resolverAsked is one question asked patiently: the answer that settled it, or every try's error.
+type resolverAsked struct {
+	// right says a try was answered as it must be; answered that some try was answered at all.
+	right, answered bool
+	addresses       []string
+	rcode           dnsmessage.RCode
+	tries           int
+	errs            []error
+}
+
+// askResolverPatiently asks one question until it is answered as right says, at most resolverTries
+// times. A wrong answer is asked again too — a resolver restarting may say NXDOMAIN for a moment — and
+// stands if no try answers rightly.
+func askResolverPatiently(ctx context.Context, at, name string, kind dnsmessage.Type,
+	right func([]string, dnsmessage.RCode) bool) resolverAsked {
+	var a resolverAsked
+	pause := resolverPause
+	for a.tries < resolverTries {
+		if a.tries > 0 {
+			select {
+			case <-ctx.Done():
+				a.errs = append(a.errs, ctx.Err())
+				return a
+			case <-time.After(pause):
+			}
+			pause *= 2
+		}
+		a.tries++
+		addresses, rcode, err := askResolver(ctx, at, name, kind)
+		if err != nil {
+			a.errs = append(a.errs, err)
+			continue
+		}
+		a.answered, a.addresses, a.rcode = true, addresses, rcode
+		if right(addresses, rcode) {
+			a.right = true
+			return a
+		}
+	}
+	return a
 }

 // resolverPort is where a resolver answers; a variable so a test can stand one up.
@@ -215,13 +388,13 @@ func askResolver(ctx context.Context, at, name string, kind dnsmessage.Type) ([]
 	if err != nil {
 		return nil, 0, err
 	}
-	dialer := net.Dialer{Timeout: 3 * time.Second}
+	dialer := net.Dialer{Timeout: resolverWithin}
 	conn, err := dialer.DialContext(ctx, "udp", net.JoinHostPort(at, resolverPort))
 	if err != nil {
 		return nil, 0, err
 	}
 	defer conn.Close()
-	_ = conn.SetDeadline(time.Now().Add(3 * time.Second))
+	_ = conn.SetDeadline(time.Now().Add(resolverWithin))
 	if _, err := conn.Write(packed); err != nil {
 		return nil, 0, err
 	}
@@ -308,6 +481,34 @@ func probeHolders(ctx context.Context, d *doctor) ([]conditions.Observation, err
 	if err != nil {
 		return nil, err
 	}
+	// **A holder whose answer to one discovery came late is asked again** (novox/hq issue 277): a
+	// runtime on a loaded machine answers last, and once past discoveryPatience. What a second discovery
+	// still does not hear is held for the next run (Confirm), and said when that run does not hear it
+	// either.
+	missing := func() bool {
+		for seat, nodes := range expected {
+			for node := range nodes {
+				if !answering[seat][node] {
+					return true
+				}
+			}
+		}
+		return false
+	}
+	if missing() {
+		again, err := discoverHolders(ctx, d.js.Conn())
+		if err != nil {
+			return nil, err
+		}
+		for seat, nodes := range again {
+			for node := range nodes {
+				if answering[seat] == nil {
+					answering[seat] = map[string]bool{}
+				}
+				answering[seat][node] = true
+			}
+		}
+	}
 	var out []conditions.Observation
 	for seat, nodes := range expected {
 		for node := range nodes {
@@ -315,7 +516,7 @@ func probeHolders(ctx context.Context, d *doctor) ([]conditions.Observation, err
 				continue
 			}
 			out = append(out, conditions.Observation{Scope: conditions.ScopeSeat, ID: seat + "." + node,
-				Token: "silent", Machine: node, Severity: conditions.Warning,
+				Token: "silent", Machine: node, Severity: conditions.Warning, Confirm: true,
 				Summary: fmt.Sprintf("%s's holder on %s does not answer the bus: its verbs reach nothing there", seat, node),
 				Said:    fmt.Sprintf("no answer for %s from %s to the bus's discovery", seat, node)})
 		}
@@ -529,8 +730,10 @@ func probeConsumers(ctx context.Context, d *doctor) ([]conditions.Observation, e
 		if c.Stream != "NODES" && info.NumPending > consumerFarBehind {
 			// Its own kind (novox/hq to-be 45 §7): healer H4 answers a consumer far behind, and only
 			// this — a redefined consumer is not one a reset repairs.
+			// One look at a consumer that a burst has put behind is not one that stays behind: held for
+			// the next run, so H4 resets nothing on a single sample (novox/hq issue 277).
 			out = append(out, conditions.Observation{Scope: conditions.ScopeBus, ID: who, Token: "behind",
-				Kind: kindConsumerBehind, Severity: conditions.Warning,
+				Kind: kindConsumerBehind, Severity: conditions.Warning, Confirm: true,
 				Summary: fmt.Sprintf("%s is %d message(s) behind its stream's head", consumerWords(c), info.NumPending),
 				Said:    fmt.Sprintf("%d pending, %d handed out and not settled", info.NumPending, info.NumAckPending)})
 		}
@@ -654,7 +857,9 @@ func probeBans(ctx context.Context, d *doctor) ([]conditions.Observation, error)
 	if err != nil {
 		return nil, err
 	}
-	owned := map[string]string{} // address → whose
+	// address → whose, in machine names: what the summary says. The address, and the endpoint's name
+	// it was found by, are the evidence (ADR 0234 §6).
+	owned, via := map[string]string{}, map[string]string{}
 	for _, p := range places {
 		if p.Address != "" {
 			owned[p.Address] = p.Name + "'s private address"
@@ -664,7 +869,7 @@ func probeBans(ctx context.Context, d *doctor) ([]conditions.Observation, error)
 				owned[ip.String()] = p.Name + "'s endpoint"
 			} else if addrs, err := net.DefaultResolver.LookupHost(ctx, host); err == nil {
 				for _, a := range addrs {
-					owned[a] = p.Name + "'s endpoint (" + host + ")"
+					owned[a], via[a] = p.Name+"'s endpoint", host
 				}
 			}
 		}
@@ -708,17 +913,26 @@ func probeBans(ctx context.Context, d *doctor) ([]conditions.Observation, error)
 			unasked = append(unasked, err.Error())
 			continue
 		}
-		var banned []string
+		var banned, whose []string
 		for _, ip := range ipLike.FindAllString(string(answer), -1) {
-			if whose, ours := owned[ip]; ours && !slices.Contains(banned, ip+" ("+whose+")") {
-				banned = append(banned, ip+" ("+whose+")")
+			who, ours := owned[ip]
+			said := ip + " (" + who + ")"
+			if h := via[ip]; h != "" {
+				said = ip + " (" + who + ", " + h + ")"
+			}
+			if !ours || slices.Contains(banned, said) {
+				continue
+			}
+			banned = append(banned, said)
+			if !slices.Contains(whose, who) {
+				whose = append(whose, who)
 			}
 		}
 		if len(banned) > 0 {
 			out = append(out, conditions.Observation{Scope: conditions.ScopeMachine, ID: node, Token: "bans-the-mesh",
 				Machine: node, Severity: conditions.Urgent,
-				Summary: fmt.Sprintf("%s's ban list holds %d of the mesh's own address(es): %s — the mesh is locked out "+
-					"of itself there (ADR 0186)", node, len(banned), strings.Join(banned, ", ")),
+				Summary: fmt.Sprintf("%s's ban list holds %d of the mesh's own address(es) — %s: the mesh is locked out "+
+					"of itself there (ADR 0186)", node, len(banned), strings.Join(whose, ", ")),
 				Said: strings.Join(banned, ", ")})
 		}
 	}
@@ -755,9 +969,12 @@ func probeStatus(ctx context.Context, d *doctor) ([]conditions.Observation, erro
 		if why == "" {
 			why = fmt.Sprintf("it took %s", took.Round(time.Millisecond))
 		}
+		// Timed once, on a controller that may be busy for a moment: held for the next run (novox/hq
+		// issue 277). Why it was slow is the evidence: a composition's failure carries a store's words.
 		out = append(out, conditions.Observation{Scope: conditions.ScopeCore, ID: "controller", Token: "status-slow",
-			Machine: d.host, Severity: conditions.Warning,
-			Summary: "status does not answer in full within ten seconds: " + why, Said: why})
+			Machine: d.host, Severity: conditions.Warning, Confirm: true,
+			Summary: "status does not answer in full within ten seconds, from a summary composed lately",
+			Said:    why})
 	}
 	return out, nil
 }
@@ -910,6 +1127,14 @@ func probeWatchdogs(_ context.Context, d *doctor) ([]conditions.Observation, err
 		Said: fmt.Sprintf("no tick for %s", time.Since(since).Round(time.Second))}}, nil
 }

+// How a probe asks a seat's holder: each try waits seatAskWithin, at most seatAskTries tries,
+// seatAskPause apart.
+var (
+	seatAskTries  = 2
+	seatAskWithin = 10 * time.Second
+	seatAskPause  = 500 * time.Millisecond
+)
+
 // askSeatTool asks one machine's holder of a node seat a verb and answers its result; the holder's
 // own refusal is an error.
 func askSeatTool(ctx context.Context, conn *nats.Conn, seat, verb, node string) (json.RawMessage, error) {
@@ -917,7 +1142,26 @@ func askSeatTool(ctx context.Context, conn *nats.Conn, seat, verb, node string)
 		return nil, fmt.Errorf("%s asks %s.%s, which it does not declare in the probe registry — and so the "+
 			"controller is not granted it", who, seat, verb)
 	}
-	answer, err := link.AskSeatTool(ctx, conn, seat, verb, node, map[string]any{}, 10*time.Second)
+	// **Asked again when the bus brought no answer** (novox/hq issue 277), while the probe's bound
+	// leaves room for a whole try: a holder on a loaded machine that misses one question is not a
+	// holder that cannot answer. The holder's own refusal is an answer, and is not asked again.
+	var answer link.Answer
+	var err error
+	for try := 0; try < seatAskTries; try++ {
+		if try > 0 {
+			if deadline, ok := ctx.Deadline(); ok && time.Until(deadline) < seatAskWithin+seatAskPause {
+				break
+			}
+			select {
+			case <-ctx.Done():
+				return nil, err
+			case <-time.After(seatAskPause):
+			}
+		}
+		if answer, err = link.AskSeatTool(ctx, conn, seat, verb, node, map[string]any{}, seatAskWithin); err == nil {
+			break
+		}
+	}
 	if err != nil {
 		return nil, err
 	}
@@ -944,8 +1188,8 @@ func probeLease(ctx context.Context, d *doctor) ([]conditions.Observation, error
 			Machine: d.host, Severity: conditions.Urgent, Summary: summary, Said: said})
 	}
 	if st.Unleased != "" {
-		split("unheld", "this controller acts without the lease, so nothing keeps another from acting beside it: "+
-			st.Unleased, st.Unleased)
+		split("unheld", "this controller acts without the lease, so nothing keeps another from acting beside it",
+			st.Unleased)
 		return out, nil
 	}
 	api, err := jetstream.New(d.js.Conn())