Rim/IW4M-Admin
Rim/IW4M-Admin
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases 30 Wiki Activity

fix rcon issue

Browse Source
This commit is contained in:
RaidMax 2022-04-25 15:39:30 -05:00
parent 3ad4aa2196
commit ff0d22c142
4 changed files with 77 additions and 44 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

12
Application/Misc/ScriptPlugin.cs
View File

@ -456,7 +456,7 @@ namespace IW4MAdmin.Application.Misc
private void GetDvarAsync(Server server, string dvarName, Delegate onCompleted) private void GetDvarAsync(Server server, string dvarName, Delegate onCompleted)
{ {
Task.Run<Task>(async () => Task.Run(() =>
{ {
var tokenSource = new CancellationTokenSource(); var tokenSource = new CancellationTokenSource();
tokenSource.CancelAfter(TimeSpan.FromSeconds(5)); tokenSource.CancelAfter(TimeSpan.FromSeconds(5));
@ -464,14 +464,14 @@ namespace IW4MAdmin.Application.Misc
var success = true; var success = true;
try try
{ {
result = (await server.GetDvarAsync<string>(dvarName, token: tokenSource.Token)).Value; result = server.GetDvarAsync<string>(dvarName, token: tokenSource.Token).GetAwaiter().GetResult().Value;
} }
catch catch
{ {
success = false; success = false;
} }
await _onProcessing.WaitAsync(); _onProcessing.Wait();
try try
{ {
onCompleted.DynamicInvoke(JsValue.Undefined, onCompleted.DynamicInvoke(JsValue.Undefined,
@ -495,7 +495,7 @@ namespace IW4MAdmin.Application.Misc
} }
private void SetDvarAsync(Server server, string dvarName, string dvarValue, Delegate onCompleted) private void SetDvarAsync(Server server, string dvarName, string dvarValue, Delegate onCompleted)
{ {
Task.Run<Task>(async () => Task.Run(() =>
{ {
var tokenSource = new CancellationTokenSource(); var tokenSource = new CancellationTokenSource();
tokenSource.CancelAfter(TimeSpan.FromSeconds(5)); tokenSource.CancelAfter(TimeSpan.FromSeconds(5));
@ -503,14 +503,14 @@ namespace IW4MAdmin.Application.Misc
try try
{ {
await server.SetDvarAsync(dvarName, dvarValue, tokenSource.Token); server.SetDvarAsync(dvarName, dvarValue, tokenSource.Token).GetAwaiter().GetResult();
} }
catch catch
{ {
success = false; success = false;
} }
await _onProcessing.WaitAsync(); _onProcessing.Wait();
try try
{ {
onCompleted.DynamicInvoke(JsValue.Undefined, onCompleted.DynamicInvoke(JsValue.Undefined,

105
Integrations/Cod/CodRConConnection.cs
View File

@ -33,7 +33,8 @@ namespace Integrations.Cod
private readonly Encoding _gameEncoding; private readonly Encoding _gameEncoding;
private readonly int _retryAttempts; private readonly int _retryAttempts;
public CodRConConnection(IPEndPoint ipEndpoint, string password, ILogger<CodRConConnection> log, Encoding gameEncoding, int retryAttempts) public CodRConConnection(IPEndPoint ipEndpoint, string password, ILogger<CodRConConnection> log,
Encoding gameEncoding, int retryAttempts)
{ {
RConPassword = password; RConPassword = password;
_gameEncoding = gameEncoding; _gameEncoding = gameEncoding;
@ -66,21 +67,31 @@ namespace Integrations.Cod
} }
finally finally
{ {
using (LogContext.PushProperty("Server", Endpoint.ToString()))
{
_log.LogDebug("Releasing OnComplete {Count}", ActiveQueries[Endpoint].OnComplete.CurrentCount);
}
if (ActiveQueries[Endpoint].OnComplete.CurrentCount == 0) if (ActiveQueries[Endpoint].OnComplete.CurrentCount == 0)
{ {
ActiveQueries[Endpoint].OnComplete.Release(); ActiveQueries[Endpoint].OnComplete.Release();
} }
} }
} }
private async Task<string[]> SendQueryAsyncInternal(StaticHelpers.QueryType type, string parameters = "", CancellationToken token = default) private async Task<string[]> SendQueryAsyncInternal(StaticHelpers.QueryType type, string parameters = "",
CancellationToken token = default)
{ {
if (!ActiveQueries.ContainsKey(Endpoint)) if (!ActiveQueries.ContainsKey(Endpoint))
{ {
ActiveQueries.TryAdd(Endpoint, new ConnectionState()); ActiveQueries.TryAdd(Endpoint, new ConnectionState());
} }
var connectionState = ActiveQueries[Endpoint]; if (!ActiveQueries.TryGetValue(Endpoint, out var connectionState))
{
_log.LogError("Could not retrieve connection state");
throw new InvalidOperationException("Could not get connection state");
}
_log.LogDebug("Waiting for semaphore to be released [{Endpoint}]", Endpoint); _log.LogDebug("Waiting for semaphore to be released [{Endpoint}]", Endpoint);
@ -91,6 +102,8 @@ namespace Integrations.Cod
} }
catch (OperationCanceledException) catch (OperationCanceledException)
{ {
_log.LogDebug("OnComplete did not complete before timeout {Count}",
connectionState.OnComplete.CurrentCount);
throw new RConException("Timed out waiting for access to rcon socket"); throw new RConException("Timed out waiting for access to rcon socket");
} }
@ -100,16 +113,20 @@ namespace Integrations.Cod
{ {
try try
{ {
await Task.Delay(_config.FloodProtectInterval - (int)timeSinceLastQuery, token); var delay = _config.FloodProtectInterval - (int)timeSinceLastQuery;
_log.LogDebug("Delaying for {Delay}ms", delay);
await Task.Delay(delay, token);
} }
catch (OperationCanceledException) catch (OperationCanceledException)
{ {
_log.LogDebug("Waiting for flood protect did not complete before timeout timeout {Count}",
connectionState.OnComplete.CurrentCount);
throw new RConException("Timed out waiting for flood protect to expire"); throw new RConException("Timed out waiting for flood protect to expire");
} }
} }
_log.LogDebug("Semaphore has been released [{Endpoint}]", Endpoint); _log.LogDebug("Semaphore has been released [{Endpoint}]", Endpoint);
_log.LogDebug("Query {@QueryInfo}", new { endpoint=Endpoint.ToString(), type, parameters }); _log.LogDebug("Query {@QueryInfo}", new { endpoint = Endpoint.ToString(), type, parameters });
byte[] payload = null; byte[] payload = null;
var waitForResponse = _config.WaitForResponse; var waitForResponse = _config.WaitForResponse;
@ -163,7 +180,6 @@ namespace Integrations.Cod
// e.g: emoji -> windows-1252 // e.g: emoji -> windows-1252
catch (OverflowException ex) catch (OverflowException ex)
{ {
using (LogContext.PushProperty("Server", Endpoint.ToString())) using (LogContext.PushProperty("Server", Endpoint.ToString()))
{ {
_log.LogError(ex, "Could not convert RCon data payload to desired encoding {Encoding} {Params}", _log.LogError(ex, "Could not convert RCon data payload to desired encoding {Encoding} {Params}",
@ -181,8 +197,8 @@ namespace Integrations.Cod
using (LogContext.PushProperty("Server", Endpoint.ToString())) using (LogContext.PushProperty("Server", Endpoint.ToString()))
{ {
_log.LogInformation( _log.LogInformation(
"Retrying RCon message ({ConnectionAttempts}/{AllowedConnectionFailures} attempts) with parameters {Payload}", "Retrying RCon message ({ConnectionAttempts}/{AllowedConnectionFailures} attempts) with parameters {Payload}",
connectionState.ConnectionAttempts, connectionState.ConnectionAttempts,
_retryAttempts, parameters); _retryAttempts, parameters);
} }
} }
@ -201,6 +217,7 @@ namespace Integrations.Cod
} }
catch (OperationCanceledException) catch (OperationCanceledException)
{ {
_log.LogDebug("OnSent did not complete in time");
throw new RConException("Timed out waiting for access to RCon send socket"); throw new RConException("Timed out waiting for access to RCon send socket");
} }
@ -211,14 +228,13 @@ namespace Integrations.Cod
} }
catch (OperationCanceledException) catch (OperationCanceledException)
{ {
throw new RConException("Timed out waiting for access to RCon receive socket"); _log.LogDebug("OnReceived did not complete in time");
}
finally
{
if (connectionState.OnSentData.CurrentCount == 0) if (connectionState.OnSentData.CurrentCount == 0)
{ {
connectionState.OnSentData.Release(); connectionState.OnSentData.Release();
} }
throw new RConException("Timed out waiting for access to RCon receive socket");
} }
connectionState.SendEventArgs.UserToken = new ConnectionUserToken connectionState.SendEventArgs.UserToken = new ConnectionUserToken
@ -242,6 +258,7 @@ namespace Integrations.Cod
if ((response?.Length == 0 || response[0].Length == 0) && waitForResponse) if ((response?.Length == 0 || response[0].Length == 0) && waitForResponse)
{ {
_log.LogDebug("0 bytes received from rcon request");
throw new RConException("Expected response but got 0 bytes back"); throw new RConException("Expected response but got 0 bytes back");
} }
@ -252,6 +269,7 @@ namespace Integrations.Cod
{ {
// if we timed out due to the cancellation token, // if we timed out due to the cancellation token,
// we don't want to count that as an attempt // we don't want to count that as an attempt
_log.LogDebug("OperationCanceledException when waiting for payload send to complete");
connectionState.ConnectionAttempts = 0; connectionState.ConnectionAttempts = 0;
} }
catch catch
@ -265,7 +283,8 @@ namespace Integrations.Cod
} }
catch (OperationCanceledException) catch (OperationCanceledException)
{ {
return Array.Empty<string>(); _log.LogDebug("OperationCancelled while waiting for retry");
throw;
} }
goto retrySend; goto retrySend;
@ -311,11 +330,13 @@ namespace Integrations.Cod
return Array.Empty<string>(); return Array.Empty<string>();
} }
var responseString = type == StaticHelpers.QueryType.COMMAND_STATUS ? var responseString = type == StaticHelpers.QueryType.COMMAND_STATUS
ReassembleSegmentedStatus(response) : RecombineMessages(response); ? ReassembleSegmentedStatus(response)
: RecombineMessages(response);
// note: not all games respond if the password is wrong or not set // note: not all games respond if the password is wrong or not set
if (responseString.Contains("Invalid password") || responseString.Contains("rconpassword")) if (responseString.Contains("Invalid password", StringComparison.InvariantCultureIgnoreCase) ||
responseString.Contains("rconpassword"))
{ {
throw new RConException(Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_RCON_INVALID"]); throw new RConException(Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_RCON_INVALID"]);
} }
@ -327,11 +348,14 @@ namespace Integrations.Cod
if (responseString.Contains(_config.ServerNotRunningResponse)) if (responseString.Contains(_config.ServerNotRunningResponse))
{ {
throw new ServerException(Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_NOT_RUNNING"].FormatExt(Endpoint.ToString())); throw new ServerException(Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_NOT_RUNNING"]
.FormatExt(Endpoint.ToString()));
} }
var responseHeaderMatch = Regex.Match(responseString, _config.CommandPrefixes.RConResponse).Value; var responseHeaderMatch = Regex.Match(responseString, _config.CommandPrefixes.RConResponse).Value;
var headerSplit = responseString.Split(type == StaticHelpers.QueryType.GET_INFO ? _config.CommandPrefixes.RconGetInfoResponseHeader : responseHeaderMatch); var headerSplit = responseString.Split(type == StaticHelpers.QueryType.GET_INFO
? _config.CommandPrefixes.RconGetInfoResponseHeader
: responseHeaderMatch);
if (headerSplit.Length != 2) if (headerSplit.Length != 2)
{ {
@ -369,7 +393,8 @@ namespace Integrations.Cod
else else
{ {
splitStatusStrings.Add(responseString.Replace(_config.CommandPrefixes.RConResponse, "").TrimEnd('\0')); splitStatusStrings.Add(responseString.Replace(_config.CommandPrefixes.RConResponse, "")
.TrimEnd('\0'));
} }
} }
@ -396,8 +421,10 @@ namespace Integrations.Cod
{ {
message = message.Replace(_config.CommandPrefixes.RConResponse, ""); message = message.Replace(_config.CommandPrefixes.RConResponse, "");
} }
builder.Append(message); builder.Append(message);
} }
builder.Append('\n'); builder.Append('\n');
return builder.ToString(); return builder.ToString();
} }
@ -410,6 +437,7 @@ namespace Integrations.Cod
if (rconSocket is null) if (rconSocket is null)
{ {
_log.LogDebug("Invalid state");
throw new InvalidOperationException("State is not valid for socket operation"); throw new InvalidOperationException("State is not valid for socket operation");
} }
@ -419,6 +447,7 @@ namespace Integrations.Cod
// setup the event handlers only once because we're reusing the event args // setup the event handlers only once because we're reusing the event args
connectionState.SendEventArgs.Completed += OnDataSent; connectionState.SendEventArgs.Completed += OnDataSent;
connectionState.ReceiveEventArgs.Completed += OnDataReceived; connectionState.ReceiveEventArgs.Completed += OnDataReceived;
connectionState.ReceiveEventArgs.UserToken = connectionState.SendEventArgs.UserToken;
connectionState.SendEventArgs.RemoteEndPoint = Endpoint; connectionState.SendEventArgs.RemoteEndPoint = Endpoint;
connectionState.ReceiveEventArgs.RemoteEndPoint = Endpoint; connectionState.ReceiveEventArgs.RemoteEndPoint = Endpoint;
connectionState.ReceiveEventArgs.DisconnectReuseSocket = true; connectionState.ReceiveEventArgs.DisconnectReuseSocket = true;
@ -435,15 +464,15 @@ namespace Integrations.Cod
// the send has not been completed asynchronously // the send has not been completed asynchronously
// this really shouldn't ever happen because it's UDP // this really shouldn't ever happen because it's UDP
var complete = await connectionState.OnSentData.WaitAsync(StaticHelpers.SocketTimeout(4), token); var complete = await connectionState.OnSentData.WaitAsync(StaticHelpers.SocketTimeout(4), token);
if (!complete) if (!complete)
{ {
using(LogContext.PushProperty("Server", Endpoint.ToString())) using (LogContext.PushProperty("Server", Endpoint.ToString()))
{ {
_log.LogWarning("Socket timed out while sending RCon data on attempt {Attempt}", _log.LogWarning("Socket timed out while sending RCon data on attempt {Attempt}",
connectionState.ConnectionAttempts); connectionState.ConnectionAttempts);
} }
rconSocket.Close(); rconSocket.Close();
throw new NetworkException("Timed out sending RCon data", rconSocket); throw new NetworkException("Timed out sending RCon data", rconSocket);
} }
@ -461,7 +490,8 @@ namespace Integrations.Cod
if (receiveDataPending) if (receiveDataPending)
{ {
_log.LogDebug("Waiting to asynchronously receive data on attempt #{ConnectionAttempts}", connectionState.ConnectionAttempts); _log.LogDebug("Waiting to asynchronously receive data on attempt #{ConnectionAttempts}",
connectionState.ConnectionAttempts);
var completed = false; var completed = false;
@ -493,6 +523,7 @@ namespace Integrations.Cod
} }
rconSocket.Close(); rconSocket.Close();
_log.LogDebug("OnDataReceived did not complete in allocated time");
throw new NetworkException("Timed out receiving RCon response", rconSocket); throw new NetworkException("Timed out receiving RCon response", rconSocket);
} }
} }
@ -521,13 +552,14 @@ namespace Integrations.Cod
private void OnDataReceived(object sender, SocketAsyncEventArgs e) private void OnDataReceived(object sender, SocketAsyncEventArgs e)
{ {
_log.LogDebug("Read {BytesTransferred} bytes from {Endpoint}", e.BytesTransferred, e.RemoteEndPoint?.ToString()); _log.LogDebug("Read {BytesTransferred} bytes from {Endpoint}", e.BytesTransferred,
e.RemoteEndPoint?.ToString());
// this occurs when we close the socket // this occurs when we close the socket
if (e.BytesTransferred == 0) if (e.BytesTransferred == 0)
{ {
_log.LogDebug("No bytes were transmitted so the connection was probably closed"); _log.LogDebug("No bytes were transmitted so the connection was probably closed");
var semaphore = ActiveQueries[Endpoint].OnReceivedData; var semaphore = ActiveQueries[Endpoint].OnReceivedData;
try try
@ -545,7 +577,7 @@ namespace Integrations.Cod
return; return;
} }
var state = ActiveQueries[Endpoint]; var state = ActiveQueries[Endpoint];
var cancellationRequested = ((ConnectionUserToken)e.UserToken)?.CancellationToken.IsCancellationRequested ?? var cancellationRequested = ((ConnectionUserToken)e.UserToken)?.CancellationToken.IsCancellationRequested ??
false; false;
@ -566,12 +598,12 @@ namespace Integrations.Cod
// ignored because we can have the socket operation cancelled (which releases the semaphore) but // ignored because we can have the socket operation cancelled (which releases the semaphore) but
// this thread is not notified because it's an event // this thread is not notified because it's an event
} }
return; return;
} }
state.BytesReadPerSegment.Add(e.BytesTransferred); state.BytesReadPerSegment.Add(e.BytesTransferred);
// I don't even want to know why this works for getting more data from Cod4x // I don't even want to know why this works for getting more data from Cod4x
// but I'm leaving it in here as long as it doesn't break anything. // but I'm leaving it in here as long as it doesn't break anything.
// it's very stupid... // it's very stupid...
@ -582,7 +614,7 @@ namespace Integrations.Cod
var totalBytesTransferred = e.BytesTransferred; var totalBytesTransferred = e.BytesTransferred;
_log.LogDebug("{Total} total bytes transferred with {Available} bytes remaining", totalBytesTransferred, _log.LogDebug("{Total} total bytes transferred with {Available} bytes remaining", totalBytesTransferred,
sock.Available); sock.Available);
// we still have available data so the payload was segmented // we still have available data so the payload was segmented
while (sock.Available > 0) while (sock.Available > 0)
{ {
@ -596,17 +628,17 @@ namespace Integrations.Cod
bufferSpaceAvailable); bufferSpaceAvailable);
continue; continue;
} }
state.ReceiveEventArgs.SetBuffer(state.ReceiveBuffer, totalBytesTransferred, sock.Available); state.ReceiveEventArgs.SetBuffer(state.ReceiveBuffer, totalBytesTransferred, sock.Available);
if (sock.ReceiveAsync(state.ReceiveEventArgs)) if (sock.ReceiveAsync(state.ReceiveEventArgs))
{ {
_log.LogDebug("Remaining bytes are async"); _log.LogDebug("Remaining bytes are async");
continue; continue;
} }
_log.LogDebug("Read {BytesTransferred} synchronous bytes from {Endpoint}", _log.LogDebug("Read {BytesTransferred} synchronous bytes from {Endpoint}",
state.ReceiveEventArgs.BytesTransferred, e.RemoteEndPoint?.ToString()); state.ReceiveEventArgs.BytesTransferred, e.RemoteEndPoint?.ToString());
// we need to increment this here because the callback isn't executed if there's no pending IO // we need to increment this here because the callback isn't executed if there's no pending IO
state.BytesReadPerSegment.Add(state.ReceiveEventArgs.BytesTransferred); state.BytesReadPerSegment.Add(state.ReceiveEventArgs.BytesTransferred);
totalBytesTransferred += state.ReceiveEventArgs.BytesTransferred; totalBytesTransferred += state.ReceiveEventArgs.BytesTransferred;
@ -638,8 +670,9 @@ namespace Integrations.Cod
private void OnDataSent(object sender, SocketAsyncEventArgs e) private void OnDataSent(object sender, SocketAsyncEventArgs e)
{ {
_log.LogDebug("Sent {ByteCount} bytes to {Endpoint}", e.Buffer?.Length, e.ConnectSocket?.RemoteEndPoint?.ToString()); _log.LogDebug("Sent {ByteCount} bytes to {Endpoint}", e.Buffer?.Length,
e.ConnectSocket?.RemoteEndPoint?.ToString());
var semaphore = ActiveQueries[Endpoint].OnSentData; var semaphore = ActiveQueries[Endpoint].OnSentData;
try try
{ {

2
Integrations/Cod/ConnectionState.cs
View File

@ -20,7 +20,7 @@ namespace Integrations.Cod
public int ConnectionAttempts { get; set; } public int ConnectionAttempts { get; set; }
private const int BufferSize = 16384; private const int BufferSize = 16384;
public readonly byte[] ReceiveBuffer = new byte[BufferSize]; public readonly byte[] ReceiveBuffer = new byte[BufferSize];
public readonly SemaphoreSlim OnComplete = new SemaphoreSlim(1, 1); public readonly SemaphoreSlim OnComplete = new(1, 1);
public readonly SemaphoreSlim OnSentData = new(1, 1); public readonly SemaphoreSlim OnSentData = new(1, 1);
public readonly SemaphoreSlim OnReceivedData = new (1, 1); public readonly SemaphoreSlim OnReceivedData = new (1, 1);

2
Plugins/ScriptPlugins/GameInterface.js
View File

@ -482,7 +482,7 @@ const pollForEvents = server => {
if (!state.waitingOnOutput) { if (!state.waitingOnOutput) {
if (state.queuedMessages.length === 0) { if (state.queuedMessages.length === 0) {
logger.WriteDebug('No messages in queue'); logger.WriteDebug('No messages in queue');
return;`` return;
} }
state.waitingOnOutput = true; state.waitingOnOutput = true;