From 9cbfd5c8f0f32814642ade0b27a89d063712258d Mon Sep 17 00:00:00 2001 From: Chris Miles Date: Sat, 19 Aug 2023 23:53:34 -0500 Subject: [PATCH] [Logging] Add detailed zoning logging (#3555) * WIP: Add zoning logging * Update zoning.cpp --- common/eqemu_logsys.h | 2 + common/eqemu_logsys_log_aliases.h | 10 ++++ world/zoneserver.cpp | 59 +++++++++++++++++++--- zone/client.cpp | 26 ++++++++++ zone/client.h | 3 ++ zone/worldserver.cpp | 35 ++++++++++++- zone/zonedb.cpp | 2 - zone/zoning.cpp | 82 ++++++++++++++++++++++++++++--- 8 files changed, 202 insertions(+), 17 deletions(-) diff --git a/common/eqemu_logsys.h b/common/eqemu_logsys.h index 70e0c430b..cbbbd1e6f 100644 --- a/common/eqemu_logsys.h +++ b/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", }; } diff --git a/common/eqemu_logsys_log_aliases.h b/common/eqemu_logsys_log_aliases.h index faaa59bcc..07b031c9c 100644 --- a/common/eqemu_logsys_log_aliases.h +++ b/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__);\ diff --git a/world/zoneserver.cpp b/world/zoneserver.cpp index 8ccc26cb4..f525ab2b9 100644 --- a/world/zoneserver.cpp +++ b/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( - "Processing ZTZ for ingress to zone for client [{}] instance_id [{}] zone_id [{}]", + LogZoning( + "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); } } diff --git a/zone/client.cpp b/zone/client.cpp index ab60952a3..bdd949d8c 100644 --- a/zone/client.cpp +++ b/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"; + } +} diff --git a/zone/client.h b/zone/client.h index 7672bcd86..ce4089514 100644 --- a/zone/client.h +++ b/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, diff --git a/zone/worldserver.cpp b/zone/worldserver.cpp index 6a3ee3289..cc8ecb34a 100644 --- a/zone/worldserver.cpp +++ b/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() - && ztz->current_instance_id == zone->GetInstanceID()) { + LogZoning( + "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; diff --git a/zone/zonedb.cpp b/zone/zonedb.cpp index f02e085fa..951fe712d 100755 --- a/zone/zonedb.cpp +++ b/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); diff --git a/zone/zoning.cpp b/zone/zoning.cpp index 6c59d14ff..240a50855 100644 --- a/zone/zoning.cpp +++ b/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( - "Zoning [{}] to: [{}] ([{}]) - ([{}]) x [{}] y [{}] z [{}]", - m_pp.name, + LogZoning( + "Client [{}] char_name [{}] zoning to [{}] ({}) instance_id [{}] x [{}] y [{}] z [{}] zone_reason [{}] success [{}]", + 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