chore(Core/Logging): replace most server loggers (#5726)

* chore(Core/Logging): replace most server loggers

Co-authored-by: Kitzunu <24550914+Kitzunu@users.noreply.github.com>
This commit is contained in:
Kargatum
2021-06-21 08:07:12 +07:00
committed by GitHub
parent 9f80a592bb
commit 5787d00d54
199 changed files with 2312 additions and 4487 deletions

View File

@@ -214,7 +214,7 @@ void WorldSession::SendPacket(WorldPacket const* packet)
if (!m_Socket)
return;
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS) && defined(ACORE_DEBUG)
#if defined(ACORE_DEBUG)
// Code for network use statistic
static uint64 sendPacketCount = 0;
static uint64 sendPacketBytes = 0;
@@ -240,9 +240,9 @@ void WorldSession::SendPacket(WorldPacket const* packet)
uint64 minTime = uint64(cur_time - lastTime);
uint64 fullTime = uint64(lastTime - firstTime);
LOG_DEBUG("server", "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));
LOG_DEBUG("network", "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));
LOG_DEBUG("server", "Send last min packets count: " UI64FMTD " bytes: " UI64FMTD " avr.count/sec: %f avr.bytes/sec: %f", sendLastPacketCount, sendLastPacketBytes, float(sendLastPacketCount) / minTime, float(sendLastPacketBytes) / minTime);
LOG_DEBUG("network", "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;
@@ -393,7 +393,7 @@ bool WorldSession::Update(uint32 diff, PacketFilter& updater)
}
catch (ByteBufferException const&)
{
LOG_ERROR("server", "WorldSession::Update ByteBufferException occured while parsing a packet (opcode: %u) from client %s, accountid=%i. Skipped packet.", packet->GetOpcode(), GetRemoteAddress().c_str(), GetAccountId());
LOG_ERROR("network", "WorldSession::Update ByteBufferException occured while parsing a packet (opcode: %u) from client %s, accountid=%i. Skipped packet.", packet->GetOpcode(), GetRemoteAddress().c_str(), GetAccountId());
if (sLog->ShouldLog("network", LogLevel::LOG_LEVEL_DEBUG))
{
LOG_DEBUG("network", "Dumping error causing packet:");
@@ -665,9 +665,7 @@ void WorldSession::LogoutPlayer(bool save)
//! Client will respond by sending 3x CMSG_CANCEL_TRADE, which we currently dont handle
WorldPacket data(SMSG_LOGOUT_COMPLETE, 0);
SendPacket(&data);
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
LOG_DEBUG("network", "SESSION: Sent SMSG_LOGOUT_COMPLETE Message");
#endif
//! Since each account can only have one online character at any given time, ensure all characters for active account are marked as offline
PreparedStatement* stmt = CharacterDatabase.GetPreparedStatement(CHAR_UPD_ACCOUNT_ONLINE);
@@ -794,13 +792,13 @@ void WorldSession::LoadAccountData(PreparedQueryResult result, uint32 mask)
uint32 type = fields[0].GetUInt8();
if (type >= NUM_ACCOUNT_DATA_TYPES)
{
LOG_ERROR("server", "Table `%s` have invalid account data type (%u), ignore.", mask == GLOBAL_CACHE_MASK ? "account_data" : "character_account_data", type);
LOG_ERROR("network", "Table `%s` have invalid account data type (%u), ignore.", mask == GLOBAL_CACHE_MASK ? "account_data" : "character_account_data", type);
continue;
}
if ((mask & (1 << type)) == 0)
{
LOG_ERROR("server", "Table `%s` have non appropriate for table account data type (%u), ignore.", mask == GLOBAL_CACHE_MASK ? "account_data" : "character_account_data", type);
LOG_ERROR("network", "Table `%s` have non appropriate for table account data type (%u), ignore.", mask == GLOBAL_CACHE_MASK ? "account_data" : "character_account_data", type);
continue;
}
@@ -1056,7 +1054,7 @@ void WorldSession::ReadAddonsInfo(WorldPacket& data)
if (size > 0xFFFFF)
{
LOG_ERROR("server", "WorldSession::ReadAddonsInfo addon info too big, size %u", size);
LOG_ERROR("network", "WorldSession::ReadAddonsInfo addon info too big, size %u", size);
return;
}
@@ -1086,34 +1084,28 @@ void WorldSession::ReadAddonsInfo(WorldPacket& data)
addonInfo >> enabled >> crc >> unk1;
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
LOG_DEBUG("server", "ADDON: Name: %s, Enabled: 0x%x, CRC: 0x%x, Unknown2: 0x%x", addonName.c_str(), enabled, crc, unk1);
#endif
LOG_DEBUG("network", "ADDON: Name: %s, Enabled: 0x%x, CRC: 0x%x, Unknown2: 0x%x", addonName.c_str(), enabled, crc, unk1);
AddonInfo addon(addonName, enabled, crc, 2, true);
SavedAddon const* savedAddon = AddonMgr::GetAddonInfo(addonName);
if (savedAddon)
{
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
bool match = true;
if (addon.CRC != savedAddon->CRC)
match = false;
if (!match)
LOG_DEBUG("server", "ADDON: %s was known, but didn't match known CRC (0x%x)!", addon.Name.c_str(), savedAddon->CRC);
LOG_DEBUG("network", "ADDON: %s was known, but didn't match known CRC (0x%x)!", addon.Name.c_str(), savedAddon->CRC);
else
LOG_DEBUG("server", "ADDON: %s was known, CRC is correct (0x%x)", addon.Name.c_str(), savedAddon->CRC);
#endif
LOG_DEBUG("network", "ADDON: %s was known, CRC is correct (0x%x)", addon.Name.c_str(), savedAddon->CRC);
}
else
{
AddonMgr::SaveAddon(addon);
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
LOG_DEBUG("server", "ADDON: %s (0x%x) was not known, saving...", addon.Name.c_str(), addon.CRC);
#endif
LOG_DEBUG("network", "ADDON: %s (0x%x) was not known, saving...", addon.Name.c_str(), addon.CRC);
}
// TODO: Find out when to not use CRC/pubkey, and other possible states.
@@ -1122,17 +1114,13 @@ void WorldSession::ReadAddonsInfo(WorldPacket& data)
uint32 currentTime;
addonInfo >> currentTime;
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
LOG_DEBUG("network", "ADDON: CurrentTime: %u", currentTime);
#endif
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
if (addonInfo.rpos() != addonInfo.size())
LOG_DEBUG("network", "packet under-read!");
#endif
}
else
LOG_ERROR("server", "Addon packet uncompress error!");
LOG_ERROR("network", "Addon packet uncompress error!");
}
void WorldSession::SendAddonsInfo()
@@ -1171,9 +1159,7 @@ void WorldSession::SendAddonsInfo()
data << uint8(usepk);
if (usepk) // if CRC is wrong, add public key (client need it)
{
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
LOG_DEBUG("server", "ADDON: CRC (0x%x) for addon %s is wrong (does not match expected 0x%x), sending pubkey", itr->CRC, itr->Name.c_str(), STANDARD_ADDON_CRC);
#endif
LOG_DEBUG("network", "ADDON: CRC (0x%x) for addon %s is wrong (does not match expected 0x%x), sending pubkey", itr->CRC, itr->Name.c_str(), STANDARD_ADDON_CRC);
data.append(addonPublicKey, sizeof(addonPublicKey));
}

View File

@@ -240,7 +240,7 @@ int WorldSocket::SendPacket(WorldPacket const& pct)
if (msg_queue()->enqueue_tail(mb, (ACE_Time_Value*)&ACE_Time_Value::zero) == -1)
{
LOG_ERROR("server", "WorldSocket::SendPacket enqueue_tail failed");
LOG_ERROR("network", "WorldSocket::SendPacket enqueue_tail failed");
mb->release();
return -1;
}
@@ -283,7 +283,7 @@ int WorldSocket::open(void* a)
if (peer().get_remote_addr(remote_addr) == -1)
{
LOG_ERROR("server", "WorldSocket::open: peer().get_remote_addr errno = %s", ACE_OS::strerror (errno));
LOG_ERROR("network", "WorldSocket::open: peer().get_remote_addr errno = %s", ACE_OS::strerror (errno));
return -1;
}
@@ -301,7 +301,7 @@ int WorldSocket::open(void* a)
// Register with ACE Reactor
if (reactor()->register_handler(this, ACE_Event_Handler::READ_MASK | ACE_Event_Handler::WRITE_MASK) == -1)
{
LOG_ERROR("server", "WorldSocket::open: unable to register client handler errno = %s", ACE_OS::strerror (errno));
LOG_ERROR("network", "WorldSocket::open: unable to register client handler errno = %s", ACE_OS::strerror (errno));
return -1;
}
@@ -337,18 +337,14 @@ int WorldSocket::handle_input(ACE_HANDLE)
return Update(); // interesting line, isn't it ?
}
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
LOG_DEBUG("server", "WorldSocket::handle_input: Peer error closing connection errno = %s", ACE_OS::strerror (errno));
#endif
LOG_DEBUG("network", "WorldSocket::handle_input: Peer error closing connection errno = %s", ACE_OS::strerror (errno));
errno = ECONNRESET;
return -1;
}
case 0:
{
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
LOG_DEBUG("server", "WorldSocket::handle_input: Peer has closed connection");
#endif
LOG_DEBUG("network", "WorldSocket::handle_input: Peer has closed connection");
errno = ECONNRESET;
return -1;
@@ -417,7 +413,7 @@ int WorldSocket::handle_output_queue()
if (msg_queue()->dequeue_head(mblk, (ACE_Time_Value*)&ACE_Time_Value::zero) == -1)
{
LOG_ERROR("server", "WorldSocket::handle_output_queue dequeue_head");
LOG_ERROR("network", "WorldSocket::handle_output_queue dequeue_head");
return -1;
}
@@ -452,7 +448,7 @@ int WorldSocket::handle_output_queue()
if (msg_queue()->enqueue_head(mblk, (ACE_Time_Value*) &ACE_Time_Value::zero) == -1)
{
LOG_ERROR("server", "WorldSocket::handle_output_queue enqueue_head");
LOG_ERROR("network", "WorldSocket::handle_output_queue enqueue_head");
mblk->release();
return -1;
}
@@ -530,7 +526,7 @@ int WorldSocket::handle_input_header(void)
if ((header.size < 4) || (header.size > 10240) || (header.cmd > 10240))
{
LOG_ERROR("server", "WorldSocket::handle_input_header(): client (%s) sent malformed packet (size: %hd, cmd: %d)",
LOG_ERROR("network", "WorldSocket::handle_input_header(): client (%s) sent malformed packet (size: %hd, cmd: %d)",
GetRemoteAddress().c_str(), header.size, header.cmd);
errno = EINVAL;
@@ -633,7 +629,7 @@ int WorldSocket::handle_input_missing_data(void)
// hope this is not hack, as proper m_RecvWPct is asserted around
if (!m_RecvWPct)
{
LOG_ERROR("server", "Forcing close on input m_RecvWPct = nullptr");
LOG_ERROR("network", "Forcing close on input m_RecvWPct = nullptr");
errno = EINVAL;
return -1;
}
@@ -677,7 +673,7 @@ int WorldSocket::cancel_wakeup_output()
(this, ACE_Event_Handler::WRITE_MASK) == -1)
{
// would be good to store errno from reactor with errno guard
LOG_ERROR("server", "WorldSocket::cancel_wakeup_output");
LOG_ERROR("network", "WorldSocket::cancel_wakeup_output");
return -1;
}
@@ -694,7 +690,7 @@ int WorldSocket::schedule_wakeup_output()
if (reactor()->schedule_wakeup
(this, ACE_Event_Handler::WRITE_MASK) == -1)
{
LOG_ERROR("server", "WorldSocket::schedule_wakeup_output");
LOG_ERROR("network", "WorldSocket::schedule_wakeup_output");
return -1;
}
@@ -727,12 +723,12 @@ int WorldSocket::ProcessIncoming(WorldPacket* new_pct)
return HandlePing(*new_pct);
}
catch (ByteBufferPositionException const&) { }
LOG_ERROR("server", "WorldSocket::ReadDataHandler(): client sent malformed CMSG_PING");
LOG_ERROR("network", "WorldSocket::ReadDataHandler(): client sent malformed CMSG_PING");
return -1;
case CMSG_AUTH_SESSION:
if (m_Session)
{
LOG_ERROR("server", "WorldSocket::ProcessIncoming: Player send CMSG_AUTH_SESSION again");
LOG_ERROR("network", "WorldSocket::ProcessIncoming: Player send CMSG_AUTH_SESSION again");
return -1;
}
return HandleAuthSession (*new_pct);
@@ -749,7 +745,7 @@ int WorldSocket::ProcessIncoming(WorldPacket* new_pct)
}
catch (ByteBufferException const&)
{
LOG_ERROR("server", "WorldSocket::ProcessIncoming ByteBufferException occured while parsing an instant handled packet (opcode: %u) from client %s, accountid=%u. Disconnected client.",
LOG_ERROR("network", "WorldSocket::ProcessIncoming ByteBufferException occured while parsing an instant handled packet (opcode: %u) from client %s, accountid=%u. Disconnected client.",
aptr->GetOpcode(), GetRemoteAddress().c_str(), m_Session ? m_Session->GetAccountId() : 0);
if (sLog->ShouldLog("network", LogLevel::LOG_LEVEL_DEBUG))
@@ -785,7 +781,7 @@ int WorldSocket::ProcessIncoming(WorldPacket* new_pct)
return 0;
}
LOG_ERROR("server", "WorldSocket::ProcessIncoming: Client not authed opcode = %u", aptr->GetOpcode());
LOG_ERROR("network", "WorldSocket::ProcessIncoming: Client not authed opcode = %u", aptr->GetOpcode());
return -1;
}
@@ -806,7 +802,7 @@ int WorldSocket::HandleAuthSession(WorldPacket& recvPacket)
packet << uint8(AUTH_REJECT);
SendPacket(packet);
LOG_ERROR("server", "WorldSocket::HandleAuthSession: World closed, denying client (%s).", GetRemoteAddress().c_str());
LOG_ERROR("network", "WorldSocket::HandleAuthSession: World closed, denying client (%s).", GetRemoteAddress().c_str());
return -1;
}
@@ -822,10 +818,9 @@ int WorldSocket::HandleAuthSession(WorldPacket& recvPacket)
recvPacket >> DosResponse;
recvPacket.read(digest);
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
LOG_DEBUG("server", "WorldSocket::HandleAuthSession: client %u, loginServerID %u, accountName %s, loginServerType %u",
LOG_DEBUG("network", "WorldSocket::HandleAuthSession: client %u, loginServerID %u, accountName %s, loginServerType %u",
BuiltNumberClient, loginServerID, accountName.c_str(), loginServerType);
#endif
// Get the account information from the realmd database
// 0 1 2 3 4 5 6 7 8 9 10
// SELECT id, sessionkey, last_ip, locked, lock_country, expansion, mutetime, locale, recruiter, os, totaltime FROM account WHERE username = ?
@@ -844,7 +839,7 @@ int WorldSocket::HandleAuthSession(WorldPacket& recvPacket)
SendPacket(packet);
LOG_ERROR("server", "WorldSocket::HandleAuthSession: Sent Auth Response (unknown account).");
LOG_ERROR("network", "WorldSocket::HandleAuthSession: Sent Auth Response (unknown account).");
return -1;
}
@@ -870,7 +865,7 @@ int WorldSocket::HandleAuthSession(WorldPacket& recvPacket)
packet << uint8(AUTH_REJECT);
SendPacket(packet);
LOG_ERROR("server", "WorldSocket::HandleAuthSession: World closed, denying client (%s).", address.c_str());
LOG_ERROR("network", "WorldSocket::HandleAuthSession: World closed, denying client (%s).", address.c_str());
sScriptMgr->OnFailedAccountLogin(account.Id);
return -1;
}
@@ -914,10 +909,8 @@ int WorldSocket::HandleAuthSession(WorldPacket& recvPacket)
{
packet.Initialize(SMSG_AUTH_RESPONSE, 1);
packet << uint8(AUTH_FAILED);
SendPacket(packet);
LOG_ERROR("server", "WorldSocket::HandleAuthSession: Authentication failed for account: %u ('%s') address: %s", account.Id, accountName.c_str(), address.c_str());
LOG_ERROR("network", "WorldSocket::HandleAuthSession: Authentication failed for account: %u ('%s') address: %s", account.Id, accountName.c_str(), address.c_str());
return -1;
}
@@ -1042,7 +1035,7 @@ int WorldSocket::HandlePing(WorldPacket& recvPacket)
if (m_Session && AccountMgr::IsPlayerAccount(m_Session->GetSecurity()))
{
Player* _player = m_Session->GetPlayer();
LOG_ERROR("server", "WorldSocket::HandlePing: Player (account: %u, %s, name: %s) kicked for over-speed pings (address: %s)",
LOG_ERROR("network", "WorldSocket::HandlePing: Player (account: %u, %s, name: %s) kicked for over-speed pings (address: %s)",
m_Session->GetAccountId(),
_player ? _player->GetGUID().ToString().c_str() : "",
_player ? _player->GetName().c_str() : "<none>",
@@ -1066,7 +1059,7 @@ int WorldSocket::HandlePing(WorldPacket& recvPacket)
}
else
{
LOG_ERROR("server", "WorldSocket::HandlePing: peer sent CMSG_PING, "
LOG_ERROR("network", "WorldSocket::HandlePing: peer sent CMSG_PING, "
"but is not authenticated or got recently kicked, "
" address = %s",
GetRemoteAddress().c_str());

View File

@@ -30,7 +30,7 @@ public:
protected:
virtual int handle_timeout(const ACE_Time_Value& /*current_time*/, const void* /*act = 0*/)
{
LOG_INFO("server", "Resuming acceptor");
LOG_INFO("network", "Resuming acceptor");
reactor()->cancel_timer(this, 1);
return reactor()->register_handler(this, ACE_Event_Handler::ACCEPT_MASK);
}
@@ -40,7 +40,7 @@ protected:
#if defined(ENFILE) && defined(EMFILE)
if (errno == ENFILE || errno == EMFILE)
{
LOG_ERROR("server", "Out of file descriptors, suspending incoming connections for 10 seconds");
LOG_ERROR("network", "Out of file descriptors, suspending incoming connections for 10 seconds");
reactor()->remove_handler(this, ACE_Event_Handler::ACCEPT_MASK | ACE_Event_Handler::DONT_CALL);
reactor()->schedule_timer(this, nullptr, ACE_Time_Value(10));
}

View File

@@ -135,9 +135,7 @@ protected:
int svc() override
{
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
LOG_DEBUG("server", "Network Thread Starting");
#endif
LOG_DEBUG("network", "Network Thread Starting");
ASSERT(m_Reactor);
@@ -174,9 +172,7 @@ protected:
}
}
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
LOG_DEBUG("server", "Network Thread exits");
#endif
LOG_DEBUG("network", "Network Thread exits");
return 0;
}
@@ -226,7 +222,7 @@ WorldSocketMgr::StartReactiveIO (uint16 port, const char* address)
if (num_threads <= 0)
{
LOG_ERROR("server", "Network.Threads is wrong in your config file");
LOG_ERROR("network", "Network.Threads is wrong in your config file");
return -1;
}
@@ -234,7 +230,7 @@ WorldSocketMgr::StartReactiveIO (uint16 port, const char* address)
m_NetThreads = new ReactorRunnable[m_NetThreadsCount];
LOG_INFO("server", "Max allowed socket connections %d", ACE::max_handles());
LOG_INFO("network", "Max allowed socket connections %d", ACE::max_handles());
// -1 means use default
m_SockOutKBuff = sConfigMgr->GetOption<int32> ("Network.OutKBuff", -1);
@@ -243,7 +239,7 @@ WorldSocketMgr::StartReactiveIO (uint16 port, const char* address)
if (m_SockOutUBuff <= 0)
{
LOG_ERROR("server", "Network.OutUBuff is wrong in your config file");
LOG_ERROR("network", "Network.OutUBuff is wrong in your config file");
return -1;
}
@@ -253,7 +249,7 @@ WorldSocketMgr::StartReactiveIO (uint16 port, const char* address)
if (m_Acceptor->open(listen_addr, m_NetThreads[0].GetReactor(), ACE_NONBLOCK) == -1)
{
LOG_ERROR("server", "Failed to open acceptor, check if the port is free");
LOG_ERROR("network", "Failed to open acceptor, check if the port is free");
return -1;
}
@@ -317,7 +313,7 @@ WorldSocketMgr::OnSocketOpen (WorldSocket* sock)
(void*) & m_SockOutKBuff,
sizeof (int)) == -1 && errno != ENOTSUP)
{
LOG_ERROR("server", "WorldSocketMgr::OnSocketOpen set_option SO_SNDBUF");
LOG_ERROR("network", "WorldSocketMgr::OnSocketOpen set_option SO_SNDBUF");
return -1;
}
}
@@ -332,7 +328,7 @@ WorldSocketMgr::OnSocketOpen (WorldSocket* sock)
(void*)&ndoption,
sizeof (int)) == -1)
{
LOG_ERROR("server", "WorldSocketMgr::OnSocketOpen: peer().set_option TCP_NODELAY errno = %s", ACE_OS::strerror (errno));
LOG_ERROR("network", "WorldSocketMgr::OnSocketOpen: peer().set_option TCP_NODELAY errno = %s", ACE_OS::strerror (errno));
return -1;
}
}