Page 1 of 1
New Mutex code, Tess crashed!
Posted: Mon Oct 05, 2009 6:42 am
by John Adams
LE, I didn't bother getting a call stack, because a) I'd rather you just look directly at the crash when you have a moment, and b) it looked very similar to the other crashes I sent when a zone is shutting down. Some log entries:
Error log:
3896 [20091004 20:33:15] Possible deadlock attempt by 'ZoneServer::MMasterSpawnLock'!
Debug Log (only entry near that time, and last entry in the log til I restarted):
3896 [20091004 20:28:15] Combined Packet: 2, 0!
World Log:
3896 [20091004 20:28:13] AddAuth: 2121 Key: 1254713293
3896 [20091004 20:28:14] New client from ip: 173.21.141.166 port: 64554
3896 [20091004 20:28:14] Adding new client...
3896 [20091004 20:28:15] ZoneAuth: Access Key: 1254713293, Character Name: Sergsdrg, Account ID: 2121
3896 [20091004 20:28:15] Loading new Zone 'TimorousDeep'
3896 [20091004 20:28:16] Loaded for zone 'TimorousDeep':
2199 NPC(s), 801 Object(s), 28 Widget(s)
18 Sign(s), 542 Ground Spawn(s), 0 Spawn Group(s)
0 Spawn Group Association(s), 0 Spawn Group Chance(s)
3896 [20091004 20:28:23] OP_Unknown Received 0x0038
3896 [20091004 20:31:13] Zone: Removing client from ip: 173.21.141.166 port 64554
3896 [20091004 20:32:44] Initiating zone shutdown of 'TimorousDeep'
Looks to me like this player logged in to Timorous Deep, sat there for 2 mins and logged off (probably crashed client, since there was no Sat or Track messages, indicative of someone /camp'ing or /exit'ing)
I'd like to point out that TimorousDeep was a problem many times before, shutting down, ending in a crashed world. I am not sure if it's the data, but you should have the current Tim Deep data from SVN if you need to try it out.
For anyone else having World crash issues after last night's World updates, let us know here. There's a whole new mechanism in place for dealing with deadlocks and such, LE can explain better if he wishes.
Re: New Mutex code, Tess crashed!
Posted: Mon Oct 05, 2009 8:00 am
by John Adams
Ok, I give. Seems to be happening every zone shutdown again. Or still. Maybe missed a lock? heh
Here's the trace:
Code: Select all
ntdll.dll!7c85e661()
[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]
ntdll.dll!7c85e661()
ntdll.dll!7c812f85()
ntdll.dll!7c80807d()
kernel32.dll!77e7690d()
ntdll.dll!7c84b0dc()
ntdll.dll!7c83d281()
> EQ2WorldDebug.exe!_lock(int locknum=15) Line 349 C
EQ2WorldDebug.exe!_VCrtDbgReportW(int nRptType=2, const wchar_t * szFile=0x00cac608, int nLine=245, const wchar_t * szModule=0x00000000, const wchar_t * szFormat=0x00cad050, char * arglist=0x21c1f9d0) Line 492 + 0x7 bytes C
EQ2WorldDebug.exe!_CrtDbgReportWV(int nRptType=2, const wchar_t * szFile=0x00cac608, int nLine=245, const wchar_t * szModule=0x00000000, const wchar_t * szFormat=0x00cad050, char * arglist=0x21c1f9d0) Line 300 + 0x1d bytes C++
EQ2WorldDebug.exe!_CrtDbgReportW(int nRptType=2, const wchar_t * szFile=0x00cac608, int nLine=245, const wchar_t * szModule=0x00000000, const wchar_t * szFormat=0x00cad050, ...) Line 317 + 0x1d bytes C++
EQ2WorldDebug.exe!std::_Debug_message(const wchar_t * message=0x00cad050, const wchar_t * file=0x00cac608, unsigned int line=245) Line 21 + 0x15 bytes C++
EQ2WorldDebug.exe!std::_Tree<std::_Tmap_traits<unsigned short,PacketStruct *,std::less<unsigned short>,std::allocator<std::pair<unsigned short const ,PacketStruct *> >,0> >::const_iterator::operator*() Line 245 + 0x14 bytes C++
EQ2WorldDebug.exe!std::_Tree<std::_Tmap_traits<unsigned short,PacketStruct *,std::less<unsigned short>,std::allocator<std::pair<unsigned short const ,PacketStruct *> >,0> >::iterator::operator*() Line 452 C++
EQ2WorldDebug.exe!std::_Tree<std::_Tmap_traits<unsigned short,PacketStruct *,std::less<unsigned short>,std::allocator<std::pair<unsigned short const ,PacketStruct *> >,0> >::iterator::operator->() Line 457 C++
EQ2WorldDebug.exe!Spawn::~Spawn() Line 97 + 0x8 bytes C++
EQ2WorldDebug.exe!Entity::~Entity() Line 48 + 0x3f bytes C++
EQ2WorldDebug.exe!NPC::~NPC() Line 107 + 0xf bytes C++
EQ2WorldDebug.exe!NPC::`scalar deleting destructor'() + 0x14 bytes C++
EQ2WorldDebug.exe!ZoneServer::DeleteSpawns(bool delete_all=false) Line 728 + 0x32 bytes C++
EQ2WorldDebug.exe!ZoneServer::SpawnProcess() Line 710 C++
EQ2WorldDebug.exe!SpawnLoop(void * tmp=0x06ab4018) Line 3514 + 0x8 bytes C++
EQ2WorldDebug.exe!_callthreadstart() Line 293 + 0xf bytes C
EQ2WorldDebug.exe!_threadstart(void * ptd=0x06ab7470) Line 277 C
kernel32.dll!77e64829()
And the entire Console session (1 connection):
Code: Select all
[Status] Using database 'eq2live' at mysqlx64.visionsmusicgroup.local
[20091005 04:34:55] [Status] CURRENT_WORLD_VERSION:EQ2EMu 0.6.5 Developer Alpha
[20091005 04:34:55] [Status] ./LoginServer.ini read.
[20091005 04:34:55] [Status] Connecting to Update Server..
[20091005 04:34:59] [Status] Connected to Update Server: updates.eq2emulator.
net:9103
[20091005 04:34:59] [Status] Checking for updates.
[20091005 04:35:02] [Status] Server is already up-to-date.
[20091005 04:35:02] [Status] Loading opcodes..
[20091005 04:35:05] [Status] Loading structs..
[20091005 04:35:10] [Status] Loading command list..
[20091005 04:35:10] [Status] Clearing player online flags..
[20091005 04:35:10] [Status] Loaded 526 entity command lists.
[20091005 04:35:11] [Status] Loaded 3613 NPC(s).
[20091005 04:35:11] [Status] Loaded 164 NPC Spell(s).
[20091005 04:35:11] [Status] Loaded 127 NPC Skill(s).
[20091005 04:35:11] [Status] Loaded 0 NPC Equipment Piece(s).
[20091005 04:35:12] [Status] Loaded 3598 NPC Appearance(s).
[20091005 04:35:12] [Status] Loaded 2453 NPC Equipment Appearance(s).
[20091005 04:35:12] [Status] Loaded 646 Object(s).
[20091005 04:35:12] [Status] Loaded 145 GroundSpawn(s).
[20091005 04:35:12] [Status] Loaded 356 Widget(s).
[20091005 04:35:12] [Status] Loaded 581 Sign(s).
[20091005 04:35:12] [Status] Loading ground spawn items..
[20091005 04:35:12] [Status] Loading loot data..
[20091005 04:35:12] [Status] Loaded 2 loot tables.
[20091005 04:35:12] [Status] Loaded 2 loot drops.
[20091005 04:35:12] [Status] Loaded 1673 spawn loot lists.
[20091005 04:35:12] [Status] Loading Transporter Information..
[20091005 04:35:12] [Status] Loaded 25 Teleporter(s)
[20091005 04:35:12] [Status] Loaded global variables list..
[20091005 04:35:13] [Status] Loaded visual states list..
[20091005 04:35:13] [Status] Loading World Time..
[20091005 04:35:13] [Status] Loading items.. (this might take a few minutes)
[20091005 04:35:32] [Status] Loaded 314 Bag(s)
[20091005 04:35:33] [Status] Loaded 2310 Food(s)
[20091005 04:35:33] [Status] Loaded 2237 Ranged Weapon(s)
[20091005 04:35:33] [Status] Loaded 127 Thrown Weapon(s)
[20091005 04:35:33] [Status] Loaded 17759 Weapon(s)
[20091005 04:35:34] [Status] Loaded 38950 Armor Piece(s)
[20091005 04:35:34] [Status] Loaded 4456 Shield Piece(s)
[20091005 04:35:34] [Status] Loaded 0 Skill Item(s)
[20091005 04:35:35] [Status] Loaded 12718 Regular Items
[20091005 04:35:35] [Status] Loading spells..
[20091005 04:35:43] [Status] Loaded 5522 Spell(s)
[20091005 04:35:43] [Status] Loading LUA spells..
[20091005 04:35:43] [Status] Loaded 27 LUA Spell(s)
[20091005 04:35:44] [Status] Loading factions..
[20091005 04:35:44] [Status] Loaded 205 Factions
[20091005 04:35:44] [Status] Loading skills..
[20091005 04:35:44] [Status] Loaded 129 Skills
[20091005 04:35:44] [Status] Loading Quests..
[20091005 04:35:45] [Status] Loaded 267 Quest(s)
[20091005 04:35:45] [Status] Loading Merchant Information..
[20091005 04:35:45] [Status] Loaded 3 Merchant Inventory Item(s)
[20091005 04:35:45] [Status] Loaded 1 Merchant List(s)
[20091005 04:35:45] [Status] Loading Spawn Script Information..
[20091005 04:35:45] [Status] Loading Zone Script Information..
[20091005 04:35:45] [Status] Loading EQ2 time of day..
Starting factory Reader
Starting factory Writer
[20091005 04:35:45] [Status] World server listening on: mmoemulators.com:9200
[20091005 04:35:45] [Status] World server listening on: 192.168.2.33:9200
[20091005 04:35:45] [Status] Starting static zones...
[20091005 04:35:48] [Status] Connected to LoginServer: eq2emulator.net: 9100
[20091005 06:55:20] [Status] AddAuth: 1452 Key: 1254750920
[20091005 06:55:22] [Status] New client from ip: 79.208.210.78 port: 65018
[20091005 06:55:22] [Status] Adding client to waiting list...
[20091005 06:55:22] [Status] Removing client from waiting list...
[20091005 06:55:23] [Debug] Creating OP_AppCombined Packet!
[20091005 06:55:23] [Debug] Combined App Packet!
[20091005 06:55:23] [Debug] Combined Packet: 2, 0![20091005 06:55:23] [Status]
ZoneAuth: Access Key: 1254750920, Character Name: Schnecke, Account ID: 1452
[20091005 06:55:23] [Status] Loading new Zone 'TimorousDeep'
[20091005 06:55:24] [Status] Loaded for zone 'TimorousDeep':
2199 NPC(s), 801 Object(s), 28 Widget(s)
18 Sign(s), 542 Ground Spawn(s), 0 Spawn Group(s)
0 Spawn Group Association(s), 0 Spawn Group Chance(s)
[20091005 06:55:26] [Debug] Combined Packet: 2, 0!
[20091005 06:55:26] [Debug] Combined Packet: 2, 0!
[20091005 06:55:26] [Status] OP_Unknown Received 0x0038
0: 01 00 00 00 48 44 | ....HD
[20091005 06:55:34] [Debug] Combined Packet: 2, 0!
[20091005 06:55:35] [Debug] Combined Packet: 2, 0!
0: CE 01 00 00 | ....
[20091005 06:55:36] [Status] Unhandled command: clearallqueuedabilities
[20091005 06:55:38] [Status] OP_Unknown Received 0x0466
0: 00 00 01 6A 00 00 00 00 - 00 00 00 | ...j.......
[20091005 06:55:38] [Debug] Combined Packet: 2, 0!
[20091005 06:55:38] [Status] OP_Unknown Received 0x0178
0: 00 00 | ..
0: CE 01 00 00 | ....
[20091005 06:55:39] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 30 | %...0
0: 23 00 01 00 31 | #...1
[20091005 06:55:39] [Status] OP_Unknown Received 0x0510
0: 0C 00 77 65 6C 63 6F 6D - 65 5F 74 69 6D 65 B1 B7 | ..welcome_time..
16: C1 00 00 00 00 00 | ......
[20091005 06:55:40] [Debug] [20091005 06:55:40] [Status] Combined Packet: 2, 0!U
nhandled command: clearallqueuedabilities
[20091005 06:55:41] [Debug] Fragmented Packet!
[20091005 06:55:41] [Debug] Fragmented Packet!
Left Grid 4294967295 and Entered Grid 1701767597
[20091005 06:55:45] [Debug] Fragmented Packet!
[20091005 06:55:45] [Debug] Fragmented Packet!
[20091005 06:55:47] [Debug] Fragmented Packet!
[20091005 06:55:47] [Debug] Fragmented Packet!
[20091005 06:55:50] [Debug] Fragmented Packet!
[20091005 06:55:50] [Debug] Fragmented Packet!
[20091005 06:55:50] [Debug] Creating Opcode 0 Packet!
[20091005 06:55:52] [Debug] Fragmented Packet!
[20091005 06:55:52] [Debug] Fragmented Packet!
[20091005 06:55:54] [Debug] Fragmented Packet!
[20091005 06:55:54] [Debug] Fragmented Packet!
[20091005 06:55:55] [Debug] Creating Opcode 0 Packet!
[20091005 06:55:56] [Debug] Fragmented Packet!
[20091005 06:55:56] [Debug] Fragmented Packet!
[20091005 06:55:59] [Debug] Fragmented Packet!
[20091005 06:55:59] [Debug] Fragmented Packet!
0: 29 00 03 00 61 6C 6C | )...all
0: CE 01 00 00 | ....
[20091005 06:56:12] [Status] Unhandled command: clearallqueuedabilities
0: 22 00 06 00 34 30 30 30 - 30 33 | "...400003
0: 22 00 06 00 34 30 30 30 - 30 33 | "...400003
0: 22 00 06 00 34 30 30 30 - 30 32 | "...400002
[20091005 06:56:45] [Status] OP_SatMsg Received 0x0171
[20091005 06:56:45] [Debug] Fragmented Packet!
[20091005 06:56:45] [Debug] Fragmented Packet!
0: CE 01 00 00 | ....
[20091005 06:57:02] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 30 | %...0
Delete char request: 1452 2989
Removing connection
[20091005 06:58:01] [Status] AddAuth: 1452 Key: 1254751081
[20091005 06:58:02] [Status] New client from ip: 79.208.210.78 port: 65018
[20091005 06:58:02] [Status] Adding new client...
[20091005 06:58:03] [Debug] Creating OP_AppCombined Packet!
[20091005 06:58:03] [Debug] Combined App Packet!
[20091005 06:58:03] [Debug] Combined Packet: 2, 0!
[20091005 06:58:03] [Status] ZoneAuth: Access Key: 1254751081, Character Name: S
chnecke, Account ID: 1452
[20091005 06:58:03] [Status] Zone: Removing client from ip: 79.208.210.78 port 6
5018
[20091005 06:58:04] [Debug] Combined Packet: 2, 0!
[20091005 06:58:04] [Status] OP_QuestJournalSetVisibleMsg Received 0x0108
0: 01 00 00 00 69 00 00 00 - 00 | ....i....
[20091005 06:58:04] [Status] OP_Unknown Received 0x0038
0: 01 00 00 00 48 44 | ....HD
[20091005 06:58:09] [Status] OP_Unknown Received 0x0466
0: 00 00 01 6A 00 00 00 00 - 00 00 00 | ...j.......
[20091005 06:58:09] [Debug] Combined Packet: 2, 0!
[20091005 06:58:10] [Debug] Combined Packet: 2, 0!
[20091005 06:58:10] [Status] OP_Unknown Received 0x0178
0: 00 00 | ..
0: CE 01 00 00 | ....
[20091005 06:58:10] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 30 | %...0
0: 23 00 01 00 31 | #...1
[20091005 06:58:12] [Debug] Fragmented Packet!
[20091005 06:58:12] [Debug] Fragmented Packet!
Left Grid 4294967295 and Entered Grid 1701767597
0: CE 01 00 00 | ....
[20091005 06:58:15] [Status] Unhandled command: clearallqueuedabilities
[20091005 06:58:21] [Debug] Fragmented Packet!
[20091005 06:58:21] [Debug] Fragmented Packet!
0: CE 01 00 00 | ....
[20091005 06:58:21] [Status] Unhandled command: clearallqueuedabilities
[20091005 06:58:25] [Debug] Fragmented Packet!
[20091005 06:58:25] [Debug] Fragmented Packet!
0: CE 01 00 00 | ....
[20091005 06:58:27] [Status] Unhandled command: clearallqueuedabilities
[20091005 06:58:27] [Debug] Fragmented Packet!
[20091005 06:58:27] [Debug] Fragmented Packet!
0: 25 00 01 00 31 | %...1
0: 25 00 01 00 31 | %...1
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 25 00 01 00 31 | %...1
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
[20091005 06:58:34] [Debug] Fragmented Packet!
[20091005 06:58:34] [Debug] Fragmented Packet!
0: 25 00 01 00 31 | %...1
[20091005 06:58:38] [Debug] Fragmented Packet!
[20091005 06:58:38] [Debug] Fragmented Packet!
0: 25 00 01 00 31 | %...1
0: 25 00 01 00 31 | %...1
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
[20091005 06:59:34] [Debug] Creating Opcode 0 Packet!
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: CE 01 00 00 | ....
[20091005 06:59:55] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 30 | %...0
[20091005 07:00:10] [Debug] Fragmented Packet!
[20091005 07:00:10] [Debug] Fragmented Packet!
[20091005 07:00:13] [Debug] Fragmented Packet!
[20091005 07:00:13] [Debug] Fragmented Packet!
[20091005 07:00:16] [Debug] Fragmented Packet!
[20091005 07:00:16] [Debug] Fragmented Packet!
[20091005 07:00:18] [Debug] Fragmented Packet!
[20091005 07:00:18] [Debug] Fragmented Packet!
[20091005 07:00:25] [Debug] Combined Packet: 2, 0!
[20091005 07:00:25] [Debug] Combined Packet: 2, 0!
[20091005 07:00:26] [Debug] Combined Packet: 2, 0!
[20091005 07:00:27] [Debug] Combined Packet: 2, 0!
0: 25 00 01 00 31 | %...1
0: CE 01 00 00 | ....
[20091005 07:00:32] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 31 | %...1
[20091005 07:00:35] [Debug] Combined Packet: 2, 0!
0: 25 00 01 00 31 | %...1
[20091005 07:00:36] [Debug] Fragmented Packet!
[20091005 07:00:36] [Debug] Fragmented Packet!
0: 25 00 01 00 31 | %...1
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 0A 01 00 00 | ....
[20091005 07:00:55] [Status] Unhandled command: refreshuidata
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
[20091005 07:01:50] [Debug] Combined Packet: 2, 0!
0: CE 01 00 00 | ....
[20091005 07:01:50] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 30 | %...0
0: CE 01 00 00 | ....
[20091005 07:01:54] [Status] Unhandled command: clearallqueuedabilities
0: CE 01 00 00 | ....
[20091005 07:01:54] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 30 | %...0
[20091005 07:01:56] [Debug] Combined Packet: 2, 0!
[20091005 07:02:00] [Debug] Creating Opcode 0 Packet!
0: CE 01 00 00 | ....
[20091005 07:02:06] [Status] Unhandled command: clearallqueuedabilities
0: CE 01 00 00 | ....
[20091005 07:02:12] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 30 | %...0
[20091005 07:02:27] [Debug] Combined Packet: 2, 0!
0: CE 01 00 00 | ....
[20091005 07:02:29] [Status] Unhandled command: clearallqueuedabilities
[20091005 07:02:29] [Debug] Fragmented Packet!
[20091005 07:02:29] [Debug] Fragmented Packet!
[20091005 07:02:29] [Debug] Creating Opcode 0 Packet!
0: CE 01 00 00 | ....
[20091005 07:02:39] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 31 | %...1
0: 25 00 01 00 31 | %...1
0: 25 00 01 00 31 | %...1
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
[20091005 07:02:56] [Debug] Combined Packet: 2, 0!
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 29 00 00 00 | )...
0: 29 00 03 00 61 6C 6C | )...all
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: CE 01 00 00 | ....
[20091005 07:03:45] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 30 | %...0
0: CE 01 00 00 | ....
[20091005 07:03:46] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 31 | %...1
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
[20091005 07:03:53] [Debug] Combined Packet: 2, 0!
[20091005 07:03:54] [Debug] Combined Packet: 2, 0!
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 33 38 30 30 - 30 30 | "...380000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: CE 01 00 00 | ....
[20091005 07:04:56] [Status] Unhandled command: clearallqueuedabilities
[20091005 07:04:56] [Debug] Combined Packet: 3, 0!
[20091005 07:04:57] [Debug] Combined Packet: 3, 0!
[20091005 07:04:57] [Debug] Combined Packet: 2, 0!
0: CE 01 00 00 | ....
[20091005 07:04:57] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 30 | %...0
0: CE 01 00 00 | ....
[20091005 07:04:57] [Status] Unhandled command: clearallqueuedabilities
0: CE 01 00 00 | ....
[20091005 07:04:59] [Status] Unhandled command: clearallqueuedabilities
0: 22 00 06 00 34 30 30 30 - 30 30 | "...400000
0: CE 01 00 00 | ....
[20091005 07:05:02] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 30 | %...0
0: CE 01 00 00 | ....
[20091005 07:05:04] [Status] Unhandled command: clearallqueuedabilities
0: CE 01 00 00 | ....
[20091005 07:05:06] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 30 | %...0
0: CE 01 00 00 | ....
[20091005 07:05:07] [Status] Unhandled command: clearallqueuedabilities
0: CE 01 00 00 | ....
[20091005 07:05:09] [Status] Unhandled command: clearallqueuedabilities
0: CE 01 00 00 | ....
[20091005 07:05:10] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 30 | %...0
0: CE 01 00 00 | ....
[20091005 07:05:12] [Status] Unhandled command: clearallqueuedabilities
[20091005 07:05:22] [Debug] Combined Packet: 2, 0!
[20091005 07:05:28] [Debug] Fragmented Packet!
[20091005 07:05:28] [Debug] Fragmented Packet!
[20091005 07:05:31] [Debug] Fragmented Packet!
[20091005 07:05:31] [Debug] Fragmented Packet!
[20091005 07:05:38] [Debug] Fragmented Packet!
[20091005 07:05:38] [Debug] Fragmented Packet!
[20091005 07:05:38] [Status] OP_SatMsg Received 0x0171
Removing connection
[20091005 07:08:00] [Status] Zone: Removing client from ip: 79.208.210.78 port 6
5018
[20091005 07:09:32] [Status] Initiating zone shutdown of 'TimorousDeep'
[20091005 07:10:04] [Error] Possible deadlock attempt by 'ZoneServer::MMasterSpa
wnLock'!
Seems to always be in this same spot - same as before the recent world updates I believe. mlock.c, like 348:
Code: Select all
/*
* Enter the critical section.
*/
EnterCriticalSection( _locktable[locknum].lock );
}
Going to force TimorousDeep to always_loaded for now.
Re: New Mutex code, Tess crashed!
Posted: Mon Oct 05, 2009 8:30 am
by erde
Hi,
that was me.
ZoneAuth: Access Key: 1254750920, Character Name: Schnecke, Account ID: 1452
The funny thing is,
- i logged in
- logged out
- delete my char
- cretead a new one with the same name!
- logged in and started from the same position with everything i got from the previous character
So the char was still the first created one, i think.
greetings Stefan
Re: New Mutex code, Tess crashed!
Posted: Mon Oct 05, 2009 8:50 am
by John Adams
Hmm that seems very strange. We've heard that before, but could never reproduce it. Almost like the server didn't recognize the delete. Since each new character generates a unique char_id, it should be impossible for LoginServer to confuse the two. Interesting.
UPDATE: Zones set to always_loaded, server is no longer crashing on client exit. So LE when you're ready to debug, we'll have to reset those zones.
Re: New Mutex code, Tess crashed!
Posted: Mon Oct 05, 2009 1:45 pm
by LethalEncounter
Ahh some left over locks. I'll see about getting rid of them as well.
Re: New Mutex code, Tess crashed!
Posted: Mon Oct 05, 2009 2:14 pm
by LethalEncounter
btw it is crashing when it is trying to delete your required quests. I'm looking into it now.
Re: New Mutex code, Tess crashed!
Posted: Mon Oct 05, 2009 2:53 pm
by Scatman
That's my fault LE. I re-arranged them to support multiple quests and multiple quest steps on a given quest so in ~Spawn() it is deleting them and I screwed that up like a newb! I can fix that if you haven't already, sorry. I am deleting the iterator that was used in the previous loop heh.
Re: New Mutex code, Tess crashed!
Posted: Mon Oct 05, 2009 3:26 pm
by LethalEncounter
lol I noticed it right after I made my post
Copy/paste 4tw
I'm making some additional fixes now, but it should be ready in a bit.
Re: New Mutex code, Tess crashed!
Posted: Mon Oct 05, 2009 4:50 pm
by John Adams
Scatman wrote:I re-arranged them to support multiple quests and multiple quest steps on a given quest so in ~Spawn() it is deleting them
So for a week I have been crying like a school girl about zones crashing at ~Spawn(), and NOW you mention this?
/nutpunt
Re: New Mutex code, Tess crashed!
Posted: Mon Oct 05, 2009 6:40 pm
by Scatman
k thanks
Copy/paste can be your best friend or worst enemy
Lol sorry John, right when you mentioned ~Spawn() and LE mentioned the required quests I gasped and said 'oh shit'.
Re: New Mutex code, Tess crashed!
Posted: Wed Oct 07, 2009 5:19 pm
by Scatman
I'm on TessDev and I keep getting client crashes or just disconnects. Sometimes I zone in, and get that "Cannot deserialize" message.
Another time I zoned in, did a /zone oakmyst and got booted upon zoning into Oakmyst. Here's what the console said:
Code: Select all
0: 14 00 07 00 6F 61 6B 6D - 79 73 74 | ....oakmyst
Zone access check for oakmyst
Grabbing zone requirements for oakmyst
Zone Requirements: 0 status to override negative status requirement, 0 status to override level requirement.
[20091007 17:15:31] [Status] Loading new Zone 'oakmyst'
[New Thread 0xa64f9b90 (LWP 6031)]
[New Thread 0xa5af8b90 (LWP 6032)]
[New Thread 0xa50f7b90 (LWP 6033)]
[20091007 17:15:32] [Status] Loaded for zone 'oakmyst':
304 NPC(s), 86 Object(s), 2 Widget(s)
4 Sign(s), 141 Ground Spawn(s), 8 Spawn Group(s)
4 Spawn Group Association(s), 0 Spawn Group Chance(s)
[20091007 17:15:32] [Status] AddAuth: 25 Key: 1254960932
[20091007 17:15:32] [Status] OP_ReadyToZone: Player Scatmann zoning to oakmyst
[20091007 17:15:32] [Status] Zone: Removing client from ip: 98.244.105.129 port 1440
[20091007 17:15:32] [Status] New client from ip: 98.244.105.129 port: 1440
[20091007 17:15:32] [Status] Adding new client...
[20091007 17:15:34] [Status] ZoneAuth: Access Key: 1254960932, Character Name: Scatmann, Account ID: 25
[20091007 17:15:34] [Status] OP_Unknown Received 0x0038
0: 01 00 00 00 96 43 | .....C
[New Thread 0xa46f6b90 (LWP 6034)]
[Thread 0xa46f6b90 (LWP 6034) exited]
[20091007 17:15:43] [Debug] Creating OP_AppCombined Packet!
[20091007 17:15:43] [Debug] Combined App Packet!
[20091007 17:15:44] [Status] OP_Unknown Received 0x0179
0: 00 00 | ..
[20091007 17:15:45] [Debug] Creating OP_AppCombined Packet!
[20091007 17:15:45] [Debug] Combined App Packet!
0: 62 01 00 00 | b...
[20091007 17:15:45] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 30 | %...0
0: 23 00 01 00 31 | #...1
[20091007 17:15:45] [Status] Zone: Finishing removal of client 'Scatmann'.
Removing connection
[20091007 17:16:02] [Status] Zone: Finishing removal of client 'Scatmann'.
Not sure if this is of any use to you but here's what my AlertLog.txt is telling me
Code: Select all
build="SOEBuild=5916L" version="SOEVersionString=2009/9/24 17:56:49" build_type="USER OPTIMIZED" ls_address="none" zone="ZoneScene::onOpen" loc=" 0.00 0.00 0.00" performance="6" alert="E:\live\eq2\game\gamecommon\client\EqSpellCast.cpp(97): ERROR - Unable to load spell cast 'clientvdl/spellvisuals/expansion_06/vd_amputation.vdl'."
build="SOEBuild=5916L" version="SOEVersionString=2009/9/24 17:56:49" build_type="USER OPTIMIZED" ls_address="none" zone="GameScene::ZR_NETWORKED_ZONE_CHANGE" loc="-124.68 59.82 -890.29" performance="6" alert="E:\live\eq2\game\client\src\GameScene.cpp(27192): Out of bounds macro index; ignoring"
build="SOEBuild=5916L" version="SOEVersionString=2009/9/24 17:56:49" build_type="USER OPTIMIZED" ls_address="none" zone="GameScene::ZR_NETWORKED_ZONE_CHANGE" loc="-124.68 59.82 -890.29" performance="6" alert="E:\live\eq2\game\client\src\GameScene.cpp(27522): Tried to set hotkey out of bounds (bank 179, slot 251); ignoring"
build="SOEBuild=5916L" version="SOEVersionString=2009/9/24 17:56:49" build_type="USER OPTIMIZED" ls_address="none" zone="GameScene::ZR_NETWORKED_ZONE_CHANGE" loc="-124.68 59.82 -890.29" performance="6" alert="E:\live\eq2\game\client\src\GameScene.cpp(27522): Tried to set hotkey out of bounds (bank 225, slot 140); ignoring"
build="SOEBuild=5916L" version="SOEVersionString=2009/9/24 17:56:49" build_type="USER OPTIMIZED" ls_address="none" zone="GameScene::ZR_NETWORKED_ZONE_CHANGE" loc="-124.68 59.82 -890.29" performance="6" alert="E:\live\eq2\game\client\src\GameScene.cpp(27522): Tried to set hotkey out of bounds (bank 98, slot 20); ignoring"
build="SOEBuild=5916L" version="SOEVersionString=2009/9/24 17:56:49" build_type="USER OPTIMIZED" ls_address="none" zone="qey_adv01_oakmyst" loc=" 0.00 0.00 0.00" performance="6" alert="E:\live\eq2\game\client\src\GameScene.cpp(17861): CRC missmatch in EqCreateGhostCmd state buf."
build="SOEBuild=5916L" version="SOEVersionString=2009/9/24 17:56:49" build_type="USER OPTIMIZED" ls_address="none" zone="qey_adv01_oakmyst" loc=" -2.37 1.23 -4.40" performance="6" alert="E:\live\eq2\game\client\src\ZoneScene.cpp(5293): Camera is not in a room."
build="SOEBuild=5916L" version="SOEVersionString=2009/9/24 17:56:49" build_type="USER OPTIMIZED" ls_address="none" zone="qey_adv01_oakmyst" loc=" -2.37 1.23 -4.40" performance="6" alert="E:\live\eq2\game\gamecommon\client\CompressedXOR.cpp(243): Bogus compressed data. This is normally caused by mismatched client and server."
build="SOEBuild=5916L" version="SOEVersionString=2009/9/24 17:56:49" build_type="USER OPTIMIZED" ls_address="none" zone="qey_adv01_oakmyst" loc=" -0.79 1.23 -1.48" performance="6" alert="E:\live\eq2\game\client\UI\src\Eq2GuiCompassWindow.cpp(111): Camera is not in a room."
build="SOEBuild=5916L" version="SOEVersionString=2009/9/24 17:56:49" build_type="USER OPTIMIZED" ls_address="none" zone="qey_adv01_oakmyst" loc="860.67 3.50 -191.58" performance="6" alert="E:\live\eq2\game\client\src\ProxyActor.cpp(5644): Widget 'inspect_rock_poem' has same widget id (985534865) as another 'inspect_rock_poem'"
build="SOEBuild=5916L" version="SOEVersionString=2009/9/24 17:56:49" build_type="USER OPTIMIZED" ls_address="none" zone="qey_adv01_oakmyst" loc="794.51 9.39 -204.57" performance="6" alert="E:\live\eq2\game\client\src\GameScene.cpp(12489): Unhandled client cmd 0, last: 560"
build="SOEBuild=5916L" version="SOEVersionString=2009/9/24 17:56:49" build_type="USER OPTIMIZED" ls_address="none" zone="qey_adv01_oakmyst" loc="794.51 9.39 -204.57" performance="6" alert="E:\live\eq2\game\client\src\GameScene.cpp(12489): Unhandled client cmd 0, last: 0"
Re: New Mutex code, Tess crashed!
Posted: Thu Oct 08, 2009 1:15 pm
by John Adams
Big nasty ugly crash of a whole new kind on TessEQ2 (Live) test server. Here's the details I can muster.
crash.jpg
Console 2 Zones running, 1 client:
Code: Select all
[20091007 18:46:37] [Status] AddAuth: 5108 Key: 1254966397
0: 62 01 00 00 | b...
[20091007 18:46:37] [Status] Unhandled command: clearallqueuedabilities
[20091007 18:46:38] [Status] OP_ReadyToZone: Player Fretta zoning to SouthQeynos
[20091007 18:46:38] [Status] Zone: Removing client from ip: 65.24.39.181 port 62
977
[20091007 18:46:38] [Status] New client from ip: 65.24.39.181 port: 62977
[20091007 18:46:38] [Status] Adding new client...
[20091007 18:46:39] [Status] ZoneAuth: Access Key: 1254966397, Character Name: F
retta, Account ID: 5108
[20091007 18:46:41] [Status] OP_Unknown Received 0x0038
0: 01 00 00 00 C8 43 | .....C
[20091007 18:46:54] [Debug] Creating OP_AppCombined Packet!
[20091007 18:46:54] [Debug] Combined App Packet!
[20091007 18:46:54] [Status] OP_Unknown Received 0x0179
0: 00 00 | ..
[20091007 18:46:55] [Debug] Creating OP_AppCombined Packet!
[20091007 18:46:55] [Debug] Combined App Packet!
0: 62 01 00 00 | b...
[20091007 18:46:55] [Status] Unhandled command: clearallqueuedabilities
0: 25 00 01 00 30 | %...0
0: 23 00 01 00 31 | #...1
[20091007 18:46:57] [Debug] Creating OP_AppCombined Packet!
[20091007 18:46:57] [Debug] Combined App Packet!
Left Grid 4294967295 and Entered Grid 4181623745
[20091007 18:47:04] [Status] Initiating zone shutdown of 'QueensColony'
[20091007 18:47:05] [Status] Completed zone shutdown of 'QueensColony'
[20091007 18:47:06] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:06] [Debug] Combined App Packet!
[20091007 18:47:08] [Status] Zone: Finishing removal of client 'Fretta'.
[20091007 18:47:09] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:09] [Debug] Combined App Packet!
[20091007 18:47:11] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:11] [Debug] Combined App Packet!
[20091007 18:47:11] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:11] [Debug] Combined App Packet!
[20091007 18:47:13] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:13] [Debug] Combined App Packet!
[20091007 18:47:16] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:16] [Debug] Combined App Packet!
[20091007 18:47:18] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:18] [Debug] Combined App Packet!
[20091007 18:47:20] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:20] [Debug] Combined App Packet!
Left Grid 4181623745 and Entered Grid 1003686961
[20091007 18:47:22] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:22] [Debug] Combined App Packet!
[20091007 18:47:24] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:24] [Debug] Combined App Packet!
[20091007 18:47:27] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:27] [Debug] Combined App Packet!
[20091007 18:47:27] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:27] [Debug] Combined App Packet!
[20091007 18:47:29] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:29] [Debug] Combined App Packet!
[20091007 18:47:29] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:29] [Debug] Combined App Packet!
[20091007 18:47:31] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:31] [Debug] Combined App Packet!
[20091007 18:47:33] [Debug] Creating OP_AppCombined Packet!
[20091007 18:47:33] [Debug] Combined App Packet!
[20091007 18:47:54] [Debug] Creating Opcode 0 Packet!
[20091007 18:48:05] [Debug] Creating OP_AppCombined Packet!
[20091007 18:48:05] [Debug] Combined App Packet!
[20091007 18:48:09] [Status] Initiating zone shutdown of 'Nettleville'
Stack:
Code: Select all
ntdll.dll!7c81a3e1()
[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]
ntdll.dll!7c878921()
ntdll.dll!7c853045()
ntdll.dll!7c83e6d5()
ntdll.dll!7c879f3f()
ntdll.dll!7c879f23()
> EQ2WorldDebug.exe!_heap_alloc_dbg(unsigned int nSize=0, int nBlockUse=218103905, const char * szFileName=0x0000003c, int nLine=1675451048) Line 475 + 0x7 bytes C++
ntdll.dll!7c879f23()
ntdll.dll!7c8684d3()
ntdll.dll!7c879eb4()
ntdll.dll!7c82a0fc()
EQ2WorldDebug.exe!std::_Bidit<std::pair<Spawn * const,int>,int,std::pair<Spawn * const,int> const *,std::pair<Spawn * const,int> const &>::_Bidit<std::pair<Spawn * const,int>,int,std::pair<Spawn * const,int> const *,std::pair<Spawn * const,int> const &>() + 0x14 bytes C++
ntdll.dll!7c83e76e()
ntdll.dll!7c83e7f5()
ntdll.dll!7c878c6b()
ntdll.dll!7c879f3f()
ntdll.dll!7c879f23()
ntdll.dll!7c83e5d0()
ntdll.dll!7c879f3f()
ntdll.dll!7c879f23()
ntdll.dll!7c8684d3()
ntdll.dll!7c858398()
ntdll.dll!7c8070bc()
ntdll.dll!7c80705f()
EQ2WorldDebug.exe!_free_base(void * pBlock=0x63dd5ab0) Line 109 + 0x12 bytes C
EQ2WorldDebug.exe!_free_dbg_nolock(void * pUserData=0x63dd5ad0, int nBlockUse=1) Line 1329 + 0x9 bytes C++
EQ2WorldDebug.exe!_free_dbg(void * pUserData=0x63dd5ad0, int nBlockUse=1) Line 1194 + 0xd bytes C++
EQ2WorldDebug.exe!operator delete(void * pUserData=0x63dd5ad0) Line 54 + 0x10 bytes C++
EQ2WorldDebug.exe!std::allocator<std::_Tree_nod<std::_Tmap_traits<Spawn *,VisualStateList *,std::less<Spawn *>,std::allocator<std::pair<Spawn * const,VisualStateList *> >,0> >::_Node>::deallocate(std::_Tree_nod<std::_Tmap_traits<Spawn *,VisualStateList *,std::less<Spawn *>,std::allocator<std::pair<Spawn * const,VisualStateList *> >,0> >::_Node * _Ptr=0x63dd5ad0, unsigned int __formal=1) Line 141 + 0x9 bytes C++
EQ2WorldDebug.exe!std::_Tree<std::_Tmap_traits<Spawn *,VisualStateList *,std::less<Spawn *>,std::allocator<std::pair<Spawn * const,VisualStateList *> >,0> >::_Erase(std::_Tree_nod<std::_Tmap_traits<Spawn *,VisualStateList *,std::less<Spawn *>,std::allocator<std::pair<Spawn * const,VisualStateList *> >,0> >::_Node * _Rootnode=0x63dd5ad0) Line 1079 C++
EQ2WorldDebug.exe!std::_Tree<std::_Tmap_traits<Spawn *,VisualStateList *,std::less<Spawn *>,std::allocator<std::pair<Spawn * const,VisualStateList *> >,0> >::_Erase(std::_Tree_nod<std::_Tmap_traits<Spawn *,VisualStateList *,std::less<Spawn *>,std::allocator<std::pair<Spawn * const,VisualStateList *> >,0> >::_Node * _Rootnode=0x63d209c0) Line 1076 C++
EQ2WorldDebug.exe!std::_Tree<std::_Tmap_traits<Spawn *,VisualStateList *,std::less<Spawn *>,std::allocator<std::pair<Spawn * const,VisualStateList *> >,0> >::clear() Line 955 C++
EQ2WorldDebug.exe!MutexMap<Spawn *,VisualStateList *>::update() Line 154 C++
EQ2WorldDebug.exe!MutexMap<Spawn *,VisualStateList *>::iterator::iterator(MutexMap<Spawn *,VisualStateList *> * map=0x639d29e8) Line 48 C++
EQ2WorldDebug.exe!MutexMap<Spawn *,VisualStateList *>::begin() Line 118 + 0xc bytes C++
EQ2WorldDebug.exe!ZoneServer::CheckVisualStateLoop() Line 3222 + 0x12 bytes C++
EQ2WorldDebug.exe!ZoneServer::SpawnProcess() Line 696 C++
EQ2WorldDebug.exe!SpawnLoop(void * tmp=0x639d2878) Line 3521 + 0x8 bytes C++
EQ2WorldDebug.exe!_callthreadstart() Line 293 + 0xf bytes C
EQ2WorldDebug.exe!_threadstart(void * ptd=0x5fbe0e90) Line 277 C
kernel32.dll!77e64829()
Server still in this state, until LE says he has no time tonight to look at it. Then I'll restart the server again for players.