From 1cbb349e05a25d84bc2b006555aae82cff317e67 Mon Sep 17 00:00:00 2001
From: maelstrom <maelstrom@maelstrom.dev>
Date: Fri, 23 May 2025 00:59:31 +0200
Subject: [PATCH] feat(logging): better error logging with stack trace in lua

---
 core/src/logger.cpp                       | 17 ++++++++++++
 core/src/logger.h                         |  9 +++++-
 core/src/objects/base/instance.cpp        | 13 +++++++++
 core/src/objects/base/instance.h          |  1 +
 core/src/objects/script.cpp               | 34 +++++++++++++++++++++--
 core/src/objects/script/scriptcontext.cpp | 14 ++++++++--
 core/src/objects/script/scriptcontext.h   |  7 +++++
 editor/mainwindow.cpp                     |  8 ++++++
 editor/mainwindow.h                       |  1 +
 9 files changed, 98 insertions(+), 6 deletions(-)

diff --git a/core/src/logger.cpp b/core/src/logger.cpp
index 8af1379..d5ab497 100644
--- a/core/src/logger.cpp
+++ b/core/src/logger.cpp
@@ -4,10 +4,12 @@
 #include <fstream>
 #include <chrono>
 #include <format>
+#include <string>
 #include <vector>
 
 static std::ofstream logStream;
 static std::vector<Logger::LogListener> logListeners;
+static std::vector<Logger::TraceLogListener> traceLogListeners;
 std::string Logger::currentLogDir = "NULL";
 
 void Logger::init() {
@@ -29,6 +31,7 @@ void Logger::finish() {
 void Logger::log(std::string message, Logger::LogLevel logLevel) {
     std::string logLevelStr = logLevel == Logger::LogLevel::INFO ? "INFO" : 
         logLevel == Logger::LogLevel::DEBUG ? "DEBUG" :
+        logLevel == Logger::LogLevel::TRACE ? "TRACE" :
         logLevel == Logger::LogLevel::WARNING ? "WARN" :
         logLevel == Logger::LogLevel::ERROR ? "ERROR" :
         logLevel == Logger::LogLevel::FATAL_ERROR ? "FATAL" : "?";
@@ -49,6 +52,20 @@ void Logger::log(std::string message, Logger::LogLevel logLevel) {
     }
 }
 
+void Logger::trace(std::string source, int line, void* userData) {
+    std::string message = "'" + source + "' Line " + std::to_string(line);
+
+    log(message, Logger::LogLevel::TRACE);
+
+    for (Logger::TraceLogListener listener : traceLogListeners) {
+        listener(message, source, line, userData);
+    }
+}
+
 void Logger::addLogListener(Logger::LogListener listener) {
     logListeners.push_back(listener);
+}
+
+void Logger::addLogListener(Logger::TraceLogListener listener) {
+    traceLogListeners.push_back(listener);
 }
\ No newline at end of file
diff --git a/core/src/logger.h b/core/src/logger.h
index 8f9792b..f0b098e 100644
--- a/core/src/logger.h
+++ b/core/src/logger.h
@@ -8,18 +8,21 @@ namespace Logger {
     enum class LogLevel {
         INFO,
         DEBUG,
+        TRACE,
         WARNING,
         ERROR,
         FATAL_ERROR,
     };
 
-    typedef std::function<void(LogLevel logLeve, std::string message)> LogListener;
+    typedef std::function<void(LogLevel logLevel, std::string message)> LogListener;
+    typedef std::function<void(std::string message, std::string source, int line, void* userData)> TraceLogListener;
 
     extern std::string currentLogDir;
 
     void init();
     void finish();
     void addLogListener(LogListener);
+    void addLogListener(TraceLogListener);
 
     void log(std::string message, LogLevel logLevel);
     inline void info(std::string message) { log(message, LogLevel::INFO); }
@@ -28,6 +31,10 @@ namespace Logger {
     inline void error(std::string message) { log(message, LogLevel::ERROR); }
     inline void fatalError(std::string message) { log(message, LogLevel::FATAL_ERROR); }
 
+    inline void traceStart() { log("Stack start", LogLevel::TRACE); }
+    inline void traceEnd() { log("Stack end", LogLevel::TRACE); }
+    void trace(std::string source, int line, void* userData = nullptr);
+
     template <typename ...Args>
     void logf(std::string format, LogLevel logLevel, Args&&... args) {
         char message[200];
diff --git a/core/src/objects/base/instance.cpp b/core/src/objects/base/instance.cpp
index 871c583..5f995d0 100644
--- a/core/src/objects/base/instance.cpp
+++ b/core/src/objects/base/instance.cpp
@@ -429,4 +429,17 @@ std::vector<std::pair<std::string, std::shared_ptr<Instance>>> Instance::GetRefe
     }
 
     return referenceProperties;
+}
+
+std::string Instance::GetFullName() {
+    std::string currentName = name;
+    std::optional<std::shared_ptr<Instance>> currentParent = GetParent();
+
+    while (currentParent.has_value() && !currentParent.value()->IsA("DataModel")) {
+        currentName = currentParent.value()->name + "." + currentName;
+
+        currentParent = currentParent.value()->GetParent();
+    }
+
+    return currentName;
 }
\ No newline at end of file
diff --git a/core/src/objects/base/instance.h b/core/src/objects/base/instance.h
index 1e9734e..b1f968a 100644
--- a/core/src/objects/base/instance.h
+++ b/core/src/objects/base/instance.h
@@ -113,6 +113,7 @@ public:
     // Utility functions
     inline void AddChild(std::shared_ptr<Instance> object) { object->SetParent(this->shared_from_this()); }
     std::optional<std::shared_ptr<Instance>> FindFirstChild(std::string);
+    std::string GetFullName();
 
     // Properties
     result<Data::Variant, MemberNotFound> GetPropertyValue(std::string name);
diff --git a/core/src/objects/script.cpp b/core/src/objects/script.cpp
index 3ac6e67..235e67d 100644
--- a/core/src/objects/script.cpp
+++ b/core/src/objects/script.cpp
@@ -22,7 +22,8 @@ Script::Script(): Instance(&TYPE) {
                 "workspace.Part.TouchEnded:Connect(function(otherPart)\n"
 	            "    print(\"Touched ended with: \", otherPart.Name)\n"
                 "end)\n"
-                "\n";
+                "\n"
+                "error(\"Test\")";
 }
 
 Script::~Script() {
@@ -57,12 +58,39 @@ void Script::Run() {
     lua_pop(Lt, 1); // _G
 
     // Load source and push onto thread stack as function ptr
-    luaL_loadstring(Lt, source.c_str());
+    // luaL_loadstring(Lt, source.c_str());
+    luaL_loadbuffer(Lt, source.c_str(), source.size(), scriptContext->RegisterScriptSource(shared<Script>()).c_str());
     
     int status = lua_resume(Lt, 0);
     if (status > LUA_YIELD) {
-        Logger::error(lua_tostring(Lt, -1));
+        lua_Debug dbg;
+        lua_getstack(Lt, 1, &dbg);
+        lua_getinfo(Lt, "S", &dbg);
+
+        std::weak_ptr<Script> source = scriptContext->GetScriptFromSource(dbg.source);
+
+        std::string errorMessage = lua_tostring(Lt, -1);
+        if (!source.expired())
+            errorMessage = source.lock()->GetFullName() + errorMessage.substr(errorMessage.find(':'));
+
+        Logger::error(errorMessage);
         lua_pop(Lt, 1); // Pop return value
+
+        Logger::traceStart();
+
+        int stack = 1;
+        while (lua_getstack(Lt, stack++, &dbg)) {
+            lua_getinfo(Lt, "nlSu", &dbg);
+            
+            std::weak_ptr<Script> source = scriptContext->GetScriptFromSource(dbg.source);
+            if (source.expired()) {
+                Logger::trace(dbg.source, dbg.currentline);
+            } else {
+                Logger::trace(source.lock()->GetFullName(), dbg.currentline, &source);
+            }
+        }
+
+        Logger::traceEnd();
     }
 
     lua_pop(L, 1); // Pop the thread
diff --git a/core/src/objects/script/scriptcontext.cpp b/core/src/objects/script/scriptcontext.cpp
index 2f240cc..d43f7a1 100644
--- a/core/src/objects/script/scriptcontext.cpp
+++ b/core/src/objects/script/scriptcontext.cpp
@@ -4,9 +4,8 @@
 #include "datatypes/vector.h"
 #include "logger.h"
 #include "timeutil.h"
-#include <cstdint>
 #include <ctime>
-#include <chrono>
+#include <string>
 #include "lua.h"
 
 static int g_print(lua_State*);
@@ -130,6 +129,17 @@ void ScriptContext::RunSleepingThreads() {
     }
 }
 
+std::string ScriptContext::RegisterScriptSource(std::shared_ptr<Script> script) {
+    int id = lastScriptSourceId++;
+    scriptSources[id] = script;
+    return "=f" + std::to_string(id);
+}
+
+std::weak_ptr<Script> ScriptContext::GetScriptFromSource(std::string source) {
+    int id = std::stoi(source.c_str() + 2);
+    return scriptSources[id];
+}
+
 // https://www.lua.org/source/5.1/lbaselib.c.html
 static int g_print(lua_State* L) {
     std::string buf;
diff --git a/core/src/objects/script/scriptcontext.h b/core/src/objects/script/scriptcontext.h
index f3305a3..7009397 100644
--- a/core/src/objects/script/scriptcontext.h
+++ b/core/src/objects/script/scriptcontext.h
@@ -3,6 +3,7 @@
 #include "objects/annotation.h"
 #include "objects/base/service.h"
 #include "lua.h"
+#include <memory>
 #include <vector>
 
 struct SleepingThread {
@@ -12,10 +13,14 @@ struct SleepingThread {
     bool active = true;
 };
 
+class Script;
+
 class DEF_INST_SERVICE ScriptContext : public Service {
     AUTOGEN_PREAMBLE
 
     std::vector<SleepingThread> sleepingThreads;
+    std::map<int, std::weak_ptr<Script>> scriptSources;
+    int lastScriptSourceId = 0;
 protected:
     void InitService() override;
     bool initialized = false;
@@ -27,6 +32,8 @@ public:
     lua_State* state;
     void PushThreadSleep(lua_State* thread, float delay);
     void RunSleepingThreads();
+    std::string RegisterScriptSource(std::shared_ptr<Script>);
+    std::weak_ptr<Script> GetScriptFromSource(std::string source);
 
     static inline std::shared_ptr<Instance> Create() { return std::make_shared<ScriptContext>(); };
 };
\ No newline at end of file
diff --git a/editor/mainwindow.cpp b/editor/mainwindow.cpp
index 4049b7a..030f833 100644
--- a/editor/mainwindow.cpp
+++ b/editor/mainwindow.cpp
@@ -82,6 +82,7 @@ MainWindow::MainWindow(QWidget *parent)
     // Logger
 
     Logger::addLogListener(std::bind(&MainWindow::handleLog, this, std::placeholders::_1, std::placeholders::_2));
+    Logger::addLogListener(std::bind(&MainWindow::handleLogTrace, this, std::placeholders::_1, std::placeholders::_2, std::placeholders::_3, std::placeholders::_4));
 
     QFont font("");
     font.setStyleHint(QFont::Monospace);
@@ -161,12 +162,19 @@ void MainWindow::handleLog(Logger::LogLevel logLevel, std::string message) {
 
     if (logLevel == Logger::LogLevel::INFO)
         ui->outputTextView->appendHtml(QString("<p>%1</p>").arg(QString::fromStdString(message)));
+    if (logLevel == Logger::LogLevel::TRACE)
+        ui->outputTextView->appendHtml(QString("<p style=\"color:rgb(0, 127, 255);\">%1</p>").arg(QString::fromStdString(message)));
     if (logLevel == Logger::LogLevel::WARNING)
         ui->outputTextView->appendHtml(QString("<p style=\"color:rgb(255, 127, 0); font-weight: bold;\">%1</p>").arg(QString::fromStdString(message)));
     if (logLevel == Logger::LogLevel::ERROR || logLevel == Logger::LogLevel::FATAL_ERROR)
         ui->outputTextView->appendHtml(QString("<p style=\"color:rgb(255, 0, 0); font-weight: bold;\">%1</p>").arg(QString::fromStdString(message)));
 }
 
+void MainWindow::handleLogTrace(std::string message, std::string source, int line, void* userData) {
+    
+}
+
+
 void MainWindow::connectActionHandlers() {
     // Explorer View
 
diff --git a/editor/mainwindow.h b/editor/mainwindow.h
index 5373cf2..b02e062 100644
--- a/editor/mainwindow.h
+++ b/editor/mainwindow.h
@@ -65,6 +65,7 @@ private:
     void updateToolbars();
     void closeEvent(QCloseEvent* evt) override;
     void handleLog(Logger::LogLevel, std::string);
+    void handleLogTrace(std::string, std::string, int, void*);
 
     void connectActionHandlers();