feat(Core/Logging): rework logging (#4692)

* feat(Core/Logging): rework logging

* correct level for sql.sql

* del unused config options

* Correct build

* correct after merge

* whitespace

20:29:37 1. 'Player.cpp'. Replace (1)
20:29:37 2. 'ObjectMgr.cpp'. Replace (3)

* 1

* correct logging

* correct affter merge

* 1

* 2

* LOG_LEVEL_WARN

* #include "AppenderDB.h"

* 3

* 4

* 5

* 1. 'WorldSocket.cpp'. Replace (1)

* 6

* 1
This commit is contained in:
Kargatum
2021-04-17 16:20:07 +07:00
committed by GitHub
parent b2861be1cd
commit 4af4cbd3d9
246 changed files with 7413 additions and 6807 deletions

View File

@@ -223,9 +223,9 @@ void WorldSession::SendPacket(WorldPacket const* packet)
uint64 minTime = uint64(cur_time - lastTime);
uint64 fullTime = uint64(lastTime - firstTime);
sLog->outDetail("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 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->outDetail("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("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);
lastTime = cur_time;
sendLastPacketCount = 1;
@@ -277,7 +277,7 @@ bool WorldSession::Update(uint32 diff, PacketFilter& updater)
{
if (packet->GetOpcode() >= NUM_MSG_TYPES)
{
sLog->outError("WorldSession Packet filter: received non-existent opcode %s (0x%.4X)", LookupOpcodeName(packet->GetOpcode()), packet->GetOpcode());
LOG_ERROR("server", "WorldSession Packet filter: received non-existent opcode %s (0x%.4X)", LookupOpcodeName(packet->GetOpcode()), packet->GetOpcode());
}
else
{
@@ -359,10 +359,10 @@ bool WorldSession::Update(uint32 diff, PacketFilter& updater)
}
catch (ByteBufferException const&)
{
sLog->outError("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->IsOutDebug())
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());
if (sLog->ShouldLog("network", LogLevel::LOG_LEVEL_DEBUG))
{
sLog->outDebug(LOG_FILTER_NETWORKIO, "Dumping error causing packet:");
LOG_DEBUG("network", "Dumping error causing packet:");
packet->hexlike();
}
}
@@ -594,7 +594,7 @@ void WorldSession::LogoutPlayer(bool save)
//! Call script hook before deletion
sScriptMgr->OnPlayerLogout(_player);
sLog->outChar("Account: %d (IP: %s) Logout Character:[%s] (GUID: %u) Level: %d", GetAccountId(), GetRemoteAddress().c_str(), _player->GetName().c_str(), _player->GetGUIDLow(), _player->getLevel());
LOG_INFO("entities.player", "Account: %d (IP: %s) Logout Character:[%s] (GUID: %u) Level: %d", GetAccountId(), GetRemoteAddress().c_str(), _player->GetName().c_str(), _player->GetGUIDLow(), _player->getLevel());
//! Remove the player from the world
// the player may not be in the world when logging out
@@ -614,7 +614,7 @@ void WorldSession::LogoutPlayer(bool save)
WorldPacket data(SMSG_LOGOUT_COMPLETE, 0);
SendPacket(&data);
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
sLog->outDebug(LOG_FILTER_NETWORKIO, "SESSION: Sent SMSG_LOGOUT_COMPLETE Message");
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
@@ -680,22 +680,22 @@ char const* WorldSession::GetAcoreString(uint32 entry) const
void WorldSession::Handle_NULL(WorldPacket& recvPacket)
{
sLog->outError("SESSION: received unhandled opcode %s (0x%.4X)", LookupOpcodeName(recvPacket.GetOpcode()), recvPacket.GetOpcode());
LOG_ERROR("server", "SESSION: received unhandled opcode %s (0x%.4X)", LookupOpcodeName(recvPacket.GetOpcode()), recvPacket.GetOpcode());
}
void WorldSession::Handle_EarlyProccess(WorldPacket& recvPacket)
{
sLog->outError("SESSION: received opcode %s (0x%.4X) that must be processed in WorldSocket::OnRead", LookupOpcodeName(recvPacket.GetOpcode()), recvPacket.GetOpcode());
LOG_ERROR("server", "SESSION: received opcode %s (0x%.4X) that must be processed in WorldSocket::OnRead", LookupOpcodeName(recvPacket.GetOpcode()), recvPacket.GetOpcode());
}
void WorldSession::Handle_ServerSide(WorldPacket& recvPacket)
{
sLog->outError("SESSION: received server-side opcode %s (0x%.4X)", LookupOpcodeName(recvPacket.GetOpcode()), recvPacket.GetOpcode());
LOG_ERROR("server", "SESSION: received server-side opcode %s (0x%.4X)", LookupOpcodeName(recvPacket.GetOpcode()), recvPacket.GetOpcode());
}
void WorldSession::Handle_Deprecated(WorldPacket& recvPacket)
{
sLog->outError("SESSION: received deprecated opcode %s (0x%.4X)", LookupOpcodeName(recvPacket.GetOpcode()), recvPacket.GetOpcode());
LOG_ERROR("server", "SESSION: received deprecated opcode %s (0x%.4X)", LookupOpcodeName(recvPacket.GetOpcode()), recvPacket.GetOpcode());
}
void WorldSession::SendAuthWaitQue(uint32 position)
@@ -738,13 +738,13 @@ void WorldSession::LoadAccountData(PreparedQueryResult result, uint32 mask)
uint32 type = fields[0].GetUInt8();
if (type >= NUM_ACCOUNT_DATA_TYPES)
{
sLog->outError("Table `%s` have invalid account data type (%u), ignore.", mask == GLOBAL_CACHE_MASK ? "account_data" : "character_account_data", type);
LOG_ERROR("server", "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)
{
sLog->outError("Table `%s` have non appropriate for table account data type (%u), ignore.", mask == GLOBAL_CACHE_MASK ? "account_data" : "character_account_data", type);
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);
continue;
}
@@ -877,7 +877,7 @@ void WorldSession::ReadMovementInfo(WorldPacket& data, MovementInfo* mi)
{ \
if (check) \
{ \
sLog->outDebug(LOG_FILTER_UNITS, "WorldSession::ReadMovementInfo: Violation of MovementFlags found (%s). " \
LOG_DEBUG("entities.unit", "WorldSession::ReadMovementInfo: Violation of MovementFlags found (%s). " \
"MovementFlags: %u, MovementFlags2: %u for player GUID: %u. Mask %u will be removed.", \
STRINGIZE(check), mi->GetMovementFlags(), mi->GetExtraMovementFlags(), GetPlayer()->GetGUIDLow(), maskToRemove); \
mi->RemoveMovementFlag((maskToRemove)); \
@@ -1000,7 +1000,7 @@ void WorldSession::ReadAddonsInfo(WorldPacket& data)
if (size > 0xFFFFF)
{
sLog->outError("WorldSession::ReadAddonsInfo addon info too big, size %u", size);
LOG_ERROR("server", "WorldSession::ReadAddonsInfo addon info too big, size %u", size);
return;
}
@@ -1031,7 +1031,7 @@ void WorldSession::ReadAddonsInfo(WorldPacket& data)
addonInfo >> enabled >> crc >> unk1;
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
sLog->outDetail("ADDON: Name: %s, Enabled: 0x%x, CRC: 0x%x, Unknown2: 0x%x", addonName.c_str(), enabled, crc, unk1);
LOG_DEBUG("server", "ADDON: Name: %s, Enabled: 0x%x, CRC: 0x%x, Unknown2: 0x%x", addonName.c_str(), enabled, crc, unk1);
#endif
AddonInfo addon(addonName, enabled, crc, 2, true);
@@ -1046,9 +1046,9 @@ void WorldSession::ReadAddonsInfo(WorldPacket& data)
match = false;
if (!match)
sLog->outDetail("ADDON: %s was known, but didn't match known CRC (0x%x)!", addon.Name.c_str(), savedAddon->CRC);
LOG_DEBUG("server", "ADDON: %s was known, but didn't match known CRC (0x%x)!", addon.Name.c_str(), savedAddon->CRC);
else
sLog->outDetail("ADDON: %s was known, CRC is correct (0x%x)", addon.Name.c_str(), savedAddon->CRC);
LOG_DEBUG("server", "ADDON: %s was known, CRC is correct (0x%x)", addon.Name.c_str(), savedAddon->CRC);
#endif
}
else
@@ -1056,7 +1056,7 @@ void WorldSession::ReadAddonsInfo(WorldPacket& data)
AddonMgr::SaveAddon(addon);
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
sLog->outDetail("ADDON: %s (0x%x) was not known, saving...", addon.Name.c_str(), addon.CRC);
LOG_DEBUG("server", "ADDON: %s (0x%x) was not known, saving...", addon.Name.c_str(), addon.CRC);
#endif
}
@@ -1067,16 +1067,16 @@ void WorldSession::ReadAddonsInfo(WorldPacket& data)
uint32 currentTime;
addonInfo >> currentTime;
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
sLog->outDebug(LOG_FILTER_NETWORKIO, "ADDON: CurrentTime: %u", currentTime);
LOG_DEBUG("network", "ADDON: CurrentTime: %u", currentTime);
#endif
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
if (addonInfo.rpos() != addonInfo.size())
sLog->outDebug(LOG_FILTER_NETWORKIO, "packet under-read!");
LOG_DEBUG("network", "packet under-read!");
#endif
}
else
sLog->outError("Addon packet uncompress error!");
LOG_ERROR("server", "Addon packet uncompress error!");
}
void WorldSession::SendAddonsInfo()
@@ -1116,7 +1116,7 @@ void WorldSession::SendAddonsInfo()
if (usepk) // if CRC is wrong, add public key (client need it)
{
#if defined(ENABLE_EXTRAS) && defined(ENABLE_EXTRA_LOGS)
sLog->outDetail("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);
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
data.append(addonPublicKey, sizeof(addonPublicKey));
}
@@ -1364,7 +1364,7 @@ bool WorldSession::DosProtection::EvaluateOpcode(WorldPacket& p, time_t time) co
if (++packetCounter.amountCounter <= maxPacketCounterAllowed)
return true;
sLog->outString("AntiDOS: Account %u, IP: %s, Ping: %u, Character %s, flooding packet (opc: %s (0x%X), count: %u)",
LOG_INFO("server", "AntiDOS: Account %u, IP: %s, Ping: %u, Character %s, flooding packet (opc: %s (0x%X), count: %u)",
Session->GetAccountId(), Session->GetRemoteAddress().c_str(), Session->GetLatency(),
Session->GetPlayerName().c_str(), opcodeTable[p.GetOpcode()].name, p.GetOpcode(), packetCounter.amountCounter);
@@ -1374,7 +1374,7 @@ bool WorldSession::DosProtection::EvaluateOpcode(WorldPacket& p, time_t time) co
return true;
case POLICY_KICK:
{
sLog->outString("AntiDOS: Player %s kicked!", Session->GetPlayerName().c_str());
LOG_INFO("server", "AntiDOS: Player %s kicked!", Session->GetPlayerName().c_str());
Session->KickPlayer();
return false;
}
@@ -1395,7 +1395,7 @@ bool WorldSession::DosProtection::EvaluateOpcode(WorldPacket& p, time_t time) co
break;
}
sLog->outString("AntiDOS: Player automatically banned for %u seconds.", duration);
LOG_INFO("server", "AntiDOS: Player automatically banned for %u seconds.", duration);
return false;
}
default: // invalid policy