Client dropping without disconnect?

Kikinaak · #1 01-21-2012, 09:01 PM

This ones got me scratching my head. I'm running the server on a lan and all works great for logging in and playing, but we are having problems getting disconnected. When this happens, the client appears to still be connected, but doors do not work, NPCs cannot be interacted with, and mobs cannot be fought. But the client never throws a timeout or disconnection message, it just lets us wander around the zone aimlessly.

/camp does not work, but /quit will get us back to the login screen. From there we can log back in, and be somewhere in the zone we were several minutes before noticing something was wrong.

This only appears to happen in gfaydark, it has not yet happened in any other zone that we know of. We have 2 other machines playing and it happens to both. Server side there are no disconnection messages or any hint there is anything wrong, and the same zone server takes the "new" connection. We are playing on a lan so I've ruled out latency issues. Any suggestions on where to look next?

**trevius** · #2 01-22-2012, 10:40 AM

Sounds like you are running into the standard bugged client issue. This was more of an issue in the past when there was an issue with packets getting out of sync or missing a response from the server that the client is expecting.

What server code revision are you running, and which client are you using? Does the sync issue happen after doing anything in particular such as killing a bunch of stuff all at once? What are the stats of the server you are running on, and are you running anything else (or playing) on that same PC? There are many possible causes for that type of issue, but mostly it is due to flooding too many packets to the clients like when doing mass killings, or when using a feature that may not be fully implemented like a special type of merchant or something. It could even be due to a spell issue or just about any number of other things.

Mersia · #3 01-23-2012, 03:01 AM

not trying to hijack the thread, but i have the same problem as the OP, Except im internet based and folks connect and i first noticed it in 2 Zones unrest and Cauldron, then Finally OOT. We are running r2907 svn ( latest ) and unpatched Titanium clients. I notice alot lag so quote but i doubt its comming from the server as im always in the shell watching, so it is certainly clientbased.

Having my GM online ( same computer but doesnt matter if its 2 clients running the bug happens regardless) i ported over to my character and they look fine but on the characters side nothing updates, the mob i was fighting is standing there at 0% hp and my #bot group disapears but reappears occasionally when i move the character about, while i can see via a dual monitor setup that my alt is moving just fine like all data is being sent to the server but its not being sent back for visual updates at all but it is staying online regardless. its out of Sync massivly. So i did the Same Fight after relogging the client except with out my bots, One thing i noticed that casting Creeping crud cause a slightly familiar lag issue but otherwise i ended the fight just fine. My bot group consists of a Ogre F Warrior, Gnome M Wizard, a Baldie Enchanter F, a Blueberry Rog M, and last most is a Drakkin Cleric Female, i have the world locked to Kunark only expansion so im not sure what kind model problems the Drakkin gives ( looks like a normal human )

But here is some stuff from my debug logs, quite a few errors.

Code:

--- from Debug log ----
15443 [01.23. - 05:33:51] Zone request from Zenya
15438 [01.23. - 05:33:51] The next weather check for zone: oot will be in 11664 seconds.
15438 [01.23. - 05:33:52] Zone: oot has weather of type 1.
15438 [01.23. - 05:33:52] Zone: oot(69) has weather type = 1. The weather timer has been enabled.
15438 [01.23. - 05:33:53] [WORLD__CLIENT] New connection from XXX.XXX.XXX.XXX:50519
15438 [01.23. - 05:33:54] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:50519: First opcode 0x7213 did not match expected 0x2792
15438 [01.23. - 05:33:54] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:50519: Tried patch 6.2_world, and it did not match.
15438 [01.23. - 05:33:54] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:50519: First opcode 0x7213 did not match expected 0x2ec9
15438 [01.23. - 05:33:54] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:50519: Tried patch 6.2_zone, and it did not match.
15438 [01.23. - 05:33:54] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:50519: First opcode 0x7213 did not match expected 0x4dd0
15438 [01.23. - 05:33:54] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:50519: Tried patch Titanium_world, and it did not match.
15438 [01.23. - 05:33:54] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:50519: First opcode matched 0x7213 and length matched 68
15438 [01.23. - 05:33:54] [NET__IDENTIFY] Identified stream XXX.XXX.XXX.XXX:50519 with signature Titanium_zone
15438 [01.23. - 05:33:54] [WORLD__CLIENT] New client from XXX.XXX.XXX.XXX:50519
15438 [01.23. - 05:33:54] Member of group 4001 named 'Zenya' had an out of date pointer!!
15438 [01.23. - 05:33:54] Member of group 4001 named 'Sanjia' had an out of date pointer!!
15438 [01.23. - 05:33:54] Member of group 4001 named 'Vayrie' had an out of date pointer!!
15438 [01.23. - 05:33:54] Member of group 4001 named 'Kierva' had an out of date pointer!!
15438 [01.23. - 05:33:54] Member of group 4001 named 'Sigel' had an out of date pointer!!
15438 [01.23. - 05:33:54] Member of group 4001 named 'Faelln' had an out of date pointer!!
15438 [01.23. - 05:34:05] [CLIENT__NET_ERR] Zenya: Unhandled incoming opcode: [OpCode OP_WeaponEquip2 (0x63da) Size=8]
15438 [01.23. - 05:34:05] [CLIENT__NET_ERR] Zenya: Unhandled incoming opcode: [OpCode OP_WeaponEquip1 (0x6c5e) Size=12]
<snipped mob attacking mobs >
15448 [01.23. - 05:39:22] Unable to convert EQ opcode 0x6a5f to an Application opcode.
15448 [01.23. - 05:39:22] [CLIENT__NET_ERR] Lain: Unhandled incoming opcode: [OpCode OP_Unknown (0x6a5f) Size=8]
15438 [01.23. - 05:42:34] OP CastSpell: slot=4, spell=264, target=138, inv=ffffffff
15438 [01.23. - 05:42:40] OP CastSpell: slot=3, spell=99, target=138, inv=ffffffff
15438 [01.23. - 05:42:46] OP CastSpell: slot=7, spell=91, target=138, inv=ffffffff
15438 [01.23. - 05:42:52] Client::AddMoneyToPP() Zenya should have:  plat:571 gold:287 silver:258 copper:249
15438 [01.23. - 05:42:58] [INVENTORY__SLOTS] Zenya: Putting loot item Robe of the Oracle (1354) into slot 30
15438 [01.23. - 05:43:04] [INVENTORY__SLOTS] Zenya: Putting item Thaumaturgist's Robe (1322) on the cursor
15438 [01.23. - 05:43:04] DeleteItemInInventory(30, 0, true)
15438 [01.23. - 05:43:10] [INVENTORY__SLOTS] Zenya: Src slot 30 has item Thaumaturgist's Robe (1322) with 1 charges in it.
15438 [01.23. - 05:43:10] [INVENTORY__SLOTS] Zenya: Moving entire item from slot 30 to slot 255

15438 [01.23. - 05:43:14] [INVENTORY__SLOTS] Zenya: Src slot 255 has item Thaumaturgist's Robe (1322) with 1 charges in it.
15438 [01.23. - 05:43:14] [INVENTORY__SLOTS] Zenya: Moving entire item from slot 255 to slot 30
15438 [01.23. - 05:43:22] DeleteItemInInventory(30, 0, true)

15438 [01.23. - 05:43:43] [INVENTORY__SLOTS] Zenya: Src slot 253 has item Spell: Greater Wolf Form (15426) with 1 charges in it.
15438 [01.23. - 05:43:43] [INVENTORY__SLOTS] Zenya: Moving entire item from slot 253 to slot 30
15438 [01.23. - 05:43:53] DeleteItemInInventory(30, 1, true)
15438 [01.23. - 05:44:25] OP CastSpell: slot=2, spell=278, target=189, inv=ffffffff

15438 [01.23. - 05:47:28] OP CastSpell: slot=5, spell=242, target=187, inv=ffffffff
15438 [01.23. - 05:47:33] OP CastSpell: slot=4, spell=264, target=187, inv=ffffffff
15438 [01.23. - 05:47:42] Client::AddMoneyToPP() Zenya should have:  plat:571 gold:18 silver:43 copper:67
15438 [01.23. - 05:47:44] [INVENTORY__SLOTS] Zenya: Putting loot item Mug of Sea Foam (22547) into slot 253
15448 [01.23. - 05:48:30] Player Lain has requested a zoning to LOC x=320.000000, y=2815.000000, z=473.000000, heading=0.000000 in zoneid=202
15448 [01.23. - 05:48:30] Zone request from Lain
15448 [01.23. - 05:48:30] Zoning Lain to safe coords (-285.000000,-148.000000,-159.000000) in poknowledge (202)
15443 [01.23. - 05:48:30] The next weather check for zone: poknowledge will be in 9392 seconds.
15443 [01.23. - 05:48:31] Zone: poknowledge has weather of type 0.
15443 [01.23. - 05:48:31] Zone: poknowledge(202) has no weather type. The weather timer has been disabled.
15443 [01.23. - 05:48:32] [WORLD__CLIENT] New connection from XXX.XXX.XXX.XXX:64511
---------------- its right about below here is when Zenya/my character's screen locks up ---------------
15443 [01.23. - 05:48:33] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:64511: First opcode 0x7213 did not match expected 0x2792
15443 [01.23. - 05:48:33] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:64511: Tried patch 6.2_world, and it did not match.
15443 [01.23. - 05:48:33] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:64511: First opcode 0x7213 did not match expected 0x2ec9
15443 [01.23. - 05:48:33] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:64511: Tried patch 6.2_zone, and it did not match.
15443 [01.23. - 05:48:33] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:64511: First opcode 0x7213 did not match expected 0x4dd0
15443 [01.23. - 05:48:33] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:64511: Tried patch Titanium_world, and it did not match.
15443 [01.23. - 05:48:33] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:64511: First opcode matched 0x7213 and length matched 68
15443 [01.23. - 05:48:33] [NET__IDENTIFY] Identified stream XXX.XXX.XXX.XXX:64511 with signature Titanium_zone
15443 [01.23. - 05:48:33] [WORLD__CLIENT] New client from XXX.XXX.XXX.XXX:64511
15438 [01.23. - 05:49:56] OP CastSpell: slot=4, spell=264, target=48, inv=ffffffff
15443 [01.23. - 05:54:34] Player Lain has requested a zoning to LOC x=-6683.372070, y=1081.693359, z=-6.376295, heading=0.375000 in zoneid=69
15443 [01.23. - 05:54:35] Zone request from Lain
15438 [01.23. - 05:54:37] [WORLD__CLIENT] New connection from XXX.XXX.XXX.XXX:55678
15438 [01.23. - 05:54:37] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:55678: First opcode 0x7213 did not match expected 0x2792
15438 [01.23. - 05:54:37] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:55678: Tried patch 6.2_world, and it did not match.
15438 [01.23. - 05:54:37] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:55678: First opcode 0x7213 did not match expected 0x2ec9
15438 [01.23. - 05:54:37] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:55678: Tried patch 6.2_zone, and it did not match.
15438 [01.23. - 05:54:37] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:55678: First opcode 0x7213 did not match expected 0x4dd0
15438 [01.23. - 05:54:37] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:55678: Tried patch Titanium_world, and it did not match.
15438 [01.23. - 05:54:37] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:55678: First opcode matched 0x7213 and length matched 68
15438 [01.23. - 05:54:37] [NET__IDENTIFY] Identified stream XXX.XXX.XXX.XXX:55678 with signature Titanium_zone
15438 [01.23. - 05:54:37] [WORLD__CLIENT] New client from XXX.XXX.XXX.XXX:55678
15438 [01.23. - 06:00:20] Tagged a_seafury_cyclops's corpse48 player corpse has burried.
15438 [01.23. - 06:06:07] Unable to convert EQ opcode 0x6a5f to an Application opcode.
15438 [01.23. - 06:06:07] [CLIENT__NET_ERR] Zenya: Unhandled incoming opcode: [OpCode OP_Unknown (0x6a5f) Size=8]
15438 [01.23. - 06:10:32] Unable to convert EQ opcode 0x6a5f to an Application opcode.
15438 [01.23. - 06:10:32] [CLIENT__NET_ERR] Lain: Unhandled incoming opcode: [OpCode OP_Unknown (0x6a5f) Size=8]
15438 [01.23. - 06:17:18] Unable to convert EQ opcode 0x6a5f to an Application opcode.
15438 [01.23. - 06:17:18] [CLIENT__NET_ERR] Zenya: Unhandled incoming opcode: [OpCode OP_Unknown (0x6a5f) Size=8]
15438 [01.23. - 06:17:31] Unable to convert EQ opcode 0x6a5f to an Application opcode.
15438 [01.23. - 06:17:31] [CLIENT__NET_ERR] Lain: Unhandled incoming opcode: [OpCode OP_Unknown (0x6a5f) Size=8]

================================== From my zone_dynamic_03.log

[Debug] [INVENTORY__SLOTS] Zenya: Putting loot item Mug of Sea Foam (22547) into slot 253
<= attacking a mob an it starts to lag so i let it go ====>
[Debug] OP CastSpell: slot=4, spell=264, target=48, inv=ffffffff

<=====zoning my GM in to watch ========>
Zoning Unknown to oot(69) - 0
[Debug] [WORLD__CLIENT] New connection from XXX.XXX.XXX.XXX:55678
[Debug] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:55678: First opcode 0x7213 did not match expected 0x2792
[Debug] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:55678: Tried patch 6.2_world, and it did not match.
[Debug] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:55678: First opcode 0x7213 did not match expected 0x2ec9
[Debug] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:55678: Tried patch 6.2_zone, and it did not match.
[Debug] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:55678: First opcode 0x7213 did not match expected 0x4dd0
[Debug] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:55678: Tried patch Titanium_world, and it did not match.
[Debug] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:55678: First opcode matched 0x7213 and length matched 68
[Debug] [NET__IDENTIFY] Identified stream XXX.XXX.XXX.XXX:55678 with signature Titanium_zone
[Debug] [WORLD__CLIENT] New client from XXX.XXX.XXX.XXX:55678
Unable to get group id, char not found!

< === About the time my player character's screen stops updating ====== >>

[Error] HandlePacket() Opcode error: Unexpected packet during CLIENT_CONNECTING: opcode: OP_AnnoyingZoneUnknown (#311 eq=0x0000), size: 4112
[Error] HandlePacket() Opcode error: Unexpected packet during CLIENT_CONNECTING: opcode: OP_AnnoyingZoneUnknown (#311 eq=0x0000), size: 4112
[Error] HandlePacket() Opcode error: Unexpected packet during CLIENT_CONNECTING: opcode: OP_AnnoyingZoneUnknown (#311 eq=0x0000), size: 4112
Lain is a GM
Unable to get raid id, char not found!
[Debug] Tagged a_seafury_cyclops's corpse48 player corpse has burried.
[Debug] Unable to convert EQ opcode 0x6a5f to an Application opcode.
[Debug] [CLIENT__NET_ERR] Zenya: Unhandled incoming opcode: [OpCode OP_Unknown (0x6a5f) Size=8]
   0: 49 2E F2 73 09 2E F2 73                            | I..s...s
[Debug] Unable to convert EQ opcode 0x6a5f to an Application opcode.
[Debug] [CLIENT__NET_ERR] Lain: Unhandled incoming opcode: [OpCode OP_Unknown (0x6a5f) Size=8]
   0: 49 2E F2 73 09 2E F2 73                            | I..s...s
[Debug] Unable to convert EQ opcode 0x6a5f to an Application opcode.
[Debug] [CLIENT__NET_ERR] Zenya: Unhandled incoming opcode: [OpCode OP_Unknown (0x6a5f) Size=8]
   0: 41 6B C5 00 04 6B C5 00                            | Ak...k..
[Debug] Unable to convert EQ opcode 0x6a5f to an Application opcode.
[Debug] [CLIENT__NET_ERR] Lain: Unhandled incoming opcode: [OpCode OP_Unknown (0x6a5f) Size=8]
   0: 41 DF 18 00 48 DF 18 00                            | A...H...
   
< ========= logged out character and relogged in to reproduce error with out use of Bots helping, no success. ====>>

   [Debug] [WORLD__CLIENT] New connection from XXX.XXX.XXX.XXX:58617
[Debug] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:58617: First opcode 0x7752 did not match expected 0x2792
[Debug] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:58617: Tried patch 6.2_world, and it did not match.
[Debug] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:58617: First opcode 0x7213 did not match expected 0x2ec9
[Debug] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:58617: Tried patch 6.2_zone, and it did not match.
[Debug] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:58617: First opcode 0x7752 did not match expected 0x4dd0
[Debug] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:58617: Tried patch Titanium_world, and it did not match.
[Debug] [NET__IDENT_TRACE] XXX.XXX.XXX.XXX:58617: First opcode matched 0x7213 and length matched 68
[Debug] [NET__IDENTIFY] Identified stream XXX.XXX.XXX.XXX:58617 with signature Titanium_zone
[Debug] [WORLD__CLIENT] New client from XXX.XXX.XXX.XXX:58617
Unable to get group id, char not found!
Unable to get raid id, char not found!
[Debug] [CLIENT__NET_ERR] Zenya: Unhandled incoming opcode: [OpCode OP_WeaponEquip2 (0x63da) Size=8]
   0: CC 00 00 00 40 00 00 00                            | ....@...
[Debug] [CLIENT__NET_ERR] Zenya: Unhandled incoming opcode: [OpCode OP_WeaponEquip1 (0x6c5e) Size=12]
   0: CC 00 00 00 00 00 00 00 - 00 00 00 00              | ............
[Debug] OP CastSpell: slot=1, spell=261, target=204, inv=ffffffff
[Debug] OP CastSpell: slot=2, spell=278, target=204, inv=ffffffff
[Debug] OP CastSpell: slot=5, spell=242, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=6, spell=76, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=6, spell=76, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=3, spell=99, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=3, spell=99, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=4, spell=264, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=3, spell=99, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=3, spell=99, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=7, spell=91, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=6, spell=76, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=4, spell=264, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=6, spell=76, target=203, inv=ffffffff
[Debug] Drinking from slot:29
[Debug] DeleteItemInInventory(29, 1, false)
[Debug] Eating from slot:25
[Debug] DeleteItemInInventory(25, 1, false)
[Debug] OP CastSpell: slot=4, spell=264, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=3, spell=99, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=3, spell=99, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=6, spell=76, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=6, spell=76, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=4, spell=264, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=3, spell=99, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=3, spell=99, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=7, spell=91, target=203, inv=ffffffff
[Debug] OP CastSpell: slot=7, spell=91, target=203, inv=ffffffff
[Debug] Client::AddMoneyToPP() Zenya should have:  plat:571 gold:47 silver:93 copper:134
[Debug] Tagged a_seafury_cyclops's corpse203 player corpse has burried.
< end >

And thats pretty much my findings it seems for me has something to do with Bots being out? perhaps their casting a spell that isnt making the client happy? i hope this sheds some light in some way.

Kikinaak · #4 01-23-2012, 12:34 PM

Kinda figured thats what was happening, but narrowing down the problem packet is gonna be a right pain in the arse.

I'm running server version 2068, no bots, with PEQ 2083. I have not upgraded yet as the changelog suggested the updates above my version were minor changes and a revert, not worth the hassle of getting.

Client side I'm running the steam version of Underfoot with most of the missing files sourced from live.

So far the problem is localized to gfay, but looking at the point I appear when I log back in as the point of disconnect, there is no real pattern. Its happened way out in the middle of nowhere with no spawns around, one of the high platforms of kelethin, down near the wizard spires, all over the place. Its not just one bugged bank, merchant or trade container either. We play a wood elf ranger and a high elf paladin, so spells and buffs are flying but still no one reliable "doing this will get you desynched"