Fix admin log crash in the lobby

Add test
Fixes https://github.com/space-wizards/space-station-14/issues/5504

Content.IntegrationTests/Tests/Administration/Logs/AddTests.cs

@@ -4,6 +4,7 @@ using System.Linq;
 using System.Threading.Tasks;
 using Content.Server.Administration.Logs;
 using Content.Server.Database;
+using Content.Server.GameTicking;
 using Content.Shared.Administration.Logs;
 using Content.Shared.CCVar;
 using NUnit.Framework;
@@ -117,28 +118,22 @@ public class AddTests : ContentIntegrationTest
             return false;
         });
 
-        await server.WaitPost(() =>
+        var filter = new LogFilter
         {
-            Task.Run(async () =>
+            Round = log.RoundId,
-            {
+            Search = log.Message,
-                var filter = new LogFilter
+            Types = new List<LogType> {log.Type},
-                {
+        };
-                    Round = log.RoundId,
-                    Search = log.Message,
-                    Types = new List<LogType> {log.Type},
-                };
 
-                await foreach (var json in sDatabase.GetAdminLogsJson(filter))
+        await foreach (var json in sDatabase.GetAdminLogsJson(filter))
-                {
+        {
-                    var root = json.RootElement;
+            var root = json.RootElement;
 
-                    Assert.That(root.TryGetProperty("entity", out _), Is.True);
+            Assert.That(root.TryGetProperty("entity", out _), Is.True);
-                    Assert.That(root.TryGetProperty("guid", out _), Is.True);
+            Assert.That(root.TryGetProperty("guid", out _), Is.True);
 
-                    json.Dispose();
+            json.Dispose();
-                }
+        }
-            }).Wait();
-        });
     }
 
     [Test]
@@ -218,7 +213,7 @@ public class AddTests : ContentIntegrationTest
         Guid playerGuid = default;
 
         await server.WaitPost(() =>
-        {;
+        {
             var player = sPlayers.ServerSessions.First();
             playerGuid = player.UserId;
 
@@ -241,4 +236,76 @@ public class AddTests : ContentIntegrationTest
             return false;
         });
     }
+
+    [Test]
+    public async Task PreRoundAddAndGetSingle()
+    {
+        var server = StartServer(new ServerContentIntegrationOption
+        {
+            CVarOverrides =
+            {
+                [CCVars.AdminLogsQueueSendDelay.Name] = "0",
+                [CCVars.GameLobbyEnabled.Name] = "true"
+            },
+        });
+        await server.WaitIdleAsync();
+
+        var sDatabase = server.ResolveDependency<IServerDbManager>();
+        var sEntities = server.ResolveDependency<IEntityManager>();
+        var sMaps = server.ResolveDependency<IMapManager>();
+        var sSystems = server.ResolveDependency<IEntitySystemManager>();
+
+        var sAdminLogSystem = sSystems.GetEntitySystem<AdminLogSystem>();
+        var sGamerTicker = sSystems.GetEntitySystem<GameTicker>();
+
+        var guid = Guid.NewGuid();
+
+        await server.WaitPost(() =>
+        {
+            var coordinates = GetMainEntityCoordinates(sMaps);
+            var entity = sEntities.SpawnEntity(null, coordinates);
+
+            sAdminLogSystem.Add(LogType.Unknown, $"{entity} test log: {guid}");
+        });
+
+        await server.WaitPost(() =>
+        {
+            sGamerTicker.StartRound(true);
+        });
+
+        LogRecord log = null;
+
+        await WaitUntil(server, async () =>
+        {
+            var logs = sAdminLogSystem.CurrentRoundLogs(new LogFilter
+            {
+                Search = guid.ToString()
+            });
+
+            await foreach (var found in logs)
+            {
+                log = found;
+                return true;
+            }
+
+            return false;
+        });
+
+        var filter = new LogFilter
+        {
+            Round = log.RoundId,
+            Search = log.Message,
+            Types = new List<LogType> {log.Type},
+        };
+
+        await foreach (var json in sDatabase.GetAdminLogsJson(filter))
+        {
+            var root = json.RootElement;
+
+            Assert.That(root.TryGetProperty("entity", out _), Is.True);
+            Assert.That(root.TryGetProperty("guid", out _), Is.True);
+
+            json.Dispose();
+        }
+    }
 }

Content.IntegrationTests/Tests/Administration/Logs/FilterTests.cs

@@ -47,8 +47,6 @@ public class FilterTests : ContentIntegrationTest
 
                 sAdminLogSystem.Add(LogType.Unknown, $"{entity:Entity} test log: {commonGuid} {guids[i]}");
             });
-
-            await server.WaitRunTicks(60);
         }
 
         await WaitUntil(server, async () =>

Content.IntegrationTests/Tests/Administration/Logs/QueryTests.cs

@@ -34,7 +34,7 @@ public class QueryTests : ContentIntegrationTest
         var sPlayers = server.ResolveDependency<IPlayerManager>();
 
         var sAdminLogSystem = sSystems.GetEntitySystem<AdminLogSystem>();
-        var sGameTicker = sSystems.GetEntitySystem<GameTicker>();
+        var sGamerTicker = sSystems.GetEntitySystem<GameTicker>();
 
         var date = DateTime.UtcNow;
         var guid = Guid.NewGuid();
@@ -43,14 +43,14 @@ public class QueryTests : ContentIntegrationTest
 
         await server.WaitPost(() =>
         {
-            player = sPlayers.GetAllPlayers().First();
+            player = sPlayers.ServerSessions.First();
 
             sAdminLogSystem.Add(LogType.Unknown, $"{player.AttachedEntity:Entity} test log: {guid}");
         });
 
         var filter = new LogFilter
         {
-            Round = sGameTicker.RoundId,
+            Round = sGamerTicker.RoundId,
             Search = guid.ToString(),
             Types = new List<LogType> {LogType.Unknown},
             After = date,

Content.Server/Administration/Logs/AdminLogSystem.Json.cs

@@ -32,7 +32,7 @@ public partial class AdminLogSystem
         }
 
         var converterNames = _jsonOptions.Converters.Select(converter => converter.GetType().Name);
-        _sawmill.Info($"Admin log converters found: {string.Join(" ", converterNames)}");
+        _sawmill.Debug($"Admin log converters found: {string.Join(" ", converterNames)}");
     }
 
     private (JsonDocument json, List<Guid> players, List<(int id, string? name)> entities) ToJson(
@@ -82,5 +82,4 @@ public partial class AdminLogSystem
 
         return (JsonSerializer.SerializeToDocument(parsed, _jsonOptions), players, entities);
     }
-
 }

Content.Server/Administration/Logs/AdminLogSystem.cs

@@ -39,10 +39,22 @@ public partial class AdminLogSystem : SharedAdminLogSystem
             Buckets = Histogram.LinearBuckets(0, 0.5, 20)
         });
 
+    private static readonly Gauge Queue = Metrics.CreateGauge(
+        "admin_logs_queue",
+        "How many logs are in the queue.");
+
+    private static readonly Gauge PreRoundQueue = Metrics.CreateGauge(
+        "admin_logs_pre_round_queue",
+        "How many logs are in the pre-round queue.");
+
     private static readonly Gauge QueueCapReached = Metrics.CreateGauge(
         "admin_logs_queue_cap_reached",
         "Number of times the log queue cap has been reached in a round.");
 
+    private static readonly Gauge PreRoundQueueCapReached = Metrics.CreateGauge(
+        "admin_logs_queue_cap_reached",
+        "Number of times the pre-round log queue cap has been reached in a round.");
+
     private static readonly Gauge LogsSent = Metrics.CreateGauge(
         "admin_logs_sent",
         "Amount of logs sent to the database in a round.");
@@ -54,10 +66,12 @@ public partial class AdminLogSystem : SharedAdminLogSystem
     private bool _metricsEnabled;
     private TimeSpan _queueSendDelay;
     private int _queueMax;
+    private int _preRoundQueueMax;
 
     // Per update
     private float _accumulatedFrameTime;
-    private readonly ConcurrentQueue<QueuedLog> _logsToAdd = new();
+    private readonly ConcurrentQueue<QueuedLog> _logQueue = new();
+    private readonly ConcurrentQueue<QueuedLog> _preRoundLogQueue = new();
 
     private int CurrentRoundId => _gameTicker.RoundId;
 
@@ -75,9 +89,12 @@ public partial class AdminLogSystem : SharedAdminLogSystem
             value => _queueSendDelay = TimeSpan.FromSeconds(value), true);
         _configuration.OnValueChanged(CCVars.AdminLogsQueueMax,
             value => _queueMax = value, true);
+        _configuration.OnValueChanged(CCVars.AdminLogsPreRoundQueueMax,
+            value => _preRoundQueueMax = value, true);
 
         if (_metricsEnabled)
         {
+            PreRoundQueueCapReached.Set(0);
             QueueCapReached.Set(0);
             LogsSent.Set(0);
         }
@@ -89,33 +106,95 @@ public partial class AdminLogSystem : SharedAdminLogSystem
     {
         base.Shutdown();
 
-        if (!_logsToAdd.IsEmpty)
+        if (!_logQueue.IsEmpty)
         {
-            await SendLogs();
+            await SaveLogs();
         }
     }
 
     public override async void Update(float frameTime)
     {
-        var count = _logsToAdd.Count;
+        if (_gameTicker.RunLevel == GameRunLevel.PreRoundLobby)
-        if (count == 0)
+        {
+            await PreRoundUpdate();
+            return;
+        }
+
+        var count = _logQueue.Count;
+        Queue.Set(count);
+
+        var preRoundCount = _preRoundLogQueue.Count;
+        PreRoundQueue.Set(preRoundCount);
+
+        if (count + preRoundCount == 0)
         {
             return;
         }
 
-        if (count < _queueMax && _accumulatedFrameTime < _queueSendDelay.TotalSeconds)
+        if (_accumulatedFrameTime >= _queueSendDelay.TotalSeconds)
         {
-            _accumulatedFrameTime += frameTime;
+            await SaveLogs();
             return;
         }
 
-        await SendLogs();
+        if (count >= _queueMax)
+        {
+            if (_metricsEnabled)
+            {
+                QueueCapReached.Inc();
+            }
+
+            _sawmill.Warning($"Maximum cap of {_queueMax} reached for admin logs.");
+            await SaveLogs();
+            return;
+        }
+
+        _accumulatedFrameTime += frameTime;
     }
 
-    private async Task SendLogs()
+    private async Task PreRoundUpdate()
     {
-        var copy = new List<QueuedLog>(_logsToAdd);
+        var preRoundCount = _preRoundLogQueue.Count;
-        _logsToAdd.Clear();
+        PreRoundQueue.Set(preRoundCount);
+
+        if (preRoundCount < _preRoundQueueMax)
+        {
+            return;
+        }
+
+        if (_metricsEnabled)
+        {
+            PreRoundQueueCapReached.Inc();
+        }
+
+        _sawmill.Warning($"Maximum cap of {_preRoundQueueMax} reached for pre-round admin logs.");
+        await SaveLogs();
+    }
+
+    private async Task SaveLogs()
+    {
+        var copy = new List<QueuedLog>(_logQueue.Count + _preRoundLogQueue.Count);
+
+        copy.AddRange(_logQueue);
+        _logQueue.Clear();
+        Queue.Set(0);
+
+        if (_gameTicker.RunLevel == GameRunLevel.PreRoundLobby)
+        {
+            _sawmill.Error($"Dropping {_preRoundLogQueue.Count} pre-round logs. Current cap: {_preRoundQueueMax}");
+        }
+        else
+        {
+            foreach (var queued in _preRoundLogQueue)
+            {
+                queued.Log.RoundId = _gameTicker.RoundId;
+            }
+
+            copy.AddRange(_preRoundLogQueue);
+        }
+        _preRoundLogQueue.Clear();
+        PreRoundQueue.Set(0);
+
         _accumulatedFrameTime = 0;
 
         // ship the logs to Azkaban
@@ -124,13 +203,10 @@ public partial class AdminLogSystem : SharedAdminLogSystem
             await _db.AddAdminLogs(copy);
         });
 
+        _sawmill.Debug($"Saving {copy.Count} admin logs.");
+
         if (_metricsEnabled)
         {
-            if (copy.Count >= _queueMax)
-            {
-                QueueCapReached.Inc();
-            }
-
             LogsSent.Inc(copy.Count);
 
             using (DatabaseUpdateTime.NewTimer())
@@ -147,6 +223,7 @@ public partial class AdminLogSystem : SharedAdminLogSystem
     {
         if (_metricsEnabled)
         {
+            PreRoundQueueCapReached.Set(0);
             QueueCapReached.Set(0);
             LogsSent.Set(0);
         }
@@ -166,7 +243,6 @@ public partial class AdminLogSystem : SharedAdminLogSystem
         };
 
         var queued = new QueuedLog(log, entities);
-        _logsToAdd.Enqueue(queued);
 
         foreach (var id in players)
         {
@@ -178,6 +254,15 @@ public partial class AdminLogSystem : SharedAdminLogSystem
 
             log.Players.Add(player);
         }
+
+        if (_gameTicker.RunLevel == GameRunLevel.PreRoundLobby)
+        {
+            _preRoundLogQueue.Enqueue(queued);
+        }
+        else
+        {
+            _logQueue.Enqueue(queued);
+        }
     }
 
     public override void Add(LogType type, LogImpact impact, ref LogStringHandler handler)

Content.Shared/CCVar/CCVars.cs

@@ -304,6 +304,9 @@ namespace Content.Shared.CCVar
         public static readonly CVarDef<int> AdminLogsQueueMax =
             CVarDef.Create("adminlogs.queue_max", 5000, CVar.SERVERONLY);
 
+        public static readonly CVarDef<int> AdminLogsPreRoundQueueMax =
+            CVarDef.Create("adminlogs.pre_round_queue_max", 5000, CVar.SERVERONLY);
+
         // How many logs to send to the client at once
         public static readonly CVarDef<int> AdminLogsClientBatchSize =
             CVarDef.Create("adminlogs.client_batch_size", 1000, CVar.SERVERONLY);