Skip to content

Commit

Permalink
some logging changes
Browse files Browse the repository at this point in the history
  • Loading branch information
@jacksonrakena
jacksonrakena committed Dec 2, 2023
1 parent b4f50d1 commit b2cab0e
Show file tree
Hide file tree
Showing 4 changed files with 31 additions and 26 deletions.
32 changes: 16 additions & 16 deletions Common/Networking/Channels/ReliableChannel.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -58,7 +58,7 @@ public async Task<bool> ClearAsync(PeerBase peer)
private readonly NetworkPacket _outgoingAcks; //for send acks
private readonly PendingReliablePacket[] _pendingPackets; //for unacked packets and duplicates
private readonly NetworkPacket[]? _receivedPackets; //for order
private readonly bool[]? _earlyReceived; //for unordered
private readonly bool[] _earlyReceived; //for unordered

private int _localSequence;
private int _remoteSequence;
Expand Down Expand Up @@ -86,6 +86,7 @@ public ReliableChannel(PeerBase peer, bool ordered, byte id) : base(peer)
{
_deliveryMethod = DeliveryMethod.ReliableOrdered;
_receivedPackets = new NetworkPacket[_windowSize];
_earlyReceived = Array.Empty<bool>();
}
else
{
Expand Down Expand Up @@ -173,22 +174,22 @@ private async Task ProcessAckAsync(NetworkPacket packet)
}
}

SemaphoreSlim pendingPacketsSem = new SemaphoreSlim(1, 1);
SemaphoreSlim outgoingAcksSem = new SemaphoreSlim(1, 1);
readonly SemaphoreSlim _pendingPacketsSem = new SemaphoreSlim(1, 1);
readonly SemaphoreSlim _outgoingAcksSem = new SemaphoreSlim(1, 1);
protected override async Task<bool> FlushQueueAsync()
{
if (_mustSendAcks)
{
_mustSendAcks = false;
await outgoingAcksSem.WaitAsync();
await _outgoingAcksSem.WaitAsync();
try { await Peer.SendUserData(_outgoingAcks); }
finally { outgoingAcksSem.Release(); }
finally { _outgoingAcksSem.Release(); }
}

long currentTime = DateTime.UtcNow.Ticks;
bool hasPendingPackets = false;

await pendingPacketsSem.WaitAsync();
await _pendingPacketsSem.WaitAsync();
try
{
await outgoingQueueSem.WaitAsync();
Expand Down Expand Up @@ -225,7 +226,7 @@ protected override async Task<bool> FlushQueueAsync()
}
finally
{
pendingPacketsSem.Release();
_pendingPacketsSem.Release();
}

return hasPendingPackets || _mustSendAcks || OutgoingQueue.Count > 0;
Expand All @@ -243,7 +244,7 @@ public override async Task<bool> HandlePacketAsync(NetworkPacket packet)
int seq = packet.Sequence;
if (seq >= NetConstants.MaxSequence)
{
NetDebug.Write("[RR]Bad sequence");
Peer.LogDebug("[RR]Bad sequence");
return false;
}

Expand All @@ -252,34 +253,33 @@ public override async Task<bool> HandlePacketAsync(NetworkPacket packet)

if (relateSeq > _windowSize)
{
NetDebug.Write("[RR]Bad sequence");
Peer.LogDebug("[RR]Bad sequence");
return false;
}

//Drop bad packets
if (relate < 0)
{
//Too old packet doesn't ack
NetDebug.Write("[RR]ReliableInOrder too old");
Peer.LogDebug("[RR]ReliableInOrder too old");
return false;
}
if (relate >= _windowSize * 2)
{
//Some very new packet
NetDebug.Write("[RR]ReliableInOrder too new");
Peer.LogDebug("[RR]ReliableInOrder too new");
return false;
}

//If very new - move window
int ackIdx;
int ackByte;
int ackBit;
await outgoingAcksSem.WaitAsync();
await _outgoingAcksSem.WaitAsync();
try
{
if (relate >= _windowSize)
{
NetDebug.Write("New window position");
//New window position
int newWindowStart = (_remoteWindowStart + relate - _windowSize + 1) % NetConstants.MaxSequence;
_outgoingAcks.Sequence = (ushort)newWindowStart;
Expand All @@ -304,7 +304,7 @@ public override async Task<bool> HandlePacketAsync(NetworkPacket packet)
ackBit = ackIdx % BitsInByte;
if ((_outgoingAcks.Data[ackByte] & (1 << ackBit)) != 0)
{
NetDebug.Write("[RR]ReliableInOrder duplicate");
Peer.LogDebug("[RR]ReliableInOrder duplicate");
//because _mustSendAcks == true
AddToPeerChannelSendQueue();
return false;
Expand All @@ -315,15 +315,15 @@ public override async Task<bool> HandlePacketAsync(NetworkPacket packet)
}
finally
{
outgoingAcksSem.Release();
_outgoingAcksSem.Release();
}

AddToPeerChannelSendQueue();

//detailed check
if (seq == _remoteSequence)
{
NetDebug.Write("[RR]ReliableInOrder packet succes");
Peer.LogDebug($"Reliable packet of type {packet.Property} ({packet.Data.Count} bytes) received successfully");
await Peer.AddReliablePacket(_deliveryMethod, packet);
_remoteSequence = (_remoteSequence + 1) % NetConstants.MaxSequence;

Expand Down
20 changes: 13 additions & 7 deletions Common/Networking/Peers/PeerBase.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -334,7 +334,7 @@ private async Task SendInternal(
}

//Prepare
NetDebug.Write("[RS]Packet: " + property);
LogDebug($"{property} channel message queued ({data.Count} bytes, {deliveryMethod:G})");

//Check fragmentation
int headerSize = NetworkPacket.GetHeaderSize(property);
Expand Down Expand Up @@ -558,6 +558,7 @@ internal async Task AddReliablePacket(DeliveryMethod method, NetworkPacket p)
_holdedFragments.Remove(packetFragId);

//Send to process
LogDebug($"Reconstructed fragmented packet from {fragments.Length} fragments (size {resultingPacket.Data.Count})");
await PromulManager.CreateReceiveEvent(resultingPacket, method, (byte)(packetChannelId / NetConstants.ChannelTypeCount), 0, this);
}
else //Just simple packet
Expand Down Expand Up @@ -613,7 +614,7 @@ internal async Task ProcessPacket(NetworkPacket packet)
{
FastBitConverter.GetBytes(_pongPacket.Data.Array, _pongPacket.Data.Offset+3, DateTime.UtcNow.Ticks);
_pongPacket.Sequence = packet.Sequence;
NetDebug.Write($"[PING] Received ping #{packet.Sequence}. Sending pong.");
LogDebug($"[PING] Received ping #{packet.Sequence}. Sending pong.");
await PromulManager.RawSendAsync(_pongPacket, EndPoint);
}
break;
Expand All @@ -625,7 +626,7 @@ internal async Task ProcessPacket(NetworkPacket packet)
RemoteTimeDelta = BitConverter.ToInt64(packet.Data[3..]) + (elapsedMs * TimeSpan.TicksPerMillisecond ) / 2 - DateTime.UtcNow.Ticks;
UpdateRoundTripTime(elapsedMs);
await PromulManager.ConnectionLatencyUpdated(this, elapsedMs / 2);
NetDebug.Write($"[PING] Received pong #{packet.Sequence}. Time: {elapsedMs}ms. Delta time: {RemoteTimeDelta}");
LogDebug($"[PING] Received pong #{packet.Sequence}. Time: {elapsedMs}ms. Delta time: {RemoteTimeDelta}");
}
break;
case PacketProperty.Ack:
Expand Down Expand Up @@ -664,8 +665,8 @@ internal async Task SendUserData(NetworkPacket packet)
const int splitThreshold = 20;
//if (mergedPacketSize + splitThreshold >= MaximumTransferUnit)
//{
NetDebug.Write("[P]SendingPacket: " + packet.Property);
await PromulManager.RawSendAsync(packet, EndPoint);
LogDebug($"[Send] Sent {packet.Data.Count} bytes with type {packet.Property}.");
return;
//}
// if (_mergePos + mergedPacketSize > MaximumTransferUnit) await SendMerged();
Expand All @@ -683,7 +684,7 @@ private async Task SendMerged()
int bytesSent;
if (_mergeCount > 1)
{
NetDebug.Write("[P]Send merged: " + _mergePos + ", count: " + _mergeCount);
LogDebug("[P]Send merged: " + _mergePos + ", count: " + _mergeCount);
bytesSent = await PromulManager.RawSendAsync(new ArraySegment<byte>(_mergeData.Data.Array, _mergeData.Data.Offset, NetConstants.HeaderSize + _mergePos),
EndPoint);
}
Expand Down Expand Up @@ -712,7 +713,7 @@ internal async Task Update(long deltaTime)
case ConnectionState.Connected:
if (_timeSinceLastPacket > PromulManager.DisconnectTimeout)
{
NetDebug.Write($"[UPDATE] Disconnect by timeout: {_timeSinceLastPacket} > {PromulManager.DisconnectTimeout}");
LogDebug($"[UPDATE] Disconnect by timeout: {_timeSinceLastPacket} > {PromulManager.DisconnectTimeout}");
await PromulManager.ForceDisconnectPeerAsync(this, DisconnectReason.Timeout, 0);
return;
}
Expand Down Expand Up @@ -759,7 +760,7 @@ internal async Task Update(long deltaTime)
_pingSendTimer += deltaTime;
if (_pingSendTimer >= PromulManager.PingInterval)
{
NetDebug.Write($"[PING] Sending regular ping #{_pingPacket.Sequence+1}");
LogDebug($"[PING] Sending regular ping #{_pingPacket.Sequence+1}");
_pingSendTimer = 0;
_pingPacket.Sequence++;
if (_pingTimer.IsRunning) UpdateRoundTripTime((int)_pingTimer.ElapsedMilliseconds);
Expand Down Expand Up @@ -832,5 +833,10 @@ internal async Task RecycleAndDeliver(NetworkPacket packet)
}

internal abstract Task<ConnectRequestResult> ProcessReconnectionRequestAsync(NetConnectRequestPacket connRequest);

public void LogDebug(string text)
{
NetDebug.Write($"[Peer {this.Id}] {text}");
}
}
}
2 changes: 1 addition & 1 deletion Runtime/PromulTransport.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -112,7 +112,7 @@ async Task OnNetworkReceive(PeerBase peer, CompositeReader reader, byte channel,
// Relayed data
case RelayControlMessageType.Data:
{
Debug.Log("Data: " + string.Join(" ", message.Data.Select(e => e.ToString("X"))));
Debug.Log("Data: " + string.Join(" ", message.Data.Select(e => e.ToString("X2"))));
var data = new byte[message.Data.Count];
message.Data.CopyTo(data);
_queue.Enqueue((NetworkEvent.Data, author, data, 0));
Expand Down
3 changes: 1 addition & 2 deletions Server~/Relay/Sessions/RelaySession.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,6 @@ public async Task OnReceive(PeerBase from, RelayControlMessage message, Delivery
switch (message.Type)
{
case RelayControlMessageType.Data:
Console.WriteLine($"{from.Id} requesting to send {message.Data.Count} bytes of data to {message.AuthorClientId}");
await SendAsync(dest, new RelayControlMessage { Type = RelayControlMessageType.Data, AuthorClientId = (ulong)from.Id, Data = message.Data }, method);
break;
case RelayControlMessageType.KickFromRelay:
Expand Down Expand Up @@ -62,7 +61,7 @@ private async Task SendAsync(PeerBase to, RelayControlMessage message, DeliveryM
{
var writer = CompositeWriter.Create();
writer.Write(message);
_logger.LogInformation($"Sending {message.Type} from {message.AuthorClientId} to {to.Id}");
_logger.LogInformation($"Sending {message.Type} ({message.Data.Count} bytes) from {message.AuthorClientId} to {to.Id}");
await to.SendAsync(writer, deliveryMethod: method);
}

Expand Down

0 comments on commit b2cab0e

Please sign in to comment.