From 7154a11192e49945a8ac39a9820a12d47546a887 Mon Sep 17 00:00:00 2001
From: ZappoMan <brad@highfidelity.io>
Date: Wed, 26 Apr 2017 14:03:36 -0700
Subject: [PATCH] add some more logging

---
 assignment-client/src/Agent.cpp                    | 1 +
 assignment-client/src/avatars/AvatarMixer.cpp      | 8 ++++++++
 assignment-client/src/avatars/AvatarMixerSlave.cpp | 2 ++
 libraries/avatars/src/AvatarData.cpp               | 5 ++---
 4 files changed, 13 insertions(+), 3 deletions(-)

diff --git a/assignment-client/src/Agent.cpp b/assignment-client/src/Agent.cpp
index c8ab489311..3cfccbea9e 100644
--- a/assignment-client/src/Agent.cpp
+++ b/assignment-client/src/Agent.cpp
@@ -583,6 +583,7 @@ void Agent::setIsAvatar(bool isAvatar) {
 void Agent::sendAvatarIdentityPacket() {
     if (_isAvatar) {
         auto scriptedAvatar = DependencyManager::get<ScriptableAvatar>();
+        qDebug() << __FUNCTION__ << "about to call sendIdentityPacket()";
         scriptedAvatar->sendIdentityPacket();
     }
 }
diff --git a/assignment-client/src/avatars/AvatarMixer.cpp b/assignment-client/src/avatars/AvatarMixer.cpp
index 43eac8ebbe..5e131cbcd7 100644
--- a/assignment-client/src/avatars/AvatarMixer.cpp
+++ b/assignment-client/src/avatars/AvatarMixer.cpp
@@ -70,6 +70,7 @@ AvatarMixer::~AvatarMixer() {
 }
 
 void AvatarMixer::sendIdentityPacket(AvatarMixerClientData* nodeData, const SharedNodePointer& destinationNode) {
+    qDebug() << __FUNCTION__ << "about to call nodeData->getAvatar().identityByteArray()... for node:" << nodeData->getNodeID();
     QByteArray individualData = nodeData->getAvatar().identityByteArray();
 
     auto identityPacket = NLPacket::create(PacketType::AvatarIdentity, individualData.size());
@@ -215,6 +216,8 @@ void AvatarMixer::manageDisplayName(const SharedNodePointer& node) {
         soFar.second++; // refcount
         nodeData->flagIdentityChange();
         nodeData->setAvatarSessionDisplayNameMustChange(false);
+
+        qCDebug(avatars) << __FUNCTION__ << "about to call sendIdentityPacket()";
         sendIdentityPacket(nodeData, node); // Tell node whose name changed about its new session display name.
         qCDebug(avatars) << "Giving session display name" << sessionDisplayName << "to node with ID" << node->getUUID();
     }
@@ -405,9 +408,14 @@ void AvatarMixer::handleAvatarIdentityPacket(QSharedPointer<ReceivedMessage> mes
 
             // parse the identity packet and update the change timestamp if appropriate
             AvatarData::Identity identity;
+
+            qCDebug(avatars) << __FUNCTION__ << "about to call parseAvatarIdentityPacket()";
             AvatarData::parseAvatarIdentityPacket(message->getMessage(), identity);
+
             bool identityChanged = false;
             bool displayNameChanged = false;
+
+            qCDebug(avatars) << __FUNCTION__ << "about to call processAvatarIdentity()";
             avatar.processAvatarIdentity(identity, identityChanged, displayNameChanged);
             if (identityChanged) {
                 QMutexLocker nodeDataLocker(&nodeData->getMutex());
diff --git a/assignment-client/src/avatars/AvatarMixerSlave.cpp b/assignment-client/src/avatars/AvatarMixerSlave.cpp
index 2ad8bb58ed..3266276a45 100644
--- a/assignment-client/src/avatars/AvatarMixerSlave.cpp
+++ b/assignment-client/src/avatars/AvatarMixerSlave.cpp
@@ -67,6 +67,7 @@ void AvatarMixerSlave::processIncomingPackets(const SharedNodePointer& node) {
 
 
 int AvatarMixerSlave::sendIdentityPacket(const AvatarMixerClientData* nodeData, const SharedNodePointer& destinationNode) {
+    qDebug() << __FUNCTION__ << "about to call nodeData->getConstAvatarData().identityByteArray()... for node:" << nodeData->getNodeID();
     QByteArray individualData = nodeData->getConstAvatarData()->identityByteArray();
     individualData.replace(0, NUM_BYTES_RFC4122_UUID, nodeData->getNodeID().toRfc4122()); // FIXME, this looks suspicious
     auto identityPackets = NLPacketList::create(PacketType::AvatarIdentity, QByteArray(), true, true);
@@ -302,6 +303,7 @@ void AvatarMixerSlave::broadcastAvatarData(const SharedNodePointer& node) {
             // If the time that the mixer sent AVATAR DATA about Avatar B to Avatar A is BEFORE OR EQUAL TO
             // the time that Avatar B flagged an IDENTITY DATA change, send IDENTITY DATA about Avatar B to Avatar A.
             if (nodeData->getLastBroadcastTime(otherNode->getUUID()) <= otherNodeData->getIdentityChangeTimestamp()) {
+                qCDebug(avatars) << __FUNCTION__ << "about to call sendIdentityPacket()";
                 identityBytesSent += sendIdentityPacket(otherNodeData, node);
             }
 
diff --git a/libraries/avatars/src/AvatarData.cpp b/libraries/avatars/src/AvatarData.cpp
index e75f801885..a9ca366d05 100644
--- a/libraries/avatars/src/AvatarData.cpp
+++ b/libraries/avatars/src/AvatarData.cpp
@@ -1529,15 +1529,13 @@ void AvatarData::processAvatarIdentity(const Identity& identity, bool& identityC
 }
 
 QByteArray AvatarData::identityByteArray() const {
-    qDebug() << __FUNCTION__;
-
     QByteArray identityData;
     QDataStream identityStream(&identityData, QIODevice::Append);
     const QUrl& urlToSend = cannonicalSkeletonModelURL(emptyURL); // depends on _skeletonModelURL
 
     _avatarEntitiesLock.withReadLock([&] {
 
-        qDebug() << __FUNCTION__
+        qDebug() << "AvatarData::identityByteArray() ... "
             << "session:" << getSessionUUID()
             << "url:" << urlToSend
             << "displayName:" << _displayName
@@ -1731,6 +1729,7 @@ void AvatarData::sendIdentityPacket() {
     qDebug() << __FUNCTION__;
     auto nodeList = DependencyManager::get<NodeList>();
 
+    qDebug() << __FUNCTION__ << "about to call identityByteArray()... for getSessionUUID:" << getSessionUUID();
     QByteArray identityData = identityByteArray();
 
     auto packetList = NLPacketList::create(PacketType::AvatarIdentity, QByteArray(), true, true);