From 6fa5a1262b10cca9edb089dd735f21aae9b45ae6 Mon Sep 17 00:00:00 2001 From: Meketreve <34199654+meketreve@users.noreply.github.com> Date: Wed, 19 Aug 2026 16:01:14 -0300 Subject: [PATCH 1/4] 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 --- .../Unit/SessionDiagnosticsTests.cs | 80 +++++++++++++++++++ .../Unit/StaleOnlineFlagsTests.cs | 60 ++++++++++++++ .../Services/Sessions/SessionDiagnostics.cs | 65 +++++++++++++++ .../Services/Sessions/StaleOnlineFlags.cs | 38 +++++++++ 4 files changed, 243 insertions(+) create mode 100644 src/Perpetuum.Tests/Unit/SessionDiagnosticsTests.cs create mode 100644 src/Perpetuum.Tests/Unit/StaleOnlineFlagsTests.cs create mode 100644 src/Perpetuum/Services/Sessions/SessionDiagnostics.cs create mode 100644 src/Perpetuum/Services/Sessions/StaleOnlineFlags.cs diff --git a/src/Perpetuum.Tests/Unit/SessionDiagnosticsTests.cs b/src/Perpetuum.Tests/Unit/SessionDiagnosticsTests.cs new file mode 100644 index 0000000..8026bfc --- /dev/null +++ b/src/Perpetuum.Tests/Unit/SessionDiagnosticsTests.cs @@ -0,0 +1,80 @@ +using System.Net; +using Perpetuum.Services.Sessions; +using Xunit; + +namespace Perpetuum.Tests.Unit +{ + public class SessionDiagnosticsTests + { + private static readonly IPEndPoint Remote = new(IPAddress.Loopback, 4321); + + [Fact] + public void A_stale_login_that_still_holds_a_session_reports_how_long_it_has_been_silent() + { + SessionID sessionId = SessionID.New(); + + string line = SessionDiagnostics.DescribeStaleLogin( + accountId: 7, + sessionId: sessionId, + remoteEndPoint: Remote, + silentFor: TimeSpan.FromSeconds(93), + longestGap: TimeSpan.FromSeconds(12)); + + // The silence is the discriminator. A session still held by the server means the peer + // vanished without closing and nothing here noticed, which is the missing idle timeout + // rather than a rolled back sign out. + Assert.Contains("live session", line); + Assert.Contains("accountId:7", line); + Assert.Contains($"sessionId:{sessionId}", line); + Assert.Contains("silentFor:93.0s", line); + Assert.Contains("longestGap:12.0s", line); + Assert.Contains(Remote.ToString(), line); + } + + [Fact] + public void A_stale_login_with_no_session_left_is_reported_as_a_flag_nobody_cleared() + { + string line = SessionDiagnostics.DescribeStaleLogin(accountId: 7); + + // The other half of the discriminator: the session is gone but the account row still + // says logged in, which is what a sign out that rolled back leaves behind. + Assert.Contains("no live session", line); + Assert.Contains("accountId:7", line); + Assert.DoesNotContain("silentFor", line); + } + + [Fact] + public void A_closing_session_is_reported_with_everything_needed_to_stitch_the_other_lines() + { + SessionID sessionId = SessionID.New(); + + string line = SessionDiagnostics.DescribeClosing( + sessionId: sessionId, + accountId: 7, + characterId: 55, + remoteEndPoint: Remote, + silentFor: TimeSpan.FromSeconds(4), + longestGap: TimeSpan.FromSeconds(2.5)); + + // TcpConnection and SessionManager both log the same disconnect with only the endpoint + // to identify it. This line is the one that carries the identity, so it has to be + // written before sign out clears AccountId and Character. + Assert.Contains($"sessionId:{sessionId}", line); + Assert.Contains("accountId:7", line); + Assert.Contains("characterId:55", line); + Assert.Contains(Remote.ToString(), line); + Assert.Contains("silentFor:4.0s", line); + Assert.Contains("longestGap:2.5s", line); + } + + [Fact] + public void A_census_reports_the_flags_that_have_nobody_connected_behind_them() + { + string line = SessionDiagnostics.DescribeCensus(orphaned: 3, flagged: 40, liveSessions: 37); + + Assert.Contains("3", line); + Assert.Contains("40", line); + Assert.Contains("37", line); + } + } +} diff --git a/src/Perpetuum.Tests/Unit/StaleOnlineFlagsTests.cs b/src/Perpetuum.Tests/Unit/StaleOnlineFlagsTests.cs new file mode 100644 index 0000000..43c3936 --- /dev/null +++ b/src/Perpetuum.Tests/Unit/StaleOnlineFlagsTests.cs @@ -0,0 +1,60 @@ +using Perpetuum.Services.Sessions; +using Perpetuum.Tests.Fakes.Data; +using Perpetuum.Tests.Infrastructure; +using Xunit; + +namespace Perpetuum.Tests.Unit +{ + [Collection(PerpetuumStaticsCollection.Name)] + public class StaleOnlineFlagsTests + { + private readonly PerpetuumStaticsFixture _fixture; + private readonly FakeDb _db; + + public StaleOnlineFlagsTests(PerpetuumStaticsFixture fixture) + { + _fixture = fixture; + _fixture.Logger.Clear(); + _db = FakeDb.Install(); + } + + [Fact] + public void Clearing_stale_flags_reports_how_many_it_cleared() + { + _db.WhenNonQuery("update characters set inuse=0", 2); + + int cleared = StaleOnlineFlags.ClearForAccount(7); + + Assert.Equal(2, cleared); + Assert.Contains(_fixture.Logger.Events, e => e.Message.Contains("2") && e.Message.Contains("accountId:7")); + } + + [Fact] + public void Clearing_stale_flags_says_nothing_when_none_were_set() + { + _db.WhenNonQuery("update characters set inuse=0", 0); + + int cleared = StaleOnlineFlags.ClearForAccount(7); + + Assert.Equal(0, cleared); + Assert.DoesNotContain(_fixture.Logger.Events, e => e.Message.Contains("accountId:7")); + } + + [Fact] + public void Clearing_stale_flags_only_matches_rows_that_are_actually_set() + { + // The count is the whole point of this type, and it is only a ghost count if the + // statement matches the rows it changes. "where accountid=@id" alone matches every + // character on the account, so it would report the account's character count on every + // single sign in. The extra predicate makes the number mean what it says. + _db.WhenNonQuery("update characters set inuse=0", 1); + + _ = StaleOnlineFlags.ClearForAccount(7); + + RecordedCommand? command = _db.LastCommandMatching("update characters set inuse=0"); + Assert.NotNull(command); + Assert.Contains("inuse=1", command.CommandText); + Assert.Equal(7, command.Parameters["@id"]); + } + } +} diff --git a/src/Perpetuum/Services/Sessions/SessionDiagnostics.cs b/src/Perpetuum/Services/Sessions/SessionDiagnostics.cs new file mode 100644 index 0000000..ca7671c --- /dev/null +++ b/src/Perpetuum/Services/Sessions/SessionDiagnostics.cs @@ -0,0 +1,65 @@ +using System; +using System.Globalization; +using System.Net; + +namespace Perpetuum.Services.Sessions +{ + /// + /// Composes the session lifecycle log lines in one place, so the words and the units stay the + /// same wherever they are written from and a live log can be read without guessing. + /// + /// + /// Two tags are used deliberately. [Session] marks the ordinary lifecycle, [Ghost] + /// marks a character left flagged online with nobody behind it. Grepping one does not drag in + /// the other. + /// + /// This type exists as much for testability as for tidiness: builds its + /// connection from a raw socket in its constructor and cannot be reached at the unit tier, so + /// anything it logs is proved by inspection unless the wording lives somewhere else. + /// + public static class SessionDiagnostics + { + /// + /// A sign in found the account already marked as logged in, and the server is still holding + /// its session. The peer went away without closing and nothing noticed — the missing idle + /// timeout rather than a sign out that failed. + /// + public static string DescribeStaleLogin(int accountId, SessionID sessionId, IPEndPoint remoteEndPoint, TimeSpan silentFor, TimeSpan longestGap) + { + return $"[Ghost] stale login: live session still held. accountId:{accountId} sessionId:{sessionId} " + + $"remote:{remoteEndPoint} silentFor:{Seconds(silentFor)} longestGap:{Seconds(longestGap)}"; + } + + /// + /// A sign in found the account already marked as logged in and there was no session behind + /// it. The flag outlived the session, which is what a sign out that rolled back leaves. + /// + public static string DescribeStaleLogin(int accountId) + { + return $"[Ghost] stale login: no live session, the account flag was left set. accountId:{accountId}"; + } + + /// + /// A session is closing. Written before sign out runs, because sign out clears the account + /// and character on commit and every later line then has only the endpoint to identify it. + /// + public static string DescribeClosing(SessionID sessionId, int accountId, int characterId, IPEndPoint remoteEndPoint, TimeSpan silentFor, TimeSpan longestGap) + { + return $"[Session] closing. sessionId:{sessionId} accountId:{accountId} characterId:{characterId} " + + $"remote:{remoteEndPoint} silentFor:{Seconds(silentFor)} longestGap:{Seconds(longestGap)}"; + } + + /// + /// How many characters are flagged online with no session behind them, sampled periodically. + /// + public static string DescribeCensus(int orphaned, int flagged, int liveSessions) + { + return $"[Ghost] census: {orphaned} of {flagged} online flag(s) have no live session. liveSessions:{liveSessions}"; + } + + private static string Seconds(TimeSpan value) + { + return value.TotalSeconds.ToString("F1", CultureInfo.InvariantCulture) + "s"; + } + } +} diff --git a/src/Perpetuum/Services/Sessions/StaleOnlineFlags.cs b/src/Perpetuum/Services/Sessions/StaleOnlineFlags.cs new file mode 100644 index 0000000..4f74ac5 --- /dev/null +++ b/src/Perpetuum/Services/Sessions/StaleOnlineFlags.cs @@ -0,0 +1,38 @@ +using Perpetuum.Data; +using Perpetuum.Log; + +namespace Perpetuum.Services.Sessions +{ + /// + /// Clears the online flag an account's characters may have been left carrying, and reports how + /// many there were. + /// + /// + /// Sign in has always run this statement defensively, because a sign out that rolls back leaves + /// characters.inuse = 1 behind and the next sign in is what heals it. Running it blind + /// meant the healing was invisible: nothing recorded that a ghost had been found, so there was + /// no way to tell how often it happens or whether it happens at all. + /// + /// The and inuse=1 predicate is what makes the count mean something. Without it the + /// statement matches every character on the account and reports that number on every sign in, + /// whether anything was stale or not. With it, the rows affected are exactly the stale flags, + /// and the effect on the data is identical — setting a column to the value it already holds + /// changes nothing. + /// + public static class StaleOnlineFlags + { + public static int ClearForAccount(int accountId) + { + int cleared = Db.Query().CommandText("update characters set inuse=0 where accountid=@id and inuse=1") + .SetParameter("@id", accountId) + .ExecuteNonQuery(); + + if (cleared > 0) + { + Logger.Info($"[Ghost] sign in cleared {cleared} stale online flag(s). accountId:{accountId}"); + } + + return cleared; + } + } +} From 4317051b7c3d000a5ca7983915042a1481c642eb Mon Sep 17 00:00:00 2001 From: Meketreve <34199654+meketreve@users.noreply.github.com> Date: Wed, 19 Aug 2026 16:01:30 -0300 Subject: [PATCH 2/4] 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 --- .../SignInRequestHandler.cs | 18 +++- .../Fakes/Sessions/FakeAccountRepository.cs | 31 +++++++ .../Fakes/Sessions/FakeRelayServices.cs | 41 +++++++++ .../Fakes/Sessions/FakeSession.cs | 59 +++++++++++++ .../Fakes/Sessions/FakeSessionManager.cs | 35 ++++++++ src/Perpetuum.Tests/Perpetuum.Tests.csproj | 1 + .../Unit/StaleLoginReportingTests.cs | 83 +++++++++++++++++++ src/Perpetuum/Network/ITcpConnection.cs | 5 ++ src/Perpetuum/Services/Sessions/Session.cs | 31 ++++++- 9 files changed, 299 insertions(+), 5 deletions(-) create mode 100644 src/Perpetuum.Tests/Fakes/Sessions/FakeAccountRepository.cs create mode 100644 src/Perpetuum.Tests/Fakes/Sessions/FakeRelayServices.cs create mode 100644 src/Perpetuum.Tests/Fakes/Sessions/FakeSession.cs create mode 100644 src/Perpetuum.Tests/Fakes/Sessions/FakeSessionManager.cs create mode 100644 src/Perpetuum.Tests/Unit/StaleLoginReportingTests.cs diff --git a/src/Perpetuum.RequestHandlers/SignInRequestHandler.cs b/src/Perpetuum.RequestHandlers/SignInRequestHandler.cs index c28f486..f0ba3a2 100644 --- a/src/Perpetuum.RequestHandlers/SignInRequestHandler.cs +++ b/src/Perpetuum.RequestHandlers/SignInRequestHandler.cs @@ -42,9 +42,23 @@ public void HandleRequest(IRequest request) var isLoggedIn = account.IsLoggedIn; if (isLoggedIn) { - Logger.Info("a logged in account was found, starting disconnect. accountID:" + account.Id); - var session = _sessionManager.GetByAccount(account); + + // This is the only place a ghost announces itself, and the two shapes of it need + // different fixes. A session still held means the peer vanished without closing and + // nothing noticed, which is the missing idle timeout. No session behind the flag + // means the sign out ran and rolled back, leaving the row saying logged in. The one + // line this replaced said "a logged in account was found" for both, so a live log + // could not tell them apart. + Logger.Info(session == null + ? SessionDiagnostics.DescribeStaleLogin(account.Id) + : SessionDiagnostics.DescribeStaleLogin( + account.Id, + session.Id, + session.RemoteEndPoint, + session.Activity.SilentFor(DateTime.Now), + session.Activity.LongestGap)); + session?.ForceQuit(ErrorCodes.NoSimultaneousLoginsAllowed); account.IsLoggedIn = false; diff --git a/src/Perpetuum.Tests/Fakes/Sessions/FakeAccountRepository.cs b/src/Perpetuum.Tests/Fakes/Sessions/FakeAccountRepository.cs new file mode 100644 index 0000000..27a769f --- /dev/null +++ b/src/Perpetuum.Tests/Fakes/Sessions/FakeAccountRepository.cs @@ -0,0 +1,31 @@ +using Perpetuum.Accounting; + +namespace Perpetuum.Tests.Fakes.Sessions +{ + /// + /// Holds one account in memory and records the updates written to it. + /// + public sealed class FakeAccountRepository : IAccountRepository + { + private readonly Account _account; + + public FakeAccountRepository(Account account) + { + _account = account; + } + + public int Updates { get; private set; } + + public Account Get(int id) => _account; + + public void Update(Account item) => Updates++; + + public AccessLevel GetAccessLevel(int accountId) => _account.AccessLevel; + public Account Get(int accountId, string steamId) => _account; + public Account Get(string email, string password) => _account; + public IEnumerable GetBySteamId(string steamId) => [_account]; + public IEnumerable GetAll() => [_account]; + public void Insert(Account item) => throw new NotSupportedException(); + public void Delete(Account item) => throw new NotSupportedException(); + } +} diff --git a/src/Perpetuum.Tests/Fakes/Sessions/FakeRelayServices.cs b/src/Perpetuum.Tests/Fakes/Sessions/FakeRelayServices.cs new file mode 100644 index 0000000..ec09d3b --- /dev/null +++ b/src/Perpetuum.Tests/Fakes/Sessions/FakeRelayServices.cs @@ -0,0 +1,41 @@ +using Perpetuum.Host.Requests; +using Perpetuum.Services.Relay; +using Perpetuum.Services.Sessions; + +namespace Perpetuum.Tests.Fakes.Sessions +{ + public sealed class FakeRelayStateService : IRelayStateService + { + public RelayState State { get; set; } = RelayState.OpenForPublic; + + public event Action StateChanged { add { } remove { } } + + public void SendStateToClient(ISession session) => throw new NotSupportedException(); + public void ConfigOnlyAllowAdmins(bool enabled) => throw new NotSupportedException(); + } + + public sealed class FakeLoginQueueService : ILoginQueueService + { + public int Enqueued { get; private set; } + + public void EnqueueAccount(ISession session, int accountID, string hwHash, int language) => Enqueued++; + + public void Start() { } + public void Stop() { } + public void Update(TimeSpan time) { } + } + + public sealed class FakeRequest : IRequest + { + public FakeRequest(ISession session, Dictionary? data = null) + { + Session = session; + Data = data ?? []; + } + + public ISession Session { get; } + public Dictionary Data { get; } + public Command Command => throw new NotSupportedException(); + public string Target => throw new NotSupportedException(); + } +} diff --git a/src/Perpetuum.Tests/Fakes/Sessions/FakeSession.cs b/src/Perpetuum.Tests/Fakes/Sessions/FakeSession.cs new file mode 100644 index 0000000..31b9a19 --- /dev/null +++ b/src/Perpetuum.Tests/Fakes/Sessions/FakeSession.cs @@ -0,0 +1,59 @@ +using System.Net; +using Perpetuum.Accounting.Characters; +using Perpetuum.Host.Requests; +using Perpetuum.Network; +using Perpetuum.Services.Sessions; +using Perpetuum.Zones; + +namespace Perpetuum.Tests.Fakes.Sessions +{ + /// + /// A session that carries an identity and records whether it was forced to quit. Everything a + /// test does not use throws, so a member that starts being used cannot pass silently. + /// + public sealed class FakeSession : ISession + { + public FakeSession(int accountId, ConnectionActivity? activity = null, IPEndPoint? remoteEndPoint = null) + { + AccountId = accountId; + Activity = activity ?? new ConnectionActivity(DateTime.Now); + RemoteEndPoint = remoteEndPoint ?? new IPEndPoint(IPAddress.Loopback, 1024 + accountId); + } + + public SessionID Id { get; } = SessionID.New(); + public int AccountId { get; } + public IPEndPoint RemoteEndPoint { get; } + public ConnectionActivity Activity { get; } + public bool IsAuthenticated => AccountId > 0; + // Deliberately not initialised to Character.None: that property reaches into the entity + // services locator, which a test using this fake has no reason to have installed. + public Character Character { get; set; } + public AccessLevel AccessLevel => AccessLevel.normal; + public bool AccountCreatedInSession { get; set; } + public string ClientVersion { get; set; } = string.Empty; + public int SteamBuild { get; set; } + + public ErrorCodes? ForcedQuitWith { get; private set; } + + public void ForceQuit(ErrorCodes error = ErrorCodes.NoError, string comment = null) + { + ForcedQuitWith = error; + } + + public IZoneManager ZoneMgr => throw new NotSupportedException(); + public void SendMessage(MessageBuilder builder) => throw new NotSupportedException(); + public void SendMessage(IMessage message) => throw new NotSupportedException(); + public IRequest CreateLocalRequest(string data) => throw new NotSupportedException(); + public void HandleLocalRequest(IRequest request) => throw new NotSupportedException(); + public void Start() => throw new NotSupportedException(); + public void SignIn(int accountID, string hwHash, int language) => throw new NotSupportedException(); + public void SignOut() => throw new NotSupportedException(); + public void SelectCharacter(Character character) => throw new NotSupportedException(); + public void DeselectCharacter() => throw new NotSupportedException(); + + public event SessionEventHandler Disconnected { add { } remove { } } + public event SessionEventHandler RsaKeyReceived { add { } remove { } } + public event SessionEventHandler CharacterSelected { add { } remove { } } + public event SessionEventHandler CharacterDeselected { add { } remove { } } + } +} diff --git a/src/Perpetuum.Tests/Fakes/Sessions/FakeSessionManager.cs b/src/Perpetuum.Tests/Fakes/Sessions/FakeSessionManager.cs new file mode 100644 index 0000000..65254b6 --- /dev/null +++ b/src/Perpetuum.Tests/Fakes/Sessions/FakeSessionManager.cs @@ -0,0 +1,35 @@ +using Perpetuum.Accounting; +using Perpetuum.Accounting.Characters; +using Perpetuum.Services.Sessions; + +namespace Perpetuum.Tests.Fakes.Sessions +{ + /// + /// Holds whatever sessions a test put in it. Lookups that no test needs throw rather than + /// returning null, so an unimplemented path cannot be mistaken for an empty one. + /// + public sealed class FakeSessionManager : ISessionManager + { + private readonly List _sessions = []; + + public void Add(ISession session) => _sessions.Add(session); + + public IEnumerable Sessions => _sessions; + + public ISession GetByAccount(Account account) => GetByAccount(account.Id); + + public ISession GetByAccount(int accountId) => _sessions.FirstOrDefault(s => s.AccountId == accountId); + + public int MaxSessions { get; set; } + + public ISession Get(SessionID sessionId) => throw new NotSupportedException(); + public ISession GetByCharacter(Character character) => throw new NotSupportedException(); + public ISession GetByCharacter(int characterid) => throw new NotSupportedException(); + public IEnumerable SelectedCharacters => throw new NotSupportedException(); + public bool Contains(SessionID sessionId) => throw new NotSupportedException(); + public bool IsOnline(Character character) => throw new NotSupportedException(); + + public event SessionEventHandler SessionAdded { add { } remove { } } + public event SessionEventHandler CharacterDeselected { add { } remove { } } + } +} diff --git a/src/Perpetuum.Tests/Perpetuum.Tests.csproj b/src/Perpetuum.Tests/Perpetuum.Tests.csproj index 96019f2..888e45f 100644 --- a/src/Perpetuum.Tests/Perpetuum.Tests.csproj +++ b/src/Perpetuum.Tests/Perpetuum.Tests.csproj @@ -17,6 +17,7 @@ + diff --git a/src/Perpetuum.Tests/Unit/StaleLoginReportingTests.cs b/src/Perpetuum.Tests/Unit/StaleLoginReportingTests.cs new file mode 100644 index 0000000..aa53d08 --- /dev/null +++ b/src/Perpetuum.Tests/Unit/StaleLoginReportingTests.cs @@ -0,0 +1,83 @@ +using Perpetuum.Accounting; +using Perpetuum.Host.Requests; +using Perpetuum.Network; +using Perpetuum.RequestHandlers; +using Perpetuum.Services.Relay; +using Perpetuum.Services.Sessions; +using Perpetuum.Tests.Fakes.Sessions; +using Perpetuum.Tests.Infrastructure; +using Xunit; + +namespace Perpetuum.Tests.Unit +{ + /// + /// Sign in is where a ghost announces itself: the account says it is logged in when nobody + /// asked it to be. Until now the handler logged one line for both shapes of that, and they need + /// different fixes. + /// + [Collection(PerpetuumStaticsCollection.Name)] + public class StaleLoginReportingTests + { + private readonly PerpetuumStaticsFixture _fixture; + private readonly FakeSessionManager _sessions = new(); + + public StaleLoginReportingTests(PerpetuumStaticsFixture fixture) + { + _fixture = fixture; + _fixture.Logger.Clear(); + } + + private sealed class TestSignInHandler(IRelayStateService relayState, ISessionManager sessions, IAccountRepository accounts, ILoginQueueService queue, Account account) + : SignInRequestHandler(relayState, sessions, accounts, queue) + { + protected override Account LoadAccount(IRequest request) => account; + } + + private (TestSignInHandler Handler, FakeSession Connecting) Handler(Account account) + { + FakeSession connecting = new(accountId: 0); + + return (new TestSignInHandler(new FakeRelayStateService(), _sessions, new FakeAccountRepository(account), new FakeLoginQueueService(), account), connecting); + } + + [Fact] + public void A_stale_login_still_holding_its_session_is_reported_with_its_silence() + { + Account account = new() { Id = 7, IsLoggedIn = true }; + ConnectionActivity activity = new(DateTime.Now - TimeSpan.FromSeconds(40)); + FakeSession held = new(accountId: 7, activity); + _sessions.Add(held); + + (TestSignInHandler handler, FakeSession connecting) = Handler(account); + + _ = Assert.Throws(() => handler.HandleRequest(new FakeRequest(connecting))); + + Assert.Contains(_fixture.Logger.Events, e => e.Message.Contains("live session still held") && e.Message.Contains("accountId:7")); + Assert.Equal(ErrorCodes.NoSimultaneousLoginsAllowed, held.ForcedQuitWith); + } + + [Fact] + public void A_stale_login_with_no_session_behind_it_is_reported_as_a_flag_left_set() + { + Account account = new() { Id = 7, IsLoggedIn = true }; + + (TestSignInHandler handler, FakeSession connecting) = Handler(account); + + _ = Assert.Throws(() => handler.HandleRequest(new FakeRequest(connecting))); + + Assert.Contains(_fixture.Logger.Events, e => e.Message.Contains("no live session") && e.Message.Contains("accountId:7")); + } + + [Fact] + public void An_ordinary_login_reports_no_ghost_at_all() + { + Account account = new() { Id = 7, IsLoggedIn = false }; + + (TestSignInHandler handler, FakeSession connecting) = Handler(account); + + handler.HandleRequest(new FakeRequest(connecting)); + + Assert.DoesNotContain(_fixture.Logger.Events, e => e.Message.Contains("[Ghost]")); + } + } +} diff --git a/src/Perpetuum/Network/ITcpConnection.cs b/src/Perpetuum/Network/ITcpConnection.cs index d1e1531..d62c9f9 100644 --- a/src/Perpetuum/Network/ITcpConnection.cs +++ b/src/Perpetuum/Network/ITcpConnection.cs @@ -15,6 +15,11 @@ public interface ITcpConnection IPEndPoint RemoteEndPoint { get; } + /// + /// How long this connection has been receiving nothing, and the widest such gap so far. + /// + ConnectionActivity Activity { get; } + event TcpConnectionEventHandler Disconnected; event TcpConnectionEventHandler Received; } diff --git a/src/Perpetuum/Services/Sessions/Session.cs b/src/Perpetuum/Services/Sessions/Session.cs index b7375e2..865b48a 100644 --- a/src/Perpetuum/Services/Sessions/Session.cs +++ b/src/Perpetuum/Services/Sessions/Session.cs @@ -24,6 +24,13 @@ public interface ISession SessionID Id { get; } int AccountId { get; } IPEndPoint RemoteEndPoint { get; } + + /// + /// Silence measured on this session's connection. Reported at sign in when a stale login + /// finds the session still held: a long silence says the peer went away without closing. + /// + ConnectionActivity Activity { get; } + bool IsAuthenticated { get; } Character Character { get; } AccessLevel AccessLevel { get; } @@ -129,6 +136,8 @@ public IZoneManager ZoneMgr public IPEndPoint RemoteEndPoint => _connection.RemoteEndPoint; + public ConnectionActivity Activity => _connection.Activity; + private TimeSpan OnlineTime => DateTime.Now.Subtract(_sessionStart); public bool IsAuthenticated => AccountId > 0; @@ -206,9 +215,10 @@ public void SignIn(int accountID, string hwHash, int language) { var account = _accountManager.Repository.Get(accountID).ThrowIfNull(ErrorCodes.AccountNotFound); - Db.Query().CommandText("update characters set inuse=0 where accountid=@id") - .SetParameter("@id", account.Id) - .ExecuteNonQuery(); + // Was an unconditional update here. Moved out so the rows it clears can be counted + // and reported: they are exactly the online flags a previous sign out failed to + // clear, and nothing recorded how often that happens. + _ = StaleOnlineFlags.ClearForAccount(account.Id); Db.Query().CommandText("accountonlinetimestart") .SetParameter("@accountId", account.Id) @@ -299,6 +309,21 @@ private void OnCharacterDeselected(Character character) private void OnDisconnected(ITcpConnection connection) { + // Written before sign out rather than after, because sign out clears AccountId and + // Character on commit and every line logged after that has only the endpoint left to + // identify the connection by. Unauthenticated connections are skipped: they carry no + // identity to correlate, and TcpConnection already logs their close. + if (IsAuthenticated) + { + Logger.Info(SessionDiagnostics.DescribeClosing( + Id, + AccountId, + Character.Id, + RemoteEndPoint, + Activity.SilentFor(DateTime.Now), + Activity.LongestGap)); + } + // 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 From 73ce1255acf527f4424f432c4a26d9bf0545ecae Mon Sep 17 00:00:00 2001 From: Meketreve <34199654+meketreve@users.noreply.github.com> Date: Wed, 19 Aug 2026 16:01:43 -0300 Subject: [PATCH 3/4] 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 --- .../PerpetuumBootstrapper.cs | 8 ++ .../Unit/StaleOnlineFlagCensusTests.cs | 83 +++++++++++++++++++ .../Sessions/StaleOnlineFlagCensus.cs | 64 ++++++++++++++ 3 files changed, 155 insertions(+) create mode 100644 src/Perpetuum.Tests/Unit/StaleOnlineFlagCensusTests.cs create mode 100644 src/Perpetuum/Services/Sessions/StaleOnlineFlagCensus.cs diff --git a/src/Perpetuum.Bootstrapper/PerpetuumBootstrapper.cs b/src/Perpetuum.Bootstrapper/PerpetuumBootstrapper.cs index 92432c1..2cf0791 100644 --- a/src/Perpetuum.Bootstrapper/PerpetuumBootstrapper.cs +++ b/src/Perpetuum.Bootstrapper/PerpetuumBootstrapper.cs @@ -415,6 +415,14 @@ private void InitContainer(string gameRoot) _ = _builder.RegisterType().As().SingleInstance(); + // Reports how many characters are flagged online with nobody connected behind them. + // Five minutes because it is a trend, not an alarm: the number is read off a log after + // the fact, and a shorter period would only add lines. + _ = _builder.RegisterType().AutoActivate().OnActivated(e => + { + e.Context.Resolve().AddProcess(e.Instance.ToAsync().AsTimed(TimeSpan.FromMinutes(5))); + }).SingleInstance(); + InitRelayManager(); _ = _builder.RegisterType().SingleInstance(); diff --git a/src/Perpetuum.Tests/Unit/StaleOnlineFlagCensusTests.cs b/src/Perpetuum.Tests/Unit/StaleOnlineFlagCensusTests.cs new file mode 100644 index 0000000..8d1f701 --- /dev/null +++ b/src/Perpetuum.Tests/Unit/StaleOnlineFlagCensusTests.cs @@ -0,0 +1,83 @@ +using Perpetuum.Services.Sessions; +using Perpetuum.Tests.Fakes.Data; +using Perpetuum.Tests.Fakes.Sessions; +using Perpetuum.Tests.Infrastructure; +using Xunit; + +namespace Perpetuum.Tests.Unit +{ + [Collection(PerpetuumStaticsCollection.Name)] + public class StaleOnlineFlagCensusTests + { + private const string FlaggedCharactersQuery = "select accountid from characters where inuse=1"; + + private readonly PerpetuumStaticsFixture _fixture; + private readonly FakeDb _db; + private readonly FakeSessionManager _sessions = new(); + + public StaleOnlineFlagCensusTests(PerpetuumStaticsFixture fixture) + { + _fixture = fixture; + _fixture.Logger.Clear(); + _db = FakeDb.Install(); + } + + [Fact] + public void A_flag_whose_account_has_no_session_is_counted_as_orphaned() + { + _db.When(FlaggedCharactersQuery, FakeResultSet.FromRows(["accountid"], [7], [8], [9])); + _sessions.Add(new FakeSession(accountId: 7)); + + new StaleOnlineFlagCensus(_sessions).Update(TimeSpan.FromMinutes(5)); + + Assert.Contains(_fixture.Logger.Events, e => e.Message.Contains("2 of 3")); + } + + [Fact] + public void Nothing_is_orphaned_while_every_flag_has_a_session_behind_it() + { + _db.When(FlaggedCharactersQuery, FakeResultSet.FromRows(["accountid"], [7], [8])); + _sessions.Add(new FakeSession(accountId: 7)); + _sessions.Add(new FakeSession(accountId: 8)); + + new StaleOnlineFlagCensus(_sessions).Update(TimeSpan.FromMinutes(5)); + + Assert.Contains(_fixture.Logger.Events, e => e.Message.Contains("0 of 2")); + } + + [Fact] + public void The_census_reports_every_cycle_so_a_quiet_server_is_told_apart_from_a_dead_census() + { + _db.When(FlaggedCharactersQuery, FakeResultSet.Empty("accountid")); + + new StaleOnlineFlagCensus(_sessions).Update(TimeSpan.FromMinutes(5)); + + Assert.Contains(_fixture.Logger.Events, e => e.Message.Contains("[Ghost] census")); + } + + [Fact] + public void The_census_takes_a_reading_as_soon_as_it_starts() + { + // The timer fires a full interval after start, so without this the first number would + // arrive five minutes into the run. A reading at start is also the most interesting one + // there is: nobody is connected yet, so every flag still set was left by the last run. + _db.When(FlaggedCharactersQuery, FakeResultSet.FromRows(["accountid"], [8], [9])); + + new StaleOnlineFlagCensus(_sessions).Start(); + + Assert.Contains(_fixture.Logger.Events, e => e.Message.Contains("2 of 2")); + } + + [Fact] + public void Two_flags_on_one_account_with_no_session_are_both_counted() + { + // One account can hold several characters, and a rolled back sign out leaves the flag on + // whichever one was selected. Counting accounts rather than rows would undercount. + _db.When(FlaggedCharactersQuery, FakeResultSet.FromRows(["accountid"], [8], [8])); + + new StaleOnlineFlagCensus(_sessions).Update(TimeSpan.FromMinutes(5)); + + Assert.Contains(_fixture.Logger.Events, e => e.Message.Contains("2 of 2")); + } + } +} diff --git a/src/Perpetuum/Services/Sessions/StaleOnlineFlagCensus.cs b/src/Perpetuum/Services/Sessions/StaleOnlineFlagCensus.cs new file mode 100644 index 0000000..3d1c1ec --- /dev/null +++ b/src/Perpetuum/Services/Sessions/StaleOnlineFlagCensus.cs @@ -0,0 +1,64 @@ +using System; +using System.Collections.Generic; +using System.Data; +using System.Linq; +using Perpetuum.Data; +using Perpetuum.Log; +using Perpetuum.Threading.Process; + +namespace Perpetuum.Services.Sessions +{ + /// + /// Counts, on a timer, the characters flagged online in the database with no session behind + /// them. Reports only; nothing is cleared here. + /// + /// + /// 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 whether the problem is one player's bad evening or + /// a steady leak — and it is the only one of the two that keeps being true while nobody is + /// signing in. + /// + /// Clearing the flags from here would be wrong. A census that also repaired what it counted + /// would erase the evidence it was added to gather, and doing it on a timer would race the + /// sessions that legitimately hold those flags. + /// + public sealed class StaleOnlineFlagCensus : IProcess + { + private readonly ISessionManager _sessionManager; + + public StaleOnlineFlagCensus(ISessionManager sessionManager) + { + _sessionManager = sessionManager; + } + + /// + /// Takes a reading immediately. The timer only fires an interval after this, and the boot + /// reading is the sharpest one available: no session is connected yet, so every flag still + /// set was left behind by the run before. + /// + public void Start() + { + Report(); + } + + public void Stop() { } + + public void Update(TimeSpan time) + { + Report(); + } + + private void Report() + { + List flagged = Db.Query().CommandText("select accountid from characters where inuse=1").Execute(); + + HashSet liveAccounts = [.. _sessionManager.Sessions.Select(s => s.AccountId)]; + + // Counted per row rather than per account: one account can hold several characters and + // the flag is left on whichever one was selected. + int orphaned = flagged.Count(record => !liveAccounts.Contains(record.GetValue("accountid"))); + + Logger.Info(SessionDiagnostics.DescribeCensus(orphaned, flagged.Count, liveAccounts.Count)); + } + } +} From bb26dfe5d15044dc241e0d8d0fea58defb1b4c0b Mon Sep 17 00:00:00 2001 From: Meketreve <34199654+meketreve@users.noreply.github.com> Date: Wed, 19 Aug 2026 16:01:54 -0300 Subject: [PATCH 4/4] 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 --- docs/backlog/issues.md | 35 +++++++++++++++++++++++++++++------ docs/codebase/TESTING.md | 8 +++++++- 2 files changed, 36 insertions(+), 7 deletions(-) diff --git a/docs/backlog/issues.md b/docs/backlog/issues.md index 83be191..79a5f16 100644 --- a/docs/backlog/issues.md +++ b/docs/backlog/issues.md @@ -61,9 +61,11 @@ So one exception thrown anywhere inside `SignOut()` leaves the server in exactly 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. +This also fits the report saying *sometimes* rather than *always*: `SignIn` clears the flags for the +account on the way in, so a ghost heals itself the next time that player signs in. That statement now +lives in `StaleOnlineFlags.ClearForAccount` and carries `and inuse=1`, which leaves the data identical +and makes the rows affected mean something: without the predicate the update matches every character +on the account and reports that count on every sign in, stale or not. **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. @@ -84,9 +86,17 @@ runs from the transaction's commit callback. - Anything gated on online state acts on stale information for the lifetime of the ghost. ### Proposed Fix -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. +1. **Instrumented 2026-08-19 instead of asked.** The question was whether a ghost came from a sign out + that rolled back or from a peer that vanished without closing, and the log could not tell them + apart: the sign in handler wrote `a logged in account was found` for both. It now writes which one + it is — `[Ghost] stale login: live session still held` with the connection's silence when the + server is still holding the session, and `[Ghost] stale login: no live session, the account flag was + left set` when the flag outlived it. The first is the missing idle timeout, the second is the + rolled-back sign out. Also shipped: `[Session] closing.` carrying session, account, character, + endpoint and silence, written before sign out clears the identity; a count of the stale flags each + sign in clears (`StaleOnlineFlags`); and `StaleOnlineFlagCensus`, which reports every five minutes + and at startup how many characters are flagged online with no session behind them. Nothing here + changes behaviour. **Read the live log after the next patch deploy and the mechanism is named.** 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 @@ -109,6 +119,19 @@ runs from the transaction's commit callback. 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. +### A live report, 2026-08-19 + +The operator lost their connection to the live server when their internet dropped, and on signing in +again was told the character was already logged in and that continuing would disconnect the old +session. That is the `account.IsLoggedIn` branch of `SignInRequestHandler`, and it is the **keepalive** +half of this issue rather than the rollback half: a dropped link sends no close, so the server went on +holding a session whose peer was gone. It is also the case the shipped measurement was built for — the +silence on that session is exactly what `ConnectionActivity` records. + +It cannot be attributed with certainty, because the log of the day could not distinguish the two +mechanisms. That is what the step 1 instrumentation fixes, and the next occurrence will say which it +was. + ### The half still open Step 2 stops the session leaking and stops the `Player` being ticked forever, but it does **not** put diff --git a/docs/codebase/TESTING.md b/docs/codebase/TESTING.md index eb4535d..5822d84 100644 --- a/docs/codebase/TESTING.md +++ b/docs/codebase/TESTING.md @@ -10,7 +10,7 @@ coverage map below states what is covered and what is not. | Tier | Project | Count | Needs | |------|---------|-------|-------| | 1 — smoke | `tools/smoke-test.ps1` | 1 end-to-end run | A configured `GameRoot` and a live database | -| 2 — unit | `src/Perpetuum.Tests` | 58 tests | Nothing. Runs anywhere the solution builds | +| 2 — unit | `src/Perpetuum.Tests` | 99 tests | Nothing. Runs anywhere the solution builds | | 3 — integration | `src/Perpetuum.Tests.Integration` | 10 tests | A configured `GameRoot` and a live database | Tier 2 is the tier that runs in CI. Tiers 1 and 3 run on a developer machine that already has the @@ -75,6 +75,12 @@ production change. against a command pattern, then asserts on the SQL and parameters the code under test actually produced. `Fakes/RecordingLogger.cs` does the same for log output. +`Fakes/Sessions/` holds hand-written doubles for `ISession`, `ISessionManager`, `IAccountRepository`, +`IRelayStateService`, `ILoginQueueService` and `IRequest`, which is what makes request handlers +reachable at this tier. Every member no test uses throws rather than returning a default, so a path +that starts being exercised cannot pass unnoticed. The project references `Perpetuum.RequestHandlers` +for the same reason. + Because these seams are process-wide static state, the fixtures live in xUnit collections (`PerpetuumStaticsCollection`) so classes touching them do not run in parallel with each other.