thaloco/banger
1
Fork 0
Code Pull requests Releases Packages Activity Actions

cli: log elapsed time after vm create reaches ready

Browse source 
Print '[vm create] ready in <elapsed>' to stderr once the create
operation completes successfully. Surfaces how long the full
create-to-ready cycle took (image resolve + work disk + boot +
guest agents + capability post-start), which the per-stage
progress lines don't add up to in any visible way.

Format adapts to scale: sub-second prints as 'NNNms', sub-minute
keeps one decimal ('4.7s'), longer prints as 'MmSSs'. Always
emitted (not gated on TTY) so logged and CI output carry the
number too.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
Thales Maciel 2026-04-26 21:17:47 -03:00
parent a3a51e06c4
commit 679cf87cfd
No known key found for this signature in database
GPG key ID: 33112E6833C34679
2 changed files with 41 additions and 1 deletions
Download patch file Download diff file Expand all files Collapse all files

24
internal/cli/cli_test.go
View file

@ -584,7 +584,8 @@ func TestRunVMCreatePollsUntilDone(t *testing.T) {
return nil
}
got, err := d.runVMCreate(context.Background(), "/tmp/bangerd.sock", &bytes.Buffer{}, api.VMCreateParams{Name: "devbox"})
var stderr bytes.Buffer
got, err := d.runVMCreate(context.Background(), "/tmp/bangerd.sock", &stderr, api.VMCreateParams{Name: "devbox"})
if err != nil {
t.Fatalf("d.runVMCreate: %v", err)
}
@ -594,6 +595,27 @@ func TestRunVMCreatePollsUntilDone(t *testing.T) {
if statusCalls != 2 {
t.Fatalf("statusCalls = %d, want 2", statusCalls)
}
if !strings.Contains(stderr.String(), "[vm create] ready in ") {
t.Fatalf("stderr missing elapsed line:\n%s", stderr.String())
}
}
func TestFormatVMCreateElapsed(t *testing.T) {
cases := []struct {
in time.Duration
want string
}{
{350 * time.Millisecond, "350ms"},
{4*time.Second + 700*time.Millisecond, "4.7s"},
{59*time.Second + 900*time.Millisecond, "59.9s"},
{62 * time.Second, "1m02s"},
{2*time.Minute + 5*time.Second, "2m05s"},
}
for _, tc := range cases {
if got := formatVMCreateElapsed(tc.in); got != tc.want {
t.Errorf("formatVMCreateElapsed(%s) = %q, want %q", tc.in, got, tc.want)
}
}
}
func TestVMCreateProgressRendererSuppressesDuplicateLines(t *testing.T) {

18
internal/cli/vm_create.go
View file

@ -61,6 +61,7 @@ func printVMSpecLine(out io.Writer, params api.VMCreateParams) {
// On context cancel we cooperate with the daemon to cancel the
// in-flight op so it doesn't leak partially-created VM state.
func (d *deps) runVMCreate(ctx context.Context, socketPath string, stderr io.Writer, params api.VMCreateParams) (model.VMRecord, error) {
start := time.Now()
printVMSpecLine(stderr, params)
begin, err := d.vmCreateBegin(ctx, socketPath, params)
if err != nil {
@ -74,6 +75,7 @@ func (d *deps) runVMCreate(ctx context.Context, socketPath string, stderr io.Wri
if op.Done {
renderer.render(op)
if op.Success && op.VM != nil {
_, _ = fmt.Fprintf(stderr, "[vm create] ready in %s\n", formatVMCreateElapsed(time.Since(start)))
return *op.VM, nil
}
if strings.TrimSpace(op.Error) == "" {
@ -231,6 +233,22 @@ func vmCreateStageLabel(stage string) string {
}
}
// formatVMCreateElapsed renders a wall-clock duration as a friendly
// "ready in 4.7s" / "ready in 1m02s" string. Sub-second durations
// keep one decimal so quick smoke runs don't print "0s".
func formatVMCreateElapsed(d time.Duration) string {
if d < time.Second {
return fmt.Sprintf("%dms", d.Milliseconds())
}
if d < time.Minute {
return fmt.Sprintf("%.1fs", d.Seconds())
}
d = d.Round(time.Second)
minutes := int(d / time.Minute)
seconds := int((d % time.Minute) / time.Second)
return fmt.Sprintf("%dm%02ds", minutes, seconds)
}
func validatePositiveSetting(label string, value int) error {
if value <= 0 {
return fmt.Errorf("%s must be a positive integer", label)