/// Update the WorldSession (triggered by World update)
bool WorldSession::Update(uint32 diff, PacketFilter& updater)
{
/// Update Timeout timer.
UpdateTimeOutTime(diff);
///- Before we process anything:
/// If necessary, kick the player from the character select screen
if (IsConnectionIdle())
m_Socket->CloseSocket();
///- Retrieve packets from the receive queue and call the appropriate handlers
/// not process packets if socket already closed
WorldPacket* packet = NULL;
//! Delete packet after processing by default
bool deletePacket = true;
//! To prevent infinite loop
WorldPacket* firstDelayedPacket = NULL;
//! If _recvQueue.peek() == firstDelayedPacket it means that in this Update call, we've processed all
//! *properly timed* packets, and we're now at the part of the queue where we find
//! delayed packets that were re-enqueued due to improper timing. To prevent an infinite
//! loop caused by re-enqueueing the same packets over and over again, we stop updating this session
//! and continue updating others. The re-enqueued packets will be handled in the next Update call for this session.
uint32 processedPackets = 0;
while (m_Socket && !m_Socket->IsClosed() &&
!_recvQueue.empty() && _recvQueue.peek(true) != firstDelayedPacket &&
_recvQueue.next(packet, updater))
{
if (!AntiDOS.EvaluateOpcode(*packet))
KickPlayer();
OpcodeHandler const* opHandle = clientOpcodeTable[packet->GetOpcode()];
try
{
switch (opHandle->Status)
{
case STATUS_LOGGEDIN:
if (!_player)
{
// skip STATUS_LOGGEDIN opcode unexpected errors if player logout sometime ago - this can be network lag delayed packets
//! If player didn't log out a while ago, it means packets are being sent while the server does not recognize
//! the client to be in world yet. We will re-add the packets to the bottom of the queue and process them later.
if (!m_playerRecentlyLogout)
{
//! Prevent infinite loop
if (!firstDelayedPacket)
firstDelayedPacket = packet;
//! Because checking a bool is faster than reallocating memory
deletePacket = false;
QueuePacket(packet);
//! Log
TC_LOG_DEBUG("network", "Re-enqueueing packet with opcode %s with with status STATUS_LOGGEDIN. "
"Player is currently not in world yet.", GetOpcodeNameForLogging(packet->GetOpcode(), false).c_str());
}
}
else if (_player->IsInWorld())
{
sScriptMgr->OnPacketReceive(m_Socket, WorldPacket(*packet));
(this->*opHandle->Handler)(*packet);
LogUnprocessedTail(packet);
}
// lag can cause STATUS_LOGGEDIN opcodes to arrive after the player started a transfer
break;
case STATUS_LOGGEDIN_OR_RECENTLY_LOGGOUT:
if (!_player && !m_playerRecentlyLogout && !m_playerLogout) // There's a short delay between _player = null and m_playerRecentlyLogout = true during logout
LogUnexpectedOpcode(packet, "STATUS_LOGGEDIN_OR_RECENTLY_LOGGOUT",
"the player has not logged in yet and not recently logout");
else
{
// not expected _player or must checked in packet hanlder
sScriptMgr->OnPacketReceive(m_Socket, WorldPacket(*packet));
(this->*opHandle->Handler)(*packet);
LogUnprocessedTail(packet);
}
break;
case STATUS_TRANSFER:
if (!_player)
LogUnexpectedOpcode(packet, "STATUS_TRANSFER", "the player has not logged in yet");
else if (_player->IsInWorld())
LogUnexpectedOpcode(packet, "STATUS_TRANSFER", "the player is still in world");
else
{
sScriptMgr->OnPacketReceive(m_Socket, WorldPacket(*packet));
(this->*opHandle->Handler)(*packet);
LogUnprocessedTail(packet);
}
break;
case STATUS_AUTHED:
// prevent cheating with skip queue wait
if (m_inQueue)
{
LogUnexpectedOpcode(packet, "STATUS_AUTHED", "the player not pass queue yet");
break;
}
// some auth opcodes can be recieved before STATUS_LOGGEDIN_OR_RECENTLY_LOGGOUT opcodes
// however when we recieve CMSG_CHAR_ENUM we are surely no longer during the logout process.
if (packet->GetOpcode() == CMSG_CHAR_ENUM)
m_playerRecentlyLogout = false;
sScriptMgr->OnPacketReceive(m_Socket, WorldPacket(*packet));
(this->*opHandle->Handler)(*packet);
LogUnprocessedTail(packet);
break;
case STATUS_NEVER:
TC_LOG_ERROR("network.opcode", "Received not allowed opcode %s from %s", GetOpcodeNameForLogging(packet->GetOpcode(), false).c_str()
, GetPlayerInfo().c_str());
break;
case STATUS_UNHANDLED:
TC_LOG_ERROR("network.opcode", "Received not handled opcode %s from %s", GetOpcodeNameForLogging(packet->GetOpcode(), false).c_str()
, GetPlayerInfo().c_str());
break;
}
}
catch (ByteBufferException const&)
{
TC_LOG_ERROR("network", "WorldSession::Update ByteBufferException occured while parsing a packet (opcode: %s) from client %s, accountid=%i. Skipped packet.",
GetOpcodeNameForLogging(packet->GetOpcode(), false).c_str(), GetRemoteAddress().c_str(), GetAccountId());
packet->hexlike();
}
if (deletePacket)
delete packet;
deletePacket = true;
#define MAX_PROCESSED_PACKETS_IN_SAME_WORLDSESSION_UPDATE 100
processedPackets++;
//process only a max amout of packets in 1 Update() call.
//Any leftover will be processed in next update
if (processedPackets > MAX_PROCESSED_PACKETS_IN_SAME_WORLDSESSION_UPDATE)
break;
}
if (m_Socket && !m_Socket->IsClosed() && _warden)
_warden->Update();
ProcessQueryCallbacks();
//check if we are safe to proceed with logout
//logout procedure should happen only in World::UpdateSessions() method!!!
if (updater.ProcessLogout())
{
time_t currTime = time(NULL);
///- If necessary, log the player out
if (ShouldLogOut(currTime) && !m_playerLoading)
LogoutPlayer(true);
if (m_Socket && GetPlayer() && _warden)
_warden->Update();
///- Cleanup socket pointer if need
if (m_Socket && m_Socket->IsClosed())
{
m_Socket->RemoveReference();
m_Socket = NULL;
}
if (!m_Socket)
return false; //Will remove this session from the world session map
}
return true;
}
void WorldSession::Handle_EarlyProccess(WorldPacket& recvPacket)
{
TC_LOG_ERROR("network.opcode", "Received opcode %s that must be processed in WorldSocket::OnRead from %s"
, GetOpcodeNameForLogging(recvPacket.GetOpcode(), false).c_str(), GetPlayerInfo().c_str());
}
void WorldSession::Handle_Deprecated(WorldPacket& recvPacket)
{
TC_LOG_ERROR(LOG_FILTER_OPCODES, "Received deprecated opcode %s from %s"
, GetOpcodeNameForLogging(recvPacket.GetOpcode()).c_str(), GetPlayerInfo().c_str());
}
/// Logging helper for unexpected opcodes
void WorldSession::LogUnexpectedOpcode(WorldPacket* packet, const char* status, const char *reason)
{
TC_LOG_ERROR("network.opcode", "Received unexpected opcode %s Status: %s Reason: %s from %s",
GetOpcodeNameForLogging(packet->GetOpcode(), false).c_str(), status, reason, GetPlayerInfo().c_str());
}
int WorldSocket::SendPacket(WorldPacket const& pct)
{
ACE_GUARD_RETURN (LockType, Guard, m_OutBufferLock, -1);
if (closing_)
return -1;
// Dump outgoing packet
if (sPacketLog->CanLogPacket())
sPacketLog->LogPacket(pct, SERVER_TO_CLIENT);
WorldPacket const* pkt = &pct;
// Empty buffer used in case packet should be compressed
/*WorldPacket buff;
if (m_Session && pkt->size() > 0x400)
{
buff.Compress(m_Session->GetCompressionStream(), pkt);
pkt = &buff;
}*/
//switch to make console stop spams opcodes
switch(pkt->GetOpcode())
{
case SMSG_MONSTER_MOVE:
case SMSG_UPDATE_OBJECT:
case SMSG_DESTROY_OBJECT:
case SMSG_TIME_SYNC_REQ:
case SMSG_PLAYER_MOVE:
case SMSG_POWER_UPDATE:
break;
default:
{
if (m_Session)
sLog->outDebug(LOG_FILTER_OPCODES, "S->C: %s %s", m_Session->GetPlayerInfo().c_str(), GetOpcodeNameForLogging(pkt->GetOpcode()).c_str());
else
sLog->outDebug(LOG_FILTER_OPCODES, "None m_Session S->C: %s", GetOpcodeNameForLogging(pkt->GetOpcode()).c_str());
break;
}
}
sScriptMgr->OnPacketSend(this, *pkt);
ServerPktHeader header(!m_Crypt.IsInitialized() ? pkt->size() + 2 : pct.size(), pkt->GetOpcode(), &m_Crypt);
if (m_OutBuffer->space() >= pkt->size() + header.getHeaderLength() && msg_queue()->is_empty())
{
// Put the packet on the buffer.
if (m_OutBuffer->copy((char*) header.header, header.getHeaderLength()) == -1)
ACE_ASSERT (false);
if (!pkt->empty())
if (m_OutBuffer->copy((char*) pkt->contents(), pkt->size()) == -1)
ACE_ASSERT (false);
}
else
{
// Enqueue the packet.
ACE_Message_Block* mb;
ACE_NEW_RETURN(mb, ACE_Message_Block(pkt->size() + header.getHeaderLength()), -1);
mb->copy((char*) header.header, header.getHeaderLength());
if (!pkt->empty())
mb->copy((const char*)pkt->contents(), pkt->size());
if (msg_queue()->enqueue_tail(mb, (ACE_Time_Value*)&ACE_Time_Value::zero) == -1)
{
//TC_LOG_ERROR(LOG_FILTER_NETWORKIO, "WorldSocket::SendPacket enqueue_tail failed");
mb->release();
return -1;
}
}
return 0;
}
int WorldSocket::SendPacket(WorldPacket const& pct)
{
ACE_GUARD_RETURN (LockType, Guard, m_OutBufferLock, -1);
if (closing_)
return -1;
// Dump outgoing packet
if (sPacketLog->CanLogPacket())
sPacketLog->LogPacket(pct, SERVER_TO_CLIENT);
WorldPacket const* pkt = &pct;
// TODO : Find the compress flag
// Empty buffer used in case packet should be compressed
/*WorldPacket buff;
if (m_Session && pkt->size() > 0x400)
{
buff.Compress(m_Session->GetCompressionStream(), pkt);
pkt = &buff;
}*/
uint16 opcodeNumber = serverOpcodeTable[pkt->GetOpcode()]->OpcodeNumber;
if (m_Session)
switch(pkt->GetOpcode())
{
case SMSG_POWER_UPDATE:
case SMSG_ATTACKER_STATE_UPDATE:
case SMSG_MONSTER_MOVE:
case SMSG_UPDATE_OBJECT:
case SMSG_DESTROY_OBJECT:
case SMSG_PLAYER_MOVE:
break;
default:
{
sLog->outError(LOG_FILTER_GENERAL, "S->C: %s", GetOpcodeNameForLogging(pkt->GetOpcode(), true).c_str());
}
}
sScriptMgr->OnPacketSend(this, *pkt);
ServerPktHeader header(!m_Crypt.IsInitialized() ? pkt->size() + 2 : pct.size(), opcodeNumber, &m_Crypt);
if (m_OutBuffer->space() >= pkt->size() + header.getHeaderLength() && msg_queue()->is_empty())
{
// Put the packet on the buffer.
if (m_OutBuffer->copy((char*) header.header, header.getHeaderLength()) == -1)
ACE_ASSERT (false);
if (!pkt->empty())
if (m_OutBuffer->copy((char*) pkt->contents(), pkt->size()) == -1)
ACE_ASSERT (false);
}
else
{
// Enqueue the packet.
ACE_Message_Block* mb;
ACE_NEW_RETURN(mb, ACE_Message_Block(pkt->size() + header.getHeaderLength()), -1);
mb->copy((char*) header.header, header.getHeaderLength());
if (!pkt->empty())
mb->copy((const char*)pkt->contents(), pkt->size());
if (msg_queue()->enqueue_tail(mb, (ACE_Time_Value*)&ACE_Time_Value::zero) == -1)
{
sLog->outError(LOG_FILTER_NETWORKIO, "WorldSocket::SendPacket enqueue_tail failed");
mb->release();
return -1;
}
}
return 0;
}
//! Compresses packet in place
void WorldPacket::Compress(z_stream* compressionStream)
{
Opcodes uncompressedOpcode = GetOpcode();
if (uncompressedOpcode & COMPRESSED_OPCODE_MASK)
{
sLog->outError(LOG_FILTER_NETWORKIO, "Packet with opcode 0x%04X is already compressed!", uncompressedOpcode);
return;
}
Opcodes opcode = Opcodes(uncompressedOpcode | COMPRESSED_OPCODE_MASK);
uint32 size = wpos();
uint32 destsize = compressBound(size);
std::vector<uint8> storage(destsize);
_compressionStream = compressionStream;
Compress(static_cast<void*>(&storage[0]), &destsize, static_cast<const void*>(contents()), size);
if (destsize == 0)
return;
clear();
reserve(destsize + sizeof(uint32));
*this << uint32(size);
append(&storage[0], destsize);
SetOpcode(opcode);
sLog->outInfo(LOG_FILTER_NETWORKIO, "%s (len %u) successfully compressed to %04X (len %u)", GetOpcodeNameForLogging(uncompressedOpcode, true).c_str(), size, opcode, destsize);
}
void WorldSession::Handle_Deprecated(WorldPacket& recvPacket)
{
sLog->outError(LOG_FILTER_OPCODES, "Received deprecated opcode %s from %s"
, GetOpcodeNameForLogging(recvPacket.GetOpcode()).c_str(), GetPlayerName(false).c_str());
}
void WorldSession::Handle_EarlyProccess(WorldPacket& recvPacket)
{
sLog->outError(LOG_FILTER_OPCODES, "Received opcode %s that must be processed in WorldSocket::OnRead from %s"
, GetOpcodeNameForLogging(recvPacket.GetOpcode()).c_str(), GetPlayerInfo().c_str());
}
void WorldSession::Handle_ServerSide(WorldPacket& recvPacket)
{
sLog->outError(LOG_FILTER_OPCODES, "Received server-side opcode %s from %s"
, GetOpcodeNameForLogging(recvPacket.GetOpcode()).c_str(), GetPlayerInfo().c_str());
}
/// Logging helper for unexpected opcodes
void WorldSession::LogUnexpectedOpcode(WorldPacket* packet, const char* status, const char *reason)
{
sLog->outError(LOG_FILTER_OPCODES, "Received unexpected opcode %s Status: %s Reason: %s from %s",
GetOpcodeNameForLogging(packet->GetOpcode()).c_str(), status, reason, GetPlayerInfo().c_str());
}
int WorldSocket::SendPacket(WorldPacket const& pct)
{
ACE_GUARD_RETURN (LockType, Guard, m_OutBufferLock, -1);
if (closing_)
return -1;
// Dump outgoing packet
if (sPacketLog->CanLogPacket())
sPacketLog->LogPacket(pct, SERVER_TO_CLIENT);
WorldPacket const* pkt = &pct;
// Empty buffer used in case packet should be compressed
// Disable compression for now :)
/* WorldPacket buff;
if (m_Session && pkt->size() > 0x400)
{
buff.Compress(m_Session->GetCompressionStream(), pkt);
pkt = &buff;
}*/
if (m_Session)
TC_LOG_TRACE("network.opcode", "S->C: %s %s", m_Session->GetPlayerInfo().c_str(), GetOpcodeNameForLogging(pkt->GetOpcode()).c_str());
sScriptMgr->OnPacketSend(this, *pkt);
ServerPktHeader header(!m_Crypt.IsInitialized() ? pkt->size() + 2 : pct.size(), pkt->GetOpcode(), &m_Crypt);
if (m_OutBuffer->space() >= pkt->size() + header.getHeaderLength() && msg_queue()->is_empty())
{
// Put the packet on the buffer.
if (m_OutBuffer->copy((char*) header.header, header.getHeaderLength()) == -1)
ACE_ASSERT (false);
if (!pkt->empty())
if (m_OutBuffer->copy((char*) pkt->contents(), pkt->size()) == -1)
ACE_ASSERT (false);
}
else
{
// Enqueue the packet.
ACE_Message_Block* mb;
ACE_NEW_RETURN(mb, ACE_Message_Block(pkt->size() + header.getHeaderLength()), -1);
mb->copy((char*) header.header, header.getHeaderLength());
if (!pkt->empty())
mb->copy((const char*)pkt->contents(), pkt->size());
if (msg_queue()->enqueue_tail(mb, (ACE_Time_Value*)&ACE_Time_Value::zero) == -1)
{
TC_LOG_ERROR("network", "WorldSocket::SendPacket enqueue_tail failed");
mb->release();
return -1;
}
}
return 0;
}
void WorldSession::Handle_ServerSide(WorldPacket& recvPacket)
{
TC_LOG_ERROR("network.opcode", "Received server-side opcode %s from %s"
, GetOpcodeNameForLogging(recvPacket.GetOpcode()).c_str(), GetPlayerInfo().c_str());
}
void WorldSession::Handle_Deprecated(WorldPacket& recvPacket)
{
TC_LOG_ERROR("network.opcode", "Received deprecated opcode %s from %s"
, GetOpcodeNameForLogging(recvPacket.GetOpcode(), false).c_str(), GetPlayerInfo().c_str());
}
//! Compresses another packet and stores it in self (source left intact)
void WorldPacket::Compress(z_stream* compressionStream, WorldPacket const* source)
{
ASSERT(source != this);
Opcodes uncompressedOpcode = source->GetOpcode();
if (uncompressedOpcode & COMPRESSED_OPCODE_MASK)
{
sLog->outError(LOG_FILTER_NETWORKIO, "Packet with opcode 0x%04X is already compressed!", uncompressedOpcode);
return;
}
Opcodes opcode = Opcodes(uncompressedOpcode | COMPRESSED_OPCODE_MASK);
uint32 size = source->size();
uint32 destsize = compressBound(size);
size_t sizePos = 0;
resize(destsize + sizeof(uint32));
_compressionStream = compressionStream;
Compress(static_cast<void*>(&_storage[0] + sizeof(uint32)), &destsize, static_cast<const void*>(source->contents()), size);
if (destsize == 0)
return;
put<uint32>(sizePos, size);
resize(destsize + sizeof(uint32));
SetOpcode(opcode);
sLog->outInfo(LOG_FILTER_NETWORKIO, "%s (len %u) successfully compressed to %04X (len %u)", GetOpcodeNameForLogging(uncompressedOpcode, true).c_str(), size, opcode, destsize);
}
/// Send a packet to the client
void WorldSession::SendPacket(WorldPacket const* packet, bool forced /*= false*/)
{
if (!m_Socket)
return;
if (packet->GetOpcode() == NULL_OPCODE)
{
sLog->outError(LOG_FILTER_OPCODES, "Prevented sending of NULL_OPCODE to %s", GetPlayerName(false).c_str());
return;
}
else if (packet->GetOpcode() == UNKNOWN_OPCODE)
{
sLog->outError(LOG_FILTER_OPCODES, "Prevented sending of UNKNOWN_OPCODE to %s", GetPlayerName(false).c_str());
return;
}
if (!forced)
{
OpcodeHandler* handler = opcodeTable[packet->GetOpcode()];
if (!handler || handler->status == STATUS_UNHANDLED)
{
sLog->outError(LOG_FILTER_OPCODES, "Prevented sending disabled opcode %s to %s", GetOpcodeNameForLogging(packet->GetOpcode()).c_str(), GetPlayerName(false).c_str());
return;
}
}
#ifdef TRINITY_DEBUG
// Code for network use statistic
static uint64 sendPacketCount = 0;
static uint64 sendPacketBytes = 0;
static time_t firstTime = time(NULL);
static time_t lastTime = firstTime; // next 60 secs start time
static uint64 sendLastPacketCount = 0;
static uint64 sendLastPacketBytes = 0;
time_t cur_time = time(NULL);
if ((cur_time - lastTime) < 60)
{
sendPacketCount+=1;
sendPacketBytes+=packet->size();
sendLastPacketCount+=1;
sendLastPacketBytes+=packet->size();
}
else
{
uint64 minTime = uint64(cur_time - lastTime);
uint64 fullTime = uint64(lastTime - firstTime);
sLog->outInfo(LOG_FILTER_GENERAL, "Send all time packets count: " UI64FMTD " bytes: " UI64FMTD " avr.count/sec: %f avr.bytes/sec: %f time: %u", sendPacketCount, sendPacketBytes, float(sendPacketCount)/fullTime, float(sendPacketBytes)/fullTime, uint32(fullTime));
sLog->outInfo(LOG_FILTER_GENERAL, "Send last min packets count: " UI64FMTD " bytes: " UI64FMTD " avr.count/sec: %f avr.bytes/sec: %f", sendLastPacketCount, sendLastPacketBytes, float(sendLastPacketCount)/minTime, float(sendLastPacketBytes)/minTime);
lastTime = cur_time;
sendLastPacketCount = 1;
sendLastPacketBytes = packet->wpos(); // wpos is real written size
}
#endif // !TRINITY_DEBUG
if (m_Socket->SendPacket(*packet) == -1)
m_Socket->CloseSocket();
}
/// Logging helper for unexpected opcodes
void WorldSession::LogUnprocessedTail(WorldPacket* packet)
{
sLog->outError(LOG_FILTER_OPCODES, "Unprocessed tail data (read stop at %u from %u) Opcode %s from %s",
uint32(packet->rpos()), uint32(packet->wpos()), GetOpcodeNameForLogging(packet->GetOpcode()).c_str(), GetPlayerName(false).c_str());
packet->print_storage();
}