Core/Log: Add type safe formatting

* improves safety and log speed through:
  - variadic templates
  - perfect forwarding
* fixes a newline in db logs
* improve performance of Appender::write by using std::ostringstream && std::move

14 files changed, 108 insertions, 112 deletions

diff --git a/src/server/shared/Logging/Appender.cpp b/src/server/shared/Logging/Appender.cpp
index dff931e3da8..ca40a857419 100644
--- a/src/server/shared/Logging/Appender.cpp
+++ b/src/server/shared/Logging/Appender.cpp
@@ -18,6 +18,10 @@
 #include "Appender.h"
 #include "Common.h"
 #include "Util.h"
+#include "StringFormat.h"
+
+#include <utility>
+#include <sstream>
 
 std::string LogMessage::getTimeStr(time_t time)
 {
@@ -68,38 +72,36 @@ void Appender::setLogLevel(LogLevel _level)
     level = _level;
 }
 
-void Appender::write(LogMessage& message)
+void Appender::write(LogMessage* message)
 {
-    if (!level || level > message.level)
+    if (!level || level > message->level)
         return;
 
-    message.prefix.clear();
+    std::ostringstream ss;
+
     if (flags & APPENDER_FLAGS_PREFIX_TIMESTAMP)
-        message.prefix.append(message.getTimeStr());
+        ss << message->getTimeStr();
 
     if (flags & APPENDER_FLAGS_PREFIX_LOGLEVEL)
     {
-        if (!message.prefix.empty())
-            message.prefix.push_back(' ');
+        if (ss.rdbuf()->in_avail() == 0)
+            ss << ' ';
 
-        char text[MAX_QUERY_LEN];
-        snprintf(text, MAX_QUERY_LEN, "%-5s", Appender::getLogLevelString(message.level));
-        message.prefix.append(text);
+        ss << Trinity::StringFormat("%-5s", Appender::getLogLevelString(message->level));
     }
 
     if (flags & APPENDER_FLAGS_PREFIX_LOGFILTERTYPE)
     {
-        if (!message.prefix.empty())
-            message.prefix.push_back(' ');
+        if (ss.rdbuf()->in_avail() == 0)
+            ss << ' ';
 
-        message.prefix.push_back('[');
-        message.prefix.append(message.type);
-        message.prefix.push_back(']');
+        ss << '[' << message->type << ']';
     }
 
-    if (!message.prefix.empty())
-        message.prefix.push_back(' ');
+    if (ss.rdbuf()->in_avail() == 0)
+        ss << ' ';
 
+    message->prefix = std::move(ss.str());
     _write(message);
 }
 
diff --git a/src/server/shared/Logging/Appender.h b/src/server/shared/Logging/Appender.h
index 6f38eb6aaf7..38c45b3bcf1 100644
--- a/src/server/shared/Logging/Appender.h
+++ b/src/server/shared/Logging/Appender.h
@@ -21,6 +21,7 @@
 #include <unordered_map>
 #include <string>
 #include <time.h>
+#include <type_traits>
 #include "Define.h"
 
 // Values assigned have their equivalent in enum ACE_Log_Priority
@@ -57,16 +58,16 @@ enum AppenderFlags
 
 struct LogMessage
 {
-    LogMessage(LogLevel _level, std::string const& _type, std::string const& _text)
-        : level(_level), type(_type), text(_text), mtime(time(NULL))
+    LogMessage(LogLevel _level, std::string const& _type, std::string&& _text)
+        : level(_level), type(_type), text(std::forward<std::string>(_text)), mtime(time(NULL))
     { }
 
     static std::string getTimeStr(time_t time);
     std::string getTimeStr();
 
-    LogLevel level;
-    std::string type;
-    std::string text;
+    LogLevel const level;
+    std::string const type;
+    std::string const text;
     std::string prefix;
     std::string param1;
     time_t mtime;
@@ -91,11 +92,11 @@ class Appender
         AppenderFlags getFlags() const;
 
         void setLogLevel(LogLevel);
-        void write(LogMessage& message);
+        void write(LogMessage* message);
         static const char* getLogLevelString(LogLevel level);
 
     private:
-        virtual void _write(LogMessage const& /*message*/) = 0;
+        virtual void _write(LogMessage const* /*message*/) = 0;
 
         uint8 id;
         std::string name;
diff --git a/src/server/shared/Logging/AppenderConsole.cpp b/src/server/shared/Logging/AppenderConsole.cpp
index ae27337fb9a..2efa4db4d2e 100644
--- a/src/server/shared/Logging/AppenderConsole.cpp
+++ b/src/server/shared/Logging/AppenderConsole.cpp
@@ -158,14 +158,14 @@ void AppenderConsole::ResetColor(bool stdout_stream)
     #endif
 }
 
-void AppenderConsole::_write(LogMessage const& message)
+void AppenderConsole::_write(LogMessage const* message)
 {
-    bool stdout_stream = !(message.level == LOG_LEVEL_ERROR || message.level == LOG_LEVEL_FATAL);
+    bool stdout_stream = !(message->level == LOG_LEVEL_ERROR || message->level == LOG_LEVEL_FATAL);
 
     if (_colored)
     {
         uint8 index;
-        switch (message.level)
+        switch (message->level)
         {
             case LOG_LEVEL_TRACE:
                index = 5;
@@ -189,9 +189,9 @@ void AppenderConsole::_write(LogMessage const& message)
         }
 
         SetColor(stdout_stream, _colors[index]);
-        utf8printf(stdout_stream ? stdout : stderr, "%s%s", message.prefix.c_str(), message.text.c_str());
+        utf8printf(stdout_stream ? stdout : stderr, "%s%s\n", message->prefix.c_str(), message->text.c_str());
         ResetColor(stdout_stream);
     }
     else
-        utf8printf(stdout_stream ? stdout : stderr, "%s%s", message.prefix.c_str(), message.text.c_str());
+        utf8printf(stdout_stream ? stdout : stderr, "%s%s\n", message->prefix.c_str(), message->text.c_str());
 }
diff --git a/src/server/shared/Logging/AppenderConsole.h b/src/server/shared/Logging/AppenderConsole.h
index 0f9536b3111..0acf7636e35 100644
--- a/src/server/shared/Logging/AppenderConsole.h
+++ b/src/server/shared/Logging/AppenderConsole.h
@@ -51,7 +51,7 @@ class AppenderConsole: public Appender
     private:
         void SetColor(bool stdout_stream, ColorTypes color);
         void ResetColor(bool stdout_stream);
-        void _write(LogMessage const& message) override;
+        void _write(LogMessage const* message) override;
         bool _colored;
         ColorTypes _colors[MaxLogLevels];
 };
diff --git a/src/server/shared/Logging/AppenderDB.cpp b/src/server/shared/Logging/AppenderDB.cpp
index 99ae822af34..8a329ea3a0f 100644
--- a/src/server/shared/Logging/AppenderDB.cpp
+++ b/src/server/shared/Logging/AppenderDB.cpp
@@ -23,18 +23,18 @@ AppenderDB::AppenderDB(uint8 id, std::string const& name, LogLevel level)
 
 AppenderDB::~AppenderDB() { }
 
-void AppenderDB::_write(LogMessage const& message)
+void AppenderDB::_write(LogMessage const* message)
 {
     // Avoid infinite loop, PExecute triggers Logging with "sql.sql" type
-    if (!enabled || (message.type.find("sql") != std::string::npos))
+    if (!enabled || (message->type.find("sql") != std::string::npos))
         return;
 
     PreparedStatement* stmt = LoginDatabase.GetPreparedStatement(LOGIN_INS_LOG);
-    stmt->setUInt64(0, message.mtime);
+    stmt->setUInt64(0, message->mtime);
     stmt->setUInt32(1, realmId);
-    stmt->setString(2, message.type);
-    stmt->setUInt8(3, uint8(message.level));
-    stmt->setString(4, message.text);
+    stmt->setString(2, message->type);
+    stmt->setUInt8(3, uint8(message->level));
+    stmt->setString(4, message->text);
     LoginDatabase.Execute(stmt);
 }
 
diff --git a/src/server/shared/Logging/AppenderDB.h b/src/server/shared/Logging/AppenderDB.h
index e20ceaf77b4..09affdb46f1 100644
--- a/src/server/shared/Logging/AppenderDB.h
+++ b/src/server/shared/Logging/AppenderDB.h
@@ -31,7 +31,7 @@ class AppenderDB: public Appender
     private:
         uint32 realmId;
         bool enabled;
-        void _write(LogMessage const& message) override;
+        void _write(LogMessage const* message) override;
 };
 
 #endif
diff --git a/src/server/shared/Logging/AppenderFile.cpp b/src/server/shared/Logging/AppenderFile.cpp
index 07a88a367ae..3892adbe3be 100644
--- a/src/server/shared/Logging/AppenderFile.cpp
+++ b/src/server/shared/Logging/AppenderFile.cpp
@@ -43,21 +43,21 @@ AppenderFile::~AppenderFile()
     CloseFile();
 }
 
-void AppenderFile::_write(LogMessage const& message)
+void AppenderFile::_write(LogMessage const* message)
 {
-    bool exceedMaxSize = maxFileSize > 0 && (fileSize.load() + message.Size()) > maxFileSize;
+    bool exceedMaxSize = maxFileSize > 0 && (fileSize.load() + message->Size()) > maxFileSize;
 
     if (dynamicName)
     {
         char namebuf[TRINITY_PATH_MAX];
-        snprintf(namebuf, TRINITY_PATH_MAX, filename.c_str(), message.param1.c_str());
+        snprintf(namebuf, TRINITY_PATH_MAX, filename.c_str(), message->param1.c_str());
         // always use "a" with dynamic name otherwise it could delete the log we wrote in last _write() call
         FILE* file = OpenFile(namebuf, "a", backup || exceedMaxSize);
         if (!file)
             return;
-        fprintf(file, "%s%s", message.prefix.c_str(), message.text.c_str());
+        fprintf(file, "%s%s", message->prefix.c_str(), message->text.c_str());
         fflush(file);
-        fileSize += uint64(message.Size());
+        fileSize += uint64(message->Size());
         fclose(file);
         return;
     }
@@ -67,9 +67,9 @@ void AppenderFile::_write(LogMessage const& message)
     if (!logfile)
         return;
 
-    fprintf(logfile, "%s%s", message.prefix.c_str(), message.text.c_str());
+    fprintf(logfile, "%s%s\n", message->prefix.c_str(), message->text.c_str());
     fflush(logfile);
-    fileSize += uint64(message.Size());
+    fileSize += uint64(message->Size());
 }
 
 FILE* AppenderFile::OpenFile(std::string const &filename, std::string const &mode, bool backup)
diff --git a/src/server/shared/Logging/AppenderFile.h b/src/server/shared/Logging/AppenderFile.h
index 23651fc1129..36afdd23ad1 100644
--- a/src/server/shared/Logging/AppenderFile.h
+++ b/src/server/shared/Logging/AppenderFile.h
@@ -30,7 +30,7 @@ class AppenderFile: public Appender
 
     private:
         void CloseFile();
-        void _write(LogMessage const& message) override;
+        void _write(LogMessage const* message) override;
         FILE* logfile;
         std::string filename;
         std::string logDir;
diff --git a/src/server/shared/Logging/Log.cpp b/src/server/shared/Logging/Log.cpp
index aa432128171..861140d104f 100644
--- a/src/server/shared/Logging/Log.cpp
+++ b/src/server/shared/Logging/Log.cpp
@@ -261,30 +261,18 @@ void Log::ReadLoggersFromConfig()
     }
 }
 
-void Log::vlog(std::string const& filter, LogLevel level, char const* str, va_list argptr)
-{
-    char text[MAX_QUERY_LEN];
-    vsnprintf(text, MAX_QUERY_LEN, str, argptr);
-    write(new LogMessage(level, filter, text));
-}
-
-void Log::write(LogMessage* msg) const
+void Log::write(std::unique_ptr<LogMessage>&& msg) const
 {
     Logger const* logger = GetLoggerByType(msg->type);
-    msg->text.append("\n");
 
     if (_ioService)
     {
-        auto logOperation = std::shared_ptr<LogOperation>(new LogOperation(logger, msg));
+        auto logOperation = std::shared_ptr<LogOperation>(new LogOperation(logger, std::forward<std::unique_ptr<LogMessage>>(msg)));
 
         _ioService->post(_strand->wrap([logOperation](){ logOperation->call(); }));
-
     }
     else
-    {
-        logger->write(*msg);
-        delete msg;
-    }
+        logger->write(msg.get());
 }
 
 std::string Log::GetTimestampStr()
@@ -343,33 +331,13 @@ void Log::outCharDump(char const* str, uint32 accountId, uint64 guid, char const
     ss << "== START DUMP == (account: " << accountId << " guid: " << guid << " name: " << name
        << ")\n" << str << "\n== END DUMP ==\n";
 
-    LogMessage* msg = new LogMessage(LOG_LEVEL_INFO, "entities.player.dump", ss.str());
+    std::unique_ptr<LogMessage> msg(new LogMessage(LOG_LEVEL_INFO, "entities.player.dump", ss.str()));
     std::ostringstream param;
     param << guid << '_' << name;
 
     msg->param1 = param.str();
 
-    write(msg);
-}
-
-void Log::outCommand(uint32 account, const char * str, ...)
-{
-    if (!str || !ShouldLog("commands.gm", LOG_LEVEL_INFO))
-        return;
-
-    va_list ap;
-    va_start(ap, str);
-    char text[MAX_QUERY_LEN];
-    vsnprintf(text, MAX_QUERY_LEN, str, ap);
-    va_end(ap);
-
-    LogMessage* msg = new LogMessage(LOG_LEVEL_INFO, "commands.gm", text);
-
-    std::ostringstream ss;
-    ss << account;
-    msg->param1 = ss.str();
-
-    write(msg);
+    write(std::move(msg));
 }
 
 void Log::SetRealmId(uint32 id)
diff --git a/src/server/shared/Logging/Log.h b/src/server/shared/Logging/Log.h
index 1d67ff87f76..0a14da74a50 100644
--- a/src/server/shared/Logging/Log.h
+++ b/src/server/shared/Logging/Log.h
@@ -22,12 +22,13 @@
 #include "Define.h"
 #include "Appender.h"
 #include "Logger.h"
-#include <stdarg.h>
+#include "StringFormat.h"
 #include <boost/asio/io_service.hpp>
 #include <boost/asio/strand.hpp>
 
 #include <unordered_map>
 #include <string>
+#include <memory>
 
 #define LOGGER_ROOT "root"
 
@@ -59,17 +60,34 @@ class Log
         bool ShouldLog(std::string const& type, LogLevel level) const;
         bool SetLogLevel(std::string const& name, char const* level, bool isLogger = true);
 
-        void outMessage(std::string const& f, LogLevel level, char const* str, ...) ATTR_PRINTF(4, 5);
+        template<typename... Args>
+        inline void outMessage(std::string const& filter, LogLevel const level, const char* fmt, Args const&... args)
+        {
+            write(std::move(std::unique_ptr<LogMessage>(new LogMessage(level, filter, std::move(Trinity::StringFormat(fmt, args...))))));
+        }
+
+        template<typename... Args>
+        void outCommand(uint32 account, const char* fmt, Args const&... args)
+        {
+            if (!ShouldLog("commands.gm", LOG_LEVEL_INFO))
+                return;
+
+            std::unique_ptr<LogMessage> msg(new LogMessage(LOG_LEVEL_INFO, "commands.gm", std::move(Trinity::StringFormat(fmt, args...))));
+
+            std::ostringstream ss;
+            ss << account;
+            msg->param1 = ss.str();
+
+            write(std::move(msg));
+        }
 
-        void outCommand(uint32 account, const char * str, ...) ATTR_PRINTF(3, 4);
         void outCharDump(char const* str, uint32 account_id, uint64 guid, char const* name);
 
         void SetRealmId(uint32 id);
 
     private:
         static std::string GetTimestampStr();
-        void vlog(std::string const& f, LogLevel level, char const* str, va_list argptr);
-        void write(LogMessage* msg) const;
+        void write(std::unique_ptr<LogMessage>&& msg) const;
 
         Logger const* GetLoggerByType(std::string const& type) const;
         Appender* GetAppenderByName(std::string const& name);
@@ -121,23 +139,34 @@ inline bool Log::ShouldLog(std::string const& type, LogLevel level) const
     return logLevel != LOG_LEVEL_DISABLED && logLevel <= level;
 }
 
-inline void Log::outMessage(std::string const& filter, LogLevel level, const char * str, ...)
-{
-    va_list ap;
-    va_start(ap, str);
-
-    vlog(filter, level, str, ap);
-
-    va_end(ap);
-}
-
 #define sLog Log::instance()
 
+#define LOG_EXCEPTION_FREE(filterType__, level__, ...) \
+    { \
+        try \
+        { \
+            sLog->outMessage(filterType__, level__, __VA_ARGS__); \
+        } \
+        catch (std::exception& e) \
+        { \
+            sLog->outMessage("server", LOG_LEVEL_ERROR, "Wrong format occurred (%s) at %s:%u.", \
+                e.what(), __FILE__, __LINE__); \
+        } \
+    }
+
 #if PLATFORM != PLATFORM_WINDOWS
+void check_args(const char* format, ...) ATTR_PRINTF(1, 2);
+
+// This will catch format errors on build time
 #define TC_LOG_MESSAGE_BODY(filterType__, level__, ...)                 \
         do {                                                            \
             if (sLog->ShouldLog(filterType__, level__))                 \
-                sLog->outMessage(filterType__, level__, __VA_ARGS__);   \
+            {                                                           \
+                if (false)                                              \
+                    check_args(__VA_ARGS__);                            \
+                                                                        \
+                LOG_EXCEPTION_FREE(filterType__, level__, __VA_ARGS__); \
+            }                                                           \
         } while (0)
 #else
 #define TC_LOG_MESSAGE_BODY(filterType__, level__, ...)                 \
@@ -145,7 +174,7 @@ inline void Log::outMessage(std::string const& filter, LogLevel level, const cha
         __pragma(warning(disable:4127))                                 \
         do {                                                            \
             if (sLog->ShouldLog(filterType__, level__))                 \
-                sLog->outMessage(filterType__, level__, __VA_ARGS__);   \
+                LOG_EXCEPTION_FREE(filterType__, level__, __VA_ARGS__); \
         } while (0)                                                     \
         __pragma(warning(pop))
 #endif
diff --git a/src/server/shared/Logging/LogOperation.cpp b/src/server/shared/Logging/LogOperation.cpp
index 9afb28a49c2..bcd923c705e 100644
--- a/src/server/shared/Logging/LogOperation.cpp
+++ b/src/server/shared/Logging/LogOperation.cpp
@@ -18,14 +18,8 @@
 #include "LogOperation.h"
 #include "Logger.h"
 
-LogOperation::~LogOperation()
-{
-    delete msg;
-}
-
 int LogOperation::call()
 {
-    if (logger && msg)
-        logger->write(*msg);
+    logger->write(msg.get());
     return 0;
 }
diff --git a/src/server/shared/Logging/LogOperation.h b/src/server/shared/Logging/LogOperation.h
index b8655413273..ffdd35c3c09 100644
--- a/src/server/shared/Logging/LogOperation.h
+++ b/src/server/shared/Logging/LogOperation.h
@@ -18,23 +18,25 @@
 #ifndef LOGOPERATION_H
 #define LOGOPERATION_H
 
+#include <memory>
+
 class Logger;
 struct LogMessage;
 
 class LogOperation
 {
     public:
-        LogOperation(Logger const* _logger, LogMessage* _msg)
-            : logger(_logger), msg(_msg)
+        LogOperation(Logger const* _logger, std::unique_ptr<LogMessage>&& _msg)
+            : logger(_logger), msg(std::forward<std::unique_ptr<LogMessage>>(_msg))
         { }
 
-        ~LogOperation();
+        ~LogOperation() { }
 
         int call();
 
     protected:
         Logger const* logger;
-        LogMessage* msg;
+        std::unique_ptr<LogMessage> msg;
 };
 
 #endif
diff --git a/src/server/shared/Logging/Logger.cpp b/src/server/shared/Logging/Logger.cpp
index 615732deb30..3b02eb47575 100644
--- a/src/server/shared/Logging/Logger.cpp
+++ b/src/server/shared/Logging/Logger.cpp
@@ -50,9 +50,9 @@ void Logger::setLogLevel(LogLevel _level)
     level = _level;
 }
 
-void Logger::write(LogMessage& message) const
+void Logger::write(LogMessage* message) const
 {
-    if (!level || level > message.level || message.text.empty())
+    if (!level || level > message->level || message->text.empty())
     {
         //fprintf(stderr, "Logger::write: Logger %s, Level %u. Msg %s Level %u WRONG LEVEL MASK OR EMPTY MSG\n", getName().c_str(), getLogLevel(), message.text.c_str(), message.level);
         return;
diff --git a/src/server/shared/Logging/Logger.h b/src/server/shared/Logging/Logger.h
index a81ee8d7bd2..1aee75c5d72 100644
--- a/src/server/shared/Logging/Logger.h
+++ b/src/server/shared/Logging/Logger.h
@@ -32,7 +32,7 @@ class Logger
         std::string const& getName() const;
         LogLevel getLogLevel() const;
         void setLogLevel(LogLevel level);
-        void write(LogMessage& message) const;
+        void write(LogMessage* message) const;
 
     private:
         std::string name;