World Server Disconnects

**trevius** · #1 09-19-2008, 06:37 PM

I am not sure what is causing this, but recently I started noticing an much high frequency of World Server Disconnects on my server. I have seen these in the past, but it was pretty rare and only happened when I was using the admin tool that comes with the emulator to search for accounts/character names. Now they are occurring randomly every 1 to 4 hours it seems. I can't seem to find any common thing that could be causing this.

When this happens, it doesn't crash the zones, but it does crash anyone that tries to zone. Then they can log back in again. But, it gets very annoying I am sure to people who box 3 characters and have to relog each one every couple of hours.

Here is what I am seeing in game:

Code:

ZServer BROADCASTS, 'WARNING: World server connection lost'

Zone connect: Dreadspire Keep
Zone connect: Nexus
Zone connect: Crushbone
Zone connect: The Plane of Time
Zone connect: Guild Hall

Etc until it lists all dynamic zones in use.

And here are some of the logs from when that has happened:

These are 4 different times that it occured

Code:

20823 [09.18. - 18:30:35] Starting Log: logs/eqemu_debug_world.log
28494 [09.18. - 23:38:09] Starting Log: logs/eqemu_debug_world.log
31091 [09.19. - 01:14:53] Starting Log: logs/eqemu_debug_world.log
4111 [09.19. - 04:42:48] Starting Log: logs/eqemu_debug_world.log

And here are more detailed logs from when those occur (note that I changed all player names in these logs to "Player"):

Code:

4260 [09.18. - 18:30:25] OP CastSpell: slot=3, spell=262, target=326, inv=ffffffff
4240 [09.18. - 18:30:25] DeleteItemInInventory(300, 1, true)
4240 [09.18. - 18:30:25] DeleteItemInInventory(317, 1, true)
4240 [09.18. - 18:30:25] DeleteItemInInventory(319, 1, true)
4240 [09.18. - 18:30:25] DeleteItemInInventory(313, 1, true)
4252 [09.18. - 18:30:25] Client::AddMoneyToPP() Player should have:  plat:391 gold:66 silver:71 copper:77
4218 [09.18. - 18:30:26] Client::AddMoneyToPP() Player should have:  plat:2872 gold:339 silver:422 copper:445
4252 [09.18. - 18:30:27] Client::AddMoneyToPP() Player should have:  plat:391 gold:66 silver:71 copper:77
4206 [09.18. - 18:30:27] Player Player has died and will be zoned to bind point in zone: Nexus at LOC x=0.000000, y=0.000000, z=-28.000000, heading=0.000000
4206 [09.18. - 18:30:27] Player Player has requested a zoning to LOC x=0.000000, y=0.000000, z=-28.000000, heading=0.000000 in zoneid=152
4206 [09.18. - 18:30:28] Zone request from Sayin
4206 [09.18. - 18:30:28] Client::AddMoneyToPP() Player should have:  plat:125 gold:183 silver:192 copper:67
4246 [09.18. - 18:30:29] OP CastSpell: slot=2, spell=3391, target=779, inv=ffffffff
4246 [09.18. - 18:30:29] OP CastSpell: slot=5, spell=524, target=1141, inv=ffffffff
4206 [09.18. - 18:30:29] AIYellForHelp("Emperor_Crush000","Player's corpse453") Ambassador_DVinn000 attacking Player's corpse453 Dist 24.936730 Z 67.119133
4206 [09.18. - 18:30:29] AIYellForHelp("Emperor_Crush000","Player's corpse453") The_Prophet000 attacking Player's corpse453 Dist 0.899057 Z 67.568897
4206 [09.18. - 18:30:29] AIYellForHelp("Emperor_Crush000","Player's corpse453") orc_legionnaire003 attacking Player's corpse453 Dist 16.603519 Z 66.166519
4240 [09.18. - 18:30:29] DeleteItemInInventory(300, 1, true)
4240 [09.18. - 18:30:29] DeleteItemInInventory(317, 1, true)
4240 [09.18. - 18:30:29] DeleteItemInInventory(319, 1, true)
4240 [09.18. - 18:30:29] DeleteItemInInventory(313, 1, true)
4252 [09.18. - 18:30:31] Player has a melee rune spell buff with 1800 points remaining.
4252 [09.18. - 18:30:31] Player has a melee rune spell buff with 1500 points remaining.
4252 [09.18. - 18:30:31] Member of group 58001 named 'Player' had an out of date pointer!!
4198 [09.18. - 18:30:31] Client::AddMoneyToPP() Player should have:  plat:2359 gold:124 silver:119 copper:149
4266 [09.18. - 18:30:31] Player Player has requested a zoning to LOC x=158.000000, y=-644.000000, z=4.000000, heading=0.000000 in zoneid=58
4266 [09.18. - 18:30:31] Zone request from Player
4266 [09.18. - 18:30:31] Client::AddMoneyToPP() Player should have:  plat:56 gold:45 silver:59 copper:50
4198 [09.18. - 18:30:33] OP CastSpell: slot=10, spell=5146, target=0, inv=16
4252 [09.18. - 18:30:33] OP CastSpell: slot=10, spell=1940, target=44, inv=c
4206 [09.18. - 18:30:35] AIYellForHelp("Emperor_Crush000","Player's corpse453") Ambassador_DVinn000 attacking Player's corpse453 Dist 24.936730 Z 67.119133
4206 [09.18. - 18:30:35] AIYellForHelp("Emperor_Crush000","Player's corpse453") The_Prophet000 attacking Player's corpse453 Dist 0.899057 Z 67.568897
4206 [09.18. - 18:30:35] AIYellForHelp("Emperor_Crush000","Player's corpse453") orc_legionnaire003 attacking Player's corpse453 Dist 16.603519 Z 66.166519
4266 [09.18. - 18:30:35] [NET__WORLD] Connected to World: localhost:9000

Code:

4266 [09.18. - 23:37:59] Member Disband Request from Player
4266 [09.18. - 23:38:00] Member Disband Request from Player
4266 [09.18. - 23:38:00] Member Disband Request from Player
22601 [09.18. - 23:38:00] OP CastSpell: slot=7, spell=112, target=479, inv=ffffffff
22601 [09.18. - 23:38:00] OP CastSpell: slot=10, spell=1940, target=551, inv=c
3943 [09.18. - 23:38:01] Client::AddMoneyToPP() Player should have:  plat:488 gold:30 silver:28 copper:25
22601 [09.18. - 23:38:01] OP CastSpell: slot=10, spell=4619, target=551, inv=ffffffff
3937 [09.18. - 23:38:01] OP CastSpell: slot=0, spell=560, target=251, inv=ffffffff
22601 [09.18. - 23:38:01] OP CastSpell: slot=10, spell=4625, target=551, inv=ffffffff
4266 [09.18. - 23:38:01] OP CastSpell: slot=6, spell=1670, target=1375, inv=ffffffff
25727 [09.18. - 23:38:02] OP CastSpell: slot=10, spell=1940, target=407, inv=c
25727 [09.18. - 23:38:03] OP CastSpell: slot=10, spell=4633, target=407, inv=ffffffff
3943 [09.18. - 23:38:03] Client::AddMoneyToPP() Player should have:  plat:493 gold:32 silver:36 copper:30
22601 [09.18. - 23:38:04] OP CastSpell: slot=10, spell=4607, target=443, inv=ffffffff
4266 [09.18. - 23:38:04] OP CastSpell: slot=10, spell=3900, target=0, inv=17
4280 [09.18. - 23:38:05] OP CastSpell: slot=7, spell=8462, target=697, inv=ffffffff
22601 [09.18. - 23:38:05] OP CastSpell: slot=10, spell=1940, target=551, inv=c
4011 [09.18. - 23:38:05] Unable to convert EQ opcode 0x7085 to an Application opcode.
4011 [09.18. - 23:38:05] [CLIENT__NET_ERR] Player: Unhandled incoming opcode: [OpCode OP_Unknown (0x7085) Size=4]
4266 [09.18. - 23:38:06] OP CastSpell: slot=10, spell=172, target=1375, inv=4
25727 [09.18. - 23:38:06] OP CastSpell: slot=10, spell=1940, target=406, inv=c
22601 [09.18. - 23:38:07] OP CastSpell: slot=10, spell=4607, target=442, inv=ffffffff
4150 [09.18. - 23:38:07] OP CastSpell: slot=0, spell=5417, target=132, inv=ffffffff
3937 [09.18. - 23:38:07] Client::AddMoneyToPP() Player should have:  plat:150 gold:263 silver:289 copper:255
22601 [09.18. - 23:38:09] OP CastSpell: slot=10, spell=4607, target=442, inv=ffffffff
4260 [09.18. - 23:38:09] OP CastSpell: slot=10, spell=172, target=177, inv=1
4266 [09.18. - 23:38:09] DeleteItemInInventory(253, 1, true)
4266 [09.18. - 23:38:09] DeleteItemInInventory(253, 1, true)
4266 [09.18. - 23:38:09] DeleteItemInInventory(253, 1, true)
4266 [09.18. - 23:38:09] DeleteItemInInventory(253, 1, true)
4266 [09.18. - 23:38:09] DeleteItemInInventory(253, 1, true)
3810 [09.18. - 23:38:09] [NET__WORLD] Connected to World: localhost:9000

Code:

4172 [09.19. - 01:14:43] Drinking from slot:251
4172 [09.19. - 01:14:43] DeleteItemInInventory(251, 1, false)
4172 [09.19. - 01:14:43] Eating from slot:252
4172 [09.19. - 01:14:43] DeleteItemInInventory(252, 1, false)
4274 [09.19. - 01:14:46] OP CastSpell: slot=10, spell=4053, target=179, inv=1d
3805 [09.19. - 01:14:49] OP CastSpell: slot=7, spell=3981, target=7, inv=ffffffff
4172 [09.19. - 01:14:50] OP CastSpell: slot=10, spell=4608, target=339, inv=ffffffff
25727 [09.19. - 01:14:50] OP CastSpell: slot=0, spell=16, target=111, inv=ffffffff
4172 [09.19. - 01:14:51] OP CastSpell: slot=10, spell=4598, target=339, inv=ffffffff
4172 [09.19. - 01:14:51] Fading rune from slot 0
4172 [09.19. - 01:14:51] OP CastSpell: slot=10, spell=4600, target=339, inv=ffffffff
4172 [09.19. - 01:14:53] OP CastSpell: slot=10, spell=4591, target=339, inv=ffffffff
4212 [09.19. - 01:14:53] [NET__WORLD] Connected to World: localhost:9000

Code:

3802 [09.19. - 04:42:28] OP CastSpell: slot=10, spell=2435, target=476, inv=d
3802 [09.19. - 04:42:32] OP CastSpell: slot=10, spell=2435, target=476, inv=d
3802 [09.19. - 04:42:34] OP CastSpell: slot=10, spell=1940, target=222, inv=c
3802 [09.19. - 04:42:35] Eating from slot:270
3802 [09.19. - 04:42:35] DeleteItemInInventory(270, 1, false)
3957 [09.19. - 04:42:38] DeleteItemInInventory(21, 1, true)
3802 [09.19. - 04:42:39] OP CastSpell: slot=6, spell=8521, target=138, inv=ffffffff
3805 [09.19. - 04:42:42] Player Player has requested a zoning to LOC x=0.000000, y=-2915.000000, z=-766.000000, heading=0.000000 in zoneid=212
3805 [09.19. - 04:42:42] Zone request from Player
3805 [09.19. - 04:42:43] Client::AddMoneyToPP() Player should have:  plat:0 gold:73 silver:84 copper:67
3802 [09.19. - 04:42:44] Member of group 38004 named 'Player' had an out of date pointer!!
3802 [09.19. - 04:42:47] OP CastSpell: slot=10, spell=8760, target=0, inv=ffffffff
3805 [09.19. - 04:42:49] [NET__WORLD] Connected to World: localhost:9000

If anyone else has been seeing this problem more lately, maybe we can all work together and figure out what is causing it. This is starting to get more than just a little annoying now. The problem with troubleshooting is that it takes at least a day to test each step. I plan to possibly revert back to some older code that I know didn't do this and see if that resolves it. If not, then I plan to remove all level 75 discs which were added recently. After that, I will have to look at quest scripts and see if one of them could possibly be causing it.

wiley99 · #2 09-21-2008, 05:30 AM

I have a build 1129 (cvs db,quest) eqemu peq server running on debian 4.0r1 linux server. Just got this up and running 3 days ago. I had the windows one running before that. No issues at all until today

I had 2 buddies log in and we were doing some hunting in some planes when they disappeared and we then saw a black screen stating "we were disconnected", we could instantly log-back in the server did not report anything in the logs at that time abnormally and it did not crash.

This happened about an hour later, then another 4 times at different times (Hour apart, 2 hours, 45 minutes). I was grouped with them and things stopped responding, they vanish and that black screen comes up with you have been disconnected (we all got the same error). I am extremely new with eqemu. I find it amazing what work was put into this and how skilled everyone is around here doing the work they do.

I will def try and get some logs posted exactly when this occurs again as right now I am not exactly sure the issue is showing in the logs. I reviewed them a few times. I thought it may be network related, due to Saturday heavy network loads with my ISP but I will be testing that out the following days.

wiley99 · #3 09-21-2008, 11:37 PM

After looking at logs and testing in game it seems as though my world server is not disconnecting me. Its when someone turns on PVP and tries to hit someone the zone will crash instantly.

**trevius** · #4 09-21-2008, 11:46 PM

Ya, I think your issue is something completely different than my issue.

**trevius** · #5 09-22-2008, 06:04 AM

Well, I tested every level 70+ disc that I recently added to my server and none of them caused the crash for me. So, I am guessing it is something else. I am still leaning towards it being the source code or one of the custom changes I added in recently since I do run quite a few of them.

I will continue testing and see if I can come up with anything. So far, I tried reverting back to 1128 code version, but I also added in most of the features that have been added since then to it as well. Maybe it is one of those features that is causing the problem. The list of most of the added features I am currently using is:

Enraged, Flurry and Rampage Spamming Fix
http://www.eqemulator.net/forums/showthread.php?t=26258

Technique of Master Wu AA (Fix)
http://www.eqemulator.net/forums/showthread.php?t=26160

quest::traindiscs() and new quest::scribespells()
http://www.eqemulator.net/forums/showthread.php?t=26083

IP Limiting Additional Feature and Correction
http://www.eqemulator.net/forums/showthread.php?t=26122

#ItemLink <Item ID Number> (quest::itemlink())
http://www.eqemulator.net/forums/showthread.php?t=26018

Proc spells don't work after zoning (Proc Buff Fix)
http://www.eqemulator.net/forums/showthread.php?t=25991

New Quest Command quest::clearspawntimers()
http://www.eqemulator.net/forums/showthread.php?t=26261

Damage Bonus Functions (2H Bonus Fix)
http://www.eqemulator.net/forums/showthread.php?t=26262

Resurrection Reworked (with Confirmation box)
http://www.eqemulator.net/forums/showthread.php?t=26049

Buffs Being Blocked That Shouldn't Be (CHA Stacking Fix)
http://www.eqemulator.net/forums/showthread.php?t=25570

Spell Blocking (now with Intra-Zone restrictions!)
http://www.eqemulator.net/forums/showthread.php?t=26051

Spell And Skill Rule for Above MaxLevel Players
http://www.eqemulator.net/forums/showthread.php?t=25937

**Derision** · #6 09-22-2008, 07:32 AM

Quote:

Originally Posted by trevius

IP Limiting Additional Feature and Correction
http://www.eqemulator.net/forums/showthread.php?t=26122

I've just been looking over the changes to clientlist.cpp in that thread and I think the logic is flawed if that is how you have it coded:

Code:

                if (IPInstances > (RuleI(World, MaxClientsPerIP))){
                        countCLEIPs->SetOnline(CLE_Status_Offline);
                        iterator.RemoveCurrent();
                }
        }
        countCLEIPs->SetOnline(CLE_Status_Offline);
        iterator.RemoveCurrent();

If the code reaches the most deepy nested iterator.RemoveCurrent(), then not only will it it remove the ClientList entry of the connection exceeding the IP limit, but the iterator will be updated to point to the next entry in the ClientList (which probably belongs to someone else), and the flow of execution will then reach the second iterator.RemoveCurrent() and remove that one as well.

My head's hurting from looking at it, so maybe I am misunderstanding the intention of the code.