diff --git a/Content.IntegrationTests/Tests/Administration/Logs/AddTests.cs b/Content.IntegrationTests/Tests/Administration/Logs/AddTests.cs index f327287bd1..121eb5740b 100644 --- a/Content.IntegrationTests/Tests/Administration/Logs/AddTests.cs +++ b/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 () => - { - var filter = new LogFilter - { - Round = log.RoundId, - Search = log.Message, - Types = new List {log.Type}, - }; + Round = log.RoundId, + Search = log.Message, + Types = new List {log.Type}, + }; - await foreach (var json in sDatabase.GetAdminLogsJson(filter)) - { - var root = json.RootElement; + 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); + Assert.That(root.TryGetProperty("entity", out _), Is.True); + Assert.That(root.TryGetProperty("guid", out _), Is.True); - json.Dispose(); - } - }).Wait(); - }); + json.Dispose(); + } } [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(); + var sEntities = server.ResolveDependency(); + var sMaps = server.ResolveDependency(); + var sSystems = server.ResolveDependency(); + + var sAdminLogSystem = sSystems.GetEntitySystem(); + var sGamerTicker = sSystems.GetEntitySystem(); + + 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 {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(); + } + } } diff --git a/Content.IntegrationTests/Tests/Administration/Logs/FilterTests.cs b/Content.IntegrationTests/Tests/Administration/Logs/FilterTests.cs index d0e09e8819..25abba9eee 100644 --- a/Content.IntegrationTests/Tests/Administration/Logs/FilterTests.cs +++ b/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 () => diff --git a/Content.IntegrationTests/Tests/Administration/Logs/QueryTests.cs b/Content.IntegrationTests/Tests/Administration/Logs/QueryTests.cs index 46b6d17a30..8a1fff83f0 100644 --- a/Content.IntegrationTests/Tests/Administration/Logs/QueryTests.cs +++ b/Content.IntegrationTests/Tests/Administration/Logs/QueryTests.cs @@ -34,7 +34,7 @@ public class QueryTests : ContentIntegrationTest var sPlayers = server.ResolveDependency(); var sAdminLogSystem = sSystems.GetEntitySystem(); - var sGameTicker = sSystems.GetEntitySystem(); + var sGamerTicker = sSystems.GetEntitySystem(); 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.Unknown}, After = date, diff --git a/Content.Server/Administration/Logs/AdminLogSystem.Json.cs b/Content.Server/Administration/Logs/AdminLogSystem.Json.cs index 5a1f764ed1..098f88b5c0 100644 --- a/Content.Server/Administration/Logs/AdminLogSystem.Json.cs +++ b/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 players, List<(int id, string? name)> entities) ToJson( @@ -82,5 +82,4 @@ public partial class AdminLogSystem return (JsonSerializer.SerializeToDocument(parsed, _jsonOptions), players, entities); } - } diff --git a/Content.Server/Administration/Logs/AdminLogSystem.cs b/Content.Server/Administration/Logs/AdminLogSystem.cs index 956e7db49c..c5f2001844 100644 --- a/Content.Server/Administration/Logs/AdminLogSystem.cs +++ b/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 _logsToAdd = new(); + private readonly ConcurrentQueue _logQueue = new(); + private readonly ConcurrentQueue _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 (count == 0) + if (_gameTicker.RunLevel == GameRunLevel.PreRoundLobby) + { + 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(_logsToAdd); - _logsToAdd.Clear(); + var preRoundCount = _preRoundLogQueue.Count; + 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(_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) diff --git a/Content.Shared/CCVar/CCVars.cs b/Content.Shared/CCVar/CCVars.cs index 5d7844e95f..f18d88ed82 100644 --- a/Content.Shared/CCVar/CCVars.cs +++ b/Content.Shared/CCVar/CCVars.cs @@ -304,6 +304,9 @@ namespace Content.Shared.CCVar public static readonly CVarDef AdminLogsQueueMax = CVarDef.Create("adminlogs.queue_max", 5000, CVar.SERVERONLY); + public static readonly CVarDef 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 AdminLogsClientBatchSize = CVarDef.Create("adminlogs.client_batch_size", 1000, CVar.SERVERONLY);