diff --git a/domain-server/src/DomainGatekeeper.cpp b/domain-server/src/DomainGatekeeper.cpp index 29656f4465..f5705a570b 100644 --- a/domain-server/src/DomainGatekeeper.cpp +++ b/domain-server/src/DomainGatekeeper.cpp @@ -128,7 +128,7 @@ void DomainGatekeeper::processConnectRequestPacket(QSharedPointergetFirstPacketReceiveTime()); } else { qDebug() << "Refusing connection from node at" << message->getSenderSockAddr() << "with hardware address" << nodeConnection.hardwareAddress @@ -358,7 +358,8 @@ SharedNodePointer DomainGatekeeper::processAssignmentConnectRequest(const NodeCo nodeData->setNodeVersion(it->second.getNodeVersion()); nodeData->setHardwareAddress(nodeConnection.hardwareAddress); nodeData->setMachineFingerprint(nodeConnection.machineFingerprint); - + // client-side send time of last connect/domain list request + nodeData->setLastDomainCheckinTimestamp(nodeConnection.lastPingTimestamp); nodeData->setWasAssigned(true); // cleanup the PendingAssignedNodeData for this assignment now that it's connecting @@ -499,6 +500,9 @@ SharedNodePointer DomainGatekeeper::processAgentConnectRequest(const NodeConnect // set the machine fingerprint passed in the connect request nodeData->setMachineFingerprint(nodeConnection.machineFingerprint); + // set client-side send time of last connect/domain list request + nodeData->setLastDomainCheckinTimestamp(nodeConnection.lastPingTimestamp); + // also add an interpolation to DomainServerNodeData so that servers can get username in stats nodeData->addOverrideForKey(USERNAME_UUID_REPLACEMENT_STATS_KEY, uuidStringWithoutCurlyBraces(newNode->getUUID()), username); diff --git a/domain-server/src/DomainGatekeeper.h b/domain-server/src/DomainGatekeeper.h index f8d79179d6..92b400882e 100644 --- a/domain-server/src/DomainGatekeeper.h +++ b/domain-server/src/DomainGatekeeper.h @@ -64,7 +64,7 @@ public slots: signals: void killNode(SharedNodePointer node); - void connectedNode(SharedNodePointer node); + void connectedNode(SharedNodePointer node, quint64 requestReceiveTime); public slots: void updateNodePermissions(); diff --git a/domain-server/src/DomainServer.cpp b/domain-server/src/DomainServer.cpp index 051dd989f5..9a2aaca18b 100644 --- a/domain-server/src/DomainServer.cpp +++ b/domain-server/src/DomainServer.cpp @@ -14,6 +14,7 @@ #include #include #include +#include #include #include @@ -57,6 +58,8 @@ #include +using namespace std::chrono; + Q_LOGGING_CATEGORY(domain_server, "hifi.domain_server") Q_LOGGING_CATEGORY(domain_server_ice, "hifi.domain_server.ice") @@ -1068,7 +1071,10 @@ void DomainServer::processListRequestPacket(QSharedPointer mess // update the connecting hostname in case it has changed nodeData->setPlaceName(nodeRequestData.placeName); - sendDomainListToNode(sendingNode, message->getSenderSockAddr()); + // client-side send time of last connect/domain list request + nodeData->setLastDomainCheckinTimestamp(nodeRequestData.lastPingTimestamp); + + sendDomainListToNode(sendingNode, message->getFirstPacketReceiveTime(), message->getSenderSockAddr()); } bool DomainServer::isInInterestSet(const SharedNodePointer& nodeA, const SharedNodePointer& nodeB) { @@ -1130,11 +1136,11 @@ QUrl DomainServer::oauthAuthorizationURL(const QUuid& stateUUID) { return authorizationURL; } -void DomainServer::handleConnectedNode(SharedNodePointer newNode) { +void DomainServer::handleConnectedNode(SharedNodePointer newNode, quint64 requestReceiveTime) { DomainServerNodeData* nodeData = static_cast(newNode->getLinkedData()); // reply back to the user with a PacketType::DomainList - sendDomainListToNode(newNode, nodeData->getSendingSockAddr()); + sendDomainListToNode(newNode, requestReceiveTime, nodeData->getSendingSockAddr()); // if this node is a user (unassigned Agent), signal if (newNode->getType() == NodeType::Agent && !nodeData->wasAssigned()) { @@ -1150,7 +1156,7 @@ void DomainServer::handleConnectedNode(SharedNodePointer newNode) { broadcastNewNode(newNode); } -void DomainServer::sendDomainListToNode(const SharedNodePointer& node, const HifiSockAddr &senderSockAddr) { +void DomainServer::sendDomainListToNode(const SharedNodePointer& node, quint64 requestPacketReceiveTime, const HifiSockAddr &senderSockAddr) { const int NUM_DOMAIN_LIST_EXTENDED_HEADER_BYTES = NUM_BYTES_RFC4122_UUID + NLPacket::NUM_BYTES_LOCALID + NUM_BYTES_RFC4122_UUID + NLPacket::NUM_BYTES_LOCALID + 4; @@ -1158,7 +1164,7 @@ void DomainServer::sendDomainListToNode(const SharedNodePointer& node, const Hif // this data is at the beginning of each of the domain list packets QByteArray extendedHeader(NUM_DOMAIN_LIST_EXTENDED_HEADER_BYTES, 0); QDataStream extendedHeaderStream(&extendedHeader, QIODevice::WriteOnly); - + DomainServerNodeData* nodeData = static_cast(node->getLinkedData()); auto limitedNodeList = DependencyManager::get(); extendedHeaderStream << limitedNodeList->getSessionUUID(); @@ -1167,13 +1173,14 @@ void DomainServer::sendDomainListToNode(const SharedNodePointer& node, const Hif extendedHeaderStream << node->getLocalID(); extendedHeaderStream << node->getPermissions(); extendedHeaderStream << limitedNodeList->getAuthenticatePackets(); + extendedHeaderStream << nodeData->getLastDomainCheckinTimestamp(); + extendedHeaderStream << requestPacketReceiveTime; + extendedHeaderStream << quint64(duration_cast(p_high_resolution_clock::now().time_since_epoch()).count()); auto domainListPackets = NLPacketList::create(PacketType::DomainList, extendedHeader); // always send the node their own UUID back QDataStream domainListStream(domainListPackets.get()); - DomainServerNodeData* nodeData = static_cast(node->getLinkedData()); - // store the nodeInterestSet on this DomainServerNodeData, in case it has changed auto& nodeInterestSet = nodeData->getNodeInterestSet(); diff --git a/domain-server/src/DomainServer.h b/domain-server/src/DomainServer.h index 8276566233..704650e594 100644 --- a/domain-server/src/DomainServer.h +++ b/domain-server/src/DomainServer.h @@ -111,7 +111,7 @@ private slots: void sendHeartbeatToMetaverse() { sendHeartbeatToMetaverse(QString()); } void sendHeartbeatToIceServer(); - void handleConnectedNode(SharedNodePointer newNode); + void handleConnectedNode(SharedNodePointer newNode, quint64 requestReceiveTime); void handleTempDomainSuccess(QNetworkReply* requestReply); void handleTempDomainError(QNetworkReply* requestReply); @@ -172,7 +172,7 @@ private: void handleKillNode(SharedNodePointer nodeToKill); void broadcastNodeDisconnect(const SharedNodePointer& disconnnectedNode); - void sendDomainListToNode(const SharedNodePointer& node, const HifiSockAddr& senderSockAddr); + void sendDomainListToNode(const SharedNodePointer& node, quint64 requestPacketReceiveTime, const HifiSockAddr& senderSockAddr); bool isInInterestSet(const SharedNodePointer& nodeA, const SharedNodePointer& nodeB); diff --git a/domain-server/src/DomainServerNodeData.h b/domain-server/src/DomainServerNodeData.h index f465cceb96..370886cbce 100644 --- a/domain-server/src/DomainServerNodeData.h +++ b/domain-server/src/DomainServerNodeData.h @@ -61,6 +61,9 @@ public: void setMachineFingerprint(const QUuid& machineFingerprint) { _machineFingerprint = machineFingerprint; } const QUuid& getMachineFingerprint() { return _machineFingerprint; } + void setLastDomainCheckinTimestamp(quint64 lastDomainCheckinTimestamp) { _lastDomainCheckinTimestamp = lastDomainCheckinTimestamp; } + quint64 getLastDomainCheckinTimestamp() { return _lastDomainCheckinTimestamp; } + void addOverrideForKey(const QString& key, const QString& value, const QString& overrideValue); void removeOverrideForKey(const QString& key, const QString& value); @@ -93,7 +96,7 @@ private: QString _nodeVersion; QString _hardwareAddress; QUuid _machineFingerprint; - + quint64 _lastDomainCheckinTimestamp; QString _placeName; bool _wasAssigned { false }; diff --git a/domain-server/src/NodeConnectionData.cpp b/domain-server/src/NodeConnectionData.cpp index 0a3782d79b..b3ea005bd1 100644 --- a/domain-server/src/NodeConnectionData.cpp +++ b/domain-server/src/NodeConnectionData.cpp @@ -36,6 +36,8 @@ NodeConnectionData NodeConnectionData::fromDataStream(QDataStream& dataStream, c // now the machine fingerprint dataStream >> newHeader.machineFingerprint; } + + dataStream >> newHeader.lastPingTimestamp; dataStream >> newHeader.nodeType >> newHeader.publicSockAddr >> newHeader.localSockAddr diff --git a/domain-server/src/NodeConnectionData.h b/domain-server/src/NodeConnectionData.h index dd9ca6b650..43661f9caf 100644 --- a/domain-server/src/NodeConnectionData.h +++ b/domain-server/src/NodeConnectionData.h @@ -22,6 +22,7 @@ public: bool isConnectRequest = true); QUuid connectUUID; + quint64 lastPingTimestamp{ 0 }; // client-side send time of last connect/domain list request NodeType_t nodeType; HifiSockAddr publicSockAddr; HifiSockAddr localSockAddr; diff --git a/libraries/networking/src/NodeList.cpp b/libraries/networking/src/NodeList.cpp index 4f0e3ca9bd..ae2a495431 100644 --- a/libraries/networking/src/NodeList.cpp +++ b/libraries/networking/src/NodeList.cpp @@ -11,6 +11,8 @@ #include "NodeList.h" +#include + #include #include #include @@ -37,6 +39,8 @@ #include "SharedUtil.h" #include +using namespace std::chrono; + const int KEEPALIVE_PING_INTERVAL_MS = 1000; NodeList::NodeList(char newOwnerType, int socketListenPort, int dtlsListenPort) : @@ -412,6 +416,8 @@ void NodeList::sendDomainServerCheckIn() { packetStream << FingerprintUtils::getMachineFingerprint(); } + packetStream << quint64(duration_cast(p_high_resolution_clock::now().time_since_epoch()).count()); + // pack our data to send to the domain-server including // the hostname information (so the domain-server can see which place name we came in on) packetStream << _ownerType.load() << publicSockAddr << localSockAddr << _nodeTypesOfInterest.toList(); @@ -618,32 +624,14 @@ void NodeList::processDomainServerConnectionTokenPacket(QSharedPointer message) { - if (_domainHandler.getSockAddr().isNull()) { - qWarning() << "IGNORING DomainList packet while not connected to a Domain Server"; - // refuse to process this packet if we aren't currently connected to the DS - return; - } - - // this is a packet from the domain server, reset the count of un-replied check-ins - _domainHandler.clearPendingCheckins(); - - // emit our signal so listeners know we just heard from the DS - emit receivedDomainServerList(); - - DependencyManager::get()->flagTimeForConnectionStep(LimitedNodeList::ConnectionStep::ReceiveDSList); + // parse header information QDataStream packetStream(message->getMessage()); // grab the domain's ID from the beginning of the packet QUuid domainUUID; packetStream >> domainUUID; - if (_domainHandler.isConnected() && _domainHandler.getUUID() != domainUUID) { - // Recieved packet from different domain. - qWarning() << "IGNORING DomainList packet from" << domainUUID << "while connected to" << _domainHandler.getUUID(); - return; - } - Node::LocalID domainLocalID; packetStream >> domainLocalID; @@ -654,6 +642,65 @@ void NodeList::processDomainServerList(QSharedPointer message) packetStream >> newUUID; packetStream >> newLocalID; + // pull the permissions/right/privileges for this node out of the stream + NodePermissions newPermissions; + packetStream >> newPermissions; + // Is packet authentication enabled? + bool isAuthenticated; + packetStream >> isAuthenticated; + + qint64 now = qint64(duration_cast(p_high_resolution_clock::now().time_since_epoch()).count()); + + quint64 connectRequestTimestamp; + packetStream >> connectRequestTimestamp; + + quint64 domainServerRequestReceiveTime; + packetStream >> domainServerRequestReceiveTime; + + quint64 domainServerPingSendTime; + packetStream >> domainServerPingSendTime; + + qint64 pingLagTime = (now - qint64(connectRequestTimestamp)) / qint64(USECS_PER_MSEC); + + qint64 domainServerRequestLag = (qint64(domainServerRequestReceiveTime) - qint64(connectRequestTimestamp)) / qint64(USECS_PER_MSEC); + quint64 domainServerCheckinProcessingTime = domainServerPingSendTime - domainServerRequestReceiveTime; + qint64 domainServerResponseLag = (now - qint64(domainServerPingSendTime)) / qint64(USECS_PER_MSEC); + + if (_domainHandler.getSockAddr().isNull()) { + qWarning(networking) << "IGNORING DomainList packet while not connected to a Domain Server: sent " << pingLagTime << " msec ago."; + qWarning(networking) << "DomainList request lag (interface->ds): " << domainServerRequestLag << "msec"; + qWarning(networking) << "DomainList server processing time: " << domainServerCheckinProcessingTime << "usec"; + qWarning(networking) << "DomainList response lag (ds->interface): " << domainServerResponseLag << "msec"; + // refuse to process this packet if we aren't currently connected to the DS + return; + } + + // warn if ping lag is getting long + if (pingLagTime > qint64(MSECS_PER_SECOND)) { + qCDebug(networking) << "DomainList ping is lagging: " << pingLagTime << "msec"; + qCDebug(networking) << "DomainList request lag (interface->ds): " << domainServerRequestLag << "msec"; + qCDebug(networking) << "DomainList server processing time: " << domainServerCheckinProcessingTime << "usec"; + qCDebug(networking) << "DomainList response lag (ds->interface): " << domainServerResponseLag << "msec"; + } + + // this is a packet from the domain server, reset the count of un-replied check-ins + _domainHandler.clearPendingCheckins(); + + // emit our signal so listeners know we just heard from the DS + emit receivedDomainServerList(); + + DependencyManager::get()->flagTimeForConnectionStep(LimitedNodeList::ConnectionStep::ReceiveDSList); + + if (_domainHandler.isConnected() && _domainHandler.getUUID() != domainUUID) { + // Recieved packet from different domain. + qWarning() << "IGNORING DomainList packet from" << domainUUID << "while connected to" + << _domainHandler.getUUID() << ": sent " << pingLagTime << " msec ago."; + qWarning(networking) << "DomainList request lag (interface->ds): " << domainServerRequestLag << "msec"; + qWarning(networking) << "DomainList server processing time: " << domainServerCheckinProcessingTime << "usec"; + qWarning(networking) << "DomainList response lag (ds->interface): " << domainServerResponseLag << "msec"; + return; + } + // when connected, if the session ID or local ID were not null and changed, we should reset auto currentLocalID = getSessionLocalID(); auto currentSessionID = getSessionUUID(); @@ -684,13 +731,7 @@ void NodeList::processDomainServerList(QSharedPointer message) DependencyManager::get()->lookupShareableNameForDomainID(domainUUID); } - // pull the permissions/right/privileges for this node out of the stream - NodePermissions newPermissions; - packetStream >> newPermissions; setPermissions(newPermissions); - // Is packet authentication enabled? - bool isAuthenticated; - packetStream >> isAuthenticated; setAuthenticatePackets(isAuthenticated); // pull each node in the packet diff --git a/libraries/networking/src/ReceivedMessage.cpp b/libraries/networking/src/ReceivedMessage.cpp index e70301dab1..7ae408ef7a 100644 --- a/libraries/networking/src/ReceivedMessage.cpp +++ b/libraries/networking/src/ReceivedMessage.cpp @@ -12,6 +12,7 @@ #include "ReceivedMessage.h" #include +#include #include "QSharedPointer" @@ -20,6 +21,8 @@ int sharedPtrReceivedMessageMetaTypeId = qRegisterMetaType(packetList.getFirstPacketReceiveTime().time_since_epoch()).count(); } ReceivedMessage::ReceivedMessage(NLPacket& packet) @@ -41,6 +45,7 @@ ReceivedMessage::ReceivedMessage(NLPacket& packet) _senderSockAddr(packet.getSenderSockAddr()), _isComplete(packet.getPacketPosition() == NLPacket::ONLY) { + _firstPacketReceiveTime = duration_cast(packet.getReceiveTime().time_since_epoch()).count(); } ReceivedMessage::ReceivedMessage(QByteArray byteArray, PacketType packetType, PacketVersion packetVersion, @@ -48,6 +53,7 @@ ReceivedMessage::ReceivedMessage(QByteArray byteArray, PacketType packetType, Pa _data(byteArray), _headData(_data.mid(0, HEAD_DATA_SIZE)), _numPackets(1), + _firstPacketReceiveTime(0), _sourceID(sourceID), _packetType(packetType), _packetVersion(packetVersion), @@ -77,7 +83,13 @@ void ReceivedMessage::appendPacket(NLPacket& packet) { emit progress(getSize()); } - if (packet.getPacketPosition() == NLPacket::PacketPosition::LAST) { + auto packetPosition = packet.getPacketPosition(); + if ((packetPosition == NLPacket::PacketPosition::FIRST) || + (packetPosition == NLPacket::PacketPosition::ONLY)) { + _firstPacketReceiveTime = duration_cast(packet.getReceiveTime().time_since_epoch()).count(); + } + + if (packetPosition == NLPacket::PacketPosition::LAST) { _isComplete = true; emit completed(); } diff --git a/libraries/networking/src/ReceivedMessage.h b/libraries/networking/src/ReceivedMessage.h index af87ef75af..c864616635 100644 --- a/libraries/networking/src/ReceivedMessage.h +++ b/libraries/networking/src/ReceivedMessage.h @@ -48,6 +48,8 @@ public: // Get the number of packets that were used to send this message qint64 getNumPackets() const { return _numPackets; } + qint64 getFirstPacketReceiveTime() const { return _firstPacketReceiveTime; } + qint64 getSize() const { return _data.size(); } qint64 getBytesLeftToRead() const { return _data.size() - _position; } @@ -92,6 +94,7 @@ private: std::atomic _position { 0 }; std::atomic _numPackets { 0 }; + std::atomic _firstPacketReceiveTime { 0 }; NLPacket::LocalID _sourceID { NLPacket::NULL_LOCAL_ID }; PacketType _packetType; diff --git a/libraries/networking/src/udt/Packet.cpp b/libraries/networking/src/udt/Packet.cpp index 0456fa1223..f8b74cea37 100644 --- a/libraries/networking/src/udt/Packet.cpp +++ b/libraries/networking/src/udt/Packet.cpp @@ -171,6 +171,7 @@ void Packet::copyMembers(const Packet& other) { _packetPosition = other._packetPosition; _messageNumber = other._messageNumber; _messagePartNumber = other._messagePartNumber; + _receiveTime = other._receiveTime; } void Packet::readHeader() const { diff --git a/libraries/networking/src/udt/PacketHeaders.cpp b/libraries/networking/src/udt/PacketHeaders.cpp index f8574b3b94..566e1e4946 100644 --- a/libraries/networking/src/udt/PacketHeaders.cpp +++ b/libraries/networking/src/udt/PacketHeaders.cpp @@ -27,7 +27,7 @@ PacketVersion versionForPacketType(PacketType packetType) { case PacketType::StunResponse: return 17; case PacketType::DomainList: - return static_cast(DomainListVersion::AuthenticationOptional); + return static_cast(DomainListVersion::HasTimestamp); case PacketType::EntityAdd: case PacketType::EntityClone: case PacketType::EntityEdit: @@ -72,7 +72,7 @@ PacketVersion versionForPacketType(PacketType packetType) { return static_cast(DomainConnectionDeniedVersion::IncludesExtraInfo); case PacketType::DomainConnectRequest: - return static_cast(DomainConnectRequestVersion::AlwaysHasMachineFingerprint); + return static_cast(DomainConnectRequestVersion::HasTimestamp); case PacketType::DomainServerAddedNode: return static_cast(DomainServerAddedNodeVersion::PermissionsGrid); diff --git a/libraries/networking/src/udt/PacketHeaders.h b/libraries/networking/src/udt/PacketHeaders.h index 5deadd8c43..903c1f4c93 100644 --- a/libraries/networking/src/udt/PacketHeaders.h +++ b/libraries/networking/src/udt/PacketHeaders.h @@ -344,7 +344,8 @@ enum class DomainConnectRequestVersion : PacketVersion { HasProtocolVersions, HasMACAddress, HasMachineFingerprint, - AlwaysHasMachineFingerprint + AlwaysHasMachineFingerprint, + HasTimestamp }; enum class DomainConnectionDeniedVersion : PacketVersion { @@ -363,7 +364,8 @@ enum class DomainListVersion : PacketVersion { PermissionsGrid, GetUsernameFromUUIDSupport, GetMachineFingerprintFromUUIDSupport, - AuthenticationOptional + AuthenticationOptional, + HasTimestamp }; enum class AudioVersion : PacketVersion { diff --git a/libraries/networking/src/udt/PacketList.cpp b/libraries/networking/src/udt/PacketList.cpp index d69ff39197..f6ea12242e 100644 --- a/libraries/networking/src/udt/PacketList.cpp +++ b/libraries/networking/src/udt/PacketList.cpp @@ -13,6 +13,7 @@ #include "../NetworkLogging.h" +#include #include using namespace udt; @@ -261,3 +262,11 @@ qint64 PacketList::writeData(const char* data, qint64 maxSize) { return maxSize; } + +p_high_resolution_clock::time_point PacketList::getFirstPacketReceiveTime() const { + using namespace std::chrono;; + if (!_packets.empty()) { + return _packets.front()->getReceiveTime(); + } + return p_high_resolution_clock::time_point(); +} \ No newline at end of file diff --git a/libraries/networking/src/udt/PacketList.h b/libraries/networking/src/udt/PacketList.h index b9bd6a8c15..8d3ffb2783 100644 --- a/libraries/networking/src/udt/PacketList.h +++ b/libraries/networking/src/udt/PacketList.h @@ -59,6 +59,9 @@ public: virtual qint64 size() const override { return getDataSize(); } qint64 writeString(const QString& string); + + p_high_resolution_clock::time_point getFirstPacketReceiveTime() const; + protected: PacketList(PacketType packetType, QByteArray extendedHeader = QByteArray(), bool isReliable = false, bool isOrdered = false); diff --git a/libraries/networking/src/udt/Socket.cpp b/libraries/networking/src/udt/Socket.cpp index 7829e3727c..6f93281b2a 100644 --- a/libraries/networking/src/udt/Socket.cpp +++ b/libraries/networking/src/udt/Socket.cpp @@ -334,6 +334,7 @@ void Socket::readPendingDatagrams() { if (system_clock::now() > abortTime) { // We've been running for too long, stop processing packets for now // Once we've processed the event queue, we'll come back to packet processing + qCDebug(networking) << "Socket::readPendingDatagrams() running too long, aborting to process event queue"; break; }