From a7b06879046b4d16add922316c7df3f6f9abcab3 Mon Sep 17 00:00:00 2001 From: nxships <2096086+nxships@users.noreply.github.com> Date: Sun, 2 Aug 2026 00:06:57 +0200 Subject: [PATCH] fix(internaldata): stamp ended_at when the territory-drift check abandons an encounter UpsertSightingAsync's territory-drift branch nulled mCurrentEncounterId without stamping ended_at, unlike OnTerritoryChanged and the world-drift branch immediately below it. A missed or late TerritoryChanged therefore left the row dangling at ended_at IS NULL until the next session's orphan sweep - and when that reload happened to land in the same territory, pass 1's unbounded crash-recovery branch resumed it and welded two unrelated visits into one encounter with a bogus duration. Both drift branches now feed a shared driftStampId slot. They are mutually exclusive by construction: the territory branch nulls mCurrentEncounterId, so the world branch's `mCurrentEncounterId is { } drifted` pattern can no longer match afterwards. Also add a one-shot warning to the watcher's ProcessAsync IsStopping bail. That path returning silently is why the lifetime-token regression fixed in NexusKit (Dalamud's load-timeout token being treated as the plugin lifetime) went unnoticed for weeks: observation persistence died 60s into every session, Recent and ObservationProcessed froze, and the nearby-player list silently stopped growing with nothing in the log. On a legitimate unload the warning fires at most once during teardown. Docs: correct the "plugin unload leaves the encounter open" claim - the Stopping transition now closes it cleanly, so only a hard crash leaves ended_at NULL - and document both drift checks plus the COUNT(*) WHERE ended_at IS NULL invariant. --- .../InternalDataEncounterTracker.cs | 53 +++++++++++++------ .../Players/InternalDataPlayerWatcher.cs | 22 +++++++- .../docs/encounters.md | 40 ++++++++++++-- 3 files changed, 93 insertions(+), 22 deletions(-) diff --git a/NexusKit.Modules.InternalData/Encounters/InternalDataEncounterTracker.cs b/NexusKit.Modules.InternalData/Encounters/InternalDataEncounterTracker.cs index 231adcb..34d64d0 100644 --- a/NexusKit.Modules.InternalData/Encounters/InternalDataEncounterTracker.cs +++ b/NexusKit.Modules.InternalData/Encounters/InternalDataEncounterTracker.cs @@ -15,11 +15,13 @@ namespace NexusKit.Modules.InternalData.Encounters; /// Lazy encounter creation: no row is written when the local player /// enters a zone alone — the parent encounter row is only inserted on the /// first sighting of a non-local character. Solo zone walks produce nothing. -/// One open encounter at a time. On in-game logout the encounter is -/// closed cleanly (ended_at stamped). On plugin unload the encounter is -/// left open with ended_at = null; the next session's orphan-close sweep -/// stamps it from the latest player_encounter activity. Same recovery -/// branch covers a hard game crash. +/// One open encounter at a time. On in-game logout AND on plugin +/// unload the encounter is closed cleanly (ended_at stamped) — the unload +/// case rides the transition, +/// which fires while the lifetime token is still live. Only a hard game +/// crash leaves the row open with ended_at = null; the next session's +/// orphan-close sweep then stamps it from the latest player_encounter +/// activity. /// internal sealed class InternalDataEncounterTracker : IInternalDataEncounterTracker, IDisposable { @@ -205,10 +207,9 @@ private void OnLifecycleStateChanged(PluginLifecycleState state) // encounter id, so mCurrentEncounterId is null here // and the write branch is skipped. Keeping the case // in the switch makes the state-machine intent - // explicit and survives the external-cancel path - // (where Stopping fires with the CT already gone, - // StampEndedAtAsync bails at its IsStopping guard, - // and we'd otherwise leak the in-memory id). + // explicit and is cheap belt-and-braces in case a + // future lifetime driver ever reaches Stopped without + // having fired Stopping first. if (state != PluginLifecycleState.Idle && state != PluginLifecycleState.Stopping && state != PluginLifecycleState.Stopped) return; @@ -243,7 +244,9 @@ private void OnLifecycleStateChanged(PluginLifecycleState state) // Stopped: CT is already cancelled; StampEndedAtAsync would bail // at its IsStopping guard anyway. Nothing to do beyond the - // in-memory clear above. + // in-memory clear above. In the normal flow the Stopping case + // ran first and already stamped ended_at, so there is nothing + // left to write here either. } } @@ -305,7 +308,13 @@ private async Task UpsertSightingAsync( // simultaneous sightings can't race two encounter rows into the DB. long encounterId; bool openedNew = false; - long? worldDriftStampId = null; + // Encounter that a drift check (territory or world) decided is + // stale and needs its ended_at stamped. Both branches below feed + // the same slot: they're mutually exclusive by construction, since + // the territory branch nulls mCurrentEncounterId and the world + // branch's `mCurrentEncounterId is { } drifted` pattern can then + // no longer match. + long? driftStampId = null; lock (mLock) { // If the cached territory has drifted from the snapshot's @@ -315,6 +324,16 @@ private async Task UpsertSightingAsync( if (mCurrentTerritoryId != territoryId) { mCurrentTerritoryId = territoryId; + // Stamp the drifted encounter, mirroring what + // OnTerritoryChanged does. Dropping the id on the floor + // here (as this branch used to) left the row dangling at + // ended_at IS NULL until the NEXT session's orphan sweep — + // and when that reload happened to land in the same zone, + // pass 1's unbounded crash-recovery branch resumed it and + // welded two unrelated visits into one encounter with a + // bogus duration. Null is fine here: it just means nothing + // was open yet. + driftStampId = mCurrentEncounterId; mCurrentEncounterId = null; } // World-drift defensive check. Lifestream world visits can @@ -339,7 +358,7 @@ private async Task UpsertSightingAsync( if (mCurrentWorldId is { } wOld && wNew != wOld && mCurrentEncounterId is { } drifted) { - worldDriftStampId = drifted; + driftStampId = drifted; mCurrentEncounterId = null; } mCurrentWorldId = wNew; @@ -355,11 +374,11 @@ private async Task UpsertSightingAsync( } } - // Stamp the world-drifted encounter's ended_at outside the - // lock. Fire-and-forget mirrors the OnTerritoryChanged path - // (it dispatches StampEndedAtAsync the same way after marking - // the encounter id null). - if (worldDriftStampId is { } toClose) + // Stamp the drifted encounter's ended_at outside the lock. + // Fire-and-forget mirrors the OnTerritoryChanged path (it + // dispatches StampEndedAtAsync the same way after marking the + // encounter id null). + if (driftStampId is { } toClose) _ = Task.Run(() => StampEndedAtAsync(toClose)); if (openedNew) diff --git a/NexusKit.Modules.InternalData/Players/InternalDataPlayerWatcher.cs b/NexusKit.Modules.InternalData/Players/InternalDataPlayerWatcher.cs index d0bb6e2..58ea9e7 100644 --- a/NexusKit.Modules.InternalData/Players/InternalDataPlayerWatcher.cs +++ b/NexusKit.Modules.InternalData/Players/InternalDataPlayerWatcher.cs @@ -65,6 +65,11 @@ private sealed record HydrateRow( private readonly SemaphoreSlim mProcessGate = new(initialCount: 1, maxCount: 1); private int mFrameCounter; private bool mDisposed; + // 0 until the "lifetime is stopping, persistence is off" warning in + // ProcessAsync has been emitted once. Flipped with Interlocked because + // ProcessAsync runs on thread-pool threads and overlapping ticks would + // otherwise each log a copy. + private int mStoppingBailLogged; // Bumped every time the in-memory mObserved map mutates. Exposed via // IInternalDataPlayerWatcher.Revision so UI consumers (currently the // user-filter memoization in PlayerListPanel) can detect "list changed @@ -314,7 +319,22 @@ private async Task ProcessAsync( bool canTrackChange, uint? localPlayerCurrentWorldId) { - if (mDb.IsStopping) return; + if (mDb.IsStopping) + { + // One-shot. On a legitimate unload this fires at most once during + // teardown, which is harmless noise. If it shows up while the + // plugin is plainly still running, the lifetime token was + // cancelled by something that is NOT a shutdown — observation + // persistence is then dead for the rest of the session, Recent / + // ObservationProcessed are frozen, and the nearby-player list + // silently stops growing. That exact failure mode ran unnoticed + // for weeks because this path used to return without a word. + if (Interlocked.Exchange(ref mStoppingBailLogged, 1) == 0) + mLog.LogWarning( + "InternalData: observation persistence disabled — the plugin lifetime is stopping. " + + "If the plugin is still running, this is a lifetime-token bug, not a shutdown."); + return; + } // Try-acquire the serialization gate. If a previous tick's scan is // still running, drop this tick — the next ~1s scan re-sees the // same players and applies the same upsert, so nothing is lost. diff --git a/NexusKit.Modules.InternalData/docs/encounters.md b/NexusKit.Modules.InternalData/docs/encounters.md index 20803a4..c3ad44e 100644 --- a/NexusKit.Modules.InternalData/docs/encounters.md +++ b/NexusKit.Modules.InternalData/docs/encounters.md @@ -61,7 +61,8 @@ truth; both upsert and close paths read/write it under `mLock`. Mid-zone-load races (TerritoryChanged hasn't fired yet but the client is partway through the load) are reconciled in `UpsertSightingAsync`: if the cached territory drifts from the snapshot's, the snapshot wins and the -cached encounter is treated as stale. +cached encounter is closed and treated as stale. See "Drift reconciliation" +below. ## Startup recovery sweep @@ -116,9 +117,40 @@ rolls both back instead of leaving an orphan parent. unload paths the DI container backing `INexusDbContextFactory` is already torn down by the time `Dispose` runs. The `Stopping` lifecycle callback above is the supported final-write point; `Dispose` only unsubscribes and -nulls the in-memory id. If the `Stopping` write was missed (external -cancel path), the next startup's sweep closes the orphan from -`last_seen_at`. +nulls the in-memory id. + +That final write depends on `Stopping` firing while the lifetime token is +still live. It only does so because `PluginLifetime` is **not** linked to +Dalamud's `LoadAsync` token — see `NexusKit.Hosting/docs/lifecycle.md`, +"Do NOT feed `BuildAsync`'s token to `PluginLifetime`". While it was linked, +`Stopping` fired 60 s after every load with the token already cancelled, so +this write always bailed and the real unload fired nothing at all. If the +`Stopping` write is ever missed again, the next startup's sweep closes the +orphan from `last_seen_at`. + +## Drift reconciliation + +Two checks in `UpsertSightingAsync` catch a stale open encounter, and **both** +stamp `ended_at` on the row they abandon: + +| Drift | Detection | Why no event covers it | +|---|---|---| +| Territory | cached `mCurrentTerritoryId` != the snapshot's | `TerritoryChanged` hasn't fired yet — the client is partway through a zone load. | +| World | cached `mCurrentWorldId` != the snapshot's | A Lifestream world visit can land back in the SAME territory id on the destination world (Limsa 129 → Limsa 129), so `TerritoryChanged` never fires at all. Dalamud has no world-transfer event. | + +The two are mutually exclusive by construction (the territory branch nulls +`mCurrentEncounterId`, so the world branch's pattern match can no longer +succeed), which is why one `driftStampId` slot serves both. + +The territory branch used to null the id **without** stamping. That left the +row dangling at `ended_at IS NULL` until the next session's sweep — and when +that reload happened to land in the same zone, pass 1's unbounded +crash-recovery branch resumed it and welded two unrelated visits into one +encounter with a bogus duration. + +Invariant worth asserting after any multi-zone session: +`SELECT COUNT(*) FROM nexus_internal_encounter WHERE ended_at IS NULL` must be +`0` (plugin unloaded) or `1` (running, current zone). ## `seen_count` is gone