BUGZ-322 - add domain checkin lag logging

domain-server/src/DomainGatekeeper.cpp

@@ -358,7 +358,7 @@ SharedNodePointer DomainGatekeeper::processAssignmentConnectRequest(const NodeCo
     nodeData->setNodeVersion(it->second.getNodeVersion());
     nodeData->setHardwareAddress(nodeConnection.hardwareAddress);
     nodeData->setMachineFingerprint(nodeConnection.machineFingerprint);
-
+    nodeData->setLastDomainCheckinTimestamp(nodeConnection.lastPingTimestamp);
     nodeData->setWasAssigned(true);
 
     // cleanup the PendingAssignedNodeData for this assignment now that it's connecting
@@ -499,6 +499,9 @@ SharedNodePointer DomainGatekeeper::processAgentConnectRequest(const NodeConnect
     // set the machine fingerprint passed in the connect request
     nodeData->setMachineFingerprint(nodeConnection.machineFingerprint);
 
+    // set the last ping timestamp passed in the connect 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/DomainServer.cpp

@@ -1068,6 +1068,8 @@ void DomainServer::processListRequestPacket(QSharedPointer<ReceivedMessage> mess
     // update the connecting hostname in case it has changed
     nodeData->setPlaceName(nodeRequestData.placeName);
 
+    nodeData->setLastDomainCheckinTimestamp(nodeRequestData.lastPingTimestamp);
+
     sendDomainListToNode(sendingNode, message->getSenderSockAddr());
 }
 
@@ -1174,6 +1176,10 @@ void DomainServer::sendDomainListToNode(const SharedNodePointer& node, const Hif
 
     DomainServerNodeData* nodeData = static_cast<DomainServerNodeData*>(node->getLinkedData());
 
+    domainListStream << nodeData->getLastDomainCheckinTimestamp();
+
+    domainListStream << usecTimestampNow();
+
     // store the nodeInterestSet on this DomainServerNodeData, in case it has changed
     auto& nodeInterestSet = nodeData->getNodeInterestSet();
 

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;
     NodeType_t nodeType;
     HifiSockAddr publicSockAddr;
     HifiSockAddr localSockAddr;

libraries/networking/src/NodeList.cpp

@@ -412,6 +412,8 @@ void NodeList::sendDomainServerCheckIn() {
             packetStream << FingerprintUtils::getMachineFingerprint();
         }
 
+        packetStream << usecTimestampNow();
+
         // 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 +620,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 +638,57 @@ 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;
+    setPermissions(newPermissions);
+    // Is packet authentication enabled?
+    bool isAuthenticated;
+    packetStream >> isAuthenticated;
+    setAuthenticatePackets(isAuthenticated);
+
+    quint64 connectRequestTimestamp;
+    quint64 now = usecTimestampNow();
+    packetStream >> connectRequestTimestamp;
+    quint64 pingLagTime = (now - connectRequestTimestamp) / USECS_PER_MSEC;
+    quint64 domainServerPingReceiveTime;
+
+    packetStream >> domainServerPingReceiveTime;
+    quint64 domainServerRequestLag = (domainServerPingReceiveTime - connectRequestTimestamp) / USECS_PER_MSEC;
+    quint64 domainServerResponseLag = (now - domainServerPingReceiveTime) / 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 (with skew): " << domainServerRequestLag << "msec";
+        qWarning(networking) << "DomainList response lag (with skew): " << 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 > MSECS_PER_SECOND) {
+        qCDebug(networking) << "DomainList ping is lagging: " << pingLagTime << "msec";
+        qCDebug(networking) << "DomainList request lag (with skew): " << domainServerRequestLag << "msec";
+        qCDebug(networking) << "DomainList response lag (with skew): " << 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 (with skew): " << domainServerRequestLag << "msec";
+        qWarning(networking) << "DomainList response lag (with skew): " << 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,15 +719,6 @@ 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
     while (packetStream.device()->pos() < message->getSize()) {
         parseNodeFromPacketStream(packetStream);

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 {