More logging updates

This commit is contained in:
Akkadius 2019-07-03 18:49:53 -05:00
parent 11bc21f99f
commit 9613d128ae
8 changed files with 134 additions and 71 deletions

View File

@ -19,6 +19,7 @@
*/
#include "eqemu_logsys.h"
#include "rulesys.h"
#include "platform.h"
#include "string_util.h"
#include "database.h"
@ -96,16 +97,12 @@ EQEmuLogSys::EQEmuLogSys()
{
on_log_gmsay_hook = [](uint16 log_type, const std::string &) {};
on_log_console_hook = [](uint16 debug_level, uint16 log_type, const std::string &) {};
bool file_logs_enabled = false;
int log_platform = 0;
}
/**
* EQEmuLogSys Deconstructor
*/
EQEmuLogSys::~EQEmuLogSys()
{
}
EQEmuLogSys::~EQEmuLogSys() = default;
void EQEmuLogSys::LoadLogSettingsDefaults()
{
@ -113,7 +110,7 @@ void EQEmuLogSys::LoadLogSettingsDefaults()
* Get Executable platform currently running this code (Zone/World/etc)
*/
log_platform = GetExecutablePlatformInt();
for (int log_category_id = Logs::AA; log_category_id != Logs::MaxCategoryID; log_category_id++) {
log_settings[log_category_id].log_to_console = 0;
log_settings[log_category_id].log_to_file = 0;
@ -351,6 +348,25 @@ void EQEmuLogSys::ProcessConsoleMessage(uint16 debug_level, uint16 log_category,
on_log_console_hook(debug_level, log_category, message);
}
constexpr const char *str_end(const char *str)
{
return *str ? str_end(str + 1) : str;
}
constexpr bool str_slant(const char *str)
{
return *str == '/' ? true : (*str ? str_slant(str + 1) : false);
}
constexpr const char *r_slant(const char *str)
{
return *str == '/' ? (str + 1) : r_slant(str - 1);
}
constexpr const char *file_name(const char *str)
{
return str_slant(str) ? r_slant(str_end(str)) : str;
}
/**
* Core logging function
*
@ -359,7 +375,15 @@ void EQEmuLogSys::ProcessConsoleMessage(uint16 debug_level, uint16 log_category,
* @param message
* @param ...
*/
void EQEmuLogSys::Out(Logs::DebugLevel debug_level, uint16 log_category, std::string message, ...)
void EQEmuLogSys::Out(
Logs::DebugLevel debug_level,
uint16 log_category,
const char *file,
const char *func,
int line,
const std::string &message,
...
)
{
bool log_to_console = true;
if (log_settings[log_category].log_to_console < debug_level) {
@ -381,12 +405,18 @@ void EQEmuLogSys::Out(Logs::DebugLevel debug_level, uint16 log_category, std::st
return;
}
std::string prefix;
if (RuleB(Logging, PrintFileFunctionAndLine)) {
prefix = fmt::format("[{0}::{1}:{2}] ", file_name(file), func, line);
}
va_list args;
va_start(args, message);
std::string output_message = vStringFormat(message.c_str(), args);
va_end(args);
std::string output_debug_message = EQEmuLogSys::FormatOutMessageString(log_category, output_message);
std::string output_debug_message = EQEmuLogSys::FormatOutMessageString(log_category, prefix + output_message);
if (log_to_console) {
EQEmuLogSys::ProcessConsoleMessage(debug_level, log_category, output_debug_message);
@ -463,12 +493,13 @@ void EQEmuLogSys::StartFileLogs(const std::string &log_name)
return;
}
EQEmuLogSys::Out(
Log(
Logs::General,
Logs::Status,
"Starting File Log 'logs/%s_%i.log'",
platform_file_name.c_str(),
getpid());
getpid()
);
/**
* Make directory if not exists
@ -493,12 +524,13 @@ void EQEmuLogSys::StartFileLogs(const std::string &log_name)
return;
}
EQEmuLogSys::Out(
Log(
Logs::General,
Logs::Status,
"Starting File Log 'logs/%s_%i.log'",
platform_file_name.c_str(),
getpid());
getpid()
);
/**
* Open file pointer

View File

@ -21,6 +21,7 @@
#ifndef EQEMU_LOGSYS_H
#define EQEMU_LOGSYS_H
#include <fmt/format.h>
#include <iostream>
#include <fstream>
#include <stdio.h>
@ -158,12 +159,12 @@ namespace Logs {
#define Log(debug_level, log_category, message, ...) do {\
if (LogSys.log_settings[log_category].is_category_enabled == 1)\
LogSys.Out(debug_level, log_category, message, ##__VA_ARGS__);\
LogSys.Out(debug_level, log_category, __FILE__, __func__, __LINE__, message, ##__VA_ARGS__);\
} while (0)
#define LogF(debug_level, log_category, message, ...) do {\
if (LogSys.log_settings[log_category].is_category_enabled == 1)\
OutF(LogSys, debug_level, log_category, message, ##__VA_ARGS__);\
OutF(LogSys, debug_level, log_category, __FILE__, __func__, __LINE__, message, ##__VA_ARGS__);\
} while (0)
class EQEmuLogSys {
@ -188,7 +189,15 @@ public:
* - This would pipe the same category and debug level to all output formats, but the internal memory reference of log_settings would
* be checked against to see if that piped output is set to actually process it for the category and debug level
*/
void Out(Logs::DebugLevel debug_level, uint16 log_category, std::string message, ...);
void Out(
Logs::DebugLevel debug_level,
uint16 log_category,
const char *file,
const char *func,
int line,
const std::string &message,
...
);
/**
* Used in file logs to prepend a timestamp entry for logs
@ -218,14 +227,14 @@ public:
* These are loaded via DB and have defaults loaded in LoadLogSettingsDefaults
* Database loaded via Database::LoadLogSettings(log_settings)
*/
LogSettings log_settings[Logs::LogCategory::MaxCategoryID];
LogSettings log_settings[Logs::LogCategory::MaxCategoryID]{};
bool file_logs_enabled;
bool file_logs_enabled{};
/**
* Sets Executable platform (Zone/World/UCS) etc.
*/
int log_platform;
int log_platform{};
/**
* File name used in writing logs

View File

@ -22,9 +22,18 @@
#include <fmt/format.h>
template <typename... Args>
void OutF(EQEmuLogSys &ls, Logs::DebugLevel debug_level, uint16 log_category, const char *fmt, const Args&... args)
template<typename... Args>
void OutF(
EQEmuLogSys &ls,
Logs::DebugLevel debug_level,
uint16 log_category,
const char *file,
const char *func,
int line,
const char *fmt,
const Args &... args
)
{
std::string log_str = fmt::format(fmt, args...);
ls.Out(debug_level, log_category, log_str);
}
ls.Out(debug_level, log_category, file, func, line, log_str);
}

View File

@ -746,6 +746,10 @@ RULE_INT(Faction, DubiouslyFactionMinimum, -500)
RULE_INT(Faction, ThreateninglyFactionMinimum, -750)
RULE_CATEGORY_END()
RULE_CATEGORY(Logging)
RULE_BOOL(Logging, PrintFileFunctionAndLine, true) // Ex: [World Server] [net.cpp::main:309] Loading variables...
RULE_CATEGORY_END()
#undef RULE_CATEGORY
#undef RULE_INT
#undef RULE_REAL

View File

@ -181,12 +181,7 @@ void Client::Handle_SessionReady(const char *data, unsigned int size)
void Client::Handle_Login(const char *data, unsigned int size)
{
if (status != cs_waiting_for_login) {
LogF(
Logs::General,
Logs::Error,
"{0} Login received after already having logged in",
__func__
);
LogF(Logs::General, Logs::Error, "Login received after already having logged in");
return;
}
@ -194,8 +189,7 @@ void Client::Handle_Login(const char *data, unsigned int size)
LogF(
Logs::General,
Logs::Error,
"{0} Login received packet of size: {1}, this would cause a block corruption, discarding.",
__func__,
"Login received packet of size: {0}, this would cause a block corruption, discarding.",
size
);
return;
@ -205,8 +199,7 @@ void Client::Handle_Login(const char *data, unsigned int size)
LogF(
Logs::General,
Logs::Error,
"{0} Login received packet of size: %u, this would cause a buffer overflow, discarding.",
__func__,
"Login received packet of size: {0}, this would cause a buffer overflow, discarding.",
size
);
@ -236,12 +229,7 @@ void Client::Handle_Login(const char *data, unsigned int size)
std::string user(&outbuffer[0]);
if (user.length() >= outbuffer.length()) {
LogF(
Logs::General,
Logs::Debug,
"{0} Corrupt buffer sent to server, preventing buffer overflow.",
__func__
);
LogF(Logs::General, Logs::Debug,"Corrupt buffer sent to server, preventing buffer overflow.");
return;
}
@ -272,8 +260,7 @@ void Client::Handle_Login(const char *data, unsigned int size)
LogF(
Logs::General,
Logs::Login_Server,
"{0} Attempting password based login [{1}] login [{2}] user [{3}]",
__func__,
"Attempting password based login [{0}] login [{1}] user [{2}]",
user,
db_loginserver,
user
@ -287,8 +274,7 @@ void Client::Handle_Login(const char *data, unsigned int size)
LogF(
Logs::Detail,
Logs::Login_Server,
"{0} [VerifyLoginHash] Success [{1}]",
__func__,
"[VerifyLoginHash] Success [{0}]",
(result ? "true" : "false")
);
}
@ -306,9 +292,7 @@ void Client::Handle_Login(const char *data, unsigned int size)
*/
if (result) {
LogF(
Logs::Detail, Logs::Login_Server, "{0} [{1}] login [{2}] user [{3}] Login succeeded",
__func__,
user,
Logs::Detail, Logs::Login_Server, "lgoin [{0}] user [{2}] Login succeeded",
db_loginserver,
user
);
@ -317,9 +301,7 @@ void Client::Handle_Login(const char *data, unsigned int size)
}
else {
LogF(
Logs::Detail, Logs::Login_Server, "{0} [{1}] login [{2}] user [{3}] Login failed",
__func__,
user,
Logs::Detail, Logs::Login_Server, "lgoin [{0}] user [{2}] Login failed",
db_loginserver,
user
);
@ -537,6 +519,14 @@ bool Client::VerifyLoginHash(
if (hash.length() == 32) { //md5 is insecure
for (int i = EncryptionModeMD5; i <= EncryptionModeMD5Triple; ++i) {
if (i != mode && eqcrypt_verify_hash(user, cred, hash, i)) {
LogF(
Logs::Detail,
Logs::Login_Server,
"user [{0}] loginserver [{1}] mode [{2}]",
user,
loginserver,
mode
);
server.db->UpdateLoginHash(user, loginserver, eqcrypt_hash(user, cred, mode));
return true;
}
@ -545,6 +535,15 @@ bool Client::VerifyLoginHash(
else if (hash.length() == 40) { //sha1 is insecure
for (int i = EncryptionModeSHA; i <= EncryptionModeSHATriple; ++i) {
if (i != mode && eqcrypt_verify_hash(user, cred, hash, i)) {
LogF(
Logs::Detail,
Logs::Login_Server,
"user [{0}] loginserver [{1}] mode [{2}]",
user,
loginserver,
mode
);
server.db->UpdateLoginHash(user, loginserver, eqcrypt_hash(user, cred, mode));
return true;
}
@ -553,6 +552,15 @@ bool Client::VerifyLoginHash(
else if (hash.length() == 128) { //sha2-512 is insecure
for (int i = EncryptionModeSHA512; i <= EncryptionModeSHA512Triple; ++i) {
if (i != mode && eqcrypt_verify_hash(user, cred, hash, i)) {
LogF(
Logs::Detail,
Logs::Login_Server,
"user [{0}] loginserver [{1}] mode [{2}]",
user,
loginserver,
mode
);
server.db->UpdateLoginHash(user, loginserver, eqcrypt_hash(user, cred, mode));
return true;
}
@ -694,22 +702,13 @@ void Client::LoginOnStatusChange(
)
{
if (to == EQ::Net::StatusConnected) {
LogF(
Logs::Detail,
Logs::Login_Server,
"[{0}] == EQ::Net::StatusConnected",
__func__
);
LogF(Logs::Detail, Logs::Login_Server, "EQ::Net::StatusConnected");
LoginSendSessionReady();
}
if (to == EQ::Net::StatusDisconnecting || to == EQ::Net::StatusDisconnected) {
LogF(
Logs::Detail,
Logs::Login_Server,
"[{0}] == EQ::Net::StatusDisconnecting || EQ::Net::StatusDisconnected",
__func__
);
LogF(Logs::Detail, Logs::Login_Server, "EQ::Net::StatusDisconnecting || EQ::Net::StatusDisconnected");
DoFailedLogin();
}
}
@ -734,7 +733,7 @@ void Client::LoginOnStatusChangeIgnored(
void Client::LoginOnPacketRecv(std::shared_ptr<EQ::Net::DaybreakConnection> conn, const EQ::Net::Packet &p)
{
auto opcode = p.GetUInt16(0);
LogF(Logs::Detail, Logs::Login_Server, "[{0}] [{1}]", __func__, opcode);
LogF(Logs::Detail, Logs::Login_Server, "[{0}]", opcode);
switch (opcode) {
case 0x0017: //OP_ChatMessage
LoginSendLogin();
@ -806,7 +805,7 @@ void Client::LoginProcessLoginResponse(const EQ::Net::Packet &p)
);
if (response_error > 101) {
LogF(Logs::Detail, Logs::Login_Server, "[{0}] response [{1}] failed login", __func__, response_error);
LogF(Logs::Detail, Logs::Login_Server, "response [{0}] failed login", response_error);
DoFailedLogin();
login_connection->Close();
}
@ -814,8 +813,7 @@ void Client::LoginProcessLoginResponse(const EQ::Net::Packet &p)
LogF(
Logs::Detail,
Logs::Login_Server,
"[{0}] response [{1}] login succeeded user [{2}]",
__func__,
"response [{0}] login succeeded user [{1}]",
response_error,
stored_user
);

View File

@ -134,8 +134,7 @@ bool DatabaseMySQL::GetLoginDataFromAccountInfo(
LogF(
Logs::Detail,
Logs::Login_Server,
"[{0}] could not find account for name [{1}] login [{2}]",
__func__,
"Could not find account for name [{0}] login [{1}]",
name,
loginserver
);
@ -155,8 +154,7 @@ bool DatabaseMySQL::GetLoginDataFromAccountInfo(
LogF(
Logs::Detail,
Logs::Login_Server,
"[{0}] found account for name [{1}] login [{2}]",
__func__,
"Found account for name [{0}] login [{1}]",
name,
loginserver
);
@ -329,8 +327,21 @@ bool DatabaseMySQL::CreateLoginDataWithID(
* @param loginserver
* @param hash
*/
void DatabaseMySQL::UpdateLoginHash(const std::string &name, const std::string &loginserver, const std::string &hash)
void DatabaseMySQL::UpdateLoginHash(
const std::string &name,
const std::string &loginserver,
const std::string &hash
)
{
LogF(
Logs::Detail,
Logs::Login_Server,
"name [{0}] loginserver [{1}] hash [{2}]",
name,
loginserver,
hash
);
auto query = fmt::format(
"UPDATE {0} SET AccountPassword='{1}' WHERE AccountName='{2}' AND AccountLoginserver='{3}'",
server.options.GetAccountTable(),
@ -366,6 +377,7 @@ bool DatabaseMySQL::GetWorldRegistration(
std::string &password
)
{
if (!database) {
return false;
}

View File

@ -587,7 +587,6 @@ void WorldServer::Handle_NewLSInfo(ServerNewLSInfo_Struct *i)
std::string server_account_name;
std::string server_account_password;
if (server.db->GetWorldRegistration(
long_name,
short_name,

View File

@ -226,7 +226,7 @@ int main(int argc, char** argv) {
worldserver.SetLauncherName("NONE");
}
Log(Logs::General, Logs::Zone_Server, "Connecting to MySQL...");
Log(Logs::General, Logs::Zone_Server, "Connecting to MySQL... ");
if (!database.Connect(
Config->DatabaseHost.c_str(),
Config->DatabaseUsername.c_str(),