Skip to content

ISSUE-041: make session teardown survive a failing SignOut, and start measuring connection silence - #56

Merged
Sellafield merged 3 commits into
OpenPerpetuum:developfrom
meketreve:issue-041-investigation-findings
Aug 19, 2026
Merged

ISSUE-041: make session teardown survive a failing SignOut, and start measuring connection silence#56
Sellafield merged 3 commits into
OpenPerpetuum:developfrom
meketreve:issue-041-investigation-findings

Conversation

@meketreve

Copy link
Copy Markdown
Contributor

Addresses part of ISSUE-041 — characters
staying online after the player has gone. The reasoning behind it is on that issue; this is what came
out of it.

It does not close the issue, and the parts it leaves open are named below rather than left for a
reader to discover.

The defect

There is one session teardown path and both a clean logout and a dropped connection reach it
identically: Session.Disconnect(safeLogout) calls ForceQuit, which ends in
_connection.Disconnect() — the same call a lost socket makes.

Session.OnDisconnected completed its transaction and only then raised Disconnected, on the next
line and outside it. SessionManager.Remove is a subscriber to that event. So an exception anywhere
inside SignOut() skipped the removal:

  • the session stayed in _sessions, and its Player stayed in the zone tick for the life of the
    process
  • the rolled-back inuse = 0 left the character shown as online
  • TcpConnection runs the whole teardown under LogExceptions, so the only trace was one logged
    exception and nothing else

A second variant needed no rollback at all: Disconnected is a plain multicast invoke,
SessionManager.OnSessionDisconnected is subscribed to it before Remove is, and a multicast
delegate stops at the first subscriber that throws.

The fix

Raising Disconnected moves into a finally, so the session leaves _sessions whether or not
SignOut() succeeded. SessionManager.OnSessionDisconnected contains its own failure so it cannot
cancel the Remove subscribed after it.

The exception is still allowed to leave Session.OnDisconnected deliberately. What throws is a
separate and still unanswered question, and swallowing it would make that question harder to answer,
not easier.

The measurement, and why there is no timeout in here

An idle timeout is the other half of this issue, and it needs a threshold that cannot be chosen from
inside this repository. The client sends zero-length keepalive packets — they arrive as data, since
they still carry their four length bytes — but their interval is a client decision. A threshold set
below it disconnects players who are still connected, which is a worse failure than the one being
fixed.

So this ships the measurement rather than a guess. ConnectionActivity records when data last arrived
and the widest gap between two receives; TcpConnection touches it on every receive; both numbers are
logged when a connection closes:

connection closed. 1.2.3.4:5678 silent for 3.4s, longest gap 12.1s

Nothing disconnects on those numbers. Read them off a live server, then the threshold can be set
from data and the timeout enabled. Worth noting the timeout belongs on the relay connection rather than
on ZoneSession, whose existing InactiveTime only covers players who are currently in a zone.

One design detail the tests forced: a gap that is still open does not count towards the longest. A
connection whose peer vanished an hour ago would otherwise report a one-hour keepalive interval and
poison the very measurement this exists to collect.

Test coverage, stated plainly

ConnectionActivity has 11 unit tests, written before the type existed and observed failing against
its absence. They inject "now" rather than sleeping.

The teardown change is covered by inspection only. Session takes a raw Socket in its
constructor and builds its connection from it, and SessionManager.Add is private and reachable only
through a real TcpListener accept — neither can be exercised at the unit tier without adding a
production seam, and that seemed like a bigger request than a fix should smuggle in. If you would
rather have the seam (a Session constructor taking ITcpConnection, which touches Session.Factory
and the Autofac registration), say so and it can be a separate pull request with the tests that seam
makes possible.

What is still open

This stops the session leaking and stops a dead Player being ticked forever. It does not put the
character offline when the transaction rolls back: Character.IsOnline is the characters.inuse
column, so a rolled-back SignOut() leaves the player shown as online until they next sign in, at
which point SignIn clears it. Fixing that means a compensating write outside the failed transaction,
in a catch path, and that is a design decision that should not be made while the thing being
compensated for is still unnamed.

The question that unblocks the rest

Both open parts need the same thing — a look at a live log. [Relay] client disconnected. is written
by a subscriber to Disconnected, so before this change it could only appear when the event fired. In
a window where a ghost was reported, was there a logged exception with no matching
[Relay] client disconnected. line?
That confirms the mechanism and names what throws.

Validation

Solution builds with 0 errors and no new warnings on the changed files. Tier 2 84/84 (73 before, 11
new), tier 3 10/10, neither skipped. tools/smoke-test.ps1 green: online in 78 s, 6425 members,
graceful shutdown in 28 s, exit 0.

The backlog entry is updated in the same branch: status IN_PROGRESS, each step marked with what
actually shipped, and the open half written up as its own section so it is not mistaken for done.

meketreve and others added 3 commits August 17, 2026 16:35
…ating

The entry asked which case was being reported, a graceful logout or a dropped
connection, and said the two would be different defects. Tracing the code
answers it: there is only one teardown path and it is reached identically by
both, so a mechanism that breaks it produces the symptom either way.

Session.OnDisconnected completes its transaction and only then raises
Disconnected on the following line, outside it. SessionManager.Remove is a
subscriber to that event. So an exception anywhere in SignOut() rolls back the
inuse = 0 write and skips the removal, leaving the character online and the
session in _sessions -- and TcpConnection runs the whole teardown under
LogExceptions, which swallows it after logging.

What throws is still unknown and cannot be read off the code. Step 1 of the
proposed fix is now a log question rather than a code change: a ghost produced
this way logs an exception with no matching "[Relay] client disconnected."
line, because that line is written by a subscriber to the event that never
fired.

Also records one thing found in passing and deliberately not fixed: the
ThrowIfZero guards on the two accountonlinetime procedures cannot fire, since
both procedures set NOCOUNT ON and ExecuteNonQuery then returns -1.

No code changed. Line numbers anchored to 1e68c4a; the files cited are
byte-identical to 4e6d697, so the entry's earlier anchors still resolve.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…re silence

Two changes, one defect and one measurement.

The defect. Session.OnDisconnected completed its transaction and only then raised
Disconnected, on the following line and outside it. SessionManager.Remove is a
subscriber to that event, so an exception anywhere in SignOut() skipped the
removal: the session stayed in _sessions, the rolled-back inuse = 0 left the
character shown as online, and its Player stayed in the zone tick. TcpConnection
runs the whole teardown under LogExceptions, so the only trace was one logged
exception.

Raising the event now happens in a finally. The exception is still allowed to
leave, because what throws is a separate question and hiding it would make that
question harder to answer.

SessionManager.OnSessionDisconnected is subscribed to Disconnected before Remove
is, and a multicast delegate stops at the first subscriber that throws, so it
could cancel the removal on its own. It now contains its failure and logs it.
Signing out twice was already expected there; SignOut returns early once
AccountId has been cleared.

The measurement. An idle timeout is the other half of this issue and it needs a
threshold nobody here can supply: the client sends zero-length keepalive packets,
which arrive as data, but their interval is a client decision and guessing it low
disconnects players who are still connected. ConnectionActivity records when data
last arrived and the widest gap between two receives, TcpConnection touches it on
every receive, and the numbers are logged when the connection closes. Nothing
disconnects on them. The threshold comes later, from what a live server reports.

Test coverage is honest about what it reaches. ConnectionActivity has eleven unit
tests, written first and observed failing, and injects "now" rather than sleeping.
The teardown change is covered by inspection only: Session takes a raw Socket in
its constructor and SessionManager.Add is private and reachable only through a
real TcpListener accept, so neither can be exercised at the unit tier without a
production seam, and adding one was declined as out of scope for a fix.

Solution builds with 0 errors and no new warnings. Tier 2 84/84, tier 3 10/10,
smoke green: online in 78 s, 6425 members, graceful shutdown in 28 s, exit 0.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Status goes to IN_PROGRESS. Step 2 is done, step 3 is half done -- the
measurement shipped, the timeout did not, because its threshold has to come from
a live server rather than from a guess. Step 4 is not done and now says why: the
teardown cannot be reached at the unit tier without a production seam.

Adds a section for the half that is still open, so it is not mistaken for fixed.
The teardown change stops the session leaking, but a rolled-back SignOut still
leaves characters.inuse = 1, so the player is still shown online until they next
sign in. Fixing that means a compensating write in a catch path, which should not
be designed while the thing it compensates for is unnamed.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@Sellafield
Sellafield merged commit 1c21cdc into OpenPerpetuum:develop Aug 19, 2026
4 checks passed
@meketreve
meketreve deleted the issue-041-investigation-findings branch August 19, 2026 18:27
Sellafield pushed a commit that referenced this pull request Aug 20, 2026
* ISSUE-041: give the session log a vocabulary, and count the flags sign in clears

Two small types, both unit tested, neither wired in yet.

SessionDiagnostics composes the lines in one place so the words and the units
stay the same wherever they are written from. Two tags: [Session] for the
ordinary lifecycle, [Ghost] for a character left flagged online with nobody
behind it. It also exists so the wording can be tested at all -- Session builds
its connection from a raw socket and cannot be reached at the unit tier.

StaleOnlineFlags takes over the update sign in has always run defensively
against characters.inuse, and reports how many rows it cleared. Those rows are
exactly the online flags a previous sign out failed to clear, and nothing has
ever recorded how often that happens.

The statement gains "and inuse=1". The data it leaves behind is identical --
setting a column to the value it already holds changes nothing -- but without
the predicate the update matches every character on the account and would report
that count on every single sign in, stale or not.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

* ISSUE-041: tell the two kinds of stale login apart, and name the closing session

A ghost announces itself at sign in: the account row says logged in when nobody
asked it to be. Until now the handler wrote "a logged in account was found" for
both shapes of that, and they need different fixes.

If the server is still holding the session, the peer vanished without closing
and nothing here noticed -- the missing idle timeout. If there is no session
behind the flag, the sign out ran and rolled back, leaving the row set. The
handler now writes which one it is, and the held case carries the connection's
silence, so the gap that produced it is on the record next to it.

Session gains a line of its own when it closes, carrying session, account,
character, endpoint and both silence numbers. It is written before sign out
rather than after, because sign out clears AccountId and Character on commit and
every later line has only the endpoint left to identify the connection by.
Unauthenticated connections are skipped: no identity to correlate, and
TcpConnection already logs their close.

ISession and ITcpConnection expose the ConnectionActivity that #56 added, which
is what lets the handler report a held session's silence.

Perpetuum.Tests now references Perpetuum.RequestHandlers, and Fakes/Sessions
holds the doubles that make a request handler reachable at the unit tier. Every
member no test uses throws rather than returning a default.

Sign in no longer runs the flag update inline; it calls StaleOnlineFlags.

Three tests, written first and observed failing against the single old line.
The Session change itself is covered by inspection only -- Session takes a raw
Socket in its constructor and cannot be constructed at this tier -- which is why
the wording it logs lives in SessionDiagnostics, where it is tested.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

* ISSUE-041: report how many online flags have nobody behind them

The per-event lines say when a ghost was made or found. This says how many are
standing right now, which is the number that tells a bad evening apart from a
steady leak -- and the only one of the two that keeps being true while nobody is
signing in.

StaleOnlineFlagCensus counts the characters flagged online whose account holds
no live session, and logs the count every five minutes. Five minutes because it
is a trend rather than an alarm: the number is read off a log afterwards, and a
shorter period would only add lines.

It also reports as soon as it starts. The timer fires a full interval after
that, so the first number would otherwise arrive five minutes into the run, and
the reading at start is the sharpest one available: no session is connected yet,
so every flag still set was left behind by the run before.

Counted per row rather than per account, because one account can hold several
characters and the flag is left on whichever one was selected.

It reports and does not repair. A census that cleared what it counted would
erase the evidence it was added to gather, and doing that on a timer would race
the sessions legitimately holding those flags.

Five tests, written first and observed failing.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

* ISSUE-041: record what the instrumentation answers, and a live report

The backlog entry asked for a live server log before anything else, on the
grounds that only a log could say whether a ghost came from a sign out that
rolled back or from a peer that vanished without closing. The log of the day
could not say: the sign in handler wrote the same line for both. Step 1 now
describes what was shipped to make it answerable instead of who to ask.

Also recorded: a ghost session reported from the live server on 2026-08-19,
after a dropped internet connection. That is the keepalive half of this issue
rather than the rollback half, and it is the case the measurement in #56 was
built for -- but it cannot be attributed with certainty, because that is exactly
the distinction the log could not draw.

TESTING.md picks up the unit count, which was stale, and the session fakes that
make request handlers reachable at that tier.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

---------

Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants