Core/Logging: Add Asyncronous logging with Loggers ("What to log") and Appenders ("Where to log") system. Will allow to select to full log some parts of core while others are not even logged.

- Logging System is asyncronous to improve performance.
- Each msg and Logger has a Log Type and Log Level assigned. Each msg is assigned the Logger of same Log Type or "root" Logger is selected if there is no Logger configured for the given Log Type
- Loggers have a list of Appenders to send the msg to. The Msg in the Logger is not sent to Appenders if the msg LogLevel is lower than Logger LogLevel.
- There are three (at the moment) types of Appenders: Console, File or DB (this is WIP, not working ATM). Msg is not written to the resource if msg LogLevel is lower than Appender LogLevel.
- Appender and Console Log levels can be changed while server is active with command '.set loglevel (a/l) name level'

Explanation of use with Sample config:

Appender.Console.Type=1       (1 = Console)
Appender.Console.Level=2      (2 = Debug)

Appender.Server.Type=2        (2 = File)
Appender.Server.Level=3       (3 = Info)
Appender.Server.File=Server.log

Appender.SQL.Type=2           (2 = File)
Appender.SQL.Level=1          (1 = Trace)
Appender.SQL.File=sql.log

Appenders=Console Server      (NOTE: SQL has not been included here... that will make core ignore the config for "SQL" as it's not in this list)

Logger.root.Type=0            (0 = Default - if it's not created by config, server will create it with LogLevel = DISABLED)
Logger.root.Level=5           (5 = Error)
Logger.root.Appenders=Console

Logger.SQL.Type=26            (26 = SQL)
Logger.SQL.Level=3            (2 = Debug)
Logger.SQL.Appenders=Console Server SQL

Logger.SomeRandomName.Type=24 (24 = Guild)
Logger.SomeRandomName.Level=5 (5 = Error)
Loggers=root SQL SomeRandomName

* At loading Appender SQL will be ignored, as it's not present on "Appenders"

* sLog->outDebug(LOG_FILTER_GUILD, "Some log msg related to Guilds")
  - Msg is sent to Logger of Type LOG_FILTER_GUILD (24). Logger with name SomeRandomName is found but it's LogLevel = 5 and Msg LogLevel=2... Msg is not logged

* sLog->outError(LOG_FILTER_GUILD, "Some error log msg related to Guilds")
  - Msg is sent to Logger of Type LOG_FILTER_GUILD (24). Logger with name SomeRandomeName is found with proper LogLevel but Logger does not have any Appenders assigned to that logger... Msg is not logged

* sLog->outDebug(LOG_FILTER_SQL, "Some msg related to SQLs")
  - Msg is sent to Logger SQL (matches type), as it matches LogLevel the msg is sent to Appenders Console, Server and SQL
    - Appender Console has lower Log Level: Msg is logged to Console
    - Appender Server has higher Log Level: Msg is not logged to file
    - Appender SQL has lower Log Level: Msg is logged to file sql.log

* sLog->outDebug(LOG_FILTER_BATTLEGROUND, "Some msg related to Battelgrounds")
  - Msg is sent to Logger root (Type 0) as no Logger was found with Type LOG_FILTER_BATTLEGROUND (13). As Logger has higher LogLevel msg is not sent to any appender

* sLog->outError(LOG_FILTER_BATTLEGROUND, "Some error msg related to Battelgrounds")
  - Msg is sent to Logger root (Type 0) as no Logger was found with Type LOG_FILTER_BATTLEGROUND (13). Msg has lower LogLevel and is sent to Appender Console
    - Appender Console has lower LogLevel: Msg is logged to Console

1 files changed, 49 insertions, 59 deletions

diff --git a/src/server/shared/Database/MySQLConnection.cpp b/src/server/shared/Database/MySQLConnection.cpp
index 7fb4a4f7025..324efab067e 100755
--- a/src/server/shared/Database/MySQLConnection.cpp
+++ b/src/server/shared/Database/MySQLConnection.cpp
@@ -22,6 +22,8 @@
   #include <winsock2.h>
 #endif
 #include <mysql.h>
+#include <mysqld_error.h>
+#include <errmsg.h>
 
 #include "MySQLConnection.h"
 #include "MySQLThreading.h"
@@ -79,7 +81,7 @@ bool MySQLConnection::Open()
     mysqlInit = mysql_init(NULL);
     if (!mysqlInit)
     {
-        sLog->outError("Could not initialize Mysql connection to database `%s`", m_connectionInfo.database.c_str());
+        sLog->outError(LOG_FILTER_SQL, "Could not initialize Mysql connection to database `%s`", m_connectionInfo.database.c_str());
         return false;
     }
 
@@ -123,13 +125,13 @@ bool MySQLConnection::Open()
     {
         if (!m_reconnecting)
         {
-            sLog->outSQLDriver("MySQL client library: %s", mysql_get_client_info());
-            sLog->outSQLDriver("MySQL server ver: %s ", mysql_get_server_info(m_Mysql));
+            sLog->outInfo(LOG_FILTER_SQL, "MySQL client library: %s", mysql_get_client_info());
+            sLog->outInfo(LOG_FILTER_SQL, "MySQL server ver: %s ", mysql_get_server_info(m_Mysql));
             if (mysql_get_server_version(m_Mysql) != mysql_get_client_version())
-                sLog->outSQLDriver("[WARNING] MySQL client/server version mismatch; may conflict with behaviour of prepared statements.");
+                sLog->outInfo(LOG_FILTER_SQL, "[WARNING] MySQL client/server version mismatch; may conflict with behaviour of prepared statements.");
         }
 
-        sLog->outDetail("Connected to MySQL database at %s", m_connectionInfo.host.c_str());
+        sLog->outInfo(LOG_FILTER_SQL, "Connected to MySQL database at %s", m_connectionInfo.host.c_str());
         mysql_autocommit(m_Mysql, 1);
 
         // set connection properties to UTF8 to properly handle locales for different
@@ -139,7 +141,7 @@ bool MySQLConnection::Open()
     }
     else
     {
-        sLog->outError("Could not connect to MySQL database at %s: %s\n", m_connectionInfo.host.c_str(), mysql_error(mysqlInit));
+        sLog->outError(LOG_FILTER_SQL, "Could not connect to MySQL database at %s: %s\n", m_connectionInfo.host.c_str(), mysql_error(mysqlInit));
         mysql_close(mysqlInit);
         return false;
     }
@@ -159,26 +161,22 @@ bool MySQLConnection::Execute(const char* sql)
         return false;
 
     {
-        uint32 _s = 0;
-        if (sLog->GetSQLDriverQueryLogging())
-            _s = getMSTime();
+        uint32 _s = getMSTime();
 
         if (mysql_query(m_Mysql, sql))
         {
             uint32 lErrno = mysql_errno(m_Mysql);
 
-            sLog->outSQLDriver("SQL: %s", sql);
-            sLog->outSQLDriver("ERROR: [%u] %s", lErrno, mysql_error(m_Mysql));
+            sLog->outInfo(LOG_FILTER_SQL, "SQL: %s", sql);
+            sLog->outError(LOG_FILTER_SQL, "[%u] %s", lErrno, mysql_error(m_Mysql));
 
             if (_HandleMySQLErrno(lErrno))  // If it returns true, an error was handled successfully (i.e. reconnection)
                 return Execute(sql);       // Try again
 
             return false;
         }
-        else if (sLog->GetSQLDriverQueryLogging())
-        {
-            sLog->outSQLDriver("[%u ms] SQL: %s", getMSTimeDiff(_s, getMSTime()), sql);
-        }
+        else 
+            sLog->outDebug(LOG_FILTER_SQL, "[%u ms] SQL: %s", getMSTimeDiff(_s, getMSTime()), sql);
     }
 
     return true;
@@ -201,14 +199,12 @@ bool MySQLConnection::Execute(PreparedStatement* stmt)
         MYSQL_STMT* msql_STMT = m_mStmt->GetSTMT();
         MYSQL_BIND* msql_BIND = m_mStmt->GetBind();
 
-        uint32 _s = 0;
-        if (sLog->GetSQLDriverQueryLogging())
-            _s = getMSTime();
+        uint32 _s = getMSTime();
 
         if (mysql_stmt_bind_param(msql_STMT, msql_BIND))
         {
             uint32 lErrno = mysql_errno(m_Mysql);
-            sLog->outSQLDriver("SQL(p): %s\n [ERROR]: [%u] %s", m_mStmt->getQueryString(m_queries[index].first).c_str(), lErrno, mysql_stmt_error(msql_STMT));
+            sLog->outError(LOG_FILTER_SQL, "SQL(p): %s\n [ERROR]: [%u] %s", m_mStmt->getQueryString(m_queries[index].first).c_str(), lErrno, mysql_stmt_error(msql_STMT));
 
             if (_HandleMySQLErrno(lErrno))  // If it returns true, an error was handled successfully (i.e. reconnection)
                 return Execute(stmt);       // Try again
@@ -220,7 +216,7 @@ bool MySQLConnection::Execute(PreparedStatement* stmt)
         if (mysql_stmt_execute(msql_STMT))
         {
             uint32 lErrno = mysql_errno(m_Mysql);
-            sLog->outSQLDriver("SQL(p): %s\n [ERROR]: [%u] %s", m_mStmt->getQueryString(m_queries[index].first).c_str(), lErrno, mysql_stmt_error(msql_STMT));
+            sLog->outError(LOG_FILTER_SQL, "SQL(p): %s\n [ERROR]: [%u] %s", m_mStmt->getQueryString(m_queries[index].first).c_str(), lErrno, mysql_stmt_error(msql_STMT));
 
             if (_HandleMySQLErrno(lErrno))  // If it returns true, an error was handled successfully (i.e. reconnection)
                 return Execute(stmt);       // Try again
@@ -229,8 +225,7 @@ bool MySQLConnection::Execute(PreparedStatement* stmt)
             return false;
         }
 
-        if (sLog->GetSQLDriverQueryLogging())
-            sLog->outSQLDriver("[%u ms] SQL(p): %s", getMSTimeDiff(_s, getMSTime()), m_mStmt->getQueryString(m_queries[index].first).c_str());
+        sLog->outDebug(LOG_FILTER_SQL, "[%u ms] SQL(p): %s", getMSTimeDiff(_s, getMSTime()), m_mStmt->getQueryString(m_queries[index].first).c_str());
 
         m_mStmt->ClearParameters();
         return true;
@@ -254,14 +249,12 @@ bool MySQLConnection::_Query(PreparedStatement* stmt, MYSQL_RES **pResult, uint6
         MYSQL_STMT* msql_STMT = m_mStmt->GetSTMT();
         MYSQL_BIND* msql_BIND = m_mStmt->GetBind();
 
-        uint32 _s = 0;
-        if (sLog->GetSQLDriverQueryLogging())
-            _s = getMSTime();
+        uint32 _s = getMSTime();
 
         if (mysql_stmt_bind_param(msql_STMT, msql_BIND))
         {
             uint32 lErrno = mysql_errno(m_Mysql);
-            sLog->outSQLDriver("SQL(p): %s\n [ERROR]: [%u] %s", m_mStmt->getQueryString(m_queries[index].first).c_str(), lErrno, mysql_stmt_error(msql_STMT));
+            sLog->outError(LOG_FILTER_SQL, "SQL(p): %s\n [ERROR]: [%u] %s", m_mStmt->getQueryString(m_queries[index].first).c_str(), lErrno, mysql_stmt_error(msql_STMT));
 
             if (_HandleMySQLErrno(lErrno))  // If it returns true, an error was handled successfully (i.e. reconnection)
                 return _Query(stmt, pResult, pRowCount, pFieldCount);       // Try again
@@ -273,7 +266,7 @@ bool MySQLConnection::_Query(PreparedStatement* stmt, MYSQL_RES **pResult, uint6
         if (mysql_stmt_execute(msql_STMT))
         {
             uint32 lErrno = mysql_errno(m_Mysql);
-            sLog->outSQLDriver("SQL(p): %s\n [ERROR]: [%u] %s",
+            sLog->outError(LOG_FILTER_SQL, "SQL(p): %s\n [ERROR]: [%u] %s",
                 m_mStmt->getQueryString(m_queries[index].first).c_str(), lErrno, mysql_stmt_error(msql_STMT));
 
             if (_HandleMySQLErrno(lErrno))  // If it returns true, an error was handled successfully (i.e. reconnection)
@@ -283,8 +276,7 @@ bool MySQLConnection::_Query(PreparedStatement* stmt, MYSQL_RES **pResult, uint6
             return false;
         }
 
-        if (sLog->GetSQLDriverQueryLogging())
-            sLog->outSQLDriver("[%u ms] SQL(p): %s", getMSTimeDiff(_s, getMSTime()), m_mStmt->getQueryString(m_queries[index].first).c_str());
+        sLog->outDebug(LOG_FILTER_SQL, "[%u ms] SQL(p): %s", getMSTimeDiff(_s, getMSTime()), m_mStmt->getQueryString(m_queries[index].first).c_str());
 
         m_mStmt->ClearParameters();
 
@@ -319,25 +311,21 @@ bool MySQLConnection::_Query(const char *sql, MYSQL_RES **pResult, MYSQL_FIELD *
         return false;
 
     {
-        uint32 _s = 0;
-        if (sLog->GetSQLDriverQueryLogging())
-            _s = getMSTime();
+        uint32 _s = getMSTime();
 
         if (mysql_query(m_Mysql, sql))
         {
             uint32 lErrno = mysql_errno(m_Mysql);
-            sLog->outSQLDriver("SQL: %s", sql);
-            sLog->outSQLDriver("ERROR: [%u] %s", lErrno, mysql_error(m_Mysql));
+            sLog->outInfo(LOG_FILTER_SQL, "SQL: %s", sql);
+            sLog->outError(LOG_FILTER_SQL, "[%u] %s", lErrno, mysql_error(m_Mysql));
 
             if (_HandleMySQLErrno(lErrno))      // If it returns true, an error was handled successfully (i.e. reconnection)
                 return _Query(sql, pResult, pFields, pRowCount, pFieldCount);    // We try again
 
             return false;
         }
-        else if (sLog->GetSQLDriverQueryLogging())
-        {
-            sLog->outSQLDriver("[%u ms] SQL: %s", getMSTimeDiff(_s, getMSTime()), sql);
-        }
+        else
+            sLog->outDebug(LOG_FILTER_SQL, "[%u ms] SQL: %s", getMSTimeDiff(_s, getMSTime()), sql);
 
         *pResult = mysql_store_result(m_Mysql);
         *pRowCount = mysql_affected_rows(m_Mysql);
@@ -393,7 +381,7 @@ bool MySQLConnection::ExecuteTransaction(SQLTransaction& transaction)
                 ASSERT(stmt);
                 if (!Execute(stmt))
                 {
-                    sLog->outSQLDriver("[Warning] Transaction aborted. %u queries not executed.", (uint32)queries.size());
+                    sLog->outWarn(LOG_FILTER_SQL, "Transaction aborted. %u queries not executed.", (uint32)queries.size());
                     RollbackTransaction();
                     return false;
                 }
@@ -405,7 +393,7 @@ bool MySQLConnection::ExecuteTransaction(SQLTransaction& transaction)
                 ASSERT(sql);
                 if (!Execute(sql))
                 {
-                    sLog->outSQLDriver("[Warning] Transaction aborted. %u queries not executed.", (uint32)queries.size());
+                    sLog->outWarn(LOG_FILTER_SQL, "Transaction aborted. %u queries not executed.", (uint32)queries.size());
                     RollbackTransaction();
                     return false;
                 }
@@ -428,7 +416,7 @@ MySQLPreparedStatement* MySQLConnection::GetPreparedStatement(uint32 index)
     ASSERT(index < m_stmts.size());
     MySQLPreparedStatement* ret = m_stmts[index];
     if (!ret)
-        sLog->outSQLDriver("ERROR: Could not fetch prepared statement %u on database `%s`, connection type: %s.",
+        sLog->outError(LOG_FILTER_SQL, "Could not fetch prepared statement %u on database `%s`, connection type: %s.",
             index, m_connectionInfo.database.c_str(), (m_connectionFlags & CONNECTION_ASYNC) ? "asynchronous" : "synchronous");
 
     return ret;
@@ -449,19 +437,19 @@ void MySQLConnection::PrepareStatement(uint32 index, const char* sql, Connection
         return;
     }
 
-    MYSQL_STMT * stmt = mysql_stmt_init(m_Mysql);
+    MYSQL_STMT* stmt = mysql_stmt_init(m_Mysql);
     if (!stmt)
     {
-        sLog->outSQLDriver("[ERROR]: In mysql_stmt_init() id: %u, sql: \"%s\"", index, sql);
-        sLog->outSQLDriver("[ERROR]: %s", mysql_error(m_Mysql));
+        sLog->outError(LOG_FILTER_SQL, "In mysql_stmt_init() id: %u, sql: \"%s\"", index, sql);
+        sLog->outError(LOG_FILTER_SQL, "%s", mysql_error(m_Mysql));
         m_prepareError = true;
     }
     else
     {
         if (mysql_stmt_prepare(stmt, sql, static_cast<unsigned long>(strlen(sql))))
         {
-            sLog->outSQLDriver("[ERROR]: In mysql_stmt_prepare() id: %u, sql: \"%s\"", index, sql);
-            sLog->outSQLDriver("[ERROR]: %s", mysql_stmt_error(stmt));
+            sLog->outError(LOG_FILTER_SQL, "In mysql_stmt_prepare() id: %u, sql: \"%s\"", index, sql);
+            sLog->outError(LOG_FILTER_SQL, "%s", mysql_stmt_error(stmt));
             mysql_stmt_close(stmt);
             m_prepareError = true;
         }
@@ -493,19 +481,19 @@ bool MySQLConnection::_HandleMySQLErrno(uint32 errNo)
 {
     switch (errNo)
     {
-        case 2006:  // "MySQL server has gone away"
-        case 2013:  // "Lost connection to MySQL server during query"
-        case 2048:  // "Invalid connection handle"
-        case 2055:  // "Lost connection to MySQL server at '%s', system error: %d"
+        case CR_SERVER_GONE_ERROR:
+        case CR_SERVER_LOST:
+        case CR_INVALID_CONN_HANDLE:
+        case CR_SERVER_LOST_EXTENDED:
         {
             m_reconnecting = true;
             uint64 oldThreadId = mysql_thread_id(GetHandle());
             mysql_close(GetHandle());
             if (this->Open())                           // Don't remove 'this' pointer unless you want to skip loading all prepared statements....
             {
-                sLog->outSQLDriver("Connection to the MySQL server is active.");
+                sLog->outInfo(LOG_FILTER_SQL, "Connection to the MySQL server is active.");
                 if (oldThreadId != mysql_thread_id(GetHandle()))
-                    sLog->outSQLDriver("Successfully reconnected to %s @%s:%s (%s).",
+                    sLog->outInfo(LOG_FILTER_SQL, "Successfully reconnected to %s @%s:%s (%s).",
                         m_connectionInfo.database.c_str(), m_connectionInfo.host.c_str(), m_connectionInfo.port_or_socket.c_str(),
                             (m_connectionFlags & CONNECTION_ASYNC) ? "asynchronous" : "synchronous");
 
@@ -518,21 +506,23 @@ bool MySQLConnection::_HandleMySQLErrno(uint32 errNo)
             return _HandleMySQLErrno(lErrno);           // Call self (recursive)
         }
 
-        case 1213:      // "Deadlock found when trying to get lock; try restarting transaction"
+        case ER_LOCK_DEADLOCK:
             return false;    // Implemented in TransactionTask::Execute and DatabaseWorkerPool<T>::DirectCommitTransaction
         // Query related errors - skip query
-        case 1058:      // "Column count doesn't match value count"
-        case 1062:      // "Duplicate entry '%s' for key '%d'"
+        case ER_WRONG_VALUE_COUNT:
+        case ER_DUP_ENTRY:
             return false;
 
         // Outdated table or database structure - terminate core
-        case 1054:      // "Unknown column '%s' in '%s'"
-        case 1146:      // "Table '%s' doesn't exist"
-            WPFatal(!errNo, "Your database structure is not up to date. Please make sure you've executed all queries in the sql/updates folders.");
+        case ER_BAD_FIELD_ERROR:
+        case ER_NO_SUCH_TABLE:
+            sLog->outError(LOG_FILTER_SQL, "Your database structure is not up to date. Please make sure you've executed all queries in the sql/updates folders.");
+            ACE_OS::sleep(10);
+            std::abort();
             return false;
 
         default:
-            sLog->outSQLDriver("Unhandled MySQL errno %u. Unexpected behaviour possible.", errNo);
+            sLog->outError(LOG_FILTER_SQL, "Unhandled MySQL errno %u. Unexpected behaviour possible.", errNo);
             return false;
     }
 }