New Telons New Behavior

[John Adams]

The last couple of outages for NT have been no crash, simply hung server processes. The code, from a console perspective, is running fine. Last night, looks like there were 3 clients across 2 chunks. At around 19:30 hours, a mutex error was thrown (this is the primary symptom each time)

[quote]19:22:38.510 D Chunk Camp started for character 'Schiller'
19:22:58.774 D Chunk Camping out character 'Schiller'
19:22:58.774 D Char ToggleIsOnline: Setting player offline
19:22:58.790 D Char No abilities need saving for 'Schiller' (356)
19:22:58.790 D Char Saved successful for character 'Schiller' (356)
19:22:58.790 D Guilds Schiller is not in a guild.
19:22:58.805 D Char ToggleIsOnline: Setting player offline
19:22:58.805 I UDP Client from xxx:52135 set to disconnect : Application
19:23:01.816 I UDP Client from xxx:52135 has been removed.
19:23:01.863 I Chunk Starting chunk shutdown timer for Plains of Anguish.
19:24:10.423 I UDP Client from xxx:58685 set to disconnect : Timeout
19:24:12.451 I UDP Client from xxx:58685 has been removed.
19:24:15.774 I UDP New client connected from xxx:60712
19:24:15.774 I UDP Received session request from xxx:60712 with connection ID 169018090
19:25:25.457 I UDP Client from xxx:60712 set to disconnect : Timeout
19:25:27.485 I UDP Client from xxx:60712 has been removed.
19:28:01.888 I Chunk Shutdown timer expired. Shutting down Plains of Anguish.
19:28:11.903 E Mutex Timeout trying to acquire mutex ChunkServerList::remove_chunk_s's write lock lock after 10000 milliseconds[/quote]

The last player logged off shortly after, making me think the chunk he was in was still running fine:
[quote]19:40:42.804 D Chunk Camp started for character 'Theun'
19:41:03.333 D Chunk Camping out character 'Theun'
19:41:03.333 D Char ToggleIsOnline: Setting player offline
19:41:03.333 D Char No abilities need saving for 'Theun' (110)
19:41:03.504 D Char Saved successful for character 'Theun' (110)
19:41:03.520 D Guilds Theun is not in a guild.
19:41:03.520 D Char ToggleIsOnline: Setting player offline
19:41:03.520 I UDP Client from xxx:59057 set to disconnect : Application
19:41:06.390 I UDP Client from xxx:59057 has been removed.
19:41:11.554 I Chunk Starting chunk shutdown timer for Khal.
19:41:45.966 I UDP Client from xxx:55790 set to disconnect : Timeout
19:41:47.994 I UDP Client from xxx:55790 has been removed.
19:46:11.561 I Chunk Shutdown timer expired. Shutting down Khal.[/quote]
And that was all she wrote. New Telon, according to LoginServer, was DOWN. Although from my end, no crash. Seems like the server got hung up in whatever the mutex was and would not accept anymore incoming packets of any kind, making Login think it was offline.

Sadly, this never happens when I am sitting there logged in, but always 100% of the time, the moment I turn off the monitor and walk away for the evening. Sorry to those players trying to check the game out... but there's no way to auto-restart of the world server doesn't crash

[zippyzee]

I'm seeing a number of mutex errors lately that I never saw before, and some can't even describe what they were trying to lock.

I've also had 2 server "crashes" where the client went to login but the server remained running. That is also new to me. My character abilities disappeared off my hotbar permanently after one, other than a custom made one.

[John Adams]

NT is stuck on rev 1612 until we finish our local testing and get our branches merged back. I know this has happened long before 1612 though, and generally speaking we get 100+ connections before we encounter crashes or lock ups so it's extremely random. I'd love to nail down a reproducible scenario. The player above even /camped out properly - though camp timers have always been suspicious of poor behavior. Maybe some of our more recent "kill the client connection" attempts buggered a valid disconnect?

[John Adams]

Here it is again; dead and crashed, out of the blue after 143 successful connections. Sure wish this stack was a little more informative.

SVN Rev 1612

Call Stack

Code: Select all

 	ntdll.dll!00000000774d96f8()	Unknown
 	ntdll.dll!000000007749b9ea()	Unknown
>	WorldServer.exe!Mutex::WriteUnlock() Line 215	C++
 	WorldServer.exe!ChunkServerList::Process() Line 164	C++
 	WorldServer.exe!main(int argc, char * * argv) Line 288	C++
 	WorldServer.exe!__tmainCRTStartup() Line 241	C
 	WorldServer.exe!mainCRTStartup() Line 164	C
 	kernel32.dll!0000000077305a4d()	Unknown
 	ntdll.dll!000000007743b831()	Unknown

Thread list:

Code: Select all

Not Flagged		4080	0	Worker Thread	ntdll.dll thread	ntdll.dll!000000007745df6a	Normal
Not Flagged	>	3080	0	Main Thread	Main Thread	WorldServer.exe!Mutex::WriteUnlock	Normal
Not Flagged		3348	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		2508	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		852	0	Worker Thread	WorldServer.exe!_threadstart	mswsock.dll!000007fefc94c699	Normal
Not Flagged		2644	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		4176	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!_read_nolock	Normal
Not Flagged		3196	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!_lock	Normal
Not Flagged		3268	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		2960	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3572	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		2892	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		4588	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		2760	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		4108	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		2860	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		2764	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		2244	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3860	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		2220	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3908	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		1620	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		4004	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3716	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3200	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		4884	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		2444	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		620	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3692	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		4256	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		4548	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3040	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3396	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		1396	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		4672	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		4516	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		2492	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		5064	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		4532	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3620	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3416	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3740	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		4732	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!std::map<unsigned int,Rule * __ptr64,std::less<unsigned int>,std::allocator<std::pair<unsigned int const ,Rule * __ptr64> > >::operator[]	Normal
Not Flagged		3640	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		2916	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3372	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		1512	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3260	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!_free_base	Normal
Not Flagged		1632	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3316	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		2624	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		1872	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		4284	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal
Not Flagged		3628	0	Worker Thread	WorldServer.exe!_threadstart	WorldServer.exe!SleepMS	Normal

Code:

Code: Select all

    //Remove old chunk servers    if (!remove_chunk_servers.empty()){        m_remove_chunk_servers.WriteLock();        m_chunk_servers.WriteLock();        for (auto& itr2 : remove_chunk_servers)            chunk_servers.erase(itr2->GetChunkID());        m_chunk_servers.WriteUnlock();        remove_chunk_servers.clear();        m_remove_chunk_servers.WriteUnlock();    }

Console:
[quote]18:09:57.200 W Mover PendulumMoverProcessor detected mover with move time decimals, legacy_mover_id=
18:09:57.200 W Mover PendulumMoverProcessor detected mover with move time decimals, legacy_mover_id=
18:09:57.200 W Mover PendulumMoverProcessor detected mover with move time decimals, legacy_mover_id=
18:09:57.200 W Mover PendulumMoverProcessor detected mover with move time decimals, legacy_mover_id=
18:09:57.200 W Mover PendulumMoverProcessor detected mover with move time decimals, legacy_mover_id=
18:09:57.200 W Mover PendulumMoverProcessor detected mover with move time decimals, legacy_mover_id=
18:09:57.200 W Mover PendulumMoverProcessor detected mover with move time decimals, legacy_mover_id=
18:09:57.200 D Mover 212 Movers Loaded in Chunk ID: 30
18:10:07.527 D Command Player 'Kavin Magius' used command '.rift' (1)
18:10:07.527 D Command Player 'Kavin' .rift to chunk 30 (The Tomb of Lord Tsang)
18:10:13.455 I Chunk Shutdown timer expired. Shutting down Tauthien Delta.
18:10:18.914 I Chunk Shutdown timer expired. Shutting down Skawlra Rock.
18:10:18.930 I Chunk Shutdown timer expired. Shutting down Martok.
18:10:47.571 D Command Player 'Kavin Magius' used command '.rift' (1)
18:10:47.571 D Command Player 'Kavin' .rift to chunk 31 (Hasium's Hideout)
18:10:47.571 D Chunk Loading Unreal File List for Chunk 31
18:10:47.571 D Chunk Starting chunk 'Hasium's Hideout' (31)
18:10:47.618 D NPC 17 NPCs Loaded in Chunk ID: 31
18:10:47.742 D PPO 3175 PPOs Loaded in Chunk ID: 31
18:10:47.742 D Music 1 Music Tracks Loaded in Chunk ID: 31
18:10:47.742 D Sound 3 Sounds Loaded in Chunk ID: 31
18:10:47.758 D Mover 213 Movers Loaded in Chunk ID: 31
18:10:52.625 I Chunk Starting chunk shutdown timer for Hasium's Hideout.
18:10:55.480 D Command Player 'Kavin Magius' used command '.rift' (1)
18:10:55.480 D Command Player 'Kavin' .rift to chunk 30 (The Tomb of Lord Tsang)
18:10:55.605 I UDP Client from 68.134.58.99:54597 set to disconnect : Application
18:10:55.620 I UDP New client connected from 68.134.58.99:54598
18:10:55.620 I UDP Received session request from 68.134.58.99:54598 with connection ID 1353848513
18:10:55.683 I Chunk Chunk shutdown cancelled for The Tomb of Lord Tsang.
18:10:55.807 I Chunk New Session: Account ID: 721 Session ID: '7b32e5ts11ig9u2cqtiajk9rb4'
18:10:55.932 I UDP Client from 68.134.58.99:54598 set to disconnect : Application
18:10:55.948 I UDP New client connected from 68.134.58.99:54599
18:10:55.948 I UDP Received session request from 68.134.58.99:54599 with connection ID 1359193139
18:10:56.150 I Chunk New Session: Account ID: 721 Session ID: '7b32e5ts11ig9u2cqtiajk9rb4'
18:10:56.275 18:10:56.275 I I UDP 18:10:56.275 UDP New client connected from 68.134.58.99:54600
I Client from 68.134.58.99:54599 set to disconnect : Application
Chunk Chunk shutdown cancelled for Hasium's Hideout.
18:10:56.275 I UDP Received session request from 68.134.58.99:54600 with connection ID 1365041975
18:10:56.462 I Chunk New Session: Account ID: 721 Session ID: '7b32e5ts11ig9u2cqtiajk9rb4'
18:10:56.587 I UDP Client from 68.134.58.99:54600 set to disconnect : Application
18:10:56.587 I UDP New client connected from 68.134.58.99:54601
18:10:56.587 I UDP Received session request from 68.134.58.99:54601 with connection ID 1370252145
18:10:56.790 I Chunk New Session: Account ID: 721 Session ID: '7b32e5ts11ig9u2cqtiajk9rb4'
18:10:57.008 D Chunk control_text='HELLO REVISION=0 MINVER=3151 VER=3186'
18:10:57.196 D Chunk control_text='LOGIN'
18:10:58.054 I UDP Client from 68.134.58.99:54597 has been removed.
18:10:58.085 I Chunk Starting chunk shutdown timer for Ceros Isle.
18:10:58.256 I UDP Client from 68.134.58.99:54598 has been removed.
18:10:58.724 I UDP Client from 68.134.58.99:54600 has been removed.
18:10:59.270 I UDP Client from 68.134.58.99:54599 has been removed.
18:11:01.345 D Chunk control_text='JOIN'
18:11:01.361 D Char Load World Time...
18:11:03.841 I Chunk Starting chunk shutdown timer for Hasium's Hideout.
18:11:24.276 I Chunk Shutdown timer expired. Shutting down Grimsea Watch.
18:11:31.265 D Command Player 'Kavin Magius' used command '.rift' (1)
18:12:21.465 D Char No abilities need saving for 'Kavin Magius' (1223)
18:12:21.481 D Char Saved successful for character 'Kavin Magius' (1223)
18:12:40.185 I Chunk Shutdown timer expired. Shutting down Tanvu.
18:12:40.543 I Chunk Shutdown timer expired. Shutting down Tanvu Bay.
18:12:40.668 I Chunk Shutdown timer expired. Shutting down Ceros Isle.
18:12:40.871 I Chunk Shutdown timer expired. Shutting down Shang Village.
18:12:41.682 I Chunk Shutdown timer expired. Shutting down Ceros Isle.
18:12:50.558 E Mutex Timeout trying to acquire mutex ChunkServerList::remove_chunk_s's write lock lock after 10000 mi
lliseconds[/quote]

[zippyzee]

I'm going to add some debug statements in the area where I think this might be failing. Whenever I have a few more fixes in I'll send it up.

[John Adams]

I know I also need to update NT, but I'm hesitant with all the current work on SVN, though it seems very stable in our Targonor testing.