[Logging] Add detailed zoning logging (#3555)

* WIP: Add zoning logging

* Update zoning.cpp

common/eqemu_logsys.h

@@ -138,6 +138,7 @@ namespace Logs {
 		QuestErrors,
 		PlayerEvents,
 		DataBuckets,
+		Zoning,
 		MaxCategoryID /* Don't Remove this */
 	};
 
@@ -235,6 +236,7 @@ namespace Logs {
 		"QuestErrors",
 		"PlayerEvents",
 		"DataBuckets",
+		"Zoning",
 	};
 }
 

common/eqemu_logsys_log_aliases.h

@@ -804,6 +804,16 @@
         OutF(LogSys, Logs::Detail, Logs::DataBuckets, __FILE__, __func__, __LINE__, message, ##__VA_ARGS__);\
 } while (0)
 
+#define LogZoning(message, ...) do {\
+    if (LogSys.IsLogEnabled(Logs::General, Logs::Zoning))\
+        OutF(LogSys, Logs::General, Logs::Zoning, __FILE__, __func__, __LINE__, message, ##__VA_ARGS__);\
+} while (0)
+
+#define LogZoningDetail(message, ...) do {\
+    if (LogSys.IsLogEnabled(Logs::Detail, Logs::Zoning))\
+        OutF(LogSys, Logs::Detail, Logs::Zoning, __FILE__, __func__, __LINE__, message, ##__VA_ARGS__);\
+} while (0)
+
 #define Log(debug_level, log_category, message, ...) do {\
     if (LogSys.IsLogEnabled(debug_level, log_category))\
         LogSys.Out(debug_level, log_category, __FILE__, __func__, __LINE__, message, ##__VA_ARGS__);\

world/zoneserver.cpp

@@ -795,11 +795,29 @@ void ZoneServer::HandleMessage(uint16 opcode, const EQ::Net::Packet &p) {
 				client = client_list.FindCharacter(ztz->name);
 			}
 
-			LogInfo("ZoneToZone request for [{}] current zone [{}] req zone [{}]", ztz->name, ztz->current_zone_id, ztz->requested_zone_id);
+			LogZoning(
+				"ZoneToZone request for client [{}] guild_id [{}] requested_zone [{}] requested_zone_id [{}] requested_instance_id [{}] current_zone [{}] current_zone_id [{}] current_instance_id [{}] response [{}] admin [{}] ignorerestrictions [{}]",
+				ztz->name,
+				ztz->guild_id,
+				ZoneName(ztz->requested_zone_id),
+				ztz->requested_zone_id,
+				ztz->requested_instance_id,
+				ZoneName(ztz->current_zone_id),
+				ztz->current_zone_id,
+				ztz->current_instance_id,
+				ztz->response,
+				ztz->admin,
+				ztz->ignorerestrictions
+			);
 
 			/* This is a request from the egress zone */
 			if (GetZoneID() == ztz->current_zone_id && GetInstanceID() == ztz->current_instance_id) {
-				LogInfo("Processing ZTZ for egress from zone for client [{}]", ztz->name);
+				LogZoning(
+					"ZoneToZone request for client [{}] for egress from zone [{}]",
+					ztz->name,
+					ZoneName(ztz->current_zone_id),
+					ztz->current_zone_id
+				);
 
 				if (
 					ztz->admin < AccountStatus::QuestTroupe &&
@@ -807,6 +825,14 @@ void ZoneServer::HandleMessage(uint16 opcode, const EQ::Net::Packet &p) {
 					zoneserver_list.IsZoneLocked(ztz->requested_zone_id)
 				) {
 					ztz->response = 0;
+
+					LogZoning(
+						"ZoneToZone request for client [{}] for egress from zone [{}] denied, zone is locked",
+						ztz->name,
+						ZoneName(ztz->current_zone_id),
+						ztz->current_zone_id
+					);
+
 					SendPacket(pack);
 					break;
 				}
@@ -818,12 +844,25 @@ void ZoneServer::HandleMessage(uint16 opcode, const EQ::Net::Packet &p) {
 				);
 
 				if (ingress_server) {
-					LogInfo("Found a zone already booted for [{}]", ztz->name);
+					LogZoning(
+						"Found a zone already booted for ZoneToZone for client [{}] for ingress_server from zone [{}] found booted zone",
+						ztz->name,
+						ZoneName(ztz->current_zone_id),
+						ztz->current_zone_id
+					);
+
 					ztz->response = 1;
 				} else {
 					int server_id;
 					if ((server_id = zoneserver_list.TriggerBootup(ztz->requested_zone_id, ztz->requested_instance_id))) {
-						LogInfo("Successfully booted a zone for [{}]", ztz->name);
+						LogZoning(
+							"ZoneToZone successfully booted a zone for character [{}] zone [{}] ({}) instance [{}] ({})",
+							ztz->name,
+							ZoneName(ztz->requested_zone_id),
+							ztz->requested_zone_id,
+							ztz->requested_instance_id,
+							server_id
+						);
 						ztz->response = 1;
 						ingress_server = zoneserver_list.FindByID(server_id);
 					} else {
@@ -841,8 +880,8 @@ void ZoneServer::HandleMessage(uint16 opcode, const EQ::Net::Packet &p) {
 					ingress_server->SendPacket(pack);	// inform target server
 				}
 			} else {
-				LogInfo(
+				LogZoning(
-					"Processing ZTZ for ingress to zone for client [{}] instance_id [{}] zone_id [{}]",
+					"Processing ZTZ for egress to zone for client [{}] instance_id [{}] zone_id [{}]",
 					ztz->name,
 					ztz->current_instance_id,
 					ztz->current_zone_id
@@ -854,7 +893,13 @@ void ZoneServer::HandleMessage(uint16 opcode, const EQ::Net::Packet &p) {
 				);
 
 				if (egress_server) {
-					LogInfo("Found egress server, forwarding client");
+					LogZoning(
+						"Found egress server_id [{}] zone_id [{}] zone_name [{}] instance_id [{}], forwarding client",
+						egress_server->GetID(),
+						egress_server->GetZoneID(),
+						egress_server->GetZoneName(),
+						egress_server->GetInstanceID()
+					);
 					egress_server->SendPacket(pack);
 				}
 			}

zone/client.cpp

@@ -11768,3 +11768,29 @@ void Client::ShowSpells(Client* c, ShowSpellType show_spell_type)
 		spell_table.c_str()
 	);
 }
+
+std::string GetZoneModeString(ZoneMode mode)
+{
+	switch (mode) {
+		case ZoneToSafeCoords:
+			return "ZoneToSafeCoords";
+		case GMSummon:
+			return "GMSummon";
+		case ZoneToBindPoint:
+			return "ZoneToBindPoint";
+		case ZoneSolicited:
+			return "ZoneSolicited";
+		case ZoneUnsolicited:
+			return "ZoneUnsolicited";
+		case GateToBindPoint:
+			return "GateToBindPoint";
+		case SummonPC:
+			return "SummonPC";
+		case Rewind:
+			return "Rewind";
+		case EvacToSafeCoords:
+			return "EvacToSafeCoords";
+		default:
+			return "Unknown";
+	}
+}

zone/client.h

@@ -123,6 +123,9 @@ typedef enum {
 	EvacToSafeCoords
 } ZoneMode;
 
+// translate above enum to a string
+std::string GetZoneModeString(ZoneMode mode);
+
 enum {
 	HideCorpseNone = 0,
 	HideCorpseAll = 1,

zone/worldserver.cpp

@@ -355,8 +355,24 @@ void WorldServer::HandleMessage(uint16 opcode, const EQ::Net::Packet &p)
 			break;
 		ZoneToZone_Struct* ztz = (ZoneToZone_Struct*)pack->pBuffer;
 
-		if (ztz->current_zone_id == zone->GetZoneID()
+		LogZoning(
-			&& ztz->current_instance_id == zone->GetInstanceID()) {
+			"ZoneToZone client [{}] guild_id [{}] requested_zone [{}] requested_zone_id [{}] requested_instance_id [{}] current_zone [{}] current_zone_id [{}] current_instance_id [{}] response [{}] admin [{}] ignorerestrictions [{}]",
+			ztz->name,
+			ztz->guild_id,
+			ZoneName(ztz->requested_zone_id),
+			ztz->requested_zone_id,
+			ztz->requested_instance_id,
+			ZoneName(ztz->current_zone_id),
+			ztz->current_zone_id,
+			ztz->current_instance_id,
+			ztz->response,
+			ztz->admin,
+			ztz->ignorerestrictions
+		);
+
+		// the client was rejected by the world server
+		// zone was not ready for some reason
+		if (ztz->current_zone_id == zone->GetZoneID() && ztz->current_instance_id == zone->GetInstanceID()) {
 			// it's a response
 			Entity* entity = entity_list.GetClientByName(ztz->name);
 			if (entity == 0)
@@ -371,6 +387,20 @@ void WorldServer::HandleMessage(uint16 opcode, const EQ::Net::Packet &p)
 				entity->CastToMob()->SetZone(ztz->current_zone_id, ztz->current_instance_id);
 				entity->CastToClient()->SetZoning(false);
 				entity->CastToClient()->SetLockSavePosition(false);
+
+				LogZoning("ZoneToZone (ZoneNotReady) client [{}] guild_id [{}] requested_zone [{}] requested_zone_id [{}] requested_instance_id [{}] current_zone [{}] current_zone_id [{}] current_instance_id [{}] response [{}] admin [{}] ignorerestrictions [{}] ",
+					ztz->name,
+					ztz->guild_id,
+					ZoneName(ztz->requested_zone_id),
+					ztz->requested_zone_id,
+					ztz->requested_instance_id,
+					ZoneName(ztz->current_zone_id),
+					ztz->current_zone_id,
+					ztz->current_instance_id,
+					ztz->response,
+					ztz->admin,
+					ztz->ignorerestrictions
+				);
 			}
 			else {
 				entity->CastToClient()->UpdateWho(1);
@@ -411,6 +441,7 @@ void WorldServer::HandleMessage(uint16 opcode, const EQ::Net::Packet &p)
 			}
 			}
 		}
+		// the client was accepted by the world server
 		else {
 			// it's a request
 			ztz->response = 0;

zone/zonedb.cpp

@@ -4632,8 +4632,6 @@ void ZoneDatabase::SaveCharacterBinds(Client *c)
 		}
 	}
 
-	LogInfo("bind count is [{}]", bind_count);
-
 	// allocate memory for binds
 	binds.reserve(bind_count);
 

zone/zoning.cpp

@@ -55,6 +55,22 @@ void Client::Handle_OP_ZoneChange(const EQApplicationPacket *app) {
 #endif
 	auto* zc = (ZoneChange_Struct*)app->pBuffer;
 
+	LogZoning(
+		"Client [{}] zoning to [{}] ({}) instance_id [{}] x [{}] y [{}] z [{}] zone_reason [{}] success [{}] zone_mode [{}] ({})",
+		GetCleanName(),
+		zc->char_name,
+		ZoneName(zc->zoneID),
+		zc->zoneID,
+		zc->instanceID,
+		zc->x,
+		zc->y,
+		zc->z,
+		zc->zone_reason,
+		zc->success,
+		GetZoneModeString(zone_mode),
+		zone_mode
+	);
+
 	uint16 target_zone_id = 0;
 	auto target_instance_id = zc->instanceID;
 	ZonePoint* zone_point = nullptr;
@@ -132,6 +148,14 @@ void Client::Handle_OP_ZoneChange(const EQApplicationPacket *app) {
 	}
 
 	if (target_instance_id) {
+		LogZoning(
+			"Client [{}] attempting zone to instance_id [{}] zone [{}] ({})",
+			GetCleanName(),
+			target_instance_id,
+			ZoneName(target_zone_id),
+			target_zone_id
+		);
+
 		//make sure we are in it and it's unexpired.
 		if (!database.VerifyInstanceAlive(target_instance_id, CharacterID())) {
 			Message(
@@ -185,7 +209,7 @@ void Client::Handle_OP_ZoneChange(const EQApplicationPacket *app) {
 	int16 min_status = AccountStatus::Player;
 	uint8 min_level  = 0;
 
-	LogInfo("Loaded zone flag [{}]", zone_data->flag_needed);
+	LogZoning("Loaded zone flag [{}]", zone_data->flag_needed);
 
 	safe_x       = zone_data->safe_x;
 	safe_y       = zone_data->safe_y;
@@ -328,7 +352,7 @@ void Client::Handle_OP_ZoneChange(const EQApplicationPacket *app) {
 			meets_zone_expansion_check = true;
 		}
 
-		LogInfo(
+		LogZoning(
 			"Checking zone request [{}] for expansion [{}] ({}) success [{}]",
 			target_zone_name,
 			(content_service.GetCurrentExpansion()),
@@ -360,12 +384,41 @@ void Client::SendZoneCancel(ZoneChange_Struct *zc) {
 	EQApplicationPacket *outapp = nullptr;
 	outapp = new EQApplicationPacket(OP_ZoneChange, sizeof(ZoneChange_Struct));
 	ZoneChange_Struct *zc2 = (ZoneChange_Struct*)outapp->pBuffer;
+
+	LogZoning(
+		"(zs) Client [{}] char_name [{}] zoning to [{}] ({}) cancelled instance_id [{}] x [{}] y [{}] z [{}] zone_reason [{}] success [{}]",
+		GetCleanName(),
+		zc->char_name,
+		ZoneName(zc2->zoneID),
+		zc->zoneID,
+		zc->instanceID,
+		zc->x,
+		zc->y,
+		zc->z,
+		zc->zone_reason,
+		zc->success
+	);
+
 	strcpy(zc2->char_name, zc->char_name);
 	zc2->zoneID = zone->GetZoneID();
 	zc2->success = 1;
 	outapp->priority = 6;
 	FastQueuePacket(&outapp);
 
+	LogZoning(
+		"(zc2) Client [{}] char_name [{}] zoning to [{}] ({}) cancelled instance_id [{}] x [{}] y [{}] z [{}] zone_reason [{}] success [{}]",
+		GetCleanName(),
+		zc2->char_name,
+		ZoneName(zc2->zoneID),
+		zc2->zoneID,
+		zc2->instanceID,
+		zc2->x,
+		zc2->y,
+		zc2->z,
+		zc2->zone_reason,
+		zc2->success
+	);
+
 	//reset to unsolicited.
 	zone_mode = ZoneUnsolicited;
 	// reset since we're not zoning anymore
@@ -387,6 +440,20 @@ void Client::SendZoneError(ZoneChange_Struct *zc, int8 err)
 	outapp->priority = 6;
 	FastQueuePacket(&outapp);
 
+	LogZoning(
+		"Client [{}] char_name [{}] zoning to [{}] ({}) (error) instance_id [{}] x [{}] y [{}] z [{}] zone_reason [{}] success [{}]",
+		GetCleanName(),
+		zc2->char_name,
+		ZoneName(zc2->zoneID),
+		zc2->zoneID,
+		zc2->instanceID,
+		zc2->x,
+		zc2->y,
+		zc2->z,
+		zc2->zone_reason,
+		zc2->success
+	);
+
 	//reset to unsolicited.
 	zone_mode = ZoneUnsolicited;
 	// reset since we're not zoning anymore
@@ -423,15 +490,18 @@ void Client::DoZoneSuccess(ZoneChange_Struct *zc, uint16 zone_id, uint32 instanc
 		}
 	}
 
-	LogInfo(
+	LogZoning(
-		"Zoning [{}] to: [{}] ([{}]) - ([{}]) x [{}] y [{}] z [{}]",
+		"Client [{}] char_name [{}] zoning to [{}] ({}) instance_id [{}] x [{}] y [{}] z [{}] zone_reason [{}] success [{}]",
-		m_pp.name,
+		GetCleanName(),
+		zc->char_name,
 		ZoneName(zone_id),
 		zone_id,
 		instance_id,
 		dest_x,
 		dest_y,
-		dest_z
+		dest_z,
+		zc->zone_reason,
+		zc->success
 	);
 
 	//set the player's coordinates in the new zone so they have them