chillcog/SPT-Server-Build
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Fixes and logs (#301)

Browse Source 
* Added safety checks around dictionary lookups for Areas Stages

* Added lots of debug logs for websocket handling

* Removed debug comments

---------

Co-authored-by: Alex <alex@dm-me-for-questions.com>
This commit is contained in:
clodanSPT
2025-05-29 11:06:32 +01:00
committed by GitHub
parent d079e86fcb
commit 1968afccba
4 changed files with 162 additions and 19 deletions
Download Patch File Download Diff File Expand all files Collapse all files
Libraries/SPTarkov.Server.Core/Helpers/NotificationSendHelper.cs
+17 -1
View File
@@ -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<NotificationSendHelper> _logger,
SptWebSocketConnectionHandler _sptWebSocketConnectionHandler,
HashUtil _hashUtil,
SaveServer _saveServer,
NotificationService _notificationService,
TimeUtil _timeUtil
TimeUtil _timeUtil,
JsonUtil _jsonUtil
)
{
/// <summary>
@@ -25,12 +29,24 @@ public class NotificationSendHelper(
/// <param name="notificationMessage"></param>
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);
}
}
Libraries/SPTarkov.Server.Core/Servers/WebSocketServer.cs
+41 -2
View File
@@ -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.");
}
}
}
Libraries/SPTarkov.Server.Core/Servers/Ws/SptWebSocketConnectionHandler.cs
+101 -13
View File
@@ -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<SptWebSocketConnectionHandler> _logger,
LocalisationService _localisationService,
JsonUtil _jsonUtil,
ProfileHelper _profileHelper,
IEnumerable<ISptWebSocketMessageHandler> _messageHandlers
) : IWebSocketConnectionHandler
public class SptWebSocketConnectionHandler : IWebSocketConnectionHandler
{
protected Dictionary<string, Dictionary<string, WebSocket>> _sockets = new();
protected Lock _socketsLock = new();
protected ISptLogger<SptWebSocketConnectionHandler> _logger;
protected LocalisationService _localisationService;
protected JsonUtil _jsonUtil;
protected ProfileHelper _profileHelper;
protected IEnumerable<ISptWebSocketMessageHandler> _messageHandlers;
protected Task _monitor;
public SptWebSocketConnectionHandler(
ISptLogger<SptWebSocketConnectionHandler> logger,
LocalisationService localisationService,
JsonUtil jsonUtil,
ProfileHelper profileHelper,
IEnumerable<ISptWebSocketMessageHandler> 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) ?? [];
}
}
}
Libraries/SPTarkov.Server.Core/Services/CircleOfCultistService.cs
+3 -3
View File
@@ -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);