Files
BT411/engine/MUNGA/DROPZONE.cpp
T
Joe DiPrimaandClaude Fable 5 ba6756c40a drop-zone / respawn instrumentation: make the GHOST MECH visible in field logs
The ghost (a player who dies, never respawns, stays dead-but-driveable and is a
wreck on every peer) traces to a respawn stalling on drop-zone acquisition:
DropZone::AssignDropZoneMessageHandler grants a slot only if IsAvailable(), and
when none is free it reposts to ITSELF every 0.1s at MaxEventPriority and never
replies -- so deathPending is never cleared.  This whole subsystem was DARK: not
one drop-zone line in a full night of field logs.

ALWAYS-ON (no env gate -- rare, catastrophic, field-only, same rationale as the
#57/#59 guards; volume bounded and rate-limited):
  [dz] POOL   -- slots + downTime + proximity radius, once per mission
  [dz] GRANTED-- one per respawn, with the WAIT time; tags (GHOST RECOVERED)
                 when a long-stalled request finally lands (what testers see as
                 "it fixed itself")
  [dz] STALL / GHOST LIKELY -- escalating, per-waiter rate-limited, and it names
                 WHY each slot is busy (age + last user), which discriminates
                 cooldown saturation from proximity blocking -- different fixes
  [dzreq]     -- the REQUESTER half: re-try count for this death, and msgDeath vs
                 our own deathCount.  The engine gates the hunt on those being
                 equal AND the DropZone resend net is keyed on the same value, so
                 a mismatch breaks both silently (cf #45, tally replication).
BT_DROPZONE_LOG=1 adds the verbose per-request slot dump for bench work.

First run already overturned a theory: slots=8, so an 8-slot pool cannot be
cooldown-starved by 5 players (max 5 on cooldown at once) -- the shared
dropzone=one in eggmodel.py is NOT the bottleneck.  Suspicion moves to the
handshake (lost reply / deathCount mismatch).

Verified with NO env vars set, exactly as a tester runs it: 4 probe lines for a
full death+respawn cycle, all in the normal day log.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-07-30 00:13:14 -05:00

572 lines
16 KiB
C++

#include "munga.h"
#pragma hdrstop
#include "dropzone.h"
#include "random.h"
#include "app.h"
#include "hostmgr.h"
#include "nttmgr.h"
#include "notation.h"
#include "namelist.h"
#include "player.h"
#define DOWN_TIME 5.0f
//#############################################################################
//############################### DropZone #################################
//#############################################################################
//#############################################################################
// Shared Data Support
//
Derivation* DropZone::GetClassDerivations()
{
static Derivation classDerivations(Entity::GetClassDerivations(),"DropZone");
return &classDerivations;
}
DropZone::SharedData
DropZone::DefaultData(
DropZone::GetClassDerivations(),
DropZone::GetMessageHandlers(),
DropZone::GetAttributeIndex(),
DropZone::StateCount,
(Entity::MakeHandler)DropZone::Make
);
//#############################################################################
// Message Support
//
const Receiver::HandlerEntry
DropZone::MessageHandlerEntries[]=
{
MESSAGE_ENTRY(DropZone, AssignDropZone)
};
Receiver::MessageHandlerSet& DropZone::GetMessageHandlers()
{
static Receiver::MessageHandlerSet messageHandlers(ELEMENTS(DropZone::MessageHandlerEntries), DropZone::MessageHandlerEntries, Entity::GetMessageHandlers());
return messageHandlers;
}
//#############################################################################
// Construction and Destruction
//
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
//
DropZone::DropZone(
DropZone::MakeMessage *creation_message,
DropZone::SharedData &virtual_data
):
Entity(creation_message, virtual_data)
{
Check_Pointer(this);
Check_Pointer(creation_message);
SetValidFlag();
dropZoneCount = 0;
dropZones = NULL;
//
//--------------------------------------------------------------
// Name the drop zone, and enter the zone in the drop zone group
//--------------------------------------------------------------
//
Str_Copy(dropZoneName, creation_message->dropZoneName, sizeof(dropZoneName));
EntityManager *entity_manager = application->GetEntityManager();
Check(entity_manager);
EntityGroup* drop_zones = entity_manager->UseGroup("DropZones");
Check(drop_zones);
drop_zones->Add(this);
//
//-----------------------------------------------------------------------
// Now, interpret the data to create the appropriate number of drop zones
//-----------------------------------------------------------------------
//
MemoryStream
stream(
creation_message,
creation_message->messageLength,
sizeof(*creation_message)
);
dropZoneCount = creation_message->dropZoneCount;
Verify(dropZoneCount > 0);
dropZones = new Origin[dropZoneCount];
Register_Pointer(dropZones);
lastUsageTime = new Time[dropZoneCount];
Register_Pointer(lastUsageTime);
lastUsedBy = new EntityID[dropZoneCount];
Register_Pointer(lastUsedBy);
lastDeathCount = new int[dropZoneCount];
Register_Pointer(lastDeathCount);
for (int i=0; i<dropZoneCount; ++i)
{
dropZones[i] = *(Origin*)stream.GetPointer();
lastUsageTime[i] = Time::Null;
lastUsedBy[i] = EntityID::Null;
lastDeathCount[i] = -3;
stream.AdvancePointer(sizeof(Origin));
}
}
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
//
DropZone*
DropZone::Make(DropZone::MakeMessage *creation_message)
{
return new DropZone(creation_message);
}
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
//
DropZone::~DropZone()
{
if (dropZones)
{
Unregister_Pointer(dropZones);
delete[] dropZones;
Unregister_Pointer(lastUsageTime);
delete[] lastUsageTime;
Unregister_Pointer(lastUsedBy);
delete[] lastUsedBy;
Unregister_Pointer(lastDeathCount);
delete[] lastDeathCount;
}
}
//#############################################################################
// Dropzone assignment
//
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
//
Logical
DropZone::IsAvailable(int index)
{
Check(this);
Verify(index >= 0 && index < dropZoneCount);
Check(application);
return
!lastUsageTime[index].ticks
|| Now() - lastUsageTime[index] > DOWN_TIME
&& application->GetApplicationState() == Application::RunningMission;
}
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
//
void
DropZone::AssignDropZoneMessageHandler(AssignDropZoneMessage* message)
{
Check(this);
Check_Pointer(message);
Check(application);
HostManager *host = application->GetHostManager();
Check(host);
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
// player, resend the data
//---------------------------------------------------------------------
//
Origin *drop_zone = NULL;
int
lowest, highest, remaining, i;
for (i=0; i<dropZoneCount; ++i)
{
if (
!IsAvailable(i)
&& lastUsedBy[i] == message->requestingEntity
&& lastDeathCount[i] == message->deathCount
)
{
lastUsageTime[i] = Now();
drop_zone = &dropZones[i];
goto Found_One;
}
}
//
//------------------------------------------------------------------------
// Figure out how many drop zones are available. If none are, repost this
// message to ourself
//------------------------------------------------------------------------
//
lowest = dropZoneCount;
highest = -1;
remaining = 0;
for (i=0; i<dropZoneCount; ++i)
{
if (IsAvailable(i))
{
++remaining;
if (i < lowest)
{
lowest = i;
}
if (i > highest)
{
highest = i;
}
}
}
//
//-----------------------------------------------------
// Now, randomly look about until we find one available
//-----------------------------------------------------
//
highest = highest - lowest + 1;
while (remaining)
{
i = lowest + Random(highest);
Verify(i < dropZoneCount && i >= 0);
if (IsAvailable(i))
{
//
//-------------------------------------------------------------------
// Check to see if vehicle attached to a player is within 2 meters of
// this drop zone. If so, mark it unavailable for 3 seconds
//-------------------------------------------------------------------
//
EntityManager *entity_mgr = application->GetEntityManager();
Check(entity_mgr);
EntityGroup *player_group = entity_mgr->FindGroup("Players");
if (
player_group
&& application->GetApplicationState()
== Application::RunningMission
)
{
Player *player;
ChainIteratorOf<Node*> iterator(player_group->groupMembers);
while ((player = (Player*)iterator.ReadAndNext()) != NULL)
{
Check(player);
Entity *vehicle = player->GetPlayerVehicle();
if (vehicle && player != entity)
{
Check(vehicle);
Vector3D distance;
distance.Subtract(
vehicle->localOrigin.linearPosition,
dropZones[i].linearPosition
);
if (distance.LengthSquared() <= 4.0f)
{
lastUsedBy[i] = NULL;
lastUsageTime[i] = Now();
lastUsageTime[i] -= DOWN_TIME - 1.0f;
--remaining;
if (i == lowest)
{
++lowest;
--highest;
}
else if (i == lowest + highest - 1)
{
--highest;
}
break;
}
}
}
//
//----------------------------------------------------------
// If someone was in this spot, keep looking for another one
//----------------------------------------------------------
//
if (player)
{
continue;
}
}
lastUsageTime[i] = Now();
drop_zone = &dropZones[i];
lastUsedBy[i] = message->requestingEntity;
lastDeathCount[i] = message->deathCount;
remaining = 0;
}
}
//
//----------------------------------------------------------------
// If no drop_zone could be found, repost the message to ourselves
//----------------------------------------------------------------
//
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);
return;
}
//
//--------------------------------------------------------------------
// Send a message back to the requesting object what sent this message
//--------------------------------------------------------------------
//
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,
sizeof(ReplyMessage),
*drop_zone,
message->deathCount
);
entity->Dispatch(&reply);
}
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
//
Logical
DropZone::CreateMakeMessage(
MakeMessage *creation_message,
const char* model_name,
const char* resource_name,
NotationFile *map_file
)
{
Check(creation_message);
Check(map_file);
Check_Pointer(model_name);
Check_Pointer(resource_name);
if (!Entity::CreateMakeMessage(creation_message, map_file, NULL))
{
return False;
}
creation_message->classToCreate = RegisteredClass::DropZoneClassID;
creation_message->instanceFlags = MapFlag|TrappedFlag;
//
//-----------------------------------------------
// Count up the number of drop zones in our model
//-----------------------------------------------
//
Enumeration save_modes = map_file->GetModes();
map_file->SetMode(NotationFile::CleanListMode);
NameList *zone_list =
map_file->MakeEntryList(model_name, "dropzone");
Register_Object(zone_list);
creation_message->dropZoneCount = zone_list->EntryCount();
creation_message->messageLength =
sizeof(*creation_message)
+ creation_message->dropZoneCount*sizeof(Origin);
if (!creation_message->dropZoneCount)
{
std::cout << "Error: " << model_name << " hasn't specified any drop zones!\n";
Dump_And_Die:
Unregister_Object(zone_list);
delete zone_list;
map_file->PutModes(save_modes);
return False;
}
//
//---------------------------------------------
// Allocate a buffer to hold the drop zone data
//---------------------------------------------
//
MemoryStream
stream(
creation_message,
creation_message->messageLength,
sizeof(*creation_message)
);
//
//----------------------------
// zero out the drop zone name
//----------------------------
//
for (int ii=0; ii<sizeof(creation_message->dropZoneName); ii++)
{
creation_message->dropZoneName[ii] = '\0';
}
Str_Copy(
creation_message->dropZoneName,
resource_name,
sizeof(creation_message->dropZoneName)
);
//
//-----------------
// Read in the data
//-----------------
//
NameList::Entry *drop_zone = zone_list->GetFirstEntry();
while (drop_zone)
{
Point3D translation;
EulerAngles tmp_rotation;
const char* zone_data = drop_zone->GetChar();
sscanf(
zone_data,
"%f %f %f %f %f %f",
&translation.x,
&translation.y,
&translation.z,
&tmp_rotation.pitch,
&tmp_rotation.yaw,
&tmp_rotation.roll
);
((Origin*)stream.GetPointer())->linearPosition = translation;
((Origin*)stream.GetPointer())->angularPosition = tmp_rotation;
stream.AdvancePointer(sizeof(Origin));
drop_zone = drop_zone->GetNextEntry();
}
Unregister_Object(zone_list);
delete zone_list;
map_file->PutModes(save_modes);
return True;
}
Logical
DropZone::TestInstance() const
{
return IsDerivedFrom(*GetClassDerivations());
}