Merge pull request #15626 from roxanneskelly/domaincheckin

BUGZ-322 add domain checkin time-spent logging

domain-server/src/DomainGatekeeper.cpp

@@ -128,7 +128,7 @@ void DomainGatekeeper::processConnectRequestPacket(QSharedPointer<ReceivedMessag
 
         // signal that we just connected a node so the DomainServer can get it a list
         // and broadcast its presence right away
-        emit connectedNode(node);
+        emit connectedNode(node, message->getFirstPacketReceiveTime());
     } 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);

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();

domain-server/src/DomainServer.cpp

@@ -14,6 +14,7 @@
 #include <memory>
 #include <random>
 #include <iostream>
+#include <chrono>
 
 #include <QDir>
 #include <QJsonDocument>
@@ -57,6 +58,8 @@
 
 #include <OctreeDataUtils.h>
 
+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<ReceivedMessage> 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<DomainServerNodeData*>(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<DomainServerNodeData*>(node->getLinkedData());
     auto limitedNodeList = DependencyManager::get<LimitedNodeList>();
 
     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<microseconds>(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<DomainServerNodeData*>(node->getLinkedData());
-
     // store the nodeInterestSet on this DomainServerNodeData, in case it has changed
     auto& nodeInterestSet = nodeData->getNodeInterestSet();
 

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);
 

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 };

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

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;

libraries/networking/src/NodeList.cpp

@@ -11,6 +11,8 @@
 
 #include "NodeList.h"
 
+#include <chrono>
+
 #include <QtCore/QDataStream>
 #include <QtCore/QDebug>
 #include <QtCore/QJsonDocument>
@@ -37,6 +39,8 @@
 #include "SharedUtil.h"
 #include <Trace.h>
 
+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<microseconds>(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<ReceivedM
 }
 
 void NodeList::processDomainServerList(QSharedPointer<ReceivedMessage> 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<NodeList>()->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<ReceivedMessage> 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<microseconds>(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<NodeList>()->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<ReceivedMessage> message)
         DependencyManager::get<AddressManager>()->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

libraries/networking/src/ReceivedMessage.cpp

@@ -12,6 +12,7 @@
 #include "ReceivedMessage.h"
 
 #include <algorithm>
+#include <chrono>
 
 #include "QSharedPointer"
 
@@ -20,6 +21,8 @@ int sharedPtrReceivedMessageMetaTypeId = qRegisterMetaType<QSharedPointer<Receiv
 
 static const int HEAD_DATA_SIZE = 512;
 
+using namespace std::chrono;
+
 ReceivedMessage::ReceivedMessage(const NLPacketList& packetList)
     : _data(packetList.getMessage()),
       _headData(_data.mid(0, HEAD_DATA_SIZE)),
@@ -29,6 +32,7 @@ ReceivedMessage::ReceivedMessage(const NLPacketList& packetList)
       _packetVersion(packetList.getVersion()),
       _senderSockAddr(packetList.getSenderSockAddr())
 {
+    _firstPacketReceiveTime = duration_cast<microseconds>(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<microseconds>(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<microseconds>(packet.getReceiveTime().time_since_epoch()).count();
+    }
+
+    if (packetPosition == NLPacket::PacketPosition::LAST) {
         _isComplete = true;
         emit completed();
     }

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<qint64> _position { 0 };
     std::atomic<qint64> _numPackets { 0 };
+    std::atomic<quint64> _firstPacketReceiveTime { 0 };
 
     NLPacket::LocalID _sourceID { NLPacket::NULL_LOCAL_ID };
     PacketType _packetType;

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 {

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<PacketVersion>(DomainListVersion::AuthenticationOptional);
+            return static_cast<PacketVersion>(DomainListVersion::HasTimestamp);
         case PacketType::EntityAdd:
         case PacketType::EntityClone:
         case PacketType::EntityEdit:
@@ -72,7 +72,7 @@ PacketVersion versionForPacketType(PacketType packetType) {
             return static_cast<PacketVersion>(DomainConnectionDeniedVersion::IncludesExtraInfo);
 
         case PacketType::DomainConnectRequest:
-            return static_cast<PacketVersion>(DomainConnectRequestVersion::AlwaysHasMachineFingerprint);
+            return static_cast<PacketVersion>(DomainConnectRequestVersion::HasTimestamp);
 
         case PacketType::DomainServerAddedNode:
             return static_cast<PacketVersion>(DomainServerAddedNodeVersion::PermissionsGrid);

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 {

libraries/networking/src/udt/PacketList.cpp

@@ -13,6 +13,7 @@
 
 #include "../NetworkLogging.h"
 
+#include <chrono>
 #include <QDebug>
 
 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();
+}

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);

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;
         }