private void HandlePacket(ReadOnlySequence <byte> buffer, MCConnectionContext ctx, IPacketQueue packetQueue)
{
var reader = _packetReaderFactory.CreateReader(buffer);
var length = reader.ReadVarInt();
if (length > reader.Buffer.Length || length < 1 /* 1 = small ID but no fields*/)
{
_logger.LogCritical($"Read Invalid length {length:X}. Aborting");
ctx.Abort();
return;
}
var lengthLength = buffer.Length - reader.Buffer.Length;
reader = new MCPacketReader(reader.Buffer.Slice(0, length));
var id = reader.ReadVarInt();
using var packetIdScope = _logger.BeginScope($"Packet ID: {id:x2}");
_packetHandler.HandlePacket(ctx, reader, packetQueue, id);
// NOT IDEAL, but easiest
var packetSize = length + lengthLength;
ctx.Transport.Input.AdvanceTo(buffer.GetPosition(packetSize));
_metrics.Measure.Histogram.Update(MetricsRegistry.ReadPacketSize, packetSize);
}
public async Task <ILog> Listen()
{
ILog error = null;
while (clientState.Connected)
{
try
{
var buffer = new ArraySegment <byte>(new byte[64 * 1024 * 1024]);
int read = await socket.ReceiveAsync(buffer, SocketFlags.None);
if (read > 0)
{
Serializable.Packet packet = Serializable.Packet.Parser.ParseFrom(buffer.Take(read).ToArray());
packetHandler.HandlePacket(packet);
// MainThreadContext.RunOnMainThread(() => packetHandler.HandlePacket(packet));
}
}
catch (Exception e)
{
clientState.Connected = false;
if (socket == null)
{
return(null);
}
return(new Error("[TCP] " + e));
}
}
return(error);
}
public void HandlePacket(GSPacketIn packet)
{
int code = packet.Code;
Statistics.BytesIn += packet.Length;
Statistics.PacketsIn++;
IPacketHandler packetHandler = null;
if (code < m_packetHandlers.Length)
{
packetHandler = m_packetHandlers[code];
}
else if (log.IsErrorEnabled)
{
log.ErrorFormat("Received packet code is outside of m_packetHandlers array bounds! " + m_client.ToString());
log.Error(Marshal.ToHexDump(
String.Format("===> <{2}> Packet 0x{0:X2} (0x{1:X2}) length: {3} (ThreadId={4})", code, code ^ 168, m_client.TcpEndpoint, packet.Length, Thread.CurrentThread.ManagedThreadId),
packet.Buffer));
}
if (packetHandler != null)
{
long start = Environment.TickCount;
try
{
packetHandler.HandlePacket(m_client, packet);
}
catch (Exception e)
{
if (log.IsErrorEnabled)
{
string client = m_client.TcpEndpoint;
log.Error("Error while processing packet (handler=" + packetHandler.GetType().FullName + " client: " + client + ")", e);
log.Error(Marshal.ToHexDump("Package Buffer:", packet.Buffer, 0, packet.Length));
}
}
long timeUsed = Environment.TickCount - start;
m_activePacketHandler = null;
if (log.IsDebugEnabled)
{
log.Debug("Package process Time:" + timeUsed + "ms!");
}
if (timeUsed > 1000)
{
string source = m_client.TcpEndpoint;
if (log.IsWarnEnabled)
{
log.Warn("(" + source + ") Handle packet Thread " + Thread.CurrentThread.ManagedThreadId + " " + packetHandler + " took " + timeUsed + "ms!");
}
}
}
}
public void Received(byte[] data)
{
if (!CheckVerify())
{
_session.Send(PacketFactory.CreateError("not verification"));
_session.Close();
return;
}
var package = PacketFactory.Create(data);
_packetHandler.HandlePacket(package);
}
/// <summary>
/// Parses a packet and gets a response packet from the handler
/// </summary>
/// <param name="packetHandler"></param>
/// <param name="sharedSecret"></param>
/// <param name="packetBytes"></param>
/// <param name="remoteEndpoint"></param>
/// <returns></returns>
internal IRadiusPacket GetResponsePacket(IPacketHandler packetHandler, string sharedSecret, byte[] packetBytes, IPEndPoint remoteEndpoint)
{
var requestPacket = RadiusPacketParser.Parse(packetBytes, Encoding.UTF8.GetBytes(sharedSecret));
//TODO log output here
//$"Received {requestPacket.Code} from {remoteEndpoint} Id={requestPacket.Identifier}"
//if logger in debug mode
//DumpPacket(requestPacket);
//TODO log output here
//packetBytes.ToHexString()
// Handle status server requests in server outside packet handler
if (requestPacket.Code == PacketCode.StatusServer)
{
var responseCode = ServerType == RadiusServerType.Authentication ? PacketCode.AccessAccept : PacketCode.AccountingResponse;
//TODO log output here
//$"Sending {responseCode} for StatusServer request from {remoteEndpoint}"
return(requestPacket.CreateResponsePacket(responseCode));
}
//TODO log output here
//$"Handling packet for remote ip {remoteEndpoint.Address} with {packetHandler.GetType()}"
var sw = Stopwatch.StartNew();
var responsePacket = packetHandler.HandlePacket(requestPacket);
sw.Stop();
//TODO log output here
//$"{remoteEndpoint} Id={responsePacket.Identifier}, Received {responsePacket.Code} from handler in {sw.ElapsedMilliseconds}ms"
//TODO log output here
//if (sw.ElapsedMilliseconds >= 5000)
//$"Slow response for Id {responsePacket.Identifier}, check logs"
if (requestPacket.Attributes.ContainsKey("Proxy-State"))
{
responsePacket.Attributes.Add("Proxy-State", requestPacket.Attributes.SingleOrDefault(o => o.Key == "Proxy-State").Value);
}
return(responsePacket);
}
public virtual void HandlePacket(int code, GamePacket packet)
{
if (packet == null)
{
log.Error("Packet is null!");
return;
}
IPacketHandler handler = null;
if (m_packagesHandlers.ContainsKey(code))
{
handler = m_packagesHandlers[code];
}
else
{
log.ErrorFormat("Receive package's code is not exists! Code: {0}", code);
log.Error(Marshal.ToHexDump(string.Format("Code: {0}", code), packet.Buffer, 0, packet.Length));
return;
}
long timeUsed = Environment.TickCount;
try
{
handler.HandlePacket(m_client, packet);
}
catch (Exception ex)
{
log.ErrorFormat("Error while processing package (handler={0})", handler.GetType().FullName);
log.Error("Handle package error!", ex);
}
timeUsed = Environment.TickCount - timeUsed;
log.InfoFormat("Package process time: {0}ms", timeUsed);
if (timeUsed > 1000)
{
log.WarnFormat("Handle package thread {0} {1} took {2}ms!", System.Threading.Thread.CurrentThread.ManagedThreadId, handler, timeUsed);
}
}
/// <summary>
/// Parses a packet and gets a response packet from the handler
/// </summary>
/// <param name="packetHandler"></param>
/// <param name="sharedSecret"></param>
/// <param name="packetBytes"></param>
/// <param name="remoteEndpoint"></param>
/// <returns></returns>
internal IRadiusPacket GetResponsePacket(IPacketHandler packetHandler, String sharedSecret, Byte[] packetBytes, IPEndPoint remoteEndpoint)
{
var requestPacket = RadiusPacket.Parse(packetBytes, _dictionary, Encoding.UTF8.GetBytes(sharedSecret));
_log.Info($"Received {requestPacket.Code} from {remoteEndpoint} Id={requestPacket.Identifier}");
if (_log.IsDebugEnabled)
{
DumpPacket(requestPacket);
}
_log.Debug(packetBytes.ToHexString());
// Handle status server requests in server outside packet handler
if (requestPacket.Code == PacketCode.StatusServer)
{
var responseCode = _serverType == RadiusServerType.Authentication ? PacketCode.AccessAccept : PacketCode.AccountingResponse;
_log.Debug($"Sending {responseCode} for StatusServer request from {remoteEndpoint}");
return(requestPacket.CreateResponsePacket(responseCode));
}
_log.Debug($"Handling packet for remote ip {remoteEndpoint.Address} with {packetHandler.GetType()}");
var sw = Stopwatch.StartNew();
var responsePacket = packetHandler.HandlePacket(requestPacket);
sw.Stop();
_log.Debug($"{remoteEndpoint} Id={responsePacket.Identifier}, Received {responsePacket.Code} from handler in {sw.ElapsedMilliseconds}ms");
if (sw.ElapsedMilliseconds >= 5000)
{
_log.Warn($"Slow response for Id {responsePacket.Identifier}, check logs");
}
if (requestPacket.Attributes.ContainsKey("Proxy-State"))
{
responsePacket.Attributes.Add("Proxy-State", requestPacket.Attributes.SingleOrDefault(o => o.Key == "Proxy-State").Value);
}
return(responsePacket);
}
/// <summary>
/// Handle the given packet
/// </summary>
/// <param name="packetID">Packet ID</param>
/// <param name="packetData">Packet contents</param>
/// <returns>TRUE if the packet was processed, FALSE if ignored or unknown</returns>
internal bool HandlePacket(Packet packet)
{
int packetID = packet.id;
List <byte> packetData = packet.data;
try
{
if (login_phase)
{
switch (packetID) //Packet IDs are different while logging in
{
case 0x03:
if (protocolversion >= (int)McVersion.V18)
{
connectionInfo.compressionThreshold = dataTypes.ReadNextVarInt(packetData);
}
break;
default:
return(false); //Ignored packet
}
}
return(packetHandler.HandlePacket(Protocol18PacketTypes.GetPacketIncomingType(packetID, protocolversion), packet.data));
}
catch (Exception innerException)
{
throw new System.IO.InvalidDataException(
String.Format("Failed to process incoming packet of type {0}. (PacketID: {1}, Protocol: {2}, LoginPhase: {3}, InnerException: {4}).",
Protocol18PacketTypes.GetPacketIncomingType(packetID, protocolversion),
packetID,
protocolversion,
login_phase,
innerException.GetType()),
innerException);
}
}
public void HandlePacket(GSPacketIn packet)
{
if (packet == null || m_client == null)
return;
int code = packet.ID;
Statistics.BytesIn += packet.PacketSize;
Statistics.PacketsIn++;
SavePacket(packet);
IPacketHandler packetHandler = null;
if (code < m_packetHandlers.Length)
{
packetHandler = m_packetHandlers[code];
}
else if (log.IsErrorEnabled)
{
log.ErrorFormat("Received packet code is outside of m_packetHandlers array bounds! " + m_client);
log.Error(Marshal.ToHexDump(
String.Format("===> <{2}> Packet 0x{0:X2} (0x{1:X2}) length: {3} (ThreadId={4})", code, code ^ 168,
(m_client.Account != null) ? m_client.Account.Name : m_client.TcpEndpoint,
packet.PacketSize, Thread.CurrentThread.ManagedThreadId),
packet.ToArray()));
}
// make sure we can handle this packet at this stage
var preprocess = m_packetPreprocessor.CanProcessPacket(m_client, packet);
if(!preprocess)
{
// this packet can't be processed by this client right now, for whatever reason
log.Info("PacketPreprocessor: Preprocessor prevents handling of a packet with packet.ID=" + packet.ID);
return;
}
if (packetHandler != null)
{
Timer monitorTimer = null;
if (log.IsDebugEnabled)
{
try
{
monitorTimer = new Timer(10000);
m_activePacketHandler = packetHandler;
m_handlerThreadID = Thread.CurrentThread.ManagedThreadId;
monitorTimer.Elapsed += HandlePacketTimeout;
monitorTimer.Start();
}
catch (Exception e)
{
if (log.IsErrorEnabled)
log.Error("Starting packet monitor timer", e);
if (monitorTimer != null)
{
monitorTimer.Stop();
monitorTimer.Close();
monitorTimer = null;
}
}
}
#if LOGACTIVESTACKS
//Put the current thread into the active thread list!
//No need to lock the hashtable since we created it
//synchronized! One reader, multiple writers supported!
m_activePacketThreads.Add(Thread.CurrentThread, m_client);
#endif
long start = Environment.TickCount;
try
{
packetHandler.HandlePacket(m_client, packet);
}
catch (Exception e)
{
if (log.IsErrorEnabled)
{
string client = (m_client == null ? "null" : m_client.ToString());
log.Error(
"Error while processing packet (handler=" + packetHandler.GetType().FullName + " client: " + client + ")", e);
}
}
#if LOGACTIVESTACKS
finally
{
//Remove the thread from the active list after execution
//No need to lock the hashtable since we created it
//synchronized! One reader, multiple writers supported!
m_activePacketThreads.Remove(Thread.CurrentThread);
}
#endif
long timeUsed = Environment.TickCount - start;
if (monitorTimer != null)
{
monitorTimer.Stop();
monitorTimer.Close();
}
m_activePacketHandler = null;
if (timeUsed > 1000)
{
string source = ((m_client.Account != null) ? m_client.Account.Name : m_client.TcpEndpoint);
if (log.IsWarnEnabled)
log.Warn("(" + source + ") Handle packet Thread " + Thread.CurrentThread.ManagedThreadId + " " + packetHandler +
" took " + timeUsed + "ms!");
}
}
}
public void HandlePacket(GSPacketIn packet)
{
if (packet == null || _client == null)
{
return;
}
int code = packet.ID;
Statistics.BytesIn += packet.PacketSize;
Statistics.PacketsIn++;
SavePacket(packet);
IPacketHandler packetHandler = null;
if (code < _packetHandlers.Length)
{
packetHandler = _packetHandlers[code];
}
else if (Log.IsErrorEnabled)
{
Log.Error($"Received packet code is outside of m_packetHandlers array bounds! {_client}");
Log.Error(Marshal.ToHexDump($"===> <{(_client.Account != null ? _client.Account.Name : _client.TcpEndpoint)}> Packet 0x{code:X2} (0x{code ^ 168:X2}) length: {packet.PacketSize} (ThreadId={Thread.CurrentThread.ManagedThreadId})", packet.ToArray()));
}
// make sure we can handle this packet at this stage
var preprocess = _packetPreprocessor.CanProcessPacket(_client, packet);
if (!preprocess)
{
// this packet can't be processed by this client right now, for whatever reason
Log.Info($"PacketPreprocessor: Preprocessor prevents handling of a packet with packet.ID={packet.ID}");
return;
}
if (packetHandler != null)
{
Timer monitorTimer = null;
if (Log.IsDebugEnabled)
{
try
{
monitorTimer = new Timer(10000);
_activePacketHandler = packetHandler;
_handlerThreadId = Thread.CurrentThread.ManagedThreadId;
monitorTimer.Elapsed += HandlePacketTimeout;
monitorTimer.Start();
}
catch (Exception e)
{
if (Log.IsErrorEnabled)
{
Log.Error("Starting packet monitor timer", e);
}
if (monitorTimer != null)
{
monitorTimer.Stop();
monitorTimer.Close();
monitorTimer = null;
}
}
}
#if LOGACTIVESTACKS
// Put the current thread into the active thread list!
// No need to lock the hashtable since we created it
// synchronized! One reader, multiple writers supported!
ActivePacketThreads.Add(Thread.CurrentThread, _client);
#endif
long start = Environment.TickCount;
try
{
packetHandler.HandlePacket(_client, packet);
}
catch (Exception e)
{
if (Log.IsErrorEnabled)
{
string client = _client?.ToString() ?? "null";
Log.Error($"Error while processing packet (handler={packetHandler.GetType().FullName} client: {client})", e);
}
}
#if LOGACTIVESTACKS
finally
{
// Remove the thread from the active list after execution
// No need to lock the hashtable since we created it
// synchronized! One reader, multiple writers supported!
ActivePacketThreads.Remove(Thread.CurrentThread);
}
#endif
long timeUsed = Environment.TickCount - start;
if (monitorTimer != null)
{
monitorTimer.Stop();
monitorTimer.Close();
}
_activePacketHandler = null;
if (timeUsed > 1000)
{
string source = _client.Account != null ? _client.Account.Name : _client.TcpEndpoint;
if (Log.IsWarnEnabled)
{
Log.Warn($"({source}) Handle packet Thread {Thread.CurrentThread.ManagedThreadId} {packetHandler} took {timeUsed}ms!");
}
}
}
}
public void HandlePacket(GSPacketIn packet)
{
int code = (int)packet.Code;
Statistics.BytesIn += (long)packet.Length;
Statistics.PacketsIn += 1L;
IPacketHandler packetHandler = null;
if (code < PacketProcessor.m_packetHandlers.Length)
{
packetHandler = PacketProcessor.m_packetHandlers[code];
}
else
{
{
PacketProcessor.log.ErrorFormat("Received packet code is outside of m_packetHandlers array bounds! " + this.m_client.ToString(), new object[0]);
PacketProcessor.log.Error(Marshal.ToHexDump(string.Format("===> <{2}> Packet 0x{0:X2} (0x{1:X2}) length: {3} (ThreadId={4})", new object[]
{
code,
code ^ 168,
this.m_client.TcpEndpoint,
packet.Length,
Thread.CurrentThread.ManagedThreadId
}), packet.Buffer));
}
}
if (packetHandler != null)
{
long start = (long)Environment.TickCount;
try
{
packetHandler.HandlePacket(this.m_client, packet);
}
catch (Exception e)
{
{
string client = this.m_client.TcpEndpoint;
PacketProcessor.log.Error(string.Concat(new string[]
{
"Error while processing packet (handler=",
packetHandler.GetType().FullName,
" client: ",
client,
")"
}), e);
PacketProcessor.log.Error(Marshal.ToHexDump("Package Buffer:", packet.Buffer, 0, packet.Length));
}
}
long timeUsed = (long)Environment.TickCount - start;
this.m_activePacketHandler = null;
if (timeUsed > 1000L)
{
string source = this.m_client.TcpEndpoint;
PacketProcessor.log.Warn(string.Concat(new object[]
{
"(",
source,
") Handle packet Thread ",
Thread.CurrentThread.ManagedThreadId,
" ",
packetHandler,
" took ",
timeUsed,
"ms!"
}));
}
}
}
public void HandlePacket(GSPacketIn packet)
{
int code = (int)packet.Code;
Statistics.BytesIn += (long)packet.Length;
Statistics.PacketsIn += 1L;
IPacketHandler packetHandler = null;
if (code < PacketProcessor.m_packetHandlers.Length)
{
packetHandler = PacketProcessor.m_packetHandlers[code];
Console.WriteLine(string.Concat(new object[]
{
"ClientID: " + packet.ClientID,
" received code: ",
code,
" <",
string.Format("0x{0:x}", code),
">"
}));
Console.WriteLine(" ==>" + packetHandler.ToString());
}
if (code < PacketProcessor.m_packetHandlers.Length)
{
packetHandler = PacketProcessor.m_packetHandlers[code];
try
{
packetHandler.ToString();
goto IL_157;
}
catch
{
Console.WriteLine("______________ERROR______________");
Console.WriteLine(string.Concat(new object[]
{
"___ Received code: ",
code,
" <",
string.Format("0x{0:x}", code),
"> ____"
}));
Console.WriteLine("_________________________________");
goto IL_157;
}
}
if (PacketProcessor.log.IsErrorEnabled)
{
PacketProcessor.log.ErrorFormat("Received packet code is outside of m_packetHandlers array bounds! " + this.m_client.ToString(), new object[0]);
PacketProcessor.log.Error(Marshal.ToHexDump(string.Format("===> <{2}> Packet 0x{0:X2} (0x{1:X2}) length: {3} (ThreadId={4})", new object[]
{
code,
code ^ 168,
this.m_client.TcpEndpoint,
packet.Length,
Thread.CurrentThread.ManagedThreadId
}), packet.Buffer));
}
IL_157:
if (packetHandler != null)
{
long num = (long)Environment.TickCount;
try
{
if (this.m_client != null && packet != null && this.m_client.TcpEndpoint != "not connected")
{
packetHandler.HandlePacket(this.m_client, packet);
}
}
catch (Exception exception)
{
if (PacketProcessor.log.IsErrorEnabled)
{
string tcpEndpoint = this.m_client.TcpEndpoint;
PacketProcessor.log.Error(string.Concat(new string[]
{
"Error while processing packet (handler=",
packetHandler.GetType().FullName,
" client: ",
tcpEndpoint,
")"
}), exception);
PacketProcessor.log.Error(Marshal.ToHexDump("Package Buffer:", packet.Buffer, 0, packet.Length));
}
}
long num2 = (long)Environment.TickCount - num;
this.m_activePacketHandler = null;
if (PacketProcessor.log.IsDebugEnabled)
{
PacketProcessor.log.Debug("Package process Time:" + num2 + "ms!");
}
if (num2 > 1000L)
{
string tcpEndpoint2 = this.m_client.TcpEndpoint;
if (PacketProcessor.log.IsWarnEnabled)
{
PacketProcessor.log.Warn(string.Concat(new object[]
{
"(",
tcpEndpoint2,
") Handle packet Thread ",
Thread.CurrentThread.ManagedThreadId,
" ",
packetHandler,
" took ",
num2,
"ms!"
}));
}
}
}
}
public void ExecuteHandler(IPacketHandler handler)
{
handler.HandlePacket(this);
}