trevius
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:
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
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"):
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
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
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
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.
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:
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
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"):
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
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
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
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.