Merge branch 'logging' into 'master'

Add time to logs. Redirect OSG log to OpenMW log.

See merge request OpenMW/openmw!436

apps/openmw/main.cpp

@@ -223,6 +223,42 @@ bool parseOptions (int argc, char** argv, OMW::Engine& engine, Files::Configurat
     return true;
 }
 
+namespace
+{
+    class OSGLogHandler : public osg::NotifyHandler
+    {
+        void notify(osg::NotifySeverity severity, const char* msg) override
+        {
+            // Copy, because osg logging is not thread safe.
+            std::string msgCopy(msg);
+            if (msgCopy.empty())
+                return;
+
+            Debug::Level level;
+            switch (severity)
+            {
+            case osg::ALWAYS:
+            case osg::FATAL:
+                level = Debug::Error;
+                break;
+            case osg::WARN:
+            case osg::NOTICE:
+                level = Debug::Warning;
+                break;
+            case osg::INFO:
+                level = Debug::Info;
+                break;
+            case osg::DEBUG_INFO:
+            case osg::DEBUG_FP:
+            default:
+                level = Debug::Debug;
+            }
+            std::string_view s(msgCopy);
+            Log(level) << (s.back() == '\n' ? s.substr(0, s.size() - 1) : s);
+        }
+    };
+}
+
 int runApplication(int argc, char *argv[])
 {
 #ifdef __APPLE__
@@ -231,6 +267,7 @@ int runApplication(int argc, char *argv[])
     setenv("OSG_GL_TEXTURE_STORAGE", "OFF", 0);
 #endif
 
+    osg::setNotifyHandler(new OSGLogHandler());
     Files::ConfigurationManager cfgMgr;
     std::unique_ptr<OMW::Engine> engine;
     engine.reset(new OMW::Engine(cfgMgr));

components/debug/debugging.cpp

@@ -1,5 +1,7 @@
 #include "debugging.hpp"
 
+#include <chrono>
+
 #include <components/crashcatcher/crashcatcher.hpp>
 
 #ifdef _WIN32
@@ -60,15 +62,40 @@ namespace Debug
 
     std::streamsize DebugOutputBase::write(const char *str, std::streamsize size)
     {
+        if (size <= 0)
+            return size;
+        std::string_view msg{str, size_t(size)};
+
         // Skip debug level marker
         Level level = getLevelMarker(str);
         if (level != NoLevel)
+            msg = msg.substr(1);
+
+        char prefix[32];
+        int prefixSize;
         {
-            writeImpl(str+1, size-1, level);
+            prefix[0] = '[';
-            return size;
+            uint64_t ms = std::chrono::duration_cast<std::chrono::milliseconds>(
+                std::chrono::high_resolution_clock::now().time_since_epoch()).count();
+            std::time_t t = ms / 1000;
+            prefixSize = std::strftime(prefix + 1, sizeof(prefix) - 1, "%T", std::localtime(&t)) + 1;
+            char levelLetter = " EWIVD*"[int(level)];
+            prefixSize += snprintf(prefix + prefixSize, sizeof(prefix) - prefixSize,
+                                   ".%03u %c] ", static_cast<unsigned>(ms % 1000), levelLetter);
+        }
+
+        while (!msg.empty())
+        {
+            if (msg[0] == 0)
+                break;
+            size_t lineSize = 1;
+            while (lineSize < msg.size() && msg[lineSize - 1] != '\n')
+                lineSize++;
+            writeImpl(prefix, prefixSize, level);
+            writeImpl(msg.data(), lineSize, level);
+            msg = msg.substr(lineSize);
         }
 
-        writeImpl(str, size, NoLevel);
         return size;
     }
 
@@ -172,6 +199,7 @@ int wrapApplication(int (*innerApplication)(int argc, char *argv[]), int argc, c
     // Restore cout and cerr
     std::cout.rdbuf(cout_rdbuf);
     std::cerr.rdbuf(cerr_rdbuf);
+    Debug::CurrentDebugLevel = Debug::NoLevel;
 
     return ret;
 }