test(daemon): cover bar failure signature changes and recovery
Extend TestBarScriptFailureLogsOnceUntilSignatureChanges to exercise the full shouldLogBarFailure/clearBarFailure contract, not just the repeated- identical-failure case: a different failure logs again, and a successful run clears the recorded signature so a later identical failure logs again. Also fix logBarScriptFailure reading sess.name without holding sess.mu (mutable via session rename); it now takes the session name from base.Session, which collectBarScriptContext already captured under lock.
- commit
- c9a1da5d36752e56e9c28867831ea4e026ea678b
- author
- brice · · 2026-07-20 08:15 UTC
- parent
- cbdd525
- signature
- GPG Verified
CD88F9E564E0102646FB6077A1A07C7C7C3E349D· arch-gpg Verified for the committer email
2 files · +55 -14
M internal/usecase/daemon/bar_refresh.go +6 -3
| @@ -332,21 +332,24 @@ func (d *Daemon) runOneBarScript(ctx context.Context, runner barScriptExecutor, | |||
| 332 | 332 | base.Anchor = anchor | |
| 333 | 333 | out, err := runner.run(ctx, command, env, base) | |
| 334 | 334 | if err != nil { | |
| 335 | - | d.logBarScriptFailure(sess, anchor, command, env, err) | |
| 335 | + | d.logBarScriptFailure(sess, base.Session, anchor, command, env, err) | |
| 336 | 336 | return "", false | |
| 337 | 337 | } | |
| 338 | 338 | d.clearBarFailure(sess.id, anchor) | |
| 339 | 339 | return out, true | |
| 340 | 340 | } | |
| 341 | 341 | ||
| 342 | - | func (d *Daemon) logBarScriptFailure(sess *session, anchor, command string, env []string, err error) { | |
| 342 | + | // logBarScriptFailure logs a bar script failure. sessionName must come from a | |
| 343 | + | // synchronized read of sess.name (e.g. base.Session, captured under sess.mu | |
| 344 | + | // in collectBarScriptContext) since sess.name is mutable via session rename. | |
| 345 | + | func (d *Daemon) logBarScriptFailure(sess *session, sessionName, anchor, command string, env []string, err error) { | |
| 343 | 346 | if d.log == nil { | |
| 344 | 347 | return | |
| 345 | 348 | } | |
| 346 | 349 | if !d.shouldLogBarFailure(sess.id, anchor, err.Error()) { | |
| 347 | 350 | return | |
| 348 | 351 | } | |
| 349 | - | attrs := []any{"anchor", anchor, "session", sess.name, "command", command, "err", err} | |
| 352 | + | attrs := []any{"anchor", anchor, "session", sessionName, "command", command, "err", err} | |
| 350 | 353 | var scriptErr *barScriptError | |
| 351 | 354 | if errors.As(err, &scriptErr) { | |
| 352 | 355 | attrs = append(attrs, "exit_code", scriptErr.exitCode) | |
| @@ -332,21 +332,24 @@ func (d *Daemon) runOneBarScript(ctx context.Context, runner barScriptExecutor, | |||||
| 332 | base.Anchor = anchor | 332 | base.Anchor = anchor | ||
| 333 | out, err := runner.run(ctx, command, env, base) | 333 | out, err := runner.run(ctx, command, env, base) | ||
| 334 | if err != nil { | 334 | if err != nil { | ||
| 335 | - | d.logBarScriptFailure(sess, anchor, command, env, err) | 335 | + | d.logBarScriptFailure(sess, base.Session, anchor, command, env, err) |
| 336 | return "", false | 336 | return "", false | ||
| 337 | } | 337 | } | ||
| 338 | d.clearBarFailure(sess.id, anchor) | 338 | d.clearBarFailure(sess.id, anchor) | ||
| 339 | return out, true | 339 | return out, true | ||
| 340 | } | 340 | } | ||
| 341 | 341 | ||||
| 342 | - | func (d *Daemon) logBarScriptFailure(sess *session, anchor, command string, env []string, err error) { | 342 | + | // logBarScriptFailure logs a bar script failure. sessionName must come from a |
| 343 | + | // synchronized read of sess.name (e.g. base.Session, captured under sess.mu | |||
| 344 | + | // in collectBarScriptContext) since sess.name is mutable via session rename. | |||
| 345 | + | func (d *Daemon) logBarScriptFailure(sess *session, sessionName, anchor, command string, env []string, err error) { | |||
| 343 | if d.log == nil { | 346 | if d.log == nil { | ||
| 344 | return | 347 | return | ||
| 345 | } | 348 | } | ||
| 346 | if !d.shouldLogBarFailure(sess.id, anchor, err.Error()) { | 349 | if !d.shouldLogBarFailure(sess.id, anchor, err.Error()) { | ||
| 347 | return | 350 | return | ||
| 348 | } | 351 | } | ||
| 349 | - | attrs := []any{"anchor", anchor, "session", sess.name, "command", command, "err", err} | 352 | + | attrs := []any{"anchor", anchor, "session", sessionName, "command", command, "err", err} |
| 350 | var scriptErr *barScriptError | 353 | var scriptErr *barScriptError | ||
| 351 | if errors.As(err, &scriptErr) { | 354 | if errors.As(err, &scriptErr) { | ||
| 352 | attrs = append(attrs, "exit_code", scriptErr.exitCode) | 355 | attrs = append(attrs, "exit_code", scriptErr.exitCode) | ||
M internal/usecase/daemon/bar_refresh_test.go +49 -11
| @@ -272,16 +272,33 @@ func TestBarScriptRunConsumesPendingAfterRunningClears(t *testing.T) { | |||
| 272 | 272 | }, time.Second, time.Millisecond) | |
| 273 | 273 | } | |
| 274 | 274 | ||
| 275 | + | // TestBarScriptFailureLogsOnceUntilSignatureChanges covers the full | |
| 276 | + | // shouldLogBarFailure/clearBarFailure contract for a single anchor | |
| 277 | + | // (top-right; bottom-right always succeeds in this test so it never | |
| 278 | + | // contributes a log line): | |
| 279 | + | // | |
| 280 | + | // 1. an identical repeated failure does not log a second time, | |
| 281 | + | // 2. a different failure for the same session+anchor logs again, and | |
| 282 | + | // 3. a successful run clears the recorded signature, so a subsequent | |
| 283 | + | // identical failure logs again afterward. | |
| 284 | + | // | |
| 285 | + | // Each refresh consumes two fakeBarRunner call-count entries (top-right then | |
| 286 | + | // bottom-right), so the stages are order-dependent and asserted sequentially | |
| 287 | + | // rather than table-driven. | |
| 275 | 288 | func TestBarScriptFailureLogsOnceUntilSignatureChanges(t *testing.T) { | |
| 276 | 289 | var buf bytes.Buffer | |
| 277 | 290 | var mu sync.Mutex | |
| 278 | 291 | logger := slog.New(slog.NewTextHandler(&syncWriter{w: &buf, mu: &mu}, nil)) | |
| 279 | 292 | ||
| 293 | + | notFound := &barScriptError{exitCode: 127, stderr: "sh: vev-bar-top-right: not found", err: errors.New("exit status 127")} | |
| 294 | + | permissionDenied := &barScriptError{exitCode: 126, stderr: "sh: vev-bar-top-right: permission denied", err: errors.New("exit status 126")} | |
| 295 | + | ||
| 280 | 296 | r := &fakeBarRunner{errs: []error{ | |
| 281 | - | &barScriptError{exitCode: 127, stderr: "sh: vev-bar-top-right: not found", err: errors.New("exit status 127")}, | |
| 282 | - | &barScriptError{exitCode: 127, stderr: "sh: vev-bar-bottom-right: not found", err: errors.New("exit status 127")}, | |
| 283 | - | &barScriptError{exitCode: 127, stderr: "sh: vev-bar-top-right: not found", err: errors.New("exit status 127")}, | |
| 284 | - | &barScriptError{exitCode: 127, stderr: "sh: vev-bar-bottom-right: not found", err: errors.New("exit status 127")}, | |
| 297 | + | notFound, nil, // refresh 1: top fails | |
| 298 | + | notFound, nil, // refresh 2: top fails identically -> must not log again | |
| 299 | + | permissionDenied, nil, // refresh 3: top fails differently -> must log again | |
| 300 | + | nil, nil, // refresh 4: top succeeds -> clears recorded signature | |
| 301 | + | notFound, nil, // refresh 5: top fails with the original signature -> must log (cleared) | |
| 285 | 302 | }} | |
| 286 | 303 | d := newBarRefreshTestDaemon(r, time.Second) | |
| 287 | 304 | d.log = logger | |
| @@ -289,19 +306,40 @@ func TestBarScriptFailureLogsOnceUntilSignatureChanges(t *testing.T) { | |||
| 289 | 306 | sess := newBarRefreshTestSession() | |
| 290 | 307 | sess.client = &attachedClient{size: domain.Size{Cols: 80, Rows: 24}} | |
| 291 | 308 | ||
| 309 | + | readBuf := func() string { | |
| 310 | + | mu.Lock() | |
| 311 | + | defer mu.Unlock() | |
| 312 | + | return buf.String() | |
| 313 | + | } | |
| 314 | + | ||
| 292 | 315 | require.True(t, d.refreshBarScriptsIfDue(sess, time.Unix(0, 0), true)) | |
| 293 | 316 | waitBarRefreshIdle(t, d) | |
| 317 | + | out := readBuf() | |
| 318 | + | require.Equal(t, 1, strings.Count(out, "anchor=top-right"), "first failure should log") | |
| 319 | + | require.Contains(t, out, "not found") | |
| 320 | + | require.Contains(t, out, "PATH=/usr/bin") | |
| 321 | + | ||
| 294 | 322 | require.True(t, d.refreshBarScriptsIfDue(sess, time.Unix(10, 0), true)) | |
| 295 | 323 | waitBarRefreshIdle(t, d) | |
| 324 | + | out = readBuf() | |
| 325 | + | require.Equal(t, 1, strings.Count(out, "anchor=top-right"), "identical repeated failure should not log again") | |
| 296 | 326 | ||
| 297 | - | mu.Lock() | |
| 298 | - | out := buf.String() | |
| 299 | - | mu.Unlock() | |
| 327 | + | require.True(t, d.refreshBarScriptsIfDue(sess, time.Unix(20, 0), true)) | |
| 328 | + | waitBarRefreshIdle(t, d) | |
| 329 | + | out = readBuf() | |
| 330 | + | require.Equal(t, 2, strings.Count(out, "anchor=top-right"), "a different failure for the same anchor should log again") | |
| 331 | + | require.Contains(t, out, "permission denied") | |
| 300 | 332 | ||
| 301 | - | require.Equal(t, 1, strings.Count(out, "anchor=top-right"), | |
| 302 | - | "identical repeated failure should log once") | |
| 303 | - | require.Contains(t, out, "PATH=/usr/bin") | |
| 304 | - | require.Contains(t, out, "not found") | |
| 333 | + | require.True(t, d.refreshBarScriptsIfDue(sess, time.Unix(30, 0), true)) | |
| 334 | + | waitBarRefreshIdle(t, d) | |
| 335 | + | out = readBuf() | |
| 336 | + | require.Equal(t, 2, strings.Count(out, "anchor=top-right"), "a successful run must not log and must clear the recorded signature") | |
| 337 | + | ||
| 338 | + | require.True(t, d.refreshBarScriptsIfDue(sess, time.Unix(40, 0), true)) | |
| 339 | + | waitBarRefreshIdle(t, d) | |
| 340 | + | out = readBuf() | |
| 341 | + | require.Equal(t, 3, strings.Count(out, "anchor=top-right"), | |
| 342 | + | "an identical failure after a successful run should log again since the recorded signature was cleared") | |
| 305 | 343 | } | |
| 306 | 344 | ||
| 307 | 345 | type syncWriter struct { | |
| @@ -272,16 +272,33 @@ func TestBarScriptRunConsumesPendingAfterRunningClears(t *testing.T) { | |||||
| 272 | }, time.Second, time.Millisecond) | 272 | }, time.Second, time.Millisecond) | ||
| 273 | } | 273 | } | ||
| 274 | 274 | ||||
| 275 | + | // TestBarScriptFailureLogsOnceUntilSignatureChanges covers the full | |||
| 276 | + | // shouldLogBarFailure/clearBarFailure contract for a single anchor | |||
| 277 | + | // (top-right; bottom-right always succeeds in this test so it never | |||
| 278 | + | // contributes a log line): | |||
| 279 | + | // | |||
| 280 | + | // 1. an identical repeated failure does not log a second time, | |||
| 281 | + | // 2. a different failure for the same session+anchor logs again, and | |||
| 282 | + | // 3. a successful run clears the recorded signature, so a subsequent | |||
| 283 | + | // identical failure logs again afterward. | |||
| 284 | + | // | |||
| 285 | + | // Each refresh consumes two fakeBarRunner call-count entries (top-right then | |||
| 286 | + | // bottom-right), so the stages are order-dependent and asserted sequentially | |||
| 287 | + | // rather than table-driven. | |||
| 275 | func TestBarScriptFailureLogsOnceUntilSignatureChanges(t *testing.T) { | 288 | func TestBarScriptFailureLogsOnceUntilSignatureChanges(t *testing.T) { | ||
| 276 | var buf bytes.Buffer | 289 | var buf bytes.Buffer | ||
| 277 | var mu sync.Mutex | 290 | var mu sync.Mutex | ||
| 278 | logger := slog.New(slog.NewTextHandler(&syncWriter{w: &buf, mu: &mu}, nil)) | 291 | logger := slog.New(slog.NewTextHandler(&syncWriter{w: &buf, mu: &mu}, nil)) | ||
| 279 | 292 | ||||
| 293 | + | notFound := &barScriptError{exitCode: 127, stderr: "sh: vev-bar-top-right: not found", err: errors.New("exit status 127")} | |||
| 294 | + | permissionDenied := &barScriptError{exitCode: 126, stderr: "sh: vev-bar-top-right: permission denied", err: errors.New("exit status 126")} | |||
| 295 | + | ||||
| 280 | r := &fakeBarRunner{errs: []error{ | 296 | r := &fakeBarRunner{errs: []error{ | ||
| 281 | - | &barScriptError{exitCode: 127, stderr: "sh: vev-bar-top-right: not found", err: errors.New("exit status 127")}, | 297 | + | notFound, nil, // refresh 1: top fails |
| 282 | - | &barScriptError{exitCode: 127, stderr: "sh: vev-bar-bottom-right: not found", err: errors.New("exit status 127")}, | 298 | + | notFound, nil, // refresh 2: top fails identically -> must not log again |
| 283 | - | &barScriptError{exitCode: 127, stderr: "sh: vev-bar-top-right: not found", err: errors.New("exit status 127")}, | 299 | + | permissionDenied, nil, // refresh 3: top fails differently -> must log again |
| 284 | - | &barScriptError{exitCode: 127, stderr: "sh: vev-bar-bottom-right: not found", err: errors.New("exit status 127")}, | 300 | + | nil, nil, // refresh 4: top succeeds -> clears recorded signature |
| 301 | + | notFound, nil, // refresh 5: top fails with the original signature -> must log (cleared) | |||
| 285 | }} | 302 | }} | ||
| 286 | d := newBarRefreshTestDaemon(r, time.Second) | 303 | d := newBarRefreshTestDaemon(r, time.Second) | ||
| 287 | d.log = logger | 304 | d.log = logger | ||
| @@ -289,19 +306,40 @@ func TestBarScriptFailureLogsOnceUntilSignatureChanges(t *testing.T) { | |||||
| 289 | sess := newBarRefreshTestSession() | 306 | sess := newBarRefreshTestSession() | ||
| 290 | sess.client = &attachedClient{size: domain.Size{Cols: 80, Rows: 24}} | 307 | sess.client = &attachedClient{size: domain.Size{Cols: 80, Rows: 24}} | ||
| 291 | 308 | ||||
| 309 | + | readBuf := func() string { | |||
| 310 | + | mu.Lock() | |||
| 311 | + | defer mu.Unlock() | |||
| 312 | + | return buf.String() | |||
| 313 | + | } | |||
| 314 | + | ||||
| 292 | require.True(t, d.refreshBarScriptsIfDue(sess, time.Unix(0, 0), true)) | 315 | require.True(t, d.refreshBarScriptsIfDue(sess, time.Unix(0, 0), true)) | ||
| 293 | waitBarRefreshIdle(t, d) | 316 | waitBarRefreshIdle(t, d) | ||
| 317 | + | out := readBuf() | |||
| 318 | + | require.Equal(t, 1, strings.Count(out, "anchor=top-right"), "first failure should log") | |||
| 319 | + | require.Contains(t, out, "not found") | |||
| 320 | + | require.Contains(t, out, "PATH=/usr/bin") | |||
| 321 | + | ||||
| 294 | require.True(t, d.refreshBarScriptsIfDue(sess, time.Unix(10, 0), true)) | 322 | require.True(t, d.refreshBarScriptsIfDue(sess, time.Unix(10, 0), true)) | ||
| 295 | waitBarRefreshIdle(t, d) | 323 | waitBarRefreshIdle(t, d) | ||
| 324 | + | out = readBuf() | |||
| 325 | + | require.Equal(t, 1, strings.Count(out, "anchor=top-right"), "identical repeated failure should not log again") | |||
| 296 | 326 | ||||
| 297 | - | mu.Lock() | 327 | + | require.True(t, d.refreshBarScriptsIfDue(sess, time.Unix(20, 0), true)) |
| 298 | - | out := buf.String() | 328 | + | waitBarRefreshIdle(t, d) |
| 299 | - | mu.Unlock() | 329 | + | out = readBuf() |
| 330 | + | require.Equal(t, 2, strings.Count(out, "anchor=top-right"), "a different failure for the same anchor should log again") | |||
| 331 | + | require.Contains(t, out, "permission denied") | |||
| 300 | 332 | ||||
| 301 | - | require.Equal(t, 1, strings.Count(out, "anchor=top-right"), | 333 | + | require.True(t, d.refreshBarScriptsIfDue(sess, time.Unix(30, 0), true)) |
| 302 | - | "identical repeated failure should log once") | 334 | + | waitBarRefreshIdle(t, d) |
| 303 | - | require.Contains(t, out, "PATH=/usr/bin") | 335 | + | out = readBuf() |
| 304 | - | require.Contains(t, out, "not found") | 336 | + | require.Equal(t, 2, strings.Count(out, "anchor=top-right"), "a successful run must not log and must clear the recorded signature") |
| 337 | + | ||||
| 338 | + | require.True(t, d.refreshBarScriptsIfDue(sess, time.Unix(40, 0), true)) | |||
| 339 | + | waitBarRefreshIdle(t, d) | |||
| 340 | + | out = readBuf() | |||
| 341 | + | require.Equal(t, 3, strings.Count(out, "anchor=top-right"), | |||
| 342 | + | "an identical failure after a successful run should log again since the recorded signature was cleared") | |||
| 305 | } | 343 | } | ||
| 306 | 344 | ||||
| 307 | type syncWriter struct { | 345 | type syncWriter struct { | ||