fix(keywords): some KID items were breaking certain active effects

src/data/item_cache.rs

@@ -106,8 +106,7 @@ impl ItemCache {
     /// Set the count of a cached item to the passed-in value.
     pub fn set_count(&mut self, form_spec: &str, new_count: u32) -> Option<&HudItem> {
         if !self.contains(form_spec) {
-            let fetched = fetch_game_item(form_spec);
-            self.record(fetched);
+            return None;
         }
 
         let Some(item) = self.lru.get_mut(form_spec) else {
@@ -121,8 +120,7 @@ impl ItemCache {
     /// cache, no action is taken.
     pub fn update_count(&mut self, form_spec: &str, new_count: u32) -> Option<&HudItem> {
         if !self.contains(form_spec) {
-            let fetched = fetch_game_item(form_spec);
-            self.record(fetched);
+            return None;
         }
         let Some(item) = self.lru.get_mut(form_spec) else {
             return None;

src/data/power.rs

@@ -13,7 +13,7 @@ pub struct PowerType {
 
 impl PowerType {
     pub fn new(name: &str, tags: Vec<String>) -> Self {
-        log::info!("{tags:?}");
+        // log::trace!("{tags:?}");
         let kywds = strings_to_enumset::<SpellKeywords>(&tags);
 
         let icon = if let Some(found) = icon_for_tagset(&kywds) {

src/game/gear.cpp

@@ -134,9 +134,9 @@ namespace gear
 
 		if (!foundObject) { return 0; }
 
-		rlog::debug("boundObjectForWornItem(constraint={}) found formid='{}';",
+		rlog::debug("boundObjectForWornItem(constraint={}) found formid='{:#08x}';",
 			static_cast<std::underlying_type_t<WornWhere>>(constraint),
-			rlog::formatAsHex(foundObject->formID));
+			foundObject->formID);
 
 		if (extraDataCopy.size() > 0) { outextra = extraDataCopy.back(); }
 		outobj = foundObject;
@@ -189,8 +189,7 @@ namespace gear
 
 		if (!foundObject) { return 0; }
 
-		rlog::debug(
-			"boundObjectMatchName '{}'; found formID={};"sv, nameToMatch, rlog::formatAsHex(foundObject->formID));
+		rlog::debug("boundObjectMatchName '{}'; found formID={:#08x};"sv, nameToMatch, foundObject->formID);
 		if (extraDataCopy.size() > 0) { outextra = extraDataCopy.back(); }
 		outobj = foundObject;
 		return equipData.count;
@@ -226,10 +225,10 @@ namespace gear
 
 		if (!foundObject) { return 0; }
 
-		rlog::trace("found {} instance(s) for bound object; name='{}'; formID={};"sv,
+		rlog::trace("found {} instance(s) for bound object; name='{}'; formID={:#08x};"sv,
 			count,
 			helpers::nameAsUtf8(form),
-			rlog::formatAsHex(form->formID));
+			form->formID);
 
 		if (extraDataCopy.size() > 0) { outextra = extraDataCopy.back(); }
 		outobj = foundObject;
@@ -520,10 +519,10 @@ namespace gear
 			return;
 		}
 
-		rlog::debug("queuing task to equip '{}'; left={}; formID={};"sv,
+		rlog::debug("queuing task to equip '{}'; left={}; formID={:#08x};"sv,
 			helpers::nameAsUtf8(form),
 			slot_is_left,
-			rlog::formatAsHex(equipObject->formID));
+			equipObject->formID);
 		auto* task = SKSE::GetTaskInterface();
 		if (task)
 		{
@@ -572,10 +571,10 @@ namespace gear
 			return;
 		}
 
-		rlog::debug("queued task to equip '{}'; left={}; formID={};"sv,
+		rlog::debug("queued task to equip '{}'; left={}; formID={:#08x};"sv,
 			helpers::nameAsUtf8(form),
 			slot_is_left,
-			rlog::formatAsHex(form->formID));
+			form->formID);
 	}
 
 	void unequipHand(RE::PlayerCharacter*& player, Action which)

src/game/shouts.cpp

@@ -43,7 +43,7 @@ namespace shouts
 		{
 			auto* task = SKSE::GetTaskInterface();
 			if (!task) return;
-			rlog::trace("unequipping shout/power formID={};"sv, rlog::formatAsHex(selected_power->formID));
+			rlog::trace("unequipping shout/power formID={:#08x};"sv, selected_power->formID);
 			if (selected_power->Is(RE::FormType::Shout))
 			{
 				task->AddTask(

src/game/utility.cpp

@@ -29,13 +29,12 @@ namespace utility
 
 		if (const auto* current_ammo = thePlayer->GetCurrentAmmo(); current_ammo && current_ammo->formID == obj->formID)
 		{
-			// rlog::trace("ammo is already equipped; bound formID={}"sv, rlog::formatAsHex(obj->formID));
+			// rlog::trace("ammo is already equipped; bound formID={:#08x}"sv, obj->formID);
 			return;
 		}
 
-		rlog::debug("queuing task to equip ammo; name='{}'; bound formID={}"sv,
-			helpers::nameAsUtf8(obj),
-			rlog::formatAsHex(obj->formID));
+		rlog::debug(
+			"queuing task to equip ammo; name='{}'; bound formID={:#08x};"sv, helpers::nameAsUtf8(obj), obj->formID);
 		auto* task = SKSE::GetTaskInterface();
 		if (task)
 		{
@@ -59,8 +58,7 @@ namespace utility
 			{
 				task->AddTask([=]() { RE::ActorEquipManager::GetSingleton()->UnequipObject(thePlayer, ammo); });
 			}
-			rlog::debug(
-				"ammo unequipped; name='{}'; formID={}"sv, helpers::nameAsUtf8(ammo), rlog::formatAsHex(ammo->formID));
+			rlog::debug("ammo unequipped; name='{}'; formID={:#08x};"sv, helpers::nameAsUtf8(ammo), ammo->formID);
 		}
 	}
 
@@ -133,8 +131,8 @@ namespace utility
 
 	void consumePotion(const RE::TESForm* potionForm, RE::PlayerCharacter*& thePlayer)
 	{
-		rlog::trace("consumePotion called; form_id={}; potion='{}';"sv,
-			rlog::formatAsHex(potionForm->formID),
+		rlog::trace("consumePotion called; form_id={:#08x}; potion='{}';"sv,
+			potionForm->formID,
 			helpers::nameAsUtf8(potionForm));
 
 		RE::TESBoundObject* obj      = nullptr;
@@ -151,9 +149,9 @@ namespace utility
 		if (!obj->Is(RE::FormType::AlchemyItem))
 		{
 			helpers::honk();
-			rlog::warn("bound object is not an alchemy item? name='{}'; formID={};"sv,
+			rlog::warn("bound object is not an alchemy item? name='{}'; formID={:#08x};"sv,
 				helpers::nameAsUtf8(obj),
-				rlog::formatAsHex(obj->formID));
+				obj->formID);
 			return;
 		}
 
@@ -325,7 +323,7 @@ namespace utility
 		const auto* entry_point = static_cast<RE::BGSEntryPointPerkEntry*>(perk_entry);
 		const auto* perk        = entry_point->perk;
 
-		rlog::trace("perk formID={}; name='{}';"sv, rlog::formatAsHex(perk->formID), helpers::nameAsUtf8(perk));
+		rlog::trace("perk formID={:#08x}; name='{}';"sv, perk->formID, helpers::nameAsUtf8(perk));
 
 		// This was originally intended to handle many variations of the poison
 		// dose perk-- it should calculate the correct value from vanilla,

src/plugin/inventory.cpp

@@ -61,19 +61,19 @@ RE::ObjectRefHandle PlayerHook::itemRemoved(RE::Actor* actor,
 	const RE::NiPoint3* a_drop_loc,
 	const RE::NiPoint3* a_rotate)
 {
-	auto retval = remove_item_(actor, object, delta, a_reason, extraDataList, a_move_to_ref, a_drop_loc, a_rotate);
 	if (object->IsInventoryObject())
 	{
 		auto* item_form = RE::TESForm::LookupByID(object->formID);
 		notifyInventoryChanged(item_form);
 	}
-	return retval;
+	return remove_item_(actor, object, delta, a_reason, extraDataList, a_move_to_ref, a_drop_loc, a_rotate);
 }
 
 void PlayerHook::add_item_functor(RE::TESObjectREFR* a_this, RE::TESObjectREFR* object, int32_t delta, bool a4, bool a5)
 {
 	add_item_functor_(a_this, object, delta, a4, a5);
 	auto item_form = RE::TESForm::LookupByID(object->GetBaseObject()->formID);
+	rlog::info("add_item_functor; {};", object->GetBaseObject()->formID);
 	notifyInventoryChanged(item_form);
 }
 

src/plugin/menus.cpp

@@ -75,8 +75,8 @@ RE::BSEventNotifyControl MenuHook::process_event(RE::InputEvent** eventPtr,
 					auto menu_form           = MenuSelection::getSelectionFromMenu(ui, selection);
 					if (!menu_form) continue;
 
-					rlog::debug("Got toggled favorite: form_id={}; form_type={}; is-favorited={};"sv,
-						rlog::formatAsHex(selection->form_id),
+					rlog::debug("Got toggled favorite: form_id={:#08x}; form_type={}; is-favorited={};"sv,
+						selection->form_id,
 						selection->formType,
 						selection->favorite);
 
@@ -156,7 +156,7 @@ uint32_t MenuSelection::makeFromFavoritesMenu(RE::FavoritesMenu* menu, MenuSelec
 	if (result.GetType() == RE::GFxValue::ValueType::kNumber)
 	{
 		form_id = static_cast<std::uint32_t>(result.GetNumber());
-		// rlog::debug("favorites menu selection has formid {}"sv, rlog::formatAsHex(form_id));
+		// rlog::debug("favorites menu selection has formid {:#08x}"sv, form_id);
 	}
 	if (form_id == 0) { return 0; }
 
@@ -218,7 +218,7 @@ void MenuSelection::makeFromInventoryMenu(RE::InventoryMenu* menu, MenuSelection
 	if (result.GetType() == RE::GFxValue::ValueType::kNumber)
 	{
 		RE::FormID form_id = static_cast<std::uint32_t>(result.GetNumber());
-		rlog::trace("formid {}"sv, rlog::formatAsHex(form_id));
+		rlog::trace("formid {:#08x}"sv, form_id);
 		auto* item_form = RE::TESForm::LookupByID(form_id);
 		if (!item_form) return;
 
@@ -261,7 +261,7 @@ void MenuSelection::makeFromMagicMenu(RE::MagicMenu* menu, MenuSelection*& outSe
 
 	for (auto* form : mfaves->spells)
 	{
-		rlog::debug("mfave form: id={}; name='{}'"sv, rlog::formatAsHex(form->GetFormID()), helpers::nameAsUtf8(form));
+		rlog::debug("mfave form: id={:#08x}; name='{}'"sv, form->GetFormID(), helpers::nameAsUtf8(form));
 		if (form->GetFormID() == form_id)
 		{
 			// match time

src/plugin/sinks.cpp

@@ -32,9 +32,9 @@ void registerAllListeners()
 	auto okay    = player->AddAnimationGraphEventSink(listener);
 	if (okay) { rlog::info("    animation graph events to get grip changes."); }
 
-	// scriptEventSourceHolder->GetEventSource<RE::TESMagicEffectApplyEvent>()->AddEventSink(listener);
-	// scriptEventSourceHolder->GetEventSource<RE::TESActiveEffectApplyRemoveEvent>()->AddEventSink(listener);
-	// rlog::info("    magic effects come and go, talking of Michelangelo."sv);
+	//scriptEventSourceHolder->GetEventSource<RE::TESMagicEffectApplyEvent>()->AddEventSink(listener);
+	//scriptEventSourceHolder->GetEventSource<RE::TESActiveEffectApplyRemoveEvent>()->AddEventSink(listener);
+	//rlog::info("    magic effects come and go, talking of Michelangelo."sv);
 }
 
 TheListener* TheListener::singleton()
@@ -198,8 +198,6 @@ RE::BSEventNotifyControl TheListener::ProcessEvent(const RE::TESMagicEffectApply
 		return RE::BSEventNotifyControl::kContinue;
 	}
 
-	// We are specifically looking for VampireLordEffect on the player.
-
 	rlog::info("Effect status change: '{}' {} put \"{}\" ({}) on '{}' {}",
 		casterName,
 		event->caster ? rlog::formatAsHex(event->caster->GetFormID()) : "<none>",
@@ -215,11 +213,16 @@ RE::BSEventNotifyControl TheListener::ProcessEvent(const RE::TESActiveEffectAppl
 	[[maybe_unused]] RE::BSTEventSource<RE::TESActiveEffectApplyRemoveEvent>* source)
 {
 	// TODO; just logging for now
-	auto caster     = event->caster->GetBaseObject();
-	auto casterName = helpers::displayNameAsUtf8(caster);
+	auto caster     = event->caster ? event->caster->GetBaseObject() : nullptr;
+	auto casterName = caster ? helpers::displayNameAsUtf8(caster) : "<unknown>";
 
-	auto target     = event->target->GetBaseObject();
-	auto targetName = helpers::displayNameAsUtf8(target);
+	auto target     = event->target ? event->target->GetBaseObject() : nullptr;
+	auto targetName = target ? helpers::displayNameAsUtf8(target) : "<unknown>";
+
+	rlog::info(
+		"effect unique id={:#04x}; verb: {}", event->activeEffectUniqueID, event->isApplied ? "applied" : "removed");
+
+	if (!caster || !target) { return RE::BSEventNotifyControl::kContinue; }
 
 	const auto playerID = RE::PlayerCharacter::GetSingleton()->GetFormID();
 	if (caster->GetFormID() != playerID && target->GetFormID() != playerID)

src/util/helpers.cpp

@@ -179,8 +179,7 @@ namespace helpers
 		if (form->IsDynamicForm())
 		{
 			// rlog::trace("it is dynamic"sv);
-			form_string =
-				fmt::format("{}{}{}", util::dynamic_name, util::delimiter, rlog::formatAsHex(form->GetFormID()));
+			form_string = fmt::format("{}{}{:#08x}", util::dynamic_name, util::delimiter, form->GetFormID());
 		}
 		else
 		{