SL-14081 - more teleport logging

4 files changed, 97 insertions, 50 deletions

diff --git a/indra/newview/llagent.cpp b/indra/newview/llagent.cpp
index 04b89399b0..4bc7663300 100644
--- a/indra/newview/llagent.cpp
+++ b/indra/newview/llagent.cpp
@@ -157,32 +157,6 @@ std::map<S32, std::string> LLTeleportRequest::sTeleportStatusName = { { kPending
 																	  { kFailed, "kFailed" },
 																	  { kRestartPending, "kRestartPending"} };
 
-// TODO this enum -> name idiom should be in a common class rather than repeated various places.
-const std::string& LLTeleportRequest::statusName(EStatus status)
-{
-	static std::string invalid_status_str("INVALID");
-	auto iter = LLTeleportRequest::sTeleportStatusName.find(status);
-	if (iter != LLTeleportRequest::sTeleportStatusName.end())
-	{
-		return iter->second;
-	}
-	else
-	{
-		return invalid_status_str;
-	}
-}
-
-std::ostream& operator<<(std::ostream& os, const LLTeleportRequest& req)
-{
-	req.toOstream(os);
-	return os;
-}
-
-void LLTeleportRequest::toOstream(std::ostream& os) const
-{
-	os << "status " << statusName(mStatus) << "(" << mStatus << ")";
-}
-
 class LLTeleportRequestViaLandmark : public LLTeleportRequest
 {
 public:
@@ -910,7 +884,12 @@ void LLAgent::setRegion(LLViewerRegion *regionp)
 	if (mRegionp != regionp)
 	{
 
-		LL_INFOS("AgentLocation") << "Moving agent into region: " << regionp->getName() << LL_ENDL;
+		LL_INFOS("AgentLocation","Teleport") << "Moving agent into region: handle " << regionp->getHandle() 
+											 << " id " << regionp->getRegionID()
+											 << " name " << regionp->getName()
+											 << " previous region "
+											 << (mRegionp ? mRegionp->getRegionID() : LLUUID::null)
+											 << LL_ENDL;
 		if (mRegionp)
 		{
 			// We've changed regions, we're now going to change our agent coordinate frame.
@@ -4003,10 +3982,19 @@ void LLAgent::handleTeleportFinished()
     {
         if (mRegionp->capabilitiesReceived())
         {
+			LL_DEBUGS("Teleport") << "capabilities have been received for region handle "
+								  << mRegionp->getHandle()
+								  << " id " << mRegionp->getRegionID()
+								  << ", calling onCapabilitiesReceivedAfterTeleport()"
+								  << LL_ENDL;
             onCapabilitiesReceivedAfterTeleport();
         }
         else
         {
+			LL_DEBUGS("Teleport") << "Capabilities not yet received for region handle "
+								  << mRegionp->getHandle()
+								  << " id " << mRegionp->getRegionID()
+								  << LL_ENDL;
             mRegionp->setCapabilitiesReceivedCallback(boost::bind(&LLAgent::onCapabilitiesReceivedAfterTeleport));
         }
     }
@@ -4044,6 +4032,18 @@ void LLAgent::handleTeleportFailed()
 /*static*/
 void LLAgent::onCapabilitiesReceivedAfterTeleport()
 {
+	if (gAgent.getRegion())
+	{
+		LL_DEBUGS("Teleport") << "running after capabilities received callback has been triggered, agent region "
+							  << gAgent.getRegion()->getHandle()
+							  << " id " << gAgent.getRegion()->getRegionID()
+							  << " name " << gAgent.getRegion()->getName()
+							  << LL_ENDL;
+	}
+	else
+	{
+		LL_WARNS("Teleport") << "called when agent region is null!" << LL_ENDL;
+	}
 
     check_merchant_status();
 }
@@ -4772,6 +4772,32 @@ void LLTeleportRequest::restartTeleport()
 	llassert(0);
 }
 
+// TODO this enum -> name idiom should be in a common class rather than repeated various places.
+const std::string& LLTeleportRequest::statusName(EStatus status)
+{
+	static std::string invalid_status_str("INVALID");
+	auto iter = LLTeleportRequest::sTeleportStatusName.find(status);
+	if (iter != LLTeleportRequest::sTeleportStatusName.end())
+	{
+		return iter->second;
+	}
+	else
+	{
+		return invalid_status_str;
+	}
+}
+
+std::ostream& operator<<(std::ostream& os, const LLTeleportRequest& req)
+{
+	req.toOstream(os);
+	return os;
+}
+
+void LLTeleportRequest::toOstream(std::ostream& os) const
+{
+	os << "status " << statusName(mStatus) << "(" << mStatus << ")";
+}
+
 //-----------------------------------------------------------------------------
 // LLTeleportRequestViaLandmark
 //-----------------------------------------------------------------------------
diff --git a/indra/newview/llviewerdisplay.cpp b/indra/newview/llviewerdisplay.cpp
index 8a7a87445b..fd283fe21b 100644
--- a/indra/newview/llviewerdisplay.cpp
+++ b/indra/newview/llviewerdisplay.cpp
@@ -445,7 +445,7 @@ void display(BOOL rebuild, F32 zoom_factor, int subfield, BOOL for_snapshot)
 			gTeleportDisplayTimer.reset();
 			gViewerWindow->setShowProgress(TRUE);
 			gViewerWindow->setProgressPercent(llmin(teleport_percent, 0.0f));
-			LL_INFOS("Teleport") << "Teleport request of some kind has been sent, setting state to TELEPORT_REQUESTED" << LL_ENDL;
+			LL_INFOS("Teleport") << "A teleport request has been sent, setting state to TELEPORT_REQUESTED" << LL_ENDL;
 			gAgent.setTeleportState( LLAgent::TELEPORT_REQUESTED );
 			gAgent.setTeleportMessage(
 				LLAgent::sTeleportProgressMessages["requesting"]);
diff --git a/indra/newview/llviewermessage.cpp b/indra/newview/llviewermessage.cpp
index ac66e61d85..4f96838181 100644
--- a/indra/newview/llviewermessage.cpp
+++ b/indra/newview/llviewermessage.cpp
@@ -406,6 +406,7 @@ void give_money(const LLUUID& uuid, LLViewerRegion* region, S32 amount, BOOL is_
 
 void send_complete_agent_movement(const LLHost& sim_host)
 {
+	LL_DEBUGS("Teleport", "Messaging") << "Sending CompleteAgentMovement to sim_host " << sim_host << LL_ENDL;
 	LLMessageSystem* msg = gMessageSystem;
 	msg->newMessageFast(_PREHASH_CompleteAgentMovement);
 	msg->nextBlockFast(_PREHASH_AgentData);
@@ -2877,12 +2878,12 @@ BOOL LLPostTeleportNotifiers::tick()
 // We're going to pretend to be a new agent
 void process_teleport_finish(LLMessageSystem* msg, void**)
 {
-	LL_DEBUGS("Teleport","Messaging") << "Got teleport location message" << LL_ENDL;
+	LL_DEBUGS("Teleport","Messaging") << "Received TeleportFinish message" << LL_ENDL;
 	LLUUID agent_id;
 	msg->getUUIDFast(_PREHASH_Info, _PREHASH_AgentID, agent_id);
 	if (agent_id != gAgent.getID())
 	{
-		LL_WARNS("Messaging") << "Got teleport notification for wrong agent!" << LL_ENDL;
+		LL_WARNS("Teleport","Messaging") << "Got teleport notification for wrong agent " << agent_id << " expected " << gAgent.getID() << ", ignoring!" << LL_ENDL;
 		return;
 	}
 
@@ -2907,7 +2908,7 @@ void process_teleport_finish(LLMessageSystem* msg, void**)
     }
     else if (gAgent.getTeleportState() == LLAgent::TELEPORT_MOVING)
     {
-        LL_WARNS("Messaging") << "Teleport message in the middle of other teleport" << LL_ENDL;
+        LL_WARNS("Teleport","Messaging") << "Teleport message in the middle of other teleport" << LL_ENDL;
     }
 	
 	// Teleport is finished; it can't be cancelled now.
@@ -2935,11 +2936,18 @@ void process_teleport_finish(LLMessageSystem* msg, void**)
 	msg->getU64Fast(_PREHASH_Info, _PREHASH_RegionHandle, region_handle);
 	U32 teleport_flags;
 	msg->getU32Fast(_PREHASH_Info, _PREHASH_TeleportFlags, teleport_flags);
-	
-	
+
 	std::string seedCap;
 	msg->getStringFast(_PREHASH_Info, _PREHASH_SeedCapability, seedCap);
 
+	LL_DEBUGS("Teleport") << "TeleportFinish message params are:"
+						  << " sim_ip " << sim_ip
+						  << " sim_port " << sim_port
+						  << " region_handle " << region_handle
+						  << " teleport_flags " << teleport_flags
+						  << " seedCap " << seedCap
+						  << LL_ENDL;
+	
 	// update home location if we are teleporting out of prelude - specific to teleporting to welcome area 
 	if((teleport_flags & TELEPORT_FLAGS_SET_HOME_TO_TARGET)
 	   && (!gAgent.isGodlike()))
@@ -2981,7 +2989,7 @@ void process_teleport_finish(LLMessageSystem* msg, void**)
 	gAgent.standUp();
 
 	// now, use the circuit info to tell simulator about us!
-	LL_INFOS("Messaging") << "process_teleport_finish() Enabling "
+	LL_INFOS("Teleport","Messaging") << "process_teleport_finish() sending UseCircuitCode to enable sim_host "
 			<< sim_host << " with code " << msg->mOurCircuitCode << LL_ENDL;
 	msg->newMessageFast(_PREHASH_UseCircuitCode);
 	msg->nextBlockFast(_PREHASH_CircuitCode);
@@ -2995,7 +3003,7 @@ void process_teleport_finish(LLMessageSystem* msg, void**)
 	gAgent.setTeleportState( LLAgent::TELEPORT_MOVING );
 	gAgent.setTeleportMessage(LLAgent::sTeleportProgressMessages["contacting"]);
 
-	LL_DEBUGS("CrossingCaps") << "Calling setSeedCapability from process_teleport_finish(). Seed cap == "
+	LL_DEBUGS("CrossingCaps") << "Calling setSeedCapability(). Seed cap == "
 			<< seedCap << LL_ENDL;
 	regionp->setSeedCapability(seedCap);
 
@@ -3028,6 +3036,8 @@ void process_avatar_init_complete(LLMessageSystem* msg, void**)
 
 void process_agent_movement_complete(LLMessageSystem* msg, void**)
 {
+	LL_DEBUGS("Teleport","Messaging") << "Received ProcessAgentMovementComplete" << LL_ENDL;
+
 	gShiftFrame = true;
 	gAgentMovementCompleted = true;
 
@@ -3037,13 +3047,13 @@ void process_agent_movement_complete(LLMessageSystem* msg, void**)
 	msg->getUUIDFast(_PREHASH_AgentData, _PREHASH_SessionID, session_id);
 	if((gAgent.getID() != agent_id) || (gAgent.getSessionID() != session_id))
 	{
-		LL_WARNS("Messaging") << "Incorrect id in process_agent_movement_complete()"
-				<< LL_ENDL;
+		LL_WARNS("Teleport", "Messaging") << "Incorrect agent or session id in process_agent_movement_complete()"
+										  << " agent " << agent_id << " expected " << gAgent.getID() 
+										  << " session " << session_id << " expected " << gAgent.getSessionID()
+										  << ", ignoring" << LL_ENDL;
 		return;
 	}
 
-	LL_DEBUGS("Messaging") << "process_agent_movement_complete()" << LL_ENDL;
-
 	// *TODO: check timestamp to make sure the movement compleation
 	// makes sense.
 	LLVector3 agent_pos;
@@ -3060,7 +3070,7 @@ void process_agent_movement_complete(LLMessageSystem* msg, void**)
 	{
 		// Could happen if you were immediately god-teleported away on login,
 		// maybe other cases.  Continue, but warn.
-		LL_WARNS("Messaging") << "agent_movement_complete() with NULL avatarp." << LL_ENDL;
+		LL_WARNS("Teleport", "Messaging") << "agent_movement_complete() with NULL avatarp." << LL_ENDL;
 	}
 
 	F32 x, y;
@@ -3070,19 +3080,21 @@ void process_agent_movement_complete(LLMessageSystem* msg, void**)
 	{
 		if (gAgent.getRegion())
 		{
-			LL_WARNS("Messaging") << "current region " << gAgent.getRegion()->getOriginGlobal() << LL_ENDL;
+			LL_WARNS("Teleport", "Messaging") << "current region origin "
+											  << gAgent.getRegion()->getOriginGlobal() << " id " << gAgent.getRegion()->getRegionID() << LL_ENDL;
 		}
 
-		LL_WARNS("Messaging") << "Agent being sent to invalid home region: " 
-			<< x << ":" << y 
-			<< " current pos " << gAgent.getPositionGlobal()
-			<< LL_ENDL;
+		LL_WARNS("Teleport", "Messaging") << "Agent being sent to invalid home region: " 
+										  << x << ":" << y 
+										  << " current pos " << gAgent.getPositionGlobal()
+										  << ", calling forceDisconnect()"
+										  << LL_ENDL;
 		LLAppViewer::instance()->forceDisconnect(LLTrans::getString("SentToInvalidRegion"));
 		return;
 
 	}
 
-	LL_INFOS("Messaging") << "Changing home region to " << x << ":" << y << LL_ENDL;
+	LL_INFOS("Teleport","Messaging") << "Changing home region to region id " << regionp->getRegionID() << " handle " << region_handle << " == x,y " << x << "," << y << LL_ENDL;
 
 	// set our upstream host the new simulator and shuffle things as
 	// appropriate.
@@ -5960,6 +5972,8 @@ std::string formatted_time(const time_t& the_time)
 
 void process_teleport_failed(LLMessageSystem *msg, void**)
 {
+	LL_WARNS("Teleport","Messaging") << "Received TeleportFailed message" << LL_ENDL;
+
 	std::string message_id;		// Tag from server, like "RegionEntryAccessBlocked"
 	std::string big_reason;		// Actual message to display
 	LLSD args;
@@ -5978,6 +5992,7 @@ void process_teleport_failed(LLMessageSystem *msg, void**)
 			// Nothing found in the map - use what the server returned in the original message block
 			msg->getStringFast(_PREHASH_Info, _PREHASH_Reason, big_reason);
 		}
+		LL_WARNS("Teleport") << "AlertInfo message_id " << message_id << " reason: " << big_reason << LL_ENDL;
 
 		LLSD llsd_block;
 		std::string llsd_raw;
@@ -5987,10 +6002,11 @@ void process_teleport_failed(LLMessageSystem *msg, void**)
 			std::istringstream llsd_data(llsd_raw);
 			if (!LLSDSerialize::deserialize(llsd_block, llsd_data, llsd_raw.length()))
 			{
-				LL_WARNS() << "process_teleport_failed: Attempted to read alert parameter data into LLSD but failed:" << llsd_raw << LL_ENDL;
+				LL_WARNS("Teleport") << "process_teleport_failed: Attempted to read alert parameter data into LLSD but failed:" << llsd_raw << LL_ENDL;
 			}
 			else
 			{
+				LL_WARNS("Teleport") << "AlertInfo llsd block received: " << llsd_block << LL_ENDL;
 				if(llsd_block.has("REGION_NAME"))
 				{
 					std::string region_name = llsd_block["REGION_NAME"].asString();
@@ -6029,6 +6045,7 @@ void process_teleport_failed(LLMessageSystem *msg, void**)
 			args["REASON"] = message_id;
 		}
 	}
+	LL_WARNS("Teleport") << "Displaying CouldNotTeleportReason string, REASON= " << args["REASON"] << LL_ENDL;
 
 	LLNotificationsUtil::add("CouldNotTeleportReason", args);
 
@@ -6042,11 +6059,13 @@ void process_teleport_failed(LLMessageSystem *msg, void**)
 
 void process_teleport_local(LLMessageSystem *msg,void**)
 {
+	LL_INFOS("Teleport","Messaging") << "Received TeleportLocal message" << LL_ENDL;
+	
 	LLUUID agent_id;
 	msg->getUUIDFast(_PREHASH_Info, _PREHASH_AgentID, agent_id);
 	if (agent_id != gAgent.getID())
 	{
-		LL_WARNS("Messaging") << "Got teleport notification for wrong agent!" << LL_ENDL;
+		LL_WARNS("Teleport", "Messaging") << "Got teleport notification for wrong agent " << agent_id << " expected " << gAgent.getID() << ", ignoring!" << LL_ENDL;
 		return;
 	}
 
@@ -6058,6 +6077,7 @@ void process_teleport_local(LLMessageSystem *msg,void**)
 	msg->getVector3Fast(_PREHASH_Info, _PREHASH_LookAt, look_at);
 	msg->getU32Fast(_PREHASH_Info, _PREHASH_TeleportFlags, teleport_flags);
 
+	LL_INFOS("Teleport") << "Message params are location_id " << location_id << " teleport_flags " << teleport_flags << LL_ENDL;
 	if( gAgent.getTeleportState() != LLAgent::TELEPORT_NONE )
 	{
 		if( gAgent.getTeleportState() == LLAgent::TELEPORT_LOCAL )
diff --git a/indra/newview/llviewerregion.cpp b/indra/newview/llviewerregion.cpp
index a30c5156fa..5c99e693d2 100644
--- a/indra/newview/llviewerregion.cpp
+++ b/indra/newview/llviewerregion.cpp
@@ -291,6 +291,7 @@ void LLViewerRegionImpl::requestBaseCapabilitiesCoro(U64 regionHandle)
 
         LL_INFOS("AppInit", "Capabilities") << "Requesting seed from " << url 
                                             << " region name " << regionp->getName()
+                                            << " handle " << regionp->getHandle()
                                             << " (attempt #" << mSeedCapAttempts + 1 << ")" << LL_ENDL;
 		LL_DEBUGS("AppInit", "Capabilities") << "Capabilities requested: " << capabilityNames << LL_ENDL;
 
@@ -350,9 +351,9 @@ void LLViewerRegionImpl::requestBaseCapabilitiesCoro(U64 regionHandle)
         log_capabilities(mCapabilities);
 #endif
 
+        LL_DEBUGS("AppInit", "Capabilities", "Teleport") << "received caps for handle " << regionHandle 
+														 << " region name " << regionp->getName() << LL_ENDL;
         regionp->setCapabilitiesReceived(true);
-        LL_DEBUGS("AppInit", "Capabilities") << "received caps for handle " << regionHandle 
-                                             << " region name " << regionp->getName() << LL_ENDL;
 
         if (STATE_SEED_GRANTED_WAIT == LLStartUp::getStartupState())
         {