World Crash - CombatProcess()

[John Adams]

Boy... I should not have updated from SVN, huh?

EQ2TC -

Code

Code: Select all

bool ZoneServer::CombatProcess() {
	bool ret = true;
	Spawn* spawn = 0;
	MutexMap<int32, Spawn*>::iterator itr = spawn_list.begin();
	while (itr.Next()) {
		spawn = itr->second;
==> Here	if (spawn && spawn->IsEntity())
			((Entity*)spawn)->ProcessCombat();
	}
	return ret;
}

Stack:

Code: Select all

 	feeefeee()	
>	EQ2World.exe!ZoneServer::CombatProcess()  Line 1004 + 0xb bytes	C++
 	EQ2World.exe!ZoneServer::SpawnProcess()  Line 1057	C++
 	EQ2World.exe!SpawnLoop(void * tmp)  Line 5585 + 0xb bytes	C++
 	EQ2World.exe!_callthreadstart()  Line 259 + 0x6 bytes	C
 	EQ2World.exe!_threadstart(void * ptd)  Line 241 + 0x5 bytes	C
 	kernel32.dll!77e6481f() 	
 	[Frames below may be incorrect and/or missing, no symbols loaded for kernel32.dll]	

Console:

12:29:52 I Command : command: inventory
12:29:52 D Items : Deleting item_id 43528 (Type: EQUIPPED) for player 3985
12:29:52 D Items : Deleting item_id 43264 (Type: NOT-EQUIPPED) for player 3985
12:29:56 D Command : Player 'Zujaomeunk' (6624), Command: clearallqueuedabilities
12:29:56 D Command : Handler: 37, COMMAND: 'autoattack'
12:29:56 D Command : Player 'Zujaomeunk' (6624), Command: autoattack
12:30:00 D Command : Player 'Zujaomeunk' (6624), Command: clearallqueuedabilities
12:30:05 D Command : Handler: 34, COMMAND: 'useability'
12:30:05 D Command : Player 'Zujaomeunk' (6624), Command: useability
12:30:05 D LUA : Found LUA Spell Script: 'Spells/Fighter/Warrior/Guardian/Overpower.lua'
12:30:05 D Spell : Zujaomeunk is casting Overpower on a crustose defender.
12:30:05 D Spell : Overpower: Not Self, Not Group AE, Not None, Max Targets = 0
12:30:05 D Spell : Overpower: Target Enemy (a crustose defender) and Max AE Targets = 0.
12:30:05 D Spell : Overpower: Is Not Friendly (catch all)
12:30:05 D Spell : No precast function found for Overpower
12:30:06 D Player : Player: Zujaomeunk earned 16 experience.
12:30:06 D Combat : Zone Killing 'a crustose defender'
12:30:06 D Spell : Concentration is now 0 on Zujaomeunk
12:30:07 D Command : Player 'Zujaomeunk' (6624), Command: clearallqueuedabilities
12:30:07 D Command : Handler: 37, COMMAND: 'autoattack'
12:30:07 D Command : Player 'Zujaomeunk' (6624), Command: autoattack

[Jabantiz]

Most work recently has been in spell process and doesn't touch the spawn list in the zone server...

Judging by the log I would assume the death of the NPC is some how screwing up the list but that shouldn't be possible. Debating if I should attempt to move the spawn list over to mutex and a normal map again, all past attempts haven't gone to well though.

[thefoof]

Looked though mutexmap code and this looks suspicious

Code: Select all

void deleteData(KeyT key, int8 type, int32 erase_time = 0){
		DeleteData<KeyT, ValueT>* del = new DeleteData<KeyT, ValueT>();
		pending_deletes[del] = true;
		has_pending_deletes = true;
      del->SetData(type, key, current_data[key], Timer::GetCurrentTime2() + erase_time);
}

SetData() just sets the actual info of the DeleteData class (timestamp to delete ect), which gets called AFTER we add it to the pending delete map, so maybe the deletion handler iterates to a delete we added before the timestamp was set, sees it's 0 and insta deletes.

EDIT: Nope all calls to this are inside a Locker so that shouldn't cause problems...still might change the order of the SetData and adding to the map, that really bothers me.

[thefoof]

Okay new theory!

Code: Select all

iterator(MutexMap* map){				
				this->map = map;
				map->update();
				map->SetChanging(); // <---
				this->map->AddAccess();
				map->SetNotChanging(); //<---
				first_itr = true;
				itr = map->current_data.begin();
				if(itr != map->current_data.end()){
					first = itr->first;
					second = itr->second;
				}
			}

Ok so when we make a new iterator and call begin(), this code above is called to initialize the iterator values. This also adds to the map's access count, which acts as a readlock and stops all writing/erasing. However we never check if another thread IS already changing, so if an iterator gets called while the thread is changing, and a spawn gets deleted it allows old pointers to be iterated through.

My above changes marked by arrows should make sure the locker for changing is not already set, and hold it until access is added. The update function will check for is access_count > 0 before making further changes so I think this should bad values from being iterated through. Just a theory obviously.

[Jabantiz]

Worth a shot, commit the code and lets see if it keeps happening, after looking at the spawn list I really don't want to try and change it to a normal map again, it is just used to often.

[thefoof]

Committed, only did this for MutexMaps right now since that's where we have the most problems

[thefoof]

Another thought just occurred to me - what if the spawn list is used so heavily on high-popped zones that a situation may arise where the list is not even able to update? We don't handle deletion of spawns in the list - we just tell the MutexMap to take them off the list and handle deletion in the zoneserver. What if in that 30 seconds, the list is not able to actually remove the spawn from the list - and along comes the outdated spawn pointer.

I've thought of a couple ways to safeguard against this from ever happening today.

1. Do not use the spawn values from spawn_list iterators other than at zone startup. Use the GetSpawnByID() function instead. The reason for this is the Get() function from MutexMap is smart enough to know if an item is pending deletion, iterators are not.

2. I don't know if this one is possible, Jab might know, if you call delete on a Spawn* pointer of let's say an NPC, do the Entity and NPC data values also get deleted? If so we could handle deletion in the MutexMap instead.

3. Force an update so often let's say if an update hasn't occurred in 5 seconds we say, ok update now. Wait for all other threads but you have to take control of the map and update now.

4. Move everything that uses the spawn_list inside ZoneProcess() to SpawnProcess(). Should allow for more updates.

5. Drop MutexMap altogether for the spawn_list.

I've stared at this code for a couple days on and off during my EQ2 time, and it really does look fine. I'm also not saying we should do ALL of this, personally I'm leaning towards saying if we were to do either 1 or 3, that would fix this possibility by themselves. I like 3 better because of the fact I mention in my next sentence.


IF this is really the problem we need to seriously consider not using MutexMap for this, because that would mean things aren't being added quickly as well. But at the same time if we go with fix #3 that would fix this problem as well. If this next change doesn't fix it, I really think we need to switch it over to a normal map though, because I just cannot see anything else that could even theoretically happen. Doesn't mean it's not there, just if it is I'm not smart enough to fix it.

[Jabantiz]

2. I don't know if this one is possible, Jab might know, if you call delete on a Spawn* pointer of let's say an NPC, do the Entity and NPC data values also get deleted? If so we could handle deletion in the MutexMap instead.

You have to cast it to the type it is when it gets deleted otherwise there can be abandoned data, basically a NPC has more info then a Spawn, calling a delete on a Spawn pointer that is actually a NPC will only delete the data a Spawn holds, leaving the extra data a NPC contains in memory. We do handle this in the zone server though.

As for the rest, it is late and I will have to get back to you tomorrow as it requires more thinking then I am capable of tonight.

[Jabantiz]

We should see if the list is in fact unable to update first, easiest way would be to just add a LogWrite in the mutex map update function the only issue is all mutex maps will trigger it, could add a bool to it and set the bool on the spawn list so the log write only triggers for that map though.

1. Do not use the spawn values from spawn_list iterators other than at zone startup. Use the GetSpawnByID() function instead. The reason for this is the Get() function from MutexMap is smart enough to know if an item is pending deletion, iterators are not.

I do not see where MutexMap.Get() checks pending deletes, looks to me like it only checks current_data and pending_add. pending_removes are not removed from current_data until an Update. It wouldn't be hard to add support to check pending_remove though.

3. Force an update so often let's say if an update hasn't occurred in 5 seconds we say, ok update now. Wait for all other threads but you have to take control of the map and update now.

Who knows how long of a delay this may cause while it waits for all others to finish off using the list, if in fact this is the issue still think we need to verify the large list is the issue.

4. Move everything that uses the spawn_list inside ZoneProcess() to SpawnProcess(). Should allow for more updates.

ZoneServer would just be a single thread in this case as almost every thing uses the spawn_list, clients add the player to it when they load, SpellProcess uses it for AE targets and LUA functions even call functions that loop through the list, not to mention sending spawns to a new client which we currently start a special thread for.

5. Drop MutexMap altogether for the spawn_list.

I hate MutexMaps now so this is my favorite idea but a lot more difficult then it sounds cause it is very easy to end up in a deadlock.

I would like to add another suggestion I just thought of while thinking over these ideas, it is sort of a combination of 1 and 5. Basically make a new class to handle the spawn map for the zone server, lets call it spawn manager for now, and change the current spawn_list to something like List<int32>. The zone server would create the spawn manager at startup and add the spawns to it, when a spawn is added it could return an id to put in the List<int32> spawn_list, or we could manually do it. Whenever we need a Spawn* pointer we would call spawn_mgr.Get(id) or something similar. In the spawn manager class we would only ever use a write lock on add and erase, every thing else would be a read lock.

In the zone server we would loop through spawn_list, try to get the spawn if we can't get a valid spawn then we would add the id to a pending delete list, again only ever using read locks on the list when we loop through it. In the spawn thread at the end, or beginning, we would loop through the pending list and delete from the spawn_list, this would require a write lock.

Not sure the cost of doing so many read locks so fast, however the map would never be locked for long periods of time and hopefully would prevent any deadlocks and these crashes we have been seeing.

[thefoof]

I do not see where MutexMap.Get() checks pending deletes, looks to me like it only checks current_data and pending_add. pending_removes are not removed from current_data until an Update. It wouldn't be hard to add support to check pending_remove though.

No more late night Mutex for me because I SWEAR I was seeing that last night...like consistently lol.

Whatever you think will work I'm good with, I was just brainstorming some ideas to try and get this dealt with. Making this assumption because it seems almost like it's the only thing that could possibly be causing this, I'll try a logwrite though.

[Jabantiz]

Not sure if my suggestion will fix it just something I thought of while thinking over your post. Should verify if the Mutex Update() delay is the issue or not before we decide what path to take.

[thefoof]

Did a little bit of testing on this last night and I couldn't find any evidence of this being the problem, so it's something else I guess.

[John Adams]

k, this crash is pretty brutal. We are not getting many players logging into Test Center lately, but every time we do, the world crashes almost immediately.

Same place, CombatProcess() on the null/missing spawn object.

I would guarantee if someone actually logged into Test Center while debugging, they could see this problem as easily as players do. If it is not happening on your servers, maybe it's time for more drastic measures.

[Jabantiz]

So foof's fix in rev 2442 didn't work? This does not crash on my local server in debug or release both before and after foof's attempted fix.

I have been going over the zone server code the past couple days looking to implement my possible solution if needed, will take some time though if we go ahead with it.

[John Adams]

Yes, I am on the current code. First player in the world for days, crashed pretty much immediately.

The whole log, from the first outside communication:

Code: Select all

12:01:55 D Login: Looking for Login Appearance Updates...
12:12:38 D World: Delete character request: 6624 454
12:12:47 D World: Delete character request: 6624 456
12:12:59 D World: Delete character request: 6624 3985
12:13:55 D World: Name check on: Ocon
12:13:55 D World: Response: 13
12:14:02 D World: Name check on: Epeawoex
12:14:02 D World: Response: 1
12:14:02 D Player: Adding default zone for race: 0, class: 3 for char_id: 3988 (choice: 4)
12:14:02 D Player: Setting New Character Starting Zone to 'FrostfangSea' FROM starting_zones table.
12:14:02 D Player: Adding default items for race: 0, class: 3 for char_id: 3988
12:14:02 D Player: Adding default skills for race: 0, class: 3 for char_id: 3988
12:14:02 D Player: Adding default spells for race: 0, class: 3 for char_id: 3988
12:14:02 D Player: Adding default skillbar for race: 0, class: 3 for char_id: 3988
12:14:02 D Player: Adding default titles for race: 0, class: 3, gender: 1 for char_id: 3988
12:14:03 D Net: AddAuth: 6624 Key: 1392146043
12:14:04 D Net: New client from ip: 92.74.93.63 port: 65329
12:14:04 D Net: Adding new client...
12:14:04 D Client: Client::Process, ProcessQuestUpdates
12:14:05 I ZoneAuth: Access Key: 1392146043, Character Name: Epeawoex, Account ID: 6624
12:14:05 D Player: Loading character for 'Epeawoex' (char_id: 3988)
12:14:05 I Zone: Loading new Zone 'FrostfangSea'
12:14:05 D Zone: SpawnUpdateTimer: 200ms
12:14:05 D Recipes: Loaded 0 recipes for player: Epeawoex (3988)
12:14:05 D Achievements: Loaded 0 player achievement updates
12:14:05 D Player: Loading character_details for 'Epeawoex' (char_id: 3988)
12:14:06 I Spawn: Loaded for zone 'FrostfangSea' (470):
	1804 NPC(s), 1238 Object(s), 34 Widget(s)
	81 Sign(s), 1920 Ground Spawn(s), 1828 Spawn Group(s)
	1164 Spawn Group Association(s), 0 Spawn Group Chance(s)
12:14:10 D Client: SendLoginInfo to new client...
12:14:10 D World: Increment Server_Accepted_Connection + 1
12:14:10 D Client: Populate Skill Map...
12:14:10 D Client: Toggle Character Online...
12:14:10 D Player: Toggling Character ONLINE!
12:14:10 D Client: Loading Character Skills for player 'Epeawoex'...
12:14:10 D World: Loading Titles for player 'Epeawoex'...
12:14:10 D World: Loading Languages for player 'Epeawoex'...
12:14:10 D Client: No character languages loaded!
12:14:10 D Spells: Loading Character Spells for player Epeawoex...
12:14:10 D Recipes: Loading Character Recipe Books for player 'Epeawoex' ...
12:14:10 D Client: No character recipe books found!
12:14:10 D Packet: Sending Login Accepted packet (LS_LoginResponse, 1096)
12:14:10 D World: Send MOTD...
12:14:10 D Packet: Sending Character Macro packet (WS_MacroInit, 1096)
12:14:10 D World: Sending FriendList...
12:14:10 D Player: Loading Player Factions...
12:14:10 D Player: Loading Character Quests...
12:14:10 D Player: Loading Player Mail...
12:14:10 D Client: Send Quest Journal...
12:14:10 D Client: Loading Faction Updates...
12:14:10 D Client: Send Command List...
12:14:10 D Client: Send Language Updates...
12:14:10 D Player: Getting current language for player 'Epeawoex'...
12:14:10 D Client: SendFriendList
12:14:10 D Client: SendIgnoreList
12:14:18 D Items: Loading items for character 'Epeawoex' (3988)
12:14:18 D Player: Getting current title index for player 'Epeawoex'...
12:14:18 D Player: Getting current title index for player 'Epeawoex'...
12:14:18 D Merchant: Loading Buyback - Player: 3988
12:14:24 D Command: Handler: 37, COMMAND: 'autoattack'
12:14:24 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:14:24 D Command: Handler: 35, COMMAND: 'enablequeuedabilities'
12:14:24 D Command: Player 'Epeawoex' (6624), Command: enablequeuedabilities
12:14:24 D Command: Player 'Epeawoex' (6624), Command: welcome_info
12:14:28 D Player: Epeawoex left grid 4294967295 and entered grid 3646759888
12:14:29 D Command: Player 'Epeawoex' (6624), Command: hail
12:14:29 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:14:37 D Command: Handler: 76, COMMAND: 'q_accept_pending_quest'
12:14:37 D Command: Player 'Epeawoex' (6624), Command: q_accept_pending_quest
12:14:37 D Client: Found 1 pending quests for char_id: 3988
12:14:37 D LUA: Quest: A Fine Halasian Welcome, function: Accepted
12:14:37 D LUA: Done!
12:14:37 D Client: Send Quest Journal...
12:14:37 D Client: Found 1 active quests for char_id: 3988
12:14:59 D Command: Player 'Epeawoex' (6624), Command: hail
12:14:59 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:15:01 D Client: Client::Process, ProcessQuestUpdates
12:15:01 D LUA: Quest: A Fine Halasian Welcome, function: quest_complete
12:15:01 D LUA: Done!
12:15:01 D Client: Send Quest Journal...
12:15:01 D Client: Send Quest Journal...
12:15:02 D Command: Player 'Epeawoex' (6624), Command: accept_reward
12:15:05 D Command: Handler: 76, COMMAND: 'q_accept_pending_quest'
12:15:05 D Command: Player 'Epeawoex' (6624), Command: q_accept_pending_quest
12:15:05 D Client: Found 1 pending quests for char_id: 3988
12:15:05 D LUA: Quest: Stonefist's Art of Combat, function: Accepted
12:15:05 D LUA: Done!
12:15:05 D Client: Send Quest Journal...
12:15:06 D Client: Found 1 active quests for char_id: 3988
12:15:21 D Command: Player 'Epeawoex' (6624), Command: hail
12:15:21 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:15:21 D Client: Client::Process, ProcessQuestUpdates
12:15:21 D LUA: Quest: Stonefist's Art of Combat, function: TalkedToStonefist
12:15:21 D LUA: Done!
12:15:21 D Client: Send Quest Journal...
12:15:21 D Client: Client::Process, CheckQuestQueue
12:15:21 D Command: Player 'Epeawoex' (6624), Command: hail
12:15:25 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:15:27 D Command: Handler: 37, COMMAND: 'autoattack'
12:15:27 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:15:40 D LUA: Quest: Stonefist's Art of Combat, function: KilledSparringPartner
12:15:40 D LUA: Done!
12:15:40 D Client: Client::Process, CheckQuestQueue
12:15:40 D Client: Send Quest Journal...
12:15:40 D World: Setting Global XP Rate to: 1.00
12:15:40 D Player: Player: Epeawoex earned 16 experience.
12:15:40 D Combat: Zone Killing 'a weak sparring partner'
12:15:41 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:15:41 D Command: Handler: 37, COMMAND: 'autoattack'
12:15:41 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:15:44 D Command: Player 'Epeawoex' (6624), Command: hail
12:15:44 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:15:45 D Client: Client::Process, ProcessQuestUpdates
12:15:45 D LUA: Quest: Stonefist's Art of Combat, function: ReturnedToStonefist
12:15:45 D LUA: Done!
12:15:45 D Client: Send Quest Journal...
12:15:45 D Client: Client::Process, CheckQuestQueue
12:15:54 D Command: Player 'Epeawoex' (6624), Command: hail
12:15:54 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:15:56 D Client: Client::Process, ProcessQuestUpdates
12:15:56 D LUA: Quest: Stonefist's Art of Combat, function: ReturnToYasha
12:15:56 D LUA: Done!
12:15:56 D Client: Send Quest Journal...
12:15:56 D Client: Send Quest Journal...
12:15:59 D Command: Handler: 85, COMMAND: 'accept_reward'
12:15:59 D Command: Player 'Epeawoex' (6624), Command: accept_reward
12:16:04 D Command: Handler: 76, COMMAND: 'q_accept_pending_quest'
12:16:04 D Command: Player 'Epeawoex' (6624), Command: q_accept_pending_quest
12:16:04 D Client: Found 1 pending quests for char_id: 3988
12:16:04 D LUA: Quest: Call to Arms, function: Accepted
12:16:04 D LUA: Done!
12:16:04 D Client: Send Quest Journal...
12:16:04 D Client: Found 1 active quests for char_id: 3988
12:16:05 D Items: Saving ItemID: 89454 (Type: NOT-EQUIPPED) for account: 6624, player: 3988
12:16:15 D Command: Player 'Epeawoex' (6624), Command: invite
12:16:23 D Command: Handler: 24, COMMAND: 'inventory'
12:16:23 D Command: Player 'Epeawoex' (6624), Command: inventory
12:16:23 I Command: command: inventory
12:16:23 D Items: Deleting item_id 79782 (Type: EQUIPPED) for player 3988
12:16:23 D Items: Deleting item_id 89454 (Type: NOT-EQUIPPED) for player 3988
12:16:28 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:16:28 D Command: Handler: 37, COMMAND: 'autoattack'
12:16:28 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:16:42 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:16:45 D Command: Handler: 37, COMMAND: 'autoattack'
12:16:45 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:16:46 D Combat: Zone Killing 'a Ry'Gorr centurion'
12:16:49 D Client: Send Quest Journal...
12:16:49 D Player: Player: Epeawoex earned 17 experience.
12:16:49 D Combat: Zone Killing 'a Ry'Gorr centurion'
12:16:50 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:16:50 D Command: Handler: 37, COMMAND: 'autoattack'
12:16:50 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:16:54 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:16:55 D Login: Looking for Login Appearance Updates...
12:16:55 D Login: Found 4 Login Appearance Updates...
12:16:55 D Login: Updating `character_items` CRC in WorldDatabase::UpdateLoginEquipment
12:16:57 D Command: Handler: 37, COMMAND: 'autoattack'
12:16:57 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:16:57 D Client: Send Quest Journal...
12:16:57 D Player: Player: Epeawoex earned 17 experience.
12:16:57 D Combat: Zone Killing 'a Ry'Gorr centurion'
12:16:58 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:16:58 D Command: Handler: 37, COMMAND: 'autoattack'
12:16:58 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:17:00 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:17:00 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:17:00 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:17:02 D Command: Handler: 37, COMMAND: 'autoattack'
12:17:02 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:17:05 D Items: Saving ItemID: 79782 (Type: NOT-EQUIPPED) for account: 6624, player: 3988
12:17:05 D Items: Saving ItemID: 89454 (Type: EQUIPPED) for account: 6624, player: 3988
12:17:07 D Client: Found 1 active quests for char_id: 3988
12:17:07 D Client: Send Quest Journal...
12:17:07 D Player: Player: Epeawoex earned 17 experience.
12:17:07 D Combat: Zone Killing 'a Ry'Gorr centurion'
12:17:08 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:17:08 D Command: Handler: 37, COMMAND: 'autoattack'
12:17:08 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:17:10 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:17:15 D Command: Handler: 37, COMMAND: 'autoattack'
12:17:15 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:17:26 D LUA: Quest: Call to Arms, function: KilledOrcs
12:17:26 D LUA: Done!
12:17:26 D Client: Client::Process, CheckQuestQueue
12:17:26 D Client: Send Quest Journal...
12:17:26 D Player: Player: Epeawoex earned 17 experience.
12:17:27 D Combat: Zone Killing 'a Ry'Gorr centurion'
12:17:27 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:17:30 D Command: Handler: 37, COMMAND: 'autoattack'
12:17:30 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:17:31 D Command: Handler: 37, COMMAND: 'autoattack'
12:17:31 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:17:32 D Command: Handler: 37, COMMAND: 'autoattack'
12:17:32 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:17:32 D Player: Player: Epeawoex earned 17 experience.
12:17:32 D Combat: Zone Killing 'a Ry'Gorr centurion'
12:17:34 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:17:34 D Command: Handler: 37, COMMAND: 'autoattack'
12:17:34 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:17:56 D Command: Player 'Epeawoex' (6624), Command: hail
12:17:56 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:17:57 D Client: Client::Process, ProcessQuestUpdates
12:17:57 D LUA: Quest: Call to Arms, function: TalkedYasha
12:17:57 D LUA: Done!
12:17:57 D Client: Send Quest Journal...
12:17:57 D Client: Send Quest Journal...
12:17:57 D World: Player: Epeawoex leveled from 1 to 2
12:18:00 D Command: Handler: 85, COMMAND: 'accept_reward'
12:18:00 D Command: Player 'Epeawoex' (6624), Command: accept_reward
12:18:05 D Items: Saving ItemID: 43263 (Type: NOT-EQUIPPED) for account: 6624, player: 3988
12:18:07 D Command: Handler: 76, COMMAND: 'q_accept_pending_quest'
12:18:07 D Command: Player 'Epeawoex' (6624), Command: q_accept_pending_quest
12:18:07 D Client: Found 1 pending quests for char_id: 3988
12:18:07 D LUA: Quest: Boatload of Work, function: Accepted
12:18:07 D LUA: Done!
12:18:07 D Client: Send Quest Journal...
12:18:07 D Client: Found 1 active quests for char_id: 3988
12:18:07 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:18:11 D Command: Handler: 34, COMMAND: 'useability'
12:18:11 D Command: Player 'Epeawoex' (6624), Command: useability
12:18:11 D LUA: Found LUA Spell Script: 'Spells/Fighter/Warrior/Guardian/ShieldBash.lua'
12:18:11 D Spell: Epeawoex is casting Shield Bash on a crustose defender.
12:18:11 D Spell: Shield Bash: Not Self, Not Group AE, Not None, Max Targets = 0
12:18:11 D Spell: Shield Bash: Target Enemy (a crustose defender) and Max AE Targets = 0.
12:18:11 D Spell: Shield Bash: Is Not Friendly (catch all)
12:18:11 D Spell: No precast function found for Shield Bash
12:18:12 D Spell: Concentration is now 0 on Epeawoex
12:18:14 D Command: Handler: 34, COMMAND: 'useability'
12:18:14 D Command: Player 'Epeawoex' (6624), Command: useability
12:18:14 D LUA: Found LUA Spell Script: 'Spells/Fighter/Warrior/Guardian/Overpower.lua'
12:18:14 D Spell: Epeawoex is casting Overpower on a crustose defender.
12:18:14 D Spell: Overpower: Not Self, Not Group AE, Not None, Max Targets = 0
12:18:14 D Spell: Overpower: Target Enemy (a crustose defender) and Max AE Targets = 0.
12:18:14 D Spell: Overpower: Is Not Friendly (catch all)
12:18:14 D Spell: No precast function found for Overpower
12:18:15 D Spell: Concentration is now 0 on Epeawoex
12:18:17 D Command: Handler: 34, COMMAND: 'useability'
12:18:17 D Command: Player 'Epeawoex' (6624), Command: useability
12:18:17 D LUA: Found LUA Spell Script: 'Spells/Fighter/Taunt.lua'
12:18:17 D Spell: Epeawoex is casting Taunt on a crustose defender.
12:18:17 D Spell: Taunt: Not Self, Not Group AE, Not None, Max Targets = 0
12:18:17 D Spell: Taunt: Target Enemy (a crustose defender) and Max AE Targets = 0.
12:18:17 D Spell: Taunt: Is Not Friendly (catch all)
12:18:17 D Spell: No precast function found for Taunt
12:18:20 D Spell: Concentration is now 0 on Epeawoex
12:18:22 D Command: Handler: 34, COMMAND: 'useability'
12:18:22 D Command: Player 'Epeawoex' (6624), Command: useability
12:18:22 D LUA: Found LUA Spell Script: 'Spells/Fighter/Warrior/Guardian/Provoke.lua'
12:18:22 D Spell: Epeawoex is casting Provoke on a crustose defender.
12:18:22 D Spell: Provoke: Not Self, Not Group AE, Not None, Max Targets = 0
12:18:22 D Spell: Provoke: Target Enemy (a crustose defender) and Max AE Targets = 0.
12:18:22 D Spell: Provoke: Is Not Friendly (catch all)
12:18:22 D Spell: No precast function found for Provoke
12:18:25 D Spell: Concentration is now 0 on Epeawoex
12:18:26 D Player: Player: Epeawoex earned 16 experience.
12:18:26 D Combat: Zone Killing 'a crustose defender'
12:18:27 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:18:27 D Command: Handler: 37, COMMAND: 'autoattack'
12:18:27 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:18:38 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:18:42 D Command: Handler: 34, COMMAND: 'useability'
12:18:42 D Command: Player 'Epeawoex' (6624), Command: useability
12:18:42 D LUA: Found LUA Spell Script: 'Spells/Fighter/Warrior/Guardian/Overpower.lua'
12:18:42 D Spell: Epeawoex is casting Overpower on a crustose defender.
12:18:42 D Spell: Overpower: Not Self, Not Group AE, Not None, Max Targets = 0
12:18:42 D Spell: Overpower: Target Enemy (a crustose defender) and Max AE Targets = 0.
12:18:42 D Spell: Overpower: Is Not Friendly (catch all)
12:18:42 D Spell: No precast function found for Overpower
12:18:43 D Spell: Concentration is now 0 on Epeawoex
12:18:45 D Command: Handler: 34, COMMAND: 'useability'
12:18:45 D Command: Player 'Epeawoex' (6624), Command: useability
12:18:45 D LUA: Found LUA Spell Script: 'Spells/Fighter/Warrior/Guardian/ShieldBash.lua'
12:18:45 D Spell: Epeawoex is casting Shield Bash on a crustose defender.
12:18:45 D Spell: Shield Bash: Not Self, Not Group AE, Not None, Max Targets = 0
12:18:45 D Spell: Shield Bash: Target Enemy (a crustose defender) and Max AE Targets = 0.
12:18:45 D Spell: Shield Bash: Is Not Friendly (catch all)
12:18:45 D Spell: No precast function found for Shield Bash
12:18:47 D Spell: Concentration is now 0 on Epeawoex
12:18:51 D Player: Player: Epeawoex earned 16 experience.
12:18:51 D Combat: Zone Killing 'a crustose defender'
12:18:52 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:18:52 D Command: Handler: 37, COMMAND: 'autoattack'
12:18:52 D Command: Player 'Epeawoex' (6624), Command: autoattack
12:18:54 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:18:57 D Command: Player 'Epeawoex' (6624), Command: clearallqueuedabilities
12:18:57 D Command: Handler: 37, COMMAND: 'autoattack'
12:18:57 D Command: Player 'Epeawoex' (6624), Command: autoattack

minus the spam about not finding the spells in the 1,000,000's