Merge pull request #669 from odysseus654/pr/script-logging

add more details to messages logged in entity scripts

interface/src/ui/LogDialog.cpp

@@ -167,6 +167,13 @@ LogDialog::LogDialog(QWidget* parent, AbstractLoggerInterface* logger) : BaseLog
     }
     _extraDebuggingBox->show();
     connect(_extraDebuggingBox, &QCheckBox::stateChanged, this, &LogDialog::handleExtraDebuggingCheckbox);
+    
+    _showSourceDebuggingBox = new QCheckBox("Show script sources", this);
+    if (_logger->showSourceDebugging()) {
+        _showSourceDebuggingBox->setCheckState(Qt::Checked);
+    }
+    _showSourceDebuggingBox->show();
+    connect(_showSourceDebuggingBox, &QCheckBox::stateChanged, this, &LogDialog::handleShowSourceDebuggingCheckbox);
 
     _allLogsButton = new QPushButton("All Messages", this);
     // set object name for css styling
@@ -196,8 +203,13 @@ void LogDialog::resizeEvent(QResizeEvent* event) {
         THIRD_ROW,
         COMBOBOX_WIDTH,
         ELEMENT_HEIGHT);
-
-     _keepOnTopBox->setGeometry(width() - ELEMENT_MARGIN - COMBOBOX_WIDTH - ELEMENT_MARGIN - ALL_LOGS_BUTTON_WIDTH - ELEMENT_MARGIN - COMBOBOX_WIDTH - ELEMENT_MARGIN,
+    _keepOnTopBox->setGeometry(width() - ELEMENT_MARGIN - COMBOBOX_WIDTH - ELEMENT_MARGIN - ALL_LOGS_BUTTON_WIDTH - ELEMENT_MARGIN - COMBOBOX_WIDTH - ELEMENT_MARGIN,
+        THIRD_ROW,
+        COMBOBOX_WIDTH,
+        ELEMENT_HEIGHT);
+    _showSourceDebuggingBox->setGeometry(width() - ELEMENT_MARGIN - COMBOBOX_WIDTH - ELEMENT_MARGIN - ALL_LOGS_BUTTON_WIDTH
+                                                 - ELEMENT_MARGIN - COMBOBOX_WIDTH - ELEMENT_MARGIN - ELEMENT_MARGIN
+                                                 - COMBOBOX_WIDTH - ELEMENT_MARGIN,
         THIRD_ROW,
         COMBOBOX_WIDTH,
         ELEMENT_HEIGHT);
@@ -217,6 +229,8 @@ void LogDialog::handleRevealButton() {
 }
 
 void LogDialog::handleAllLogsButton() {
+    _logger->setShowSourceDebugging(false);
+    _showSourceDebuggingBox->setCheckState(Qt::Unchecked);
     _logger->setExtraDebugging(false);
     _extraDebuggingBox->setCheckState(Qt::Unchecked);
     _logger->setDebugPrint(true);
@@ -238,6 +252,10 @@ void LogDialog::handleAllLogsButton() {
     printLogFile();
 }
 
+void LogDialog::handleShowSourceDebuggingCheckbox(int state) {
+    _logger->setShowSourceDebugging(state != 0);
+}
+
 void LogDialog::handleExtraDebuggingCheckbox(int state) {
     _logger->setExtraDebugging(state != 0);
 }

interface/src/ui/LogDialog.h

@@ -33,6 +33,7 @@ public slots:
 
 private slots:
     void handleRevealButton();
+    void handleShowSourceDebuggingCheckbox(int);
     void handleExtraDebuggingCheckbox(int);
     void handleKeepWindowOnTop(int);
     void handleDebugPrintBox(int);
@@ -55,6 +56,7 @@ protected:
     
 
 private:
+    QCheckBox* _showSourceDebuggingBox;
     QCheckBox* _extraDebuggingBox;
     QCheckBox* _keepOnTopBox;
     QPushButton* _revealLogButton;

libraries/script-engine/src/ScriptEngine.cpp

@@ -40,6 +40,7 @@
 
 #include <shared/LocalFileAccessGate.h>
 #include <shared/QtHelpers.h>
+#include <shared/AbstractLoggerInterface.h>
 #include <AudioConstants.h>
 #include <AudioEffectOptions.h>
 #include <AvatarData.h>
@@ -78,7 +79,6 @@
 #include "StackTestScriptingInterface.h"
 #include "ModelScriptingInterface.h"
 
-
 #include <Profile.h>
 
 #include "../../midi/src/Midi.h"        // FIXME why won't a simpler include work?
@@ -111,6 +111,7 @@ int scriptEnginePointerMetaID = qRegisterMetaType<ScriptEnginePointer>();
 Q_DECLARE_METATYPE(ExternalResource::Bucket);
 
 static QScriptValue debugPrint(QScriptContext* context, QScriptEngine* engine) {
+    // assemble the message by concatenating our arguments
     QString message = "";
     for (int i = 0; i < context->argumentCount(); i++) {
         if (i > 0) {
@@ -119,12 +120,53 @@ static QScriptValue debugPrint(QScriptContext* context, QScriptEngine* engine) {
         message += context->argument(i).toString();
     }
 
-    if (ScriptEngine *scriptEngine = qobject_cast<ScriptEngine*>(engine)) {
+    // was this generated by a script engine? If we don't recognize it then send the message and exit
+    ScriptEngine* scriptEngine = qobject_cast<ScriptEngine*>(engine);
+    if (!scriptEngine) {
+        qCDebug(scriptengine_script, "%s", qUtf8Printable(message));
+        return QScriptValue();
+    }
+
+    // This message was sent by one of our script engines, let's try to see if we can find the source.
+    // Note that the first entry in the backtrace should be "print" and is somewhat useless to us
+    AbstractLoggerInterface* loggerInterface = AbstractLoggerInterface::get();
+    if (loggerInterface->showSourceDebugging()) {
+        QScriptContext* userContext = context;
+        while (userContext && QScriptContextInfo(userContext).functionType() == QScriptContextInfo::NativeFunction) {
+            userContext = userContext->parentContext();
+        }
+        QString location;
+        if (userContext) {
+            QScriptContextInfo contextInfo(userContext);
+            QString fileName = contextInfo.fileName();
+            int lineNumber = contextInfo.lineNumber();
+            QString functionName = contextInfo.functionName();
+    
+            location = functionName;
+            if (!fileName.isEmpty()) {
+                if (location.isEmpty()) {
+                    location = fileName;
+                } else {
+                    location = QString("%1 at %2").arg(location).arg(fileName);
+                }
+            }
+            if (lineNumber != -1) {
+                location = QString("%1:%2").arg(location).arg(lineNumber);
+            }
+        }
+        if (location.isEmpty()) {
+            location = scriptEngine->getFilename();
+        }
+    
+        // give the script engine a chance to notify the system about this message
+        scriptEngine->print(message);
+    
+        // send the message to debug log
+        qCDebug(scriptengine_script, "[%s] %s", qUtf8Printable(location), qUtf8Printable(message));
+    } else {
         scriptEngine->print(message);
         // prefix the script engine name to help disambiguate messages in the main debug log
         qCDebug(scriptengine_script, "[%s] %s", qUtf8Printable(scriptEngine->getFilename()), qUtf8Printable(message));
-    } else {
-        qCDebug(scriptengine_script, "%s", qUtf8Printable(message));
     }
 
     return QScriptValue();

libraries/shared/src/shared/AbstractLoggerInterface.h

@@ -23,6 +23,7 @@ public:
     static AbstractLoggerInterface* get();
     AbstractLoggerInterface(QObject* parent = NULL);
     ~AbstractLoggerInterface();
+    inline bool showSourceDebugging() { return _showSourceDebugging; }
     inline bool extraDebugging() { return _extraDebugging; }
     inline bool debugPrint() { return _debugPrint; }
     inline bool infoPrint() { return _infoPrint; }
@@ -31,6 +32,7 @@ public:
     inline bool suppressPrint() { return _suppressPrint; }
     inline bool fatalPrint() { return _fatalPrint; }
     inline bool unknownPrint() { return _unknownPrint; }
+    inline void setShowSourceDebugging(bool showSourceDebugging) { _showSourceDebugging = showSourceDebugging; }
     inline void setExtraDebugging(bool extraDebugging) { _extraDebugging = extraDebugging; }
     inline void setDebugPrint(bool debugPrint) { _debugPrint = debugPrint; }
     inline void setInfoPrint(bool infoPrint) { _infoPrint = infoPrint; }
@@ -49,6 +51,7 @@ signals:
     void logReceived(QString message);
 
 private:
+    bool _showSourceDebugging{ false };
     bool _extraDebugging{ false };
     bool _debugPrint{ true };
     bool _infoPrint{ true };