From c8c9118d4d0f671ea7f7cc4ed9dc64bdb4eaae30 Mon Sep 17 00:00:00 2001 From: Atlante45 Date: Fri, 23 Oct 2015 15:40:56 -0700 Subject: [PATCH] Improve script engine error logging + some cleanup --- libraries/script-engine/src/ScriptEngine.cpp | 74 ++++++++++++++------ libraries/script-engine/src/ScriptEngine.h | 5 +- libraries/shared/src/LogHandler.cpp | 2 +- 3 files changed, 56 insertions(+), 25 deletions(-) diff --git a/libraries/script-engine/src/ScriptEngine.cpp b/libraries/script-engine/src/ScriptEngine.cpp index a317f2a82c..cbe9449551 100644 --- a/libraries/script-engine/src/ScriptEngine.cpp +++ b/libraries/script-engine/src/ScriptEngine.cpp @@ -556,7 +556,7 @@ void ScriptEngine::addEventHandler(const EntityItemID& entityID, const QString& } -QScriptValue ScriptEngine::evaluate(const QString& program, const QString& fileName, int lineNumber) { +QScriptValue ScriptEngine::evaluate(const QString& sourceCode, const QString& fileName, int lineNumber) { if (_stoppingAllScripts) { return QScriptValue(); // bail early } @@ -565,27 +565,30 @@ QScriptValue ScriptEngine::evaluate(const QString& program, const QString& fileN QScriptValue result; #ifdef THREAD_DEBUGGING qDebug() << "*** WARNING *** ScriptEngine::evaluate() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] " - "program:" << program << " fileName:" << fileName << "lineNumber:" << lineNumber; + "sourceCode:" << sourceCode << " fileName:" << fileName << "lineNumber:" << lineNumber; #endif QMetaObject::invokeMethod(this, "evaluate", Qt::BlockingQueuedConnection, Q_RETURN_ARG(QScriptValue, result), - Q_ARG(const QString&, program), + Q_ARG(const QString&, sourceCode), Q_ARG(const QString&, fileName), Q_ARG(int, lineNumber)); return result; } + + // Check synthax + const QScriptProgram program(sourceCode, fileName, lineNumber); + if (!checkSynthax(program)) { + return QScriptValue(); + } - _evaluatesPending++; - QScriptValue result = QScriptEngine::evaluate(program, fileName, lineNumber); - if (hasUncaughtException()) { - int line = uncaughtExceptionLineNumber(); - qCDebug(scriptengine) << "Uncaught exception at (" << _fileNameString << " : " << fileName << ") line" << line << ": " << result.toString(); - } - _evaluatesPending--; + ++_evaluatesPending; + const auto result = QScriptEngine::evaluate(program); + --_evaluatesPending; + + const auto hadUncaughtException = checkExceptions(this, program.fileName()); if (_wantSignals) { - emit evaluationFinished(result, hasUncaughtException()); + emit evaluationFinished(result, hadUncaughtException); } - clearExceptions(); return result; } @@ -603,7 +606,7 @@ void ScriptEngine::run() { emit runningStateChanged(); } - QScriptValue result = evaluate(_scriptContents); + QScriptValue result = evaluate(_scriptContents, _fileNameString); QElapsedTimer startTime; startTime.start(); @@ -644,15 +647,6 @@ void ScriptEngine::run() { qint64 now = usecTimestampNow(); float deltaTime = (float) (now - lastUpdate) / (float) USECS_PER_SECOND; - if (hasUncaughtException()) { - int line = uncaughtExceptionLineNumber(); - qCDebug(scriptengine) << "Uncaught exception at (" << _fileNameString << ") line" << line << ":" << uncaughtException().toString(); - if (_wantSignals) { - emit errorMessage("Uncaught exception at (" + _fileNameString + ") line" + QString::number(line) + ":" + uncaughtException().toString()); - } - clearExceptions(); - } - if (!_isFinished) { if (_wantSignals) { emit update(deltaTime); @@ -660,6 +654,7 @@ void ScriptEngine::run() { } lastUpdate = now; + checkExceptions(this, _fileNameString); } stopAllTimers(); // make sure all our timers are stopped if the script is ending @@ -896,6 +891,38 @@ void ScriptEngine::load(const QString& loadFile) { } } + +bool ScriptEngine::checkSynthax(const QScriptProgram& program) { + const auto syntaxCheck = QScriptEngine::checkSyntax(program.sourceCode()); + if (syntaxCheck.state() != QScriptSyntaxCheckResult::Valid) { + const auto error = syntaxCheck.errorMessage(); + const auto line = QString::number(syntaxCheck.errorLineNumber()); + const auto column = QString::number(syntaxCheck.errorColumnNumber()); + const auto message = QString("[SyntaxError] %1 in %2:%3(%4)").arg(error, program.fileName(), line, column); + qCWarning(scriptengine) << qPrintable(message); + return false; + } + return true; +} + +bool ScriptEngine::checkExceptions(QScriptEngine* engine, const QString& fileName) { + if (engine->hasUncaughtException()) { + const auto backtrace = engine->uncaughtExceptionBacktrace(); + const auto exception = engine->uncaughtException().toString(); + const auto line = QString::number(engine->uncaughtExceptionLineNumber()); + engine->clearExceptions(); + + auto message = QString("[UncaughtException] %1 in %2:%3").arg(exception, fileName, line); + if (!backtrace.empty()) { + static const auto lineSeparator = "\n "; + message += QString("\n[Backtrace]%1%2").arg(lineSeparator, backtrace.join(lineSeparator)); + } + qCWarning(scriptengine) << qPrintable(message); + return false; + } + return true; +} + // Look up the handler associated with eventName and entityID. If found, evalute the argGenerator thunk and call the handler with those args void ScriptEngine::forwardHandlerCall(const EntityItemID& entityID, const QString& eventName, QScriptValueList eventHanderArgs) { if (QThread::currentThread() != thread()) { @@ -1015,7 +1042,8 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co lastModified = (quint64)QFileInfo(file).lastModified().toMSecsSinceEpoch(); } - QScriptValue entityScriptConstructor = evaluate(contents); + auto fileName = QString("(EntityID:%1, %2)").arg(entityID.toString(), isURL ? scriptOrURL : "EmbededEntityScript"); + QScriptValue entityScriptConstructor = evaluate(contents, fileName); QScriptValue entityScriptObject = entityScriptConstructor.construct(); EntityScriptDetails newDetails = { scriptOrURL, entityScriptObject, lastModified }; _entityScripts[entityID] = newDetails; diff --git a/libraries/script-engine/src/ScriptEngine.h b/libraries/script-engine/src/ScriptEngine.h index c2f9d966f1..8fda876a31 100644 --- a/libraries/script-engine/src/ScriptEngine.h +++ b/libraries/script-engine/src/ScriptEngine.h @@ -88,7 +88,7 @@ public: Q_INVOKABLE void registerValue(const QString& valueName, QScriptValue value); /// evaluate some code in the context of the ScriptEngine and return the result - Q_INVOKABLE QScriptValue evaluate(const QString& program, const QString& fileName = QString(), int lineNumber = 1); // this is also used by the script tool widget + Q_INVOKABLE QScriptValue evaluate(const QString& program, const QString& fileName, int lineNumber = 1); // this is also used by the script tool widget /// if the script engine is not already running, this will download the URL and start the process of seting it up /// to run... NOTE - this is used by Application currently to load the url. We don't really want it to be exposed @@ -182,6 +182,9 @@ private: QObject* setupTimerWithInterval(const QScriptValue& function, int intervalMS, bool isSingleShot); void stopTimer(QTimer* timer); + static bool checkSynthax(const QScriptProgram& program); + static bool checkExceptions(QScriptEngine* engine, const QString& fileName); + AbstractControllerScriptingInterface* _controllerScriptingInterface; QString _fileNameString; Quat _quatLibrary; diff --git a/libraries/shared/src/LogHandler.cpp b/libraries/shared/src/LogHandler.cpp index 22ea12c1b3..cc3519e43e 100644 --- a/libraries/shared/src/LogHandler.cpp +++ b/libraries/shared/src/LogHandler.cpp @@ -135,7 +135,7 @@ QString LogHandler::printMessage(LogMsgType type, const QMessageLogContext& cont prefixString.append(QString(" [%1]").arg(_targetName)); } - QString logMessage = QString("%1 %2").arg(prefixString, message); + QString logMessage = QString("%1 %2").arg(prefixString, message.split("\n").join("\n" + prefixString + " ")); fprintf(stdout, "%s\n", qPrintable(logMessage)); return logMessage; }