/// <summary> /// is used to expand neighborhood /// </summary> internal async Task RegisterAsync(uint minimalDistanceToNeighbor, ushort busySectorIds, byte numberOfHopsRemaining, byte numberOfRandomHopsRemaining, double[] directionVectorNullable, bool allowConnectionsToRequesterRegistrationId) { _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, RequesterNatBehaviour = _engine.LocalNatBehaviour, AllowConnectionsToRequesterRegistrationId = allowConnectionsToRequesterRegistrationId, 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)); newConnectionToNeighbor.InitialPendingPingRequest = 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(newConnectionToNeighbor.InitialPendingPingRequest); 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, newConnectionToNeighbor.InitialPendingPingRequest.ResponseReceivedAtUtc.Value, newConnectionToNeighbor.InitialPendingPingRequest.ResponseReceivedAtUtc.Value - newConnectionToNeighbor.InitialPendingPingRequest.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, bool allowConnectionsToRequesterRegistrationId) // 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; var req = new RegisterRequestPacket { RequesterRegistrationId = localDrpPeer.Configuration.LocalPeerRegistrationId, ReqTimestamp64 = Timestamp64, MinimalDistanceToNeighbor = minimalDistanceToNeighbor, RequesterNatBehaviour = LocalNatBehaviour, AllowConnectionsToRequesterRegistrationId = allowConnectionsToRequesterRegistrationId, 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}"); // this is used in non-standard way when routing registration requests to same (local) reg. ID, too 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)); newConnectionToNeighbor.InitialPendingPingRequest = 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(newConnectionToNeighbor.InitialPendingPingRequest); 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, newConnectionToNeighbor.InitialPendingPingRequest.ResponseReceivedAtUtc.Value, newConnectionToNeighbor.InitialPendingPingRequest.ResponseReceivedAtUtc.Value - newConnectionToNeighbor.InitialPendingPingRequest.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--; } }