Implement advanced logging system (feature #4581)

CHANGELOG.md

@@ -103,6 +103,7 @@
     Feature #4548: Weapon priority: use the actual chance to hit the target instead of weapon skill
     Feature #4549: Weapon priority: use the actual damage in weapon rating calculations
     Feature #4550: Weapon priority: make ranged weapon bonus more sensible
+    Feature #4581: Use proper logging system
     Task #2490: Don't open command prompt window on Release-mode builds automatically
     Task #4545: Enable is_pod string test
 

apps/opencs/main.cpp

@@ -8,7 +8,7 @@
 #include <QIcon>
 #include <QMetaType>
 
-#include <components/misc/debugging.hpp>
+#include <components/debug/debugging.hpp>
 
 #include "model/doc/messages.hpp"
 #include "model/world/universalid.hpp"
@@ -80,5 +80,5 @@ int runApplication(int argc, char *argv[])
 
 int main(int argc, char *argv[])
 {
-    return wrapApplication(&runApplication, argc, argv, "/openmw-cs.log");
+    return wrapApplication(&runApplication, argc, argv, "OpenMW-CS");
 }

apps/openmw/main.cpp

@@ -5,7 +5,7 @@
 #include <components/files/configurationmanager.hpp>
 #include <components/files/escape.hpp>
 #include <components/fallback/validate.hpp>
-#include <components/misc/debugging.hpp>
+#include <components/debug/debugging.hpp>
 
 #include "engine.hpp"
 
@@ -265,7 +265,7 @@ extern "C" int SDL_main(int argc, char**argv)
 int main(int argc, char**argv)
 #endif
 {
-    return wrapApplication(&runApplication, argc, argv, "/openmw.log");
+    return wrapApplication(&runApplication, argc, argv, "OpenMW");
 }
 
 // Platform specific for Windows when there is no console built into the executable.

components/CMakeLists.txt

@@ -85,7 +85,11 @@ add_component_dir (esmterrain
     )
 
 add_component_dir (misc
-    utf8stream stringops resourcehelpers rng debugging messageformatparser
+    utf8stream stringops resourcehelpers rng messageformatparser
+    )
+
+add_component_dir (debug
+    debugging debuglog
     )
 
 IF(NOT WIN32 AND NOT APPLE)

components/debug/debugging.cpp

@@ -0,0 +1,103 @@
+#include "debugging.hpp"
+
+namespace Debug
+{
+    std::streamsize DebugOutputBase::write(const char *str, std::streamsize size)
+    {
+        // Skip debug level marker
+        Level level = getLevelMarker(str);
+        if (level != NoLevel)
+        {
+            writeImpl(str+1, size-1, level);
+            return size;
+        }
+
+        writeImpl(str, size, NoLevel);
+        return size;
+    }
+
+    Level DebugOutputBase::getLevelMarker(const char *str)
+    {
+        if (unsigned(*str) <= unsigned(Marker))
+        {
+            return Level(*str);
+        }
+
+        return NoLevel;
+    }
+
+    void DebugOutputBase::fillCurrentDebugLevel()
+    {
+        const char* env = getenv("OPENMW_DEBUG_LEVEL");
+        if (env)
+        {
+            std::string value(env);
+            if (value == "ERROR")
+                CurrentDebugLevel = Error;
+            else if (value == "WARNING")
+                CurrentDebugLevel = Warning;
+            else if (value == "INFO")
+                CurrentDebugLevel = Info;
+            else if (value == "VERBOSE")
+                CurrentDebugLevel = Verbose;
+
+            return;
+        }
+
+        CurrentDebugLevel = Verbose;
+    }
+}
+
+int wrapApplication(int (*innerApplication)(int argc, char *argv[]), int argc, char *argv[], const std::string& appName)
+{
+    // Some objects used to redirect cout and cerr
+    // Scope must be here, so this still works inside the catch block for logging exceptions
+    std::streambuf* cout_rdbuf = std::cout.rdbuf ();
+    std::streambuf* cerr_rdbuf = std::cerr.rdbuf ();
+
+    int ret = 0;
+    try
+    {
+        Files::ConfigurationManager cfgMgr;
+#if defined(_WIN32) && defined(_DEBUG)
+        // Redirect cout and cerr to VS debug output when running in debug mode
+        boost::iostreams::stream_buffer<Debug::DebugOutput> sb;
+        sb.open(Debug::DebugOutput());
+        std::cout.rdbuf (&sb);
+        std::cerr.rdbuf (&sb);
+#else
+        // Redirect cout and cerr to the log file
+        const std::string logName = Misc::StringUtils::lowerCase(appName) + ".log";
+        boost::filesystem::ofstream logfile;
+        logfile.open (boost::filesystem::path(cfgMgr.getLogPath() / logName));
+
+        boost::iostreams::stream_buffer<Debug::Tee> coutsb;
+        boost::iostreams::stream_buffer<Debug::Tee> cerrsb;
+        std::ostream oldcout(cout_rdbuf);
+        std::ostream oldcerr(cerr_rdbuf);
+        coutsb.open (Debug::Tee(logfile, oldcout));
+        cerrsb.open (Debug::Tee(logfile, oldcerr));
+
+        std::cout.rdbuf (&coutsb);
+        std::cerr.rdbuf (&cerrsb);
+#endif
+        ret = innerApplication(argc, argv);
+    }
+    catch (std::exception& e)
+    {
+#if (defined(__APPLE__) || defined(__linux) || defined(__unix) || defined(__posix))
+        if (!isatty(fileno(stdin)))
+#endif
+            SDL_ShowSimpleMessageBox(0, (appName + ": Fatal error").c_str(), e.what(), NULL);
+
+        Log(Debug::Error) << "ERROR: " << e.what();
+
+        ret = 1;
+    }
+
+    // Restore cout and cerr
+    std::cout.rdbuf(cout_rdbuf);
+    std::cerr.rdbuf(cerr_rdbuf);
+
+    return ret;
+}

components/debug/debugging.hpp

@@ -0,0 +1,129 @@
+#ifndef DEBUG_DEBUGGING_H
+#define DEBUG_DEBUGGING_H
+
+#include <boost/filesystem/fstream.hpp>
+#include <boost/iostreams/stream.hpp>
+
+#include <components/files/configurationmanager.hpp>
+
+#include <SDL_messagebox.h>
+
+#include "debuglog.hpp"
+
+namespace Debug
+{
+    // ANSI colors for terminal
+    enum Color
+    {
+        Reset = 0,
+        DarkGray = 90,
+        Red = 91,
+        Yellow = 93
+    };
+
+    class DebugOutputBase : public boost::iostreams::sink
+    {
+    public:
+        DebugOutputBase()
+        {
+            if (CurrentDebugLevel == NoLevel)
+                fillCurrentDebugLevel();
+        }
+
+        virtual std::streamsize write(const char *str, std::streamsize size);
+
+    protected:
+        static Level getLevelMarker(const char *str);
+
+        static void fillCurrentDebugLevel();
+
+        virtual std::streamsize writeImpl(const char *str, std::streamsize size, Level debugLevel)
+        {
+            return size;
+        }
+
+        char mDebugLevel;
+    };
+
+#if defined(_WIN32) && defined(_DEBUG)
+    class DebugOutput : public DebugOutputBase
+    {
+    public:
+        std::streamsize writeImpl(const char *str, std::streamsize size, Level debugLevel)
+        {
+            // Make a copy for null termination
+            std::string tmp (str, static_cast<unsigned int>(size));
+            // Write string to Visual Studio Debug output
+            OutputDebugString (tmp.c_str ());
+            return size;
+        }
+
+        virtual ~DebugOutput() {}
+    };
+#else
+
+    class Tee : public DebugOutputBase
+    {
+    public:
+        Tee(std::ostream &stream, std::ostream &stream2)
+            : out(stream), out2(stream2)
+        {
+            // TODO: check which stream is stderr?
+            mUseColor = useColoredOutput();
+
+            mColors[Error] = Red;
+            mColors[Warning] = Yellow;
+            mColors[Info] = Reset;
+            mColors[Verbose] = DarkGray;
+            mColors[NoLevel] = Reset;
+        }
+
+        virtual std::streamsize writeImpl(const char *str, std::streamsize size, Level debugLevel)
+        {
+            out.write (str, size);
+            out.flush();
+
+            if(mUseColor)
+            {
+                out2 << "\033[0;" << mColors[debugLevel] << "m";
+                out2.write (str, size);
+                out2 << "\033[0;" << Reset << "m";
+            }
+            else
+            {
+                out2.write(str, size);
+            }
+            out2.flush();
+
+            return size;
+        }
+
+        virtual ~Tee() {}
+
+    private:
+
+        static bool useColoredOutput()
+        {
+    // Note: cmd.exe in Win10 should support ANSI colors, but in its own way.
+#if defined(_WIN32)
+            return 0;
+#else
+            char *term = getenv("TERM");
+            bool useColor = term && !getenv("NO_COLOR") && isatty(fileno(stderr));
+
+            return useColor;
+#endif
+        }
+
+        std::ostream &out;
+        std::ostream &out2;
+        bool mUseColor;
+
+        std::map<Level, int> mColors;
+    };
+#endif
+}
+
+int wrapApplication(int (*innerApplication)(int argc, char *argv[]), int argc, char *argv[], const std::string& appName);
+
+#endif

components/debug/debuglog.cpp

@@ -0,0 +1,8 @@
+#include "debuglog.hpp"
+
+namespace Debug
+{
+    Level CurrentDebugLevel = Level::NoLevel;
+}
+
+std::mutex Log::sLock;

components/debug/debuglog.hpp

@@ -0,0 +1,66 @@
+#ifndef DEBUG_LOG_H
+#define DEBUG_LOG_H
+
+#include <mutex>
+#include <sstream>
+#include <iostream>
+
+namespace Debug
+{
+    enum Level
+    {
+        NoLevel = 0,
+        Error = 1,
+        Warning = 2,
+        Info = 3,
+        Verbose = 4,
+        Marker = Verbose
+    };
+
+    extern Level CurrentDebugLevel;
+}
+
+class Log
+{
+    static std::mutex sLock;
+
+    std::unique_lock<std::mutex> mLock;
+public:
+    // Locks a global lock while the object is alive
+    Log(Debug::Level level) :
+    mLock(sLock),
+    mLevel(level)
+    {
+        if (mLevel <= Debug::CurrentDebugLevel)
+            std::cout << static_cast<unsigned char>(mLevel);
+    }
+
+    // Perfect forwarding wrappers to give the chain of objects to cout
+    template<typename T>
+    Log& operator<<(T&& rhs)
+    {
+        if (mLevel <= Debug::CurrentDebugLevel)
+            std::cout << std::forward<T>(rhs);
+
+        return *this;
+    }
+    template<typename T>
+    Log& operator<<(const T& rhs)
+    {
+        if (mLevel <= Debug::CurrentDebugLevel)
+            std::cout << std::forward<const T&>(rhs);
+
+        return *this;
+    }
+
+    ~Log()
+    {
+        if (mLevel <= Debug::CurrentDebugLevel)
+            std::cout << std::endl;
+    }
+
+private:
+    Debug::Level mLevel;
+};
+
+#endif

components/misc/debugging.hpp

@@ -1,108 +0,0 @@
-#ifndef MISC_DEBUGGING_H
-#define MISC_DEBUGGING_H
-
-#include <boost/filesystem/fstream.hpp>
-#include <boost/iostreams/stream.hpp>
-
-#include <SDL_messagebox.h>
-
-namespace Misc
-{
-#if defined(_WIN32) && defined(_DEBUG)
-
-    class DebugOutput : public boost::iostreams::sink
-    {
-    public:
-        std::streamsize write(const char *str, std::streamsize size)
-        {
-            // Make a copy for null termination
-            std::string tmp (str, static_cast<unsigned int>(size));
-            // Write string to Visual Studio Debug output
-            OutputDebugString (tmp.c_str ());
-            return size;
-        }
-    };
-#else
-    class Tee : public boost::iostreams::sink
-    {
-    public:
-        Tee(std::ostream &stream, std::ostream &stream2)
-            : out(stream), out2(stream2)
-        {
-        }
-
-        std::streamsize write(const char *str, std::streamsize size)
-        {
-            out.write (str, size);
-            out.flush();
-            out2.write (str, size);
-            out2.flush();
-            return size;
-        }
-
-    private:
-        std::ostream &out;
-        std::ostream &out2;
-    };
-#endif
-}
-
-int wrapApplication(int (*innerApplication)(int argc, char *argv[]), int argc, char *argv[], const std::string& logName)
-{
-    // Some objects used to redirect cout and cerr
-    // Scope must be here, so this still works inside the catch block for logging exceptions
-    std::streambuf* cout_rdbuf = std::cout.rdbuf ();
-    std::streambuf* cerr_rdbuf = std::cerr.rdbuf ();
-
-#if !(defined(_WIN32) && defined(_DEBUG))
-    boost::iostreams::stream_buffer<Misc::Tee> coutsb;
-    boost::iostreams::stream_buffer<Misc::Tee> cerrsb;
-#endif
-
-    std::ostream oldcout(cout_rdbuf);
-    std::ostream oldcerr(cerr_rdbuf);
-
-    boost::filesystem::ofstream logfile;
-
-    int ret = 0;
-    try
-    {
-        Files::ConfigurationManager cfgMgr;
-#if defined(_WIN32) && defined(_DEBUG)
-        // Redirect cout and cerr to VS debug output when running in debug mode
-        boost::iostreams::stream_buffer<Misc::DebugOutput> sb;
-        sb.open(Misc::DebugOutput());
-        std::cout.rdbuf (&sb);
-        std::cerr.rdbuf (&sb);
-#else
-        // Redirect cout and cerr to the log file
-        logfile.open (boost::filesystem::path(cfgMgr.getLogPath() / logName));
-
-        coutsb.open (Misc::Tee(logfile, oldcout));
-        cerrsb.open (Misc::Tee(logfile, oldcerr));
-
-        std::cout.rdbuf (&coutsb);
-        std::cerr.rdbuf (&cerrsb);
-#endif
-        ret = innerApplication(argc, argv);
-    }
-    catch (std::exception& e)
-    {
-#if (defined(__APPLE__) || defined(__linux) || defined(__unix) || defined(__posix))
-        if (!isatty(fileno(stdin)))
-#endif
-            SDL_ShowSimpleMessageBox(0, "OpenMW: Fatal error", e.what(), NULL);
-
-        std::cerr << "\nERROR: " << e.what() << std::endl;
-
-        ret = 1;
-    }
-
-    // Restore cout and cerr
-    std::cout.rdbuf(cout_rdbuf);
-    std::cerr.rdbuf(cerr_rdbuf);
-
-    return ret;
-}
-
-#endif

components/nifosg/nifloader.cpp

@@ -9,6 +9,7 @@
 #include <osg/ValueObject>
 
 // resource
+#include <components/debug/debuglog.hpp>
 #include <components/misc/stringops.hpp>
 #include <components/misc/resourcehelpers.hpp>
 #include <components/resource/imagemanager.hpp>
@@ -992,7 +993,7 @@ namespace NifOsg
                 int uvSet = *it;
                 if (uvSet >= (int)data->uvlist.size())
                 {
-                    std::cerr << "Warning: out of bounds UV set " << uvSet << " on TriShape \"" << triShape->name << "\" in " << mFilename << std::endl;
+                    Log(Debug::Verbose) << "Out of bounds UV set " << uvSet << " on TriShape \"" << triShape->name << "\" in " << mFilename;
                     if (!data->uvlist.empty())
                         geometry->setTexCoordArray(textureStage, new osg::Vec2Array(data->uvlist[0].size(), &data->uvlist[0][0]), osg::Array::BIND_PER_VERTEX);
                     continue;
@@ -1279,7 +1280,7 @@ namespace NifOsg
                     const Nif::NiTexturingProperty::Texture& tex = texprop->textures[i];
                     if(tex.texture.empty() && texprop->controller.empty())
                     {
-                        std::cerr << "Warning: texture layer " << i << " is in use but empty in " << mFilename << std::endl;
+                        Log(Debug::Verbose) << "Texture layer " << i << " is in use but empty in " << mFilename;
                         continue;
                     }