diff --git a/docs/backlog/issues.md b/docs/backlog/issues.md index bc743ddb..83be191e 100644 --- a/docs/backlog/issues.md +++ b/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. --- diff --git a/src/Perpetuum.Tests/Unit/ConnectionActivityTests.cs b/src/Perpetuum.Tests/Unit/ConnectionActivityTests.cs new file mode 100644 index 00000000..18ebb138 --- /dev/null +++ b/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); + } + } +} diff --git a/src/Perpetuum/Network/ConnectionActivity.cs b/src/Perpetuum/Network/ConnectionActivity.cs new file mode 100644 index 00000000..6666522d --- /dev/null +++ b/src/Perpetuum/Network/ConnectionActivity.cs @@ -0,0 +1,74 @@ +using System; +using System.Threading; + +namespace Perpetuum.Network +{ + /// + /// Tracks when a connection last received data from its peer. + /// + /// + /// The OS keepalive set in 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. 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. + /// + public sealed class ConnectionActivity + { + private long _lastReceivedTicks; + private long _longestGapTicks; + + public ConnectionActivity(DateTime now) + { + _lastReceivedTicks = now.Ticks; + } + + /// + /// 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. + /// + public TimeSpan LongestGap => TimeSpan.FromTicks(Interlocked.Read(ref _longestGapTicks)); + + /// + /// Records that data arrived. Receives are serialised per connection by the + /// BeginReceive/EndReceive chain, so this is only contended against readers. + /// + 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; + } + } +} diff --git a/src/Perpetuum/Network/TcpConnection.cs b/src/Perpetuum/Network/TcpConnection.cs index be270278..8eca9e4b 100644 --- a/src/Perpetuum/Network/TcpConnection.cs +++ b/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; } + /// + /// How long this connection has been receiving nothing, and the widest such gap so far. + /// Reported only; nothing disconnects on it yet. See . + /// + 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; diff --git a/src/Perpetuum/Services/Sessions/Session.cs b/src/Perpetuum/Services/Sessions/Session.cs index 3c5f4eaf..b7375e2a 100644 --- a/src/Perpetuum/Services/Sessions/Session.cs +++ b/src/Perpetuum/Services/Sessions/Session.cs @@ -299,13 +299,23 @@ private void OnCharacterDeselected(Character character) private void OnDisconnected(ITcpConnection connection) { - using (var scope = Db.CreateTransaction()) + // The event has to be raised even when signing out fails. SessionManager removes the + // session from its dictionary through this event, so leaving it on the success path + // means a throwing SignOut leaks the session, keeps the character shown as online and + // keeps its Player in the zone tick — the ISSUE-041 symptom. The exception is still + // allowed to leave, and TcpConnection logs it. + try { - SignOut(); - scope.Complete(); + using (var scope = Db.CreateTransaction()) + { + SignOut(); + scope.Complete(); + } + } + finally + { + Disconnected?.Invoke(this); } - - Disconnected?.Invoke(this); } private void OnRsaKeyReceived() diff --git a/src/Perpetuum/Services/Sessions/SessionManager.cs b/src/Perpetuum/Services/Sessions/SessionManager.cs index fcc0a75c..cf11be5d 100644 --- a/src/Perpetuum/Services/Sessions/SessionManager.cs +++ b/src/Perpetuum/Services/Sessions/SessionManager.cs @@ -98,10 +98,23 @@ private static void OnSessionDisconnected(ISession session) { Logger.Info($"[Relay] client disconnected. {session.RemoteEndPoint}"); - using (var scope = Db.CreateTransaction()) + // This handler is subscribed to Disconnected before Remove is, and a multicast delegate + // stops at the first subscriber that throws. Letting an exception out of here would + // therefore cancel the removal and leak the session, so it is contained rather than + // propagated. Signing out twice is already expected: Session.OnDisconnected has done it + // once, and SignOut returns early once AccountId has been cleared. + try { - session.SignOut(); - scope.Complete(); + using (var scope = Db.CreateTransaction()) + { + session.SignOut(); + scope.Complete(); + } + } + catch (Exception ex) + { + Logger.Error($"[Relay] sign out failed on disconnect for {session.RemoteEndPoint}. The session is still removed."); + Logger.Exception(ex); } }