diff --git a/engine/MUNGA/DROPZONE.cpp b/engine/MUNGA/DROPZONE.cpp index 2e9c1ff..1120dc7 100644 --- a/engine/MUNGA/DROPZONE.cpp +++ b/engine/MUNGA/DROPZONE.cpp @@ -170,6 +170,67 @@ void Entity *entity = host->GetEntityPointer(message->requestingEntity); Check(entity); + // ---- BT_DROPZONE_LOG (2026-07-30) ------------------------------------- + // The GHOST MECH investigation: a respawn strands forever when no slot is + // available, because the no-zone path below reposts this message to itself + // every 0.1 s at MaxEventPriority and NEVER replies -- so the player's + // deathPending latch is never cleared (Gitea #57/#81). This whole + // subsystem was previously DARK: not one log line about drop zones in a + // full night of field logs, which is why it hid. Log the pool state on + // every request, and the outcome, so saturation is measurable. + // Rate-limited: reposts are logged for the first few then once a second, + // because a single stranded player generates 10 reposts/second forever. + // The POOL CENSUS and the STALL WATCHDOG below are ALWAYS ON (no env gate): + // a respawn stall is rare, catastrophic and field-only, exactly like the + // Gitea #57/#59 guards. Volume is bounded -- one census line per mission, + // one line per grant (i.e. per respawn), and stall lines are rate-limited + // per waiting player. BT_DROPZONE_LOG adds the verbose per-request dump + // for bench work. + const Logical dzLog = (getenv("BT_DROPZONE_LOG") != 0); + static Logical s_census = False; + if (!s_census) + { + s_census = True; + DEBUG_STREAM << "[dz] POOL name='" << GetDropZoneName() + << "' slots=" << dropZoneCount << " downTime=" << DOWN_TIME + << "s proximityBlock=2m\n" << std::flush; + } + // + // Track how long THIS (requester, death) pair has been waiting. The engine + // reposts the same message to itself every 0.1 s while no slot is free, so + // the first sighting is the start of the stall. + // + enum { DZ_WAITERS = 8 }; + static EntityID s_waitWho[DZ_WAITERS]; + static int s_waitDeath[DZ_WAITERS]; + static Time s_waitSince[DZ_WAITERS]; + static Time s_waitLastLog[DZ_WAITERS]; + static int s_waitUsed = 0; + int wslot = -1; + for (int w = 0; w < s_waitUsed; ++w) + if (s_waitWho[w] == message->requestingEntity + && s_waitDeath[w] == message->deathCount) + { wslot = w; break; } + if (wslot < 0 && s_waitUsed < DZ_WAITERS) + { + wslot = s_waitUsed++; + s_waitWho[wslot] = message->requestingEntity; + s_waitDeath[wslot] = message->deathCount; + s_waitSince[wslot] = Now(); + s_waitLastLog[wslot].ticks = 0; + } + const Scalar waited = (wslot >= 0) ? (Scalar)(Now() - s_waitSince[wslot]) : 0.0f; + + if (dzLog) + { + DEBUG_STREAM << "[dz] REQUEST from entity " << (int)message->requestingEntity + << " deathCount=" << message->deathCount + << " waited=" << waited << "s slots["; + for (int d = 0; d < dropZoneCount; ++d) + DEBUG_STREAM << (d ? " " : "") << d << (IsAvailable(d) ? ":free" : ":BUSY"); + DEBUG_STREAM << "]\n" << std::flush; + } + // //--------------------------------------------------------------------- // If we have allocated a dropzone within the last ten seconds for this @@ -306,6 +367,41 @@ void // if (!drop_zone) { + // NO SLOT: repost to ourselves in 0.1 s and reply to nobody. The + // requester's respawn is stalled until this eventually succeeds -- if it + // never does, that player is a permanent GHOST (dead, un-reset, still + // simulated and driveable, wearing the wreck on every peer). + // ALWAYS-ON STALL WATCHDOG. Escalating, rate-limited (first sighting, + // then every 5 s per waiting player), and it names WHY each slot is + // busy -- seconds since last use and who used it -- which is the + // actionable half: cooldown saturation (pool too small for the death + // rate) looks different from proximity blocking (mechs parked on the + // pad). After 15 s a stalled respawn is a confirmed GHOST: the player + // is dead, un-reset, still driveable, and a wreck on every peer. + if (wslot >= 0 + && (!s_waitLastLog[wslot].ticks || (Now() - s_waitLastLog[wslot]) > 5.0f)) + { + s_waitLastLog[wslot] = Now(); + DEBUG_STREAM << (waited >= 15.0f ? "[dz] GHOST LIKELY -- " : "[dz] STALL -- ") + << "entity " << (int)message->requestingEntity + << " death#" << message->deathCount + << " has waited " << waited << "s for a slot; all " + << dropZoneCount << " busy ["; + for (int d = 0; d < dropZoneCount; ++d) + { + Scalar age = lastUsageTime[d].ticks ? (Scalar)(Now() - lastUsageTime[d]) : -1.0f; + DEBUG_STREAM << (d ? " " : "") << d << ":usedBy=" + << (int)lastUsedBy[d] << ",age=" << age << "s"; + } + DEBUG_STREAM << "]\n" << std::flush; + } + if (dzLog) + { + static int s_rp = 0; + if (++s_rp <= 5) + DEBUG_STREAM << "[dz] repost #" << s_rp << " (entity " + << (int)message->requestingEntity << ")\n" << std::flush; + } Time when=Now(); when += 0.1f; application->Post(MaxEventPriority, this, message, when); @@ -318,6 +414,34 @@ void //-------------------------------------------------------------------- // Found_One: + // ALWAYS ON -- one line per respawn. `waited` is the headline number: 0 is + // healthy, anything seconds-long means the pool is saturating, and a grant + // after a long wait is a ghost that RECOVERED (which is what testers see as + // "it fixed itself after a while"). + { + static int s_grants = 0, s_stalledGrants = 0; + int slot = (int)(drop_zone - dropZones); + if (waited > 0.5f) ++s_stalledGrants; + ++s_grants; + DEBUG_STREAM << "[dz] GRANTED slot " << slot << " to entity " + << (int)message->requestingEntity << " death#" << message->deathCount + << " waited=" << waited << "s" + << (waited >= 15.0f ? " (GHOST RECOVERED)" : "") + << " [grants=" << s_grants << " stalled=" << s_stalledGrants << "]" + << "\n" << std::flush; + // retire this waiter slot so the table does not fill up over a match + if (wslot >= 0) + { + for (int w = wslot; w + 1 < s_waitUsed; ++w) + { + s_waitWho[w] = s_waitWho[w+1]; + s_waitDeath[w] = s_waitDeath[w+1]; + s_waitSince[w] = s_waitSince[w+1]; + s_waitLastLog[w] = s_waitLastLog[w+1]; + } + --s_waitUsed; + } + } ReplyMessage reply( message->replyMessageID, diff --git a/game/reconstructed/btplayer.cpp b/game/reconstructed/btplayer.cpp index b331801..3fde367 100644 --- a/game/reconstructed/btplayer.cpp +++ b/game/reconstructed/btplayer.cpp @@ -413,6 +413,33 @@ void << message->deathCount << " deathCount=" << deathCount << ")\n" << std::flush; + // ALWAYS-ON GHOST TRACE (#81 field diagnostics). The requester half of + // the drop-zone handshake, paired with the [dz] lines from the DropZone + // entity. Two things are worth recording on every re-post: + // * how many times we have re-posted for THIS death -- the respawn is + // supposed to complete on the first or second try, so a climbing + // count is a ghost forming; + // * msgDeath vs our own deathCount -- the engine gates the hunt on + // message->deathCount == deathCount, and the DropZone's re-send + // safety net is keyed on lastDeathCount == message->deathCount, so a + // MISMATCH silently breaks both (Gitea #45: the death tally is known + // not to replicate correctly). This is the cheapest way to see it. + { + static int s_tries = 0; + static int s_forDeath = -999; + if (s_forDeath != message->deathCount) { s_forDeath = message->deathCount; s_tries = 0; } + ++s_tries; + if (s_tries <= 3 || (s_tries % 5) == 0) + DEBUG_STREAM << "[dzreq] player " << BTMatchHostOf(GetEntityID()) + << ":" << (int)GetEntityID() << " asking for a drop zone" + << " try=" << s_tries + << " msgDeath=" << message->deathCount + << " ourDeathCount=" << deathCount + << (message->deathCount != deathCount ? " *** MISMATCH -- hunt gate + resend net both break ***" : "") + << (s_tries >= 4 ? " (respawn not completing -- ghost forming)" : "") + << "\n" << std::flush; + } + // // Respawning needs a drop zone. A dev mission without a "DropZones" // group would hit the engine base's ACTIVE Check(dropzones) -> an