diff --git a/docs/backlog/issues.md b/docs/backlog/issues.md index 83be191e..79a5f163 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 eb4535d1..5822d84c 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. diff --git a/src/Perpetuum.Bootstrapper/PerpetuumBootstrapper.cs b/src/Perpetuum.Bootstrapper/PerpetuumBootstrapper.cs index 92432c1b..2cf07914 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.RequestHandlers/SignInRequestHandler.cs b/src/Perpetuum.RequestHandlers/SignInRequestHandler.cs index c28f4862..f0ba3a27 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 00000000..27a769f2 --- /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 00000000..ec09d3b6 --- /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 00000000..31b9a19b --- /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 00000000..65254b68 --- /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 96019f2a..888e45fc 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/SessionDiagnosticsTests.cs b/src/Perpetuum.Tests/Unit/SessionDiagnosticsTests.cs new file mode 100644 index 00000000..8026bfce --- /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/StaleLoginReportingTests.cs b/src/Perpetuum.Tests/Unit/StaleLoginReportingTests.cs new file mode 100644 index 00000000..aa53d084 --- /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.Tests/Unit/StaleOnlineFlagCensusTests.cs b/src/Perpetuum.Tests/Unit/StaleOnlineFlagCensusTests.cs new file mode 100644 index 00000000..8d1f7015 --- /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.Tests/Unit/StaleOnlineFlagsTests.cs b/src/Perpetuum.Tests/Unit/StaleOnlineFlagsTests.cs new file mode 100644 index 00000000..43c39360 --- /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/Network/ITcpConnection.cs b/src/Perpetuum/Network/ITcpConnection.cs index d1e1531e..d62c9f97 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 b7375e2a..865b48a5 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 diff --git a/src/Perpetuum/Services/Sessions/SessionDiagnostics.cs b/src/Perpetuum/Services/Sessions/SessionDiagnostics.cs new file mode 100644 index 00000000..ca7671c7 --- /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/StaleOnlineFlagCensus.cs b/src/Perpetuum/Services/Sessions/StaleOnlineFlagCensus.cs new file mode 100644 index 00000000..3d1c1ec7 --- /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)); + } + } +} diff --git a/src/Perpetuum/Services/Sessions/StaleOnlineFlags.cs b/src/Perpetuum/Services/Sessions/StaleOnlineFlags.cs new file mode 100644 index 00000000..4f74ac50 --- /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; + } + } +}