Client-Server Item Desyncronization Bugs

[Uleat]

Hello All!


I am creating this thread so that a thorough bug description repository and feedback forum will be available for me
and others to use to troubleshoot and trace the source of client-server item desyncronizations.

I have already researched posted issues both here and at www.peqtgc.com and have accumulated a small library. Most of
what I have seen are the results of desyncronization and not the actual bugs themselves.


I have been able to find, and reproduce with 100% accuracy, at least six desyncronization bugs. Some minor fixes have
led to even more bugs revealing themselves. None of the bugs, that I have discovered, are exploits. However, certain
conditions can lead to exploits or permanent loss of items.

I will not give detailed information on what bugs lead to exploits and ask that anyone posting information not to give
explainations of how to do so as well. We know that certain bugs can be exploited..we just need information about what
led to the occurrence of the bug. If you choose to find a way to exploit these bugs, you will most likely be treated
as a hacker by the GM's and Admin's of your host server and suffer any consequences thereof.


As this is the EQEmulator forum, we cannot promise any bug submission rewards for posted information. You will need to
apply on the forums of your host server, should they offer them. They will determine feasability based on their set of
rules and criteria.


So far, all of the bugs that I have discovered are initiated by some function that deals with sorting stackable items.
I have added immense debug code to inventory.cpp so that I may see in real-time what is occurring. This includes standard
item swapping, bandolier swapping and the possibility of corpse looting. I have not tested the corpse looting myself, but
looking over the code responsible for handling stackable items, I see a major difference in the way that it's handled
versus the way the client and other server methods do.

Without this debug code added to the zone server, you will not be able to see the actual bug conditions as they happen.
Only the results of a desyncronization will be apparent.

ANY desyncronization will lead to problems at some point and it is not recommended to replicate these bugs on anything
but test or private servers.


Here are some of the conditions that I have found that will lead to desync:

- Holding a weapon (especially one used in a bandolier swap) in-hand while performing a swap that contains arrows.
- Clicking a stack of arrows that doesn't respond, then clicking on another item or empty slot.
- Holding a partial stack of ammo that is used during a bandolier swap.
- Certain swap conditions will lead to an arrow with zero charges.
- Certain swap conditions will lead to having a backpack (or other non-ammo item) placed in the ammo slot.

You should zone or camp as soon as possible if you discover that you have a stackable item that is not clickable!
(If you manage to get a backpack in your ammo slot, zone and then click on the ammo slot with the backpack that appears.)


The following patch is not guaranteed to be bug free nor provide 100% reliable results. The code is intended to aid in
resolving current issues and may or may not be upgraded or refined in the future. Some portions are untested and could
cause a server crash with item loss. Use it at your own risk. (It was reverted and patched with no apparent issues.)

<inventory.cpp.patch>

Index: inventory.cpp
===================================================================
--- inventory.cpp	(revision 2158)
+++ inventory.cpp	(working copy)
@@ -35,13 +35,21 @@
 
 // @merth: this needs to be touched up
 uint32 Client::NukeItem(uint32 itemnum, uint8 where_to_check) {
-	if (itemnum == 0)
+	Message(4, "NukeIt->Entry(ItemID[%u])", itemnum);
+
+	if (itemnum == 0) {
+		Message(4, "NukeIt->Exit(Item[Null])");
+		
 		return 0;
+	}
+
 	uint32 x = 0;
 	ItemInst *cur = NULL;
     
 	int i;
     if(where_to_check & invWhereWorn) {
+		Message(4, "NukeIt->Process(Worn[%s])", database.GetItem(itemnum)?database.GetItem(itemnum)->Name:"InvalidID");
+
 	    for (i=0; i<=21; i++) { // Equipped
 	    	if (GetItemIDAt(i) == itemnum || (itemnum == 0xFFFE && GetItemIDAt(i) != INVALID_ID)) {
                 cur = m_inv.GetItem(i);
@@ -72,6 +80,8 @@
     }
 
     if(where_to_check & invWhereCursor) {
+		Message(4, "NukeIt->Process(Cursor[%s])", database.GetItem(itemnum)?database.GetItem(itemnum)->Name:"InvalidID");
+
 	    if (GetItemIDAt(30) == itemnum || (itemnum == 0xFFFE && GetItemIDAt(30) != INVALID_ID)) {
             cur = m_inv.GetItem(30);
             if(cur && cur->GetItem()->Stackable) {
@@ -98,6 +108,8 @@
     }
 
     if(where_to_check & invWherePersonal) {
+		Message(4, "NukeIt->Process(Inventory[%s])", database.GetItem(itemnum)?database.GetItem(itemnum)->Name:"InvalidID");
+
         for (i=22; i<=29; i++) { // Equipped
 	    	if (GetItemIDAt(i) == itemnum || (itemnum == 0xFFFE && GetItemIDAt(i) != INVALID_ID)) {
                 cur = m_inv.GetItem(i);
@@ -126,6 +138,8 @@
     }
 
     if(where_to_check & invWhereBank) {
+		Message(4, "NukeIt->Process(Bank[%s])", database.GetItem(itemnum)?database.GetItem(itemnum)->Name:"InvalidID");
+
 	    for (i=2000; i<=2023; i++) { // Bank slots
 	    	if (GetItemIDAt(i) == itemnum || (itemnum == 0xFFFE && GetItemIDAt(i) != INVALID_ID)) {
                 cur = m_inv.GetItem(i);
@@ -154,6 +168,8 @@
     }
 
     if(where_to_check & invWhereSharedBank) {
+		Message(4, "NukeIt->Process(SharedBank[%s])", database.GetItem(itemnum)?database.GetItem(itemnum)->Name:"InvalidID");
+
 	    for (i=2500; i<=2501; i++) { // Shared bank
 	    	if (GetItemIDAt(i) == itemnum || (itemnum == 0xFFFE && GetItemIDAt(i) != INVALID_ID)) {
                 cur = m_inv.GetItem(i);
@@ -180,29 +196,48 @@
 	    	}
 	    }
     }
+	Message(4, "NukeIt->Exit(Item[%s])->NukeTotal[%u]", database.GetItem(itemnum)?database.GetItem(itemnum)->Name:"InvalidID", x);
 
 	return x;
 }
 
 
 bool Client::CheckLoreConflict(const Item_Struct* item) {
-	if (!item)
+	Message(4, "ChkLoreCon->Entry(ItemID[%u])", item?item->ID:0);
+
+	if (!item) {
+		Message(4, "ChkLoreCon->Exit(Item[Null])");
+
 		return false;
-	if (!(item->LoreFlag))
+	}
+
+	if (!(item->LoreFlag)) {
+		Message(4, "ChkLoreCon->Exit(NoLoreFlag[%s])", item->Name);
+
 		return false;
+	}
 
-	if (item->LoreGroup == -1)	// Standard lore items; look everywhere except the shared bank, return the result
-		return (m_inv.HasItem(item->ID, 0, ~invWhereSharedBank) != SLOT_INVALID);	
+	if (item->LoreGroup == -1) {	// Standard lore items; look everywhere except the shared bank, return the result
+		Message(4, "ChkLoreCon->Exit(LoreCheck[%s]->Conflict[%s])", item->Name, (m_inv.HasItem(item->ID, 0, ~invWhereSharedBank) != SLOT_INVALID)?"True":"False");
+		
+		return (m_inv.HasItem(item->ID, 0, ~invWhereSharedBank) != SLOT_INVALID);
+	}
+	//If the item has a lore group, we check for other items with the same group and return the result
+	Message(4, "ChkLoreCon->Exit(LoreGroupCheck[%s]->Conflict[%s])", item->Name, (m_inv.HasItemByLoreGroup(item->LoreGroup, ~invWhereSharedBank) != SLOT_INVALID)?"True":"False");
 
-	//If the item has a lore group, we check for other items with the same group and return the result
 	return (m_inv.HasItemByLoreGroup(item->LoreGroup, ~invWhereSharedBank) != SLOT_INVALID);
 }
 
 void Client::SummonItem(uint32 item_id, sint16 charges, uint32 aug1, uint32 aug2, uint32 aug3, uint32 aug4, uint32 aug5, bool attuned, uint16 to_slot) {
+	Message(4, "SumIt->Entry(ItemID[%u])", item_id);
+	
 	const Item_Struct* item = database.GetItem(item_id);
 	
 	if (item == NULL) {
 		Message(0, "No such item: %i", item_id);
+
+		Message(4, "SumIt->Exit(Item[Null]->SummonCancelled->InvalidItemID[%u])", item_id);
+
 		return;
 	}
 	// Checking to see if the Item is lore or not.
@@ -217,73 +252,131 @@
 	if (!foundlore && !foundgm) { // Okay, It isn't LORE, or if it is, it is not in player's inventory.
 		ItemInst* inst = database.CreateItem(item, charges);
 		if (inst) {
+			Message(4, "SumIt->Process(Create[%s]->SetCharges[%i])", inst->GetItem()->Name, inst->GetCharges());
+
 			// Custom logic for SummonItem
-			if ((inst->GetCharges()==0))// && inst->IsStackable())
+			if ((inst->GetCharges()==0)) { // && inst->IsStackable())
+				Message(4, "SumIt->Process(SetCharges[%s]->Charges[1])", inst->GetItem()->Name);
+				
 				inst->SetCharges(1);
-			if ((inst->GetCharges()>0))
+			}
+
+			if ((inst->GetCharges()>0)) {
+				Message(4, "SumIt->Process(SetCharges[%s]->GetCharges[%i])", inst->GetItem()->Name, inst->GetCharges());
+
 				inst->SetCharges(inst->GetCharges());
+			}
+
 			if (aug1) {
+				Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[1]->AddRequest)", inst->GetItem()->Name);
+
 				const Item_Struct* augitem1 = database.GetItem(aug1);
 				if (augitem1) {
+					Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[1]->AugmentationFound[%s])", inst->GetItem()->Name, augitem1->Name);
+
 					if (!CheckLoreConflict(augitem1)) {
+						Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[1]->AddingAugmentation[%s])", inst->GetItem()->Name, augitem1->Name);
+
 						inst->PutAugment(&database, 0, aug1);
 					}
 					else {
 						Message(0, "You already have a %s (%i) in your inventory!", item->Name, item_id);
+
+						Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[1]->DuplicateLoreItem->Augmentation[%s])", inst->GetItem()->Name, augitem1->Name);
 					}
 				}
 			}
 			if (aug2) {
+				Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[2]->AddRequest)", inst->GetItem()->Name);
+
 				const Item_Struct* augitem2 = database.GetItem(aug2);
 				if (augitem2) {
+					Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[2]->AugmentationFound[%s])", inst->GetItem()->Name, augitem2->Name);
+
 					if (!CheckLoreConflict(augitem2)) {
+						Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[2]->AddingAugmentation[%s])", inst->GetItem()->Name, augitem2->Name);
+
 						inst->PutAugment(&database, 1, aug2);
 					}
 					else {
 						Message(0, "You already have a %s (%i) in your inventory!", item->Name, item_id);
+
+						Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[2]->DuplicateLoreItem->Augmentation[%s])", inst->GetItem()->Name, augitem2->Name);
 					}
 				}
 			}
 			if (aug3) {
+				Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[3]->AddRequest)", inst->GetItem()->Name);
+
 				const Item_Struct* augitem3 = database.GetItem(aug3);
 				if (augitem3) {
+					Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[3]->AugmentationFound[%s])", inst->GetItem()->Name, augitem3->Name);
+
 					if (!CheckLoreConflict(augitem3)) {
+						Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[3]->AddingAugmentation[%s])", inst->GetItem()->Name, augitem3->Name);
+
 						inst->PutAugment(&database, 2, aug3);
 					}
 					else {
 						Message(0, "You already have a %s (%i) in your inventory!", item->Name, item_id);
+
+						Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[3]->DuplicateLoreItem->Augmentation[%s])", inst->GetItem()->Name, augitem3->Name);
 					}
 				}
 			}
 			if (aug4) {
+				Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[4]->AddRequest)", inst->GetItem()->Name);
+
 				const Item_Struct* augitem4 = database.GetItem(aug4);
 				if (augitem4) {
+					Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[4]->AugmentationFound[%s])", inst->GetItem()->Name, augitem4->Name);
+
 					if (!CheckLoreConflict(augitem4)) {
+						Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[4]->AddingAugmentation[%s])", inst->GetItem()->Name, augitem4->Name);
+
 						inst->PutAugment(&database, 3, aug4);
 					}
 					else {
 						Message(0, "You already have a %s (%i) in your inventory!", item->Name, item_id);
+
+						Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[4]->DuplicateLoreItem->Augmentation[%s])", inst->GetItem()->Name, augitem4->Name);
 					}
 				}
 			}
 			if (aug5) {
+				Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[5]->AddRequest)", inst->GetItem()->Name);
+
 				const Item_Struct* augitem5 = database.GetItem(aug5);
 				if (augitem5) {
+					Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[5]->AugmentationFound[%s])", inst->GetItem()->Name, augitem5->Name);
+
 					if (!CheckLoreConflict(augitem5)) {
+						Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[5]->AddingAugmentation[%s])", inst->GetItem()->Name, augitem5->Name);
+
 						inst->PutAugment(&database, 4, aug5);
 					}
 					else {
 						Message(0, "You already have a %s (%i) in your inventory!", item->Name, item_id);
+
+						Message(4, "SumIt->Process(Item[%s]->AugmentationSlot[5]->DuplicateLoreItem->Augmentation[%s])", inst->GetItem()->Name, augitem5->Name);
 					}
 				}
 			}
+
 			if (attuned) {
+				Message(4, "SumIt->Process(Attuned[True])");
+
 				if (inst->GetItem()->Attuneable) {
+					Message(4, "SumIt->Process(Attuned->SetNoDrop[True])");
+
 					inst->SetInstNoDrop(true);
 				}
 			}
+
 			if (to_slot == SLOT_CURSOR)
 			{
+				Message(4, "SumIt->Process(PushToCursor[%s]->Charges[%i])", inst->GetItem()->Name, inst->GetCharges());
+
 				//inst->SetCharges(
 				PushItemOnCursor(*inst);
 				// Send item packet to user
@@ -291,33 +384,50 @@
 			}
 			else
 			{
+				Message(4, "SumIt->Process(PutItemInInventory[%s]->ToSlot[%u]->Charges[%i])", inst->GetItem()->Name, to_slot, inst->GetCharges());
+
 				PutItemInInventory(to_slot, *inst, true);
 			}
 			safe_delete(inst);
 
 			if ((RuleB(Character, EnableDiscoveredItems)))
 			{
-				if(!GetGM() && !IsDiscovered(item_id))
-				DiscoverItem(item_id);
+				Message(4, "SumIt->Process(ItemDiscovery[Enabled])");
+
+				if(!GetGM() && !IsDiscovered(item_id)) {
+					Message(4, "SumIt->Process(Player[%s]->DiscoverItem[%s])", GetName(), database.GetItem(item_id)->Name);
+
+					DiscoverItem(item_id);
+				}
 			}
 		}
 	}
 	else { // Item was already in inventory & is a LORE item or was a GM only item.  Give them a message about it.
 		if (foundlore){
 			Message_StringID(0,PICK_LORE);
+
+			Message(4, "SumIt->Process(DuplicateLoreItem[%s]->SummonCancelled)", database.GetItem(item_id)->Name);
 			//Message(0, "You already have a %s (%i) in your inventory!", item->Name, item_id);
 		}
-		else if (foundgm)
+		else if (foundgm) {
 			Message(0, "You are not a GM to summon this item");
+
+			Message(4, "SumIt->Process(GMOnlyItem[%s]->SummonCancelled)", database.GetItem(item_id)->Name);
+		}
 	}
+	Message(4, "SumIt->Exit");
 }
 
 // Drop item from inventory to ground (generally only dropped from SLOT_CURSOR)
 void Client::DropItem(sint16 slot_id)
 {
+	Message(4, "DropIt->Entry");
 
 	if (GetInv().CheckNoDrop(slot_id) && RuleI(World, FVNoDropFlag) == 0 || RuleI(Character, MinStatusForNoDropExemptions) < Admin() && RuleI(World, FVNoDropFlag) == 2) {
 		//Message(0, "No Drop Exploit: Items Destroyed.");
+
+		Message(4, "DropIt->Exit(NoDropExploit[%s]->Slot[%i]->Delete)", GetInv().GetItem(slot_id)->GetItem()->Name, slot_id);
+
 		database.SetHackerFlag(this->AccountName(), this->GetCleanName(), "Tried to drop an item on the ground that was nodrop!");
 		GetInv().DeleteItem(slot_id);
 		return;
@@ -329,15 +439,24 @@
 	if (!inst) {
 		// Item doesn't exist in inventory!
 		Message(13, "Error: Item not found in slot %i", slot_id);
+
+		Message(4, "DropIt->Exit(Item[Null]->Slot[%i])", slot_id);
+
 		return;
 	}
 	
 	// Save client inventory change to database
 	if (slot_id==SLOT_CURSOR) {
+		Message(4, "DropIt->Process(SaveCursor[Null])");
+
 		list<ItemInst*>::const_iterator s=m_inv.cursor_begin(),e=m_inv.cursor_end();
 		database.SaveCursor(CharacterID(), s, e);
-	} else
+	}
+	else {
+		Message(4, "DropIt->Process(SaveInventory[Null]->Slot[%i])", slot_id);
+
 		database.SaveInventory(CharacterID(), NULL, slot_id);
+	}
 
 	// Package as zone object
 	Object* object = new Object(this, inst);
@@ -345,14 +464,21 @@
 	object->StartDecay();
 	
 	safe_delete(inst);
+
+	Message(4, "DropIt->Exit");
 }
 
 // Drop inst
 void Client::DropInst(const ItemInst* inst)
 {
+	Message(4, "DropInst->Entry(ItemID[%u])", inst?inst->GetItem()->ID:0);
+
 	if (!inst) {
 		// Item doesn't exist in inventory!
 		Message(13, "Error: Item not found");
+
+		Message(4, "DropInst->Exit(Item[Null])");
+
 		return;
 	}
 
@@ -360,6 +486,9 @@
 	if (inst->GetItem()->NoDrop == 0)
 	{
 		Message(13, "This item is NODROP. Deleting.");
+
+		Message(4, "DropInst->Exit(NoDropItem[%s]->Delete)", inst->GetItem()->Name);
+
 		return;
 	}
 
@@ -367,37 +496,62 @@
 	Object* object = new Object(this, inst);
 	entity_list.AddObject(object, true);
 	object->StartDecay();
+
+	Message(4, "DropInst->Exit");
 }
 
 // Returns a slot's item ID (returns INVALID_ID if not found)
 uint32 Client::GetItemIDAt(sint16 slot_id) {
+	// Something is calling this function every 8 seconds in-game. Debug is remarked out to avoid spamming
+	//Message(4, "GetItIDAt->Entry");
+
 	const ItemInst* inst = m_inv[slot_id];
-	if (inst)
+	if (inst) {
+		//Message(4, "GetItIDAt->Exit(Item[%s]->ItemID[%u]->Slot[%i])", inst->GetItem()->Name, inst->GetItem()->ID, slot_id);
+
 		return inst->GetItem()->ID;
-	
+	}
 	// None found
+	//Message(4, "GetItIDAt->Exit(Item[Null]->Slot[%i])", slot_id);
+
 	return INVALID_ID;
 }
 
 // Returns an augment's ID that's in an item (returns INVALID_ID if not found)
 // Pass in the slot ID of the item and which augslot you want to check (0-4)
 uint32 Client::GetAugmentIDAt(sint16 slot_id, uint8 augslot) {
+	Message(4, "GetAugIDAt->Entry");
+
 	const ItemInst* inst = m_inv[slot_id];
-	if (inst)
-		if (inst->GetAugmentItemID(augslot))
+	if (inst) {
+		if (inst->GetAugmentItemID(augslot)) {
+			Message(4, "GetAugIDAt->Exit(Augmentation[%s]->AugID[%u]->Slot[%i]->AugSlot[%i])", inst->GetAugment(augslot)->GetItem()->Name, inst->GetAugmentItemID(augslot), slot_id, augslot);
+
 			return inst->GetAugmentItemID(augslot);
+		}
+		else {
+			Message(4, "GetAugIDAt->Exit(Augmentation[Null]->Slot[%i]->AugSlot[%i])", slot_id, augslot);
 
+			return INVALID_ID;
+		}
+	}
 	// None found
+	Message(4, "GetAugIDAt->Exit(Item[Null]->Slot[%i])", slot_id);
+
 	return INVALID_ID;
 }
 
 // Remove item from inventory
 void Client::DeleteItemInInventory(sint16 slot_id, sint8 quantity, bool client_update, bool update_db) {
+	Message(4, "DelItInInv->Entry");
+
 	#if (EQDEBUG >= 5)
 		LogFile->write(EQEMuLog::Debug, "DeleteItemInInventory(%i, %i, %s)", slot_id, quantity, (client_update) ? "true":"false");
 	#endif
 
 	if(!m_inv[slot_id]) {
+		Message(4, "DelItInInv->Process(EmptySlot->ClientDelete->Slot[%i])", slot_id);
+
 		// Make sure the client deletes anything in this slot to match the server.
 		if(client_update) {
 			EQApplicationPacket* outapp;
@@ -416,26 +570,42 @@
 
 	const ItemInst* inst=NULL;
 	if (slot_id==SLOT_CURSOR) {
+		Message(4, "DelItInInv->Process(CursorDelete)");
+
 		list<ItemInst*>::const_iterator s=m_inv.cursor_begin(),e=m_inv.cursor_end();
-        if(update_db)
+        if(update_db) {
+			Message(4, "DelItInInv->Process(CursorDelete->UpdateDatabase)");
+
 		    database.SaveCursor(character_id, s, e);
+		}
 	}
 	else {
+		Message(4, "DelItInInv->Process(InventoryDelete->Slot[%i])", slot_id);
+
 		// Save change to database
 		inst = m_inv[slot_id];
-        if(update_db)
+        if(update_db) {
+			Message(4, "DelItInInv->Process(InventoryDelete->Slot[%i]->UpdateDatabase)", slot_id);
+
 		    database.SaveInventory(character_id, inst, slot_id);
+		}
 	}
 
 	if(client_update) {
 		EQApplicationPacket* outapp;
 		if(inst) {
-			if(!inst->IsStackable() && !isDeleted) 
+			if(!inst->IsStackable() && !isDeleted) {
+				Message(4, "DelItInInv->Process(Client->ChargeItem->DeleteCharge[%s])", inst->GetItem()->Name);
+
 				// Non stackable item with charges = Item with clicky spell effect ? Delete a charge.
 				outapp = new EQApplicationPacket(OP_DeleteCharge, sizeof(MoveItem_Struct));
-			else
+			}
+			else {
+				Message(4, "DelItInInv->Process(Client->StackableItem->DeleteItem[%s])", inst->GetItem()->Name);
+
 				// Stackable, arrows, etc ? Delete one from the stack
 				outapp = new EQApplicationPacket(OP_DeleteItem, sizeof(MoveItem_Struct));
+			}
 
 			DeleteItem_Struct* delitem	= (DeleteItem_Struct*)outapp->pBuffer;
 			delitem->from_slot			= slot_id;
@@ -446,6 +616,8 @@
 			safe_delete(outapp);
 		}
 		else {
+			Message(4, "DelItInInv->Process(Client->DeleteItem->Slot[%i])", slot_id);
+
 			outapp = new EQApplicationPacket(OP_MoveItem, sizeof(MoveItem_Struct));
 			MoveItem_Struct* delitem	= (MoveItem_Struct*)outapp->pBuffer;
 			delitem->from_slot			= slot_id;
@@ -455,7 +627,7 @@
 			safe_delete(outapp);
 		}
 	}
-
+	Message(4, "DelItInInv->Exit");
 }
 
 // Puts an item into the person's inventory
@@ -464,55 +636,91 @@
 // client_update: Sends packet to client
 bool Client::PushItemOnCursor(const ItemInst& inst, bool client_update)
 {
+	Message(4, "PushItOnCur->Entry(ItemID[%u])", inst?inst.GetItem()->ID:0);
+	Message(4, "PushItOnCur->Process(PushToCursor[%s])", inst?inst.GetItem()->Name:0);
+
 	mlog(INVENTORY__SLOTS, "Putting item %s (%d) on the cursor", inst.GetItem()->Name, inst.GetItem()->ID);
 	m_inv.PushCursor(inst);
 	
 	if (client_update) {
+		Message(4, "PushItOnCur->Process(ClientUpdate->PushToCursor[%s])", inst?inst.GetItem()->Name:"Null");
+
 		SendItemPacket(SLOT_CURSOR, &inst, ItemPacketSummonItem);
 	}
 	
 	list<ItemInst*>::const_iterator s=m_inv.cursor_begin(),e=m_inv.cursor_end();
+
+	Message(4, "PushItOnCur->Exit(SaveCursor[%s])", inst?inst.GetItem()->Name:"Null");
+
 	return database.SaveCursor(CharacterID(), s, e);
 }
 
 bool Client::PutItemInInventory(sint16 slot_id, const ItemInst& inst, bool client_update)
 {
+	// No code to handle inst=null
+	Message(4, "PutItInInv->Entry(ItemID[%u])", inst?inst.GetItem()->ID:0);
+
 	mlog(INVENTORY__SLOTS, "Putting item %s (%d) into slot %d", inst.GetItem()->Name, inst.GetItem()->ID, slot_id);
 	if (slot_id==SLOT_CURSOR) 
 	{
+		Message(4, "PutItInInv->Exit(PushToCursor[%s])", inst?inst.GetItem()->Name:"Null");
+
 		return PushItemOnCursor(inst,client_update);
 	}
-	else
+	else {
+		Message(4, "PutItInInv->Process(PutItemInInventory[%s]->Slot[%i])", inst?inst.GetItem()->Name:"Null", slot_id);
+
 		m_inv.PutItem(slot_id, inst);
+	}
 	
 	if (client_update) {
+		Message(4, "PutItInInv->Process(ClientUpdate->PutItemInInventory[%s]->Slot[%i])", inst?inst.GetItem()->Name:"Null", slot_id);
+
 		SendItemPacket(slot_id, &inst, (slot_id==SLOT_CURSOR)?ItemPacketSummonItem:ItemPacketTrade);
 	}
 	
-	if (slot_id==SLOT_CURSOR) {
+	if (slot_id==SLOT_CURSOR) { // This code is NOT needed and never processed here..duplicate of PushItemOnCursor->called in first con check
+		Message(4, "PutItInInv->Exit(SaveCursor[%s])", inst?inst.GetItem()->Name:"Null");
+
 		list<ItemInst*>::const_iterator s=m_inv.cursor_begin(),e=m_inv.cursor_end();
 		return database.SaveCursor(this->CharacterID(), s, e);
-	} else
+	}
+	else { // This is the code that is always executed if (slot_id != SLOT_CURSOR)
+		Message(4, "PutItInInv->Exit(SaveInventory[%s]->Slot[%i])", inst?inst.GetItem()->Name:"Null", slot_id);
+
 		return database.SaveInventory(this->CharacterID(), &inst, slot_id);
-	
+	}
+	// How do we ever calc these bonuses with the above 'return's!?
 	CalcBonuses();
+
+	Message(4, "PutItInInv->Exit(LET ME KNOW IF YOU EVER SEE THIS MESSAGE! - ULEAT");
 }
 
 void Client::PutLootInInventory(sint16 slot_id, const ItemInst &inst, ServerLootItem_Struct** bag_item_data)
 {
+	Message(4, "PutLootInInv->Entry(ItemID[%u])", inst?inst.GetItem()->ID:0);
+
 	mlog(INVENTORY__SLOTS, "Putting loot item %s (%d) into slot %d", inst.GetItem()->Name, inst.GetItem()->ID, slot_id);
 	m_inv.PutItem(slot_id, inst);
 	
 	SendLootItemInPacket(&inst, slot_id);
 	
 	if (slot_id==SLOT_CURSOR) {
+		Message(4, "PutLootInInv->Process(SaveCursor[%s])", inst?inst.GetItem()->Name:"Null");
+
 		list<ItemInst*>::const_iterator s=m_inv.cursor_begin(),e=m_inv.cursor_end();
 		database.SaveCursor(this->CharacterID(), s, e);
-	} else
+	}
+	else {
+		Message(4, "PutLootInInv->Process(SaveInventory[%s]->Slot[%i])", inst?inst.GetItem()->Name:"Null", slot_id);
+
 		database.SaveInventory(this->CharacterID(), &inst, slot_id);
+	}
 
 	if(bag_item_data)	// bag contents
 	{
+		Message(4, "PutLootInInv->Process(BagLoad)");
+
 		sint16 interior_slot;
 		// solar: our bag went into slot_id, now let's pack the contents in
 		for(int i = 0; i < 10; i++)
@@ -522,22 +730,39 @@
 			const ItemInst *bagitem = database.CreateItem(bag_item_data[i]->item_id, bag_item_data[i]->charges, bag_item_data[i]->aug1, bag_item_data[i]->aug2, bag_item_data[i]->aug3, bag_item_data[i]->aug4, bag_item_data[i]->aug5);
 			interior_slot = Inventory::CalcSlotId(slot_id, i);
 			mlog(INVENTORY__SLOTS, "Putting bag loot item %s (%d) into slot %d (bag slot %d)", inst.GetItem()->Name, inst.GetItem()->ID, interior_slot, i);
+			
+			Message(4, "PutLootInInv->Process(PutLootItem[%s]->InteriorSlot[%i]->InSlot[%i])", inst?inst.GetItem()->Name:"Null", interior_slot, i);
+			
 			PutLootInInventory(interior_slot, *bagitem);
 			safe_delete(bagitem);
 		}
 	}
 	
 	CalcBonuses();
+
+	Message(4, "PutLootInInv->Exit");
 }
 bool Client::TryStacking(ItemInst* item, int8 type, bool try_worn, bool try_cursor){
-	if(!item || !item->IsStackable() || item->GetCharges()>=item->GetItem()->StackSize)
+	Message(4, "TryStac->Entry(ItemID[%u])", item?item->GetItem()->ID:0);
+
+	if(!item || !item->IsStackable() || item->GetCharges()>=item->GetItem()->StackSize) {
+		if(!item){
+			Message(4, "TryStac->Exit(Item[Null])");
+		} else {
+			Message(4, "TryStac->Exit(Item[%s]->IsStackable[%s]->StackSize[%i]->Charges[%i])", item->GetItem()->Name, item->IsStackable()?"True":"False", item->GetItem()->StackSize, item->GetCharges());
+		}
+
 		return false;
+	}
+
 	sint16 i;
 	int32 item_id = item->GetItem()->ID;
 	for (i = 22; i <= 29; i++)
 	{
 		ItemInst* tmp_inst = m_inv.GetItem(i);	
 		if(tmp_inst && tmp_inst->GetItem()->ID == item_id && tmp_inst->GetCharges() < tmp_inst->GetItem()->StackSize){
+			Message(4, "TryStac->Process(InvSlot[%i]->MoveCharges->ChargeCount[%i])", i, tmp_inst->GetCharges());
+
 			MoveItemCharges(*item, i, type);
 			CalcBonuses();
 			if(item->GetCharges())	// we didn't get them all
@@ -553,6 +778,8 @@
 			ItemInst* tmp_inst = m_inv.GetItem(slotid);
 
 			if(tmp_inst && tmp_inst->GetItem()->ID == item_id && tmp_inst->GetCharges() < tmp_inst->GetItem()->StackSize){
+				Message(4, "TryStac->Process(InvSlot[%i]->BagSlot[%u]->MoveCharges->ChargeCount[%i])", i, j, tmp_inst->GetCharges());
+
 				MoveItemCharges(*item, slotid, type);
 				CalcBonuses();
 				if(item->GetCharges())	// we didn't get them all
@@ -561,6 +788,8 @@
 			}
 		}
 	}
+	Message(4, "TryStac->Exit");
+
 	return false;
 }
 // Locate an available space in inventory to place an item
@@ -568,6 +797,8 @@
 // The change will be saved to the database
 bool Client::AutoPutLootInInventory(ItemInst& inst, bool try_worn, bool try_cursor, ServerLootItem_Struct** bag_item_data)
 {
+	Message(4, "AutoPutLootInInv->Entry(ItemID[%u])", inst?inst.GetItem()->ID:0);
+
 	// #1: Try to auto equip
 	if (try_worn && inst.IsEquipable(GetBaseRace(), GetClass()) && inst.GetItem()->ReqLevel<=level && !inst.GetItem()->Attuneable && inst.GetItem()->ItemType != ItemTypeAugment)
 	{
@@ -610,6 +841,8 @@
 					{
 						SendWearChange(worn_slot_material);
 					}
+					Message(4, "AutoPutLootInInv->Exit(AutoLoot[%s]->EquipSlot[%i])", inst.GetItem()->Name, i);
+
 					return true;
 				}
 			}
@@ -619,8 +852,11 @@
 	// #2: Stackable item?
 	if (inst.IsStackable())
 	{
-		if(TryStacking(&inst, ItemPacketTrade, try_worn, try_cursor))
+		if(TryStacking(&inst, ItemPacketTrade, try_worn, try_cursor)) {
+			Message(4, "AutoPutLootInInv->Exit(AutoLoot[%s]->AddedToExistingStack)", inst.GetItem()->Name);
+
 			return true;
+		}
 	}
 
 	// #3: put it in inventory
@@ -628,20 +864,27 @@
 	sint16 slot_id = m_inv.FindFreeSlot(inst.IsType(ItemClassContainer), try_cursor, inst.GetItem()->Size, is_arrow);
 	if (slot_id != SLOT_INVALID)
 	{
+		Message(4, "AutoPutLootInInv->Exit(AutoLoot[%s]->InvSlot[%i])", inst.GetItem()->Name, slot_id);
+
 		PutLootInInventory(slot_id, inst, bag_item_data);
 		return true;
 	}
-	
+	Message(4, "AutoPutLootInInv->Exit(AutoLoot[%s]->Failed)", inst.GetItem()->Name);
+
 	return false;
 }
 
 // solar: helper function for AutoPutLootInInventory
 void Client::MoveItemCharges(ItemInst &from, sint16 to_slot, int8 type)
 {
+	Message(4, "MoveItChrgs->Entry(ItemID[%u])", from?from.GetItem()->ID:0);
+
 	ItemInst *tmp_inst = m_inv.GetItem(to_slot);
 
 	if(tmp_inst && tmp_inst->GetCharges() < tmp_inst->GetItem()->StackSize)
 	{
+		Message(4, "MoveItChrgs->Process(Item[%s]->PartialStack[%i]->StackSize[%i])", tmp_inst?tmp_inst->GetItem()->Name:"Null", tmp_inst?tmp_inst->GetCharges():0, tmp_inst?tmp_inst->GetItem()->StackSize:0);
+
 		// this is how much room is left on the item we're stacking onto
 		int charge_slots_left = tmp_inst->GetItem()->StackSize - tmp_inst->GetCharges();
 		// this is how many charges we can move from the looted item to
@@ -655,14 +898,23 @@
 		from.SetCharges(from.GetCharges() - charges_to_move);
 		SendLootItemInPacket(tmp_inst, to_slot);
 		if (to_slot==SLOT_CURSOR){
+			Message(4, "MoveItChrgs->Process(CursorStack->AddAmount[%i])", charges_to_move);
+
 			list<ItemInst*>::const_iterator s=m_inv.cursor_begin(),e=m_inv.cursor_end();
 			database.SaveCursor(this->CharacterID(), s, e);
-		} else
+		}
+		else {
+			Message(4, "MoveItChrgs->Process(InventoryStack->Slot[%i]->AddAmount[%i])", to_slot, charges_to_move);
+
 			database.SaveInventory(this->CharacterID(), tmp_inst, to_slot);
+		}
 	}
+	Message(4, "MoveItChrgs->Exit");
 }
 
 bool Client::MakeItemLink(char* &ret_link, const ItemInst *inst) {
+	Message(4, "MakeItLink->Entry(ItemID[%u])", inst?inst->GetItem()->ID:0);
+
 	//we're sending back the entire "link", minus the null characters & item name
 	//that way, we can use it for regular links & Task links
 	//note: initiator needs to pass us ret_link
@@ -675,8 +927,11 @@
 		http://eqitems.13th-floor.org/phpBB2/viewtopic.php?p=510#510
 */
 	
-	if (!inst) //have to have an item to make the link
+	if (!inst) { //have to have an item to make the link
+		Message(4, "MakeItLink->Exit(Item[Null])");
+		
 		return false;
+	}
 
 	const Item_Struct* item = inst->GetItem();
 	//format:
@@ -692,6 +947,8 @@
 	//int hash = GetItemLinkHash(inst);	//eventually this will work (currently crashes zone), but for now we'll skip the extra overhead
 	if (GetClientVersion() >= EQClientSoF)
 	{
+		Message(4, "MakeItLink->Process(MakeLink[%s]->Client->SoF)", inst->GetItem()->Name);
+
 		MakeAnyLenString(&ret_link, "%1X" "%05X" "%05X" "%05X" "%05X" "%05X" "%05X" "%1X" "%04X" "%1X" "%05X" "%08X", 
 			0,
 			item->ID, 
@@ -709,6 +966,8 @@
 	}
 	else
 	{
+		Message(4, "MakeItLink->Process(MakeLink[%s]->Client->Titanium)", inst->GetItem()->Name);
+
 		MakeAnyLenString(&ret_link, "%1X" "%05X" "%05X" "%05X" "%05X" "%05X" "%05X" "%1X" "%04X" "%1X" "%08X", 
 			0,
 			item->ID, 
@@ -723,15 +982,21 @@
 			hash
 		);
 	}
+	Message(4, "MakeItLink->Exit");
 
 	return true;
 }
 
 int Client::GetItemLinkHash(const ItemInst* inst) {
+	Message(4, "GetItLinkHash->Entry(ItemID[%u])", inst?inst->GetItem()->Name:"Null");
+
 	//pre-Titanium: http://eqitems.13th-floor.org/phpBB2/viewtopic.php?t=70&postdays=0&postorder=asc
 	//Titanium: http://eqitems.13th-floor.org/phpBB2/viewtopic.php?t=145
-	if (!inst)	//have to have an item to make the hash
+	if (!inst) {	//have to have an item to make the hash
+		Message(4, "GetItLinkHash->Exit(NullItem)");
+		
 		return 0;
+	}
 	
 	const Item_Struct* item = inst->GetItem();
 	char* hash_str = 0;
@@ -739,6 +1004,8 @@
 
 	//now the fun part, since different types of items use different hashes...
 	if (item->ItemClass == 0 && item->CharmFileID) {	//charm
+		Message(4, "GetItLinkHash->Process(GetLink->Charm[%s])", item->Name);
+		
 		MakeAnyLenString(&hash_str, "%d%s-1-1-1-1-1%d %d %d %d %d %d %d %d %d",
 			item->ID,
 			item->Name,
@@ -752,6 +1019,8 @@
 			item->Favor,
 			item->GuildFavor);
 	} else if (item->ItemClass == 2) {	//book
+		Message(4, "GetItLinkHash->Process(GetLink->Book[%s])", item->Name);
+		
 		MakeAnyLenString(&hash_str, "%d%s%d%d%09X",
 			item->ID,
 			item->Name,
@@ -759,6 +1028,8 @@
 			item->BookType,
 			item->Price);
 	} else if (item->ItemClass == 1) {	//bag
+		Message(4, "GetItLinkHash->Process(GetLink->Bag[%s])", item->Name);
+		
 		MakeAnyLenString(&hash_str, "%d%s%x%d%09X%d",
 			item->ID,
 			item->Name,
@@ -767,6 +1038,8 @@
 			item->Price,
 			item->Weight);
 	} else {	//everything else
+		Message(4, "GetItLinkHash->Process(GetLink->Item[%s])", item->Name);
+		
 		MakeAnyLenString(&hash_str, "%d%s-1-1-1-1-1%d %d %d %d %d %d %d %d %d %d %d %d %d",
 			item->ID,
 			item->Name,
@@ -811,20 +1084,27 @@
 	}
 	*/
 
+	Message(4, "GetItLinkHash->Exit");
+
 	safe_delete_array(hash_str);
 	return hash;
 }
 
 void Client::SendItemLink(const ItemInst* inst, bool send_to_all)
 {
+	Message(4, "SentItLink->Entry(ItemID[%u])", inst?inst->GetItem()->ID:0);
+
 /*
 
 this stuff is old, live dosent do this anymore. they send a much smaller
 packet with the item number in it, but I cant seem to find it right now
 
 */
-	if (!inst)
+	if (!inst) {
+		Message(4, "SentItLink->Exit(NullItem)");
+
 		return;
+	}
 	
 	const Item_Struct* item = inst->GetItem();
 	const char* name2 = &item->Name[0];
@@ -844,8 +1124,16 @@
 	memcpy(outapp->pBuffer,buffer2,outapp->size);
 	QueuePacket(outapp);
 	safe_delete(outapp);
-	if (send_to_all==false)
+
+	if (send_to_all==false) {
+		Message(4, "SentItLink->Exit(SendToAll[False])");
+
 		return;
+	}
+	else {
+		Message(4, "SentItLink->Process(SendToAll[True])");
+	}
+
 	const char* charname = this->GetName();
 	outapp = new EQApplicationPacket(OP_ItemLinkText,strlen(itemlink)+14+strlen(charname));
 	char buffer3[150] = {0};
@@ -853,15 +1141,23 @@
 	memcpy(outapp->pBuffer,buffer3,outapp->size);
 	entity_list.QueueCloseClients(this->CastToMob(),outapp,true,200,0,false);
 	safe_delete(outapp);
+
+	Message(4, "SentItLink->Exit");
 }
 
 void Client::SendLootItemInPacket(const ItemInst* inst, sint16 slot_id)
 {
+	Message(4, "SendLootItInPack->Entry(ItemID[%u])", inst?inst->GetItem()->ID:0);
+
 	SendItemPacket(slot_id,inst, ItemPacketTrade);
+
+	Message(4, "SendLootItInPack->Exit(ClientUpdate->SendItem[%s])", inst?inst->GetItem()->Name:"Null");
 }
 
 bool Client::IsValidSlot(uint32 slot)
 {
+	Message(4, "IsValSlot->Entry");
+
 	if((slot == (uint32)SLOT_INVALID) ||	// Destroying/Dropping item
 		(slot >= 0 && slot <= 30) ||		// Worn inventory, normal inventory, and cursor
 		(slot >= 251 && slot <= 340) ||		// Normal inventory bags and cursor bag
@@ -874,22 +1170,31 @@
 		(slot >= 4000 && slot <= 4009) ||	// Tradeskill container
 		(slot == 9999))						// Power Source
 	{
+		Message(4, "IsValSlot->Exit(ValidSlot[%u])", slot);
+
 		return true;
 	}
 	else {
+		Message(4, "IsValSlot->Exit(InvalidSlot[%u])", slot);
+
 		return false;
 	}
 }
 
 bool Client::IsBankSlot(uint32 slot)
 {
+	Message(4, "IsBankSlot->Entry");
+
 	if((slot >= 2000 && slot <= 2023) || // Bank
 	   (slot >= 2031 && slot <= 2270) || // Bank bags
 	   (slot >= 2500 && slot <= 2501) || // Shared bank
 	   (slot >= 2531 && slot <= 2550))   // Shared bank bags
 	{
+		Message(4, "IsBankSlot->Exit(ValidBankSlot[%u])", slot);
+
 		return true;
 	}
+	Message(4, "IsBankSlot->Exit(InvalidBankSlot[%u])", slot);
 
 	return false;
 }
@@ -897,6 +1202,7 @@
 // Moves items around both internally and in the database
 // In the future, this can be optimized by pushing all changes through one database REPLACE call
 bool Client::SwapItem(MoveItem_Struct* move_in) {
+	Message(4, "SwapIt->Entry");
 
 	uint32 src_slot_check = move_in->from_slot;
 	uint32 dst_slot_check = move_in->to_slot;
@@ -907,6 +1213,9 @@
 		if(src_slot_check < 2147483647)
 			Message(13, "Warning: Invalid slot move from slot %u to slot %u with %u charges!", src_slot_check, dst_slot_check, stack_count_check);
 		mlog(INVENTORY__SLOTS, "Invalid slot move from slot %u to slot %u with %u charges!", src_slot_check, dst_slot_check, stack_count_check);
+		
+		Message(4, "SwapIt->Exit(SRCSlotCheck->SRCSlotCheck[%u]->DSTSlotCheck[%u]->StackCountCheck[%u])", src_slot_check, dst_slot_check, stack_count_check);
+		
 		return false;
 	}
 
@@ -915,28 +1224,48 @@
 		if(src_slot_check < 2147483647)
 			Message(13, "Warning: Invalid slot move from slot %u to slot %u with %u charges!", src_slot_check, dst_slot_check, stack_count_check);
 		mlog(INVENTORY__SLOTS, "Invalid slot move from slot %u to slot %u with %u charges!", src_slot_check, dst_slot_check, stack_count_check);
+		
+		Message(4, "SwapIt->Exit(DSTSlotCheck->SRCSlotCheck[%u]->DSTSlotCheck[%u]->StackCountCheck[%u])", src_slot_check, dst_slot_check, stack_count_check);
+		
 		return false;
 	}
 
-	if (move_in->from_slot == move_in->to_slot)
+	if (move_in->from_slot == move_in->to_slot) {
+		Message(4, "SwapIt->Exit(SummonItem->Slot[%u]->StackCount[%u])", move_in->from_slot, move_in->number_in_stack);
+
 		return true; // Item summon, no further proccessing needed
+	}
 	
 	if (move_in->to_slot == (uint32)SLOT_INVALID) {
 		if(move_in->from_slot == (uint32)SLOT_CURSOR) {
 			mlog(INVENTORY__SLOTS, "Client destroyed item from cursor slot %d", move_in->from_slot);
+			
+			Message(4, "SwapIt->Exit(ClientAction->DeleteItem->Cursor[%u])", move_in->from_slot);
+			
 			DeleteItemInInventory(move_in->from_slot);
 			return true; // Item destroyed by client
 		}
 		else {
 			mlog(INVENTORY__SLOTS, "Deleted item from slot %d as a result of an inventory container tradeskill combine.", move_in->from_slot);
+			
+			Message(4, "SwapIt->Exit(TradeskillAction->DeleteItem->Slot[%u])", move_in->from_slot);
+			
 			DeleteItemInInventory(move_in->from_slot);
 			return true; // Item deletetion
 		}
 	}
-	if(auto_attack && (move_in->from_slot == SLOT_PRIMARY || move_in->from_slot == SLOT_SECONDARY || move_in->from_slot == SLOT_RANGE))
+
+	if(auto_attack && (move_in->from_slot == SLOT_PRIMARY || move_in->from_slot == SLOT_SECONDARY || move_in->from_slot == SLOT_RANGE)) {
+		Message(4, "SwapIt->Process(SwapWeapon->FromSlot[%u]->StartTimer)", move_in->from_slot);
+		
 		SetAttackTimer();
-	else if(auto_attack && (move_in->to_slot == SLOT_PRIMARY || move_in->to_slot == SLOT_SECONDARY || move_in->to_slot == SLOT_RANGE))
+	}
+	else if(auto_attack && (move_in->to_slot == SLOT_PRIMARY || move_in->to_slot == SLOT_SECONDARY || move_in->to_slot == SLOT_RANGE)) {
+		Message(4, "SwapIt->Process(SwapWeapon->ToSlot[%u]->StartTimer)", move_in->to_slot);
+		
 		SetAttackTimer();
+	}
+
 	// Step 1: Variables
 	sint16 src_slot_id = (sint16)move_in->from_slot;
 	sint16 dst_slot_id = (sint16)move_in->to_slot;
@@ -946,6 +1275,8 @@
 		IsBankSlot(src_slot_check) ||
 		IsBankSlot(dst_slot_check))
 	{
+		Message(4, "SwapIt->Process(BankerCheck)");
+
 		uint32 distance = 0;
 		NPC *banker = entity_list.GetClosestBanker(this, distance);
 
@@ -969,18 +1300,29 @@
 	if (src_inst){
 		mlog(INVENTORY__SLOTS, "Src slot %d has item %s (%d) with %d charges in it.", src_slot_id, src_inst->GetItem()->Name, src_inst->GetItem()->ID, src_inst->GetCharges());
 		srcitemid = src_inst->GetItem()->ID;
+		
+		Message(4, "SwapIt->Process(SRCItem[%s]->SRCItemIDAssignment[%u])", src_inst?src_inst->GetItem()->Name:"Null", srcitemid);
+		
 		//SetTint(dst_slot_id,src_inst->GetColor());
 		if (src_inst->GetCharges() > 0 && (src_inst->GetCharges() < (sint16)move_in->number_in_stack || move_in->number_in_stack > src_inst->GetItem()->StackSize))
 		{
 			Message(13,"Error: Insufficent number in stack.");
+
+			Message(4, "SwapIt->Exit(SRCItem[%s]->SRCCharges[%i]->MIStackCount[%u]->SRCStackSize[%i]->ERROR)", src_inst?src_inst->GetItem()->Name:"Null", src_inst?src_inst->GetCharges():-1, move_in?move_in->number_in_stack:-1, src_inst?src_inst->GetItem()->StackSize:-1);
+
 			return false;
 		}
 	}
 	if (dst_inst) {
 		mlog(INVENTORY__SLOTS, "Dest slot %d has item %s (%d) with %d charges in it.", dst_slot_id, dst_inst->GetItem()->Name, dst_inst->GetItem()->ID, dst_inst->GetCharges());
 		dstitemid = dst_inst->GetItem()->ID;
+
+		Message(4, "SwapIt->Process(DSTItem[%s]->DSTItemIDAssignment[%u])", dst_inst?dst_inst->GetItem()->Name:"Null", dstitemid);
 	}
+
 	if (Trader && srcitemid>0){
+		Message(4, "SwapIt->Process(TraderSatchelCheck)");
+
 		ItemInst* srcbag;
 		ItemInst* dstbag;
 		uint32 srcbagid =0;
@@ -1005,12 +1347,16 @@
 	// After this, we can assume src_inst is a valid ptr
 	if (!src_inst && (src_slot_id<4000 || src_slot_id>4009)) {
 		if (dst_inst) {
+			Message(4, "SwapIt->Process(InvalidSourceItem[Null]->DSTItem[%s]->Delete", dst_inst?dst_inst->GetItem()->Name:"Null");
 			// If there is no source item, but there is a destination item, 
 			// move the slots around before deleting the invalid source slot item,
 			// which is now in the destination slot.
 			move_in->from_slot = dst_slot_check;
 			move_in->to_slot = src_slot_check;
 			move_in->number_in_stack = dst_inst->GetCharges();
+
+			Message(4, "SwapIt->Process(RecursiveCallToDeleteSRCItem)");
+
 			SwapItem(move_in);
 		}
 		Message(13, "Error: Server found no item in slot %i (->%i), Deleting Item!", src_slot_id, dst_slot_id);
@@ -1020,6 +1366,8 @@
 	}
 	//verify shared bank transactions in the database
 	if(src_inst && src_slot_id >= 2500 && src_slot_id <= 2550) {
+		Message(4, "SwapIt->Process(SharedBankCheck->SRC)");
+
 		if(!database.VerifyInventory(account_id, src_slot_id, src_inst)) {
 			LogFile->write(EQEMuLog::Error, "Player %s on account %s was found exploiting the shared bank.\n", account_name, GetName());
 			DeleteItemInInventory(dst_slot_id,0,true);
@@ -1035,6 +1383,8 @@
 		}
 	}
 	if(dst_inst && dst_slot_id >= 2500 && dst_slot_id <= 2550) {
+		Message(4, "SwapIt->Process(SharedBankCheck->DST)");
+
 		if(!database.VerifyInventory(account_id, dst_slot_id, dst_inst)) {
 			LogFile->write(EQEMuLog::Error, "Player %s on account %s was found exploting the shared bank.\n", account_name, GetName());
 			DeleteItemInInventory(src_slot_id,0,true);
@@ -1059,11 +1409,16 @@
 	&& RuleI(World, FVNoDropFlag) == 0 || RuleI(Character, MinStatusForNoDropExemptions) < Admin() && RuleI(World, FVNoDropFlag) == 2) {
 		DeleteItemInInventory(src_slot_id);
 		WorldKick();
+
+		// No message applied here since the player is being kicked
+
 		return false;
 	}
 	
 	// Step 3: Check for interaction with World Container (tradeskills)
 	if(m_tradeskill_object != NULL) {
+		Message(4, "SwapIt->Process(WorldContainerCheck)");
+
 		if (src_slot_id>=4000 && src_slot_id<=4009) {
 			// Picking up item from world container
 			ItemInst* inst = m_tradeskill_object->PopItem(Inventory::CalcBagIdx(src_slot_id));
@@ -1136,6 +1491,8 @@
 	
 	// Step 4: Check for entity trade
 	if (dst_slot_id>=3000 && dst_slot_id<=3007) {
+		Message(4, "SwapIt->Process(EntityTradeCheck)");
+
 		if (src_slot_id != SLOT_CURSOR) {
 			Kick();
 			return false;
@@ -1161,23 +1518,38 @@
 	
 	// Step 5: Swap (or stack) items
 	if (move_in->number_in_stack > 0) {
+		Message(4, "SwapIt->Process(StackableItem[%s])", src_inst?src_inst->GetItem()->Name:"Null");
+
 		// Determine if charged items can stack
 		if (dst_inst) {
 			if(src_inst->GetID() != dst_inst->GetID()) {
 				mlog(INVENTORY__ERROR, "Move from %d to %d with stack size %d. Incompatible item types: %d != %d", src_slot_id, dst_slot_id, move_in->number_in_stack, src_inst->GetID(), dst_inst->GetID());
-				return(false);
+				
+				Message(4, "SwapIt->Process(StackableIDMisMatch->SRCItem[%s]->SRCID[%u]->DSTItem[%s]->DSTID[%u])", src_inst?src_inst->GetItem()->Name:"Null", src_inst?src_inst->GetItem()->ID:0, dst_inst?dst_inst->GetItem()->Name:"Null", dst_inst?dst_inst->GetItem()->ID:0);
+				
+				return false;
 			}
 			if(dst_inst->GetCharges() < dst_inst->GetItem()->StackSize) {
 				//we have a chance of stacking.
 				mlog(INVENTORY__SLOTS, "Move from %d to %d with stack size %d. dest has %d/%d charges", src_slot_id, dst_slot_id, move_in->number_in_stack, dst_inst->GetCharges(), dst_inst->GetItem()->StackSize);
 				// Charges can be emptied into dst
 				uint16 usedcharges = dst_inst->GetItem()->StackSize - dst_inst->GetCharges();
-				if (usedcharges > move_in->number_in_stack)
+				
+				Message(4, "SwapIt->Process(StackSize[%i]->DSTCharges[%i]->UsedCharges[%u])", dst_inst->GetItem()->StackSize, dst_inst->GetCharges(), usedcharges);
+				
+				if (usedcharges > move_in->number_in_stack) {
+					Message(4, "SwapIt->Process(UsedChargeAdjustment[%u]->NumberInStack[%u])", usedcharges, move_in->number_in_stack);
+
 					usedcharges = move_in->number_in_stack;
+				}
+				dst_inst->SetCharges(dst_inst->GetCharges() + usedcharges);
 				
-				dst_inst->SetCharges(dst_inst->GetCharges() + usedcharges);
+				Message(4, "SwapIt->Process(SetDSTCharges->CurrentCharges[%i])", dst_inst?dst_inst->GetCharges():-1);
+
 				src_inst->SetCharges(src_inst->GetCharges() - usedcharges);
 				
+				Message(4, "SwapIt->Process(SetSRCCharges->CurrentCharges[%i])", src_inst?src_inst->GetCharges():-1);
+
 				// Depleted all charges?
 				if (src_inst->GetCharges() < 1)
 				{
@@ -1187,7 +1559,11 @@
 				} else {
 					mlog(INVENTORY__SLOTS, "Dest (%d) now has %d charges, source (%d) has %d (%d moved)", dst_slot_id, dst_inst->GetCharges(), src_slot_id, src_inst->GetCharges(), usedcharges);
 				}
-			} else {
+				Message(4, "SwapIt->Process(SRCCharges->Remaining[%i])", src_inst?src_inst->GetCharges():-1);
+			}
+			else {
+				Message(4, "SwapIt->Process(Scooby->Ruh Roh Rhaggy!)");
+
 				//stack is full, so 
 			}
 		}
@@ -1197,6 +1573,8 @@
 				mlog(INVENTORY__SLOTS, "Move entire stack from %d to %d with stack size %d. Dest empty.", src_slot_id, dst_slot_id, move_in->number_in_stack);
 				// Move entire stack
 				m_inv.SwapItem(src_slot_id, dst_slot_id);
+
+				Message(4, "SwapIt->Process(MoveStack->SRCSlot[%i]->DSTSlot[]%i->StackCount[%u])", src_slot_id, dst_slot_id, move_in->number_in_stack);
 			}
 			else {
 				// Split into two
@@ -1205,6 +1583,8 @@
 				ItemInst* inst = database.CreateItem(src_inst->GetItem(), move_in->number_in_stack);
 				m_inv.PutItem(dst_slot_id, *inst);
 				safe_delete(inst);
+
+				Message(4, "SwapIt->Process(SplitStack->SRCSlot[%i]->DSTSlot[%i]->StackCount[%u])", src_slot_id, dst_slot_id, src_inst?src_inst->GetCharges():-1);
 			}
 		}
 	}
@@ -1217,6 +1597,9 @@
 			SetMaterial(dst_slot_id,src_inst->GetItem()->ID);
 		}
 		mlog(INVENTORY__SLOTS, "Moving entire item from slot %d to slot %d", src_slot_id, dst_slot_id);
+
+		Message(4, "SwapIt->Process(SwapItem[%s]->SRCSlot[%i]->DSTSlot[%i])", src_inst?src_inst->GetItem()->Name:"Null", src_slot_id, dst_slot_id);
+
 		m_inv.SwapItem(src_slot_id, dst_slot_id);
 	}
 	
@@ -1226,23 +1609,45 @@
 	}
 	
 	// Step 7: Save change to the database
-	if (src_slot_id==SLOT_CURSOR){ 
+	if (src_slot_id==SLOT_CURSOR) {
+		//Message(4, "SwapIt->Process(SaveCursor[%s]->SRC)", src_inst?src_inst->GetItem()->Name:"Null");
+		Message(4, "SwapIt->Process(SaveCursor[%s]->SRC)", "{src_inst->pointerissues-willcrashzone}");
+
 		list<ItemInst*>::const_iterator s=m_inv.cursor_begin(),e=m_inv.cursor_end();
 		database.SaveCursor(character_id, s, e);
-	} else
+	}
+	else {
+		//Message(4, "SwapIt->Process(SaveInventory[%s]->SRC[%i])", src_inst?src_inst->GetItem()->Name:"Null", src_slot_id);
+		Message(4, "SwapIt->Process(SaveInventory[%s]->SRC[%i])", "{src_inst->pointerissues-willcrashzone}", src_slot_id);
+
 		database.SaveInventory(character_id, m_inv.GetItem(src_slot_id), src_slot_id);
+	}
+
 	if (dst_slot_id==SLOT_CURSOR) {
+		//Message(4, "SwapIt->Process(SaveCursor[%s]->DST)", dst_inst?dst_inst->GetItem()->Name:"Null");
+		Message(4, "SwapIt->Process(SaveCursor[%s]->DST)", "{dst_inst->pointerissues-willcrashzone}");
+
 		list<ItemInst*>::const_iterator s=m_inv.cursor_begin(),e=m_inv.cursor_end();
 		database.SaveCursor(character_id, s, e);
-	} else
+	}
+	else {
+		//Message(4, "SwapIt->Process(SaveInventory[%s]->DST[%i])", dst_inst?dst_inst->GetItem()->Name:"Null", dst_slot_id);
+		Message(4, "SwapIt->Process(SaveInventory[%s]->DST[%i])", "{dst_inst->pointerissues-willcrashzone}", dst_slot_id);
+
 		database.SaveInventory(character_id, m_inv.GetItem(dst_slot_id), dst_slot_id);
+	}
 	
 	// Step 8: Re-calc stats
 	CalcBonuses();
+
+	Message(4, "SwapIt->Exit");
+
 	return true;
 }
 
 void Client::DyeArmor(DyeStruct* dye){
+	Message(4, "DyeArm->Entry");
+
 	sint16 slot=0;
 	for(int i=0;i<7;i++){
 		if(m_pp.item_tint[i].rgb.blue!=dye->dye[i].rgb.blue ||
@@ -1276,6 +1681,8 @@
 	QueuePacket(outapp);
 	safe_delete(outapp);
 	Save();
+
+	Message(4, "DyeArm->Exit");
 }
 
 /*bool Client::DecreaseByItemType(int32 type, int8 amt) {
@@ -1330,6 +1737,8 @@
 }*/
 
 bool Client::DecreaseByID(int32 type, int8 amt) {
+	Message(4, "DecByID->Entry");
+
 	const Item_Struct* TempItem = 0;
 	ItemInst* ins;
 	int x;
@@ -1349,8 +1758,13 @@
 				break;
 		}
 	}
-	if (num < amt)
+	
+	if (num < amt) {
+		Message(4, "DecByID->Exit(NumberLessThanAmount)");
+
 		return false;
+	}
+
 	for(x=0; x < 331; x++)
 	{
 		if (x == 31)
@@ -1375,11 +1789,15 @@
 				break;
 		}
 	}
+	Message(4, "DecByID->Exit");
+
 	return true;
 }
 
 
 void Client::RemoveNoRent() {
+	Message(4, "RemNoRent->Entry");
+
 	const Item_Struct* TempItem = 0;
 	ItemInst* ins;
 	int x;
@@ -1471,6 +1889,7 @@
 			}
 		}
 	}
+	Message(4, "RemNoRent->Exit");
 }
 
 // these functions operate with a material slot, which is from 0 to 8
@@ -1536,6 +1955,8 @@
 }
 
 bool Client::LootToStack(int32 itemid) {  //Loots stackable items to existing stacks - Wiz
+	Message(4, "LootToStac->Entry");
+	
 	// @merth: Need to do loot code with new inventory struct
 	/*
 	const Item_Struct* item;
@@ -1576,14 +1997,22 @@
 		}
 	}
 	*/
+
+	Message(4, "LootToStac->Exit");
+
 	return false;
 }
 
 // Send an item packet (including all subitems of the item)
 void Client::SendItemPacket(sint16 slot_id, const ItemInst* inst, ItemPacketType packet_type)
 {
-	if (!inst)
+	Message(4, "SendItPack->Entry(ItemID[%u])", inst?inst->GetItem()->Name:0);
+
+	if (!inst) {
+		Message(4, "SendItPack->Exit(Item[Null])");
+
 		return;
+	}
 	
 	// Serialize item into |-delimited string
 	string packet = inst->Serialize(slot_id);
@@ -1604,12 +2033,19 @@
 #endif
 	//DumpPacket(outapp);
 	FastQueuePacket(&outapp);
+
+	Message(4, "SendItPack->Exit(ClientUpdate->SendItem[%s])", inst->GetItem()->Name);
 }
 
 EQApplicationPacket* Client::ReturnItemPacket(sint16 slot_id, const ItemInst* inst, ItemPacketType packet_type)
 {
-	if (!inst)
+	Message(4, "RetItemPack->Entry(ItemID[%u])", inst?inst->GetItem()->ID:0);
+
+	if (!inst) {
+		Message(4, "RetItemPack->Exit(NullItem)");
+
 		return 0;
+	}
 	
 	// Serialize item into |-delimited string
 	string packet = inst->Serialize(slot_id);
@@ -1628,6 +2064,8 @@
 		DumpPacket(outapp);
 #endif
 
+	Message(4, "RetItemPack->Exit(ClientUpdate->ReturnItem[%s])", inst->GetItem()->Name);
+
 	return outapp;
 }
 
@@ -1646,6 +2084,7 @@
 }
 
 void Client::CreateBandolier(const EQApplicationPacket *app) {
+	Message(4, "CreBand->Entry");
 
 	// Store bandolier set with the number and name passed by the client, along with the items that are currently
 	// in the players weapon slots.
@@ -1669,17 +2108,24 @@
 			_log(INVENTORY__BANDOLIER, "Char: %s adding item %s to slot %i", GetName(),BaseItem->Name, WeaponSlot);
 			m_pp.bandoliers[bs->number].items[BandolierSlot].item_id = BaseItem->ID;
 			m_pp.bandoliers[bs->number].items[BandolierSlot].icon = BaseItem->Icon;
+
+			Message(4, "CreBand->Process(Bandolier->AddItem[%s]->BandolierSlot[%i]->WeaponSlot[%i])", InvItem->GetItem()->Name, BandolierSlot, WeaponSlot);
 		}
 		else {
 			_log(INVENTORY__BANDOLIER, "Char: %s no item in slot %i", GetName(), WeaponSlot);
 			m_pp.bandoliers[bs->number].items[BandolierSlot].item_id = 0;
 			m_pp.bandoliers[bs->number].items[BandolierSlot].icon = 0;
+
+			Message(4, "CreBand->Process(Bandolier->AddItem[Null]->BandolierSlot[%i]->WeaponSlot[%i])", BandolierSlot, WeaponSlot);
 		}
 	}
 	Save();
+
+	Message(4, "CreBand->Exit");
 }
 
 void	Client::RemoveBandolier(const EQApplicationPacket *app) {
+	Message(4, "RemBand->Entry");
 
 	// Delete bandolier with the specified number
 
@@ -1689,11 +2135,16 @@
 	for(int i = bandolierMainHand; i <= bandolierAmmo; i++) {
 		m_pp.bandoliers[bds->number].items[i].item_id = 0;
 		m_pp.bandoliers[bds->number].items[i].icon = 0;
+
+		Message(4, "RemBand->Process(Bandolier->RemoveItem->BandolierSlot[%i])", i);
 	}
 	Save();
+
+	Message(4, "RemBand->Exit");
 }
 
 void	Client::SetBandolier(const EQApplicationPacket *app) {
+	Message(4, "SetBand->Entry");
 
 	// Swap the weapons in the given bandolier set into the character's weapon slots and return
 	// any items currently in the weapon slots to inventory.
@@ -1707,16 +2158,22 @@
 	// First we pull the items for this bandolier set out of their inventory, this makes space to put the
 	// currently equipped items back.
 	for(int BandolierSlot = bandolierMainHand; BandolierSlot <= bandolierAmmo; BandolierSlot++) {
+		Message(4, "SetBand->Process(BandolierSlot[%i]->Start)", BandolierSlot);
+
 		// If this bandolier set has an item in this position
 		if(m_pp.bandoliers[bss->number].items[BandolierSlot].item_id) {
 			WeaponSlot = BandolierSlotToWeaponSlot(BandolierSlot);
 
+			Message(4, "SetBand->Process(BandolierSlot->WeaponAssigned)");
+
 			// Check if the player has the item specified in the bandolier set on them.
 			//
 			slot = m_inv.HasItem(m_pp.bandoliers[bss->number].items[BandolierSlot].item_id, 1, 
 					     invWhereWorn|invWherePersonal|invWhereCursor);
 			// if the player has this item in their inventory,
 			if(slot != SLOT_INVALID) {
+				Message(4, "SetBand->Process(InventorySearch->WeaponFound[%s]->InSlot[%i])", GetInv().GetItem(slot)?GetInv().GetItem(slot)->GetItem()->Name:"Null", slot);
+
 				// Pull the item out of the inventory
 				BandolierItems[BandolierSlot] = m_inv.PopItem(slot);
 				// If ammo with charges, only take one charge out to put in the range slot, that is what
@@ -1725,34 +2182,55 @@
 				if(((BandolierSlot == bandolierAmmo) || (BandolierSlot == bandolierRange)) && 
 				   BandolierItems[BandolierSlot] && BandolierItems[BandolierSlot]->IsStackable()){
 					int Charges = BandolierItems[BandolierSlot]->GetCharges();
+
+					Message(4, "SetBand->Process(StackableAmmoCheck)");
+
 					// If there is more than one charge
 					if(Charges > 1) {
 						BandolierItems[BandolierSlot]->SetCharges(Charges-1);
+
+						Message(4, "SetBand->Process(AmmoStack[%s]->Remove[1])", BandolierItems[BandolierSlot]?BandolierItems[BandolierSlot]->GetItem()->Name:"Null");
+
 						// Take one charge out and put the rest back
 						m_inv.PutItem(slot, *BandolierItems[BandolierSlot]);
 						database.SaveInventory(character_id, BandolierItems[BandolierSlot], slot);
 						BandolierItems[BandolierSlot]->SetCharges(1);
 					}
-					else	// Remove the item from the inventory
+					else {	// Remove the item from the inventory
+						Message(4, "SetBand->Process(AmmoItem[%s]->TakeFromInventory)", BandolierItems[BandolierSlot]?BandolierItems[BandolierSlot]->GetItem()->Name:"Null");
+						
 						database.SaveInventory(character_id, 0, slot);
+					}
 				}
-				else	// Remove the item from the inventory
+				else {	// Remove the item from the inventory
+					Message(4, "SetBand->Process(Item[%s])->RemoveFromInventory", GetInv().GetItem(slot)?GetInv().GetItem(slot)->GetItem()->Name:"Null");
+
 					database.SaveInventory(character_id, 0, slot);
+				}
 			}
 			else { // The player doesn't have the required weapon with them.
+				Message(4, "SetBand->Process(InventorySearch->WeaponNotFound)");
+
 				BandolierItems[BandolierSlot] = 0;
 				if(slot == SLOT_INVALID) {
+					Message(4, "SetBand->Process(InvalidSlotAssignment)");
+
 					_log(INVENTORY__BANDOLIER, "Character does not have required bandolier item for slot %i", WeaponSlot);
 					ItemInst *InvItem = m_inv.PopItem(WeaponSlot);
 					if(InvItem) {
 						// If there was an item in that weapon slot, put it in the inventory	
 						_log(INVENTORY__BANDOLIER, "returning item %s in weapon slot %i to inventory",
 									   InvItem->GetItem()->Name, WeaponSlot);
-						if(MoveItemToInventory(InvItem)) 
+						if(MoveItemToInventory(InvItem)) {
+							Message(4, "SetBand->Process(Item[%s]->ReturnToInventory->ToSlot[%i])", InvItem?InvItem->GetItem()->Name:"Null", WeaponSlot);
+
 							database.SaveInventory(character_id, 0, WeaponSlot);
-						else
-							_log(INVENTORY__BANDOLIER, "Char: %s, ERROR returning %s to inventory", GetName(),
-							     InvItem->GetItem()->Name);
+						}
+						else {
+							Message(4, "SetBand->Process(Item[%s]->ReturnToInventory->ERROR)", InvItem?InvItem->GetItem()->Name:"Null");
+
+							_log(INVENTORY__BANDOLIER, "Char: %s, ERROR returning %s to inventory", GetName(), InvItem->GetItem()->Name);
+						}
 						safe_delete(InvItem);
 					}
 
@@ -1770,8 +2248,12 @@
 		
 		WeaponSlot = BandolierSlotToWeaponSlot(BandolierSlot);
 
+		Message(4, "SetBand->Process(SwapItem->Begin)");
+
 		// if there is an item in this Bandolier slot ?
 		if(m_pp.bandoliers[bss->number].items[BandolierSlot].item_id) {
+			Message(4, "SetBand->Process(BandolierWeaponAssignment[%s])", (m_pp.bandoliers[bss->number].items[BandolierSlot].item_id)?database.GetItem(m_pp.bandoliers[bss->number].items[BandolierSlot].item_id)->Name:"Null");
+
 			// if the player has this item in their inventory, and it is not already where it needs to be
 			if(BandolierItems[BandolierSlot]) {
 				// Pull the item that we are going to replace
@@ -1779,15 +2261,22 @@
 				// Put the item specified in the bandolier where it needs to be
 				m_inv.PutItem(WeaponSlot, *BandolierItems[BandolierSlot]);
 
+				Message(4, "SetBand->Process(SwapAction->FromWeapon[%s]->ToWeapon[%s])", InvItem?InvItem->GetItem()->Name:"Null", BandolierItems[BandolierSlot]?BandolierItems[BandolierSlot]->GetItem()->Name:"Null");
+				
 				safe_delete(BandolierItems[BandolierSlot]);
 				// Update the database, save the item now in the weapon slot
 				database.SaveInventory(character_id, m_inv.GetItem(WeaponSlot), WeaponSlot);
 
 				if(InvItem) {
 					// If there was already an item in that weapon slot that we replaced, find a place to put it
-					if(!MoveItemToInventory(InvItem)) 
-						_log(INVENTORY__BANDOLIER, "Char: %s, ERROR returning %s to inventory", GetName(),
-						     InvItem->GetItem()->Name);
+					if(!MoveItemToInventory(InvItem)) {
+						Message(4, "SetBand->Process(AssignedBandolierSlot->ReturningWeaponToInventory[%s]->ERROR)", InvItem?InvItem->GetItem()->Name:"Null");
+
+						_log(INVENTORY__BANDOLIER, "Char: %s, ERROR returning %s to inventory", GetName(), InvItem->GetItem()->Name);
+					}
+					else {
+						Message(4, "SetBand->Process(AssignedBandolierSlot->ReturningWeaponToInventory[%s])", InvItem?InvItem->GetItem()->Name:"Null");
+					}
 					safe_delete(InvItem);
 				}
 			}
@@ -1796,25 +2285,37 @@
 			// This bandolier set has no item for this slot, so take whatever is in the weapon slot and
 			// put it in the player's inventory.
 			ItemInst *InvItem = m_inv.PopItem(WeaponSlot);
+
+			Message(4, "SetBand->Process(BandolierWeaponAssignment[Null])");
+
 			if(InvItem) {
-				_log(INVENTORY__BANDOLIER, "Bandolier has no item for slot %i, returning item %s to inventory",
-							   WeaponSlot, InvItem->GetItem()->Name);
+				Message(4, "SetBand->Process(ReturnCurrentWeaponToInventory[%s])", InvItem?InvItem->GetItem()->Name:"Null");
+
+				_log(INVENTORY__BANDOLIER, "Bandolier has no item for slot %i, returning item %s to inventory", WeaponSlot, InvItem->GetItem()->Name);
 				// If there was an item in that weapon slot, put it in the inventory	
-				if(MoveItemToInventory(InvItem)) 
+				if(MoveItemToInventory(InvItem)) {
+					Message(4, "SetBand->Process(EmptyBandolierSlot->ReturningWeaponToInventory[%s])", InvItem?InvItem->GetItem()->Name:"Null");
+
 					database.SaveInventory(character_id, 0, WeaponSlot);
-				else
-					_log(INVENTORY__BANDOLIER, "Char: %s, ERROR returning %s to inventory", GetName(),
-					     InvItem->GetItem()->Name);
+				}
+				else {
+					Message(4, "SetBand->Process(EmptyBandolierSlot->ReturningWeaponToInventory[%s]->ERROR)", InvItem?InvItem->GetItem()->Name:"Null");
+
+					_log(INVENTORY__BANDOLIER, "Char: %s, ERROR returning %s to inventory", GetName(), InvItem->GetItem()->Name);
+				}
 				safe_delete(InvItem);
 			}
 		}
 	}
 	// finally, recalculate any stat bonuses from the item change
 	CalcBonuses();
+
+	Message(4, "SetBand->Exit");
 }
 
 bool Client::MoveItemToInventory(ItemInst *ItemToReturn, bool UpdateClient) {
-	
+	Message(4, "MoveItToInv->Entry(ItemID[%u])", ItemToReturn?ItemToReturn->GetItem()->ID:0);
+
 	// This is a support function for Client::SetBandolier, however it can be used anywhere it's functionality is required.
 	//
 	// When the client moves items around as Bandolier sets are activated, it does not send details to the 
@@ -1832,12 +2333,18 @@
 	// depends on current behaviour, this routine operates the same as the client when moving items back to inventory when
 	// swapping bandolier sets.
 
-	if(!ItemToReturn) return false;
+	if(!ItemToReturn) {
+		Message(4, "MoveItToInv->Exit(Item[Null])");
 
+		return false;
+	}
+
 	_log(INVENTORY__SLOTS,"Char: %s Returning %s to inventory", GetName(), ItemToReturn->GetItem()->Name);
 
 	int32 ItemID = ItemToReturn->GetItem()->ID;
 
+	Message(4, "MoveItToInv->Process(Item[%s])", ItemToReturn->GetItem()->Name);
+
 	// If the item is stackable (ammo in range slot), try stacking it with other items of the same type
 	//
 	if(ItemToReturn->IsStackable()) {
@@ -1862,8 +2369,11 @@
 
 				ItemToReturn->SetCharges(ItemToReturn->GetCharges() - ChargesToMove);
 				
-				if(!ItemToReturn->GetCharges()) 
+				if(!ItemToReturn->GetCharges()) {
+					Message(4, "MoveItToInv->Exit(MoveCharges->ToSlot[%i])", i);
+
 					return true;
+				}
 			}
 			// If there is a bag in this slot, look inside it.
 			//
@@ -1895,8 +2405,11 @@
 
 						ItemToReturn->SetCharges(ItemToReturn->GetCharges() - ChargesToMove);
 
-						if(!ItemToReturn->GetCharges()) 
+						if(!ItemToReturn->GetCharges()) {
+							Message(4, "MoveItToInv->Exit(MoveCharges->ToSlot[%i]->ToBagSlot[%i])", i, BagSlot);
+
 							return true;
+						}
 					}		
 				}
 			}
@@ -1920,6 +2433,8 @@
 
 			_log(INVENTORY__SLOTS, "Char: %s Storing in main inventory slot %i", GetName(), i);
 
+			Message(4, "MoveItToInv->Exit(Move->ToSlot[%i])", i);
+
 			return true;
 		}
 		if(InvItem->IsType(ItemClassContainer) && Inventory::CanItemFitInContainer(ItemToReturn->GetItem(), InvItem->GetItem())) {
@@ -1943,6 +2458,8 @@
 
 					_log(INVENTORY__SLOTS, "Char: %s Storing in bag slot %i", GetName(), BaseSlotID + BagSlot);
 
+					Message(4, "MoveItToInv->Exit(Move->ToSlot[%i]->ToBagSlot[%i])", i, BagSlot);
+
 					return true;
 				}
 			}
@@ -1955,6 +2472,8 @@
 
 	PushItemOnCursor(*ItemToReturn, UpdateClient);
 
+	Message(4, "MoveItToInv->Exit(PushToCursor[%s]->WithCharges[%i])", ItemToReturn->GetItem()->Name, ItemToReturn->GetCharges());
+
 	return true;
 }

Uleat of Bertoxxulous

[joligario]

You can probably also check the item swap / item cursor with cast or click as well. Especially with the speed of the MQ2 macros.

[Uleat]

Do you happen to know if the problem occurs all the time or just when a summoned item is created per chance?

I saw a few postings about that before I found one of the major bugs and did not include it in my search criteria.


The most noticeable cursor issue is has to do with how the server is coded to handle a swap action of partial stacks. If you are holding a partial stack on
the cursor, the server will jump to placing any additional partial stacks in either an empty personal slot or bag slot, while the client will check for a
partial stack on the cursor first. This creates the client-server de-sync and the player becomes bugged to future trades/swaps resulting in obvious item
deletions - some permanent.

(Yes, the fix for that is really easy, but DO NOT TRY TO COMMIT A FIX before speaking with me privately. There are MAJOR issues that arise when you
make that change.)


I have a small list of these bugs that I will post soon, but am welcome to more input in the mean time. I need to sort my notes between de-sync issues
and actual bug triggering.

Again, item loss is not the bug, but the result of one. Like a damaged car is a result of an accident, we want the events leading up to and including the
accident, not an in-depth description of the damaged car

[Uleat]

Here are some known bugs and behaviors that I have observed.

Some of the behaviors I have seen are omitted since they are duplicate scenarios of the same issue. There are also some other
non-revelent issues here since I'm looking at the entire inventory.cpp module.


[Cursoring a partial arrow stack involved in bandolier swap, with no other partials in inventory, results in de-sync (Bug)]
- This is caused by MoveItemToInventory(). It does not check the cursor for a partial stack before trying to find an empty
slot. Client behavior checks the cursor before moving on to empty slots. {TESTED AND VERIFIED - Partial fix appears to work}


[Cursoring one of the weapons involved in bandolier swap that has arrows results in de-sync (Bug)]
- Known issue, but still researching the exact cause. Could be related to the above bug. {TESTED}


[Clicking an item stack and it is non-responsive (Behavior)]
- At this point, you are bugged. You need to camp or zone to fix this problem asap before item loss becomes permanent. Any
items that you click, trade, buy or receive after invoking this behavior become subject to item loss. I guess this could be
applied to any item, but if not, that would narrow down the cause list. {TESTED}


[Placing an arrow stack in the ammo slot results in an 'Insufficient Quantity' error message and item deletion (Behavior)]
- The part of the code that triggers this message is working correctly. Again, you have become bugged by this point. Other
stackables are probably affected the same way. {ARROWS - TESTED AND VERFIED}


[Moving an item results in an 'Item Not Found On Server' error message and item deletion (Behavior)]
- Bugged..you know what to do. {TESTED AND VERFIED}


[Zero-charge stackable item (Bug or Behavior - still in-work)]
- It's possible to have an arrow (or possibly any stackable item) with zero charges. This can turn into an exploit, so I will
not elaborate on it's cause. (I have triggered this, but do not have an exact procedure as yet. I was already suspecting this
as a problem, but I have found a way to provide evidence of it.) {TESTED}


[Backpack - the new ammo! (Behavior)]
- Overloading the inventory and then calling a swap will result in some REALLY odd behavior (And major item loss.) I managed
to get a backpack into my ammo slot..I did not try to use my bow, however... (I wonder if a bag would actually fly across the
screen..hmmm...) {TESTED}


[Probable issue with Client::PutItemInInventory 'CalcBonuses' call]
- If you look at this particular function, you will notice there are two (slot_id == SLOT_CURSOR) checks. The first one is
always processed on 'true,' but the second one is never processed on 'true,' however... The call to PushItemOnCursor in the
first check duplicates the entire segment of code that is missed. This is not the problem...

- Look at the second one again. The check ALWAYS handles a return and CalcBonuses() is never called. {NOT TESTED}


[Possible issue with Client::TryStacking]
- With stackable items, this method checks the eight personal slots first before going back through bags and misses the cursor
altogether. This does not match the client and other server scheme for parsing stackable items. Corpse looting will likely
become bugged due to the same de-sync issues described above. {NOT TESTED}


[Possible issue with Inventory::SwapItem (item.cpp)]
- One-way check... slot 'a' item is checked against slot 'b,' but not vica-versa. First attempt at a fix crashed zone.exe...
This needs to be researched more thoroughly. {CONSEQUENCE OF LACK OF CHECK - NOT TESTED}


[Not pertinent - possible message issue with summoning items with augmentations]
- This is not tested, but I have seen where a possible lore conflict message will kick back when no other lore item is owned
and also on non-lore flagged items. The lore checks are correct, but the reference to the lore item in the message is set to
the base item and not the augmentation itself - meaning that you are trying to create an additional lore augmentation, but not
lore item itself, and it is reporting the wrong lore conflict. Let me know if you have experienced this. {NOT TESTED}


[Not pertinent - #peekinv is not showing slot #30 in the listing when its value is null, or supposed to be]
- I haven't looked at the code to see if the 'GetItem()' command is just not reporting or is in a failed state. {OBSERVED}


After working these issues, and anything new that crops up with fixes, I'll take a look at consumption issues. I just need to
verify that they are not a part of these exisiting de-sync problems.


If you are posting symptoms, please include server revision, system and client information as well. I don't believe these
problems are unique to, or exclusive of, any particular setup, but we won't be able to determine that without the proper data.

These issues are long-lived and I'm sure that everyone would love to see them fixed. Please support this request if you have
pertinent information.

And to remind anyone wanting to fix these issues one at a time - Please do not do so with the item swapping issues. You will
introduce major exploits unless all of the issues are coordinated and fixed together.


Thanks!

[sorvani]

Cursor stacking can also become messed up without actually becoming desync'd in such a manner that anything becomes unusable.
I do not have a way to make it happen off hand, but it most often happens when doing tradeskills.
I was speeding through (manually not with MQ2) making something, drinks i think, and then went to give some to another player and they received instead one of the components I had been using. My inventory was seemingly normal, but upon camping and coming back some of the drinks i had turned into a component.

Along these lines I've also ended up with a bag in a bag

[Uleat]

That almost sounds like the zero-charge bug..I'll see if I can do some ts'ing and replicate it.

I've also noticed something along the lines of the server finding an item in the cursor slot (with multiple items on it) but getting the first item
regardless of if it's the correct one..almost like it doesn't iterate to find what it found...

[Uleat]

I also managed to #summonitem a stack of 100 water flasks... Should probably add code to check max stack size to help avoid problems.

I was trying to induce the arrow error and camp immediately to check the database for possible zero stacks. What I found was a stack of 100 water flasks...

[Uleat]

I'm trying to sort out some issues as I make changes. One of the things I need to know is this:

Do all clients operate in the same manner in regards to inventory placement order? I can account for any discrepancies in
client versions, but I just need to know about them.


I also know about the top-to-bottom fill order of the personal inventory slots, and the left-to-right of bag slots.


Here is the actual placement order that I have observed with my SoF client:

[Stackable Item Charge Movements Only]
> Slot 22
>> Slot 22 : Bag Slots (0 -> 9)
> Slot 23
>> Slot 23 : Bag Slots (0 -> 9)

..etc... etc...

> Slot 29
>> Slot 29 : Bag Slots (0 -> 9)
> Slot 30
>> Slot 30 : Bag Slots (0 -> 9)

[Stackable Movement Reiteration/Regular Item Movement]
> Slot 22
>> Slot 22 : Bag Slots (0 -> 9)
> Slot 23
>> Slot 23 : Bag Slots (0 -> 9)

..etc... etc...

> Slot 29
>> Slot 29 : Bag Slots (0 -> 9)
> Slot 30
>> Slot 30 : Bag Slots (0 -> 9)
>>> Slot 30 Array Push


The functions/methods that I'm dealing with at the moment all start at 22 and end at 29. I am changing the max to 30
and will check in-game to see if worn slots are included when considering certain actions. (I have not tried 'looting' an
arrow to see where it goes yet.)

If the worn slots are auto-equipped by the client, but are pushed into the personal inventory by the server, this would
account for the CSD (Client-Server Desyncronization..I got tired of spelling that everytime...) and massive item loss
associated with it.

[Theory:]
(Player auto-loots a corpse with a partial stack in ammo -> auto-equips all weapons and armor -> finds stackable ammo for the
range slot..client puts it in the ammo slot, but server puts it in slot 22 -> transfers the the bags..client puts all of the
bags in the proper place, but server places last bag on the cursor -> player zones and finds a bag on his/her cursor...
Speculative..but would like to know if anyone has experienced that exactly. I may have to test this.)

I'm still learning the processes involved and may answer my own question about the auto-equip issue.


Thanks to everyone that's provided feedback so far!

[Uleat]

Ok, disregard the [Theory] in the previous post. I tried to trigger a bug with that, but it always seemed to put the arrows in the correct places.


Is there an auto-loot button? I keep reading about how it is bugged, but can't seem to find a button or command...

[Burningsoul]

With SOD+ I believe (been awhile since I've used SoD, on HoT client now) there does exist an auto-loot button - right click corpse, check right by the loot button. Loot All is there, and I've been able to replicate a few of your mentioned bugs with it. They're actually pretty annoying on a single player LAN server, but I can very easilly see how they could be used for abuse. Kudos for bringing this to light.

[Uleat]

Ahh, I'm using a SoF client..only button I have is 'Link All'

I believe I see the problem with it, so I may include that in an untested patch after I do this one. I think I've already described that above, but basically
it's just not iterating to match the client and items are being placed in different slots on the client versus server in some cases. I'm still waiting for
additional feedback on this, however..especially since I can't create a test for it.


I found one source of the problems, but I'm still getting this error series:

Error: Insufficent number in stack.
SwapIt->Exit(SRCItem[Shadowspike Arrow]->SRCCharges[48]->MIStackCount[49]->SRCStackSize[100]->ERROR)

The missing 3 charges were 2 on the cursor and 1 in the ammo slot.

I just need to find this other source and test it out. My head is stuck in a recursive loop at the moment...


Anyways, I'm hoping these fixes will be easy and won't require any major recoding.

[Uleat]

I'm starting to get some private feedback on these bugs as well and it seems there is proven evidence of their existence.


Give me some time to sort out this mess I call 'notes' and I'll see what I can do with them.

I 'think' that currently bugged players will be fixable as well, but someone else will probably submit that..my sql is REALLY horrible!

[lerxst2112]

Testing with SoF is probably not the right thing to do. From what I've heard it is the least stable client and probably the least used.

[cavedude]

Originally Posted by lerxst2112

Testing with SoF is probably not the right thing to do. From what I've heard it is the least stable client and probably the least used.

Based on what I've seen on PEQ, I'd agree with both points.

[Uleat]

Unfortunately, my monthly income is about -$250 a month, so I have to use what I have atm

I missed the Steam download by one day..I found the thread here after I had starting researching the different perl versions.


Anyways, I'll do what I can with this and post it as an alpha patch. There's no way that I can thoroughly test it the same as someone with internet
access and multiple players though.

The feedback is appreciated too! I spend most of my time inside VS trying to follow logic paths, so when I get verification of things that I see, it makes it
soooo much easier to find a solution. (No eta on a patch atm..I want to understand 100% what I'm seeing before I make any actual submissions.)

Edit: p.s. If anyone has any ideas about there being different client loot orders, I still need an answer to resolve that. Thanks!