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

docs/backlog/issues.md

@@ -4,7 +4,7 @@
 
 ## ISSUE-041 - Characters stay online after the player logs out and closes the client ("zombie sessions")
 
-Status: TODO
+Status: IN_PROGRESS
 Priority: MEDIUM
 Area: Networking / Sessions
 Tracking: https://github.com/OpenPerpetuum/PerpetuumServer2/issues/51
@@ -33,12 +33,47 @@ keepalive still isn't tight enough after real-world observation." **That observa
 reported, so the deferral is due for review.** The 2-hour value is confirmed shipped and live in
 `TcpConnection.cs:32`.
 
-**One detail does not fit and should be settled first.** The keepalive mechanism above explains
-*ungraceful* disconnects — a crash, a force-kill, a dropped network, a closed laptop lid. The report
-describes a *graceful* exit: the player logged out and closed the client, which should send a clean TCP
-close and run the normal session teardown. Either the reports also cover ungraceful cases, or the
-logout path itself sometimes fails to tear the session down. Those are different defects with different
-fixes, and the evidence to tell them apart has not been gathered.
+**The detail that did not fit is now explained, and it points at a second, independent mechanism.**
+The keepalive above covers only *ungraceful* disconnects, while the report describes a *graceful* exit.
+Investigated 2026-08-17: there is a single teardown path, and it is fragile in a way that produces this
+exact symptom on **either** kind of exit.
+
+`Session.Disconnect(safeLogout)` calls `ForceQuit`, which ends in `_connection.Disconnect()`
+(`src/Perpetuum/Network/TcpConnection.cs:59`) — the same call a dropped socket makes. Nothing below
+that point distinguishes a clean logout from a lost connection:
+
+1. `TcpConnection.Disconnect()` runs the whole teardown as
+   `Task.Run(OnDisconnected).ContinueWith(t => Dispose()).LogExceptions()` (`TcpConnection.cs:68`).
+2. `Session.OnDisconnected` (`Session.cs:300`) wraps `SignOut()` in a transaction, completes it, and
+   **then** raises `Disconnected` on the next line (`Session.cs:308`), outside the transaction.
+3. `SessionManager` subscribes twice and in this order: `OnSessionDisconnected` at
+   `SessionManager.cs:67`, then `Remove` at `SessionManager.cs:124` by way of `Add`.
+
+So one exception thrown anywhere inside `SignOut()` leaves the server in exactly the reported state:
+
+- The transaction rolls back. `Character.IsOnline` is the `characters.inuse` column
+  (`Character.cs:195`), so the `inuse = 0` written by `DeselectCharacter` is undone and the character
+  stays online.
+- `Session.cs:308` is never reached, so `SessionManager.Remove` never runs, the entry stays in
+  `_sessions`, and the `Player` stays in the zone tick.
+- `LogExceptions` (`TaskExtensions.cs:9`) logs the exception and swallows it. Nothing else reports it.
+
+A second variant needs no rollback at all: `Disconnected` is a plain multicast invoke with no
+per-subscriber guard, so if `OnSessionDisconnected` throws, `Remove` — subscribed after it — never runs.
+
+This also fits the report saying *sometimes* rather than *always*: `SignIn` runs
+`update characters set inuse=0 where accountid=@id` (`Session.cs:209`), so a ghost clears itself the
+next time that player signs in.
+
+**What is not established is what throws.** The remaining candidates are the three `Character` database
+writes in `DeselectCharacter` and the `ThrowIfNull(AccountNotFound)` against the account repository.
+That cannot be derived from the code and needs a live server log.
+
+**The log settles it cheaply, because the teardown leaves a marker.** `[Relay] client disconnected.`
+(`SessionManager.cs:99`) is written by a `Disconnected` subscriber, so it can only appear after
+`Session.cs:308` has run. A normal disconnect logs it; a ghost produced by this path logs an exception
+and no such line. `Character deselected /M\` (`Session.cs:289`) is the same kind of marker, since it
+runs from the transaction's commit callback.
 
 ### Impact
 - Players appear online when they are not. This is visible to everyone and misinforms corporation
@@ -49,27 +84,60 @@ fixes, and the evidence to tell them apart has not been gathered.
 - Anything gated on online state acts on stale information for the lifetime of the ghost.
 
 ### Proposed Fix
-1. Establish which case is actually being reported — graceful logout or ungraceful disconnect — before
-   changing anything. A session that survives a clean logout is a different defect from one that
-   survives a dropped connection.
-2. If graceful logouts are affected, audit the session teardown path end to end: the client's logout
-   command, `SessionManager` removal, `Character.IsOnline`, and the removal of the `Player` from the
-   zone. A teardown that is skipped or that fails partway would leave exactly this state.
-3. If only ungraceful disconnects are affected, implement the application-level idle timeout that
-   [[ISSUE-038]] deferred, using the `InactiveTime` that `ZoneSession` already tracks. This does not
-   depend on OS keepalive behaviour, which NATs and firewalls can interfere with.
-4. Cover the teardown at the unit tier with a fake session, and the surviving-state question at the
-   integration tier.
+1. **Ask for a live server log before changing anything.** In a window where a ghost was reported, look
+   for a logged exception with no matching `[Relay] client disconnected.` line. That confirms or kills
+   the mechanism above at zero cost, and it decides what the fix has to be.
+2. **DONE 2026-08-17.** The teardown no longer depends on `SignOut()` succeeding.
+   `Session.OnDisconnected` raises `Disconnected` from a `finally`, so the session leaves `_sessions`
+   either way, and `SessionManager.OnSessionDisconnected` contains its own failure so it cannot cancel
+   the `Remove` subscribed after it. The exception is still allowed to leave `Session.OnDisconnected`,
+   because what throws is step 1's question and swallowing it would make that question harder to
+   answer. **This closes the leak, not the visible symptom** — see the half still open below.
+3. **Half done 2026-08-17.** The idle timeout is not implemented, because its threshold cannot be
+   chosen here: the client's zero-length keepalive packets arrive as data, but their interval is a
+   client decision and a threshold set below it disconnects players who are still connected. What
+   shipped is the measurement — `ConnectionActivity` records when data last arrived and the widest gap
+   between two receives, `TcpConnection` touches it on every receive, and both numbers are logged when
+   a connection closes. **Read those numbers off a live server, then set the threshold and enable the
+   disconnect.** Note the timeout belongs on the relay connection rather than on `ZoneSession`, whose
+   `InactiveTime` only covers players who are in a zone.
+4. Cover the teardown at the unit tier with a fake session — a `SignOut()` that throws must still leave
+   the session removed and the character offline — and the surviving-state question at the integration
+   tier. **Not done, and it needs a decision first:** `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. The step 2 change is covered by
+   inspection only. `ConnectionActivity` was built as a separate unit precisely so the part that could
+   be tested, was — eleven tests, written first and observed failing.
+
+### The half still open
+
+Step 2 stops the session leaking and stops the `Player` being ticked forever, but it does **not** put
+the character offline when the transaction rolls back. `Character.IsOnline` is a database write
+(`Character.cs:195`), so a rolled-back `SignOut()` leaves `characters.inuse = 1` and the player still
+shows as online until they next sign in. Fixing that means a compensating write outside the failed
+transaction, in a catch path — a design decision with its own risks, and one that should not be made
+while the thing being compensated for is still unnamed. It waits on step 1.
 
 ### Notes
-- Priority is a judgement made when filing; the report did not assign one. MEDIUM rather than higher
-  because a partial mitigation already shipped. **Raise it if the graceful-logout path turns out to be
-  the cause**, since that would mean an ordinary logout can leave a ghost.
+- Priority is a judgement made when filing; the report did not assign one. Held at MEDIUM because a
+  partial mitigation already shipped and because the mechanism found on 2026-08-17 is so far a reading
+  of the code, not an observation of the live server. **Raise it as soon as a log confirms that
+  mechanism**, since it would mean an ordinary logout can leave a ghost. Status stays TODO rather than
+  BLOCKED: only step 1 waits on the maintainers, and step 3 can proceed without them.
 - Filed separately from [[ISSUE-038]] rather than folded into it: that issue is about memory growth and
   would close on a memory measurement, while the visible-online symptom is what players actually
   report and needs to survive that issue closing.
 - Named alongside [[ISSUE-040]] as a known trouble area to investigate, fix and cover by tests.
-- Every line number above was checked against `4e6d697` and is anchored to it. Line numbers drift.
+- Found while tracing the above and unrelated to the symptom, so recorded here rather than filed on its
+  own: the `.ThrowIfZero(ErrorCodes.SQLExecutionError)` guards on `accountonlinetimestart` and
+  `accountonlinetimestop` (`Session.cs:218` and `Session.cs:263`) can never fire. Both procedures begin
+  with `SET NOCOUNT ON`, so `ExecuteNonQuery()` returns `-1` rather than a row count, and `ThrowIfZero`
+  compares against `0` (`Guard.cs:12`). It was ruled out as the trigger for this issue for that reason.
+  Worth a maintainer's decision rather than an unprompted fix, since making the guard live would turn a
+  currently silent no-op into a thrown exception.
+- Every line number above was checked against `1e68c4a` and is anchored to it. The files cited are
+  byte-identical between `4e6d697` and `1e68c4a`, so the earlier anchors still resolve. Line numbers
+  drift.
 
 ---
 

src/Perpetuum.Tests/Unit/ConnectionActivityTests.cs

@@ -0,0 +1,123 @@
+using System;
+using Perpetuum.Network;
+using Xunit;
+
+namespace Perpetuum.Tests.Unit
+{
+    // ConnectionActivity is the measurement half of ISSUE-041. It answers two questions about a
+    // connection: how long it has been silent, and what the longest silence was over its lifetime.
+    // The second is the one that matters first — the client sends zero-length keepalive packets and
+    // nobody here knows their interval, so an idle timeout cannot be given a threshold until the
+    // real interval has been observed on a live server.
+    //
+    // Every test injects "now" rather than sleeping. A test that sleeps to observe a timeout is
+    // slow and flaky, and this type exists precisely so that the time-dependent decision is
+    // separable from the socket.
+    public class ConnectionActivityTests
+    {
+        private static readonly DateTime T0 = new DateTime(2026, 8, 17, 12, 0, 0, DateTimeKind.Utc);
+
+        [Fact]
+        public void A_new_connection_has_not_been_silent()
+        {
+            ConnectionActivity activity = new ConnectionActivity(T0);
+
+            Assert.Equal(TimeSpan.Zero, activity.SilentFor(T0));
+        }
+
+        [Fact]
+        public void Silence_is_measured_from_the_last_received_data()
+        {
+            ConnectionActivity activity = new ConnectionActivity(T0);
+
+            Assert.Equal(TimeSpan.FromSeconds(30), activity.SilentFor(T0.AddSeconds(30)));
+        }
+
+        [Fact]
+        public void Receiving_data_resets_the_silence()
+        {
+            ConnectionActivity activity = new ConnectionActivity(T0);
+
+            activity.Touch(T0.AddSeconds(25));
+
+            Assert.Equal(TimeSpan.FromSeconds(5), activity.SilentFor(T0.AddSeconds(30)));
+        }
+
+        [Fact]
+        public void A_connection_that_never_received_anything_reports_no_longest_gap()
+        {
+            ConnectionActivity activity = new ConnectionActivity(T0);
+
+            Assert.Equal(TimeSpan.Zero, activity.LongestGap);
+        }
+
+        [Fact]
+        public void The_longest_gap_is_the_widest_interval_between_two_receives()
+        {
+            ConnectionActivity activity = new ConnectionActivity(T0);
+
+            activity.Touch(T0.AddSeconds(10));
+            activity.Touch(T0.AddSeconds(55));
+            activity.Touch(T0.AddSeconds(60));
+
+            Assert.Equal(TimeSpan.FromSeconds(45), activity.LongestGap);
+        }
+
+        [Fact]
+        public void The_longest_gap_survives_shorter_gaps_that_follow_it()
+        {
+            ConnectionActivity activity = new ConnectionActivity(T0);
+
+            activity.Touch(T0.AddSeconds(40));
+            activity.Touch(T0.AddSeconds(41));
+            activity.Touch(T0.AddSeconds(42));
+
+            Assert.Equal(TimeSpan.FromSeconds(40), activity.LongestGap);
+        }
+
+        // The gap that is still open is deliberately not counted. A connection that dropped an hour
+        // ago would otherwise report a one-hour keepalive interval and poison the measurement this
+        // type exists to collect.
+        [Fact]
+        public void The_gap_still_in_progress_does_not_count_towards_the_longest()
+        {
+            ConnectionActivity activity = new ConnectionActivity(T0);
+
+            activity.Touch(T0.AddSeconds(5));
+            _ = activity.SilentFor(T0.AddHours(2));
+
+            Assert.Equal(TimeSpan.FromSeconds(5), activity.LongestGap);
+        }
+
+        [Theory]
+        [InlineData(29, 30, false)]
+        [InlineData(30, 30, true)]
+        [InlineData(31, 30, true)]
+        public void Silence_is_reported_against_a_threshold(int silentSeconds, int thresholdSeconds, bool expected)
+        {
+            ConnectionActivity activity = new ConnectionActivity(T0);
+
+            bool actual = activity.IsSilentForLongerThan(
+                TimeSpan.FromSeconds(thresholdSeconds),
+                T0.AddSeconds(silentSeconds));
+
+            Assert.Equal(expected, actual);
+        }
+
+        // Touches arrive on socket IO threads while a sweep would read from another. This does not
+        // prove thread safety — no test does — but a lost update under contention shows up here.
+        [Fact]
+        public void Concurrent_receives_do_not_lose_the_longest_gap()
+        {
+            ConnectionActivity activity = new ConnectionActivity(T0);
+
+            System.Threading.Tasks.Parallel.For(0, 1000, i =>
+            {
+                activity.Touch(T0.AddSeconds(i + 1));
+                _ = activity.LongestGap;
+            });
+
+            Assert.True(activity.LongestGap > TimeSpan.Zero);
+        }
+    }
+}

src/Perpetuum/Network/ConnectionActivity.cs

@@ -0,0 +1,74 @@
+using System;
+using System.Threading;
+
+namespace Perpetuum.Network
+{
+    /// <summary>
+    /// Tracks when a connection last received data from its peer.
+    /// </summary>
+    /// <remarks>
+    /// The OS keepalive set in <see cref="TcpConnection"/> is a two hour backstop, so a peer that
+    /// disappears without closing cleanly stays connected from this side for that long. The client
+    /// sends zero-length keepalive packets of its own, which arrive as data and are far more timely,
+    /// but nothing recorded when they last arrived.
+    ///
+    /// This type records it. <see cref="LongestGap"/> is the measurement that has to come first: no
+    /// idle timeout can be given a threshold until the client's real keepalive interval has been
+    /// observed on a live server, and guessing it low disconnects players who are still there.
+    ///
+    /// "now" is passed in rather than read here so the decision is testable without sleeping.
+    /// </remarks>
+    public sealed class ConnectionActivity
+    {
+        private long _lastReceivedTicks;
+        private long _longestGapTicks;
+
+        public ConnectionActivity(DateTime now)
+        {
+            _lastReceivedTicks = now.Ticks;
+        }
+
+        /// <summary>
+        /// The widest interval between two receives seen so far. A gap that is still open does not
+        /// count — a connection whose peer vanished an hour ago would otherwise report a one hour
+        /// keepalive interval and poison the measurement.
+        /// </summary>
+        public TimeSpan LongestGap => TimeSpan.FromTicks(Interlocked.Read(ref _longestGapTicks));
+
+        /// <summary>
+        /// Records that data arrived. Receives are serialised per connection by the
+        /// BeginReceive/EndReceive chain, so this is only contended against readers.
+        /// </summary>
+        public void Touch(DateTime now)
+        {
+            long previous = Interlocked.Exchange(ref _lastReceivedTicks, now.Ticks);
+            long gap = now.Ticks - previous;
+
+            // Non-positive means the clock moved backwards or two touches raced. Neither is a gap.
+            if (gap <= 0)
+                return;
+
+            long widest = Interlocked.Read(ref _longestGapTicks);
+            while (gap > widest)
+            {
+                long actual = Interlocked.CompareExchange(ref _longestGapTicks, gap, widest);
+                if (actual == widest)
+                    return;
+
+                widest = actual;
+            }
+        }
+
+        public TimeSpan SilentFor(DateTime now)
+        {
+            long silent = now.Ticks - Interlocked.Read(ref _lastReceivedTicks);
+
+            return silent <= 0 ? TimeSpan.Zero : TimeSpan.FromTicks(silent);
+        }
+
+        public bool IsSilentForLongerThan(TimeSpan threshold, DateTime now)
+        {
+            return SilentFor(now) >= threshold;
+        }
+    }
+}

src/Perpetuum/Network/TcpConnection.cs

@@ -23,6 +23,8 @@ public class TcpConnection : Disposable, ITcpConnection
 
         private long _isDisconnected;
 
+        private readonly ConnectionActivity _activity;
+
         public TcpConnection(Socket socket)
         {
             _socket = socket;
@@ -31,9 +33,17 @@ public TcpConnection(Socket socket)
             _socket.SendBufferSize = SEND_BUFFER_SIZE;
             _socket.SetKeepAlive(true, 1000 * 60 * 60 * 2, 5000);
 
+            _activity = new ConnectionActivity(DateTime.Now);
+
             RemoteEndPoint = (IPEndPoint)_socket.RemoteEndPoint;
         }
 
+        /// <summary>
+        /// How long this connection has been receiving nothing, and the widest such gap so far.
+        /// Reported only; nothing disconnects on it yet. See <see cref="ConnectionActivity"/>.
+        /// </summary>
+        public ConnectionActivity Activity => _activity;
+
         protected override void Dispose(bool disposing)
         {
             if (!disposing)
@@ -65,6 +75,12 @@ public void Disconnect()
 
             //Console.Beep(100, 200);
 
+            // Reported so the client's real keepalive interval can be read off a live server. An
+            // idle timeout cannot be given a threshold before that number is known.
+            Logger.Info(
+                $"connection closed. {RemoteEndPoint} silent for {_activity.SilentFor(DateTime.Now).TotalSeconds:F1}s, " +
+                $"longest gap {_activity.LongestGap.TotalSeconds:F1}s");
+
             Task.Run(OnDisconnected).ContinueWith(t => Dispose()).LogExceptions();
         }
 
@@ -131,6 +147,10 @@ private void ReceiveCallback(IAsyncResult ar)
                     return;
                 }
 
+                // Every byte counts here, including the client's zero-length keepalive packets:
+                // they still carry their four length bytes, so they land as received data.
+                _activity.Touch(DateTime.Now);
+
                 OnProcessReceivedRawData(_buffer, available);
 
                 int index = 0;