The sits bug.

[Scribble]

This is a placeholder for the sits bug. Im conducting research on each server to see if I can get it to happen. Appeared on stitch and character world sit and re sit over and over till crash. It was wild.

[tyrbo]

So, for some more details, it would seem like what occurs (on my server at least) is some sort of situation where the server starts to misinterpret incoming packets from the client.

When this occurs, you'll see something like the following in the server log:

01:09:45 E Client : OP_QuestJournalSetVisibleMsg error: Player does not have quest with id of 3607334484
01:09:45 E Client : OP_ReadyForTakeOffMsg recieved but unable to get an index for path (2784) in zone (252)
01:09:45 E Client : OP_QuestJournalSetVisibleMsg error: Player does not have quest with id of 2101156308
01:09:45 E Client : num_quests = 3322065697 - quantity too high, aborting load.
01:09:45 E World : Unknown id of 969906781 when looting!
01:09:45 E Command : Error, command handler of 25365 was requested, but max handler is 2010
01:09:45 E World : Invalid ZoneAuthRequest, disconnecting client.

This seems to randomly happen when connecting or zoning. I've also had it happen just by idling for a long time, where my ping will shoot up to 8K (although no lag is experienced) and the above will eventually happen.

This does not always crash the server but occasionally it will.

Stack trace from one of the crashes:

(gdb) bt
#0 _int_free (av=0x7fffc0000020, p=0x7fffc06988c0, have_lock=0) at malloc.c:3841
#1 0x00007ffff65a553c in __GI___libc_free (mem=<optimized out>) at malloc.c:2968
#2 0x000000000092e52a in __gnu_cxx::new_allocator<std::_Rb_tree_node<std::pair<unsigned short const, EQProtocolPacket*> > >::deallocate (this=0x7fffc0002f80,
__p=0x7fffc06988d0) at /usr/include/c++/5/ext/new_allocator.h:110
#3 0x000000000092dbe7 in std::allocator_traits<std::allocator<std::_Rb_tree_node<std::pair<unsigned short const, EQProtocolPacket*> > > >::deallocate (__a=...,
__p=0x7fffc06988d0, __n=1) at /usr/include/c++/5/bits/alloc_traits.h:517
#4 0x000000000092c527 in std::_Rb_tree<unsigned short, std::pair<unsigned short const, EQProtocolPacket*>, std::_Select1st<std::pair<unsigned short const, EQProtocolPacket*> >,
std::less<unsigned short>, std::allocator<std::pair<unsigned short const, EQProtocolPacket*> > >::_M_put_node (this=0x7fffc0002f80, __p=0x7fffc06988d0)
at /usr/include/c++/5/bits/stl_tree.h:495
#5 0x000000000092ab78 in std::_Rb_tree<unsigned short, std::pair<unsigned short const, EQProtocolPacket*>, std::_Select1st<std::pair<unsigned short const, EQProtocolPacket*> >,
std::less<unsigned short>, std::allocator<std::pair<unsigned short const, EQProtocolPacket*> > >::_M_drop_node (this=0x7fffc0002f80, __p=0x7fffc06988d0)
at /usr/include/c++/5/bits/stl_tree.h:562
#6 0x000000000092e854 in std::_Rb_tree<unsigned short, std::pair<unsigned short const, EQProtocolPacket*>, std::_Select1st<std::pair<unsigned short const, EQProtocolPacket*> >,
std::less<unsigned short>, std::allocator<std::pair<unsigned short const, EQProtocolPacket*> > >::_M_erase_aux (this=0x7fffc0002f80, __position=...)
at /usr/include/c++/5/bits/stl_tree.h:2249
#7 0x000000000092dee6 in std::_Rb_tree<unsigned short, std::pair<unsigned short const, EQProtocolPacket*>, std::_Select1st<std::pair<unsigned short const, EQProtocolPacket*> >,
std::less<unsigned short>, std::allocator<std::pair<unsigned short const, EQProtocolPacket*> > >::erase[abi:cxx11](std::_Rb_tree_const_iterator<std::pair<unsigned short const, E$
ProtocolPacket*> >) (this=0x7fffc0002f80, __position=...) at /usr/include/c++/5/bits/stl_tree.h:1024
#8 0x000000000092cef3 in std::_Rb_tree<unsigned short, std::pair<unsigned short const, EQProtocolPacket*>, std::_Select1st<std::pair<unsigned short const, EQProtocolPacket*> >,
std::less<unsigned short>, std::allocator<std::pair<unsigned short const, EQProtocolPacket*> > >::_M_erase_aux (this=0x7fffc0002f80, __first=..., __last=...)
at /usr/include/c++/5/bits/stl_tree.h:2263
#9 0x000000000092bba9 in std::_Rb_tree<unsigned short, std::pair<unsigned short const, EQProtocolPacket*>, std::_Select1st<std::pair<unsigned short const, EQProtocolPacket*> >,
std::less<unsigned short>, std::allocator<std::pair<unsigned short const, EQProtocolPacket*> > >::erase[abi:cxx11](std::_Rb_tree_const_iterator<std::pair<unsigned short const, E$
ProtocolPacket*> >, std::_Rb_tree_const_iterator<std::pair<unsigned short const, EQProtocolPacket*> >) (this=0x7fffc0002f80, __first=..., __last=...)
at /usr/include/c++/5/bits/stl_tree.h:1057
#10 0x0000000000929e91 in std::_Rb_tree<unsigned short, std::pair<unsigned short const, EQProtocolPacket*>, std::_Select1st<std::pair<unsigned short const, EQProtocolPacket*> >,
std::less<unsigned short>, std::allocator<std::pair<unsigned short const, EQProtocolPacket*> > >::erase (this=0x7fffc0002f80, __x=@0x7fffc00028fc: 37402)
at /usr/include/c++/5/bits/stl_tree.h:2274
#11 0x0000000000928e31 in std::map<unsigned short, EQProtocolPacket*, std::less<unsigned short>, std::allocator<std::pair<unsigned short const, EQProtocolPacket*> > >::erase (
this=0x7fffc0002f80, __x=@0x7fffc00028fc: 37402) at /usr/include/c++/5/bits/stl_map.h:745
#12 0x0000000000924f1b in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0698860) at ../common/EQStream.cpp:482
#13 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc06987b0) at ../common/EQStream.cpp:491
#14 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0698700) at ../common/EQStream.cpp:491
#15 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0698650) at ../common/EQStream.cpp:491
#16 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc06985a0) at ../common/EQStream.cpp:491
#17 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc06984f0) at ../common/EQStream.cpp:491
#18 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0698440) at ../common/EQStream.cpp:491
#19 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0698390) at ../common/EQStream.cpp:491
#20 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc06982e0) at ../common/EQStream.cpp:491
#21 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0698230) at ../common/EQStream.cpp:491
#22 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0698180) at ../common/EQStream.cpp:491
#23 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc06980b0) at ../common/EQStream.cpp:491
#24 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0698020) at ../common/EQStream.cpp:491
#25 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0696ff0) at ../common/EQStream.cpp:491
#26 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0697eb0) at ../common/EQStream.cpp:491
#27 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0697e00) at ../common/EQStream.cpp:491
#28 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0697d50) at ../common/EQStream.cpp:491
#29 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0695080) at ../common/EQStream.cpp:491
#30 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0694fd0) at ../common/EQStream.cpp:491
#31 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0694f20) at ../common/EQStream.cpp:491
#32 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0697a90) at ../common/EQStream.cpp:491
#33 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc06979e0) at ../common/EQStream.cpp:491
#34 0x0000000000924f42 in EQStream::ProcessPacket (this=0x7fffc00008c0, p=0x7fffc0697930) at ../common/EQStream.cpp:491
---Type <return> to continue, or q <return> to quit---quit

On a side note, I have a packet collect from one of the "insta crashes" that happen occasionally when you log in, where you'll get an error message and the game will exit completely. The logs seem to be filled with random garbage.

It makes me wonder if this is related to a memory access error that I saw pop up when running valgrind, something related to the Color type in one of the packet structures.

[Jabantiz]

It is a desync issue, basically the keys for encryption are no longer synced up on the client and the server causing packets to be decrypted wrong and then interpreted wrong as a result. Still no clue what causes the desync but the problem has been around for years. I am not to good with that low level network stuff either so not something I have been able to trace down.

EDIT: I should add that the packets will be passed along and as a result it can cause a server crash as it is trying to handle a packet that should normally have never made it to that function.

[Scribble]

Sits bug starts up at 14:35 https://www.twitch.tv/videos/215874053 . Just for documentation purposes.

[Gangrenous]

I used to see that crap about the invalid quest in my log, not seen it in a year. Is it possible I already fixed this? Is it happening on Norrath Reborn?

[Scribble]

could be I can never keep my toons logged in overnight. Always booted me for some reason.

[tyrbo]

I used to see that crap about the invalid quest in my log, not seen it in a year. Is it possible I already fixed this? Is it happening on Norrath Reborn?

ZoneAuthRequest message and getting kicked is the key.

Mentioning this again: My ping will rise to 8K if I AFK and allow the bug to occur. When my ping hits 8K, I can run around and do things normally with no crash, no opcode mixup, nothing. Something is already going wrong, but not enough to cause issues.

[mention]Jabantiz[/mention], any thoughts? I would think if I was going out of sync, the encryption / decryption would immediately be invalid and have issues decrypting any client<->server packets, yet I don't have any issues immediately, although the 8K ping is a predictable indicator that something is going wrong.

[Jabantiz]

I have never seen the 8k ping before so I can't really comment on it. The desync is usually when the repeated sitting happens, for some reason the commands for sitting seem the be the easiest to trigger when the desync happens, but yes as soon as the desync occurs you will notice it and stuff won't work right.

I have in the past (not recently) left a client logged on and never got a desync or the 8k ping, for me the desync has only happened when logging into to the world, once I get in it is usually fine (network wise).

[tyrbo]

This old thread seems related.

viewtopic.php?f=61&t=3583

[tyrbo]

Also likely related: viewtopic.php?f=13&t=4317&p=32415

[Gangrenous]

Both great finds.

[Cynnar]

tyrbo and I have found a way to trigger this desync issue. So far testing on my character and on his character if we put a value -1.80676e38 or 1e29 in the characters z column then we can get the client to crash.

[Gangrenous]

Variable overflow?

[tyrbo]

Maybe. It's valid as far as max floats go.

Digging into packet communications, consistently on these broken bugged characters there's a packet that comes in and hits EQStream::ProcessPacket but is not handled by any of the switch handlers, so it hits the default case. Dumping the packet, they're different each time, which makes me think they might be encrypted. Possible explanation for the desync?

I haven't dug into it more - I'd like to see if it comes before any of the other bugged packets.

[Cynnar]

[mention]tyrbo[/mention] has a fix on his server that is a possible fix.

also it looks like my fix for the idle sits bug that at least happened on my server works

Code: Select all

if (NextAckToSend>LastAckSent || LastAckSent == 0x0000ffff)
        SendAck(NextAckToSend);

tldr is when acks loop around from 65536 to 0, we stop sending acks
added the second part of that conditional to handle that case

I want to get it posted here so I can update the svn when I get home. That is of course nobody has beat me to it.