ebf4652 fix(daemon): log pty exit causes and recover dropped frames · vev

M internal/usecase/daemon/client.go +4 -0


@@ -43,6 +43,10 @@ type attachedClient struct {
43	43		resumeToken uint64
44	44		parked bool
45	45		echoAck atomic.Uint64
	46	+	// prepareFailureFallback prevents a direct fallback paint from recursively
	47	+	// reporting the same failed prepare through its notice repaint. It is only
	48	+	// needed while no render coordinator is installed.
	49	+	prepareFailureFallback atomic.Bool
46	50		// pipelineCache is the last successfully emitted composition. pipelineScratch
47	51		// is its attachment-owned alternate buffer; both are only touched under
48	52		// sendMu and must never share mutable backing storage.


@@ -43,6 +43,10 @@ type attachedClient struct {
43	resumeToken uint64	43		resumeToken uint64
44	parked bool	44		parked bool
45	echoAck atomic.Uint64	45		echoAck atomic.Uint64
		46	+	// prepareFailureFallback prevents a direct fallback paint from recursively
		47	+	// reporting the same failed prepare through its notice repaint. It is only
		48	+	// needed while no render coordinator is installed.
		49	+	prepareFailureFallback atomic.Bool
46	// pipelineCache is the last successfully emitted composition. pipelineScratch	50		// pipelineCache is the last successfully emitted composition. pipelineScratch
47	// is its attachment-owned alternate buffer; both are only touched under	51		// is its attachment-owned alternate buffer; both are only touched under
48	// sendMu and must never share mutable backing storage.	52		// sendMu and must never share mutable backing storage.

M internal/usecase/daemon/floating_test.go +11 -4


@@ -501,11 +501,18 @@ func TestFloatingLaunchUsesLiveOrValidatedSessionCwd(t *testing.T) {
501	501		type floatingLogHandler struct {
502	502		slog.Handler
503	503		handled chan struct{}
	504	+	mu sync.Mutex
504	505		}
505	506
506		-	func (h floatingLogHandler) Handle(ctx context.Context, r slog.Record) error {
	507	+	func (h *floatingLogHandler) Handle(ctx context.Context, r slog.Record) error {
507	508		err := h.Handler.Handle(ctx, r)
508		-	close(h.handled)
	509	+	h.mu.Lock()
	510	+	select {
	511	+	case <-h.handled:
	512	+	default:
	513	+	close(h.handled)
	514	+	}
	515	+	h.mu.Unlock()
509	516		return err
510	517		}
511	518

@@ -514,7 +521,7 @@ func TestFloatingLaunchFailureCapturesSessionNameBeforeConcurrentRename(t *testi
514	521		var logs bytes.Buffer
515	522		handled := make(chan struct{})
516	523		d := newTestDaemon(t, factory, stubClock{})
517		-	d.log = slog.New(floatingLogHandler{Handler: slog.NewTextHandler(&logs, nil), handled: handled})
	524	+	d.log = slog.New(&floatingLogHandler{Handler: slog.NewTextHandler(&logs, nil), handled: handled})
518	525		tb := newFloatingTestTab(t)
519	526		sess := &session{name: "captured", tabs: []*tab{tb}, ctx: t.Context()}
520	527		d.startFloating(sess, tb, false)

@@ -552,7 +559,7 @@ func TestFloatingInstallLogsSessionNameSafelyDuringRename(t *testing.T) {
552	559		var logs bytes.Buffer
553	560		handled := make(chan struct{})
554	561		d := newTestDaemon(t, factory, stubClock{})
555		-	d.log = slog.New(floatingLogHandler{Handler: slog.NewTextHandler(&logs, nil), handled: handled})
	562	+	d.log = slog.New(&floatingLogHandler{Handler: slog.NewTextHandler(&logs, nil), handled: handled})
556	563		tb := newFloatingTestTab(t)
557	564		sess := &session{name: "captured", tabs: []*tab{tb}, ctx: t.Context()}
558	565

 type floatingLogHandler struct {
 	slog.Handler
 	handled chan struct{}
+	mu      sync.Mutex
 }
-func (h floatingLogHandler) Handle(ctx context.Context, r slog.Record) error {
+func (h *floatingLogHandler) Handle(ctx context.Context, r slog.Record) error {
 	err := h.Handler.Handle(ctx, r)
-	close(h.handled)
+	h.mu.Lock()
+	select {
+	case <-h.handled:
+	default:
+		close(h.handled)
+	}
+	h.mu.Unlock()
 	return err
 }
 	var logs bytes.Buffer
 	handled := make(chan struct{})
 	d := newTestDaemon(t, factory, stubClock{})
-	d.log = slog.New(floatingLogHandler{Handler: slog.NewTextHandler(&logs, nil), handled: handled})
+	d.log = slog.New(&floatingLogHandler{Handler: slog.NewTextHandler(&logs, nil), handled: handled})
 	tb := newFloatingTestTab(t)
 	sess := &session{name: "captured", tabs: []*tab{tb}, ctx: t.Context()}
 	d.startFloating(sess, tb, false)
 	var logs bytes.Buffer
 	handled := make(chan struct{})
 	d := newTestDaemon(t, factory, stubClock{})
-	d.log = slog.New(floatingLogHandler{Handler: slog.NewTextHandler(&logs, nil), handled: handled})
+	d.log = slog.New(&floatingLogHandler{Handler: slog.NewTextHandler(&logs, nil), handled: handled})
 	tb := newFloatingTestTab(t)
 	sess := &session{name: "captured", tabs: []*tab{tb}, ctx: t.Context()}

M internal/usecase/daemon/input_test.go +4 -1


@@ -380,8 +380,11 @@ func TestActionFocusPaneGenuineErrorReportsNoticeInternal(t *testing.T) {
380	380		daemonKeyHandler{d: d, ac: ac}.Action(keys.ActionFocusPaneLeft)
381	381
382	382		history := d.notices.history()
383		-	require.Len(t, history, 1, "a genuine layout-tree error must surface exactly one notice")
	383	+	require.Len(t, history, 2, "the layout error and its failed direct display update must both surface")
384	384		require.Equal(t, domain.NoticeInternal, history[0].Code)
	385	+	require.Equal(t, "display update failed", history[0].Message)
	386	+	require.Equal(t, domain.NoticeInternal, history[1].Code)
	387	+	require.Equal(t, "internal error", history[1].Message)
385	388		}
386	389
387	390		func TestFloatingVisibilityRemainsIndependentAcrossTabSwitches(t *testing.T) {

 	daemonKeyHandler{d: d, ac: ac}.Action(keys.ActionFocusPaneLeft)
 	history := d.notices.history()
-	require.Len(t, history, 1, "a genuine layout-tree error must surface exactly one notice")
+	require.Len(t, history, 2, "the layout error and its failed direct display update must both surface")
 	require.Equal(t, domain.NoticeInternal, history[0].Code)
+	require.Equal(t, "display update failed", history[0].Message)
+	require.Equal(t, domain.NoticeInternal, history[1].Code)
+	require.Equal(t, "internal error", history[1].Message)
 }
 func TestFloatingVisibilityRemainsIndependentAcrossTabSwitches(t *testing.T) {

M internal/usecase/daemon/render.go +1 -0


@@ -101,6 +101,7 @@ func (d Daemon) ptyReader(sess session, tb tab, p pane) {
101	101		d.processPTYData(sess, tb, p, buf[:n], true)
102	102		}
103	103		if err != nil {
	104	+	d.log.Info("pane pty closed", "err", err, "session", sess.name)
104	105		if p.onExit != nil {
105	106		p.onExit()
106	107		} else {


@@ -101,6 +101,7 @@ func (d Daemon) ptyReader(sess session, tb tab, p pane) {
101	d.processPTYData(sess, tb, p, buf[:n], true)	101		d.processPTYData(sess, tb, p, buf[:n], true)
102	}	102		}
103	if err != nil {	103		if err != nil {
		104	+	d.log.Info("pane pty closed", "err", err, "session", sess.name)
104	if p.onExit != nil {	105		if p.onExit != nil {
105	p.onExit()	106		p.onExit()
106	} else {	107		} else {

M internal/usecase/daemon/render_damage_receipt_test.go +40 -0


@@ -104,6 +104,10 @@ func TestRenderDamageReceiptRetainsRealVTDamageAcrossFailedEmission(t *testing.T
104	104		} {
105	105		t.Run(tt.name, func(t *testing.T) {
106	106		d, sess, ac, sends := newManualSessionWithPTYs(t, nil)
	107	+	// Prepare failures now schedule recovery through the coordinator;
	108	+	// retain the failed transaction here until this test explicitly retries.
	109	+	d.clock = newNoticeClock()
	110	+	d.attachCoordinator(sess, nil, ac, true)
107	111		healthy := ac.transport()
108	112		p := sess.tabs[0].focusedPane()
109	113

@@ -136,6 +140,42 @@ func TestRenderDamageReceiptRetainsRealVTDamageAcrossFailedEmission(t *testing.T
136	140		}
137	141		}
138	142
	143	+	func TestPrepareFailureNotifiesAndSchedulesRecovery(t *testing.T) {
	144	+	clock := newNoticeClock()
	145	+	d, sess, ac, _ := newNoticeFixture(t, clock)
	146	+	rc := d.attachCoordinator(sess, nil, ac, true)
	147	+	var producers []string
	148	+	rc.opts.onInvalidate = func(inv renderInvalidation) {
	149	+	// Both the notice repaint and the explicit recovery must re-enter only
	150	+	// after emitFrame releases its attachment locks.
	151	+	require.True(t, ac.sendMu.TryLock(), "invalidation must not run under sendMu")
	152	+	ac.sendMu.Unlock()
	153	+	producers = append(producers, inv.producer)
	154	+	}
	155	+	state, composed := captureComposeForReceiptTest(t, sess, ac)
	156	+	// An invalid frame makes output.prepare fail after capture. emitFrame owns
	157	+	// sendMu on entry and releases it before reporting and rescheduling.
	158	+	composed.frame = renderer.Frame{Width: 1}
	159	+
	160	+	require.True(t, d.emitFrame(sess, ac, state, composed))
	161	+
	162	+	history := d.notices.history()
	163	+	require.Len(t, history, 1)
	164	+	require.Equal(t, domain.NoticeInternal, history[0].Code)
	165	+	require.Equal(t, "display update failed", history[0].Message)
	166	+	toasts, _ := visibleToasts(ac)
	167	+	require.Len(t, toasts, 1)
	168	+	require.Equal(t, "display update failed", toasts[0].Message)
	169	+
	170	+	rc.mu.Lock()
	171	+	pending, reset := rc.pending, rc.pendingReset
	172	+	rc.mu.Unlock()
	173	+	require.True(t, pending, "prepare failure must schedule a recovery render")
	174	+	require.True(t, reset, "recovery must invalidate the full render state")
	175	+	require.Contains(t, producers, "render_pipeline.go:prepare-failed", "prepare failure must explicitly schedule recovery")
	176	+	require.Contains(t, clock.durations(), urgentRenderDeadline, "notice/recovery invalidation must arm the coordinator")
	177	+	}
	178	+
139	179		func TestRenderDamageReceiptStaleGenerationForcesFullRedraw(t *testing.T) {
140	180		d, sess, ac, sends := newManualSessionWithPTYs(t, nil)
141	181		d.paint(sess, ac, true, nil)


@@ -104,6 +104,10 @@ func TestRenderDamageReceiptRetainsRealVTDamageAcrossFailedEmission(t *testing.T
104	} {	104		} {
105	t.Run(tt.name, func(t *testing.T) {	105		t.Run(tt.name, func(t *testing.T) {
106	d, sess, ac, sends := newManualSessionWithPTYs(t, nil)	106		d, sess, ac, sends := newManualSessionWithPTYs(t, nil)
		107	+	// Prepare failures now schedule recovery through the coordinator;
		108	+	// retain the failed transaction here until this test explicitly retries.
		109	+	d.clock = newNoticeClock()
		110	+	d.attachCoordinator(sess, nil, ac, true)
107	healthy := ac.transport()	111		healthy := ac.transport()
108	p := sess.tabs[0].focusedPane()	112		p := sess.tabs[0].focusedPane()
109		113

@@ -136,6 +140,42 @@ func TestRenderDamageReceiptRetainsRealVTDamageAcrossFailedEmission(t *testing.T
136	}	140		}
137	}	141		}
138		142
		143	+	func TestPrepareFailureNotifiesAndSchedulesRecovery(t *testing.T) {
		144	+	clock := newNoticeClock()
		145	+	d, sess, ac, _ := newNoticeFixture(t, clock)
		146	+	rc := d.attachCoordinator(sess, nil, ac, true)
		147	+	var producers []string
		148	+	rc.opts.onInvalidate = func(inv renderInvalidation) {
		149	+	// Both the notice repaint and the explicit recovery must re-enter only
		150	+	// after emitFrame releases its attachment locks.
		151	+	require.True(t, ac.sendMu.TryLock(), "invalidation must not run under sendMu")
		152	+	ac.sendMu.Unlock()
		153	+	producers = append(producers, inv.producer)
		154	+	}
		155	+	state, composed := captureComposeForReceiptTest(t, sess, ac)
		156	+	// An invalid frame makes output.prepare fail after capture. emitFrame owns
		157	+	// sendMu on entry and releases it before reporting and rescheduling.
		158	+	composed.frame = renderer.Frame{Width: 1}
		159	+
		160	+	require.True(t, d.emitFrame(sess, ac, state, composed))
		161	+
		162	+	history := d.notices.history()
		163	+	require.Len(t, history, 1)
		164	+	require.Equal(t, domain.NoticeInternal, history[0].Code)
		165	+	require.Equal(t, "display update failed", history[0].Message)
		166	+	toasts, _ := visibleToasts(ac)
		167	+	require.Len(t, toasts, 1)
		168	+	require.Equal(t, "display update failed", toasts[0].Message)
		169	+
		170	+	rc.mu.Lock()
		171	+	pending, reset := rc.pending, rc.pendingReset
		172	+	rc.mu.Unlock()
		173	+	require.True(t, pending, "prepare failure must schedule a recovery render")
		174	+	require.True(t, reset, "recovery must invalidate the full render state")
		175	+	require.Contains(t, producers, "render_pipeline.go:prepare-failed", "prepare failure must explicitly schedule recovery")
		176	+	require.Contains(t, clock.durations(), urgentRenderDeadline, "notice/recovery invalidation must arm the coordinator")
		177	+	}
		178	+
139	func TestRenderDamageReceiptStaleGenerationForcesFullRedraw(t *testing.T) {	179		func TestRenderDamageReceiptStaleGenerationForcesFullRedraw(t *testing.T) {
140	d, sess, ac, sends := newManualSessionWithPTYs(t, nil)	180		d, sess, ac, sends := newManualSessionWithPTYs(t, nil)
141	d.paint(sess, ac, true, nil)	181		d.paint(sess, ac, true, nil)

M internal/usecase/daemon/render_pipeline.go +12 -0


@@ -407,6 +407,18 @@ func (d Daemon) emitFrame(sess session, ac attachedClient, state capturedRen
407	407		ac.sess.mu.Unlock()
408	408		ac.sendMu.Unlock()
409	409		d.log.Error("render draw failed", "err", err, "session", sess.name)
	410	+	// Without a coordinator invalidateRender paints synchronously. Suppress
	411	+	// the nested failed paint caused by reportError's notice repaint; the
	412	+	// outer failure still records the notice and attempts recovery once.
	413	+	fallback := sess.renderCoordinator() == nil
	414	+	if fallback && !ac.prepareFailureFallback.CompareAndSwap(false, true) {
	415	+	return true
	416	+	}
	417	+	if fallback {
	418	+	defer ac.prepareFailureFallback.Store(false)
	419	+	}
	420	+	d.reportError(sess, domain.UserErr(domain.NoticeInternal, "display update failed", err))
	421	+	d.invalidateRender(sess, ac, true, "render_pipeline.go:prepare-failed")
410	422		return true
411	423		}
412	424		data := append([]byte(nil), prepared.data...)


@@ -407,6 +407,18 @@ func (d Daemon) emitFrame(sess session, ac attachedClient, state capturedRen
407	ac.sess.mu.Unlock()	407		ac.sess.mu.Unlock()
408	ac.sendMu.Unlock()	408		ac.sendMu.Unlock()
409	d.log.Error("render draw failed", "err", err, "session", sess.name)	409		d.log.Error("render draw failed", "err", err, "session", sess.name)
		410	+	// Without a coordinator invalidateRender paints synchronously. Suppress
		411	+	// the nested failed paint caused by reportError's notice repaint; the
		412	+	// outer failure still records the notice and attempts recovery once.
		413	+	fallback := sess.renderCoordinator() == nil
		414	+	if fallback && !ac.prepareFailureFallback.CompareAndSwap(false, true) {
		415	+	return true
		416	+	}
		417	+	if fallback {
		418	+	defer ac.prepareFailureFallback.Store(false)
		419	+	}
		420	+	d.reportError(sess, domain.UserErr(domain.NoticeInternal, "display update failed", err))
		421	+	d.invalidateRender(sess, ac, true, "render_pipeline.go:prepare-failed")
410	return true	422		return true
411	}	423		}
412	data := append([]byte(nil), prepared.data...)	424		data := append([]byte(nil), prepared.data...)

M internal/usecase/daemon/render_test.go +22 -0


@@ -218,6 +218,28 @@ func fireCoordinatorTimer(t testing.T, rc renderCoordinator, timers []*coordin
218	218		t.Fatalf("coordinator did not arm %s timer", duration)
219	219		}
220	220
	221	+	func TestPTYReaderLogsClosureWithoutNotification(t *testing.T) {
	222	+	pty := portsmocks.NewMockPTY(t)
	223	+	readErr := errors.New("pty master closed")
	224	+	pty.EXPECT().Read(mock.Anything).Return(0, readErr).Once()
	225	+	d, sess, ac, _ := newManualSessionWithPTYs(t, pty)
	226	+	var logs bytes.Buffer
	227	+	d.log = slog.New(slog.NewTextHandler(&logs, nil))
	228	+	pane := sess.tabs[0].focusedPane()
	229	+	pane.onExit = func() {}
	230	+
	231	+	d.sessWg.Add(1)
	232	+	d.ptyReader(sess, sess.tabs[0], pane)
	233	+
	234	+	require.Contains(t, logs.String(), "level=INFO")
	235	+	require.Contains(t, logs.String(), "msg=\"pane pty closed\"")
	236	+	require.Contains(t, logs.String(), "err=\"pty master closed\"")
	237	+	require.Contains(t, logs.String(), "session=work")
	238	+	require.Empty(t, d.notices.history(), "PTY closure is diagnostic only")
	239	+	toasts, _ := visibleToasts(ac)
	240	+	require.Empty(t, toasts, "PTY closure must not notify the user")
	241	+	}
	242	+
221	243		func TestPTYReaderSyncVisibilityTransitions(t *testing.T) {
222	244		t.Run("inactive synchronized pane activates only after complete urgent frame", func(t *testing.T) {
223	245		inactivePTY, inactiveSteps, inactiveProcessed := newChannelPTY(t)


@@ -218,6 +218,28 @@ func fireCoordinatorTimer(t testing.T, rc renderCoordinator, timers []*coordin
218	t.Fatalf("coordinator did not arm %s timer", duration)	218		t.Fatalf("coordinator did not arm %s timer", duration)
219	}	219		}
220		220
		221	+	func TestPTYReaderLogsClosureWithoutNotification(t *testing.T) {
		222	+	pty := portsmocks.NewMockPTY(t)
		223	+	readErr := errors.New("pty master closed")
		224	+	pty.EXPECT().Read(mock.Anything).Return(0, readErr).Once()
		225	+	d, sess, ac, _ := newManualSessionWithPTYs(t, pty)
		226	+	var logs bytes.Buffer
		227	+	d.log = slog.New(slog.NewTextHandler(&logs, nil))
		228	+	pane := sess.tabs[0].focusedPane()
		229	+	pane.onExit = func() {}
		230	+
		231	+	d.sessWg.Add(1)
		232	+	d.ptyReader(sess, sess.tabs[0], pane)
		233	+
		234	+	require.Contains(t, logs.String(), "level=INFO")
		235	+	require.Contains(t, logs.String(), "msg=\"pane pty closed\"")
		236	+	require.Contains(t, logs.String(), "err=\"pty master closed\"")
		237	+	require.Contains(t, logs.String(), "session=work")
		238	+	require.Empty(t, d.notices.history(), "PTY closure is diagnostic only")
		239	+	toasts, _ := visibleToasts(ac)
		240	+	require.Empty(t, toasts, "PTY closure must not notify the user")
		241	+	}
		242	+
221	func TestPTYReaderSyncVisibilityTransitions(t *testing.T) {	243		func TestPTYReaderSyncVisibilityTransitions(t *testing.T) {
222	t.Run("inactive synchronized pane activates only after complete urgent frame", func(t *testing.T) {	244		t.Run("inactive synchronized pane activates only after complete urgent frame", func(t *testing.T) {
223	inactivePTY, inactiveSteps, inactiveProcessed := newChannelPTY(t)	245		inactivePTY, inactiveSteps, inactiveProcessed := newChannelPTY(t)