fix: prevent crash when going to character select from ingame (AscensionGameDev#2067)

* partial fix for race condition
can still cause it by logging in with no pv, setting the pv and quickly exiting to char select, logging out, deleting the pv instance from the player db, logging back in, setting the pv, and quickly exiting to char select (and maybe even just normal logout triggers it in this specific scenario?)

* fix: actually complete the logout when logging out from character select

* cleanup cruft from working on dbce

Author: pandinocoder

Intersect.Client/Core/Main.cs

@@ -330,10 +330,17 @@ public static void JoinGame()
             Audio.StopMusic(ClientConfiguration.Instance.MusicFadeTimer);
         }
 
-        public static void Logout(bool characterSelect)
+        public static void Logout(bool characterSelect, bool skipFade = false)
         {
             Audio.PlayMusic(ClientConfiguration.Instance.MenuMusic, ClientConfiguration.Instance.MusicFadeTimer, ClientConfiguration.Instance.MusicFadeTimer, true);
-            Fade.FadeOut();
+            if (skipFade)
+            {
+                Fade.Cancel();
+            }
+            else
+            {
+                Fade.FadeOut();
+            }
 
             if (!ClientContext.IsSinglePlayer)
             {
@@ -387,7 +394,14 @@ public static void Logout(bool characterSelect)
                 PacketSender.SendLogout(characterSelect);
             }
 
-            Fade.FadeIn();
+            if (skipFade)
+            {
+                Fade.Cancel();
+            }
+            else
+            {
+                Fade.FadeIn();
+            }
         }
 
     }

Intersect.Client/Interface/Menu/SelectCharacterWindow.cs

@@ -344,6 +344,7 @@ public void Hide()
 
         private void mLogoutButton_Clicked(Base sender, ClickedEventArgs arguments)
         {
+            Main.Logout(false, skipFade: true);
             mMainMenu.Reset();
         }
 

Intersect.Network/LiteNetLib/LiteNetLibInterface.cs

@@ -446,6 +446,13 @@ public void OnNetworkReceiveUnconnected(IPEndPoint remoteEndPoint, NetPacketRead
 
     public void OnNetworkLatencyUpdate(NetPeer peer, int latency)
     {
+#if !DIAGNOSTIC
+        if (latency < 1)
+        {
+            return;
+        }
+#endif
+
         Log.Verbose($"LTNC {peer.EndPoint} {latency}ms");
     }
 

Intersect.Server.Core/Core/ServerContext.cs

@@ -118,7 +118,7 @@ protected override void Dispose(bool disposing)
                 var savingTasks = new List<Task>();
                 foreach (var user in Database.PlayerData.User.OnlineList.ToArray())
                 {
-                    savingTasks.Add(Task.Run(() => user.Save()));
+                    savingTasks.Add(Task.Run(() => user.SaveWithDebounce()));
                 }
 
                 Task.WaitAll(savingTasks.ToArray());

Intersect.Server.Core/Database/IntersectDbContext.cs

@@ -9,6 +9,7 @@
 using Microsoft.EntityFrameworkCore;
 using Microsoft.EntityFrameworkCore.ChangeTracking;
 using Microsoft.EntityFrameworkCore.Infrastructure;
+using Microsoft.Extensions.Primitives;
 
 namespace Intersect.Server.Database;
 
@@ -204,40 +205,46 @@ public override int SaveChanges(bool acceptAllChangesOnSuccess)
 
             return rowsChanged;
         }
-        catch (DbUpdateConcurrencyException ex)
+        catch (DbUpdateConcurrencyException concurrencyException)
         {
             var concurrencyErrors = new StringBuilder();
-            foreach (var entry in ex.Entries)
+            foreach (var entry in concurrencyException.Entries)
             {
-                var type = entry.GetType().FullName;
-                concurrencyErrors.AppendLine($"Entry Type [{type} / {entry.State}]");
-                concurrencyErrors.AppendLine("--------------------");
-                concurrencyErrors.AppendLine($"Type: {entry.Entity.GetFullishName()}");
+                concurrencyErrors.AppendLine(
+                    $"[{entry.State}] {entry.Entity.GetFullishName()} ({entry.GetFullishName()})"
+                );
 
                 var proposedValues = entry.CurrentValues;
                 var databaseValues = entry.GetDatabaseValues();
 
                 foreach (var property in proposedValues.Properties)
                 {
                     concurrencyErrors.AppendLine(
-                        $"\t{property.Name:propertyNameColumnSize} (Token: {property.IsConcurrencyToken}): Proposed: {proposedValues[property]}  Original Value: {entry.OriginalValues[property]}  Database Value: {(databaseValues != null ? databaseValues[property] : "null")}"
+                        string.Join(
+                            ' ',
+                            $"\t{property.Name:propertyNameColumnSize} (Token: {property.IsConcurrencyToken}):",
+                            $"Proposed: {proposedValues[property]}",
+                            $"Original Value: {entry.OriginalValues[property]}",
+                            $"Database Value: {(databaseValues?[property] ?? "null")}"
+                        )
                     );
                 }
 
-                concurrencyErrors.AppendLine("");
-                concurrencyErrors.AppendLine("");
+                concurrencyErrors.AppendLine();
             }
 
-            var suffix = string.Empty;
 #if DEBUG
-            suffix = $"#{currentExecutionId}";
+            var suffix = $"#{currentExecutionId}";
+#else
+            var suffix = string.Empty;
 #endif
             var entityTypeNames = ChangeTracker.Entries()
                 .Select(entry => entry.Entity.GetType().Name)
                 .Distinct()
                 .ToArray();
-            Log.Error(ex, $"Jackpot! Concurrency Bug For {string.Join(", ", entityTypeNames)} {suffix}");
+            Log.Error(concurrencyException, $"Jackpot! Concurrency Bug For {string.Join(", ", entityTypeNames)} {suffix}");
             Log.Error(concurrencyErrors.ToString());
+            Log.Error(Environment.StackTrace);
 
 #if DEBUG
             Log.Debug($"DBOP-C SaveChanges({acceptAllChangesOnSuccess}) #{currentExecutionId}");

Intersect.Server.Core/Database/PlayerData/Players/Variable.cs

@@ -6,9 +6,19 @@ namespace Intersect.Server.Database.PlayerData.Players
 {
     public partial class Variable
     {
+        private Guid _id;
+
         [DatabaseGenerated(DatabaseGeneratedOption.Identity)]
         [JsonIgnore]
-        public Guid Id { get; protected set; }
+        public Guid Id
+        {
+            get => _id;
+            set
+            {
+                Console.WriteLine("HERE IS THE ISSUE?", Environment.StackTrace);
+                _id = value;
+            }
+        }
 
         [DatabaseGenerated(DatabaseGeneratedOption.None)]
         public Guid VariableId { get; protected set; }

Intersect.Server.Core/Database/PlayerData/User.cs

@@ -32,6 +32,9 @@ namespace Intersect.Server.Database.PlayerData
     [ApiVisibility(ApiVisibility.Restricted | ApiVisibility.Private)]
     public partial class User
     {
+        private long _lastSave;
+        private readonly object _lastSaveLock = new();
+
         private static readonly ConcurrentDictionary<Guid, User> OnlineUsers = new();
 
         [JsonIgnore][NotMapped] private readonly object mSavingLock = new();
@@ -225,20 +228,19 @@ public void DeleteCharacter(Player deleteCharacter)
             {
                 lock (mSavingLock)
                 {
-                    using (var context = DbInterface.CreatePlayerContext(false))
-                    {
-                        context.Users.Update(this);
+                    using var context = DbInterface.CreatePlayerContext(false);
 
-                        context.ChangeTracker.DetectChanges();
+                    context.Users.Update(this);
 
-                        context.StopTrackingUsersExcept(this);
+                    Players.Remove(deleteCharacter);
 
-                        context.Entry(deleteCharacter).State = EntityState.Deleted;
+                    context.ChangeTracker.DetectChanges();
 
-                        Players.Remove(deleteCharacter);
+                    context.StopTrackingUsersExcept(this);
 
-                        context.SaveChanges();
-                    }
+                    context.Entry(deleteCharacter).State = EntityState.Deleted;
+
+                    context.SaveChanges();
                 }
             }
             catch (Exception ex)
@@ -294,16 +296,35 @@ public async Task SaveAsync(
             CancellationToken cancellationToken = default
         ) => Save(playerContext, force);
 
-        public void Save(bool force) => Save(force: force, create: false);
+        public void SaveWithDebounce(long debounceMs = 5000)
+        {
+            lock (_lastSaveLock)
+            {
+                if (_lastSave < debounceMs + Timing.Global.MillisecondsUtc)
+                {
+                    Log.Debug("Skipping save due to debounce");
+                    return;
+                }
+            }
+
+            Save();
+        }
 
-        public void Save(bool force = false, bool create = false) => Save(default, force, create);
+        public UserSaveResult Save(bool force) => Save(force: force, create: false);
+
+        public UserSaveResult Save(bool force = false, bool create = false) => Save(default, force, create);
 
 #if DIAGNOSTIC
         private int _saveCounter = 0;
 #endif
 
-        private void Save(PlayerContext? playerContext, bool force = false, bool create = false)
+        private UserSaveResult Save(PlayerContext? playerContext, bool force = false, bool create = false)
         {
+            lock (_lastSaveLock)
+            {
+                _lastSave = Timing.Global.MillisecondsUtc;
+            }
+
 #if DIAGNOSTIC
             var currentExecutionId = _saveCounter++;
 #endif
@@ -326,7 +347,10 @@ private void Save(PlayerContext? playerContext, bool force = false, bool create
 
                 if (!lockTaken)
                 {
-                    return;
+#if DIAGNOSTIC
+                    Log.Debug($"Failed to take lock {Environment.StackTrace}");
+#endif
+                    return UserSaveResult.SkippedCouldNotTakeLock;
                 }
 
 #if DIAGNOSTIC
@@ -345,6 +369,7 @@ private void Save(PlayerContext? playerContext, bool force = false, bool create
                 }
                 else
                 {
+                    // playerContext.Attach(this);
                     playerContext.Users.Update(this);
                 }
 
@@ -367,6 +392,8 @@ private void Save(PlayerContext? playerContext, bool force = false, bool create
 #if DIAGNOSTIC
                 Log.Debug($"DBOP-B Save({playerContext}, {force}, {create}) #{currentExecutionId} {Name} ({Id})");
 #endif
+
+                return UserSaveResult.Completed;
             }
             catch (DbUpdateConcurrencyException ex)
             {
@@ -428,6 +455,8 @@ private void Save(PlayerContext? playerContext, bool force = false, bool create
                     Monitor.Exit(mSavingLock);
                 }
             }
+
+            return UserSaveResult.Failed;
         }
 
         [return: NotNullIfNotNull(nameof(user))]

Intersect.Server.Core/Database/PlayerData/UserSaveResult.cs

@@ -0,0 +1,8 @@
+namespace Intersect.Server.Database.PlayerData;
+
+public enum UserSaveResult
+{
+    Completed,
+    SkippedCouldNotTakeLock,
+    Failed,
+}

Intersect.Server.Core/Entities/Player.cs

@@ -13,6 +13,7 @@
 using Intersect.Network.Packets.Server;
 using Intersect.Server.Database;
 using Intersect.Server.Database.Logging.Entities;
+using Intersect.Server.Database.PlayerData;
 using Intersect.Server.Database.PlayerData.Players;
 using Intersect.Server.Database.PlayerData.Security;
 using Intersect.Server.Entities.Combat;
@@ -466,7 +467,7 @@ private void Logout(bool softLogout = false)
             BankInterface = default;
             InShop = default;
 
-            //Clear cooldowns that have expired
+            // Clear cooldowns that have expired
             RemoveStaleItemCooldowns();
             RemoveStaleSpellCooldowns();
 
@@ -477,10 +478,10 @@ private void Logout(bool softLogout = false)
                 PacketSender.SendGlobalMsg(Strings.Player.left.ToString(Name, Options.Instance.GameName));
             }
 
-            //Remvoe this player from the online list
+            // Remove this player from the online list
             if (OnlinePlayers?.ContainsKey(Id) ?? false)
             {
-                OnlinePlayers.TryRemove(Id, out Player me);
+                OnlinePlayers.TryRemove(Id, out Player _);
                 OnlineList = OnlinePlayers.Values.ToArray();
             }
 
@@ -495,21 +496,63 @@ private void Logout(bool softLogout = false)
                 User?.TryLogout(softLogout);
             }
 
-            DbInterface.Pool.QueueWorkItem(CompleteLogout);
+#if DIAGNOSTIC
+            var stackTrace = Environment.StackTrace;
+#else
+            var stackTrace = default(string);
+#endif
+            var logoutOperationId = Guid.NewGuid();
+            DbInterface.Pool.QueueWorkItem(CompleteLogout, logoutOperationId, stackTrace);
         }
 
 #if DIAGNOSTIC
         private int _logoutCounter = 0;
 #endif
 
-        public void CompleteLogout()
+        public void CompleteLogout(Guid logoutOperationId, string? stackTrace = default)
         {
+            if (logoutOperationId != default)
+            {
+                Log.Debug($"Completing logout {logoutOperationId}");
+            }
+
+            if (stackTrace != default)
+            {
+                Log.Debug(stackTrace);
+            }
+
 #if DIAGNOSTIC
             var currentExecutionId = _logoutCounter++;
             Log.Debug($"Started {nameof(CompleteLogout)}() #{currentExecutionId} on {Name} ({User?.Name})");
 #endif
 
-            User?.Save();
+            try
+            {
+                Log.Diagnostic($"Starting save for logout {logoutOperationId}");
+                var saveResult = User?.Save();
+                switch (saveResult)
+                {
+                    case UserSaveResult.Completed:
+                        Log.Diagnostic($"Completed save for logout {logoutOperationId}");
+                        break;
+                    case UserSaveResult.SkippedCouldNotTakeLock:
+                        Log.Debug($"Skipped save for logout {logoutOperationId}");
+                        break;
+                    case UserSaveResult.Failed:
+                        Log.Warn($"Save failed for logout {logoutOperationId}");
+                        break;
+                    case null:
+                        Log.Warn($"Skipped save because {nameof(User)} is null.");
+                        break;
+                    default:
+                        throw new UnreachableException();
+                }
+            }
+            catch
+            {
+                Log.Warn($"Crashed while saving for logout {logoutOperationId}");
+                throw;
+            }
 
             lock (_savingLock)
             {
@@ -541,8 +584,8 @@ public override void Update(long timeMs)
                     {
                         if (CombatTimer < Timing.Global.Milliseconds)
                         {
+                            Log.Debug($"Combat timer expired for player {Id}, logging out.");
                             Logout();
-
                             return;
                         }
                     }