pa/eqemu-server
2
0
Fork 0
mirror of https://github.com/EQEmu/Server.git synced 2025-12-13 14:41:28 +00:00
Code Issues Actions Packages Projects Releases Wiki Activity

More netcode debugging _log to logger.LogDebugType

Browse Source
This commit is contained in:
Akkadius 2015-01-12 22:20:11 -06:00
parent 34f30b974e
commit bc02d7c31a
1 changed files with 98 additions and 98 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

196
common/eq_stream.cpp
View File

@ -81,18 +81,18 @@ void EQStream::init(bool resetSession) {
OpMgr = nullptr; OpMgr = nullptr;
if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) { if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) {
_log(NET__ERROR, _L "init Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, SequencedBase, SequencedQueue.size(), NextOutSeq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "init Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, SequencedBase, SequencedQueue.size(), NextOutSeq);
} }
if(NextSequencedSend > SequencedQueue.size()) { if(NextSequencedSend > SequencedQueue.size()) {
_log(NET__ERROR, _L "init Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size()); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "init Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size());
} }
} }
EQRawApplicationPacket *EQStream::MakeApplicationPacket(EQProtocolPacket *p) EQRawApplicationPacket *EQStream::MakeApplicationPacket(EQProtocolPacket *p)
{ {
EQRawApplicationPacket *ap=nullptr; EQRawApplicationPacket *ap=nullptr;
_log(NET__APP_CREATE, _L "Creating new application packet, length %d" __L, p->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Creating new application packet, length %d" __L, p->size);
_raw(NET__APP_CREATE_HEX, 0xFFFF, p); _raw(NET__APP_CREATE_HEX, 0xFFFF, p);
ap = p->MakeAppPacket(); ap = p->MakeAppPacket();
return ap; return ap;
@ -101,7 +101,7 @@ EQRawApplicationPacket *EQStream::MakeApplicationPacket(EQProtocolPacket *p)
EQRawApplicationPacket *EQStream::MakeApplicationPacket(const unsigned char *buf, uint32 len) EQRawApplicationPacket *EQStream::MakeApplicationPacket(const unsigned char *buf, uint32 len)
{ {
EQRawApplicationPacket *ap=nullptr; EQRawApplicationPacket *ap=nullptr;
_log(NET__APP_CREATE, _L "Creating new application packet, length %d" __L, len); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Creating new application packet, length %d" __L, len);
_hex(NET__APP_CREATE_HEX, buf, len); _hex(NET__APP_CREATE_HEX, buf, len);
ap = new EQRawApplicationPacket(buf, len); ap = new EQRawApplicationPacket(buf, len);
return ap; return ap;
@ -143,7 +143,7 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
while(processed < p->size) { while(processed < p->size) {
subpacket_length=*(p->pBuffer+processed); subpacket_length=*(p->pBuffer+processed);
EQProtocolPacket *subp=MakeProtocolPacket(p->pBuffer+processed+1,subpacket_length); EQProtocolPacket *subp=MakeProtocolPacket(p->pBuffer+processed+1,subpacket_length);
_log(NET__NET_CREATE, _L "Extracting combined packet of length %d" __L, subpacket_length); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Extracting combined packet of length %d" __L, subpacket_length);
_raw(NET__NET_CREATE_HEX, 0xFFFF, subp); _raw(NET__NET_CREATE_HEX, 0xFFFF, subp);
subp->copyInfo(p); subp->copyInfo(p);
ProcessPacket(subp); ProcessPacket(subp);
@ -158,12 +158,12 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
while(processed<p->size) { while(processed<p->size) {
EQRawApplicationPacket *ap=nullptr; EQRawApplicationPacket *ap=nullptr;
if ((subpacket_length=(unsigned char)*(p->pBuffer+processed))!=0xff) { if ((subpacket_length=(unsigned char)*(p->pBuffer+processed))!=0xff) {
_log(NET__NET_CREATE, _L "Extracting combined app packet of length %d, short len" __L, subpacket_length); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Extracting combined app packet of length %d, short len" __L, subpacket_length);
ap=MakeApplicationPacket(p->pBuffer+processed+1,subpacket_length); ap=MakeApplicationPacket(p->pBuffer+processed+1,subpacket_length);
processed+=subpacket_length+1; processed+=subpacket_length+1;
} else { } else {
subpacket_length=ntohs(*(uint16 *)(p->pBuffer+processed+1)); subpacket_length=ntohs(*(uint16 *)(p->pBuffer+processed+1));
_log(NET__NET_CREATE, _L "Extracting combined app packet of length %d, short len" __L, subpacket_length); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Extracting combined app packet of length %d, short len" __L, subpacket_length);
ap=MakeApplicationPacket(p->pBuffer+processed+3,subpacket_length); ap=MakeApplicationPacket(p->pBuffer+processed+3,subpacket_length);
processed+=subpacket_length+3; processed+=subpacket_length+3;
} }
@ -178,7 +178,7 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
case OP_Packet: { case OP_Packet: {
if(!p->pBuffer || (p->Size() < 4)) if(!p->pBuffer || (p->Size() < 4))
{ {
_log(NET__ERROR, _L "Received OP_Packet that was of malformed size" __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_Packet that was of malformed size" __L);
break; break;
} }
uint16 seq=ntohs(*(uint16 *)(p->pBuffer)); uint16 seq=ntohs(*(uint16 *)(p->pBuffer));
@ -188,7 +188,7 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
_raw(NET__DEBUG, seq, p); _raw(NET__DEBUG, seq, p);
PacketQueue[seq]=p->Copy(); PacketQueue[seq]=p->Copy();
_log(NET__APP_TRACE, _L "OP_Packet Queue size=%d" __L, PacketQueue.size()); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "OP_Packet Queue size=%d" __L, PacketQueue.size());
//SendOutOfOrderAck(seq); //SendOutOfOrderAck(seq);
@ -209,7 +209,7 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
// Check for an embedded OP_AppCombinded (protocol level 0x19) // Check for an embedded OP_AppCombinded (protocol level 0x19)
if (*(p->pBuffer+2)==0x00 && *(p->pBuffer+3)==0x19) { if (*(p->pBuffer+2)==0x00 && *(p->pBuffer+3)==0x19) {
EQProtocolPacket *subp=MakeProtocolPacket(p->pBuffer+2,p->size-2); EQProtocolPacket *subp=MakeProtocolPacket(p->pBuffer+2,p->size-2);
_log(NET__NET_CREATE, _L "seq %d, Extracting combined packet of length %d" __L, seq, subp->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "seq %d, Extracting combined packet of length %d" __L, seq, subp->size);
_raw(NET__NET_CREATE_HEX, seq, subp); _raw(NET__NET_CREATE_HEX, seq, subp);
subp->copyInfo(p); subp->copyInfo(p);
ProcessPacket(subp); ProcessPacket(subp);
@ -228,7 +228,7 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
case OP_Fragment: { case OP_Fragment: {
if(!p->pBuffer || (p->Size() < 4)) if(!p->pBuffer || (p->Size() < 4))
{ {
_log(NET__ERROR, _L "Received OP_Fragment that was of malformed size" __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_Fragment that was of malformed size" __L);
break; break;
} }
uint16 seq=ntohs(*(uint16 *)(p->pBuffer)); uint16 seq=ntohs(*(uint16 *)(p->pBuffer));
@ -238,7 +238,7 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
_raw(NET__DEBUG, seq, p); _raw(NET__DEBUG, seq, p);
PacketQueue[seq]=p->Copy(); PacketQueue[seq]=p->Copy();
_log(NET__APP_TRACE, _L "OP_Fragment Queue size=%d" __L, PacketQueue.size()); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "OP_Fragment Queue size=%d" __L, PacketQueue.size());
//SendOutOfOrderAck(seq); //SendOutOfOrderAck(seq);
@ -258,18 +258,18 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
if (oversize_buffer) { if (oversize_buffer) {
memcpy(oversize_buffer+oversize_offset,p->pBuffer+2,p->size-2); memcpy(oversize_buffer+oversize_offset,p->pBuffer+2,p->size-2);
oversize_offset+=p->size-2; oversize_offset+=p->size-2;
_log(NET__NET_TRACE, _L "Fragment of oversized of length %d, seq %d: now at %d/%d" __L, p->size-2, seq, oversize_offset, oversize_length); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Fragment of oversized of length %d, seq %d: now at %d/%d" __L, p->size-2, seq, oversize_offset, oversize_length);
if (oversize_offset==oversize_length) { if (oversize_offset==oversize_length) {
if (*(p->pBuffer+2)==0x00 && *(p->pBuffer+3)==0x19) { if (*(p->pBuffer+2)==0x00 && *(p->pBuffer+3)==0x19) {
EQProtocolPacket *subp=MakeProtocolPacket(oversize_buffer,oversize_offset); EQProtocolPacket *subp=MakeProtocolPacket(oversize_buffer,oversize_offset);
_log(NET__NET_CREATE, _L "seq %d, Extracting combined oversize packet of length %d" __L, seq, subp->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "seq %d, Extracting combined oversize packet of length %d" __L, seq, subp->size);
//_raw(NET__NET_CREATE_HEX, subp); //_raw(NET__NET_CREATE_HEX, subp);
subp->copyInfo(p); subp->copyInfo(p);
ProcessPacket(subp); ProcessPacket(subp);
delete subp; delete subp;
} else { } else {
EQRawApplicationPacket *ap=MakeApplicationPacket(oversize_buffer,oversize_offset); EQRawApplicationPacket *ap=MakeApplicationPacket(oversize_buffer,oversize_offset);
_log(NET__NET_CREATE, _L "seq %d, completed combined oversize packet of length %d" __L, seq, ap->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "seq %d, completed combined oversize packet of length %d" __L, seq, ap->size);
if (ap) { if (ap) {
ap->copyInfo(p); ap->copyInfo(p);
InboundQueuePush(ap); InboundQueuePush(ap);
@ -284,7 +284,7 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
oversize_buffer=new unsigned char[oversize_length]; oversize_buffer=new unsigned char[oversize_length];
memcpy(oversize_buffer,p->pBuffer+6,p->size-6); memcpy(oversize_buffer,p->pBuffer+6,p->size-6);
oversize_offset=p->size-6; oversize_offset=p->size-6;
_log(NET__NET_TRACE, _L "First fragment of oversized of seq %d: now at %d/%d" __L, seq, oversize_offset, oversize_length); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "First fragment of oversized of seq %d: now at %d/%d" __L, seq, oversize_offset, oversize_length);
} }
} }
} }
@ -292,14 +292,14 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
case OP_KeepAlive: { case OP_KeepAlive: {
#ifndef COLLECTOR #ifndef COLLECTOR
NonSequencedPush(new EQProtocolPacket(p->opcode,p->pBuffer,p->size)); NonSequencedPush(new EQProtocolPacket(p->opcode,p->pBuffer,p->size));
_log(NET__NET_TRACE, _L "Received and queued reply to keep alive" __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received and queued reply to keep alive" __L);
#endif #endif
} }
break; break;
case OP_Ack: { case OP_Ack: {
if(!p->pBuffer || (p->Size() < 4)) if(!p->pBuffer || (p->Size() < 4))
{ {
_log(NET__ERROR, _L "Received OP_Ack that was of malformed size" __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_Ack that was of malformed size" __L);
break; break;
} }
#ifndef COLLECTOR #ifndef COLLECTOR
@ -315,12 +315,12 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
case OP_SessionRequest: { case OP_SessionRequest: {
if(p->Size() < sizeof(SessionRequest)) if(p->Size() < sizeof(SessionRequest))
{ {
_log(NET__ERROR, _L "Received OP_SessionRequest that was of malformed size" __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_SessionRequest that was of malformed size" __L);
break; break;
} }
#ifndef COLLECTOR #ifndef COLLECTOR
if (GetState()==ESTABLISHED) { if (GetState()==ESTABLISHED) {
_log(NET__ERROR, _L "Received OP_SessionRequest in ESTABLISHED state (%d) streamactive (%i) attempt (%i)" __L, GetState(),streamactive,sessionAttempts); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_SessionRequest in ESTABLISHED state (%d) streamactive (%i) attempt (%i)" __L, GetState(),streamactive,sessionAttempts);
// client seems to try a max of 30 times (initial+3 retries) then gives up, giving it a few more attempts just in case // client seems to try a max of 30 times (initial+3 retries) then gives up, giving it a few more attempts just in case
// streamactive means we identified the opcode for the stream, we cannot re-establish this connection // streamactive means we identified the opcode for the stream, we cannot re-establish this connection
@ -340,7 +340,7 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
SessionRequest *Request=(SessionRequest *)p->pBuffer; SessionRequest *Request=(SessionRequest *)p->pBuffer;
Session=ntohl(Request->Session); Session=ntohl(Request->Session);
SetMaxLen(ntohl(Request->MaxLength)); SetMaxLen(ntohl(Request->MaxLength));
_log(NET__NET_TRACE, _L "Received OP_SessionRequest: session %lu, maxlen %d" __L, (unsigned long)Session, MaxLen); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_SessionRequest: session %lu, maxlen %d" __L, (unsigned long)Session, MaxLen);
SetState(ESTABLISHED); SetState(ESTABLISHED);
#ifndef COLLECTOR #ifndef COLLECTOR
Key=0x11223344; Key=0x11223344;
@ -351,7 +351,7 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
case OP_SessionResponse: { case OP_SessionResponse: {
if(p->Size() < sizeof(SessionResponse)) if(p->Size() < sizeof(SessionResponse))
{ {
_log(NET__ERROR, _L "Received OP_SessionResponse that was of malformed size" __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_SessionResponse that was of malformed size" __L);
break; break;
} }
@ -367,7 +367,7 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
compressed=(Response->Format&FLAG_COMPRESSED); compressed=(Response->Format&FLAG_COMPRESSED);
encoded=(Response->Format&FLAG_ENCODED); encoded=(Response->Format&FLAG_ENCODED);
_log(NET__NET_TRACE, _L "Received OP_SessionResponse: session %lu, maxlen %d, key %lu, compressed? %s, encoded? %s" __L, (unsigned long)Session, MaxLen, (unsigned long)Key, compressed?"yes":"no", encoded?"yes":"no"); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_SessionResponse: session %lu, maxlen %d, key %lu, compressed? %s, encoded? %s" __L, (unsigned long)Session, MaxLen, (unsigned long)Key, compressed?"yes":"no", encoded?"yes":"no");
// Kinda kludgy, but trie for now // Kinda kludgy, but trie for now
if (StreamType==UnknownStream) { if (StreamType==UnknownStream) {
@ -390,17 +390,17 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
EQStreamState state = GetState(); EQStreamState state = GetState();
if(state == ESTABLISHED) { if(state == ESTABLISHED) {
//client initiated disconnect? //client initiated disconnect?
_log(NET__NET_TRACE, _L "Received unsolicited OP_SessionDisconnect. Treating like a client-initiated disconnect." __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received unsolicited OP_SessionDisconnect. Treating like a client-initiated disconnect." __L);
_SendDisconnect(); _SendDisconnect();
SetState(CLOSED); SetState(CLOSED);
} else if(state == CLOSING) { } else if(state == CLOSING) {
//we were waiting for this anyways, ignore pending messages, send the reply and be closed. //we were waiting for this anyways, ignore pending messages, send the reply and be closed.
_log(NET__NET_TRACE, _L "Received OP_SessionDisconnect when we have a pending close, they beat us to it. Were happy though." __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_SessionDisconnect when we have a pending close, they beat us to it. Were happy though." __L);
_SendDisconnect(); _SendDisconnect();
SetState(CLOSED); SetState(CLOSED);
} else { } else {
//we are expecting this (or have already gotten it, but dont care either way) //we are expecting this (or have already gotten it, but dont care either way)
_log(NET__NET_TRACE, _L "Received expected OP_SessionDisconnect. Moving to closed state." __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received expected OP_SessionDisconnect. Moving to closed state." __L);
SetState(CLOSED); SetState(CLOSED);
} }
} }
@ -408,7 +408,7 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
case OP_OutOfOrderAck: { case OP_OutOfOrderAck: {
if(!p->pBuffer || (p->Size() < 4)) if(!p->pBuffer || (p->Size() < 4))
{ {
_log(NET__ERROR, _L "Received OP_OutOfOrderAck that was of malformed size" __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_OutOfOrderAck that was of malformed size" __L);
break; break;
} }
#ifndef COLLECTOR #ifndef COLLECTOR
@ -416,15 +416,15 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
MOutboundQueue.lock(); MOutboundQueue.lock();
if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) { if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) {
_log(NET__ERROR, _L "Pre-OOA Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, SequencedBase, SequencedQueue.size(), NextOutSeq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Pre-OOA Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, SequencedBase, SequencedQueue.size(), NextOutSeq);
} }
if(NextSequencedSend > SequencedQueue.size()) { if(NextSequencedSend > SequencedQueue.size()) {
_log(NET__ERROR, _L "Pre-OOA Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size()); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Pre-OOA Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size());
} }
//if the packet they got out of order is between our last acked packet and the last sent packet, then its valid. //if the packet they got out of order is between our last acked packet and the last sent packet, then its valid.
if (CompareSequence(SequencedBase,seq) != SeqPast && CompareSequence(NextOutSeq,seq) == SeqPast) { if (CompareSequence(SequencedBase,seq) != SeqPast && CompareSequence(NextOutSeq,seq) == SeqPast) {
_log(NET__NET_TRACE, _L "Received OP_OutOfOrderAck for sequence %d, starting retransmit at the start of our unacked buffer (seq %d, was %d)." __L, logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_OutOfOrderAck for sequence %d, starting retransmit at the start of our unacked buffer (seq %d, was %d)." __L,
seq, SequencedBase, SequencedBase+NextSequencedSend); seq, SequencedBase, SequencedBase+NextSequencedSend);
bool retransmit_acked_packets = false; bool retransmit_acked_packets = false;
@ -435,7 +435,7 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
if(!retransmit_acked_packets) { if(!retransmit_acked_packets) {
uint16 sqsize = SequencedQueue.size(); uint16 sqsize = SequencedQueue.size();
uint16 index = seq - SequencedBase; uint16 index = seq - SequencedBase;
_log(NET__NET_TRACE, _L "OP_OutOfOrderAck marking packet acked in queue (queue index = %d, queue size = %d)." __L, index, sqsize); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "OP_OutOfOrderAck marking packet acked in queue (queue index = %d, queue size = %d)." __L, index, sqsize);
if (index < sqsize) { if (index < sqsize) {
std::deque<EQProtocolPacket *>::iterator sitr; std::deque<EQProtocolPacket *>::iterator sitr;
sitr = SequencedQueue.begin(); sitr = SequencedQueue.begin();
@ -450,15 +450,15 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
NextSequencedSend = 0; NextSequencedSend = 0;
} else { } else {
_log(NET__NET_TRACE, _L "Received OP_OutOfOrderAck for out-of-window %d. Window (%d->%d)." __L, seq, SequencedBase, NextOutSeq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_OutOfOrderAck for out-of-window %d. Window (%d->%d)." __L, seq, SequencedBase, NextOutSeq);
} }
if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) { if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) {
_log(NET__ERROR, _L "Post-OOA Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, SequencedBase, SequencedQueue.size(), NextOutSeq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Post-OOA Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, SequencedBase, SequencedQueue.size(), NextOutSeq);
} }
if(NextSequencedSend > SequencedQueue.size()) { if(NextSequencedSend > SequencedQueue.size()) {
_log(NET__ERROR, _L "Post-OOA Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size()); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Post-OOA Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size());
} }
MOutboundQueue.unlock(); MOutboundQueue.unlock();
#endif #endif
@ -467,12 +467,12 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
case OP_SessionStatRequest: { case OP_SessionStatRequest: {
if(p->Size() < sizeof(SessionStats)) if(p->Size() < sizeof(SessionStats))
{ {
_log(NET__ERROR, _L "Received OP_SessionStatRequest that was of malformed size" __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_SessionStatRequest that was of malformed size" __L);
break; break;
} }
#ifndef COLLECTOR #ifndef COLLECTOR
SessionStats *Stats=(SessionStats *)p->pBuffer; SessionStats *Stats=(SessionStats *)p->pBuffer;
_log(NET__NET_TRACE, _L "Received Stats: %lu packets received, %lu packets sent, Deltas: local %lu, (%lu <- %lu -> %lu) remote %lu" __L, logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received Stats: %lu packets received, %lu packets sent, Deltas: local %lu, (%lu <- %lu -> %lu) remote %lu" __L,
(unsigned long)ntohl(Stats->packets_received), (unsigned long)ntohl(Stats->packets_sent), (unsigned long)ntohl(Stats->last_local_delta), (unsigned long)ntohl(Stats->packets_received), (unsigned long)ntohl(Stats->packets_sent), (unsigned long)ntohl(Stats->last_local_delta),
(unsigned long)ntohl(Stats->low_delta), (unsigned long)ntohl(Stats->average_delta), (unsigned long)ntohl(Stats->low_delta), (unsigned long)ntohl(Stats->average_delta),
(unsigned long)ntohl(Stats->high_delta), (unsigned long)ntohl(Stats->last_remote_delta)); (unsigned long)ntohl(Stats->high_delta), (unsigned long)ntohl(Stats->last_remote_delta));
@ -493,18 +493,18 @@ void EQStream::ProcessPacket(EQProtocolPacket *p)
} }
if(retransmittimeout > RETRANSMIT_TIMEOUT_MAX) if(retransmittimeout > RETRANSMIT_TIMEOUT_MAX)
retransmittimeout = RETRANSMIT_TIMEOUT_MAX; retransmittimeout = RETRANSMIT_TIMEOUT_MAX;
_log(NET__NET_TRACE, _L "Retransmit timeout recalculated to %dms" __L, retransmittimeout); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Retransmit timeout recalculated to %dms" __L, retransmittimeout);
} }
} }
#endif #endif
} }
break; break;
case OP_SessionStatResponse: { case OP_SessionStatResponse: {
_log(NET__NET_TRACE, _L "Received OP_SessionStatResponse. Ignoring." __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_SessionStatResponse. Ignoring." __L);
} }
break; break;
case OP_OutOfSession: { case OP_OutOfSession: {
_log(NET__NET_TRACE, _L "Received OP_OutOfSession. Ignoring." __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received OP_OutOfSession. Ignoring." __L);
} }
break; break;
default: default:
@ -562,7 +562,7 @@ void EQStream::SendPacket(uint16 opcode, EQApplicationPacket *p)
// Convert the EQApplicationPacket to 1 or more EQProtocolPackets // Convert the EQApplicationPacket to 1 or more EQProtocolPackets
if (p->size>(MaxLen-8)) { // proto-op(2), seq(2), app-op(2) ... data ... crc(2) if (p->size>(MaxLen-8)) { // proto-op(2), seq(2), app-op(2) ... data ... crc(2)
_log(NET__FRAGMENT, _L "Making oversized packet, len %d" __L, p->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Making oversized packet, len %d" __L, p->size);
unsigned char *tmpbuff=new unsigned char[p->size+3]; unsigned char *tmpbuff=new unsigned char[p->size+3];
length=p->serialize(opcode, tmpbuff); length=p->serialize(opcode, tmpbuff);
@ -571,7 +571,7 @@ void EQStream::SendPacket(uint16 opcode, EQApplicationPacket *p)
*(uint32 *)(out->pBuffer+2)=htonl(p->Size()); *(uint32 *)(out->pBuffer+2)=htonl(p->Size());
used=MaxLen-10; used=MaxLen-10;
memcpy(out->pBuffer+6,tmpbuff,used); memcpy(out->pBuffer+6,tmpbuff,used);
_log(NET__FRAGMENT, _L "First fragment: used %d/%d. Put size %d in the packet" __L, used, p->size, p->Size()); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "First fragment: used %d/%d. Put size %d in the packet" __L, used, p->size, p->Size());
SequencedPush(out); SequencedPush(out);
@ -582,7 +582,7 @@ void EQStream::SendPacket(uint16 opcode, EQApplicationPacket *p)
out->size=chunksize+2; out->size=chunksize+2;
SequencedPush(out); SequencedPush(out);
used+=chunksize; used+=chunksize;
_log(NET__FRAGMENT, _L "Subsequent fragment: len %d, used %d/%d." __L, chunksize, used, p->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Subsequent fragment: len %d, used %d/%d." __L, chunksize, used, p->size);
} }
delete p; delete p;
delete[] tmpbuff; delete[] tmpbuff;
@ -606,22 +606,22 @@ void EQStream::SequencedPush(EQProtocolPacket *p)
#else #else
MOutboundQueue.lock(); MOutboundQueue.lock();
if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) { if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) {
_log(NET__ERROR, _L "Pre-Push Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, SequencedBase, SequencedQueue.size(), NextOutSeq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Pre-Push Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, SequencedBase, SequencedQueue.size(), NextOutSeq);
} }
if(NextSequencedSend > SequencedQueue.size()) { if(NextSequencedSend > SequencedQueue.size()) {
_log(NET__ERROR, _L "Pre-Push Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size()); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Pre-Push Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size());
} }
_log(NET__APP_TRACE, _L "Pushing sequenced packet %d of length %d. Base Seq is %d." __L, NextOutSeq, p->size, SequencedBase); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Pushing sequenced packet %d of length %d. Base Seq is %d." __L, NextOutSeq, p->size, SequencedBase);
*(uint16 *)(p->pBuffer)=htons(NextOutSeq); *(uint16 *)(p->pBuffer)=htons(NextOutSeq);
SequencedQueue.push_back(p); SequencedQueue.push_back(p);
NextOutSeq++; NextOutSeq++;
if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) { if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) {
_log(NET__ERROR, _L "Push Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, SequencedBase, SequencedQueue.size(), NextOutSeq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Push Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, SequencedBase, SequencedQueue.size(), NextOutSeq);
} }
if(NextSequencedSend > SequencedQueue.size()) { if(NextSequencedSend > SequencedQueue.size()) {
_log(NET__ERROR, _L "Push Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size()); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Push Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size());
} }
MOutboundQueue.unlock(); MOutboundQueue.unlock();
#endif #endif
@ -633,7 +633,7 @@ void EQStream::NonSequencedPush(EQProtocolPacket *p)
delete p; delete p;
#else #else
MOutboundQueue.lock(); MOutboundQueue.lock();
_log(NET__APP_TRACE, _L "Pushing non-sequenced packet of length %d" __L, p->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Pushing non-sequenced packet of length %d" __L, p->size);
NonSequencedQueue.push(p); NonSequencedQueue.push(p);
MOutboundQueue.unlock(); MOutboundQueue.unlock();
#endif #endif
@ -642,14 +642,14 @@ void EQStream::NonSequencedPush(EQProtocolPacket *p)
void EQStream::SendAck(uint16 seq) void EQStream::SendAck(uint16 seq)
{ {
uint16 Seq=htons(seq); uint16 Seq=htons(seq);
_log(NET__NET_ACKS, _L "Sending ack with sequence %d" __L, seq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Sending ack with sequence %d" __L, seq);
SetLastAckSent(seq); SetLastAckSent(seq);
NonSequencedPush(new EQProtocolPacket(OP_Ack,(unsigned char *)&Seq,sizeof(uint16))); NonSequencedPush(new EQProtocolPacket(OP_Ack,(unsigned char *)&Seq,sizeof(uint16)));
} }
void EQStream::SendOutOfOrderAck(uint16 seq) void EQStream::SendOutOfOrderAck(uint16 seq)
{ {
_log(NET__APP_TRACE, _L "Sending out of order ack with sequence %d" __L, seq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Sending out of order ack with sequence %d" __L, seq);
uint16 Seq=htons(seq); uint16 Seq=htons(seq);
NonSequencedPush(new EQProtocolPacket(OP_OutOfOrderAck,(unsigned char *)&Seq,sizeof(uint16))); NonSequencedPush(new EQProtocolPacket(OP_OutOfOrderAck,(unsigned char *)&Seq,sizeof(uint16)));
} }
@ -685,7 +685,7 @@ void EQStream::Write(int eq_fd)
// if we have a timeout defined and we have not received an ack recently enough, retransmit from beginning of queue // if we have a timeout defined and we have not received an ack recently enough, retransmit from beginning of queue
if (RETRANSMIT_TIMEOUT_MULT && !SequencedQueue.empty() && NextSequencedSend && if (RETRANSMIT_TIMEOUT_MULT && !SequencedQueue.empty() && NextSequencedSend &&
(GetState()==ESTABLISHED) && ((retransmittimer+retransmittimeout) < Timer::GetCurrentTime())) { (GetState()==ESTABLISHED) && ((retransmittimer+retransmittimeout) < Timer::GetCurrentTime())) {
_log(NET__NET_TRACE, _L "Timeout since last ack received, starting retransmit at the start of our unacked " logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Timeout since last ack received, starting retransmit at the start of our unacked "
"buffer (seq %d, was %d)." __L, SequencedBase, SequencedBase+NextSequencedSend); "buffer (seq %d, was %d)." __L, SequencedBase, SequencedBase+NextSequencedSend);
NextSequencedSend = 0; NextSequencedSend = 0;
retransmittimer = Timer::GetCurrentTime(); // don't want to endlessly retransmit the first packet retransmittimer = Timer::GetCurrentTime(); // don't want to endlessly retransmit the first packet
@ -706,24 +706,24 @@ void EQStream::Write(int eq_fd)
// If we don't have a packet to try to combine into, use this one as the base // If we don't have a packet to try to combine into, use this one as the base
// And remove it form the queue // And remove it form the queue
p = NonSequencedQueue.front(); p = NonSequencedQueue.front();
_log(NET__NET_COMBINE, _L "Starting combined packet with non-seq packet of len %d" __L, p->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Starting combined packet with non-seq packet of len %d" __L, p->size);
NonSequencedQueue.pop(); NonSequencedQueue.pop();
} else if (!p->combine(NonSequencedQueue.front())) { } else if (!p->combine(NonSequencedQueue.front())) {
// Tryint to combine this packet with the base didn't work (too big maybe) // Tryint to combine this packet with the base didn't work (too big maybe)
// So just send the base packet (we'll try this packet again later) // So just send the base packet (we'll try this packet again later)
_log(NET__NET_COMBINE, _L "Combined packet full at len %d, next non-seq packet is len %d" __L, p->size, (NonSequencedQueue.front())->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Combined packet full at len %d, next non-seq packet is len %d" __L, p->size, (NonSequencedQueue.front())->size);
ReadyToSend.push(p); ReadyToSend.push(p);
BytesWritten+=p->size; BytesWritten+=p->size;
p=nullptr; p=nullptr;
if (BytesWritten > threshold) { if (BytesWritten > threshold) {
// Sent enough this round, lets stop to be fair // Sent enough this round, lets stop to be fair
_log(NET__RATES, _L "Exceeded write threshold in nonseq (%d > %d)" __L, BytesWritten, threshold); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Exceeded write threshold in nonseq (%d > %d)" __L, BytesWritten, threshold);
break; break;
} }
} else { } else {
// Combine worked, so just remove this packet and it's spot in the queue // Combine worked, so just remove this packet and it's spot in the queue
_log(NET__NET_COMBINE, _L "Combined non-seq packet of len %d, yeilding %d combined." __L, (NonSequencedQueue.front())->size, p->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Combined non-seq packet of len %d, yeilding %d combined." __L, (NonSequencedQueue.front())->size, p->size);
delete NonSequencedQueue.front(); delete NonSequencedQueue.front();
NonSequencedQueue.pop(); NonSequencedQueue.pop();
} }
@ -734,48 +734,48 @@ void EQStream::Write(int eq_fd)
if (sitr!=SequencedQueue.end()) { if (sitr!=SequencedQueue.end()) {
if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) { if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) {
_log(NET__ERROR, _L "Pre-Send Seq NSS=%d Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, NextSequencedSend, SequencedBase, SequencedQueue.size(), NextOutSeq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Pre-Send Seq NSS=%d Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, NextSequencedSend, SequencedBase, SequencedQueue.size(), NextOutSeq);
} }
if(NextSequencedSend > SequencedQueue.size()) { if(NextSequencedSend > SequencedQueue.size()) {
_log(NET__ERROR, _L "Pre-Send Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size()); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Pre-Send Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size());
} }
uint16 seq_send = SequencedBase + NextSequencedSend; //just for logging... uint16 seq_send = SequencedBase + NextSequencedSend; //just for logging...
if(SequencedQueue.empty()) { if(SequencedQueue.empty()) {
_log(NET__ERROR, _L "Tried to write a packet with an empty queue (%d is past next out %d)" __L, seq_send, NextOutSeq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Tried to write a packet with an empty queue (%d is past next out %d)" __L, seq_send, NextOutSeq);
SeqEmpty=true; SeqEmpty=true;
continue; continue;
} }
if(GetExecutablePlatform() == ExePlatformWorld || GetExecutablePlatform() == ExePlatformZone) { if(GetExecutablePlatform() == ExePlatformWorld || GetExecutablePlatform() == ExePlatformZone) {
if (!RETRANSMIT_ACKED_PACKETS && (*sitr)->acked) { if (!RETRANSMIT_ACKED_PACKETS && (*sitr)->acked) {
_log(NET__NET_TRACE, _L "Not retransmitting seq packet %d because already marked as acked" __L, seq_send); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Not retransmitting seq packet %d because already marked as acked" __L, seq_send);
sitr++; sitr++;
NextSequencedSend++; NextSequencedSend++;
} else if (!p) { } else if (!p) {
// If we don't have a packet to try to combine into, use this one as the base // If we don't have a packet to try to combine into, use this one as the base
// Copy it first as it will still live until it is acked // Copy it first as it will still live until it is acked
p=(*sitr)->Copy(); p=(*sitr)->Copy();
_log(NET__NET_COMBINE, _L "Starting combined packet with seq packet %d of len %d" __L, seq_send, p->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Starting combined packet with seq packet %d of len %d" __L, seq_send, p->size);
++sitr; ++sitr;
NextSequencedSend++; NextSequencedSend++;
} else if (!p->combine(*sitr)) { } else if (!p->combine(*sitr)) {
// Trying to combine this packet with the base didn't work (too big maybe) // Trying to combine this packet with the base didn't work (too big maybe)
// So just send the base packet (we'll try this packet again later) // So just send the base packet (we'll try this packet again later)
_log(NET__NET_COMBINE, _L "Combined packet full at len %d, next seq packet %d is len %d" __L, p->size, seq_send, (*sitr)->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Combined packet full at len %d, next seq packet %d is len %d" __L, p->size, seq_send, (*sitr)->size);
ReadyToSend.push(p); ReadyToSend.push(p);
BytesWritten+=p->size; BytesWritten+=p->size;
p=nullptr; p=nullptr;
if (BytesWritten > threshold) { if (BytesWritten > threshold) {
// Sent enough this round, lets stop to be fair // Sent enough this round, lets stop to be fair
_log(NET__RATES, _L "Exceeded write threshold in seq (%d > %d)" __L, BytesWritten, threshold); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Exceeded write threshold in seq (%d > %d)" __L, BytesWritten, threshold);
break; break;
} }
} else { } else {
// Combine worked // Combine worked
_log(NET__NET_COMBINE, _L "Combined seq packet %d of len %d, yeilding %d combined." __L, seq_send, (*sitr)->size, p->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Combined seq packet %d of len %d, yeilding %d combined." __L, seq_send, (*sitr)->size, p->size);
++sitr; ++sitr;
NextSequencedSend++; NextSequencedSend++;
} }
@ -784,35 +784,35 @@ void EQStream::Write(int eq_fd)
// If we don't have a packet to try to combine into, use this one as the base // If we don't have a packet to try to combine into, use this one as the base
// Copy it first as it will still live until it is acked // Copy it first as it will still live until it is acked
p=(*sitr)->Copy(); p=(*sitr)->Copy();
_log(NET__NET_COMBINE, _L "Starting combined packet with seq packet %d of len %d" __L, seq_send, p->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Starting combined packet with seq packet %d of len %d" __L, seq_send, p->size);
++sitr; ++sitr;
NextSequencedSend++; NextSequencedSend++;
} else if (!p->combine(*sitr)) { } else if (!p->combine(*sitr)) {
// Trying to combine this packet with the base didn't work (too big maybe) // Trying to combine this packet with the base didn't work (too big maybe)
// So just send the base packet (we'll try this packet again later) // So just send the base packet (we'll try this packet again later)
_log(NET__NET_COMBINE, _L "Combined packet full at len %d, next seq packet %d is len %d" __L, p->size, seq_send, (*sitr)->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Combined packet full at len %d, next seq packet %d is len %d" __L, p->size, seq_send, (*sitr)->size);
ReadyToSend.push(p); ReadyToSend.push(p);
BytesWritten+=p->size; BytesWritten+=p->size;
p=nullptr; p=nullptr;
if (BytesWritten > threshold) { if (BytesWritten > threshold) {
// Sent enough this round, lets stop to be fair // Sent enough this round, lets stop to be fair
_log(NET__RATES, _L "Exceeded write threshold in seq (%d > %d)" __L, BytesWritten, threshold); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Exceeded write threshold in seq (%d > %d)" __L, BytesWritten, threshold);
break; break;
} }
} else { } else {
// Combine worked // Combine worked
_log(NET__NET_COMBINE, _L "Combined seq packet %d of len %d, yeilding %d combined." __L, seq_send, (*sitr)->size, p->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Combined seq packet %d of len %d, yeilding %d combined." __L, seq_send, (*sitr)->size, p->size);
++sitr; ++sitr;
NextSequencedSend++; NextSequencedSend++;
} }
} }
if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) { if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) {
_log(NET__ERROR, _L "Post send Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, SequencedBase, SequencedQueue.size(), NextOutSeq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Post send Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, SequencedBase, SequencedQueue.size(), NextOutSeq);
} }
if(NextSequencedSend > SequencedQueue.size()) { if(NextSequencedSend > SequencedQueue.size()) {
_log(NET__ERROR, _L "Post send Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size()); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Post send Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size());
} }
} else { } else {
// No more sequenced packets // No more sequenced packets
@ -824,7 +824,7 @@ void EQStream::Write(int eq_fd)
// We have a packet still, must have run out of both seq and non-seq, so send it // We have a packet still, must have run out of both seq and non-seq, so send it
if (p) { if (p) {
_log(NET__NET_COMBINE, _L "Final combined packet not full, len %d" __L, p->size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Final combined packet not full, len %d" __L, p->size);
ReadyToSend.push(p); ReadyToSend.push(p);
BytesWritten+=p->size; BytesWritten+=p->size;
} }
@ -904,7 +904,7 @@ EQProtocolPacket *out=new EQProtocolPacket(OP_SessionResponse,nullptr,sizeof(Ses
out->size=sizeof(SessionResponse); out->size=sizeof(SessionResponse);
_log(NET__NET_TRACE, _L "Sending OP_SessionResponse: session %lu, maxlen=%d, key=0x%x, compressed? %s, encoded? %s" __L, logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Sending OP_SessionResponse: session %lu, maxlen=%d, key=0x%x, compressed? %s, encoded? %s" __L,
(unsigned long)Session, MaxLen, Key, compressed?"yes":"no", encoded?"yes":"no"); (unsigned long)Session, MaxLen, Key, compressed?"yes":"no", encoded?"yes":"no");
NonSequencedPush(out); NonSequencedPush(out);
@ -918,7 +918,7 @@ EQProtocolPacket *out=new EQProtocolPacket(OP_SessionRequest,nullptr,sizeof(Sess
Request->Session=htonl(time(nullptr)); Request->Session=htonl(time(nullptr));
Request->MaxLength=htonl(512); Request->MaxLength=htonl(512);
_log(NET__NET_TRACE, _L "Sending OP_SessionRequest: session %lu, maxlen=%d" __L, (unsigned long)ntohl(Request->Session), ntohl(Request->MaxLength)); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Sending OP_SessionRequest: session %lu, maxlen=%d" __L, (unsigned long)ntohl(Request->Session), ntohl(Request->MaxLength));
NonSequencedPush(out); NonSequencedPush(out);
} }
@ -932,7 +932,7 @@ void EQStream::_SendDisconnect()
*(uint32 *)out->pBuffer=htonl(Session); *(uint32 *)out->pBuffer=htonl(Session);
NonSequencedPush(out); NonSequencedPush(out);
_log(NET__NET_TRACE, _L "Sending OP_SessionDisconnect: session %lu" __L, (unsigned long)Session); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Sending OP_SessionDisconnect: session %lu" __L, (unsigned long)Session);
} }
void EQStream::InboundQueuePush(EQRawApplicationPacket *p) void EQStream::InboundQueuePush(EQRawApplicationPacket *p)
@ -1016,7 +1016,7 @@ void EQStream::InboundQueueClear()
{ {
EQApplicationPacket *p=nullptr; EQApplicationPacket *p=nullptr;
_log(NET__APP_TRACE, _L "Clearing inbound queue" __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Clearing inbound queue" __L);
MInboundQueue.lock(); MInboundQueue.lock();
if (!InboundQueue.empty()) { if (!InboundQueue.empty()) {
@ -1059,7 +1059,7 @@ void EQStream::OutboundQueueClear()
{ {
EQProtocolPacket *p=nullptr; EQProtocolPacket *p=nullptr;
_log(NET__APP_TRACE, _L "Clearing outbound queue" __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Clearing outbound queue" __L);
MOutboundQueue.lock(); MOutboundQueue.lock();
while(!NonSequencedQueue.empty()) { while(!NonSequencedQueue.empty()) {
@ -1081,7 +1081,7 @@ void EQStream::PacketQueueClear()
{ {
EQProtocolPacket *p=nullptr; EQProtocolPacket *p=nullptr;
_log(NET__APP_TRACE, _L "Clearing future packet queue" __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Clearing future packet queue" __L);
if(!PacketQueue.empty()) { if(!PacketQueue.empty()) {
std::map<unsigned short,EQProtocolPacket *>::iterator itr; std::map<unsigned short,EQProtocolPacket *>::iterator itr;
@ -1143,33 +1143,33 @@ std::deque<EQProtocolPacket *>::iterator itr, tmp;
MOutboundQueue.lock(); MOutboundQueue.lock();
//do a bit of sanity checking. //do a bit of sanity checking.
if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) { if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) {
_log(NET__ERROR, _L "Pre-Ack Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, SequencedBase, SequencedQueue.size(), NextOutSeq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Pre-Ack Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, SequencedBase, SequencedQueue.size(), NextOutSeq);
} }
if(NextSequencedSend > SequencedQueue.size()) { if(NextSequencedSend > SequencedQueue.size()) {
_log(NET__ERROR, _L "Pre-Ack Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size()); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Pre-Ack Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size());
} }
SeqOrder ord = CompareSequence(SequencedBase, seq); SeqOrder ord = CompareSequence(SequencedBase, seq);
if(ord == SeqInOrder) { if(ord == SeqInOrder) {
//they are not acking anything new... //they are not acking anything new...
_log(NET__NET_ACKS, _L "Received an ack with no window advancement (seq %d)." __L, seq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received an ack with no window advancement (seq %d)." __L, seq);
} else if(ord == SeqPast) { } else if(ord == SeqPast) {
//they are nacking blocks going back before our buffer, wtf? //they are nacking blocks going back before our buffer, wtf?
_log(NET__NET_ACKS, _L "Received an ack with backward window advancement (they gave %d, our window starts at %d). This is bad." __L, seq, SequencedBase); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received an ack with backward window advancement (they gave %d, our window starts at %d). This is bad." __L, seq, SequencedBase);
} else { } else {
_log(NET__NET_ACKS, _L "Received an ack up through sequence %d. Our base is %d." __L, seq, SequencedBase); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Received an ack up through sequence %d. Our base is %d." __L, seq, SequencedBase);
//this is a good ack, we get to ack some blocks. //this is a good ack, we get to ack some blocks.
seq++; //we stop at the block right after their ack, counting on the wrap of both numbers. seq++; //we stop at the block right after their ack, counting on the wrap of both numbers.
while(SequencedBase != seq) { while(SequencedBase != seq) {
if(SequencedQueue.empty()) { if(SequencedQueue.empty()) {
_log(NET__ERROR, _L "OUT OF PACKETS acked packet with sequence %lu. Next send is %d before this." __L, (unsigned long)SequencedBase, NextSequencedSend); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "OUT OF PACKETS acked packet with sequence %lu. Next send is %d before this." __L, (unsigned long)SequencedBase, NextSequencedSend);
SequencedBase = NextOutSeq; SequencedBase = NextOutSeq;
NextSequencedSend = 0; NextSequencedSend = 0;
break; break;
} }
_log(NET__NET_ACKS, _L "Removing acked packet with sequence %lu. Next send is %d before this." __L, (unsigned long)SequencedBase, NextSequencedSend); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Removing acked packet with sequence %lu. Next send is %d before this." __L, (unsigned long)SequencedBase, NextSequencedSend);
//clean out the acked packet //clean out the acked packet
delete SequencedQueue.front(); delete SequencedQueue.front();
SequencedQueue.pop_front(); SequencedQueue.pop_front();
@ -1180,10 +1180,10 @@ _log(NET__ERROR, _L "OUT OF PACKETS acked packet with sequence %lu. Next send is
SequencedBase++; SequencedBase++;
} }
if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) { if(uint16(SequencedBase + SequencedQueue.size()) != NextOutSeq) {
_log(NET__ERROR, _L "Post-Ack on %d Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, seq, SequencedBase, SequencedQueue.size(), NextOutSeq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Post-Ack on %d Invalid Sequenced queue: BS %d + SQ %d != NOS %d" __L, seq, SequencedBase, SequencedQueue.size(), NextOutSeq);
} }
if(NextSequencedSend > SequencedQueue.size()) { if(NextSequencedSend > SequencedQueue.size()) {
_log(NET__ERROR, _L "Post-Ack Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size()); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Post-Ack Next Send Sequence is beyond the end of the queue NSS %d > SQ %d" __L, NextSequencedSend, SequencedQueue.size());
} }
} }
@ -1193,7 +1193,7 @@ if(NextSequencedSend > SequencedQueue.size()) {
void EQStream::SetNextAckToSend(uint32 seq) void EQStream::SetNextAckToSend(uint32 seq)
{ {
MAcks.lock(); MAcks.lock();
_log(NET__NET_ACKS, _L "Set Next Ack To Send to %lu" __L, (unsigned long)seq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Set Next Ack To Send to %lu" __L, (unsigned long)seq);
NextAckToSend=seq; NextAckToSend=seq;
MAcks.unlock(); MAcks.unlock();
} }
@ -1201,7 +1201,7 @@ void EQStream::SetNextAckToSend(uint32 seq)
void EQStream::SetLastAckSent(uint32 seq) void EQStream::SetLastAckSent(uint32 seq)
{ {
MAcks.lock(); MAcks.lock();
_log(NET__NET_ACKS, _L "Set Last Ack Sent to %lu" __L, (unsigned long)seq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Set Last Ack Sent to %lu" __L, (unsigned long)seq);
LastAckSent=seq; LastAckSent=seq;
MAcks.unlock(); MAcks.unlock();
} }
@ -1217,7 +1217,7 @@ void EQStream::ProcessQueue()
logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Processing Queued Packet: Seq=%d" __L, NextInSeq); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Processing Queued Packet: Seq=%d" __L, NextInSeq);
ProcessPacket(qp); ProcessPacket(qp);
delete qp; delete qp;
_log(NET__APP_TRACE, _L "OP_Packet Queue size=%d" __L, PacketQueue.size()); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "OP_Packet Queue size=%d" __L, PacketQueue.size());
} }
} }
@ -1228,21 +1228,21 @@ EQProtocolPacket *qp=nullptr;
if ((itr=PacketQueue.find(seq))!=PacketQueue.end()) { if ((itr=PacketQueue.find(seq))!=PacketQueue.end()) {
qp=itr->second; qp=itr->second;
PacketQueue.erase(itr); PacketQueue.erase(itr);
_log(NET__APP_TRACE, _L "OP_Packet Queue size=%d" __L, PacketQueue.size()); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "OP_Packet Queue size=%d" __L, PacketQueue.size());
} }
return qp; return qp;
} }
void EQStream::SetStreamType(EQStreamType type) void EQStream::SetStreamType(EQStreamType type)
{ {
_log(NET__NET_TRACE, _L "Changing stream type from %s to %s" __L, StreamTypeString(StreamType), StreamTypeString(type)); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Changing stream type from %s to %s" __L, StreamTypeString(StreamType), StreamTypeString(type));
StreamType=type; StreamType=type;
switch (StreamType) { switch (StreamType) {
case LoginStream: case LoginStream:
app_opcode_size=1; app_opcode_size=1;
compressed=false; compressed=false;
encoded=false; encoded=false;
_log(NET__NET_TRACE, _L "Login stream has app opcode size %d, is not compressed or encoded." __L, app_opcode_size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Login stream has app opcode size %d, is not compressed or encoded." __L, app_opcode_size);
break; break;
case ChatOrMailStream: case ChatOrMailStream:
case ChatStream: case ChatStream:
@ -1250,7 +1250,7 @@ void EQStream::SetStreamType(EQStreamType type)
app_opcode_size=1; app_opcode_size=1;
compressed=false; compressed=false;
encoded=true; encoded=true;
_log(NET__NET_TRACE, _L "Chat/Mail stream has app opcode size %d, is not compressed, and is encoded." __L, app_opcode_size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Chat/Mail stream has app opcode size %d, is not compressed, and is encoded." __L, app_opcode_size);
break; break;
case ZoneStream: case ZoneStream:
case WorldStream: case WorldStream:
@ -1258,7 +1258,7 @@ void EQStream::SetStreamType(EQStreamType type)
app_opcode_size=2; app_opcode_size=2;
compressed=true; compressed=true;
encoded=false; encoded=false;
_log(NET__NET_TRACE, _L "World/Zone stream has app opcode size %d, is compressed, and is not encoded." __L, app_opcode_size); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "World/Zone stream has app opcode size %d, is compressed, and is not encoded." __L, app_opcode_size);
break; break;
} }
} }
@ -1308,7 +1308,7 @@ EQStream::SeqOrder EQStream::CompareSequence(uint16 expected_seq , uint16 seq)
void EQStream::SetState(EQStreamState state) { void EQStream::SetState(EQStreamState state) {
MState.lock(); MState.lock();
_log(NET__NET_TRACE, _L "Changing state from %d to %d" __L, State, state); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Changing state from %d to %d" __L, State, state);
State=state; State=state;
MState.unlock(); MState.unlock();
} }
@ -1320,7 +1320,7 @@ void EQStream::CheckTimeout(uint32 now, uint32 timeout) {
EQStreamState orig_state = GetState(); EQStreamState orig_state = GetState();
if (orig_state == CLOSING && !outgoing_data) { if (orig_state == CLOSING && !outgoing_data) {
_log(NET__NET_TRACE, _L "Out of data in closing state, disconnecting." __L); logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Out of data in closing state, disconnecting." __L);
_SendDisconnect(); _SendDisconnect();
SetState(DISCONNECTING); SetState(DISCONNECTING);
} else if (LastPacket && (now-LastPacket) > timeout) { } else if (LastPacket && (now-LastPacket) > timeout) {
@ -1371,11 +1371,11 @@ void EQStream::AdjustRates(uint32 average_delta)
MRate.lock(); MRate.lock();
RateThreshold=RATEBASE/average_delta; RateThreshold=RATEBASE/average_delta;
DecayRate=DECAYBASE/average_delta; DecayRate=DECAYBASE/average_delta;
_log(NET__RATES, _L "Adjusting data rate to thresh %d, decay %d based on avg delta %d" __L, logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Adjusting data rate to thresh %d, decay %d based on avg delta %d" __L,
RateThreshold, DecayRate, average_delta); RateThreshold, DecayRate, average_delta);
MRate.unlock(); MRate.unlock();
} else { } else {
_log(NET__RATES, _L "Not adjusting data rate because avg delta over max (%d > %d)" __L, logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Not adjusting data rate because avg delta over max (%d > %d)" __L,
average_delta, AVERAGE_DELTA_MAX); average_delta, AVERAGE_DELTA_MAX);
} }
} else { } else {
@ -1383,7 +1383,7 @@ void EQStream::AdjustRates(uint32 average_delta)
MRate.lock(); MRate.lock();
RateThreshold=RATEBASE/average_delta; RateThreshold=RATEBASE/average_delta;
DecayRate=DECAYBASE/average_delta; DecayRate=DECAYBASE/average_delta;
_log(NET__RATES, _L "Adjusting data rate to thresh %d, decay %d based on avg delta %d" __L, logger.LogDebugType(EQEmuLogSys::Detail, EQEmuLogSys::Netcode, _L "Adjusting data rate to thresh %d, decay %d based on avg delta %d" __L,
RateThreshold, DecayRate, average_delta); RateThreshold, DecayRate, average_delta);
MRate.unlock(); MRate.unlock();
} }