From c8218574cccae7c4a18ffb431052dd6f6688dfe9 Mon Sep 17 00:00:00 2001 From: Aeadoin <109764533+Aeadoin@users.noreply.github.com> Date: Sat, 10 Dec 2022 18:36:40 -0500 Subject: [PATCH] [Logging] More AI Logging Cleanup (#2616) * [Logging] Additional AI Cleanup * More cleanup/formatting fixes * Typo --- common/eqemu_logsys_log_aliases.h | 16 +++++ common/shareddb.cpp | 4 +- zone/attack.cpp | 12 ++-- zone/bot.cpp | 99 ++++++++++++++++--------------- zone/botspellsai.cpp | 14 ++--- zone/client_mods.cpp | 6 +- zone/client_packet.cpp | 26 ++++---- zone/client_process.cpp | 12 ++-- zone/groups.cpp | 2 +- zone/merc.cpp | 6 +- zone/mob.cpp | 4 +- zone/mob_ai.cpp | 34 ++++------- zone/raids.cpp | 2 +- zone/spell_effects.cpp | 28 ++++----- zone/waypoints.cpp | 6 +- zone/worldserver.cpp | 12 ++-- 16 files changed, 143 insertions(+), 140 deletions(-) diff --git a/common/eqemu_logsys_log_aliases.h b/common/eqemu_logsys_log_aliases.h index 9c3ab2f8e..339e7de95 100644 --- a/common/eqemu_logsys_log_aliases.h +++ b/common/eqemu_logsys_log_aliases.h @@ -83,6 +83,11 @@ OutF(LogSys, Logs::General, Logs::Combat, __FILE__, __func__, __LINE__, message, ##__VA_ARGS__);\ } while (0) +#define LogCombatModerate(message, ...) do {\ + if (LogSys.IsLogEnabled(Logs::Moderate, Logs::Combat))\ + OutF(LogSys, Logs::Moderate, Logs::Combat, __FILE__, __func__, __LINE__, message, ##__VA_ARGS__);\ +} while (0) + #define LogCombatDetail(message, ...) do {\ if (LogSys.IsLogEnabled(Logs::Detail, Logs::Combat))\ OutF(LogSys, Logs::Detail, Logs::Combat, __FILE__, __func__, __LINE__, message, ##__VA_ARGS__);\ @@ -263,6 +268,11 @@ OutF(LogSys, Logs::General, Logs::Spells, __FILE__, __func__, __LINE__, message, ##__VA_ARGS__);\ } while (0) +#define LogSpellsModerate(message, ...) do {\ + if (LogSys.IsLogEnabled(Logs::Moderate, Logs::Spells))\ + OutF(LogSys, Logs::Moderate, Logs::Spells, __FILE__, __func__, __LINE__, message, ##__VA_ARGS__);\ +} while (0) + #define LogSpellsDetail(message, ...) do {\ if (LogSys.IsLogEnabled(Logs::Detail, Logs::Spells))\ OutF(LogSys, Logs::Detail, Logs::Spells, __FILE__, __func__, __LINE__, message, ##__VA_ARGS__);\ @@ -926,6 +936,9 @@ #define LogCombat(message, ...) do {\ } while (0) +#define LogCombatModerate(message, ...) do {\ +} while (0) + #define LogCombatDetail(message, ...) do {\ } while (0) @@ -1028,6 +1041,9 @@ #define LogSpells(message, ...) do {\ } while (0) +#define LogSpellsModerate(message, ...) do {\ +} while (0) + #define LogSpellsDetail(message, ...) do {\ } while (0) diff --git a/common/shareddb.cpp b/common/shareddb.cpp index 49d3ccf33..13af52359 100644 --- a/common/shareddb.cpp +++ b/common/shareddb.cpp @@ -1890,7 +1890,7 @@ void SharedDatabase::LoadSpells(void *data, int max_spells) { } if(results.ColumnCount() <= SPELL_LOAD_FIELD_COUNT) { - LogSpells("Fatal error loading spells: Spell field count < SPELL_LOAD_FIELD_COUNT([{}])", SPELL_LOAD_FIELD_COUNT); + LogSpells("[SharedDatabase::LoadSpells] Fatal error loading spells: Spell field count < SPELL_LOAD_FIELD_COUNT([{}])", SPELL_LOAD_FIELD_COUNT); return; } @@ -1899,7 +1899,7 @@ void SharedDatabase::LoadSpells(void *data, int max_spells) { for (auto& row = results.begin(); row != results.end(); ++row) { const int tempid = atoi(row[0]); if(tempid >= max_spells) { - LogSpells("Non fatal error: spell.id >= max_spells, ignoring"); + LogSpells("[SharedDatabase::LoadSpells] Non fatal error: spell.id >= max_spells, ignoring"); continue; } diff --git a/zone/attack.cpp b/zone/attack.cpp index 6d2b40d67..2ed69ec0f 100644 --- a/zone/attack.cpp +++ b/zone/attack.cpp @@ -3322,14 +3322,14 @@ int64 Mob::ReduceDamage(int64 damage) int64 damage_to_reduce = damage * spellbonuses.MeleeThresholdGuard[SBIndex::THRESHOLDGUARD_MITIGATION_PERCENT] / 100; if (damage_to_reduce >= buffs[slot].melee_rune) { - LogSpells("Mob::ReduceDamage SE_MeleeThresholdGuard [{}] damage negated, [{}] damage remaining, fading buff", damage_to_reduce, buffs[slot].melee_rune); + LogSpellsDetail("[Mob::ReduceDamage] SE_MeleeThresholdGuard [{}] damage negated, [{}] damage remaining, fading buff", damage_to_reduce, buffs[slot].melee_rune); damage -= buffs[slot].melee_rune; if (!TryFadeEffect(slot)) BuffFadeBySlot(slot); } else { - LogSpells("Mob::ReduceDamage SE_MeleeThresholdGuard [{}] damage negated, [{}] damage remaining", damage_to_reduce, buffs[slot].melee_rune); + LogSpellsDetail("[Mob::ReduceDamage] SE_MeleeThresholdGuard [{}] damage negated, [{}] damage remaining", damage_to_reduce, buffs[slot].melee_rune); buffs[slot].melee_rune = (buffs[slot].melee_rune - damage_to_reduce); damage -= damage_to_reduce; } @@ -3347,14 +3347,14 @@ int64 Mob::ReduceDamage(int64 damage) if (spellbonuses.MitigateMeleeRune[SBIndex::MITIGATION_RUNE_MAX_HP_AMT] && (damage_to_reduce >= buffs[slot].melee_rune)) { - LogSpells("Mob::ReduceDamage SE_MitigateMeleeDamage [{}] damage negated, [{}] damage remaining, fading buff", damage_to_reduce, buffs[slot].melee_rune); + LogSpellsDetail("[Mob::ReduceDamage] SE_MitigateMeleeDamage [{}] damage negated, [{}] damage remaining, fading buff", damage_to_reduce, buffs[slot].melee_rune); damage -= buffs[slot].melee_rune; if (!TryFadeEffect(slot)) BuffFadeBySlot(slot); } else { - LogSpells("Mob::ReduceDamage SE_MitigateMeleeDamage [{}] damage negated, [{}] damage remaining", damage_to_reduce, buffs[slot].melee_rune); + LogSpellsDetail("[Mob::ReduceDamage] SE_MitigateMeleeDamage [{}] damage negated, [{}] damage remaining", damage_to_reduce, buffs[slot].melee_rune); if (spellbonuses.MitigateMeleeRune[SBIndex::MITIGATION_RUNE_MAX_HP_AMT]) buffs[slot].melee_rune = (buffs[slot].melee_rune - damage_to_reduce); @@ -3473,14 +3473,14 @@ int64 Mob::AffectMagicalDamage(int64 damage, uint16 spell_id, const bool iBuffTi if (spellbonuses.MitigateSpellRune[SBIndex::MITIGATION_RUNE_MAX_HP_AMT] && (damage_to_reduce >= buffs[slot].magic_rune)) { - LogSpells("Mob::ReduceDamage SE_MitigateSpellDamage [{}] damage negated, [{}] damage remaining, fading buff", damage_to_reduce, buffs[slot].magic_rune); + LogSpellsDetail("[Mob::AffectMagicalDamage] SE_MitigateSpellDamage [{}] damage negated, [{}] damage remaining, fading buff", damage_to_reduce, buffs[slot].magic_rune); damage -= buffs[slot].magic_rune; if (!TryFadeEffect(slot)) BuffFadeBySlot(slot); } else { - LogSpells("Mob::ReduceDamage SE_MitigateMeleeDamage [{}] damage negated, [{}] damage remaining", damage_to_reduce, buffs[slot].magic_rune); + LogSpellsDetail("[Mob::AffectMagicalDamage] SE_MitigateMeleeDamage [{}] damage negated, [{}] damage remaining", damage_to_reduce, buffs[slot].magic_rune); if (spellbonuses.MitigateSpellRune[SBIndex::MITIGATION_RUNE_MAX_HP_AMT]) buffs[slot].magic_rune = (buffs[slot].magic_rune - damage_to_reduce); diff --git a/zone/bot.cpp b/zone/bot.cpp index 34f45a499..fc446dc54 100644 --- a/zone/bot.cpp +++ b/zone/bot.cpp @@ -1610,9 +1610,8 @@ int32 Bot::acmod() { } else return (65 + ((agility - 300) / 21)); -#if EQDEBUG >= 11 - LogError("Error in Bot::acmod(): Agility: [{}], Level: [{}]",agility,level); -#endif + + LogError("[Bot::acmod] Agility [{}] Level [{}]",agility,level); return 0; } @@ -2136,7 +2135,7 @@ bool Bot::Process() if (mob_close_scan_timer.Check()) { LogAIScanCloseDetail( - "is_moving [{}] bot [{}] timer [{}]", + "[Bot::Process] is_moving [{}] bot [{}] timer [{}]", moving ? "true" : "false", GetCleanName(), mob_close_scan_timer.GetDuration() @@ -2294,7 +2293,7 @@ void Bot::BotRangedAttack(Mob* other) { //make sure the attack and ranged timers are up //if the ranged timer is disabled, then they have no ranged weapon and shouldent be attacking anyhow if((attack_timer.Enabled() && !attack_timer.Check(false)) || (ranged_timer.Enabled() && !ranged_timer.Check())) { - LogCombat("Bot Archery attack canceled. Timer not up. Attack [{}], ranged [{}]", attack_timer.GetRemainingTime(), ranged_timer.GetRemainingTime()); + LogCombatDetail("[Bot::BotRangedAttack] Bot Archery attack canceled. Timer not up. Attack [{}] ranged [{}]", attack_timer.GetRemainingTime(), ranged_timer.GetRemainingTime()); Message(0, "Error: Timer not up. Attack %d, ranged %d", attack_timer.GetRemainingTime(), ranged_timer.GetRemainingTime()); return; } @@ -2312,7 +2311,7 @@ void Bot::BotRangedAttack(Mob* other) { if(!RangeWeapon || !Ammo) return; - LogCombat("Shooting [{}] with bow [{}] ([{}]) and arrow [{}] ([{}])", other->GetCleanName(), RangeWeapon->Name, RangeWeapon->ID, Ammo->Name, Ammo->ID); + LogCombatDetail("[Bot::BotRangedAttack] Shooting [{}] with bow [{}] ([{}]) and arrow [{}] ([{}])", other->GetCleanName(), RangeWeapon->Name, RangeWeapon->ID, Ammo->Name, Ammo->ID); if(!IsAttackAllowed(other) || IsCasting() || DivineAura() || IsStunned() || IsMezzed() || (GetAppearance() == eaDead)) return; @@ -2322,21 +2321,21 @@ void Bot::BotRangedAttack(Mob* other) { //break invis when you attack if(invisible) { - LogCombat("Removing invisibility due to melee attack"); + LogCombatModerate("[Bot::BotRangedAttack] Removing invisibility due to melee attack"); BuffFadeByEffect(SE_Invisibility); BuffFadeByEffect(SE_Invisibility2); invisible = false; } if(invisible_undead) { - LogCombat("Removing invisibility vs. undead due to melee attack"); + LogCombatModerate("[Bot::BotRangedAttack] Removing invisibility vs. undead due to melee attack"); BuffFadeByEffect(SE_InvisVsUndead); BuffFadeByEffect(SE_InvisVsUndead2); invisible_undead = false; } if(invisible_animals) { - LogCombat("Removing invisibility vs. animals due to melee attack"); + LogCombatModerate("[Bot::BotRangedAttack] Removing invisibility vs. animals due to melee attack"); BuffFadeByEffect(SE_InvisVsAnimals); invisible_animals = false; } @@ -3496,7 +3495,7 @@ void Bot::AI_Process() if (GetTarget() && !IsRooted()) { - LogAI("Pursuing [{}] while engaged", GetTarget()->GetCleanName()); + LogAIDetail("[Bot::AI_Process] Pursuing [{}] while engaged", GetTarget()->GetCleanName()); Goal = GetTarget()->GetPosition(); if (DistanceSquared(m_Position, Goal) <= leash_distance) { RunTo(Goal.x, Goal.y, Goal.z); @@ -3882,7 +3881,7 @@ void Bot::PetAIProcess() { else if (botPet->GetTarget() && botPet->GetAIMovementTimer()->Check()) { botPet->SetRunAnimSpeed(0); if(!botPet->IsRooted()) { - LogAI("Pursuing [{}] while engaged", botPet->GetTarget()->GetCleanName()); + LogAIDetail("[Bot::AI_Process] Pursuing [{}] while engaged", botPet->GetTarget()->GetCleanName()); botPet->RunTo(botPet->GetTarget()->GetX(), botPet->GetTarget()->GetY(), botPet->GetTarget()->GetZ()); return; } else { @@ -4417,7 +4416,7 @@ void Bot::AddBotItem( if (!inst) { LogError( - "Bot:AddItem Invalid Item data: ID [{}] Charges [{}] Aug1 [{}] Aug2 [{}] Aug3 [{}] Aug4 [{}] Aug5 [{}] Aug6 [{}] Attuned [{}]", + "[Bot::AI_Process] Bot:AddItem Invalid Item data: ID [{}] Charges [{}] Aug1 [{}] Aug2 [{}] Aug3 [{}] Aug4 [{}] Aug5 [{}] Aug6 [{}] Attuned [{}]", item_id, charges, augment_one, @@ -4432,7 +4431,7 @@ void Bot::AddBotItem( } if (!database.botdb.SaveItemBySlot(this, slot_id, inst)) { - LogError("Failed to save item by slot to slot [{}] for [{}].", slot_id, GetCleanName()); + LogError("[Bot::AI_Process] Failed to save item by slot to slot [{}] for [{}].", slot_id, GetCleanName()); safe_delete(inst); return; } @@ -4683,7 +4682,7 @@ void Bot::PerformTradeWithClient(int16 begin_slot_id, int16 end_slot_id, Client* } if (!trade_instance->GetItem()) { - LogError("Bot::PerformTradeWithClient could not find item from instance in trade for {} with {} in slot {}.", client->GetCleanName(), GetCleanName(), trade_index); + LogError("[Bot::PerformTradeWithClient] could not find item from instance in trade for [{}] with [{}] in slot [{}].", client->GetCleanName(), GetCleanName(), trade_index); client->Message( Chat::White, fmt::format( @@ -4702,7 +4701,7 @@ void Bot::PerformTradeWithClient(int16 begin_slot_id, int16 end_slot_id, Client* auto item_link = linker.GenerateLink(); if (trade_index != invslot::slotCursor && !trade_instance->IsDroppable()) { - LogError("Bot::PerformTradeWithClient trade hack detected by {} with {}.", client->GetCleanName(), GetCleanName()); + LogError("[Bot::PerformTradeWithClient] trade hack detected by [{}] with [{}].", client->GetCleanName(), GetCleanName()); client->Message(Chat::White, "Trade hack detected, the trade has been cancelled."); client->ResetTrade(); return; @@ -4791,14 +4790,14 @@ void Bot::PerformTradeWithClient(int16 begin_slot_id, int16 end_slot_id, Client* } if (trade_instance->GetItem()->LoreGroup == -1 && check_iterator.trade_item_instance->GetItem()->ID == trade_instance->GetItem()->ID) { - LogError("Bot::PerformTradeWithClient trade hack detected by {} with {}.", client->GetCleanName(), GetCleanName()); + LogError("[Bot::PerformTradeWithClient] trade hack detected by [{}] with [{}].", client->GetCleanName(), GetCleanName()); client->Message(Chat::White, "Trade hack detected, the trade has been cancelled."); client->ResetTrade(); return; } if ((trade_instance->GetItem()->LoreGroup > 0) && (check_iterator.trade_item_instance->GetItem()->LoreGroup == trade_instance->GetItem()->LoreGroup)) { - LogError("Bot::PerformTradeWithClient trade hack detected by {} with {}.", client->GetCleanName(), GetCleanName()); + LogError("[Bot::PerformTradeWithClient] trade hack detected by [{}] with [{}].", client->GetCleanName(), GetCleanName()); client->Message(Chat::White, "Trade hack detected, the trade has been cancelled."); client->ResetTrade(); return; @@ -4922,7 +4921,7 @@ void Bot::PerformTradeWithClient(int16 begin_slot_id, int16 end_slot_id, Client* } if (!return_instance->GetItem()) { - LogError("Bot::PerformTradeWithClient error processing bot slot {} for {} in trade with {}.", return_iterator.from_bot_slot, GetCleanName(), client->GetCleanName()); + LogError("[Bot::PerformTradeWithClient] error processing bot slot [{}] for [{}] in trade with [{}].", return_iterator.from_bot_slot, GetCleanName(), client->GetCleanName()); client->Message( Chat::White, fmt::format( @@ -5230,7 +5229,7 @@ void Bot::Damage(Mob *from, int64 damage, uint16 spell_id, EQ::skills::SkillType //handle EVENT_ATTACK. Resets after we have not been attacked for 12 seconds if(attacked_timer.Check()) { - LogCombat("Triggering EVENT_ATTACK due to attack by [{}]", from->GetName()); + LogCombat("[Bot::Damage] Triggering EVENT_ATTACK due to attack by [{}]", from->GetName()); parse->EventBot(EVENT_ATTACK, this, from, "", 0); } @@ -5238,7 +5237,7 @@ void Bot::Damage(Mob *from, int64 damage, uint16 spell_id, EQ::skills::SkillType // if spell is lifetap add hp to the caster if (spell_id != SPELL_UNKNOWN && IsLifetapSpell(spell_id)) { int64 healed = GetActSpellHealing(spell_id, damage); - LogCombat("Applying lifetap heal of [{}] to [{}]", healed, GetCleanName()); + LogCombatDetail("[Bot::Damage] Applying lifetap heal of [{}] to [{}]", healed, GetCleanName()); HealDamage(healed); entity_list.FilteredMessageClose(this, true, RuleI(Range, SpellMessages), Chat::Emote, FilterSocials, "%s beams a smile at %s", GetCleanName(), from->GetCleanName() ); } @@ -5274,13 +5273,13 @@ void Bot::AddToHateList(Mob* other, int64 hate, int64 damage, bool iYellForHelp, bool Bot::Attack(Mob* other, int Hand, bool FromRiposte, bool IsStrikethrough, bool IsFromSpell, ExtraAttackOptions *opts) { if (!other) { SetTarget(nullptr); - LogError("A null Mob object was passed to Bot::Attack for evaluation!"); + LogErrorDetail("[Bot::Attack] A null Mob object was passed to Bot::Attack for evaluation!"); return false; } if ((GetHP() <= 0) || (GetAppearance() == eaDead)) { SetTarget(nullptr); - LogCombat("Attempted to attack [{}] while unconscious or, otherwise, appearing dead", other->GetCleanName()); + LogCombatModerate("[Bot::Attack] Attempted to attack [{}] while unconscious or, otherwise, appearing dead", other->GetCleanName()); return false; } @@ -5292,20 +5291,20 @@ bool Bot::Attack(Mob* other, int Hand, bool FromRiposte, bool IsStrikethrough, b // takes more to compare a call result, load for a call, load a compare to address and compare, and finally // push a value to an address than to just load for a call and push a value to an address. - LogCombat("Attacking [{}] with hand [{}] [{}]", other->GetCleanName(), Hand, (FromRiposte ? "(this is a riposte)" : "")); + LogCombat("[Bot::Attack] Attacking [{}] with hand [{}] [{}]", other->GetCleanName(), Hand, (FromRiposte ? "(this is a riposte)" : "")); if ((IsCasting() && (GetClass() != BARD) && !IsFromSpell) || (!IsAttackAllowed(other))) { if(GetOwnerID()) entity_list.MessageClose(this, 1, 200, 10, "%s says, '%s is not a legal target master.'", GetCleanName(), GetTarget()->GetCleanName()); if(other) { RemoveFromHateList(other); - LogCombat("I am not allowed to attack [{}]", other->GetCleanName()); + LogCombat("[Bot::Attack] I am not allowed to attack [{}]", other->GetCleanName()); } return false; } if(DivineAura()) {//cant attack while invulnerable - LogCombat("Attack canceled, Divine Aura is in effect"); + LogCombat("[Bot::Attack] Attack canceled, Divine Aura is in effect"); return false; } @@ -5323,19 +5322,19 @@ bool Bot::Attack(Mob* other, int Hand, bool FromRiposte, bool IsStrikethrough, b if(weapon != nullptr) { if (!weapon->IsWeapon()) { - LogCombat("Attack canceled, Item [{}] ([{}]) is not a weapon", weapon->GetItem()->Name, weapon->GetID()); + LogCombat("[Bot::Attack] Attack canceled, Item [{}] ([{}]) is not a weapon", weapon->GetItem()->Name, weapon->GetID()); return false; } - LogCombat("Attacking with weapon: [{}] ([{}])", weapon->GetItem()->Name, weapon->GetID()); + LogCombat("[Bot::Attack] Attacking with weapon: [{}] ([{}])", weapon->GetItem()->Name, weapon->GetID()); } else - LogCombat("Attacking without a weapon"); + LogCombat("[Bot::Attack] Attacking without a weapon"); // calculate attack_skill and skillinuse depending on hand and weapon // also send Packet to near clients DamageHitInfo my_hit; my_hit.skill = AttackAnimation(Hand, weapon); - LogCombat("Attacking with [{}] in slot [{}] using skill [{}]", weapon?weapon->GetItem()->Name:"Fist", Hand, my_hit.skill); + LogCombat("[Bot::Attack] Attacking with [{}] in slot [{}] using skill [{}]", weapon?weapon->GetItem()->Name:"Fist", Hand, my_hit.skill); // Now figure out damage my_hit.damage_done = 1; @@ -5383,7 +5382,7 @@ bool Bot::Attack(Mob* other, int Hand, bool FromRiposte, bool IsStrikethrough, b } } - LogCombat("Damage calculated: base [{}] min damage [{}] skill [{}]", my_hit.base_damage, my_hit.min_damage, my_hit.skill); + LogCombat("[Bot::Attack] Damage calculated: base [{}] min damage [{}] skill [{}]", my_hit.base_damage, my_hit.min_damage, my_hit.skill); int hit_chance_bonus = 0; my_hit.offense = offense(my_hit.skill); @@ -5401,7 +5400,7 @@ bool Bot::Attack(Mob* other, int Hand, bool FromRiposte, bool IsStrikethrough, b DoAttack(other, my_hit, opts, FromRiposte); - LogCombat("Final damage after all reductions: [{}]", my_hit.damage_done); + LogCombat("[Bot::Attack] Final damage after all reductions: [{}]", my_hit.damage_done); } else { my_hit.damage_done = DMG_INVULNERABLE; } @@ -6022,7 +6021,7 @@ int32 Bot::CalcBotFocusEffect(focusType bottype, uint16 focus_id, uint16 spell_i return 0; break; default: - LogInfo("CalcFocusEffect: unknown limit spelltype [{}]", focus_spell.base_value[i]); + LogInfo("[Bot::CalcBotFocusEffect] CalcFocusEffect: unknown limit spelltype [{}]", focus_spell.base_value[i]); } break; @@ -6255,7 +6254,7 @@ int32 Bot::CalcBotFocusEffect(focusType bottype, uint16 focus_id, uint16 spell_i break; } default: - LogSpells("CalcFocusEffect: unknown effectid [{}]", focus_spell.effect_id[i]); + LogSpellsModerate("[Bot::CalcBotFocusEffect] unknown effectid [{}]", focus_spell.effect_id[i]); break; } } @@ -6295,7 +6294,7 @@ float Bot::GetProcChances(float ProcBonus, uint16 hand) { ProcChance += (ProcChance * ProcBonus / 100.0f); } - LogCombat("Proc chance [{}] ([{}] from bonuses)", ProcChance, ProcBonus); + LogCombat("[Bot::GetProcChances] Proc chance [{}] ([{}] from bonuses)", ProcChance, ProcBonus); return ProcChance; } @@ -6349,13 +6348,13 @@ bool Bot::TryFinishingBlow(Mob *defender, int64 &damage) int fb_damage = aabonuses.FinishingBlow[1]; int levelreq = aabonuses.FinishingBlowLvl[0]; if (defender->GetLevel() <= levelreq && (chance >= zone->random.Int(1, 1000))) { - LogCombat("Landed a finishing blow: levelreq at [{}], other level [{}]", + LogCombat("[Bot::TryFinishingBlow] Landed a finishing blow: levelreq at [{}] other level [{}]", levelreq, defender->GetLevel()); entity_list.MessageCloseString(this, false, 200, Chat::MeleeCrit, FINISHING_BLOW, GetName()); damage = fb_damage; return true; } else { - LogCombat("failed a finishing blow: levelreq at [{}], other level [{}]", + LogCombat("[Bot::TryFinishingBlow] failed a finishing blow: levelreq at [{}] other level [{}]", levelreq, defender->GetLevel()); return false; } @@ -6364,14 +6363,14 @@ bool Bot::TryFinishingBlow(Mob *defender, int64 &damage) } void Bot::DoRiposte(Mob* defender) { - LogCombat("Preforming a riposte"); + LogCombatDetail("[Bot::DoRiposte] Preforming a riposte"); if (!defender) return; defender->Attack(this, EQ::invslot::slotPrimary, true); int32 DoubleRipChance = (defender->GetAABonuses().GiveDoubleRiposte[0] + defender->GetSpellBonuses().GiveDoubleRiposte[0] + defender->GetItemBonuses().GiveDoubleRiposte[0]); if(DoubleRipChance && (DoubleRipChance >= zone->random.Int(0, 100))) { - LogCombat("Preforming a double riposte ([{}] percent chance)", DoubleRipChance); + LogCombatDetail("[Bot::DoRiposte] Preforming a double riposte ([{}] percent chance)", DoubleRipChance); defender->Attack(this, EQ::invslot::slotPrimary, true); } @@ -7118,7 +7117,7 @@ int64 Bot::CalcMaxMana() { break; } default: { - LogDebug("Invalid Class [{}] in CalcMaxMana", GetCasterClass()); + LogDebug("[Bot::CalcMaxMana] Invalid Class [{}] in CalcMaxMana", GetCasterClass()); max_mana = 0; break; } @@ -7668,7 +7667,9 @@ bool Bot::CastSpell( (IsSilenced() && !IsDiscipline(spell_id)) || (IsAmnesiad() && IsDiscipline(spell_id)) ) { - LogSpells("Spell casting canceled: not able to cast now. Valid? [{}], casting [{}], waiting? [{}], spellend? [{}], stunned? [{}], feared? [{}], mezed? [{}], silenced? [{}]", IsValidSpell(spell_id), casting_spell_id, delaytimer, spellend_timer.Enabled(), IsStunned(), IsFeared(), IsMezzed(), IsSilenced() ); + LogSpellsModerate("[Bot::CastSpell] Spell casting canceled: not able to cast now. Valid? [{}] casting [{}] waiting? [{}] spellend? [{}] stunned? [{}] feared? [{}] mezed? [{}] silenced? [{}]", + IsValidSpell(spell_id), casting_spell_id, delaytimer, spellend_timer.Enabled(), IsStunned(), IsFeared(), IsMezzed(), IsSilenced() + ); if (IsSilenced() && !IsDiscipline(spell_id)) { MessageString(Chat::White, SILENCED_STRING); } @@ -7695,7 +7696,7 @@ bool Bot::CastSpell( } if (DivineAura()) { - LogSpells("Spell casting canceled: cannot cast while Divine Aura is in effect"); + LogSpellsDetail("[Bot::CastSpell] Spell casting canceled: cannot cast while Divine Aura is in effect"); InterruptSpell(173, 0x121, false); return false; } @@ -7705,13 +7706,13 @@ bool Bot::CastSpell( InterruptSpell(fizzle_msg, 0x121, spell_id); uint32 use_mana = ((spells[spell_id].mana) / 4); - LogSpells("Spell casting canceled: fizzled. [{}] mana has been consumed", use_mana); + LogSpellsModerate("[Bot::CastSpell] Spell casting canceled: fizzled. [{}] mana has been consumed", use_mana); SetMana(GetMana() - use_mana); return false; } if (HasActiveSong()) { - LogSpells("Casting a new spell/song while singing a song. Killing old song [{}]", bardsong); + LogSpellsDetail("[Bot::CastSpell] Casting a new spell/song while singing a song. Killing old song [{}]", bardsong); bardsong = 0; bardsong_target_id = 0; bardsong_slot = EQ::spells::CastingSlot::Gem1; @@ -7763,19 +7764,19 @@ bool Bot::IsImmuneToSpell(uint16 spell_id, Mob *caster) { if(caster->IsBot()) { if(spells[spell_id].target_type == ST_Undead) { if((GetBodyType() != BT_SummonedUndead) && (GetBodyType() != BT_Undead) && (GetBodyType() != BT_Vampire)) { - LogSpells("Bot's target is not an undead"); + LogSpellsModerate("[Bot::IsImmuneToSpell] Bot's target is not an undead"); return true; } } if(spells[spell_id].target_type == ST_Summoned) { if((GetBodyType() != BT_SummonedUndead) && (GetBodyType() != BT_Summoned) && (GetBodyType() != BT_Summoned2) && (GetBodyType() != BT_Summoned3)) { - LogSpells("Bot's target is not a summoned creature"); + LogSpellsModerate("[Bot::IsImmuneToSpell] Bot's target is not a summoned creature"); return true; } } } - LogSpells("No bot immunities to spell [{}] found", spell_id); + LogSpellsModerate("[Bot::IsImmuneToSpell] No bot immunities to spell [{}] found", spell_id); } } @@ -7926,7 +7927,7 @@ bool Bot::DoFinishedSpellSingleTarget(uint16 spell_id, Mob* spellTarget, EQ::spe if((spelltypeequal || spelltypetargetequal) || spelltypeclassequal || slotequal) { if(((spells[thespell].effect_id[0] == 0) && (spells[thespell].base_value[0] < 0)) && (spellTarget->GetHP() < ((spells[thespell].base_value[0] * (-1)) + 100))) { - LogSpells("Bot::DoFinishedSpellSingleTarget - GroupBuffing failure"); + LogSpells("[Bot::DoFinishedSpellSingleTarget] GroupBuffing failure"); return false; } @@ -9411,7 +9412,7 @@ bool Bot::CheckLoreConflict(const EQ::ItemData* item) { bool EntityList::Bot_AICheckCloseBeneficialSpells(Bot* caster, uint8 iChance, float iRange, uint32 iSpellTypes) { if((iSpellTypes & SPELL_TYPES_DETRIMENTAL) != 0) { - LogError("Error: detrimental spells requested from AICheckCloseBeneficialSpells!!"); + LogError("[EntityList::Bot_AICheckCloseBeneficialSpells] detrimental spells requested"); return false; } @@ -9845,7 +9846,7 @@ void EntityList::ScanCloseClientMobs(std::unordered_map& close_mob } } - LogAIScanCloseModerate("Close Client Mob List Size [{}] for mob [{}]", close_mobs.size(), scanning_mob->GetCleanName()); + LogAIScanCloseModerate("[EntityList::ScanCloseClientMobs] Close Client Mob List Size [{}] for mob [{}]", close_mobs.size(), scanning_mob->GetCleanName()); } uint8 Bot::GetNumberNeedingHealedInGroup(uint8 hpr, bool includePets) { diff --git a/zone/botspellsai.cpp b/zone/botspellsai.cpp index 90c0dae7d..a60b1d808 100644 --- a/zone/botspellsai.cpp +++ b/zone/botspellsai.cpp @@ -1165,7 +1165,7 @@ bool Bot::AIDoSpellCast(uint8 i, Mob* tar, int32 mana_cost, uint32* oDontDoAgain || dist2 <= GetActSpellRange(AIBot_spells[i].spellid, spells[AIBot_spells[i].spellid].range)*GetActSpellRange(AIBot_spells[i].spellid, spells[AIBot_spells[i].spellid].range)) && (mana_cost <= GetMana() || GetMana() == GetMaxMana())) { casting_spell_AIindex = i; - LogAIModerate("Bot::AIDoSpellCast: spellid = [{}], tar = [{}], mana = [{}], Name: [{}]", AIBot_spells[i].spellid, tar->GetName(), mana_cost, spells[AIBot_spells[i].spellid].name); + LogAI("[Bot::AIDoSpellCast] spellid [{}] tar [{}] mana [{}] Name [{}]", AIBot_spells[i].spellid, tar->GetName(), mana_cost, spells[AIBot_spells[i].spellid].name); result = Mob::CastSpell(AIBot_spells[i].spellid, tar->GetID(), EQ::spells::CastingSlot::Gem2, spells[AIBot_spells[i].spellid].cast_time, AIBot_spells[i].manacost == -2 ? 0 : mana_cost, oDontDoAgainBefore, -1, -1, 0, &(AIBot_spells[i].resist_adjust)); if (IsCasting() && IsSitting()) @@ -1232,9 +1232,7 @@ bool Bot::AI_IdleCastCheck() { bool result = false; if (AIautocastspell_timer->Check(false)) { -#if BotAI_DEBUG_Spells >= 25 LogAIDetail("Bot Non-Engaged autocast check triggered: [{}]", GetCleanName()); -#endif AIautocastspell_timer->Disable(); //prevent the timer from going off AGAIN while we are casting. bool pre_combat = false; @@ -1714,10 +1712,10 @@ bool Bot::AIHealRotation(Mob* tar, bool useFastHeals) { } } - LogAIModerate("Bot::AIHealRotation: heal spellid = [{}], fastheals = [{}], casterlevel = [{}]", + LogAIModerate("[Bot::AIHealRotation] heal spellid [{}] fastheals [{}] casterlevel [{}]", botSpell.SpellId, ((useFastHeals) ? ('T') : ('F')), GetLevel()); - LogAIDetail("Bot::AIHealRotation: target = [{}], current_time = [{}], donthealmebefore = [{}]", tar->GetCleanName(), Timer::GetCurrentTime(), tar->DontHealMeBefore()); + LogAIDetail("[Bot::AIHealRotation] target [{}] current_time [{}] donthealmebefore [{}]", tar->GetCleanName(), Timer::GetCurrentTime(), tar->DontHealMeBefore()); // If there is still no spell id, then there isn't going to be one so we are done if (botSpell.SpellId == 0) @@ -2910,7 +2908,7 @@ bool Bot::AI_AddBotSpells(uint32 bot_spell_id) { ) ); - LogAIModerate("[{}]", debug_msg); + LogAI("[{}]", debug_msg); for (const auto &iter : spell_list->entries) { LogAIDetail("([{}]) [{}]", iter.spellid, spells[iter.spellid].name); } @@ -2918,10 +2916,10 @@ bool Bot::AI_AddBotSpells(uint32 bot_spell_id) { else { debug_msg.append(" (not found)"); - LogAIModerate("[{}]", debug_msg); + LogAI("[{}]", debug_msg); } - LogAIModerate("fin (spell list)"); + LogAI("fin (spell list)"); uint16 attack_proc_spell = -1; int8 proc_chance = 3; diff --git a/zone/client_mods.cpp b/zone/client_mods.cpp index 2d18733c5..7779ae8f7 100644 --- a/zone/client_mods.cpp +++ b/zone/client_mods.cpp @@ -581,7 +581,7 @@ int64 Client::CalcMaxMana() break; } default: { - LogSpells("Invalid Class [{}] in CalcMaxMana", GetCasterClass()); + LogSpells("[Client::CalcMaxMana] Invalid Class [{}] in CalcMaxMana", GetCasterClass()); max_mana = 0; break; } @@ -599,7 +599,7 @@ int64 Client::CalcMaxMana() current_mana = curMana_cap; } } - LogSpells("Client::CalcMaxMana() called for [{}] - returning [{}]", GetName(), max_mana); + LogSpells("[Client::CalcMaxMana] for [{}] returning [{}]", GetName(), max_mana); return max_mana; } @@ -1663,7 +1663,7 @@ uint32 Mob::GetInstrumentMod(uint16 spell_id) } } - LogSpells("[{}]::GetInstrumentMod() spell=[{}] mod=[{}] modcap=[{}]\n", GetName(), spell_id, effectmod, effectmodcap); + LogSpells("[Mob::GetInstrumentMod] Name [{}] spell [{}] mod [{}] modcap [{}]\n", GetName(), spell_id, effectmod, effectmodcap); return effectmod; } diff --git a/zone/client_packet.cpp b/zone/client_packet.cpp index 256ad1e4c..484ad29e1 100644 --- a/zone/client_packet.cpp +++ b/zone/client_packet.cpp @@ -3896,14 +3896,14 @@ void Client::Handle_OP_Buff(const EQApplicationPacket *app) */ if (app->size != sizeof(SpellBuffPacket_Struct)) { - LogError("Size mismatch in OP_Buff. expected [{}] got [{}]", sizeof(SpellBuffPacket_Struct), app->size); + LogError("[Client::Handle_OP_Buff] Size mismatch in OP_Buff. expected [{}] got [{}]", sizeof(SpellBuffPacket_Struct), app->size); DumpPacket(app); return; } SpellBuffPacket_Struct* sbf = (SpellBuffPacket_Struct*)app->pBuffer; uint32 spid = sbf->buff.spellid; - LogSpells("Client requested that buff with spell id [{}] be canceled", spid); + LogSpells("[Client::Handle_OP_Buff] Client requested that buff with spell id [{}] be canceled", spid); //something about IsDetrimentalSpell() crashes this portion of code.. //tbh we shouldn't use it anyway since this is a simple red vs blue buff check and @@ -4067,7 +4067,7 @@ void Client::Handle_OP_CastSpell(const EQApplicationPacket *app) m_TargetRing = glm::vec3(castspell->x_pos, castspell->y_pos, castspell->z_pos); - LogSpells("OP CastSpell: slot [{}] spell [{}] target [{}] inv [{}]", castspell->slot, castspell->spell_id, castspell->target_id, (unsigned long)castspell->inventoryslot); + LogSpells("[Client::Handle_OP_CastSpell] OP CastSpell: slot [{}] spell [{}] target [{}] inv [{}]", castspell->slot, castspell->spell_id, castspell->target_id, (unsigned long)castspell->inventoryslot); CastingSlot slot = static_cast(castspell->slot); /* Memorized Spell */ @@ -4167,7 +4167,7 @@ void Client::Handle_OP_CastSpell(const EQApplicationPacket *app) /* Discipline -- older clients use the same slot as items, but we translate to it's own */ else if (slot == CastingSlot::Discipline) { if (!UseDiscipline(castspell->spell_id, castspell->target_id)) { - LogSpells("Unknown ability being used by [{}], spell being cast is: [{}]\n", GetName(), castspell->spell_id); + LogSpells("[Client::Handle_OP_CastSpell] Unknown ability being used by [{}] spell being cast is: [{}]\n", GetName(), castspell->spell_id); InterruptSpell(castspell->spell_id); return; } @@ -8801,7 +8801,7 @@ void Client::Handle_OP_ItemVerifyRequest(const EQApplicationPacket *app) using EQ::spells::CastingSlot; if (app->size != sizeof(ItemVerifyRequest_Struct)) { - LogError("OP size error: OP_ItemVerifyRequest expected:[{}] got:[{}]", sizeof(ItemVerifyRequest_Struct), app->size); + LogError("[Client::Handle_OP_ItemVerifyRequest] OP size error: OP_ItemVerifyRequest expected:[{}] got:[{}]", sizeof(ItemVerifyRequest_Struct), app->size); return; } @@ -8830,7 +8830,7 @@ void Client::Handle_OP_ItemVerifyRequest(const EQApplicationPacket *app) } if (slot_id < 0) { - LogDebug("Unknown slot being used by [{}], slot being used is: [{}]", GetName(), request->slot); + LogDebug("[Client::Handle_OP_ItemVerifyRequest] Unknown slot being used by [{}] slot being used is [{}]", GetName(), request->slot); return; } @@ -8891,7 +8891,7 @@ void Client::Handle_OP_ItemVerifyRequest(const EQApplicationPacket *app) if (spell_id > 0 && (spells[spell_id].target_type == ST_Pet || spells[spell_id].target_type == ST_SummonedPet)) target_id = GetPetID(); - LogDebug("OP ItemVerifyRequest: spell=[{}], target=[{}], inv=[{}]", spell_id, target_id, slot_id); + LogDebug("[Client::Handle_OP_ItemVerifyRequest] OP ItemVerifyRequest: spell=[{}] target=[{}] inv=[{}]", spell_id, target_id, slot_id); if (m_inv.SupportsClickCasting(slot_id) || ((item->ItemType == EQ::item::ItemTypePotion || item->PotionBelt) && m_inv.SupportsPotionBeltCasting(slot_id))) // sanity check { @@ -8929,7 +8929,7 @@ void Client::Handle_OP_ItemVerifyRequest(const EQApplicationPacket *app) if ((spell_id <= 0) && (item->ItemType != EQ::item::ItemTypeFood && item->ItemType != EQ::item::ItemTypeDrink && item->ItemType != EQ::item::ItemTypeAlcohol && item->ItemType != EQ::item::ItemTypeSpell)) { - LogDebug("Item with no effect right clicked by [{}]", GetName()); + LogDebug("[Client::Handle_OP_ItemVerifyRequest] Item with no effect right clicked by [{}]", GetName()); } else if (inst->IsClassCommon()) { @@ -8983,7 +8983,7 @@ void Client::Handle_OP_ItemVerifyRequest(const EQApplicationPacket *app) SendItemRecastTimer(item->RecastType); //Problem: When you loot corpse, recast display is not present. This causes it to display again. Could not get to display when sending from looting. MessageString(Chat::Red, SPELL_RECAST); SendSpellBarEnable(item->Click.Effect); - LogSpells("Casting of [{}] canceled: item spell reuse timer not expired", spell_id); + LogSpells("[Client::Handle_OP_ItemVerifyRequest] Casting of [{}] canceled: item spell reuse timer not expired", spell_id); return; } } @@ -9025,7 +9025,7 @@ void Client::Handle_OP_ItemVerifyRequest(const EQApplicationPacket *app) if (augitem->RecastDelay > 0) { if (!GetPTimers().Expired(&database, (pTimerItemStart + augitem->RecastType), false)) { - LogSpells("Casting of [{}] canceled: item spell reuse timer from augment not expired", spell_id); + LogSpells("[Client::Handle_OP_ItemVerifyRequest] Casting of [{}] canceled: item spell reuse timer from augment not expired", spell_id); MessageString(Chat::Red, SPELL_RECAST); SendSpellBarEnable(augitem->Click.Effect); return; @@ -9063,12 +9063,12 @@ void Client::Handle_OP_ItemVerifyRequest(const EQApplicationPacket *app) { if (item->ItemType != EQ::item::ItemTypeFood && item->ItemType != EQ::item::ItemTypeDrink && item->ItemType != EQ::item::ItemTypeAlcohol) { - LogDebug("Error: unknown item->Click.Type ([{}])", item->Click.Type); + LogDebug("[Client::Handle_OP_ItemVerifyRequest] Error: unknown item->Click.Type ([{}])", item->Click.Type); } } else { - LogDebug("Error: unknown item->Click.Type ([{}])", item->Click.Type); + LogDebug("[Client::Handle_OP_ItemVerifyRequest] Error: unknown item->Click.Type ([{}])", item->Click.Type); } } } @@ -12636,7 +12636,7 @@ void Client::Handle_OP_RezzAnswer(const EQApplicationPacket *app) const Resurrect_Struct* ra = (const Resurrect_Struct*)app->pBuffer; - LogSpells("Received OP_RezzAnswer from client. Pendingrezzexp is [{}], action is [{}]", + LogSpells("[Client::Handle_OP_RezzAnswer] Received OP_RezzAnswer from client. Pendingrezzexp is [{}] action is [{}]", PendingRezzXP, ra->action ? "ACCEPT" : "DECLINE"); diff --git a/zone/client_process.cpp b/zone/client_process.cpp index 9c9e05800..26314fb00 100644 --- a/zone/client_process.cpp +++ b/zone/client_process.cpp @@ -1006,7 +1006,7 @@ void Client::OPRezzAnswer(uint32 Action, uint32 SpellID, uint16 ZoneID, uint16 I { if(PendingRezzXP < 0) { // pendingrezexp is set to -1 if we are not expecting an OP_RezzAnswer - LogSpells("Unexpected OP_RezzAnswer. Ignoring it"); + LogSpells("[Client::OPRezzAnswer] Unexpected OP_RezzAnswer. Ignoring it"); Message(Chat::Red, "You have already been resurrected.\n"); return; } @@ -1016,7 +1016,7 @@ void Client::OPRezzAnswer(uint32 Action, uint32 SpellID, uint16 ZoneID, uint16 I // Mark the corpse as rezzed in the database, just in case the corpse has buried, or the zone the // corpse is in has shutdown since the rez spell was cast. database.MarkCorpseAsRezzed(PendingRezzDBID); - LogSpells("Player [{}] got a [{}] Rezz, spellid [{}] in zone[{}], instance id [{}]", + LogSpells("[Client::OPRezzAnswer] Player [{}] got a [{}] Rezz spellid [{}] in zone[{}] instance id [{}]", name, (uint16)spells[SpellID].base_value[0], SpellID, ZoneID, InstanceID); @@ -1085,7 +1085,7 @@ void Client::OPMemorizeSpell(const EQApplicationPacket* app) { if(app->size != sizeof(MemorizeSpell_Struct)) { - LogError("Wrong size on OP_MemorizeSpell. Got: [{}], Expected: [{}]", app->size, sizeof(MemorizeSpell_Struct)); + LogError("[Client::OPMemorizeSpell] Wrong size on OP_MemorizeSpell. Got: [{}] Expected: [{}]", app->size, sizeof(MemorizeSpell_Struct)); DumpPacket(app); return; } @@ -2052,7 +2052,7 @@ void Client::HandleRespawnFromHover(uint32 Option) { if (PendingRezzXP < 0 || PendingRezzSpellID == 0) { - LogSpells("Unexpected Rezz from hover request"); + LogSpells("[Client::HandleRespawnFromHover] Unexpected Rezz from hover request"); safe_delete(default_to_bind); return; } @@ -2087,10 +2087,10 @@ void Client::HandleRespawnFromHover(uint32 Option) if (corpse && corpse->IsCorpse()) { - LogSpells("Hover Rez in zone [{}] for corpse [{}]", + LogSpells("[Client::HandleRespawnFromHover] Hover Rez in zone [{}] for corpse [{}]", zone->GetShortName(), PendingRezzCorpseName.c_str()); - LogSpells("Found corpse. Marking corpse as rezzed"); + LogSpells("[Client::HandleRespawnFromHover] Found corpse. Marking corpse as rezzed"); corpse->IsRezzed(true); corpse->CompleteResurrection(); diff --git a/zone/groups.cpp b/zone/groups.cpp index baeeb382f..c9b6d47fb 100644 --- a/zone/groups.cpp +++ b/zone/groups.cpp @@ -825,7 +825,7 @@ void Group::CastGroupSpell(Mob* caster, uint16 spell_id) { caster->SpellOnTarget(spell_id, members[z]->GetPet()); #endif } else - LogSpells("Group spell: [{}] is out of range [{}] at distance [{}] from [{}]", members[z]->GetName(), range, distance, caster->GetName()); + LogSpells("[Group::CastGroupSpell] Group spell: [{}] is out of range [{}] at distance [{}] from [{}]", members[z]->GetName(), range, distance, caster->GetName()); } } diff --git a/zone/merc.cpp b/zone/merc.cpp index 044d04f24..f5c7aed41 100644 --- a/zone/merc.cpp +++ b/zone/merc.cpp @@ -1686,7 +1686,7 @@ void Merc::AI_Process() { if (AI_movement_timer->Check()) { if(!IsRooted()) { - LogAI("Pursuing [{}] while engaged", GetTarget()->GetCleanName()); + LogAIDetail("Pursuing [{}] while engaged", GetTarget()->GetCleanName()); RunTo(GetTarget()->GetX(), GetTarget()->GetY(), GetTarget()->GetZ()); return; } @@ -1805,7 +1805,7 @@ bool Merc::AI_EngagedCastCheck() { { AIautocastspell_timer->Disable(); //prevent the timer from going off AGAIN while we are casting. - LogAI("Merc Engaged autocast check triggered"); + LogAIDetail("Merc Engaged autocast check triggered"); int8 mercClass = GetClass(); @@ -1860,7 +1860,7 @@ bool Merc::AI_IdleCastCheck() { if (AIautocastspell_timer->Check(false)) { #if MercAI_DEBUG_Spells >= 25 - LogAI("Merc Non-Engaged autocast check triggered: [{}]", GetCleanName()); + LogAIDetail("Merc Non-Engaged autocast check triggered: [{}]", GetCleanName()); #endif AIautocastspell_timer->Disable(); //prevent the timer from going off AGAIN while we are casting. diff --git a/zone/mob.cpp b/zone/mob.cpp index 902ebb112..b0d575b85 100644 --- a/zone/mob.cpp +++ b/zone/mob.cpp @@ -2551,7 +2551,7 @@ void Mob::SendIllusionPacket( } LogSpells( - "Illusion: Race [{}] Gender [{}] Texture [{}] HelmTexture [{}] HairColor [{}] BeardColor [{}] EyeColor1 [{}] EyeColor2 [{}] HairStyle [{}] Face [{}] DrakkinHeritage [{}] DrakkinTattoo [{}] DrakkinDetails [{}] Size [{}]", + "[Mob::SendIllusionPacket] Illusion: Race [{}] Gender [{}] Texture [{}] HelmTexture [{}] HairColor [{}] BeardColor [{}] EyeColor1 [{}] EyeColor2 [{}] HairStyle [{}] Face [{}] DrakkinHeritage [{}] DrakkinTattoo [{}] DrakkinDetails [{}] Size [{}]", race, gender, new_texture, @@ -4163,7 +4163,7 @@ void Mob::ExecWeaponProc(const EQ::ItemInstance *inst, uint16 spell_id, Mob *on, if(!IsValidSpell(spell_id)) { // Check for a valid spell otherwise it will crash through the function if(IsClient()){ Message(0, "Invalid spell proc %u", spell_id); - LogSpells("Player [{}], Weapon Procced invalid spell [{}]", GetName(), spell_id); + LogSpells("[Mob::ExecWeaponProc] Player [{}] Weapon Procced invalid spell [{}]", GetName(), spell_id); } return; } diff --git a/zone/mob_ai.cpp b/zone/mob_ai.cpp index 5ae1b1b98..f6cfc06ff 100644 --- a/zone/mob_ai.cpp +++ b/zone/mob_ai.cpp @@ -131,10 +131,8 @@ bool NPC::AICastSpell(Mob* tar, uint8 iChance, uint32 iSpellTypes, bool bInnates && (AIspells[i].time_cancast + (zone->random.Int(0, 4) * 500)) <= Timer::GetCurrentTime() //break up the spelling casting over a period of time. ) { -#if MobAI_DEBUG_Spells >= 21 - LogAI("Mob::AICastSpell: Casting: spellid=[{}], tar=[{}], dist2[[{}]]<=[{}], mana_cost[[{}]]<=[{}], cancast[[{}]]<=[{}], type=[{}]", + LogAI("[Mob::AICastSpell] Casting: spellid [{}] tar [{}] dist2[[{}]]<=[{}] mana_cost[[{}]]<=[{}] cancast[[{}]]<=[{}] type [{}]", AIspells[i].spellid, tar->GetName(), dist2, (spells[AIspells[i].spellid].range * spells[AIspells[i].spellid].range), mana_cost, GetMana(), AIspells[i].time_cancast, Timer::GetCurrentTime(), AIspells[i].type); -#endif switch (AIspells[i].type) { case SpellType_Heal: { @@ -364,21 +362,17 @@ bool NPC::AICastSpell(Mob* tar, uint8 iChance, uint32 iSpellTypes, bool bInnates } } } -#if MobAI_DEBUG_Spells >= 21 else { - LogAI("Mob::AICastSpell: NotCasting: spellid=[{}], tar=[{}], dist2[[{}]]<=[{}], mana_cost[[{}]]<=[{}], cancast[[{}]]<=[{}], type=[{}]", + LogAI("[Mob::AICastSpell] NotCasting: spellid [{}] tar [{}] dist2[[{}]]<=[{}] mana_cost[[{}]]<=[{}] cancast[[{}]]<=[{}] type [{}]", AIspells[i].spellid, tar->GetName(), dist2, (spells[AIspells[i].spellid].range * spells[AIspells[i].spellid].range), mana_cost, GetMana(), AIspells[i].time_cancast, Timer::GetCurrentTime(), AIspells[i].type); } -#endif } } return false; } bool NPC::AIDoSpellCast(uint8 i, Mob* tar, int32 mana_cost, uint32* oDontDoAgainBefore) { -#if MobAI_DEBUG_Spells >= 1 - LogAI("Mob::AIDoSpellCast: spellid = [{}], tar = [{}], mana = [{}], Name: [{}]", AIspells[i].spellid, tar->GetName(), mana_cost, spells[AIspells[i].spellid].name); -#endif + LogAI("[Mob::AIDoSpellCast] spellid [{}] tar [{}] mana [{}] Name [{}]", AIspells[i].spellid, tar->GetName(), mana_cost, spells[AIspells[i].spellid].name); casting_spell_AIindex = i; return CastSpell(AIspells[i].spellid, tar->GetID(), EQ::spells::CastingSlot::Gem2, AIspells[i].manacost == -2 ? 0 : -1, mana_cost, oDontDoAgainBefore, -1, -1, 0, &(AIspells[i].resist_adjust)); @@ -1359,7 +1353,7 @@ void Mob::AI_Process() { (GetOwnerID() || IsBot() || IsTempPet() || CastToNPC()->GetCombatEvent())) { if (!IsRooted()) { - LogAI("Pursuing [{}] while engaged", target->GetName()); + LogAIDetail("Pursuing [{}] while engaged", target->GetName()); RunTo(target->GetX(), target->GetY(), target->GetZ()); } @@ -1722,7 +1716,7 @@ void NPC::AI_DoMovement() { else if (!(AI_walking_timer->Enabled())) { // currently moving bool doMove = true; if(IsPositionEqual(glm::vec2(m_CurrentWayPoint.x, m_CurrentWayPoint.y), glm::vec2(GetX(), GetY()))) { - LogAI("We have reached waypoint [{}] ({},{},{}) on grid [{}]", + LogAIDetail("We have reached waypoint [{}] ({},{},{}) on grid [{}]", cur_wp, GetX(), GetY(), @@ -1810,7 +1804,7 @@ void NPC::AI_DoMovement() { if (at_gp) { if (moved) { - LogAI("Reached guard point ({},{},{})", m_GuardPoint.x, m_GuardPoint.y, m_GuardPoint.z); + LogAIDetail("Reached guard point ({},{},{})", m_GuardPoint.x, m_GuardPoint.y, m_GuardPoint.z); ClearFeignMemory(); moved = false; @@ -2017,7 +2011,7 @@ bool NPC::AI_EngagedCastCheck() { if (AIautocastspell_timer->Check(false)) { AIautocastspell_timer->Disable(); //prevent the timer from going off AGAIN while we are casting. - LogAI("Engaged autocast check triggered. Trying to cast healing spells then maybe offensive spells"); + LogAIDetail("Engaged autocast check triggered. Trying to cast healing spells then maybe offensive spells"); // first try innate (spam) spells if(!AICastSpell(GetTarget(), 0, SpellType_Nuke | SpellType_Lifetap | SpellType_DOT | SpellType_Dispel | SpellType_Mez | SpellType_Slow | SpellType_Debuff | SpellType_Charm | SpellType_Root, true)) { @@ -2046,7 +2040,7 @@ bool NPC::AI_PursueCastCheck() { if (AIautocastspell_timer->Check(false)) { AIautocastspell_timer->Disable(); //prevent the timer from going off AGAIN while we are casting. - LogAI("Engaged (pursuing) autocast check triggered. Trying to cast offensive spells"); + LogAIDetail("Engaged (pursuing) autocast check triggered. Trying to cast offensive spells"); // checking innate (spam) spells first if(!AICastSpell(GetTarget(), AISpellVar.pursue_detrimental_chance, SpellType_Root | SpellType_Nuke | SpellType_Lifetap | SpellType_Snare | SpellType_DOT | SpellType_Dispel | SpellType_Mez | SpellType_Slow | SpellType_Debuff, true)) { if(!AICastSpell(GetTarget(), AISpellVar.pursue_detrimental_chance, SpellType_Root | SpellType_Nuke | SpellType_Lifetap | SpellType_Snare | SpellType_DOT | SpellType_Dispel | SpellType_Mez | SpellType_Slow | SpellType_Debuff)) { @@ -2068,7 +2062,7 @@ bool NPC::AI_IdleCastCheck() { //last duration it was set to... try to put up a more reasonable timer... AIautocastspell_timer->Start(RandomTimer(AISpellVar.idle_no_sp_recast_min, AISpellVar.idle_no_sp_recast_max), false); - LogSpells("Triggering AI_IdleCastCheck :: Mob [{}] - Min : [{}] Max : [{}]", GetCleanName(), AISpellVar.idle_no_sp_recast_min, AISpellVar.idle_no_sp_recast_max); + LogSpells("[NPC::AI_IdleCastCheck] Mob [{}] Min [{}] Max [{}]", GetCleanName(), AISpellVar.idle_no_sp_recast_min, AISpellVar.idle_no_sp_recast_max); } //else, spell casting finishing will reset the timer. } //else, spell casting finishing will reset the timer. @@ -2499,7 +2493,6 @@ bool NPC::AI_AddNPCSpells(uint32 iDBSpellsID) { return false; } DBnpcspells_Struct* parentlist = content_db.GetNPCSpells(spell_list->parent_list); -#if MobAI_DEBUG_Spells >= 10 std::string debug_msg = StringFormat("Loading NPCSpells onto %s: dbspellsid=%u, level=%u", GetName(), iDBSpellsID, GetLevel()); if (spell_list) { debug_msg.append(StringFormat(" (found, %u), parentlist=%u", spell_list->entries.size(), spell_list->parent_list)); @@ -2515,22 +2508,19 @@ bool NPC::AI_AddNPCSpells(uint32 iDBSpellsID) { } LogAI("[{}]", debug_msg.c_str()); -#ifdef MobAI_DEBUG_Spells >= 25 if (parentlist) { for (const auto &iter : parentlist->entries) { - LogAI("([{}]) [{}]", iter.spellid, spells[iter.spellid].name); + LogAIDetail("([{}]) [{}]", iter.spellid, spells[iter.spellid].name); } } LogAI("fin (parent list)"); if (spell_list) { for (const auto &iter : spell_list->entries) { - LogAI("([{}]) [{}]", iter.spellid, spells[iter.spellid].name); + LogAIDetail("([{}]) [{}]", iter.spellid, spells[iter.spellid].name); } } LogAI("fin (spell list)"); -#endif -#endif uint16 attack_proc_spell = -1; int8 proc_chance = 3; uint16 range_proc_spell = -1; @@ -2674,7 +2664,6 @@ bool NPC::AI_AddNPCSpellsEffects(uint32 iDBSpellsEffectsID) { DBnpcspellseffects_Struct* parentlist = content_db.GetNPCSpellsEffects(spell_effects_list->parent_list); uint32 i; -#if MobAI_DEBUG_Spells >= 10 std::string debug_msg = StringFormat("Loading NPCSpellsEffects onto %s: dbspellseffectid=%u", GetName(), iDBSpellsEffectsID); if (spell_effects_list) { debug_msg.append(StringFormat(" (found, %u), parentlist=%u", spell_effects_list->numentries, spell_effects_list->parent_list)); @@ -2689,7 +2678,6 @@ bool NPC::AI_AddNPCSpellsEffects(uint32 iDBSpellsEffectsID) { debug_msg.append(" (not found)"); } LogAI("[{}]", debug_msg.c_str()); -#endif if (parentlist) { for (i=0; inumentries; i++) { diff --git a/zone/raids.cpp b/zone/raids.cpp index b27cae0e0..f097decaf 100644 --- a/zone/raids.cpp +++ b/zone/raids.cpp @@ -566,7 +566,7 @@ void Raid::CastGroupSpell(Mob* caster, uint16 spellid, uint32 gid) #endif } else{ - LogSpells("Raid spell: [{}] is out of range [{}] at distance [{}] from [{}]", members[x].member->GetName(), range, distance, caster->GetName()); + LogSpells("[Raid::CastGroupSpell] Raid spell: [{}] is out of range [{}] at distance [{}] from [{}]", members[x].member->GetName(), range, distance, caster->GetName()); } } } diff --git a/zone/spell_effects.cpp b/zone/spell_effects.cpp index b642ab7ea..6408b7266 100644 --- a/zone/spell_effects.cpp +++ b/zone/spell_effects.cpp @@ -1631,7 +1631,7 @@ bool Mob::SpellEffect(Mob* caster, uint16 spell_id, float partial, int level_ove if (IsCorpse() && CastToCorpse()->IsPlayerCorpse()) { if(caster) - LogSpells(" corpse being rezzed using spell [{}] by [{}]", + LogSpells("[Mob::SpellEffect] corpse being rezzed using spell [{}] by [{}]", spell_id, caster->GetName()); CastToCorpse()->CastRezz(spell_id, caster); @@ -3361,7 +3361,7 @@ int64 Mob::CalcSpellEffectValue(uint16 spell_id, int effect_id, int caster_level && IsInstrumentModAppliedToSpellEffect(spell_id, spells[spell_id].effect_id[effect_id])) { oval = effect_value; effect_value = effect_value * static_cast(instrument_mod) / 10; - LogSpells("Effect value [{}] altered with bard modifier of [{}] to yeild [{}]", + LogSpells("[Mob::CalcSpellEffectValue] Effect value [{}] altered with bard modifier of [{}] to yeild [{}]", oval, instrument_mod, effect_value); } /* @@ -3388,7 +3388,7 @@ int64 Mob::CalcSpellEffectValue(uint16 spell_id, int effect_id, int caster_level int mod = caster->GetFocusEffect(focusFcBaseEffects, spell_id); effect_value += effect_value * mod / 100; - LogSpells("Instant Effect value [{}] altered with base effects modifier of [{}] to yeild [{}]", + LogSpells("[Mob::CalcSpellEffectValue] Instant Effect value [{}] altered with base effects modifier of [{}] to yeild [{}]", oval, mod, effect_value); } //This is checked from Mob::ApplySpellBonuses, applied to buffs that receive bonuses. See above, must be in 10% intervals to work. @@ -3399,7 +3399,7 @@ int64 Mob::CalcSpellEffectValue(uint16 spell_id, int effect_id, int caster_level oval = effect_value; effect_value = effect_value * static_cast(instrument_mod) / 10; - LogSpells("Bonus Effect value [{}] altered with base effects modifier of [{}] to yeild [{}]", + LogSpells("[Mob::CalcSpellEffectValue] Bonus Effect value [{}] altered with base effects modifier of [{}] to yeild [{}]", oval, instrument_mod, effect_value); } } @@ -3463,7 +3463,7 @@ snare has both of them negative, yet their range should work the same: updownsign = 1; } - LogSpells("CSEV: spell [{}], formula [{}], base [{}], max [{}], lvl [{}]. Up/Down [{}]", + LogSpells("[Mob::CalcSpellEffectValue_formula] spell [{}] formula [{}] base [{}] max [{}] lvl [{}] Up/Down [{}]", spell_id, formula, base_value, max_value, caster_level, updownsign); switch(formula) @@ -3686,7 +3686,7 @@ snare has both of them negative, yet their range should work the same: result = ubase * (caster_level * (formula - 2000) + 1); } else - LogDebug("Unknown spell effect value forumula [{}]", formula); + LogDebug("[Mob::CalcSpellEffectValue_formula] Unknown spell effect value forumula [{}]", formula); } } @@ -3711,7 +3711,7 @@ snare has both of them negative, yet their range should work the same: if (base_value < 0 && result > 0) result *= -1; - LogSpells("Result: [{}] (orig [{}]), cap [{}] [{}]", result, oresult, max_value, (base_value < 0 && result > 0)?"Inverted due to negative base":""); + LogSpells("[Mob::CalcSpellEffectValue_formula] Result: [{}] (orig [{}]) cap [{}] [{}]", result, oresult, max_value, (base_value < 0 && result > 0)?"Inverted due to negative base":""); return result; } @@ -3739,12 +3739,12 @@ void Mob::BuffProcess() --buffs[buffs_i].ticsremaining; if (buffs[buffs_i].ticsremaining < 0) { - LogSpells("Buff [{}] in slot [{}] has expired. Fading", buffs[buffs_i].spellid, buffs_i); + LogSpells("[Mob::BuffProcess] Buff [{}] in slot [{}] has expired. Fading", buffs[buffs_i].spellid, buffs_i); BuffFadeBySlot(buffs_i); } else { - LogSpells("Buff [{}] in slot [{}] has [{}] tics remaining", buffs[buffs_i].spellid, buffs_i, buffs[buffs_i].ticsremaining); + LogSpells("[Mob::BuffProcess] Buff [{}] in slot [{}] has [{}] tics remaining", buffs[buffs_i].spellid, buffs_i, buffs[buffs_i].ticsremaining); } } else if (IsClient() && !(CastToClient()->ClientVersionBit() & EQ::versions::maskSoFAndLater)) @@ -4128,7 +4128,7 @@ void Mob::BuffFadeBySlot(int slot, bool iRecalcBonuses) if (IsClient() && !CastToClient()->IsDead()) CastToClient()->MakeBuffFadePacket(buffs[slot].spellid, slot); - LogSpells("Fading buff [{}] from slot [{}]", buffs[slot].spellid, slot); + LogSpells("[Mob::BuffFadeBySlot] Fading buff [{}] from slot [{}]", buffs[slot].spellid, slot); std::string export_string = fmt::format( "{} {} {} {}", @@ -9674,21 +9674,21 @@ bool Mob::PassCharmTargetRestriction(Mob *target) { if (target->IsClient() && IsClient()) { MessageString(Chat::Red, CANNOT_AFFECT_PC); - LogSpells("Spell casting canceled: Can not cast charm on a client."); + LogSpells("[Mob::PassCharmTargetRestriction] Spell casting canceled: Can not cast charm on a client."); return false; } else if (target->IsCorpse()) { - LogSpells("Spell casting canceled: Can not cast charm on a corpse."); + LogSpells("[Mob::PassCharmTargetRestriction] Spell casting canceled: Can not cast charm on a corpse."); return false; } else if (GetPet() && IsClient()) { MessageString(Chat::Red, ONLY_ONE_PET); - LogSpells("Spell casting canceled: Can not cast charm if you have a pet."); + LogSpells("[Mob::PassCharmTargetRestriction] Spell casting canceled: Can not cast charm if you have a pet."); return false; } else if (target->GetOwner()) { MessageString(Chat::Red, CANNOT_CHARM); - LogSpells("Spell casting canceled: Can not cast charm on a pet."); + LogSpells("[Mob::PassCharmTargetRestriction] Spell casting canceled: Can not cast charm on a pet."); return false; } return true; diff --git a/zone/waypoints.cpp b/zone/waypoints.cpp index 2fb825de1..b1dac5094 100644 --- a/zone/waypoints.cpp +++ b/zone/waypoints.cpp @@ -252,7 +252,7 @@ void NPC::MoveTo(const glm::vec4 &position, bool saveguardspot) void NPC::UpdateWaypoint(int wp_index) { if (wp_index >= static_cast(Waypoints.size())) { - LogAI("Update to waypoint [{}] failed. Not found", wp_index); + LogAIDetail("Update to waypoint [{}] failed. Not found", wp_index); return; } std::vector::iterator cur; @@ -567,7 +567,7 @@ void NPC::SaveGuardSpot(bool ClearGuardSpot) { if (m_GuardPoint.w == 0) { m_GuardPoint.w = 0.0001; //hack to make IsGuarding simpler } - LogAI("Setting guard position to {0}", to_string(static_cast(m_GuardPoint))); + LogAIDetail("Setting guard position to [{}]", to_string(static_cast(m_GuardPoint))); } } @@ -577,7 +577,7 @@ void NPC::SaveGuardSpot(const glm::vec4 &pos) if (m_GuardPoint.w == 0) m_GuardPoint.w = 0.0001; //hack to make IsGuarding simpler - LogAI("Setting guard position to {0}", to_string(static_cast(m_GuardPoint))); + LogAIDetail("Setting guard position to [{}]", to_string(static_cast(m_GuardPoint))); } void NPC::NextGuardPosition() { diff --git a/zone/worldserver.cpp b/zone/worldserver.cpp index 7d86a58a6..36bf6ac60 100644 --- a/zone/worldserver.cpp +++ b/zone/worldserver.cpp @@ -864,7 +864,7 @@ void WorldServer::HandleMessage(uint16 opcode, const EQ::Net::Packet &p) //pendingrezexp is the amount of XP on the corpse. Setting it to a value >= 0 //also serves to inform Client::OPRezzAnswer to expect a packet. client->SetPendingRezzData(srs->exp, srs->dbid, srs->rez.spellid, srs->rez.corpse_name); - LogSpells("OP_RezzRequest in zone [{}] for [{}], spellid:[{}]", + LogSpells("[WorldServer::HandleMessage] OP_RezzRequest in zone [{}] for [{}] spellid [{}]", zone->GetShortName(), client->GetName(), srs->rez.spellid); auto outapp = new EQApplicationPacket(OP_RezzRequest, sizeof(Resurrect_Struct)); @@ -879,10 +879,10 @@ void WorldServer::HandleMessage(uint16 opcode, const EQ::Net::Packet &p) // to the zone that the corpse is in. Corpse* corpse = entity_list.GetCorpseByName(srs->rez.corpse_name); if (corpse && corpse->IsCorpse()) { - LogSpells("OP_RezzComplete received in zone [{}] for corpse [{}]", + LogSpells("[WorldServer::HandleMessage] OP_RezzComplete received in zone [{}] for corpse [{}]", zone->GetShortName(), srs->rez.corpse_name); - LogSpells("Found corpse. Marking corpse as rezzed if needed"); + LogSpells("[WorldServer::HandleMessage] Found corpse. Marking corpse as rezzed if needed"); // I don't know why Rezzed is not set to true in CompleteRezz(). if (!IsEffectInSpell(srs->rez.spellid, SE_SummonToCorpse)) { corpse->IsRezzed(true); @@ -3442,7 +3442,7 @@ bool WorldServer::SendVoiceMacro(Client* From, uint32 Type, char* Target, uint32 bool WorldServer::RezzPlayer(EQApplicationPacket* rpack, uint32 rezzexp, uint32 dbid, uint16 opcode) { - LogSpells("WorldServer::RezzPlayer rezzexp is [{}] (0 is normal for RezzComplete", rezzexp); + LogSpells("[WorldServer::RezzPlayer] rezzexp is [{}] (0 is normal for RezzComplete", rezzexp); auto pack = new ServerPacket(ServerOP_RezzPlayer, sizeof(RezzPlayer_Struct)); RezzPlayer_Struct* sem = (RezzPlayer_Struct*)pack->pBuffer; sem->rezzopcode = opcode; @@ -3451,9 +3451,9 @@ bool WorldServer::RezzPlayer(EQApplicationPacket* rpack, uint32 rezzexp, uint32 sem->dbid = dbid; bool ret = SendPacket(pack); if (ret) - LogSpells("Sending player rezz packet to world spellid:[{}]", sem->rez.spellid); + LogSpells("[WorldServer::RezzPlayer] Sending player rezz packet to world spellid:[{}]", sem->rez.spellid); else - LogSpells("NOT Sending player rezz packet to world"); + LogSpells("[WorldServer::RezzPlayer] NOT Sending player rezz packet to world"); safe_delete(pack); return ret;