Exemple #1
0
        /// <summary>
        /// Timestamp32S, NeighborToken32 and NeighborHMAC are verified at this time
        /// </summary>
        /// <returns>
        /// true to retry the request with another neighbor (if the request needs to be "rerouted")
        /// </returns>
        internal async Task <bool> ProxyInviteRequestAsync(RoutedRequest routedRequest, ConnectionToNeighbor destinationPeer)
        {
            var req    = routedRequest.InviteReq;
            var logger = routedRequest.Logger;

            logger.ModuleName = DrpPeerEngine.VisionChannelModuleName_inv_proxySide;
            if (logger.WriteToLog_detail_enabled)
            {
                logger.WriteToLog_detail($"proxying {req} to {destinationPeer}");
            }

            if (!routedRequest.CheckedRecentUniqueProxiedRequests)
            {
                if (!Engine.RecentUniqueInviteRequests.Filter(req.GetUniqueRequestIdFields))
                {
                    logger.WriteToLog_higherLevelDetail($"rejecting non-unique {req}: requesterEndpoint={routedRequest.ReceivedFromEndpoint}");
                    await routedRequest.SendErrorResponse(ResponseOrFailureCode.failure_routeIsUnavailable);

                    return(false);
                }
                routedRequest.CheckedRecentUniqueProxiedRequests = true;
            }

            if (req.NumberOfHopsRemaining > InviteRequestPacket.MaxNumberOfHopsRemaining)
            {
                await routedRequest.SendErrorResponse(ResponseOrFailureCode.failure_routeIsUnavailable);

                return(false);
            }
            if (req.NumberOfHopsRemaining <= 1)
            {
                await routedRequest.SendErrorResponse(ResponseOrFailureCode.failure_numberOfHopsRemainingReachedZero);

                return(false);
            }

            _pendingInviteRequests.Add(req.RequesterRegistrationId);
            try
            {
                // send NPACK to REQ
                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"sending NPACK to REQ source peer");
                }
                routedRequest.SendNeighborPeerAck_accepted_IfNotAlreadyReplied();

                req.NumberOfHopsRemaining--;
                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"decremented number of hops in {req}: NumberOfHopsRemaining={req.NumberOfHopsRemaining}");
                }

                // send (proxy) REQ to responder. wait for NPACK, verify NPACK.senderHMAC, retransmit REQ
                var reqUdpData = req.Encode_SetP2pFields(destinationPeer);

                #region wait for ACK1 from responder  verify NeighborHMAC

                byte[] ack1UdpData;
                try
                {
                    var sentRequest = new SentRequest(Engine, logger, destinationPeer.RemoteEndpoint, destinationPeer, reqUdpData,
                                                      req.ReqP2pSeq16, InviteAck1Packet.GetScanner(logger, req, destinationPeer));
                    ack1UdpData = await sentRequest.SendRequestAsync("inv proxy ack1 3457");
                }
                catch (RequestRejectedException reqExc)
                {
                    logger.WriteToLog_higherLevelDetail($"got response={reqExc.ResponseCode} from destination {destinationPeer}. will try another neighbor..");

                    if (reqExc.ResponseCode == ResponseOrFailureCode.failure_numberOfHopsRemainingReachedZero)
                    {
                        await routedRequest.SendErrorResponse(ResponseOrFailureCode.failure_numberOfHopsRemainingReachedZero);

                        return(false);
                    }

                    if (routedRequest.ReceivedFromNeighborNullable?.IsDisposed == true)
                    {
                        logger.WriteToLog_needsAttention($"sourcePeer={routedRequest.ReceivedFromNeighborNullable} is disposed during proxying 75675");
                        return(false);
                    }
                    if (reqExc.ResponseCode == ResponseOrFailureCode.failure_routeIsUnavailable)
                    {
                        req.NumberOfHopsRemaining++; // roll back previous decrement for a new trial
                    }
                    return(true);                    // will retry
                }
                catch (DrpTimeoutException exc)
                {
                    logger.WriteToLog_higherLevelDetail($"got timeout error when requesting {destinationPeer}: {exc.Message}");
                    req.NumberOfHopsRemaining++; // roll back previous decrement for a new trial
                    return(true);                // will retry
                }
                catch (Exception reqExc)
                {
                    logger.WriteToLog_mediumPain($"could not proxy INVITE request: {reqExc}");
                    if (routedRequest.ReceivedFromNeighborNullable?.IsDisposed == true)
                    {
                        logger.WriteToLog_needsAttention($"sourcePeer={routedRequest.ReceivedFromNeighborNullable} is disposed during proxying 76897805");
                        return(false);
                    }
                    return(true); // will retry
                }


                var ack1 = InviteAck1Packet.Decode(ack1UdpData);
                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"verified ACK1 from responder");
                }
                // respond with NPACK to ACk1
                SendNeighborPeerAckResponseToAck1(ack1, destinationPeer);
                #endregion

                #region send ACK1 to requester, wait for NPACK and ACK2
                var ack1UdpDataTx = ack1.Encode_SetP2pFields(routedRequest.ReceivedFromNeighborNullable);

                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"sending ACK1, awaiting for NPACK");
                }
                _ = Engine.OptionallySendUdpRequestAsync_Retransmit_WaitForNeighborPeerAck("ack1 13536", ack1UdpDataTx, routedRequest.ReceivedFromEndpoint,
                                                                                           ack1.ReqP2pSeq16, routedRequest.ReceivedFromNeighborNullable, ack1.GetSignedFieldsForNeighborHMAC);
                // not waiting for NPACK, wait for ACK1
                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"waiting for ACK2");
                }

                var ack2UdpData = await Engine.OptionallySendUdpRequestAsync_Retransmit_WaitForResponse("ack2 2346892",
                                                                                                        routedRequest.ReceivedFromNeighborNullable?.ToString() ?? routedRequest.ReceivedFromEndpoint.ToString(),
                                                                                                        null, routedRequest.ReceivedFromEndpoint,
                                                                                                        InviteAck2Packet.GetScanner(logger, req, routedRequest.ReceivedFromNeighborNullable));

                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"received ACK2");
                }
                var ack2 = InviteAck2Packet.Decode(ack2UdpData);
                #endregion

                // send NPACK to ACK2
                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"sending NPACK to ACK2 to source peer");
                }
                SendNeighborPeerAckResponseToAck2(ack2, routedRequest.ReceivedFromNeighborNullable);

                // send ACK2 to responder
                // put ACK2.ReqP2pSeq16, sendertoken32, senderHMAC
                // wait for NPACK
                var ack2UdpDataTx = ack2.Encode_SetP2pFields(destinationPeer);
                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"sending ACK2 to responder");
                }
                await destinationPeer.SendUdpRequestAsync_Retransmit_WaitForNPACK("ack2 5344530", ack2UdpDataTx,
                                                                                  ack2.ReqP2pSeq16, ack2.GetSignedFieldsForNeighborHMAC);

                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"received NPACK to ACK2 from destination peer");
                }

                // wait for CFM from responder
                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"waiting for CFM from responder");
                }
                var cfmUdpData = await Engine.WaitForUdpResponseAsync(new PendingLowLevelUdpRequest("cfm 12358", destinationPeer.RemoteEndpoint,
                                                                                                    InviteConfirmationPacket.GetScanner(logger, req, destinationPeer),
                                                                                                    Engine.DateTimeNowUtc, Engine.Configuration.CfmTimoutS
                                                                                                    ));

                if (cfmUdpData == null)
                {
                    throw new DrpTimeoutException($"inv. proxy CFM response from destination peer {destinationPeer} (timeout={Engine.Configuration.CfmTimoutS}s)");
                }
                var cfm = InviteConfirmationPacket.Decode(cfmUdpData);
                // todo verify signature, update RDRs and QoS
                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"verified CFM from responder");
                }

                // respond NPACK to CFM to destination peer
                SendNeighborPeerAckResponseToCfm(cfm, destinationPeer);

                // send CFM to requester
                var cfmUdpDataTx = cfm.Encode_SetP2pFields(routedRequest.ReceivedFromNeighborNullable);

                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"sending CFM to requester, waiting for NPACK");
                }
                await Engine.OptionallySendUdpRequestAsync_Retransmit_WaitForNeighborPeerAck("cfm 23468", cfmUdpDataTx, routedRequest.ReceivedFromEndpoint,
                                                                                             cfm.ReqP2pSeq16, routedRequest.ReceivedFromNeighborNullable, cfm.GetSignedFieldsForNeighborHMAC);

                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"received NPACK to CFM from source peer");
                }
            }
            catch (DrpTimeoutException exc)
            {
                logger.WriteToLog_lightPain($"could not proxy INVITE: {exc.Message}");
            }
            catch (Exception exc)
            {
                logger.WriteToLog_mediumPain($"could not proxy INVITE request: {exc}");
            }
            finally
            {
                _pendingInviteRequests.Remove(req.RequesterRegistrationId);
            }
            return(false);
        }
Exemple #2
0
        /// <summary>
        /// main register responder proc for both A-EP and P2P modes
        /// in P2P mode NeighborToken32 and NeighborHMAC are verified at this time
        /// </summary>
        /// <param name="receivedFromInP2pMode">
        /// is null in A-EP mode
        /// </param>
        /// <returns>
        /// true to retry the request with another neighbor (if the request needs to be "rerouted")
        /// </returns>
        internal async Task <bool> ProxyRegisterRequestAsync(RoutedRequest routedRequest, ConnectionToNeighbor destinationPeer) // engine thread
        {
            routedRequest.ReceivedFromNeighborNullable?.AssertIsNotDisposed();
            var req    = routedRequest.RegisterReq;
            var logger = routedRequest.Logger;

            logger.ModuleName = VisionChannelModuleName_reg_proxySide;

            if (!ValidateReceivedReqTimestamp64(req.ReqTimestamp64))
            {
                logger.WriteToLog_needsAttention($"rejecting REGISTER request {req.RequesterRegistrationId}: invalid REGISTER REQ 457 ReqTimestamp64={MiscProcedures.Int64ticksToDateTime(req.ReqTimestamp64)}");
                //   await routedRequest.SendErrorResponse(ResponseOrFailureCode.failure_numberOfHopsRemainingReachedZero);
                return(false);
            }

            if (PendingRegisterRequestExists(req.RequesterRegistrationId))
            {
                logger.WriteToLog_higherLevelDetail($"rejecting duplicate request {req}: requesterEndpoint={routedRequest.ReceivedFromEndpoint}");
                await routedRequest.SendErrorResponse(ResponseOrFailureCode.failure_routeIsUnavailable);

                return(false);
            }

            if (req.NumberOfHopsRemaining > RegisterRequestPacket.MaxNumberOfHopsRemaining || req.NumberOfRandomHopsRemaining > RegisterRequestPacket.MaxNumberOfHopsRemaining)
            {
                logger.WriteToLog_needsAttention($"rejecting {req}: invalid number of hops remaining");
                await routedRequest.SendErrorResponse(ResponseOrFailureCode.failure_routeIsUnavailable);

                return(false);
            }

            if (!routedRequest.CheckedRecentUniqueProxiedRequests)
            {
                var recentUniqueProxiedRegistrationRequests = req.RandomModeAtThisHop ? RecentUniqueProxiedRegistrationRequests_RandomHop : RecentUniqueProxiedRegistrationRequests_NonRandomHop;
                if (!recentUniqueProxiedRegistrationRequests.Filter(req.GetUniqueRequestIdFields))
                {
                    logger.WriteToLog_higherLevelDetail($"rejecting non-unique request {req}: requesterEndpoint={routedRequest.ReceivedFromEndpoint}");
                    await routedRequest.SendErrorResponse(ResponseOrFailureCode.failure_routeIsUnavailable);

                    return(false);
                }
                routedRequest.CheckedRecentUniqueProxiedRequests = true;
            }

            logger.WriteToLog_higherLevelDetail($"proxying {req}: requesterEndpoint={routedRequest.ReceivedFromEndpoint}, NumberOfHopsRemaining={req.NumberOfHopsRemaining}, ReqP2pSeq16={req.ReqP2pSeq16}, destinationPeer={destinationPeer}, sourcePeer={routedRequest.ReceivedFromNeighborNullable}");

            if (!ValidateReceivedReqTimestamp64(req.ReqTimestamp64))
            {
                throw new BadSignatureException($"invalid REGISTER REQ ReqTimestamp64={MiscProcedures.Int64ticksToDateTime(req.ReqTimestamp64)} 3507");
            }

            req.NumberOfHopsRemaining--;
            if (req.NumberOfHopsRemaining == 0)
            {
                logger.WriteToLog_needsAttention($"rejecting REGISTER request {req.RequesterRegistrationId}: max hops reached");
                await routedRequest.SendErrorResponse(ResponseOrFailureCode.failure_numberOfHopsRemainingReachedZero);

                return(false);
            }

            _pendingRegisterRequests.Add(req.RequesterRegistrationId);
            try
            {
                // send NPACK to source peer
                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"sending NPACK to REQ source peer (delay={routedRequest.ReqReceivedSw_ms}ms)");
                }
                routedRequest.SendNeighborPeerAck_accepted_IfNotAlreadyReplied();

                if (req.NumberOfRandomHopsRemaining >= 1)
                {
                    req.NumberOfRandomHopsRemaining--;
                }
                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"decremented number of hops in {req}: NumberOfHopsRemaining={req.NumberOfHopsRemaining}, NumberOfRandomHopsRemaining={req.NumberOfRandomHopsRemaining}");
                }

                req.ReqP2pSeq16 = destinationPeer.GetNewRequestP2pSeq16_P2P();
                byte[] ack1UdpData;
                try
                {
                    var sentRequest = new SentRequest(this, logger, destinationPeer.RemoteEndpoint, destinationPeer, req.Encode_OptionallySignNeighborHMAC(destinationPeer),
                                                      req.ReqP2pSeq16, RegisterAck1Packet.GetScanner(logger, req, destinationPeer));

                    // send (proxy) REQ to responder. wait for NPACK, verify NPACK.senderHMAC, retransmit REQ
                    // wait for ACK1 from destination peer
                    // verify NeighborHMAC
                    // var ack1R = await sentRequest.SendRequestAsync_NoExc("ack1 34601"); ////////////////////////////////// new method
                    ack1UdpData = await sentRequest.SendRequestAsync("ack1 34601");

                    //  if (logger.WriteToLog_detail2_enabled) logger.WriteToLog_detail("got ACK1 result");

                    if (routedRequest.ReceivedFromNeighborNullable?.IsDisposed == true)
                    {
                        logger.WriteToLog_needsAttention($"sourcePeer={routedRequest.ReceivedFromNeighborNullable} is disposed during proxying 52460");
                        return(false);
                    }
                    if (destinationPeer?.IsDisposed == true)
                    {
                        logger.WriteToLog_needsAttention($"destinationPeer={destinationPeer} is disposed during proxying 52460");
                        return(false);
                    }

                    //if (ack1R.ResponseCode != ResponseOrFailureCode.accepted)
                    //{
                    //    logger.WriteToLog_higherLevelDetail($"got response={ack1R.ResponseCode} from destination {destinationPeer}");
                    //    if (ack1R.ResponseCode == ResponseOrFailureCode.failure_routeIsUnavailable)
                    //        req.NumberOfHopsRemaining++; // roll back previous decrement for a new trial
                    //    return true; // will retry
                    //}
                    //ack1UdpData = ack1R.UdpData;
                }
                catch (RequestRejectedException reqExc)
                {
                    logger.WriteToLog_higherLevelDetail($"got exception: response={reqExc.ResponseCode} from destination {destinationPeer}");
                    if (reqExc.ResponseCode == ResponseOrFailureCode.failure_numberOfHopsRemainingReachedZero)
                    {
                        await routedRequest.SendErrorResponse(ResponseOrFailureCode.failure_numberOfHopsRemainingReachedZero);

                        return(false);
                    }

                    if (routedRequest.ReceivedFromNeighborNullable?.IsDisposed == true)
                    {
                        logger.WriteToLog_needsAttention($"sourcePeer={routedRequest.ReceivedFromNeighborNullable} is disposed during proxying 35346232");
                        return(false);
                    }
                    if (reqExc.ResponseCode == ResponseOrFailureCode.failure_routeIsUnavailable)
                    {
                        req.NumberOfHopsRemaining++; // roll back previous decrement for a new trial
                    }

                    return(true); // will retry
                }
                catch (DrpTimeoutException exc)
                {
                    logger.WriteToLog_higherLevelDetail($"got timeout error when requesting {destinationPeer}: {exc.Message}");
                    req.NumberOfHopsRemaining++; // roll back previous decrement for a new trial
                    return(true);                // will retry
                }
                catch (Exception reqExc)
                {
                    logger.WriteToLog_mediumPain($"could not proxy REGISTER request: {reqExc}");
                    if (routedRequest.ReceivedFromNeighborNullable?.IsDisposed == true)
                    {
                        logger.WriteToLog_needsAttention($"sourcePeer={routedRequest.ReceivedFromNeighborNullable} is disposed during proxying 76897805");
                        return(false);
                    }
                    return(true); // will retry
                }

                var tr1  = CreateTracker("ack1 34601 2");
                var ack1 = RegisterAck1Packet.DecodeAndOptionallyVerify(logger, ack1UdpData, req, null);
                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"verified ACK1 from destination");
                }

                // respond with NPACK
                SendNeighborPeerAckResponseToRegisterAck1(ack1, destinationPeer);

                // send ACK1 to source peer
                // wait for ACK / NPACK
                if (routedRequest.ReceivedFromNeighborNullable != null)
                {   // P2P mode
                    routedRequest.ReceivedFromNeighborNullable.AssertIsNotDisposed();
                    ack1.ReqP2pSeq16 = routedRequest.ReceivedFromNeighborNullable.GetNewRequestP2pSeq16_P2P();
                }
                else
                {   // A-EP mode
                    ack1.RequesterEndpoint = routedRequest.ReceivedFromEndpoint;
                }
                var ack1UdpDataTx = ack1.Encode_OpionallySignNeighborHMAC(routedRequest.ReceivedFromNeighborNullable);

                var sourcePeerVisibleDescription = routedRequest.ReceivedFromNeighborNullable?.ToString() ?? routedRequest.ReceivedFromEndpoint.ToString();
                var ack2Scanner = RegisterAck2Packet.GetScanner(logger, routedRequest.ReceivedFromNeighborNullable, req);
                tr1.Dispose();
                byte[] ack2UdpData;
                if (routedRequest.ReceivedFromNeighborNullable == null)
                {   // A-EP mode: wait for ACK2, retransmitting ACK1
                    if (logger.WriteToLog_detail_enabled)
                    {
                        logger.WriteToLog_detail($"sending ACK1, waiting for ACK2");
                    }
                    ack2UdpData = await OptionallySendUdpRequestAsync_Retransmit_WaitForResponse("ack2 12368", sourcePeerVisibleDescription,
                                                                                                 ack1UdpDataTx, routedRequest.ReceivedFromEndpoint, ack2Scanner);
                }
                else
                {   // P2P mode: retransmit ACK1 until NPACK (via P2P); at same time wait for ACK2
                    if (logger.WriteToLog_detail_enabled)
                    {
                        logger.WriteToLog_detail($"sending ACK1, awaiting for NPACK");
                    }
                    _ = OptionallySendUdpRequestAsync_Retransmit_WaitForNeighborPeerAck("ack1 3686", ack1UdpDataTx, routedRequest.ReceivedFromEndpoint,
                                                                                        ack1.ReqP2pSeq16, routedRequest.ReceivedFromNeighborNullable, ack1.GetSignedFieldsForNeighborHMAC);
                    // not waiting for NPACK, wait for ACK2
                    if (logger.WriteToLog_detail_enabled)
                    {
                        logger.WriteToLog_detail($"waiting for ACK2");
                    }
                    ack2UdpData = await OptionallySendUdpRequestAsync_Retransmit_WaitForResponse("ack2 345209", sourcePeerVisibleDescription,
                                                                                                 null, routedRequest.ReceivedFromEndpoint, ack2Scanner);
                }

                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"received ACK2");
                }
                if (routedRequest.ReceivedFromNeighborNullable?.IsDisposed == true)
                {
                    logger.WriteToLog_needsAttention($"sourcePeer={routedRequest.ReceivedFromNeighborNullable} is disposed during proxying 2345135");
                    return(false);
                }
                if (destinationPeer?.IsDisposed == true)
                {
                    logger.WriteToLog_needsAttention($"destinationPeer={destinationPeer} is disposed during proxying 2345135");
                    return(false);
                }
                var ack2 = RegisterAck2Packet.Decode_OptionallyVerify_InitializeP2pStreamAtResponder(logger, ack2UdpData, null, null, null);

                // send NPACK to source peer
                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"sending NPACK to ACK2 to source peer");
                }
                SendNeighborPeerAckResponseToRegisterAck2(ack2, routedRequest.ReceivedFromEndpoint, routedRequest.ReceivedFromNeighborNullable);

                // send ACK2 to destination peer
                // put ACK2.ReqP2pSeq16, sendertoken32, senderHMAC
                // wait for NPACK
                if (destinationPeer.IsDisposed == true)
                {
                    logger.WriteToLog_needsAttention($"destinationPeer={destinationPeer} is disposed during proxying 345784567");
                    return(false);
                }
                if (routedRequest.ReceivedFromNeighborNullable?.IsDisposed == true)
                {
                    logger.WriteToLog_needsAttention($"sourcePeer={routedRequest.ReceivedFromNeighborNullable} is disposed during proxying 345784567");
                    return(false);
                }
                ack2.ReqP2pSeq16 = destinationPeer.GetNewRequestP2pSeq16_P2P();
                await destinationPeer.SendUdpRequestAsync_Retransmit_WaitForNPACK("ack2 41937", ack2.Encode_OptionallySignNeighborHMAC(destinationPeer),
                                                                                  ack2.ReqP2pSeq16, ack2.GetSignedFieldsForNeighborHMAC);

                if (routedRequest.ReceivedFromNeighborNullable?.IsDisposed == true)
                {
                    logger.WriteToLog_needsAttention($"sourcePeer={routedRequest.ReceivedFromNeighborNullable} is disposed during proxying 234646");
                    return(false);
                }
                if (destinationPeer?.IsDisposed == true)
                {
                    logger.WriteToLog_needsAttention($"destinationPeer={destinationPeer} is disposed during proxying 234646");
                    return(false);
                }

                // wait for CFM from source peer
                var cfmUdpData = await OptionallySendUdpRequestAsync_Retransmit_WaitForResponse("cfm 234789", sourcePeerVisibleDescription, null,
                                                                                                routedRequest.ReceivedFromEndpoint,
                                                                                                RegisterConfirmationPacket.GetScanner(logger, routedRequest.ReceivedFromNeighborNullable, req)
                                                                                                );

                var cfm = RegisterConfirmationPacket.DecodeAndOptionallyVerify(cfmUdpData, null, null);
                if (routedRequest.ReceivedFromNeighborNullable?.IsDisposed == true)
                {
                    logger.WriteToLog_needsAttention($"sourcePeer={routedRequest.ReceivedFromNeighborNullable} is disposed during proxying 3452326");
                    return(false);
                }
                if (destinationPeer?.IsDisposed == true)
                {
                    logger.WriteToLog_needsAttention($"destinationPeer={destinationPeer} is disposed during proxying 3452326");
                    return(false);
                }

                // TODO verify signatures and update QoS

                // send NPACK to source peer
                SendNeighborPeerAckResponseToRegisterCfm(cfm, routedRequest.ReceivedFromEndpoint, routedRequest.ReceivedFromNeighborNullable);

                // send CFM to responder
                // wait for NPACK from destination peer, retransmit
                if (destinationPeer.IsDisposed == true)
                {
                    logger.WriteToLog_needsAttention($"destinationPeer={destinationPeer} is disposed during proxying 123678");
                    return(false);
                }
                if (routedRequest.ReceivedFromNeighborNullable?.IsDisposed == true)
                {
                    logger.WriteToLog_needsAttention($"sourcePeer={routedRequest.ReceivedFromNeighborNullable} is disposed during proxying 123678");
                    return(false);
                }
                cfm.ReqP2pSeq16 = destinationPeer.GetNewRequestP2pSeq16_P2P();
                await destinationPeer.SendUdpRequestAsync_Retransmit_WaitForNPACK("cfm 1357", cfm.Encode_OptionallySignNeighborHMAC(destinationPeer),
                                                                                  cfm.ReqP2pSeq16, cfm.GetSignedFieldsForNeighborHMAC);


                logger.WriteToLog_higherLevelDetail($"proxying {req} is successfully complete");
            }
            catch (DrpTimeoutException exc)
            {
                logger.WriteToLog_lightPain($"could not proxy REGISTER: request timeout: {exc.Message}");
            }
            catch (Exception exc)
            {
                logger.WriteToLog_mediumPain($"could not proxy REGISTER request: {exc}");
            }
            finally
            {
                _pendingRegisterRequests.Remove(req.RequesterRegistrationId);
            }

            return(false);
        }
Exemple #3
0
        /// <summary>
        /// sends INVITE, autenticates users, returns Session to be used to create direct cannel
        /// </summary>
        /// <param name="responderUserId">
        /// comes from local contact book
        /// </param>
        /// <param name="responderRegId">
        /// comes from local contact book
        /// </param>
        /// <param name="loggerCb">may be invoked more than one time (in case of retrying)</param>
        public async Task <InviteSession> SendInviteAsync(UserCertificate requesterUserCertificate, RegistrationId responderRegistrationId, UserId responderUserId,
                                                          SessionType sessionType, Action <Logger> loggerCb = null)
        {
            InviteSession session = null;

            try
            {
                var           sw            = Stopwatch.StartNew();
                RoutedRequest routedRequest = null;
                int           trialsCount   = 0;
                Exception     latestTriedNeighborException = null;


_retry:
                trialsCount++;
                session = new InviteSession(this);
                var req = new InviteRequestPacket
                {
                    NumberOfHopsRemaining   = InviteRequestPacket.MaxNumberOfHopsRemaining,
                    RequesterEcdhePublicKey = new EcdhPublicKey(session.LocalInviteAckEcdhePublicKey),
                    RequesterRegistrationId = this.Configuration.LocalPeerRegistrationId,
                    ResponderRegistrationId = responderRegistrationId,
                    ReqTimestamp32S         = Engine.Timestamp32S,
                };
                var logger = new Logger(Engine, this, req, DrpPeerEngine.VisionChannelModuleName_inv_requesterSide);
                if (!Engine.RecentUniqueInviteRequests.Filter(req.GetUniqueRequestIdFields))
                {
                    if (trialsCount > 50)
                    {
                        throw new NonUniquePacketFieldsException($"could not find unique fields to send INVITE request");
                    }
                    if (logger.WriteToLog_detail_enabled)
                    {
                        logger.WriteToLog_detail($"waiting a second to generate ne wunique INVITE request");
                    }
                    await Engine.EngineThreadQueue.WaitAsync(TimeSpan.FromSeconds(1), "inv_wait_1236");

                    goto _retry;
                }


                session.Logger = logger;
                loggerCb?.Invoke(logger);
                Engine.RecentUniquePublicEcdhKeys.AssertIsUnique(req.RequesterEcdhePublicKey.Ecdh25519PublicKey, "req.RequesterEcdhePublicKey");
                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"generated unique ECDH key {req.RequesterEcdhePublicKey}");
                }
                req.RequesterRegistrationSignature = RegistrationSignature.Sign(Engine.CryptoLibrary, req.GetSharedSignedFields, this.Configuration.LocalPeerRegistrationPrivateKey);

                this.TestDirection(logger, req.ResponderRegistrationId);
                routedRequest = new RoutedRequest(logger, null, null, null, req, null, routedRequest);

                // find best connected peer to send the request
                var destinationPeer = Engine.RouteInviteRequest(this, routedRequest);
                if (destinationPeer == null)
                {
                    if (latestTriedNeighborException == null)
                    {
                        throw new NoNeighborsToSendInviteException();
                    }
                    else
                    {
                        throw latestTriedNeighborException;
                    }
                }
                InviteAck1Packet ack1;
                try
                {
                    var reqUdpData = req.Encode_SetP2pFields(destinationPeer);
                    if (logger.WriteToLog_detail_enabled)
                    {
                        logger.WriteToLog_detail($"sending {req} (ReqTimestamp32S={MiscProcedures.Uint32secondsToDateTime(req.ReqTimestamp32S)}), waiting for NPACK");
                    }

                    var sentRequest = new SentRequest(Engine, logger, destinationPeer.RemoteEndpoint, destinationPeer, reqUdpData, req.ReqP2pSeq16, InviteAck1Packet.GetScanner(logger, req, destinationPeer));
                    var ack1UdpData = await sentRequest.SendRequestAsync("ack1 4146");

                    #region process ACK1
                    // NeighborHMAC and NeighborToken32 are already verified by scanner
                    ack1 = InviteAck1Packet.Decode(ack1UdpData);
                    Engine.RecentUniquePublicEcdhKeys.AssertIsUnique(ack1.ResponderEcdhePublicKey.Ecdh25519PublicKey, $"ack1.ResponderEcdhePublicKey");
                    if (!ack1.ResponderRegistrationSignature.Verify(Engine.CryptoLibrary, w =>
                    {
                        req.GetSharedSignedFields(w);
                        ack1.GetSharedSignedFields(w, true);
                    },
                                                                    responderRegistrationId))
                    {
                        throw new BadSignatureException("invalid REGISTER ACK1 ResponderRegistrationSignature 2349");
                    }
                    if (logger.WriteToLog_detail_enabled)
                    {
                        logger.WriteToLog_detail($"verified ACK1");
                    }
                    session.DeriveSharedInviteAckDhSecret(Engine.CryptoLibrary, ack1.ResponderEcdhePublicKey.Ecdh25519PublicKey);

                    // send NPACK to ACK1
                    SendNeighborPeerAckResponseToAck1(ack1, destinationPeer);
                    #endregion
                }
                catch (RequestFailedException exc2)
                {
                    latestTriedNeighborException = exc2;
                    if (trialsCount > 50)
                    {
                        throw;
                    }
                    logger.WriteToLog_higherLevelDetail($"trying again on error {exc2.Message}... alreadyTriedProxyingToDestinationPeers.Count={routedRequest.TriedNeighbors.Count}");
                    routedRequest.TriedNeighbors.Add(destinationPeer);
                    goto _retry;
                }

                // decode and verify SD
                session.RemoteSessionDescription = InviteSessionDescription.Decrypt_Verify(Engine.CryptoLibrary,
                                                                                           ack1.ToResponderSessionDescriptionEncrypted,
                                                                                           req, ack1, false, session,
                                                                                           responderUserId, Engine.DateTimeNowUtc);

                // sign and encode local SD
                session.LocalSessionDescription = new InviteSessionDescription
                {
                    DirectChannelEndPoint = destinationPeer.LocalEndpoint,
                    SessionType           = sessionType,
                    DirectChannelToken32  = session.LocalDirectChannelToken32
                };

                session.LocalSessionDescription.UserCertificate = requesterUserCertificate;

                session.LocalSessionDescription.UserCertificateSignature = UserCertificateSignature.Sign(Engine.CryptoLibrary,
                                                                                                         w =>
                {
                    req.GetSharedSignedFields(w);
                    ack1.GetSharedSignedFields(w, true);
                    session.LocalSessionDescription.WriteSignedFields(w);
                },
                                                                                                         requesterUserCertificate
                                                                                                         );

                #region send ack2
                var ack2 = new InviteAck2Packet
                {
                    RequesterRegistrationId = req.RequesterRegistrationId,
                    ResponderRegistrationId = req.ResponderRegistrationId,
                    ReqTimestamp32S         = req.ReqTimestamp32S,
                    ToRequesterSessionDescriptionEncrypted = session.LocalSessionDescription.Encrypt(Engine.CryptoLibrary, req, ack1, session, true)
                };
                ack2.RequesterRegistrationSignature = RegistrationSignature.Sign(Engine.CryptoLibrary, w =>
                {
                    req.GetSharedSignedFields(w);
                    ack1.GetSharedSignedFields(w, true);
                    ack2.GetSharedSignedFields(w);
                }, this.Configuration.LocalPeerRegistrationPrivateKey);
                var ack2UdpData = ack2.Encode_SetP2pFields(destinationPeer);

                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"sending ACK2, waiting for NPACK");
                }
                await destinationPeer.SendUdpRequestAsync_Retransmit_WaitForNPACK("ack2 234575672", ack2UdpData, ack2.ReqP2pSeq16, ack2.GetSignedFieldsForNeighborHMAC);

                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"received NPACK");
                }
                #endregion

                #region wait for CFM
                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"waiting for CFM");
                }
                var cfmUdpData = await Engine.WaitForUdpResponseAsync(new PendingLowLevelUdpRequest("cfm 1235695", destinationPeer.RemoteEndpoint,
                                                                                                    InviteConfirmationPacket.GetScanner(logger, req, destinationPeer),
                                                                                                    Engine.DateTimeNowUtc, Engine.Configuration.CfmTimoutS
                                                                                                    ));

                if (cfmUdpData == null)
                {
                    throw new DrpTimeoutException($"did not get CFM at invite requester from destination peer {destinationPeer} (timeout={Engine.Configuration.CfmTimoutS}s)");
                }

                // NeighborHMAC and NeighborToken32 are already verified by scanner
                var cfm = InviteConfirmationPacket.Decode(cfmUdpData);

                if (!cfm.ResponderRegistrationSignature.Verify(Engine.CryptoLibrary, w =>
                {
                    req.GetSharedSignedFields(w);
                    ack1.GetSharedSignedFields(w, true);
                    ack2.GetSharedSignedFields(w);
                },
                                                               responderRegistrationId))
                {
                    throw new BadSignatureException("invalid REGISTER CFM ResponderRegistrationSignature 6398");
                }

                if (logger.WriteToLog_detail_enabled)
                {
                    logger.WriteToLog_detail($"verified CFM");
                }

                // send NPACK to CFM
                SendNeighborPeerAckResponseToCfm(cfm, destinationPeer);
                #endregion

                session.DeriveSharedPingPongHmacKey(req, ack1, ack2, cfm);
                return(session);
            }
            catch
            {
                session?.Dispose();
                throw;
            }
        }
        /// <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--;
            }
        }
Exemple #5
0
        /// <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--;
            }
        }