From 1968afccba942e6ba633e8f574374352125db69f Mon Sep 17 00:00:00 2001 From: clodanSPT Date: Thu, 29 May 2025 11:06:32 +0100 Subject: [PATCH] Fixes and logs (#301) * Added safety checks around dictionary lookups for Areas Stages * Added lots of debug logs for websocket handling * Removed debug comments --------- Co-authored-by: Alex --- .../Helpers/NotificationSendHelper.cs | 18 ++- .../Servers/WebSocketServer.cs | 43 ++++++- .../Ws/SptWebSocketConnectionHandler.cs | 114 ++++++++++++++++-- .../Services/CircleOfCultistService.cs | 6 +- 4 files changed, 162 insertions(+), 19 deletions(-) diff --git a/Libraries/SPTarkov.Server.Core/Helpers/NotificationSendHelper.cs b/Libraries/SPTarkov.Server.Core/Helpers/NotificationSendHelper.cs index 3b477876..59e44d51 100644 --- a/Libraries/SPTarkov.Server.Core/Helpers/NotificationSendHelper.cs +++ b/Libraries/SPTarkov.Server.Core/Helpers/NotificationSendHelper.cs @@ -2,20 +2,24 @@ using SPTarkov.DI.Annotations; using SPTarkov.Server.Core.Models.Eft.Profile; using SPTarkov.Server.Core.Models.Eft.Ws; using SPTarkov.Server.Core.Models.Enums; +using SPTarkov.Server.Core.Models.Utils; using SPTarkov.Server.Core.Servers; using SPTarkov.Server.Core.Servers.Ws; using SPTarkov.Server.Core.Services; using SPTarkov.Server.Core.Utils; +using LogLevel = SPTarkov.Server.Core.Models.Spt.Logging.LogLevel; namespace SPTarkov.Server.Core.Helpers; [Injectable] public class NotificationSendHelper( + ISptLogger _logger, SptWebSocketConnectionHandler _sptWebSocketConnectionHandler, HashUtil _hashUtil, SaveServer _saveServer, NotificationService _notificationService, - TimeUtil _timeUtil + TimeUtil _timeUtil, + JsonUtil _jsonUtil ) { /// @@ -25,12 +29,24 @@ public class NotificationSendHelper( /// public void SendMessage(string sessionID, WsNotificationEvent notificationMessage) { + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"Send message for {sessionID} started, message: {_jsonUtil.Serialize(notificationMessage)}"); + } if (_sptWebSocketConnectionHandler.IsWebSocketConnected(sessionID)) { + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"Send message for {sessionID} websocket available, message being sent"); + } _sptWebSocketConnectionHandler.SendMessage(sessionID, notificationMessage); } else { + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"Send message for {sessionID} websocket not available, queuing into profile"); + } _notificationService.Add(sessionID, notificationMessage); } } diff --git a/Libraries/SPTarkov.Server.Core/Servers/WebSocketServer.cs b/Libraries/SPTarkov.Server.Core/Servers/WebSocketServer.cs index 5e1bf900..749827ff 100644 --- a/Libraries/SPTarkov.Server.Core/Servers/WebSocketServer.cs +++ b/Libraries/SPTarkov.Server.Core/Servers/WebSocketServer.cs @@ -27,15 +27,20 @@ public class WebSocketServer( var cts = new CancellationTokenSource(); var wsToken = cts.Token; + var message = $"Socket connection received for url {context.Request.Path.Value}, but there is no websocket handler configured for it!"; + _logger.Debug(message); if (socketHandlers.Count == 0) { - var message = $"Socket connection received for url {context.Request.Path.Value}, but there is no websocket handler configured for it!"; await webSocket.CloseAsync(WebSocketCloseStatus.ProtocolError, message, CancellationToken.None); return; } var sessionIdContext = DateTime.UtcNow.ToString("yyyyMMddHHmmssfff"); + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"[WS] Notifying handlers of new websocket connection openning with reference {sessionIdContext}"); + } foreach (var wsh in socketHandlers) { if (webSocket.State == WebSocketState.Open) @@ -49,8 +54,12 @@ public class WebSocketServer( await wsh.OnConnection(webSocket, context, sessionIdContext); } + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"[WS] Starting read loop for websocket reference {sessionIdContext}"); + } // Discard this task, we dont need to await it. - _ = Task.Factory.StartNew(async () => + var thread = Task.Factory.StartNew(async () => { while (!wsToken.IsCancellationRequested) { @@ -64,6 +73,10 @@ public class WebSocketServer( isEndOfMessage = readTask.EndOfMessage; } + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"[WS] Read loop for websocket reference {sessionIdContext} received new message. Notifying socket handlers."); + } foreach (var wsh in socketHandlers) { await wsh.OnMessage(messageBuffer.ToArray(), WebSocketMessageType.Text, webSocket, context); @@ -71,17 +84,43 @@ public class WebSocketServer( } }, TaskCreationOptions.LongRunning); + var counter = 0; while (webSocket.State == WebSocketState.Open) { + if (counter == 30 && _logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"[WS] Websocket keep alive for reference {sessionIdContext}. Thread state {thread.Status}. Websocket state {webSocket.State}"); + counter = 0; + } + else + { + counter++; + } // Keep this thread sleeping unless this status changes. Thread.Sleep(1000); } + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"[WS] State for websocket reference {sessionIdContext} is now {webSocket.State}, calling closing"); + } // Disconnect has been received, cancel the token and send OnClose to the relevant WebSockets. foreach (var wsh in socketHandlers) { + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"[WS] Cancellation token for websocket reference {sessionIdContext} requested"); + } await cts.CancelAsync(); + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"[WS] OnClose for websocket reference {sessionIdContext} requested"); + } await wsh.OnClose(webSocket, context, sessionIdContext); } + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"[WS] Websocket reference {sessionIdContext} fully closed."); + } } } diff --git a/Libraries/SPTarkov.Server.Core/Servers/Ws/SptWebSocketConnectionHandler.cs b/Libraries/SPTarkov.Server.Core/Servers/Ws/SptWebSocketConnectionHandler.cs index 55c3a216..51b1a637 100644 --- a/Libraries/SPTarkov.Server.Core/Servers/Ws/SptWebSocketConnectionHandler.cs +++ b/Libraries/SPTarkov.Server.Core/Servers/Ws/SptWebSocketConnectionHandler.cs @@ -12,16 +12,52 @@ using LogLevel = SPTarkov.Server.Core.Models.Spt.Logging.LogLevel; namespace SPTarkov.Server.Core.Servers.Ws; [Injectable(InjectionType.Singleton)] -public class SptWebSocketConnectionHandler( - ISptLogger _logger, - LocalisationService _localisationService, - JsonUtil _jsonUtil, - ProfileHelper _profileHelper, - IEnumerable _messageHandlers -) : IWebSocketConnectionHandler +public class SptWebSocketConnectionHandler : IWebSocketConnectionHandler { protected Dictionary> _sockets = new(); protected Lock _socketsLock = new(); + protected ISptLogger _logger; + protected LocalisationService _localisationService; + protected JsonUtil _jsonUtil; + protected ProfileHelper _profileHelper; + protected IEnumerable _messageHandlers; + protected Task _monitor; + + public SptWebSocketConnectionHandler( + ISptLogger logger, + LocalisationService localisationService, + JsonUtil jsonUtil, + ProfileHelper profileHelper, + IEnumerable messageHandlers + ) + { + _logger = logger; + _localisationService = localisationService; + _jsonUtil = jsonUtil; + _profileHelper = profileHelper; + _messageHandlers = messageHandlers; + StartMonitorThread(); + } + + private void StartMonitorThread() + { + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + if (_monitor == null) + { + _monitor = Task.Factory.StartNew(() => + { + _logger.Debug("Websocket monitor started"); + while (true) + { + // This is a temporary debug line, its horrible I know, its gonna be removed when we figure out the WS issue + _logger.Debug($"Sockets: {string.Join(',', _sockets.Select(kp => $"SESSID={kp.Key},SOCK=[{string.Join(',', kp.Value.Select(sess => $"CTX={sess.Key},WS={sess.Value.State}"))}]"))}"); + Thread.Sleep(10000); + } + }, TaskCreationOptions.LongRunning); + } + } + } public string GetHookUrl() { @@ -39,6 +75,11 @@ public class SptWebSocketConnectionHandler( var sessionID = splitUrl.Last(); var playerProfile = _profileHelper.GetFullProfile(sessionID); var playerInfoText = $"{playerProfile.ProfileInfo.Username} ({sessionID})"; + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"[WS] Websocket connect for player {playerInfoText} started with context {sessionIdContext}"); + } + lock (_socketsLock) { if (_sockets.TryGetValue(sessionID, out var sessionSockets) && sessionSockets.Any()) @@ -52,10 +93,16 @@ public class SptWebSocketConnectionHandler( { if (_logger.IsLogEnabled(LogLevel.Debug)) { - _logger.Debug($"[ws] Removing websocket reference {oldSocket.Key} for session {sessionID}"); + _logger.Debug($"[WS] Removing websocket reference {oldSocket.Key} for session {sessionID}"); } - oldSocket.Value.CloseAsync(WebSocketCloseStatus.NormalClosure, string.Empty, CancellationToken.None).Wait(); + oldSocket.Value.CloseAsync(WebSocketCloseStatus.NormalClosure, string.Empty, CancellationToken.None) + .Wait(); + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug( + $"[WS] Web socket connection for reference {oldSocket.Key} for session {sessionID} closed"); + } } sessionSockets.Clear(); @@ -80,10 +127,15 @@ public class SptWebSocketConnectionHandler( byte[] receivedMessage, WebSocketMessageType messageType, WebSocket ws, - HttpContext context) + HttpContext context + ) { var splitUrl = context.Request.Path.Value.Split("/"); var sessionID = splitUrl.Last(); + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"[WS] Message for session {sessionID} received. Notifying message handlers."); + } foreach (var sptWebSocketMessageHandler in _messageHandlers) { @@ -98,11 +150,23 @@ public class SptWebSocketConnectionHandler( lock (_socketsLock) { + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"Attempting to close websocket session {sessionID} with context {sessionIdContext}"); + } + if (_sockets.TryGetValue(sessionID, out var sessionSockets) && sessionSockets.Any()) { + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug( + $"Websockets for session {sessionID} entry matched, attempting to find context {sessionIdContext}"); + } + if (!sessionSockets.TryGetValue(sessionIdContext, out _) && _logger.IsLogEnabled(LogLevel.Info)) { - _logger.Info($"[ws] The websocket session {sessionID} with reference {sessionIdContext} has already been removed or reconnected"); + _logger.Info( + $"[ws] The websocket session {sessionID} with reference {sessionIdContext} has already been removed or reconnected"); } else { @@ -115,6 +179,14 @@ public class SptWebSocketConnectionHandler( } } } + else + { + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug( + $"Websocket for session {sessionID} with context {sessionIdContext} does not exist on the socket map, nothing was removed"); + } + } } } @@ -126,6 +198,12 @@ public class SptWebSocketConnectionHandler( { var webSockets = GetSessionWebSocket(sessionID); + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug( + $"Send message for {sessionID} matched {webSockets.Count()} websockets. Messages being sent"); + } + foreach (var webSocket in webSockets) { var sendTask = webSocket.SendAsync( @@ -134,7 +212,16 @@ public class SptWebSocketConnectionHandler( true, CancellationToken.None ); + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"Send message for {sessionID} on websocket async started"); + } + sendTask.Wait(); + if (_logger.IsLogEnabled(LogLevel.Debug)) + { + _logger.Debug($"Send message for {sessionID} on websocket async finished"); + } } if (_logger.IsLogEnabled(LogLevel.Debug)) @@ -160,7 +247,8 @@ public class SptWebSocketConnectionHandler( { lock (_socketsLock) { - return _sockets.TryGetValue(sessionID, out var sockets) && sockets.Any(s => s.Value.State == WebSocketState.Open); + return _sockets.TryGetValue(sessionID, out var sockets) && + sockets.Any(s => s.Value.State == WebSocketState.Open); } } @@ -168,7 +256,7 @@ public class SptWebSocketConnectionHandler( { lock (_socketsLock) { - return _sockets.GetValueOrDefault(sessionID)?.Values.Where(s => s.State == WebSocketState.Open); + return _sockets.GetValueOrDefault(sessionID)?.Values.Where(s => s.State == WebSocketState.Open) ?? []; } } } diff --git a/Libraries/SPTarkov.Server.Core/Services/CircleOfCultistService.cs b/Libraries/SPTarkov.Server.Core/Services/CircleOfCultistService.cs index 7c70a109..5317c2e7 100644 --- a/Libraries/SPTarkov.Server.Core/Services/CircleOfCultistService.cs +++ b/Libraries/SPTarkov.Server.Core/Services/CircleOfCultistService.cs @@ -763,9 +763,9 @@ public class CircleOfCultistService( var areaType = profileArea.Type; // Get next stage of area - var dbArea = dbAreas.FirstOrDefault(area => area.Type == areaType); - var nextStageDbData = dbArea?.Stages[(currentStageLevel + 1).ToString()]; - if (nextStageDbData is not null) + var dbArea = dbAreas?.FirstOrDefault(area => area.Type == areaType); + var nextTargetStageLevel = (currentStageLevel + 1).ToString() ?? ""; + if (dbArea?.Stages?.TryGetValue(nextTargetStageLevel, out var nextStageDbData) ?? false) { // Next stage exists, gather up requirements and add to pool var itemRequirements = GetItemRequirements(nextStageDbData.Requirements);