internal void CancelPendingRequest(PendingLowLevelUdpRequest request)
{
_CancelPendingRequest_WasInvoked = true;
if (WriteToLog_udp_deepDetail_enabled)
{
WriteToLog_udp_deepDetail($"cancelled {request}");
}
_pendingLowLevelUdpRequests.Remove(request);
}
/// <summary>
/// sends udp packet
/// expects response from same IPEndpoint, with specified first bytes
/// retransmits the packet if no response
/// returns null on timeout
/// </summary>
internal async Task <byte[]> SendUdpRequestAsync_Retransmit(PendingLowLevelUdpRequest request)
{
request.InitialTxTimeUTC = DateTimeNowUtc;
if (request.RequestPacketDataNullable != null)
{
SendPacket(request.RequestPacketDataNullable, request.ResponderEndpoint);
}
return(await WaitForUdpResponseAsync(request));
}
void DestroyWorstNeighbor(double?mutualValueLowLimit, DateTime timeNowUtc)
{
if (ConnectedNeighbors.Any(x => x.IsInTeardownState))
{
return;
}
double?worstValue = mutualValueLowLimit;
ConnectionToNeighbor worstNeighbor = null;
foreach (var neighbor in ConnectedNeighborsCanBeUsedForNewRequests)
{
var p2pConnectionValue_withNeighbor =
P2pConnectionValueCalculator.GetMutualP2pConnectionValue(CryptoLibrary,
this.Configuration.LocalPeerRegistrationId, this.ConnectedNeighborsBusySectorIds,
neighbor.RemoteRegistrationId, neighbor.RemoteNeighborsBusySectorIds ?? 0,
Engine.NumberOfDimensions,
true,
this.AnotherNeighborToSameSectorExists(neighbor),
neighbor.Remote_AnotherNeighborToSameSectorExists ?? false
);
Engine.WriteToLog_p2p_higherLevelDetail(neighbor, $"@DestroyWorstNeighbor() p2pConnectionValue_withNeighbor={p2pConnectionValue_withNeighbor} from {this} to {neighbor}", null);
if (worstValue == null || p2pConnectionValue_withNeighbor < worstValue)
{
worstValue = p2pConnectionValue_withNeighbor;
worstNeighbor = neighbor;
}
}
if (worstNeighbor != null)
{
_lastTimeDetroyedWorstNeighborUtc = timeNowUtc;
Engine.WriteToLog_p2p_higherLevelDetail(worstNeighbor, $"destroying worst P2P connection with neighbor. neighbors count = {ConnectedNeighbors.Count}", null);
var ping = worstNeighbor.CreatePing(false, true, 0, false);
var pendingPingRequest = new PendingLowLevelUdpRequest("pendingPingRequest 351", worstNeighbor.RemoteEndpoint,
PongPacket.GetScanner(worstNeighbor.LocalNeighborToken32, ping.PingRequestId32), Engine.DateTimeNowUtc,
Engine.Configuration.UdpLowLevelRequests_ExpirationTimeoutS,
ping.Encode(),
Engine.Configuration.UdpLowLevelRequests_InitialRetransmissionTimeoutS,
Engine.Configuration.UdpLowLevelRequests_RetransmissionTimeoutIncrement
);
_ = Engine.SendUdpRequestAsync_Retransmit(pendingPingRequest); // retransmit until PONG
worstNeighbor.IsInTeardownState = true;
Engine.EngineThreadQueue.EnqueueDelayed(TimeSpan.FromSeconds(PingPacket.ConnectionTeardownStateDurationS), () =>
{
if (!worstNeighbor.IsDisposed)
{
Engine.WriteToLog_p2p_higherLevelDetail(worstNeighbor, $"destroying worst P2P connection after teardown state timeout", null);
worstNeighbor.Dispose();
}
}, "estroying worst P2P connection 2146");
}
}
internal async Task <byte[]> WaitForUdpResponseAsync(PendingLowLevelUdpRequest request)
{
if (WriteToLog_udp_deepDetail_enabled)
{
WriteToLog_udp_deepDetail($"waiting for response to {request}");
}
_pendingLowLevelUdpRequests.AddLast(request);
if (_pendingLowLevelUdpRequests.Count > 20)
{
WriteToLog_udp_lightPain($"_pendingLowLevelUdpRequests.Count={_pendingLowLevelUdpRequests.Count}");
}
return(await request.TaskCompletionSource.Task);
}
async Task WaitForAck1Async(string completionActionVisibleId)
{
var tr1 = _engine.CreateTracker("WaitForAck1Async");
_logger.WriteToLog_detail($"waiting for ACK1");
_pendingAck1Request = new PendingLowLevelUdpRequest(completionActionVisibleId, _destinationEndpoint,
_ack1Scanner, _engine.DateTimeNowUtc, _engine.Configuration.Ack1TimoutS
);
tr1.Dispose();
Ack1UdpData = await _engine.WaitForUdpResponseAsync(_pendingAck1Request);
_pendingAck1Request = null;
_waitForAck1Completed = true;
}
async Task WaitForFailureAsync(string completionActionVisibleId)
{
var tr1 = _engine.CreateTracker("WaitForFailureAsync");
var failureScanner = FailurePacket.GetScanner(_logger, _sentReqP2pSeq16, _destinationNeighborNullable); // the scanner verifies neighborHMAC
_logger.WriteToLog_detail($"waiting for FAILURE");
_pendingFailureRequest = new PendingLowLevelUdpRequest(completionActionVisibleId, _destinationEndpoint,
failureScanner, _engine.DateTimeNowUtc, _engine.Configuration.Ack1TimoutS
);
tr1.Dispose();
_failureUdpData = await _engine.WaitForUdpResponseAsync(_pendingFailureRequest);
_pendingFailureRequest = null;
_waitForFailureCompleted = true;
}
/// <summary>
/// sends udp packet
/// expects response from same IPEndpoint, with specified first bytes
/// retransmits the packet if no response
/// returns null on timeout
/// </summary>
internal async Task <byte[]> SendUdpRequestAsync_Retransmit(PendingLowLevelUdpRequest request)
{
request.InitialTxTimeUTC = DateTimeNowUtc;
if (request.RequestPacketDataNullable != null)
{
short previousTTL = 0;
if (request.TTL != null)
{
previousTTL = _socket.Ttl; _socket.Ttl = request.TTL.Value;
}
SendPacket(request.RequestPacketDataNullable, request.ResponderEndpoint);
if (request.TTL != null)
{
_socket.Ttl = previousTTL;
}
}
return(await WaitForUdpResponseAsync(request));
}
internal async Task <byte[]> OptionallySendUdpRequestAsync_Retransmit_WaitForResponse(string completionActionVisibleId, string responderVisibleDescription, byte[] requestPacketDataNullable,
IPEndPoint responderEndpoint, LowLevelUdpResponseScanner responseScanner, double?expirationTimeoutS = null)
{
var timeoutS = expirationTimeoutS ?? Configuration.UdpLowLevelRequests_ExpirationTimeoutS;
var pendingLowLevelUdpRequest = new PendingLowLevelUdpRequest(completionActionVisibleId, responderEndpoint,
responseScanner, DateTimeNowUtc, timeoutS,
requestPacketDataNullable,
Configuration.UdpLowLevelRequests_InitialRetransmissionTimeoutS, Configuration.UdpLowLevelRequests_RetransmissionTimeoutIncrement
);
var nextHopResponsePacketData = await SendUdpRequestAsync_Retransmit(pendingLowLevelUdpRequest);
if (nextHopResponsePacketData == null)
{
string desc = $"no response to DRP request from '{responderVisibleDescription}' '";
if (requestPacketDataNullable != null)
{
desc += (PacketTypes)requestPacketDataNullable[0];
}
desc += $"' - timeout expired ({timeoutS}s) completionAction={completionActionVisibleId}";
throw new DrpTimeoutException(desc);
}
return(nextHopResponsePacketData);
}
/// <summary>
/// main register responder proc for both A-EP and P2P modes
/// in P2P mode Timestamp32S, NeighborToken32 and NeighborHMAC are verified at this time
/// </summary>
/// <param name="receivedFromInP2pMode">
/// is null in A-EP mode
/// </param>
internal async Task AcceptRegisterRequestAsync(LocalDrpPeer acceptAt, RoutedRequest routedRequest) // engine thread
{
var logger = routedRequest.Logger;
logger.ModuleName = VisionChannelModuleName_reg_responderSide;
var req = routedRequest.RegisterReq;
if (req.RequesterRegistrationId.Equals(acceptAt.Configuration.LocalPeerRegistrationId))
{
throw new InvalidOperationException();
}
// check signature of requester (A)
if (!req.RequesterSignature.Verify(_cryptoLibrary,
w => req.GetSharedSignedFields(w, false),
req.RequesterRegistrationId
)
)
{
throw new BadSignatureException("invalid REGISTER REQ RequesterSignature 2396");
}
if (routedRequest.ReceivedFromNeighborNullable == null)
{ // A-EP mode
if (req.EpEndpoint.Address.Equals(acceptAt.PublicIpApiProviderResponse) == false)
{
throw new PossibleAttackException();
}
}
if (PendingRegisterRequestExists(req.RequesterRegistrationId))
{
// received duplicate REGISTER REQ packet
logger.WriteToLog_needsAttention($"ignoring duplicate registration request {req.RequesterRegistrationId} from {routedRequest.ReceivedFromEndpoint}");
return;
}
if (!RecentUniqueAcceptedRegistrationRequests.Filter(req.GetUniqueRequestIdFields))
{
logger.WriteToLog_needsAttention($"ignoring registration request {req.RequesterRegistrationId} ts={req.ReqTimestamp64} from {routedRequest.ReceivedFromEndpoint} with non-unique request ID fields");
return;
}
logger.WriteToLog_higherLevelDetail($"accepting registration from {routedRequest.ReceivedFromEndpoint}: ReqP2pSeq16={req.ReqP2pSeq16}, NumberOfHopsRemaining={req.NumberOfHopsRemaining}, epEndpoint={req.EpEndpoint}, sourcePeer={routedRequest.ReceivedFromNeighborNullable}, ts={req.ReqTimestamp64}");
if (!RecentUniquePublicEcdhKeys.Filter(req.RequesterEcdhePublicKey.Ecdh25519PublicKey))
{
logger.WriteToLog_needsAttention($"ignoring registration request {req.RequesterRegistrationId} from {routedRequest.ReceivedFromEndpoint} with non-unique RequesterEcdhePublicKey");
return;
}
_pendingRegisterRequests.Add(req.RequesterRegistrationId);
try
{
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"sending NPACK to REQ to {routedRequest.ReceivedFromEndpoint} (delay={routedRequest.ReqReceivedSw_ms}ms)");
}
routedRequest.SendNeighborPeerAck_accepted_IfNotAlreadyReplied();
var newConnectionToNeighbor = new ConnectionToNeighbor(this, acceptAt, ConnectedDrpPeerInitiatedBy.remotePeer, req.RequesterRegistrationId)
{
LocalEndpoint = routedRequest.ReceivedFromNeighborNullable?.LocalEndpoint ?? req.EpEndpoint,
};
byte[] ack1UdpData;
try
{
var ack1 = new RegisterAck1Packet
{
RequesterRegistrationId = req.RequesterRegistrationId,
ReqTimestamp64 = req.ReqTimestamp64,
ResponderEcdhePublicKey = new EcdhPublicKey(newConnectionToNeighbor.LocalEcdhe25519PublicKey),
ResponderRegistrationId = acceptAt.Configuration.LocalPeerRegistrationId,
ReqP2pSeq16 = GetNewNpaSeq16_AtoEP(),
};
RecentUniquePublicEcdhKeys.AssertIsUnique(ack1.ResponderEcdhePublicKey.Ecdh25519PublicKey, $"ack1.ResponderEcdhePublicKey");
ack1.ToResponderTxParametersEncrypted = newConnectionToNeighbor.Encrypt_ack1_ToResponderTxParametersEncrypted_AtResponder_DeriveSharedDhSecret(logger, req, ack1, routedRequest.ReceivedFromNeighborNullable);
ack1.ResponderSignature = RegistrationSignature.Sign(_cryptoLibrary,
(w2) =>
{
req.GetSharedSignedFields(w2, true);
ack1.GetSharedSignedFields(w2, false, true);
},
acceptAt.Configuration.LocalPeerRegistrationPrivateKey);
if (routedRequest.ReceivedFromNeighborNullable == null)
{
ack1.RequesterEndpoint = routedRequest.ReceivedFromEndpoint;
}
ack1UdpData = ack1.Encode_OpionallySignNeighborHMAC(routedRequest.ReceivedFromNeighborNullable);
var ack2Scanner = RegisterAck2Packet.GetScanner(logger, routedRequest.ReceivedFromNeighborNullable, req);
var requesterVisibleDescription = routedRequest.ReceivedFromNeighborNullable?.ToString() ?? routedRequest.ReceivedFromEndpoint.ToString();
byte[] ack2UdpData;
if (routedRequest.ReceivedFromNeighborNullable == null)
{ // wait for ACK2, retransmitting ACK1
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"sending ACK1, waiting for ACK2");
}
ack2UdpData = await OptionallySendUdpRequestAsync_Retransmit_WaitForResponse("ack2 33469", requesterVisibleDescription, ack1UdpData, routedRequest.ReceivedFromEndpoint, ack2Scanner);
}
else
{ // retransmit ACK1 until NPACK (via P2P); at same time wait for ACK
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"sending ACK1, awaiting for NPACK");
}
_ = OptionallySendUdpRequestAsync_Retransmit_WaitForNeighborPeerAck("ack1 423087", ack1UdpData, routedRequest.ReceivedFromEndpoint,
ack1.ReqP2pSeq16, routedRequest.ReceivedFromNeighborNullable, ack1.GetSignedFieldsForNeighborHMAC);
// not waiting for NPACK, wait for ACK
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"waiting for ACK2");
}
ack2UdpData = await OptionallySendUdpRequestAsync_Retransmit_WaitForResponse("ack2 46051", requesterVisibleDescription, null, routedRequest.ReceivedFromEndpoint, ack2Scanner);
}
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"received ACK2");
}
var ack2 = RegisterAck2Packet.Decode_OptionallyVerify_InitializeP2pStreamAtResponder(logger, ack2UdpData, req, ack1, newConnectionToNeighbor);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"verified ACK2");
}
acceptAt.AddToConnectedNeighbors(newConnectionToNeighbor, req); // added to list here in order to respond to ping requests from A
SendNeighborPeerAckResponseToRegisterAck2(ack2, routedRequest.ReceivedFromEndpoint, routedRequest.ReceivedFromNeighborNullable); // send NPACK to ACK
_ = WaitForRegistrationConfirmationRequestAsync(requesterVisibleDescription, logger, routedRequest.ReceivedFromEndpoint, req, newConnectionToNeighbor, routedRequest.ReceivedFromNeighborNullable);
#region send ping, verify pong
var ping = newConnectionToNeighbor.CreatePing(true, false, acceptAt.ConnectedNeighborsBusySectorIds, acceptAt.AnotherNeighborToSameSectorExists(newConnectionToNeighbor));
var pendingPingRequest = new PendingLowLevelUdpRequest("pendingPingRequest 693", newConnectionToNeighbor.RemoteEndpoint,
PongPacket.GetScanner(newConnectionToNeighbor.LocalNeighborToken32, ping.PingRequestId32), DateTimeNowUtc,
Configuration.InitialPingRequests_ExpirationTimeoutS,
ping.Encode(),
Configuration.InitialPingRequests_InitialRetransmissionTimeoutS,
Configuration.InitialPingRequests_RetransmissionTimeoutIncrement
);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"sent PING");
}
var pongPacketData = await SendUdpRequestAsync_Retransmit(pendingPingRequest); // wait for pong from A
if (pongPacketData == null)
{
throw new DrpTimeoutException($"reg. responder initial PING request to {newConnectionToNeighbor} (timeout={Configuration.InitialPingRequests_ExpirationTimeoutS}s)");
}
var pong = PongPacket.DecodeAndVerify(_cryptoLibrary,
pongPacketData, ping, newConnectionToNeighbor,
true);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"verified PONG");
}
newConnectionToNeighbor.OnReceivedVerifiedPong(pong, pendingPingRequest.ResponseReceivedAtUtc.Value,
pendingPingRequest.ResponseReceivedAtUtc.Value - pendingPingRequest.InitialTxTimeUTC.Value);
#endregion
}
catch (Exception exc)
{
newConnectionToNeighbor.Dispose();
throw exc;
}
}
catch (DrpTimeoutException exc)
{
logger.WriteToLog_needsAttention($"could not accept REGISTER request: {exc}");
}
catch (Exception exc)
{
logger.WriteToLog_mediumPain($"could not accept REGISTER request: {exc}");
}
finally
{
_pendingRegisterRequests.Remove(req.RequesterRegistrationId);
}
}
/// <summary>
/// is used to expand neighborhood
/// </summary>
internal async Task RegisterAsync(uint minimalDistanceToNeighbor, ushort busySectorIds, byte numberOfHopsRemaining, byte numberOfRandomHopsRemaining, double[] directionVectorNullable)
{
_engine.WriteToLog_reg_requesterSide_detail($">> ConnectionToNeighbor.RegisterAsync(minimalDistanceToNeighbor={minimalDistanceToNeighbor}", null, null);
_localDrpPeer.CurrentRegistrationOperationsCount++;
try
{
var newConnectionToNeighbor = new ConnectionToNeighbor(_engine, _localDrpPeer, ConnectedDrpPeerInitiatedBy.localPeer, null);
PongPacket pong;
PendingLowLevelUdpRequest pendingPingRequest;
var req = new RegisterRequestPacket
{
RequesterRegistrationId = _localDrpPeer.Configuration.LocalPeerRegistrationId,
ReqTimestamp64 = _engine.Timestamp64,
MinimalDistanceToNeighbor = minimalDistanceToNeighbor,
RequesterNeighborsBusySectorIds = busySectorIds,
NumberOfHopsRemaining = numberOfHopsRemaining,
NumberOfRandomHopsRemaining = numberOfRandomHopsRemaining,
RequesterEcdhePublicKey = new EcdhPublicKey(newConnectionToNeighbor.LocalEcdhe25519PublicKey),
ReqP2pSeq16 = GetNewRequestP2pSeq16_P2P(),
EpEndpoint = this.RemoteEndpoint,
DirectionVectorNullableD = directionVectorNullable
};
var logger = new Logger(Engine, LocalDrpPeer, req, DrpPeerEngine.VisionChannelModuleName_reg_requesterSide);
try
{
_engine.RecentUniquePublicEcdhKeys.AssertIsUnique(req.RequesterEcdhePublicKey.Ecdh25519PublicKey, $"req.RequesterEcdhePublicKey {req}");
req.RequesterSignature = RegistrationSignature.Sign(_engine.CryptoLibrary,
w => req.GetSharedSignedFields(w, false),
_localDrpPeer.Configuration.LocalPeerRegistrationPrivateKey
);
var reqToAck1Stopwatch = Stopwatch.StartNew();
#region wait for ACK1, respond with NPACK
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"sending {req}, waiting for NPACK. ReqP2pSeq16={req.ReqP2pSeq16}");
}
var sentRequest = new SentRequest(Engine, logger, this.RemoteEndpoint, this, req.Encode_OptionallySignNeighborHMAC(this),
req.ReqP2pSeq16, RegisterAck1Packet.GetScanner(logger, req, this));
var ack1UdpData = await sentRequest.SendRequestAsync("reg req ack1 42084");
var ack1 = RegisterAck1Packet.DecodeAndOptionallyVerify(logger, ack1UdpData, req, newConnectionToNeighbor);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"verified ACK1, sending NPACK to ACK1");
}
_engine.SendNeighborPeerAckResponseToRegisterAck1(ack1, this);
#endregion
if (newConnectionToNeighbor.IsDisposed)
{
logger.WriteToLog_needsAttention($"connection {newConnectionToNeighbor} is disposed during reg. request 5345322345");
return;
}
if (IsDisposed)
{
logger.WriteToLog_needsAttention($"connection {this} is disposed during reg. request 5345322345");
return;
}
_engine.RecentUniquePublicEcdhKeys.AssertIsUnique(ack1.ResponderEcdhePublicKey.Ecdh25519PublicKey, $"ack1.ResponderEcdhePublicKey from {newConnectionToNeighbor}");
newConnectionToNeighbor.LocalEndpoint = this.LocalEndpoint;
newConnectionToNeighbor.RemoteRegistrationId = ack1.ResponderRegistrationId;
reqToAck1Stopwatch.Stop();
var reqToAck1TimeMs = reqToAck1Stopwatch.Elapsed.TotalMilliseconds;
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"measured REQ-ACK1 RTT = {(int)reqToAck1TimeMs}ms");
}
#region send ACK2, encode local IP
var ack2 = new RegisterAck2Packet
{
ReqTimestamp64 = req.ReqTimestamp64,
RequesterRegistrationId = _localDrpPeer.Configuration.LocalPeerRegistrationId,
ReqP2pSeq16 = GetNewRequestP2pSeq16_P2P(),
};
ack2.ToRequesterTxParametersEncrypted = newConnectionToNeighbor.Encrypt_ack2_ToRequesterTxParametersEncrypted_AtRequester(logger, req, ack1, ack2);
newConnectionToNeighbor.InitializeP2pStream(req, ack1, ack2);
ack2.RequesterSignature = RegistrationSignature.Sign(_engine.CryptoLibrary, w =>
{
req.GetSharedSignedFields(w, true);
ack1.GetSharedSignedFields(w, true, true);
ack2.GetSharedSignedFields(w, false, true);
},
_localDrpPeer.Configuration.LocalPeerRegistrationPrivateKey
);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"sending ACK2 (in response to ACK1), waiting for NPACK");
}
await _engine.OptionallySendUdpRequestAsync_Retransmit_WaitForNeighborPeerAck("ack2 1235739", ack2.Encode_OptionallySignNeighborHMAC(this), this.RemoteEndpoint, ack2.ReqP2pSeq16);
#endregion
var neighborWaitTimeMs = reqToAck1TimeMs * 0.5 - 100; if (neighborWaitTimeMs < 0)
{
neighborWaitTimeMs = 0;
}
if (neighborWaitTimeMs > 20)
{
await _engine.EngineThreadQueue.WaitAsync(TimeSpan.FromMilliseconds(neighborWaitTimeMs), "neighborWaitTimeMs45236"); // wait until the ACK2 reaches neighbor N via peers
}
if (newConnectionToNeighbor.IsDisposed)
{
logger.WriteToLog_needsAttention($"connection {newConnectionToNeighbor} is disposed during reg. request 234574568");
return;
}
if (IsDisposed)
{
logger.WriteToLog_needsAttention($"connection {this} is disposed during reg. request 234574568");
return;
}
_localDrpPeer.AddToConnectedNeighbors(newConnectionToNeighbor, req);
#region send ping request directly to neighbor N, retransmit
var pingRequest = newConnectionToNeighbor.CreatePing(true, false, _localDrpPeer.ConnectedNeighborsBusySectorIds, _localDrpPeer.AnotherNeighborToSameSectorExists(newConnectionToNeighbor));
pendingPingRequest = new PendingLowLevelUdpRequest("pendingPingRequest 12247", newConnectionToNeighbor.RemoteEndpoint,
PongPacket.GetScanner(newConnectionToNeighbor.LocalNeighborToken32, pingRequest.PingRequestId32),
_engine.DateTimeNowUtc,
_engine.Configuration.InitialPingRequests_ExpirationTimeoutS,
pingRequest.Encode(),
_engine.Configuration.InitialPingRequests_InitialRetransmissionTimeoutS,
_engine.Configuration.InitialPingRequests_RetransmissionTimeoutIncrement
);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"sending PING, waiting for PONG");
}
var pongPacketData = await _engine.SendUdpRequestAsync_Retransmit(pendingPingRequest);
if (pongPacketData == null)
{
throw new DrpTimeoutException($"reg. requester initial PING to {newConnectionToNeighbor} (timeout={_engine.Configuration.InitialPingRequests_ExpirationTimeoutS}s)");
}
if (newConnectionToNeighbor.IsDisposed)
{
logger.WriteToLog_needsAttention($"connection {newConnectionToNeighbor} is disposed during reg. request 548798");
return;
}
if (IsDisposed)
{
logger.WriteToLog_needsAttention($"connection {this} is disposed during reg. request 548798");
return;
}
pong = PongPacket.DecodeAndVerify(_engine.CryptoLibrary,
pongPacketData, pingRequest, newConnectionToNeighbor,
true);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"verified PONG");
}
newConnectionToNeighbor.OnReceivedVerifiedPong(pong, pendingPingRequest.ResponseReceivedAtUtc.Value,
pendingPingRequest.ResponseReceivedAtUtc.Value - pendingPingRequest.InitialTxTimeUTC.Value);
#endregion
}
catch
{
// todo update QoS
newConnectionToNeighbor.Dispose(); // remove from token32 table
throw;
}
#region send registration confirmation packet to X->N
try
{
if (newConnectionToNeighbor.IsDisposed)
{
logger.WriteToLog_needsAttention($"connection {newConnectionToNeighbor} is disposed during reg. request 541687987");
return;
}
if (IsDisposed)
{
logger.WriteToLog_needsAttention($"connection {this} is disposed during reg. request 541687987");
return;
}
var cfm = new RegisterConfirmationPacket
{
ReqTimestamp64 = req.ReqTimestamp64,
RequesterRegistrationId = _localDrpPeer.Configuration.LocalPeerRegistrationId,
ResponderRegistrationConfirmationSignature = pong.ResponderRegistrationConfirmationSignature,
ReqP2pSeq16 = GetNewRequestP2pSeq16_P2P()
};
cfm.RequesterRegistrationConfirmationSignature = RegistrationSignature.Sign(_engine.CryptoLibrary,
w => newConnectionToNeighbor.GetRequesterRegistrationConfirmationSignatureFields(w, cfm.ResponderRegistrationConfirmationSignature),
_localDrpPeer.Configuration.LocalPeerRegistrationPrivateKey);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"sending CFM, waiting for NPACK");
}
await _engine.OptionallySendUdpRequestAsync_Retransmit_WaitForNeighborPeerAck("cfm 14478", cfm.Encode_OptionallySignNeighborHMAC(this), this.RemoteEndpoint, cfm.ReqP2pSeq16);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"received NPACK to CFM");
}
}
catch (DrpTimeoutException exc)
{ // we ingnore exceptions here, just wite warning to log. the connection is alive already, as direct ping channel to neighbor is set up
logger.WriteToLog_needsAttention($"... registration confirmation request failed: {exc}");
}
catch (Exception exc)
{ // we ingnore exceptions here, just wite warning to log. the connection is alive already, as direct ping channel to neighbor is set up
logger.WriteToLog_mediumPain($"... registration confirmation request failed: {exc}");
}
#endregion
return;// newConnectionToNeighbor;
}
finally
{
_localDrpPeer.CurrentRegistrationOperationsCount--;
}
}
/// <returns>null if registration failed with timeout or some error code</returns>
public async Task <ConnectionToNeighbor> RegisterAsync(LocalDrpPeer localDrpPeer, IPEndPoint epEndpoint, uint minimalDistanceToNeighbor, byte numberofHops, double[] directionVectorNullable) // engine thread
{
var regSW = Stopwatch.StartNew();
WriteToLog_reg_requesterSide_higherLevelDetail($"connecting via EntryPeer {epEndpoint}", null, null);
localDrpPeer.CurrentRegistrationOperationsCount++;
try
{
#region PoW1
RegisterPow1ResponsePacket pow1ResponsePacket = null;
if (!Configuration.SandboxModeOnly_DisablePoW)
{
WriteToLog_reg_requesterSide_detail($"generating PoW1 request", null, null);
var pow1SW = Stopwatch.StartNew();
await PowThreadQueue.EnqueueAsync("pow1 6318");
WriteToLog_reg_requesterSide_detail($"generating PoW1 request @pow thread", null, null);
var registerPow1RequestPacket = GenerateRegisterPow1RequestPacket(localDrpPeer.PublicIpApiProviderResponse.GetAddressBytes(), Timestamp32S);
await EngineThreadQueue.EnqueueAsync("pow1 234709");
WriteToLog_reg_requesterSide_detail($"generated PoW1 request @engine thread", null, null);
// send register pow1 request
if (pow1SW.Elapsed.TotalMilliseconds > 3000)
{
WriteToLog_reg_requesterSide_lightPain($"PoW1 took {(int)pow1SW.Elapsed.TotalMilliseconds}ms", null, null);
}
WriteToLog_reg_requesterSide_detail($"PoW1 took {(int)pow1SW.Elapsed.TotalMilliseconds}ms. sending PoW1 request", null, null);
var rpPow1ResponsePacketData = await SendUdpRequestAsync_Retransmit(
new PendingLowLevelUdpRequest("rpPow1 469", epEndpoint,
RegisterPow1ResponsePacket.GetScanner(registerPow1RequestPacket.Pow1RequestId),
DateTimeNowUtc,
Configuration.UdpLowLevelRequests_ExpirationTimeoutS,
registerPow1RequestPacket.Encode(),
Configuration.UdpLowLevelRequests_InitialRetransmissionTimeoutS,
Configuration.UdpLowLevelRequests_RetransmissionTimeoutIncrement
));
// wait for response, retransmit
if (rpPow1ResponsePacketData == null)
{
throw new DrpTimeoutException($"pow1 request to EP '{epEndpoint}' (timeout={Configuration.UdpLowLevelRequests_ExpirationTimeoutS}s)");
}
;
pow1ResponsePacket = new RegisterPow1ResponsePacket(rpPow1ResponsePacketData);
WriteToLog_reg_requesterSide_detail($"got PoW1 response with status={pow1ResponsePacket.StatusCode}", null, null);
if (pow1ResponsePacket.StatusCode != RegisterPow1ResponseStatusCode.succeeded_Pow2Challenge)
{
throw new Pow1RejectedException(pow1ResponsePacket.StatusCode);
}
}
#endregion
var newConnectionToNeighbor = new ConnectionToNeighbor(this, localDrpPeer, ConnectedDrpPeerInitiatedBy.localPeer, null);
PongPacket pong;
PendingLowLevelUdpRequest pendingPingRequest;
var req = new RegisterRequestPacket
{
RequesterRegistrationId = localDrpPeer.Configuration.LocalPeerRegistrationId,
ReqTimestamp64 = Timestamp64,
MinimalDistanceToNeighbor = minimalDistanceToNeighbor,
NumberOfHopsRemaining = numberofHops,
RequesterEcdhePublicKey = new EcdhPublicKey(newConnectionToNeighbor.LocalEcdhe25519PublicKey),
ReqP2pSeq16 = GetNewNpaSeq16_AtoEP(),
EpEndpoint = epEndpoint,
DirectionVectorNullableD = directionVectorNullable
};
var logger = new Logger(this, localDrpPeer, req, VisionChannelModuleName_reg_requesterSide);
try
{
#region register REQ PoW2
RecentUniquePublicEcdhKeys.AssertIsUnique(req.RequesterEcdhePublicKey.Ecdh25519PublicKey, $"req.RequesterEcdhePublicKey {req}");
var pow2SW = Stopwatch.StartNew();
if (!Configuration.SandboxModeOnly_DisablePoW)
{
await PowThreadQueue.EnqueueAsync("pow2 23465");
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"calculating PoW2 @pow thread");
}
GenerateRegisterReqPow2(req, pow1ResponsePacket.ProofOfWork2Request);
await EngineThreadQueue.EnqueueAsync("pow2 2496");
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"calculated PoW2 @engine thread");
}
}
else
{
req.ProofOfWork2 = new byte[64];
}
pow2SW.Stop();
if (pow2SW.Elapsed.TotalMilliseconds > 3000)
{
logger.WriteToLog_lightPain($"PoW2 took {(int)pow2SW.Elapsed.TotalMilliseconds}ms");
}
req.RequesterSignature = RegistrationSignature.Sign(_cryptoLibrary,
w => req.GetSharedSignedFields(w, false),
localDrpPeer.Configuration.LocalPeerRegistrationPrivateKey
);
var reqToAck1Stopwatch = Stopwatch.StartNew();
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"PoW2 took {(int)pow2SW.Elapsed.TotalMilliseconds}ms. sending REQ, waiting for NPACK. ReqP2pSeq16={req.ReqP2pSeq16}");
}
#endregion
// var reqSW = Stopwatch.StartNew();
#region wait for ACK1
var sentRequest = new SentRequest(this, logger, epEndpoint, null, req.Encode_OptionallySignNeighborHMAC(null), req.ReqP2pSeq16, RegisterAck1Packet.GetScanner(logger, req));
var ack1UdpData = await sentRequest.SendRequestAsync("reg req ack1 367097");
var ack1 = RegisterAck1Packet.DecodeAndOptionallyVerify(logger, ack1UdpData, req, newConnectionToNeighbor);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"verified ACK1. RequesterEndpoint={ack1.RequesterEndpoint}");
}
#endregion
// check if it matches to previously known local public IP
if (ack1.RequesterEndpoint.Address.Equals(localDrpPeer.PublicIpApiProviderResponse) == false)
{
// MITM attack / EP sent local (requester) endpoint IP some bad IP address
throw new PossibleAttackException();
}
RecentUniquePublicEcdhKeys.AssertIsUnique(ack1.ResponderEcdhePublicKey.Ecdh25519PublicKey, $"ack1.ResponderEcdhePublicKey from {epEndpoint}");
newConnectionToNeighbor.LocalEndpoint = ack1.RequesterEndpoint;
newConnectionToNeighbor.RemoteRegistrationId = ack1.ResponderRegistrationId;
reqToAck1Stopwatch.Stop();
var reqToAck1TimeMs = reqToAck1Stopwatch.Elapsed.TotalMilliseconds;
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"measured REQ-ACK1_RTT={(int)reqToAck1TimeMs}ms");
}
#region send ACK2, encode local IP
var ack2 = new RegisterAck2Packet
{
ReqTimestamp64 = req.ReqTimestamp64,
RequesterRegistrationId = localDrpPeer.Configuration.LocalPeerRegistrationId,
ReqP2pSeq16 = GetNewNpaSeq16_AtoEP()
};
ack2.ToRequesterTxParametersEncrypted = newConnectionToNeighbor.Encrypt_ack2_ToRequesterTxParametersEncrypted_AtRequester(logger, req, ack1, ack2);
newConnectionToNeighbor.InitializeP2pStream(req, ack1, ack2);
ack2.RequesterSignature = RegistrationSignature.Sign(_cryptoLibrary, w =>
{
req.GetSharedSignedFields(w, true);
ack1.GetSharedSignedFields(w, true, true);
ack2.GetSharedSignedFields(w, false, true);
},
localDrpPeer.Configuration.LocalPeerRegistrationPrivateKey
);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"sending ACK2 (in response to ACK1), waiting for NPACK");
}
RespondToRequestAndRetransmissions(ack1UdpData, ack2.Encode_OptionallySignNeighborHMAC(null), epEndpoint);
await OptionallySendUdpRequestAsync_Retransmit_WaitForNeighborPeerAck("ack2 46873", null, epEndpoint, ack2.ReqP2pSeq16);
#endregion
var neighborWaitTimeMs = reqToAck1TimeMs * 0.5 - 250; if (neighborWaitTimeMs < 0)
{
neighborWaitTimeMs = 0;
}
if (neighborWaitTimeMs > 20)
{
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"awaiting {(int)neighborWaitTimeMs}ms before PING...");
}
await EngineThreadQueue.WaitAsync(TimeSpan.FromMilliseconds(neighborWaitTimeMs), "before PING 34589"); // wait until the ACK2 reaches neighbor N via peers
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"... awaiting is complete");
}
}
localDrpPeer.AddToConnectedNeighbors(newConnectionToNeighbor, req);
#region send ping request directly to neighbor N, retransmit
var pingRequest = newConnectionToNeighbor.CreatePing(true, false, localDrpPeer.ConnectedNeighborsBusySectorIds, localDrpPeer.AnotherNeighborToSameSectorExists(newConnectionToNeighbor));
pendingPingRequest = new PendingLowLevelUdpRequest("pingRequest 3850", newConnectionToNeighbor.RemoteEndpoint,
PongPacket.GetScanner(newConnectionToNeighbor.LocalNeighborToken32, pingRequest.PingRequestId32),
DateTimeNowUtc,
Configuration.InitialPingRequests_ExpirationTimeoutS,
pingRequest.Encode(),
Configuration.InitialPingRequests_InitialRetransmissionTimeoutS,
Configuration.InitialPingRequests_RetransmissionTimeoutIncrement
);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"sending PING neighborToken32={pingRequest.NeighborToken32}, waiting for PONG");
}
var pongPacketData = await SendUdpRequestAsync_Retransmit(pendingPingRequest);
if (pongPacketData == null)
{
throw new DrpTimeoutException($"initial reg. requester PING to {newConnectionToNeighbor} (timeout={Configuration.InitialPingRequests_ExpirationTimeoutS}s)");
}
if (newConnectionToNeighbor.IsDisposed)
{
throw new ObjectDisposedException($"initial reg. requester PING to {newConnectionToNeighbor} (special case: connection is disposed)", (Exception)null); // ping timeout already destroyed the connection, so PONG response here is too late
}
pong = PongPacket.DecodeAndVerify(_cryptoLibrary,
pongPacketData, pingRequest, newConnectionToNeighbor,
true);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"verified PONG");
}
newConnectionToNeighbor.OnReceivedVerifiedPong(pong, pendingPingRequest.ResponseReceivedAtUtc.Value,
pendingPingRequest.ResponseReceivedAtUtc.Value - pendingPingRequest.InitialTxTimeUTC.Value);
#endregion
}
catch
{
// todo update QoS
newConnectionToNeighbor.Dispose(); // remove from token32 table
throw;
}
#region send registration confirmation packet to EP->X->N
try
{
var cfm = new RegisterConfirmationPacket
{
ReqTimestamp64 = req.ReqTimestamp64,
RequesterRegistrationId = localDrpPeer.Configuration.LocalPeerRegistrationId,
ResponderRegistrationConfirmationSignature = pong.ResponderRegistrationConfirmationSignature,
ReqP2pSeq16 = GetNewNpaSeq16_AtoEP()
};
cfm.RequesterRegistrationConfirmationSignature = RegistrationSignature.Sign(_cryptoLibrary,
w => newConnectionToNeighbor.GetRequesterRegistrationConfirmationSignatureFields(w, cfm.ResponderRegistrationConfirmationSignature),
localDrpPeer.Configuration.LocalPeerRegistrationPrivateKey);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"sending CFM, waiting for NPACK");
}
await OptionallySendUdpRequestAsync_Retransmit_WaitForNeighborPeerAck("cfm 32107", cfm.Encode_OptionallySignNeighborHMAC(null), epEndpoint, cfm.ReqP2pSeq16);
if (logger.WriteToLog_detail_enabled)
{
logger.WriteToLog_detail($"received NPACK to CFM");
}
}
catch (DrpTimeoutException exc)
{ // we ingnore exceptions here, just wite warning to log. the connection is alive already, as direct ping channel to neighbor is set up
logger.WriteToLog_needsAttention($"... registration confirmation request failed: {exc}");
}
catch (Exception exc)
{ // we ingnore exceptions here, just wite warning to log. the connection is alive already, as direct ping channel to neighbor is set up
logger.WriteToLog_mediumPain($"... registration confirmation request failed: {exc}");
}
#endregion
regSW.Stop();
if (regSW.Elapsed.TotalMilliseconds > 5000)
{
logger.WriteToLog_lightPain($"registration is completed in {(int)regSW.Elapsed.TotalMilliseconds}ms");
}
else
{
logger.WriteToLog_higherLevelDetail($"registration is completed in {(int)regSW.Elapsed.TotalMilliseconds}ms");
};
return(newConnectionToNeighbor);
}
finally
{
localDrpPeer.CurrentRegistrationOperationsCount--;
}
}