Skip to content

Commit cb66ba5

Browse files
committed
hostagent: unify requirement progress logging with (N/total) counter
Pre-compute the total number of requirement steps (essential + optional + guest-agent wait + final) and thread a shared counter through waitForRequirements so each progress line is prefixed with (N/total). Progress is emitted as a structured RequirementProgress event so the limactl-side event watcher can render it two ways: * TTY: each step occupies a single line that flips from 🕐 to ✅ in place when it completes. * Non-TTY (piped output, log files, CI): two regular log lines per step, matching the previous behaviour. Built-in requirement descriptions are reworded so they read naturally in the new form (e.g. systemd must be available -> systemd is available). capitalizeFirst is kept so user-supplied probe descriptions render uniformly with the built-in ones, and is rune-safe. Fix replaying of RequirementProgress events: the progress field was kept on currentStatus after emit, so every subsequent unrelated event (port-forward, vsock, cloud-init) carried the previous RequirementProgress along and the limactl-side renderer re-emitted the pending line for each one. Clear the transient field from the cached status inside emitEvent so only the event that explicitly carries it renders. Add a defensive dedup in renderRequirementProgress keyed on step/total:done so any future re-emit path cannot reintroduce the spam. Reword the built-in descriptions back to the to be form so the pending line reads as a goal, not a premature completion claim. Closes: #4553 Signed-off-by: mn-ram <235066282+mn-ram@users.noreply.github.com>
1 parent 943e2ef commit cb66ba5

4 files changed

Lines changed: 168 additions & 18 deletions

File tree

pkg/hostagent/events/events.go

Lines changed: 26 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,32 @@ type Status struct {
2626

2727
// Vsock forwarder event
2828
Vsock *VsockEvent `json:"vsock,omitempty"`
29+
30+
// Requirement progress update — one event per state transition, see
31+
// RequirementProgress for fields.
32+
RequirementProgress *RequirementProgress `json:"requirementProgress,omitempty"`
33+
}
34+
35+
// RequirementProgress is emitted by the hostagent on every state transition
36+
// of a startup-requirement check, so the limactl-side watcher can render
37+
// progress with a TTY-aware in-place flip (🕐 -> ✅) when stdout is a
38+
// terminal, and fall back to two log lines otherwise.
39+
type RequirementProgress struct {
40+
// Step is the 1-based index of this requirement across the unified
41+
// essential / optional / guest-agent / final groups.
42+
Step int `json:"step"`
43+
// Total is the total number of steps across all groups for this boot.
44+
Total int `json:"total"`
45+
// Description is the human-readable name of the requirement, already
46+
// capitalized for display.
47+
Description string `json:"description"`
48+
// Suffix is an optional trailing annotation shown only while the step
49+
// is pending (e.g. " (essential)").
50+
Suffix string `json:"suffix,omitempty"`
51+
// Done is true when the requirement has been satisfied. The first
52+
// event for each step is emitted with Done=false; the second with
53+
// Done=true.
54+
Done bool `json:"done,omitempty"`
2955
}
3056

3157
type CloudInitProgress struct {

pkg/hostagent/hostagent.go

Lines changed: 40 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -330,6 +330,11 @@ func (a *HostAgent) emitEvent(_ context.Context, ev events.Event) {
330330

331331
a.statusMu.Lock()
332332
a.currentStatus = ev.Status
333+
// RequirementProgress is a one-shot transition signal: it must not be
334+
// replayed on subsequent unrelated events (port forwards, vsock, etc.),
335+
// otherwise the limactl-side renderer would re-emit the pending "🕐 …"
336+
// line every time some other event fires while a check is in progress.
337+
a.currentStatus.RequirementProgress = nil
333338
a.statusMu.Unlock()
334339

335340
if ev.Time.IsZero() {
@@ -362,6 +367,17 @@ func (a *HostAgent) emitPortForwardEvent(ctx context.Context, pfEvent *events.Po
362367
a.emitEvent(ctx, ev)
363368
}
364369

370+
func (a *HostAgent) emitRequirementProgress(ctx context.Context, prog *events.RequirementProgress) {
371+
a.statusMu.RLock()
372+
currentStatus := a.currentStatus
373+
a.statusMu.RUnlock()
374+
375+
currentStatus.RequirementProgress = prog
376+
377+
ev := events.Event{Status: currentStatus}
378+
a.emitEvent(ctx, ev)
379+
}
380+
365381
func (a *HostAgent) emitVsockEvent(ctx context.Context, vsockEvent *events.VsockEvent) {
366382
a.statusMu.RLock()
367383
currentStatus := a.currentStatus
@@ -556,7 +572,16 @@ func (a *HostAgent) startHostAgentRoutines(ctx context.Context) error {
556572
return nil
557573
})
558574
var errs []error
559-
if err := a.waitForRequirements("essential", a.essentialRequirements()); err != nil {
575+
hasGuestAgentDaemon := !*a.instConfig.Plain && *a.instConfig.OS == limatype.LINUX
576+
essentialReqs := a.essentialRequirements()
577+
optionalReqs := a.optionalRequirements()
578+
finalReqs := a.finalRequirements()
579+
totalSteps := len(essentialReqs) + len(optionalReqs) + len(finalReqs)
580+
if hasGuestAgentDaemon {
581+
totalSteps++ // for the explicit "guest agent is running" wait
582+
}
583+
step := 0
584+
if err := a.waitForRequirements(ctx, "essential", essentialReqs, &step, totalSteps); err != nil {
560585
errs = append(errs, err)
561586
}
562587
if *a.instConfig.SSH.ForwardAgent {
@@ -608,7 +633,6 @@ sudo chown -R "${USER}" /run/host-services`
608633
staticPortForwards := a.separateStaticPortForwards()
609634
a.addStaticPortForwardsFromList(ctx, staticPortForwards)
610635

611-
hasGuestAgentDaemon := !*a.instConfig.Plain && *a.instConfig.OS == limatype.LINUX
612636
if hasGuestAgentDaemon {
613637
go a.watchGuestAgentEvents(ctx)
614638
go a.startTimeSync(ctx)
@@ -628,19 +652,29 @@ sudo chown -R "${USER}" /run/host-services`
628652
}()
629653
}
630654
}
631-
if err := a.waitForRequirements("optional", a.optionalRequirements()); err != nil {
655+
if err := a.waitForRequirements(ctx, "optional", optionalReqs, &step, totalSteps); err != nil {
632656
errs = append(errs, err)
633657
}
634658
if hasGuestAgentDaemon {
635-
logrus.Info("Waiting for the guest agent to be running")
659+
step++
660+
a.emitRequirementProgress(ctx, &events.RequirementProgress{
661+
Step: step,
662+
Total: totalSteps,
663+
Description: "Guest agent to be running",
664+
})
636665
select {
637666
case <-a.guestAgentAliveCh:
638-
// NOP
667+
a.emitRequirementProgress(ctx, &events.RequirementProgress{
668+
Step: step,
669+
Total: totalSteps,
670+
Description: "Guest agent to be running",
671+
Done: true,
672+
})
639673
case <-time.After(time.Minute):
640674
errs = append(errs, errors.New("guest agent does not seem to be running; port forwards will not work"))
641675
}
642676
}
643-
if err := a.waitForRequirements("final", a.finalRequirements()); err != nil {
677+
if err := a.waitForRequirements(ctx, "final", finalReqs, &step, totalSteps); err != nil {
644678
errs = append(errs, err)
645679
}
646680
// Copy all config files _after_ the requirements are done

pkg/hostagent/requirements.go

Lines changed: 51 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -4,42 +4,81 @@
44
package hostagent
55

66
import (
7+
"context"
78
"errors"
89
"fmt"
910
"runtime"
1011
"strings"
1112
"time"
13+
"unicode"
14+
"unicode/utf8"
1215

1316
"github.com/lima-vm/sshocker/pkg/ssh"
1417
"github.com/sirupsen/logrus"
1518

19+
"github.com/lima-vm/lima/v2/pkg/hostagent/events"
1620
"github.com/lima-vm/lima/v2/pkg/limatype"
1721
"github.com/lima-vm/lima/v2/pkg/sshutil"
1822
)
1923

20-
func (a *HostAgent) waitForRequirements(label string, requirements []requirement) error {
24+
// capitalizeFirst returns s with its first letter upper-cased, using rune
25+
// semantics so non-ASCII inputs are handled correctly.
26+
func capitalizeFirst(s string) string {
27+
if s == "" {
28+
return s
29+
}
30+
r, size := utf8.DecodeRuneInString(s)
31+
return string(unicode.ToUpper(r)) + s[size:]
32+
}
33+
34+
// waitForRequirements iterates through requirements, advancing *step (a unified
35+
// counter shared across the essential / optional / final groups, plus the
36+
// guest-agent step) and emits a RequirementProgress event for each state
37+
// transition. The limactl-side event watcher renders these as either an
38+
// in-place 🕐 -> ✅ flip (when stdout is a TTY) or two log lines (otherwise).
39+
func (a *HostAgent) waitForRequirements(ctx context.Context, label string, requirements []requirement, step *int, total int) error {
2140
const (
2241
retries = 200
2342
sleepDuration = 3 * time.Second
2443
)
2544
var errs []error
2645

27-
for i, req := range requirements {
28-
logrus.Infof("Waiting for the %s requirement %d of %d: %q", label, i+1, len(requirements), req.description)
46+
for _, req := range requirements {
47+
*step++
48+
stepNum := *step
49+
suffix := ""
50+
if label == "essential" {
51+
suffix = " (essential)"
52+
}
53+
// capitalizeFirst is applied so user-supplied probe descriptions render
54+
// uniformly with the built-in ones; built-in descriptions are already in
55+
// sentence case so it is a no-op for them.
56+
desc := capitalizeFirst(req.description)
57+
a.emitRequirementProgress(ctx, &events.RequirementProgress{
58+
Step: stepNum,
59+
Total: total,
60+
Description: desc,
61+
Suffix: suffix,
62+
})
2963
retryLoop:
3064
for j := range retries {
3165
err := a.waitForRequirement(req)
3266
if err == nil {
33-
logrus.Infof("The %s requirement %d of %d is satisfied", label, i+1, len(requirements))
67+
a.emitRequirementProgress(ctx, &events.RequirementProgress{
68+
Step: stepNum,
69+
Total: total,
70+
Description: desc,
71+
Done: true,
72+
})
3473
break retryLoop
3574
}
3675
if req.fatal {
3776
logrus.Infof("No further %s requirements will be checked", label)
38-
errs = append(errs, fmt.Errorf("failed to satisfy the %s requirement %d of %d %q: %s; skipping further checks: %w", label, i+1, len(requirements), req.description, req.debugHint, err))
77+
errs = append(errs, fmt.Errorf("failed to satisfy the %s requirement (%d/%d) %q: %s; skipping further checks: %w", label, stepNum, total, req.description, req.debugHint, err))
3978
return errors.Join(errs...)
4079
}
4180
if j == retries-1 {
42-
errs = append(errs, fmt.Errorf("failed to satisfy the %s requirement %d of %d %q: %s: %w", label, i+1, len(requirements), req.description, req.debugHint, err))
81+
errs = append(errs, fmt.Errorf("failed to satisfy the %s requirement (%d/%d) %q: %s: %w", label, stepNum, total, req.description, req.debugHint, err))
4382
break retryLoop
4483
}
4584
time.Sleep(sleepDuration)
@@ -159,7 +198,7 @@ func (a *HostAgent) essentialRequirements() []requirement {
159198
req := make([]requirement, 0)
160199
req = append(req,
161200
requirement{
162-
description: "ssh",
201+
description: "SSH connection",
163202
script: `#!/bin/sh
164203
true
165204
`,
@@ -170,7 +209,7 @@ If any private key under ~/.ssh is protected with a passphrase, you need to have
170209
noMaster: true,
171210
})
172211
startControlMasterReq := requirement{
173-
description: "Explicitly start ssh ControlMaster",
212+
description: "Persistent SSH ControlMaster",
174213
script: `#!/bin/sh
175214
true
176215
`,
@@ -182,7 +221,7 @@ true
182221
}
183222
req = append(req,
184223
requirement{
185-
description: "user session is ready for ssh",
224+
description: "user session to be ready for SSH",
186225
script: fmt.Sprintf(`#!/bin/sh
187226
set -eux
188227
[ "$(cat /run/lima-ssh-ready 2>/dev/null)" = "%s" ]
@@ -209,7 +248,7 @@ A possible workaround is to run "apt-get install sshfs" in the guest.
209248
`,
210249
})
211250
req = append(req, requirement{
212-
description: "fuse to \"allow_other\" as user",
251+
description: "fuse \"allow_other\" to be enabled for the user",
213252
script: `#!/bin/sh
214253
set -eux
215254
sudo grep -q ^user_allow_other /etc/fuse*.conf
@@ -228,7 +267,7 @@ func (a *HostAgent) optionalRequirements() []requirement {
228267
if isLinuxGuest && (*a.instConfig.Containerd.System || *a.instConfig.Containerd.User) && !*a.instConfig.Plain {
229268
req = append(req,
230269
requirement{
231-
description: "systemd must be available",
270+
description: "systemd to be available",
232271
fatal: true,
233272
script: `#!/bin/bash
234273
set -eux -o pipefail
@@ -275,7 +314,7 @@ func (a *HostAgent) finalRequirements() []requirement {
275314
}
276315
req = append(req,
277316
requirement{
278-
description: "boot scripts must have finished",
317+
description: "boot scripts to be finished",
279318
script: fmt.Sprintf(`#!/bin/sh
280319
set -eux
281320
BOOT_DONE=/run/lima-boot-done

pkg/instance/start.go

Lines changed: 51 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ import (
1717

1818
"github.com/docker/go-units"
1919
"github.com/lima-vm/go-qcow2reader"
20+
"github.com/mattn/go-isatty"
2021
"github.com/sirupsen/logrus"
2122

2223
"github.com/lima-vm/lima/v2/pkg/autostart"
@@ -312,7 +313,20 @@ func watchHostAgentEvents(ctx context.Context, inst *limatype.Instance, haStdout
312313
err error
313314
)
314315

316+
// progressTTY is true when stderr is a real terminal, so we can render
317+
// requirement progress with an in-place 🕐 -> ✅ flip; otherwise we
318+
// fall back to two log lines per step.
319+
progressTTY := isatty.IsTerminal(os.Stderr.Fd()) || isatty.IsCygwinTerminal(os.Stderr.Fd())
320+
// lastProgressKey is the "step/total:done" of the most recently
321+
// rendered RequirementProgress, used to suppress duplicate renders
322+
// when the same event is observed more than once.
323+
var lastProgressKey string
324+
315325
onEvent := func(ev hostagentevents.Event) bool {
326+
if p := ev.Status.RequirementProgress; p != nil {
327+
renderRequirementProgress(p, progressTTY, &lastProgressKey)
328+
return false
329+
}
316330
if !printedSSHLocalPort && ev.Status.SSHLocalPort != 0 {
317331
logrus.Infof("SSH Local Port: %d", ev.Status.SSHLocalPort)
318332
printedSSHLocalPort = true
@@ -388,6 +402,43 @@ func watchHostAgentEvents(ctx context.Context, inst *limatype.Instance, haStdout
388402
return nil
389403
}
390404

405+
// renderRequirementProgress prints a RequirementProgress event. On a TTY it
406+
// keeps the pending "🕐" line on the current row and overwrites it in place
407+
// with "✅" when the step completes, so each step occupies a single line that
408+
// flips from waiting to satisfied. On a non-TTY (piped output, log file)
409+
// each transition becomes a regular log line via logrus.
410+
//
411+
// `pending` carries the text of the currently-displayed pending line across
412+
// calls so the completion event can clear it with `\r` + clear-EOL.
413+
func renderRequirementProgress(p *hostagentevents.RequirementProgress, tty bool, pending *string) {
414+
// Dedup identical consecutive renders. The hostagent should only emit
415+
// one event per state transition, but if the same RequirementProgress
416+
// gets replayed (e.g. carried along on an unrelated status event) we
417+
// must not redraw, otherwise the pending line would be reprinted on
418+
// every unrelated event and either spam the log (non-TTY) or fight
419+
// with interleaved logrus output (TTY).
420+
key := fmt.Sprintf("%d/%d:%t", p.Step, p.Total, p.Done)
421+
if key == *pending {
422+
return
423+
}
424+
*pending = key
425+
426+
if !tty {
427+
if p.Done {
428+
logrus.Infof("(%2d/%d) ✅ %s", p.Step, p.Total, p.Description)
429+
} else {
430+
logrus.Infof("(%2d/%d) 🕐 %s%s", p.Step, p.Total, p.Description, p.Suffix)
431+
}
432+
return
433+
}
434+
const clearEOL = "\033[K"
435+
if p.Done {
436+
fmt.Fprintf(os.Stderr, "\r%s(%2d/%d) ✅ %s\n", clearEOL, p.Step, p.Total, p.Description)
437+
return
438+
}
439+
fmt.Fprintf(os.Stderr, "\r%s(%2d/%d) 🕐 %s%s", clearEOL, p.Step, p.Total, p.Description, p.Suffix)
440+
}
441+
391442
type watchHostAgentEventsTimeoutKey = struct{}
392443

393444
// WithWatchHostAgentTimeout sets the value of the timeout to use for

0 commit comments

Comments
 (0)