diff --git a/bridged/src/main/java/dev/ltms/bridged/inject/CompletionResolver.java b/bridged/src/main/java/dev/ltms/bridged/inject/CompletionResolver.java index d97a5bf..1d1be03 100644 --- a/bridged/src/main/java/dev/ltms/bridged/inject/CompletionResolver.java +++ b/bridged/src/main/java/dev/ltms/bridged/inject/CompletionResolver.java @@ -214,7 +214,7 @@ public final class CompletionResolver implements TurnListener { } if (rendezvous.resolveFailure(waiter, reason)) { inFlight.remove(target, turn); - log.debug("failed send to {} via turn-stall fallback", target); + log.warn("failing send to {} via turn-stall fallback: {}", target, reason); } } diff --git a/bridged/src/main/java/dev/ltms/bridged/inject/Injector.java b/bridged/src/main/java/dev/ltms/bridged/inject/Injector.java index 82f8854..b6848e2 100644 --- a/bridged/src/main/java/dev/ltms/bridged/inject/Injector.java +++ b/bridged/src/main/java/dev/ltms/bridged/inject/Injector.java @@ -402,6 +402,10 @@ public final class Injector { t.awaitingPostTurnPickup = false; t.postTurnObserved = false; } + log.warn("{} is gone, dropping its queue: {} message(s) failed{}; cause: {}", target, + pending.size(), + hadDeliveredTurn ? " (including one turn already in flight whose completion was never confirmed)" : "", + cause.getMessage()); forget.accept(target); // the worker is gone — clear its readiness/presence too (CB-114) for (Pending p : pending) { p.delivered().completeExceptionally(cause); diff --git a/bridged/src/main/java/dev/ltms/bridged/msg/MessageService.java b/bridged/src/main/java/dev/ltms/bridged/msg/MessageService.java index 1ceecb2..e7758d4 100644 --- a/bridged/src/main/java/dev/ltms/bridged/msg/MessageService.java +++ b/bridged/src/main/java/dev/ltms/bridged/msg/MessageService.java @@ -277,7 +277,7 @@ public final class MessageService { } boolean failed = rendezvous.resolveFailure(waiter, reason); if (failed) { - log.debug("abandoned send to {}: {}", target, reason); + log.warn("abandoning the blocked send to {}: {}", target, reason); } return failed; } diff --git a/bridged/src/main/java/dev/ltms/bridged/session/SessionManager.java b/bridged/src/main/java/dev/ltms/bridged/session/SessionManager.java index e5d6d50..fdb5766 100644 --- a/bridged/src/main/java/dev/ltms/bridged/session/SessionManager.java +++ b/bridged/src/main/java/dev/ltms/bridged/session/SessionManager.java @@ -140,7 +140,13 @@ public final class SessionManager implements TurnListener { // to pick the profile out of that role's pool and to label the tab; a role kept only on // the MemberSession is recorded after the spawn it was supposed to steer. SpawnRequest req = new SpawnRequest(profile, requestedCwd, callerCwd, null, null, memberRole); - PeerHandle handle = launcher.spawn(req); + PeerHandle handle; + try { + handle = launcher.spawn(req); + } catch (RuntimeException e) { + log.warn("spawn failed for profile={} role={}: {}", profile, memberRole, e.getMessage()); + throw e; + } String resolvedProfile = resolveProfile(handle, profile); String cwd = launcher.effectiveCwd(new SpawnRequest(resolvedProfile, requestedCwd, callerCwd)); long now = nowNanos.getAsLong(); @@ -312,6 +318,8 @@ public final class SessionManager implements TurnListener { worktrees.overlayParity(repoRoot, path, launcher.parityOverlay(preResolvedProfile)); handle = launcher.spawn(new SpawnRequest(profile, path, callerCwd, null, null, memberRole)); } catch (RuntimeException e) { + log.warn("spawn failed for profile={} role={} branch={} path={}: {}", + preResolvedProfile, memberRole, branch, path, e.getMessage()); if (path != null) { try { worktrees.remove(repoRoot, path); @@ -484,8 +492,10 @@ public final class SessionManager implements TurnListener { MemberSession current = findByTerminal(target); if (current == null) return; if (current.state() == MemberSession.State.RELEASED) return; + MemberSession.State priorState = current.state(); if (replace(current, current.withState(MemberSession.State.FAILED))) { - log.debug("session marked failed terminal={} pane={}", target, current.paneId()); + log.warn("member terminal={} pane={} can no longer be delegated to: its turn never resolved " + + "(was {} when it failed)", target, current.paneId(), priorState); } } @@ -501,7 +511,11 @@ public final class SessionManager implements TurnListener { if (s.state() != MemberSession.State.READY && s.state() != MemberSession.State.DONE) { continue; } - if (now - s.lastActivityAtNanos() > idleTtlNanos) { + long idleNanos = now - s.lastActivityAtNanos(); + if (idleNanos > idleTtlNanos) { + log.debug("reaping idle session terminal={} pane={}: idle {}s exceeds the {}s ttl", + s.terminalId(), s.paneId(), TimeUnit.NANOSECONDS.toSeconds(idleNanos), + TimeUnit.NANOSECONDS.toSeconds(idleTtlNanos)); release(s.paneId()); reaped++; } diff --git a/bridged/src/test/java/dev/ltms/bridged/inject/CompletionResolverTest.java b/bridged/src/test/java/dev/ltms/bridged/inject/CompletionResolverTest.java index c7dd2fe..8ae282d 100644 --- a/bridged/src/test/java/dev/ltms/bridged/inject/CompletionResolverTest.java +++ b/bridged/src/test/java/dev/ltms/bridged/inject/CompletionResolverTest.java @@ -1,9 +1,14 @@ package dev.ltms.bridged.inject; +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; import dev.ltms.bridged.herdr.AgentControl; import dev.ltms.bridged.herdr.FakeHerdr; import dev.ltms.bridged.msg.Rendezvous; import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertFalse; @@ -298,6 +303,40 @@ class CompletionResolverTest { assertEquals("stuck on an error screen", waiter.getNow(null).text()); } + @Test + void failIsLoggedAtWarnWithTheReason() { + // CB-564: this used to be a bare DEBUG "failed send to X via turn-stall fallback" — a symptom + // with no cause, and below the level anyone watching for member health would see. A fail that + // resolves a caller's blocked send is at least WARN and must carry the reason. + LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); + ch.qos.logback.classic.Logger resolverLog = + (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(CompletionResolver.class); + ListAppender appender = new ListAppender<>(); + appender.setContext(ctx); + appender.start(); + resolverLog.addAppender(appender); + resolverLog.setLevel(Level.WARN); + try { + FakeHerdr herdr = new FakeHerdr().readText("stuck on an error screen"); + Rendezvous rendezvous = new Rendezvous(); + CompletionResolver resolver = new CompletionResolver(new AgentControl(herdr), rendezvous); + var waiter = rendezvous.open("term_a"); + + resolver.fail("term_a", null); + + String warn = appender.list.stream() + .filter(e -> e.getLevel().equals(Level.WARN)) + .map(ILoggingEvent::getFormattedMessage) + .findFirst() + .orElse("no turn-stall WARN logged"); + assertTrue(warn.contains("term_a"), "the log names the target: " + warn); + assertTrue(warn.contains("stuck on an error screen"), "the log carries the reason: " + warn); + assertTrue(waiter.isDone()); + } finally { + resolverLog.detachAppender(appender); + } + } + // --- CB-116 waiter identity: a late completion never crosses into the next turn --------- @Test diff --git a/bridged/src/test/java/dev/ltms/bridged/inject/InjectorTest.java b/bridged/src/test/java/dev/ltms/bridged/inject/InjectorTest.java index bf276e0..990b7a0 100644 --- a/bridged/src/test/java/dev/ltms/bridged/inject/InjectorTest.java +++ b/bridged/src/test/java/dev/ltms/bridged/inject/InjectorTest.java @@ -436,6 +436,38 @@ class InjectorTest { assertEquals(List.of(T), forgotten, "drop clears the gone worker's presence"); } + @Test + void dropIsLogged() { + // CB-564: a vanished worker used to drop its queue with no log at all — the only trace was + // whatever failed downstream (e.g. a caller's send timing out with no clue why). Assert the + // drop itself now names the cause and the number of messages it failed. + LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); + ch.qos.logback.classic.Logger injectorLog = + (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Injector.class); + ListAppender appender = new ListAppender<>(); + appender.setContext(ctx); + appender.start(); + injectorLog.addAppender(appender); + injectorLog.setLevel(Level.WARN); + try { + Injector inj = new Injector(new AgentControl(herdr), TurnListener.NOOP, _ -> true, _ -> { + }); + inj.enqueue(T, "orphan"); + inj.drop(T, new HerdrException("worker gone", "pane_not_found", null)); + + String warn = appender.list.stream() + .filter(e -> e.getLevel().equals(Level.WARN)) + .map(ILoggingEvent::getFormattedMessage) + .findFirst() + .orElse("no drop WARN logged"); + assertTrue(warn.contains(T), "the log names the target terminal: " + warn); + assertTrue(warn.contains("1 message"), "the log carries the failed message count: " + warn); + assertTrue(warn.contains("worker gone"), "the log carries the real cause: " + warn); + } finally { + injectorLog.detachAppender(appender); + } + } + @Test void pollerDeliversToAnIdleWorker() throws Exception { // End-to-end through the poller: idle worker → message delivered without manual onStatus. diff --git a/bridged/src/test/java/dev/ltms/bridged/session/SessionManagerTest.java b/bridged/src/test/java/dev/ltms/bridged/session/SessionManagerTest.java index 6488d7e..febf37a 100644 --- a/bridged/src/test/java/dev/ltms/bridged/session/SessionManagerTest.java +++ b/bridged/src/test/java/dev/ltms/bridged/session/SessionManagerTest.java @@ -1,5 +1,9 @@ package dev.ltms.bridged.session; +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; import dev.ltms.bridged.config.BridgedConfig; import dev.ltms.bridged.guard.SubscriptionGuard; import dev.ltms.bridged.herdr.AgentControl; @@ -8,6 +12,7 @@ import dev.ltms.bridged.herdr.WorkspaceControl; import dev.ltms.bridged.member.ClaudeCodeLauncher; import dev.ltms.bridged.peer.PeerUnreachableException; import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; import java.util.List; import java.util.Map; @@ -157,6 +162,41 @@ class SessionManagerTest { assertTrue(sessions.roster().contains(updated), "FAILED is still in acquired-minus-released roster"); } + @Test + void onTurnFailedIsLoggedAtWarnWithThePriorState() { + // CB-564: this transition used to be a bare DEBUG "session marked failed" — a symptom with no + // cause. A member that can no longer be delegated to must be at least WARN, and should name + // what stage it failed at (here: BUSY, i.e. a turn was in flight and never resolved). + LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); + ch.qos.logback.classic.Logger sessionLog = + (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(SessionManager.class); + ListAppender appender = new ListAppender<>(); + appender.setContext(ctx); + appender.start(); + sessionLog.addAppender(appender); + sessionLog.setLevel(Level.WARN); + try { + FakeHerdr herdr = new FakeHerdr(); + SessionManager sessions = sessionManager(herdr); + MemberSession session = sessions.acquire("ltms-local", null, "/caller", "term_primary"); + String terminal = session.terminalId(); + sessions.asPresence().markPresent(terminal); + sessions.onDelivered(terminal); + + sessions.onTurnFailed(terminal); + + String warn = appender.list.stream() + .filter(e -> e.getLevel().equals(Level.WARN)) + .map(ILoggingEvent::getFormattedMessage) + .findFirst() + .orElse("no turn-failed WARN logged"); + assertTrue(warn.contains(terminal), "the log names the member: " + warn); + assertTrue(warn.contains("BUSY"), "the log names the stage it failed at: " + warn); + } finally { + sessionLog.detachAppender(appender); + } + } + @Test void rosterReflectsAcquiredMinusReleased() { FakeHerdr herdr = new FakeHerdr();