Fix preference loading bugs (space-wizards#27742)

First bug: if an error occured during pref loading code, it would fail. If the person then readied up, it would likely cause the round to fail to start.

Why could they ready up? The code only checks that the prefs finished loading, not that they finished loading *successfully*. Whoops.

Anyways, now people get kicked if their prefs fail to load. And I improved the error handling.

Second bug: if a user disconnected while their prefs were loading, it would cause an exception. This exception would go unobserved on lobby servers or raise through gameticker on non-lobby servers.

This happened even on a live server once and then triggered the first bug, but idk how.

Fixed this by properly plumbing through cancellation into the preferences loading code. The stuff is now cancelled properly.

Third bug: if somebody has a loadout item with a playtime requirement active, load-time sanitization of player prefs could run into a race condition because the sanitization can happen *before* play time was loaded.

Fixed by moving pref sanitizations to a later stage in the load process.

Content.Server/Database/ServerDbBase.cs

@@ -33,9 +33,11 @@ public ServerDbBase(ISawmill opsLog)
         }
 
         #region Preferences
-        public async Task<PlayerPreferences?> GetPlayerPreferencesAsync(NetUserId userId)
+        public async Task<PlayerPreferences?> GetPlayerPreferencesAsync(
+            NetUserId userId,
+            CancellationToken cancel = default)
         {
-            await using var db = await GetDb();
+            await using var db = await GetDb(cancel);
 
             var prefs = await db.DbContext
                 .Preference
@@ -47,7 +49,7 @@ public ServerDbBase(ISawmill opsLog)
                     .ThenInclude(l => l.Groups)
                     .ThenInclude(group => group.Loadouts)
                 .AsSingleQuery()
-                .SingleOrDefaultAsync(p => p.UserId == userId.UserId);
+                .SingleOrDefaultAsync(p => p.UserId == userId.UserId, cancel);
 
             if (prefs is null)
                 return null;
@@ -515,13 +517,13 @@ public async Task EditServerRoleBan(int id, string reason, NoteSeverity severity
         #endregion
 
         #region Playtime
-        public async Task<List<PlayTime>> GetPlayTimes(Guid player)
+        public async Task<List<PlayTime>> GetPlayTimes(Guid player, CancellationToken cancel)
         {
-            await using var db = await GetDb();
+            await using var db = await GetDb(cancel);
 
             return await db.DbContext.PlayTime
                 .Where(p => p.PlayerId == player)
-                .ToListAsync();
+                .ToListAsync(cancel);
         }
 
         public async Task UpdatePlayTimes(IReadOnlyCollection<PlayTimeUpdate> updates)
@@ -673,7 +675,7 @@ public async Task AddServerBanHitsAsync(int connection, IEnumerable<ServerBanDef
          */
         public async Task<Admin?> GetAdminDataForAsync(NetUserId userId, CancellationToken cancel)
         {
-            await using var db = await GetDb();
+            await using var db = await GetDb(cancel);
 
             return await db.DbContext.Admin
                 .Include(p => p.Flags)
@@ -688,7 +690,7 @@ public async Task AddServerBanHitsAsync(int connection, IEnumerable<ServerBanDef
 
         public async Task<AdminRank?> GetAdminRankDataForAsync(int id, CancellationToken cancel = default)
         {
-            await using var db = await GetDb();
+            await using var db = await GetDb(cancel);
 
             return await db.DbContext.AdminRank
                 .Include(r => r.Flags)
@@ -697,7 +699,7 @@ public async Task AddServerBanHitsAsync(int connection, IEnumerable<ServerBanDef
 
         public async Task RemoveAdminAsync(NetUserId userId, CancellationToken cancel)
         {
-            await using var db = await GetDb();
+            await using var db = await GetDb(cancel);
 
             var admin = await db.DbContext.Admin.SingleAsync(a => a.UserId == userId.UserId, cancel);
             db.DbContext.Admin.Remove(admin);
@@ -707,7 +709,7 @@ public async Task RemoveAdminAsync(NetUserId userId, CancellationToken cancel)
 
         public async Task AddAdminAsync(Admin admin, CancellationToken cancel)
         {
-            await using var db = await GetDb();
+            await using var db = await GetDb(cancel);
 
             db.DbContext.Admin.Add(admin);
 
@@ -716,7 +718,7 @@ public async Task AddAdminAsync(Admin admin, CancellationToken cancel)
 
         public async Task UpdateAdminAsync(Admin admin, CancellationToken cancel)
         {
-            await using var db = await GetDb();
+            await using var db = await GetDb(cancel);
 
             var existing = await db.DbContext.Admin.Include(a => a.Flags).SingleAsync(a => a.UserId == admin.UserId, cancel);
             existing.Flags = admin.Flags;
@@ -728,7 +730,7 @@ public async Task UpdateAdminAsync(Admin admin, CancellationToken cancel)
 
         public async Task RemoveAdminRankAsync(int rankId, CancellationToken cancel)
         {
-            await using var db = await GetDb();
+            await using var db = await GetDb(cancel);
 
             var admin = await db.DbContext.AdminRank.SingleAsync(a => a.Id == rankId, cancel);
             db.DbContext.AdminRank.Remove(admin);
@@ -738,7 +740,7 @@ public async Task RemoveAdminRankAsync(int rankId, CancellationToken cancel)
 
         public async Task AddAdminRankAsync(AdminRank rank, CancellationToken cancel)
         {
-            await using var db = await GetDb();
+            await using var db = await GetDb(cancel);
 
             db.DbContext.AdminRank.Add(rank);
 
@@ -811,7 +813,7 @@ INSERT INTO player_round (players_id, rounds_id) VALUES ({players[player]}, {id}
 
         public async Task UpdateAdminRankAsync(AdminRank rank, CancellationToken cancel)
         {
-            await using var db = await GetDb();
+            await using var db = await GetDb(cancel);
 
             var existing = await db.DbContext.AdminRank
                 .Include(r => r.Flags)
@@ -1594,7 +1596,9 @@ public async Task<bool> HasPendingModelChanges()
             return db.DbContext.Database.HasPendingModelChanges();
         }
 
-        protected abstract Task<DbGuard> GetDb([CallerMemberName] string? name = null);
+        protected abstract Task<DbGuard> GetDb(
+            CancellationToken cancel = default,
+            [CallerMemberName] string? name = null);
 
         protected void LogDbOp(string? name)
         {

Content.Server/Database/ServerDbManager.cs

@@ -29,7 +29,11 @@ public interface IServerDbManager
         void Shutdown();
 
         #region Preferences
-        Task<PlayerPreferences> InitPrefsAsync(NetUserId userId, ICharacterProfile defaultProfile);
+        Task<PlayerPreferences> InitPrefsAsync(
+            NetUserId userId,
+            ICharacterProfile defaultProfile,
+            CancellationToken cancel);
+
         Task SaveSelectedCharacterIndexAsync(NetUserId userId, int index);
 
         Task SaveCharacterSlotAsync(NetUserId userId, ICharacterProfile? profile, int slot);
@@ -38,7 +42,7 @@ public interface IServerDbManager
 
         // Single method for two operations for transaction.
         Task DeleteSlotAndSetSelectedIndex(NetUserId userId, int deleteSlot, int newSlot);
-        Task<PlayerPreferences?> GetPlayerPreferencesAsync(NetUserId userId);
+        Task<PlayerPreferences?> GetPlayerPreferencesAsync(NetUserId userId, CancellationToken cancel);
         #endregion
 
         #region User Ids
@@ -157,8 +161,9 @@ public Task EditServerRoleBan(
         /// Look up a player's role timers.
         /// </summary>
         /// <param name="player">The player to get the role timer information from.</param>
+        /// <param name="cancel"></param>
         /// <returns>All role timers belonging to the player.</returns>
-        Task<List<PlayTime>> GetPlayTimes(Guid player);
+        Task<List<PlayTime>> GetPlayTimes(Guid player, CancellationToken cancel = default);
 
         /// <summary>
         /// Update play time information in bulk.
@@ -346,7 +351,10 @@ public void Shutdown()
             _sqliteInMemoryConnection?.Dispose();
         }
 
-        public Task<PlayerPreferences> InitPrefsAsync(NetUserId userId, ICharacterProfile defaultProfile)
+        public Task<PlayerPreferences> InitPrefsAsync(
+            NetUserId userId,
+            ICharacterProfile defaultProfile,
+            CancellationToken cancel)
         {
             DbWriteOpsMetric.Inc();
             return RunDbCommand(() => _db.InitPrefsAsync(userId, defaultProfile));
@@ -376,10 +384,10 @@ public Task SaveAdminOOCColorAsync(NetUserId userId, Color color)
             return RunDbCommand(() => _db.SaveAdminOOCColorAsync(userId, color));
         }
 
-        public Task<PlayerPreferences?> GetPlayerPreferencesAsync(NetUserId userId)
+        public Task<PlayerPreferences?> GetPlayerPreferencesAsync(NetUserId userId, CancellationToken cancel)
         {
             DbReadOpsMetric.Inc();
-            return RunDbCommand(() => _db.GetPlayerPreferencesAsync(userId));
+            return RunDbCommand(() => _db.GetPlayerPreferencesAsync(userId, cancel));
         }
 
         public Task AssignUserIdAsync(string name, NetUserId userId)
@@ -487,10 +495,10 @@ public Task EditServerRoleBan(int id, string reason, NoteSeverity severity, Date
 
         #region Playtime
 
-        public Task<List<PlayTime>> GetPlayTimes(Guid player)
+        public Task<List<PlayTime>> GetPlayTimes(Guid player, CancellationToken cancel)
         {
             DbReadOpsMetric.Inc();
-            return RunDbCommand(() => _db.GetPlayTimes(player));
+            return RunDbCommand(() => _db.GetPlayTimes(player, cancel));
         }
 
         public Task UpdatePlayTimes(IReadOnlyCollection<PlayTimeUpdate> updates)

Content.Server/Database/ServerDbPostgres.cs

@@ -527,22 +527,26 @@ protected override DateTime NormalizeDatabaseTime(DateTime time)
             return time;
         }
 
-        private async Task<DbGuardImpl> GetDbImpl([CallerMemberName] string? name = null)
+        private async Task<DbGuardImpl> GetDbImpl(
+            CancellationToken cancel = default,
+            [CallerMemberName] string? name = null)
         {
             LogDbOp(name);
 
             await _dbReadyTask;
-            await _prefsSemaphore.WaitAsync();
+            await _prefsSemaphore.WaitAsync(cancel);
 
             if (_msLag > 0)
-                await Task.Delay(_msLag);
+                await Task.Delay(_msLag, cancel);
 
             return new DbGuardImpl(this, new PostgresServerDbContext(_options));
         }
 
-        protected override async Task<DbGuard> GetDb([CallerMemberName] string? name = null)
+        protected override async Task<DbGuard> GetDb(
+            CancellationToken cancel = default,
+            [CallerMemberName] string? name = null)
         {
-            return await GetDbImpl(name);
+            return await GetDbImpl(cancel, name);
         }
 
         private sealed class DbGuardImpl : DbGuard

Content.Server/Database/ServerDbSqlite.cs

@@ -439,7 +439,7 @@ public override async Task<int> AddConnectionLogAsync(
         public override async Task<((Admin, string? lastUserName)[] admins, AdminRank[])> GetAllAdminAndRanksAsync(
             CancellationToken cancel)
         {
-            await using var db = await GetDbImpl();
+            await using var db = await GetDbImpl(cancel);
 
             var admins = await db.SqliteDbContext.Admin
                 .Include(a => a.Flags)
@@ -514,23 +514,27 @@ protected override DateTime NormalizeDatabaseTime(DateTime time)
             return DateTime.SpecifyKind(time, DateTimeKind.Utc);
         }
 
-        private async Task<DbGuardImpl> GetDbImpl([CallerMemberName] string? name = null)
+        private async Task<DbGuardImpl> GetDbImpl(
+            CancellationToken cancel = default,
+            [CallerMemberName] string? name = null)
         {
             LogDbOp(name);
             await _dbReadyTask;
             if (_msDelay > 0)
-                await Task.Delay(_msDelay);
+                await Task.Delay(_msDelay, cancel);
 
-            await _prefsSemaphore.WaitAsync();
+            await _prefsSemaphore.WaitAsync(cancel);
 
             var dbContext = new SqliteServerDbContext(_options());
 
             return new DbGuardImpl(this, dbContext);
         }
 
-        protected override async Task<DbGuard> GetDb([CallerMemberName] string? name = null)
+        protected override async Task<DbGuard> GetDb(
+            CancellationToken cancel = default,
+            [CallerMemberName] string? name = null)
         {
-            return await GetDbImpl(name).ConfigureAwait(false);
+            return await GetDbImpl(cancel, name).ConfigureAwait(false);
         }
 
         private sealed class DbGuardImpl : DbGuard
@@ -569,9 +573,9 @@ public ConcurrencySemaphore(int maxCount, bool synchronous)
                 _semaphore = new SemaphoreSlim(maxCount, maxCount);
             }
 
-            public Task WaitAsync()
+            public Task WaitAsync(CancellationToken cancel = default)
             {
-                var task = _semaphore.WaitAsync();
+                var task = _semaphore.WaitAsync(cancel);
 
                 if (_synchronous)
                 {

Content.Server/Database/UserDbDataManager.cs

@@ -2,6 +2,7 @@
 using System.Threading.Tasks;
 using Content.Server.Players.PlayTimeTracking;
 using Content.Server.Preferences.Managers;
+using Robust.Server.Player;
 using Robust.Shared.Network;
 using Robust.Shared.Player;
 using Robust.Shared.Utility;
@@ -16,17 +17,22 @@ namespace Content.Server.Database;
 /// Actual loading code is handled by separate managers such as <see cref="IServerPreferencesManager"/>.
 /// This manager is simply a centralized "is loading done" controller for other code to rely on.
 /// </remarks>
-public sealed class UserDbDataManager
+public sealed class UserDbDataManager : IPostInjectInit
 {
     [Dependency] private readonly IServerPreferencesManager _prefs = default!;
+    [Dependency] private readonly ILogManager _logManager = default!;
     [Dependency] private readonly PlayTimeTrackingManager _playTimeTracking = default!;
 
     private readonly Dictionary<NetUserId, UserData> _users = new();
 
+    private ISawmill _sawmill = default!;
+
     // TODO: Ideally connected/disconnected would be subscribed to IPlayerManager directly,
     // but this runs into ordering issues with game ticker.
     public void ClientConnected(ICommonSession session)
     {
+        _sawmill.Verbose($"Initiating load for user {session}");
+
         DebugTools.Assert(!_users.ContainsKey(session.UserId), "We should not have any cached data on client connect.");
 
         var cts = new CancellationTokenSource();
@@ -51,25 +57,71 @@ public void ClientDisconnected(ICommonSession session)
 
     private async Task Load(ICommonSession session, CancellationToken cancel)
     {
-        await Task.WhenAll(
-            _prefs.LoadData(session, cancel),
-            _playTimeTracking.LoadData(session, cancel));
+        // The task returned by this function is only ever observed by callers of WaitLoadComplete,
+        // which doesn't even happen currently if the lobby is enabled.
+        // As such, this task must NOT throw a non-cancellation error!
+        try
+        {
+            await Task.WhenAll(
+                _prefs.LoadData(session, cancel),
+                _playTimeTracking.LoadData(session, cancel));
+
+            cancel.ThrowIfCancellationRequested();
+            _prefs.SanitizeData(session);
+
+            _sawmill.Verbose($"Load complete for user {session}");
+        }
+        catch (OperationCanceledException)
+        {
+            _sawmill.Debug($"Load cancelled for user {session}");
+
+            // We can rethrow the cancellation.
+            // This will make the task returned by WaitLoadComplete() also return a cancellation.
+            throw;
+        }
+        catch (Exception e)
+        {
+            // Must catch all exceptions here, otherwise task may go unobserved.
+            _sawmill.Error($"Load of user data failed: {e}");
+
+            // Kick them from server, since something is hosed. Let them try again I guess.
+            session.Channel.Disconnect("Loading of server user data failed, this is a bug.");
+
+            // We throw a OperationCanceledException so users of WaitLoadComplete() always see cancellation here.
+            throw new OperationCanceledException("Load of user data cancelled due to unknown error");
+        }
     }
 
+    /// <summary>
+    /// Wait for all on-database data for a user to be loaded.
+    /// </summary>
+    /// <remarks>
+    /// The task returned by this function may end up in a cancelled state
+    /// (throwing <see cref="OperationCanceledException"/>) if the user disconnects while loading or an error occurs.
+    /// </remarks>
+    /// <param name="session"></param>
+    /// <returns>
+    /// A task that completes when all on-database data for a user has finished loading.
+    /// </returns>
     public Task WaitLoadComplete(ICommonSession session)
     {
         return _users[session.UserId].Task;
     }
 
     public bool IsLoadComplete(ICommonSession session)
     {
-        return GetLoadTask(session).IsCompleted;
+        return GetLoadTask(session).IsCompletedSuccessfully;
     }
 
     public Task GetLoadTask(ICommonSession session)
     {
         return _users[session.UserId].Task;
     }
 
+    void IPostInjectInit.PostInject()
+    {
+        _sawmill = _logManager.GetSawmill("userdb");
+    }
+
     private sealed record UserData(CancellationTokenSource Cancel, Task Task);
 }