fix(session): report the frame a pause began at

Frames go on counting while paused, since Pump still runs, but status
gave no pause frame and `wait --paused` replied with the current one.
A wait that came minutes after `pause --on-check` caught a failure at
frame 237 said "paused at frame 5475", which an agent takes for when
the check failed.

The session records the frame in PauseNow, and status and the paused
wait report it as pausedAt. The client prints "PAUSED since frame N",
and "paused at frame N (now M)" when the two differ.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
Jorijn van der Graaf 2026-11-01 03:21:41 +01:00
commit 2c77cdcfab
Signed by: jorijnvdgraaf
GPG key ID: 2937E59CDCC1BCFB
3 changed files with 29 additions and 5 deletions

View file

@ -269,6 +269,9 @@ namespace Crafter::Debug {
bool armedOnCheck = false; bool armedOnCheck = false;
bool armedTrap = false; bool armedTrap = false;
std::string pauseReason; std::string pauseReason;
// The frame the pause began at. Frames go on counting while paused,
// so the current one says nothing about when it stopped.
std::uint64_t pausedAt = 0;
bool shutDown = false; bool shutDown = false;
// The Pump thread's own. // The Pump thread's own.
@ -333,11 +336,12 @@ namespace Crafter::Debug {
} }
void PauseNow(std::string reason, bool trap) { void PauseNow(std::string reason, bool trap) {
paused.store(true);
{ {
std::lock_guard lock(mutex); std::lock_guard lock(mutex);
pauseReason = reason; pauseReason = reason;
pausedAt = frame.load();
} }
paused.store(true);
Detail::Timeline::Instance().Append(Detail::MakeEntry(EntryKind::Pause, "debug", std::format("paused: {}", reason), std::source_location::current())); Detail::Timeline::Instance().Append(Detail::MakeEntry(EntryKind::Pause, "debug", std::format("paused: {}", reason), std::source_location::current()));
if (trap && TracerAttached()) ::raise(SIGTRAP); if (trap && TracerAttached()) ::raise(SIGTRAP);
} }
@ -429,6 +433,7 @@ namespace Crafter::Debug {
{ {
std::lock_guard lock(mutex); std::lock_guard lock(mutex);
status.Set("pauseReason", Value(pauseReason)); status.Set("pauseReason", Value(pauseReason));
if (paused.load()) status.Set("pausedAt", Value(pausedAt));
status.Set("queued", Value(jobs.size())); status.Set("queued", Value(jobs.size()));
status.Set("waiting", Value(waiters.size())); status.Set("waiting", Value(waiters.size()));
status.Set("following", Value(followers.size())); status.Set("following", Value(followers.size()));
@ -615,7 +620,7 @@ namespace Crafter::Debug {
waiter.kind = WaitKind::Paused; waiter.kind = WaitKind::Paused;
if (paused.load()) { if (paused.load()) {
std::lock_guard lock(mutex); std::lock_guard lock(mutex);
return exchange->Reply(MakeReply(Object({ { "frame", Value(frame.load()) }, { "reason", Value(pauseReason) } }))); return exchange->Reply(MakeReply(Object({ { "frame", Value(frame.load()) }, { "pausedAt", Value(pausedAt) }, { "reason", Value(pauseReason) } })));
} }
} }
std::lock_guard lock(mutex); std::lock_guard lock(mutex);
@ -914,11 +919,13 @@ namespace Crafter::Debug {
case WaitKind::Paused: case WaitKind::Paused:
if (paused.load()) { if (paused.load()) {
std::string reason; std::string reason;
std::uint64_t since = 0;
{ {
std::lock_guard lock(mutex); std::lock_guard lock(mutex);
reason = pauseReason; reason = pauseReason;
since = pausedAt;
} }
waiter.exchange->Reply(MakeReply(Object({ { "frame", Value(current) }, { "reason", Value(reason) } }))); waiter.exchange->Reply(MakeReply(Object({ { "frame", Value(current) }, { "pausedAt", Value(since) }, { "reason", Value(reason) } })));
done = true; done = true;
} }
break; break;

View file

@ -474,8 +474,11 @@ namespace {
const Value& s = *result; const Value& s = *result;
const bool paused = s.Find("paused")->AsBool(); const bool paused = s.Find("paused")->AsBool();
const std::string reason = s.Find("pauseReason") ? s.Find("pauseReason")->AsString() : std::string(); const std::string reason = s.Find("pauseReason") ? s.Find("pauseReason")->AsString() : std::string();
const Value* pausedAt = s.Find("pausedAt");
Out() << std::format("{} frame {} {:.1f} fps {}\n", s.Find("name")->AsString(), s.Find("frame")->Dump(), s.Find("fps")->AsNumber(), Out() << std::format("{} frame {} {:.1f} fps {}\n", s.Find("name")->AsString(), s.Find("frame")->Dump(), s.Find("fps")->AsNumber(),
paused ? std::format("PAUSED ({})", reason) : std::string("running")); !paused ? std::string("running")
: pausedAt != nullptr ? std::format("PAUSED since frame {} ({})", pausedAt->Dump(), reason)
: std::format("PAUSED ({})", reason));
std::string armed; std::string armed;
if (const Value* when = s.Find("armed")->Find("when")) armed += std::format(" pause armed: when '{}'", when->AsString()); if (const Value* when = s.Find("armed")->Find("when")) armed += std::format(" pause armed: when '{}'", when->AsString());
if (s.Find("armed")->Find("onCheck") != nullptr) armed += " pause armed: on the next failing check"; if (s.Find("armed")->Find("onCheck") != nullptr) armed += " pause armed: on the next failing check";
@ -703,7 +706,11 @@ namespace {
} else if (const Value* event = r.Find("event")) { } else if (const Value* event = r.Find("event")) {
Out() << std::format("{} at frame {}: {}\n", event->AsString(), r.Find("frame")->Dump(), Display(*r.Find("payload"))); Out() << std::format("{} at frame {}: {}\n", event->AsString(), r.Find("frame")->Dump(), Display(*r.Find("payload")));
} else if (const Value* reason = r.Find("reason")) { } else if (const Value* reason = r.Find("reason")) {
Out() << std::format("paused at frame {}: {}\n", r.Find("frame")->Dump(), reason->AsString()); // When it stopped, not when this wait looked: frames go on
// counting while paused.
const Value* pausedAt = r.Find("pausedAt");
const std::string since = pausedAt != nullptr ? pausedAt->Dump() : r.Find("frame")->Dump();
Out() << std::format("paused at frame {}{}: {}\n", since, since != r.Find("frame")->Dump() ? std::format(" (now {})", r.Find("frame")->Dump()) : std::string(), reason->AsString());
} else { } else {
Out() << std::format("frame {}\n", r.Find("frame")->Dump()); Out() << std::format("frame {}\n", r.Find("frame")->Dump());
} }

View file

@ -92,7 +92,17 @@ int main() {
const Value pausedReply = ResultOf(*waitPaused); const Value pausedReply = ResultOf(*waitPaused);
const Value* reason = pausedReply.Find("reason"); const Value* reason = pausedReply.Find("reason");
Check(reason != nullptr && reason->AsString().find("counter >= 3") != std::string::npos, "wait --paused replies with the reason"); Check(reason != nullptr && reason->AsString().find("counter >= 3") != std::string::npos, "wait --paused replies with the reason");
// Frames go on while paused: a wait that comes later must still say
// when the pause began, not the frame it looked at.
const std::uint64_t pausedAt = pausedReply.Find("pausedAt")->AsInteger();
for (std::int32_t frame = 0; frame < 5; ++frame) Pump();
const Value later = ResultOf(*Send("debug.wait", R"({"paused": true})"));
const Value statusWhilePaused = ResultOf(*Send("debug.status"));
Check(later.Find("pausedAt")->AsInteger() == static_cast<std::int64_t>(pausedAt) && later.Find("frame")->AsInteger() >= static_cast<std::int64_t>(pausedAt) + 5
&& statusWhilePaused.Find("pausedAt")->AsInteger() == static_cast<std::int64_t>(pausedAt),
std::format("a later wait and status say when the pause began (frame {}), not the frame now", pausedAt));
Send("debug.resume"); Send("debug.resume");
Check(ResultOf(*Send("debug.status")).Find("pausedAt") == nullptr, "status has no pausedAt once resumed");
Check(ResultOf(*Send("debug.pause", R"({"onCheck": true})")).Find("armed")->AsString() == "onCheck", "pause --on-check arms"); Check(ResultOf(*Send("debug.pause", R"({"onCheck": true})")).Find("armed")->AsString() == "onCheck", "pause --on-check arms");
Check(Advance(), "running before the check fails"); Check(Advance(), "running before the check fails");