History

Merge pull request #9685 from humbletim/21114-part2

CR-2 21114 -- BaseScriptEngine.cpp, order-of-operations fixes, reworked JS Exceptions

Ryan Huffman committed 9 years ago

Commit a744e0d2 parents 2b11740 2505a8927 files · +1124 −238Browse files

Showing the changes to libraries/script-engine/src/ScriptEngine.cpp (1 of 27 files). Show all

Unified · Split

libraries/script-engine/src/ScriptEngine.cpp+389−204
@@ -50,6 +50,7 @@ · 49 unmodified lines
5050
5151 #include "ArrayBufferViewClass.h"
5252 #include "BatchLoader.h"
53+#include "BaseScriptEngine.h"
5354 #include "DataViewClass.h"
5455 #include "EventTypes.h"
5556 #include "FileScriptingInterface.h" // unzip project
@@ -69,9 +70,12 @@ · 13 unmodified lines
6970
7071 #include "MIDIEvent.h"
7172
72−const QString BaseScriptEngine::SCRIPT_EXCEPTION_FORMAT { "[UncaughtException] %1 in %2:%3" };
7373 static const QScriptEngine::QObjectWrapOptions DEFAULT_QOBJECT_WRAP_OPTIONS =
7474 QScriptEngine::ExcludeDeleteLater | QScriptEngine::ExcludeChildObjects;
75+static const QScriptValue::PropertyFlags READONLY_PROP_FLAGS { QScriptValue::ReadOnly | QScriptValue::Undeletable };
76+static const QScriptValue::PropertyFlags READONLY_HIDDEN_PROP_FLAGS { READONLY_PROP_FLAGS | QScriptValue::SkipInEnumeration };
77+
78+
7579
7680 static const bool HIFI_AUTOREFRESH_FILE_SCRIPTS { true };
7781
@@ -90,13 +94,9 @@ static QScriptValue debugPrint(QScriptContext* context, QScriptEngine* engine){ · 12 unmodified lines
9094 }
9195 qCDebug(scriptengineScript).noquote() << "script:print()<<" << message; // noquote() so that \n is treated as newline
9296
93− message = message.replace("\\", "\\\\")
94− .replace("\n", "\\n")
95− .replace("\r", "\\r")
96− .replace("'", "\\'");
97−
98− // FIXME - this approach neeeds revisiting. print() comes here, which ends up doing an evaluate?
99− engine->evaluate("Script.print('" + message + "')");
97+ // FIXME - this approach neeeds revisiting. print() comes here, which ends up calling Script.print?
98+ engine->globalObject().property("Script").property("print")
99+ .call(engine->nullValue(), QScriptValueList({ message }));
100100
101101 return QScriptValue();
102102 }
@@ -140,52 +140,15 @@ QString encodeEntityIdIntoEntityUrl(const QString& url, const QString& entityID) · 37 unmodified lines
140140 return url + " [EntityID:" + entityID + "]";
141141 }
142142
143−QString BaseScriptEngine::lintScript(const QString& sourceCode, const QString& fileName, const int lineNumber) {
144− const auto syntaxCheck = checkSyntax(sourceCode);
145− if (syntaxCheck.state() != syntaxCheck.Valid) {
146− const auto error = syntaxCheck.errorMessage();
147− const auto line = QString::number(syntaxCheck.errorLineNumber());
148− const auto column = QString::number(syntaxCheck.errorColumnNumber());
149− const auto message = QString("[SyntaxError] %1 in %2:%3(%4)").arg(error, fileName, line, column);
150− return message;
151− }
152− return QString();
153−}
154−
155−QString BaseScriptEngine::formatUncaughtException(const QString& overrideFileName) {
156− QString message;
157− if (hasUncaughtException()) {
158− const auto error = uncaughtException();
159− const auto backtrace = uncaughtExceptionBacktrace();
160− const auto exception = error.toString();
161− auto filename = overrideFileName;
162− if (filename.isEmpty()) {
163− QScriptContextInfo ctx { currentContext() };
164− filename = ctx.fileName();
165− }
166− const auto line = QString::number(uncaughtExceptionLineNumber());
167−
168− message = QString(SCRIPT_EXCEPTION_FORMAT).arg(exception, overrideFileName, line);
169− if (!backtrace.empty()) {
170− static const auto lineSeparator = "\n ";
171− message += QString("\n[Backtrace]%1%2").arg(lineSeparator, backtrace.join(lineSeparator));
172− }
173− }
174− return message;
175−}
176−
177−QString ScriptEngine::reportUncaughtException(const QString& overrideFileName) {
178− QString message;
179− if (!hasUncaughtException()) {
180− return message;
181− }
182− message = formatUncaughtException(overrideFileName.isEmpty() ? _fileNameString : overrideFileName);
143+QString ScriptEngine::logException(const QScriptValue& exception) {
144+ auto message = formatException(exception);
183145 scriptErrorMessage(qPrintable(message));
184146 return message;
185147 }
186148
187149 int ScriptEngine::processLevelMaxRetries { ScriptRequest::MAX_RETRIES };
188150 ScriptEngine::ScriptEngine(Context context, const QString& scriptContents, const QString& fileNameString) :
151+ BaseScriptEngine(),
189152 _context(context),
190153 _scriptContents(scriptContents),
191154 _timerFunctionMap(),
@@ -195,16 +158,30 @@ ScriptEngine::ScriptEngine(Context context, const QString& scriptContents, const · 3 unmodified lines
195158 DependencyManager::get<ScriptEngines>()->addScriptEngine(this);
196159
197160 connect(this, &QScriptEngine::signalHandlerException, this, [this](const QScriptValue& exception) {
198− reportUncaughtException();
199− clearExceptions();
200− });
161+ if (hasUncaughtException()) {
162+ // the engine's uncaughtException() seems to produce much better stack traces here
163+ emit unhandledException(cloneUncaughtException("signalHandlerException"));
164+ clearExceptions();
165+ } else {
166+ // ... but may not always be available -- so if needed we fallback to the passed exception
167+ emit unhandledException(exception);
168+ }
169+ }, Qt::DirectConnection);
201170
202171 setProcessEventsInterval(MSECS_PER_SECOND);
203172 if (isEntityServerScript()) {
204173 qCDebug(scriptengine) << "isEntityServerScript() -- limiting maxRetries to 1";
205174 processLevelMaxRetries = 1;
206175 }
207− qCDebug(scriptengine) << getContext() << "processLevelMaxRetries =" << processLevelMaxRetries;
176+
177+ // this is where all unhandled exceptions end up getting logged
178+ connect(this, &BaseScriptEngine::unhandledException, this, [this](const QScriptValue& err) {
179+ auto output = err.engine() == this ? err : makeError(err);
180+ if (!output.property("detail").isValid()) {
181+ output.setProperty("detail", "UnhandledException");
182+ }
183+ logException(output);
184+ });
208185 }
209186
210187 QString ScriptEngine::getContext() const {
@@ -224,13 +201,22 @@ QString ScriptEngine::getContext() const { · 13 unmodified lines
224201 }
225202
226203 ScriptEngine::~ScriptEngine() {
204+ // FIXME: are these scriptInfoMessage/scriptWarningMessage segfaulting anybody else at app shutdown?
205+#if !defined(Q_OS_LINUX)
227206 scriptInfoMessage("Script Engine shutting down:" + getFilename());
207+#else
208+ qCDebug(scriptengine) << "~ScriptEngine()" << this;
209+#endif
228210
229211 auto scriptEngines = DependencyManager::get<ScriptEngines>();
230212 if (scriptEngines) {
231213 scriptEngines->removeScriptEngine(this);
232214 } else {
215+#if !defined(Q_OS_LINUX)
233216 scriptWarningMessage("Script destroyed after ScriptEngines!");
217+#else
218+ qCWarning(scriptengine) << ("Script destroyed after ScriptEngines!");
219+#endif
234220 }
235221 }
236222
@@ -320,9 +306,12 @@ void ScriptEngine::runDebuggable() { · 83 unmodified lines
320306 }
321307 }
322308 _lastUpdate = now;
323− // Debug and clear exceptions
324− if (hasUncaughtException()) {
325− reportUncaughtException();
309+
310+ // only clear exceptions if we are not in the middle of evaluating
311+ if (!isEvaluating() && hasUncaughtException()) {
312+ qCWarning(scriptengine) << __FUNCTION__ << "---------- UNCAUGHT EXCEPTION --------";
313+ qCWarning(scriptengine) << "runDebuggable" << uncaughtException().toString();
314+ logException(__FUNCTION__);
326315 clearExceptions();
327316 }
328317 });
@@ -357,10 +346,9 @@ void ScriptEngine::runInThread() { · 28 unmodified lines
357346 workerThread->start();
358347 }
359348
360−void ScriptEngine::executeOnScriptThread(std::function<void()> function, bool blocking ) {
349+void ScriptEngine::executeOnScriptThread(std::function<void()> function, const Qt::ConnectionType& type ) {
361350 if (QThread::currentThread() != thread()) {
362− QMetaObject::invokeMethod(this, "executeOnScriptThread", blocking ? Qt::BlockingQueuedConnection : Qt::QueuedConnection,
363− Q_ARG(std::function<void()>, function));
351+ QMetaObject::invokeMethod(this, "executeOnScriptThread", type, Q_ARG(std::function<void()>, function));
364352 return;
365353 }
366354
@@ -559,6 +547,7 @@ void ScriptEngine::init() { · 192 unmodified lines
559547 qCWarning(scriptengine) << "deletingEntity while entity script is still running!" << entityID;
560548 }
561549 _entityScripts.remove(entityID);
550+ emit entityScriptDetailsUpdated();
562551 }
563552 });
564553
@@ -591,8 +580,7 @@ void ScriptEngine::init() { · 26 unmodified lines
591580 QScriptValue webSocketConstructorValue = newFunction(WebSocketClass::constructor);
592581 globalObject().setProperty("WebSocket", webSocketConstructorValue);
593582
594− QScriptValue printConstructorValue = newFunction(debugPrint);
595− globalObject().setProperty("print", printConstructorValue);
583+ globalObject().setProperty("print", newFunction(debugPrint));
596584
597585 QScriptValue audioEffectOptionsConstructorValue = newFunction(AudioEffectOptions::constructor);
598586 globalObject().setProperty("AudioEffectOptions", audioEffectOptionsConstructorValue);
@@ -606,6 +594,7 @@ void ScriptEngine::init() { · 7 unmodified lines
606594 qScriptRegisterMetaType(this, wscReadyStateToScriptValue, wscReadyStateFromScriptValue);
607595
608596 registerGlobalObject("Script", this);
597+
609598 registerGlobalObject("Audio", &AudioScriptingInterface::getInstance());
610599 registerGlobalObject("Entities", entityScriptingInterface.data());
611600 registerGlobalObject("Quat", &_quatLibrary);
@@ -874,7 +863,6 @@ void ScriptEngine::addEventHandler(const EntityItemID& entityID, const QString& · 262 unmodified lines
874863 handlersForEvent << handlerData; // Note that the same handler can be added many times. See removeEntityEventHandler().
875864 }
876865
877−
878866 QScriptValue ScriptEngine::evaluate(const QString& sourceCode, const QString& fileName, int lineNumber) {
879867 if (DependencyManager::get<ScriptEngines>()->isStopped()) {
880868 return QScriptValue(); // bail early
@@ -896,23 +884,30 @@ QScriptValue ScriptEngine::evaluate(const QString& sourceCode, const QString& fi · 15 unmodified lines
896884
897885 // Check syntax
898886 auto syntaxError = lintScript(sourceCode, fileName);
887+ if (syntaxError.isError()) {
888+ if (isEvaluating()) {
889+ currentContext()->throwValue(syntaxError);
890+ } else {
891+ syntaxError.setProperty("detail", "evaluate");
892+ emit unhandledException(syntaxError);
893+ }
894+ return syntaxError;
895+ }
899896 QScriptProgram program { sourceCode, fileName, lineNumber };
900− if (!syntaxError.isEmpty() || program.isNull()) {
901− scriptErrorMessage(qPrintable(syntaxError));
902− return QScriptValue();
897+ if (program.isNull()) {
898+ // can this happen?
899+ auto err = makeError("could not create QScriptProgram for " + fileName);
900+ emit unhandledException(err);
901+ return err;
903902 }
904903
905− ++_evaluatesPending;
906− auto result = BaseScriptEngine::evaluate(program);
907− --_evaluatesPending;
908−
909− if (hasUncaughtException()) {
910− result = uncaughtException();
911− reportUncaughtException(program.fileName());
912− emit evaluationFinished(result, true);
913− clearExceptions();
914− } else {
915− emit evaluationFinished(result, false);
904+ QScriptValue result;
905+ {
906+ result = BaseScriptEngine::evaluate(program);
907+ if (!isEvaluating() && hasUncaughtException()) {
908+ emit unhandledException(cloneUncaughtException(__FUNCTION__));
909+ clearExceptions();
910+ }
916911 }
917912 return result;
918913 }
@@ -933,8 +928,13 @@ void ScriptEngine::run() { · 14 unmodified lines
933928 _isRunning = true;
934929 emit runningStateChanged();
935930
936− QScriptValue result = evaluate(_scriptContents, _fileNameString);
937−
931+ {
932+ evaluate(_scriptContents, _fileNameString);
933+ if (!isEvaluating() && hasUncaughtException()) {
934+ emit unhandledException(cloneUncaughtException(__FUNCTION__));
935+ clearExceptions();
936+ }
937+ }
938938 #ifdef _WIN32
939939 // VS13 does not sleep_until unless it uses the system_clock, see:
940940 // https://www.reddit.com/r/cpp_questions/comments/3o71ic/sleep_until_not_working_with_a_time_pointsteady/
@@ -1061,13 +1061,14 @@ void ScriptEngine::run() { · 120 unmodified lines
10611061 }
10621062 _lastUpdate = now;
10631063
1064− // Debug and clear exceptions
1065− if (hasUncaughtException()) {
1066− reportUncaughtException();
1064+ // only clear exceptions if we are not in the middle of evaluating
1065+ if (!isEvaluating() && hasUncaughtException()) {
1066+ qCWarning(scriptengine) << __FUNCTION__ << "---------- UNCAUGHT EXCEPTION --------";
1067+ qCWarning(scriptengine) << "runInThread" << uncaughtException().toString();
1068+ emit unhandledException(cloneUncaughtException(__FUNCTION__));
10671069 clearExceptions();
10681070 }
10691071 }
1070−
10711072 scriptInfoMessage("Script Engine stopping:" + getFilename());
10721073
10731074 stopAllTimers(); // make sure all our timers are stopped if the script is ending
@@ -1100,9 +1101,11 @@ void ScriptEngine::run() { · 26 unmodified lines
11001101 // we want to only call it in our own run "shutdown" processing.
11011102 void ScriptEngine::stopAllTimers() {
11021103 QMutableHashIterator<QTimer*, CallbackData> i(_timerFunctionMap);
1104+ int j {0};
11031105 while (i.hasNext()) {
11041106 i.next();
11051107 QTimer* timer = i.key();
1108+ qCDebug(scriptengine) << getFilename() << "stopAllTimers[" << j++ << "]";
11061109 stopTimer(timer);
11071110 }
11081111 }
@@ -1197,11 +1200,11 @@ void ScriptEngine::timerFired() { · 88 unmodified lines
11971200 auto postTimer = p_high_resolution_clock::now();
11981201 auto elapsed = (postTimer - preTimer);
11991202 _totalTimerExecution += std::chrono::duration_cast<std::chrono::microseconds>(elapsed);
1200−
1203+ } else {
1204+ qCWarning(scriptengine) << "timerFired -- invalid function" << timerData.function.toVariant().toString();
12011205 }
12021206 }
12031207
1204−
12051208 QObject* ScriptEngine::setupTimerWithInterval(const QScriptValue& function, int intervalMS, bool isSingleShot) {
12061209 // create the timer, add it to the map, and start it
12071210 QTimer* newTimer = new QTimer(this);
@@ -1218,7 +1221,7 @@ QObject* ScriptEngine::setupTimerWithInterval(const QScriptValue& function, int · 10 unmodified lines
12181221 // make sure the timer stops when the script does
12191222 connect(this, &ScriptEngine::scriptEnding, newTimer, &QTimer::stop);
12201223
1221− CallbackData timerData = {function, currentEntityIdentifier, currentSandboxURL };
1224+ CallbackData timerData = { function, currentEntityIdentifier, currentSandboxURL };
12221225 _timerFunctionMap.insert(newTimer, timerData);
12231226
12241227 newTimer->start(intervalMS);
@@ -1248,35 +1251,46 @@ void ScriptEngine::stopTimer(QTimer *timer) { · 23 unmodified lines
12481251 timer->stop();
12491252 _timerFunctionMap.remove(timer);
12501253 delete timer;
1254+ } else {
1255+ qCDebug(scriptengine) << "stopTimer -- not in _timerFunctionMap" << timer;
12511256 }
12521257 }
12531258
12541259 QUrl ScriptEngine::resolvePath(const QString& include) const {
12551260 QUrl url(include);
1256− // first lets check to see if it's already a full URL
1257− if (!url.scheme().isEmpty()) {
1261+ // first lets check to see if it's already a full URL -- or a Windows path like "c:/"
1262+ if (include.startsWith("/") || url.scheme().length() == 1) {
1263+ url = QUrl::fromLocalFile(include);
1264+ }
1265+ if (!url.isRelative()) {
12581266 return expandScriptUrl(url);
12591267 }
12601268
1261− QScriptContextInfo contextInfo { currentContext()->parentContext() };
1262−
1263−
12641269 // we apparently weren't a fully qualified url, so, let's assume we're relative
1265− // to the original URL of our script
1266− QUrl parentURL = contextInfo.fileName();
1267− if (parentURL.isEmpty()) {
1268− if (_parentURL.isEmpty()) {
1269− parentURL = QUrl(_fileNameString);
1270− } else {
1271− parentURL = QUrl(_parentURL);
1270+ // to the first absolute URL in the JS scope chain
1271+ QUrl parentURL;
1272+ auto context = currentContext();
1273+ do {
1274+ QScriptContextInfo contextInfo { context };
1275+ parentURL = QUrl(contextInfo.fileName());
1276+ context = context->parentContext();
1277+ } while (parentURL.isRelative() && context);
1278+
1279+ if (parentURL.isRelative()) {
1280+ // fallback to the "include" parent (if defined, this will already be absolute)
1281+ parentURL = QUrl(_parentURL);
1282+ }
1283+
1284+ if (parentURL.isRelative()) {
1285+ // fallback to the original script engine URL
1286+ parentURL = QUrl(_fileNameString);
1287+
1288+ // if still relative and path-like, then this is probably a local file...
1289+ if (parentURL.isRelative() && url.path().contains("/")) {
1290+ parentURL = QUrl::fromLocalFile(_fileNameString);
12721291 }
12731292 }
12741293
1275− // if the parent URL's scheme is empty, then this is probably a local file...
1276− if (parentURL.scheme().isEmpty()) {
1277− parentURL = QUrl::fromLocalFile(_fileNameString);
1278− }
1279−
12801294 // at this point we should have a legitimate fully qualified URL for our parent
12811295 url = expandScriptUrl(parentURL.resolved(url));
12821296 return url;
@@ -1301,22 +1315,7 @@ void ScriptEngine::include(const QStringList& includeFiles, QScriptValue callbac · 18 unmodified lines
13011315 return; // bail early
13021316 }
13031317 QList<QUrl> urls;
1304− bool knowsSensitivity = false;
1305− Qt::CaseSensitivity sensitivity { Qt::CaseSensitive };
1306− auto getSensitivity = [&]() {
1307− if (!knowsSensitivity) {
1308− QString path = currentSandboxURL.path();
1309− QFileInfo upperFI(path.toUpper());
1310− QFileInfo lowerFI(path.toLower());
1311− sensitivity = (upperFI == lowerFI) ? Qt::CaseInsensitive : Qt::CaseSensitive;
1312− knowsSensitivity = true;
1313− }
1314− return sensitivity;
1315− };
13161318
1317− // Guard against meaningless query and fragment parts.
1318− // Do NOT use PreferLocalFile as its behavior is unpredictable (e.g., on defaultScriptsLocation())
1319− const auto strippingFlags = QUrl::RemoveFilename | QUrl::RemoveQuery | QUrl::RemoveFragment;
13201319 for (QString includeFile : includeFiles) {
13211320 QString file = ResourceManager::normalizeURL(includeFile);
13221321 QUrl thisURL;
@@ -1333,10 +1332,8 @@ void ScriptEngine::include(const QStringList& includeFiles, QScriptValue callbac · 10 unmodified lines
13331332 thisURL = resolvePath(file);
13341333 }
13351334
1336− if (!isStandardLibrary && !currentSandboxURL.isEmpty() && (thisURL.scheme() == "file") &&
1337− (currentSandboxURL.scheme() != "file" ||
1338− !thisURL.toString(strippingFlags).startsWith(currentSandboxURL.toString(strippingFlags), getSensitivity()))) {
1339−
1335+ bool disallowOutsideFiles = thisURL.isLocalFile() && !isStandardLibrary && !currentSandboxURL.isLocalFile();
1336+ if (disallowOutsideFiles && !PathUtils::isDescendantOf(thisURL, currentSandboxURL)) {
13401337 scriptWarningMessage("Script.include() ignoring file path" + thisURL.toString()
13411338 + "outside of original entity script" + currentSandboxURL.toString());
13421339 } else {
@@ -1373,6 +1370,10 @@ void ScriptEngine::include(const QStringList& includeFiles, QScriptValue callbac · 30 unmodified lines
13731370 };
13741371
13751372 doWithEnvironment(capturedEntityIdentifier, capturedSandboxURL, operation);
1373+ if (hasUncaughtException()) {
1374+ emit unhandledException(cloneUncaughtException(__FUNCTION__));
1375+ clearExceptions();
1376+ }
13761377 } else {
13771378 scriptWarningMessage("Script.include() skipping evaluation of previously included url:" + url.toString());
13781379 }
@@ -1474,10 +1475,16 @@ int ScriptEngine::getNumRunningEntityScripts() const { · 95 unmodified lines
14741475 return sum;
14751476 }
14761477
1477−QString ScriptEngine::getEntityScriptStatus(const EntityItemID& entityID) {
1478− if (_entityScripts.contains(entityID))
1479− return EntityScriptStatus_::valueToKey(_entityScripts[entityID].status).toLower();
1480− return QString();
1478+void ScriptEngine::setEntityScriptDetails(const EntityItemID& entityID, const EntityScriptDetails& details) {
1479+ _entityScripts[entityID] = details;
1480+ emit entityScriptDetailsUpdated();
1481+}
1482+
1483+void ScriptEngine::updateEntityScriptStatus(const EntityItemID& entityID, const EntityScriptStatus &status, const QString& errorInfo) {
1484+ EntityScriptDetails &details = _entityScripts[entityID];
1485+ details.status = status;
1486+ details.errorInfo = errorInfo;
1487+ emit entityScriptDetailsUpdated();
14811488 }
14821489
14831490 bool ScriptEngine::getEntityScriptDetails(const EntityItemID& entityID, EntityScriptDetails &details) const {
@@ -1489,43 +1496,166 @@ bool ScriptEngine::getEntityScriptDetails(const EntityItemID& entityID, EntitySc · 5 unmodified lines
14891496 return true;
14901497 }
14911498
1492−void ScriptEngine::setEntityScriptDetails(const EntityItemID& entityID, const EntityScriptDetails& details) {
1493− _entityScripts[entityID] = details;
1494− emit entityScriptDetailsUpdated();
1495−}
1499+const static EntityItemID BAD_SCRIPT_UUID_PLACEHOLDER { "{20170224-dead-face-0000-cee000021114}" };
14961500
1497−void ScriptEngine::updateEntityScriptStatus(const EntityItemID& entityID, const EntityScriptStatus &status, const QString& errorInfo) {
1498− EntityScriptDetails &details = _entityScripts[entityID];
1499− details.status = status;
1500− details.errorInfo = errorInfo;
1501− emit entityScriptDetailsUpdated();
1502−}
1501+void ScriptEngine::processDeferredEntityLoads(const QString& entityScript, const EntityItemID& leaderID) {
1502+ QList<DeferredLoadEntity> retryLoads;
1503+ QMutableListIterator<DeferredLoadEntity> i(_deferredEntityLoads);
1504+ while (i.hasNext()) {
1505+ auto retry = i.next();
1506+ if (retry.entityScript == entityScript) {
1507+ retryLoads << retry;
1508+ i.remove();
1509+ }
1510+ }
1511+ foreach(DeferredLoadEntity retry, retryLoads) {
1512+ // check whether entity was since been deleted
1513+ if (!_entityScripts.contains(retry.entityID)) {
1514+ qCDebug(scriptengine) << "processDeferredEntityLoads -- entity details gone (entity deleted?)"
1515+ << retry.entityID;
1516+ continue;
1517+ }
15031518
1504−// since all of these operations can be asynch we will always do the actual work in the response handler
1505−// for the download
1506−void ScriptEngine::loadEntityScript(QWeakPointer<ScriptEngine> theEngine, const EntityItemID& entityID, const QString& entityScript, bool forceRedownload) {
1507− auto engine = theEngine.data();
1508− engine->executeOnScriptThread([=]{
1509− EntityScriptDetails details = engine->_entityScripts[entityID];
1510− if (details.status == EntityScriptStatus::PENDING || details.status == EntityScriptStatus::UNLOADED) {
1511− engine->updateEntityScriptStatus(entityID, EntityScriptStatus::LOADING, QThread::currentThread()->objectName());
1519+ // check whether entity has since been unloaded or otherwise errored-out
1520+ auto details = _entityScripts[retry.entityID];
1521+ if (details.status != EntityScriptStatus::PENDING) {
1522+ qCDebug(scriptengine) << "processDeferredEntityLoads -- entity status no longer PENDING; "
1523+ << retry.entityID << details.status;
1524+ continue;
15121525 }
1513− });
15141526
1515− // NOTE: If the script content is not currently in the cache, the LAMBDA here will be called on the Main Thread
1516− // which means we're guaranteed that it's not the correct thread for the ScriptEngine. This means
1517− // when we get into entityScriptContentAvailable() we will likely invokeMethod() to get it over
1518− // to the "Entities" ScriptEngine thread.
1519− DependencyManager::get<ScriptCache>()->getScriptContents(entityScript, [theEngine, entityID](const QString& scriptOrURL, const QString& contents, bool isURL, bool success, const QString &status) {
1520− QSharedPointer<ScriptEngine> strongEngine = theEngine.toStrongRef();
1521− if (strongEngine) {
1522−#ifdef THREAD_DEBUGGING
1523− qCDebug(scriptengine) << "ScriptEngine::entityScriptContentAvailable() IN LAMBDA contentAvailable on thread ["
1524− << QThread::currentThread() << "] expected thread [" << strongEngine->thread() << "]";
1527+ // propagate leader's failure reasons to the pending entity
1528+ const auto leaderDetails = _entityScripts[leaderID];
1529+ if (leaderDetails.status != EntityScriptStatus::RUNNING) {
1530+ qCDebug(scriptengine) << QString("... pending load of %1 cancelled (leader: %2 status: %3)")
1531+ .arg(retry.entityID.toString()).arg(leaderID.toString()).arg(leaderDetails.status);
1532+
1533+ auto extraDetail = QString("\n(propagated from %1)").arg(leaderID.toString());
1534+ if (leaderDetails.status == EntityScriptStatus::ERROR_LOADING_SCRIPT ||
1535+ leaderDetails.status == EntityScriptStatus::ERROR_RUNNING_SCRIPT) {
1536+ // propagate same error so User doesn't have to hunt down stampede's leader
1537+ updateEntityScriptStatus(retry.entityID, leaderDetails.status, leaderDetails.errorInfo + extraDetail);
1538+ } else {
1539+ // the leader Entity somehow ended up in some other state (rapid-fire delete or unload could cause)
1540+ updateEntityScriptStatus(retry.entityID, EntityScriptStatus::ERROR_LOADING_SCRIPT,
1541+ "A previous Entity failed to load using this script URL; reload to try again." + extraDetail);
1542+ }
1543+ continue;
1544+ }
1545+
1546+ if (_occupiedScriptURLs.contains(retry.entityScript)) {
1547+ qCWarning(scriptengine) << "--- SHOULD NOT HAPPEN -- recursive call into processDeferredEntityLoads" << retry.entityScript;
1548+ continue;
1549+ }
1550+
1551+ // if we made it here then the leading entity was successful so proceed with normal load
1552+ loadEntityScript(retry.entityID, retry.entityScript, false);
1553+ }
1554+}
1555+
1556+void ScriptEngine::loadEntityScript(const EntityItemID& entityID, const QString& entityScript, bool forceRedownload) {
1557+ if (QThread::currentThread() != thread()) {
1558+ QMetaObject::invokeMethod(this, "loadEntityScript",
1559+ Q_ARG(const EntityItemID&, entityID),
1560+ Q_ARG(const QString&, entityScript),
1561+ Q_ARG(bool, forceRedownload)
1562+ );
1563+ return;
1564+ }
1565+ PROFILE_RANGE(script, __FUNCTION__);
1566+
1567+ if (isStopping() || DependencyManager::get<ScriptEngines>()->isStopped()) {
1568+ qCDebug(scriptengine) << "loadEntityScript.start " << entityScript << entityID.toString()
1569+ << " but isStopping==" << isStopping()
1570+ << " || engines->isStopped==" << DependencyManager::get<ScriptEngines>()->isStopped();
1571+ return;
1572+ }
1573+
1574+ if (!_entityScripts.contains(entityID)) {
1575+ // make sure EntityScriptDetails has an entry for this UUID right away
1576+ // (which allows bailing from the loading/provisioning process early if the Entity gets deleted mid-flight)
1577+ updateEntityScriptStatus(entityID, EntityScriptStatus::PENDING, "...pending...");
1578+ }
1579+
1580+ // This "occupied" approach allows multiple Entities to boot from the same script URL while still taking
1581+ // full advantage of cacheable require modules. This only affects Entities literally coming in back-to-back
1582+ // before the first one has time to finish loading.
1583+ if (_occupiedScriptURLs.contains(entityScript)) {
1584+ auto currentEntityID = _occupiedScriptURLs[entityScript];
1585+ if (currentEntityID == BAD_SCRIPT_UUID_PLACEHOLDER) {
1586+ if (forceRedownload) {
1587+ // script was previously marked unusable, but we're reloading so reset it
1588+ _occupiedScriptURLs.remove(entityScript);
1589+ } else {
1590+ // since not reloading, assume that the exact same input would produce the exact same output again
1591+ // note: this state gets reset with "reload all scripts," leaving/returning to a Domain, clear cache, etc.
1592+#ifdef DEBUG_ENTITY_STATES
1593+ qCDebug(scriptengine) << QString("loadEntityScript.cancelled entity: %1 script: %2 (previous script failure)")
1594+ .arg(entityID.toString()).arg(entityScript);
1595+#endif
1596+ updateEntityScriptStatus(entityID, EntityScriptStatus::ERROR_LOADING_SCRIPT,
1597+ "A previous Entity failed to load using this script URL; reload to try again.");
1598+ return;
1599+ }
1600+ } else {
1601+ // another entity is busy loading from this script URL so wait for them to finish
1602+#ifdef DEBUG_ENTITY_STATES
1603+ qCDebug(scriptengine) << QString("loadEntityScript.deferring[%0] entity: %1 script: %2 (waiting on %3)")
1604+ .arg(_deferredEntityLoads.size()).arg(entityID.toString()).arg(entityScript).arg(currentEntityID.toString());
15251605 #endif
1526− strongEngine->entityScriptContentAvailable(entityID, scriptOrURL, contents, isURL, success, status);
1606+ _deferredEntityLoads.push_back({ entityID, entityScript });
1607+ return;
15271608 }
1528− }, forceRedownload, processLevelMaxRetries);
1609+ }
1610+
1611+ // the scriptURL slot is available; flag as in-use
1612+ _occupiedScriptURLs[entityScript] = entityID;
1613+
1614+#ifdef DEBUG_ENTITY_STATES
1615+ auto previousStatus = _entityScripts.contains(entityID) ? _entityScripts[entityID].status : EntityScriptStatus::PENDING;
1616+ qCDebug(scriptengine) << "loadEntityScript.LOADING: " << entityScript << entityID.toString()
1617+ << "(previous: " << previousStatus << ")";
1618+#endif
1619+
1620+ EntityScriptDetails newDetails;
1621+ newDetails.scriptText = entityScript;
1622+ newDetails.status = EntityScriptStatus::LOADING;
1623+ newDetails.definingSandboxURL = currentSandboxURL;
1624+ setEntityScriptDetails(entityID, newDetails);
1625+
1626+ auto scriptCache = DependencyManager::get<ScriptCache>();
1627+ // note: see EntityTreeRenderer.cpp for shared pointer lifecycle management
1628+ QWeakPointer<ScriptEngine> weakRef(sharedFromThis());
1629+ scriptCache->getScriptContents(entityScript,
1630+ [this, weakRef, entityScript, entityID](const QString& url, const QString& contents, bool isURL, bool success, const QString& status) {
1631+ QSharedPointer<ScriptEngine> strongRef(weakRef);
1632+ if (!strongRef) {
1633+ qCWarning(scriptengine) << "loadEntityScript.contentAvailable -- ScriptEngine was deleted during getScriptContents!!";
1634+ return;
1635+ }
1636+ if (isStopping()) {
1637+#ifdef DEBUG_ENTITY_STATES
1638+ qCDebug(scriptengine) << "loadEntityScript.contentAvailable -- stopping";
1639+#endif
1640+ return;
1641+ }
1642+ executeOnScriptThread([=]{
1643+#ifdef DEBUG_ENTITY_STATES
1644+ qCDebug(scriptengine) << "loadEntityScript.contentAvailable" << status << QUrl(url).fileName() << entityID.toString();
1645+#endif
1646+ if (!isStopping() && _entityScripts.contains(entityID)) {
1647+ entityScriptContentAvailable(entityID, url, contents, isURL, success, status);
1648+ } else {
1649+#ifdef DEBUG_ENTITY_STATES
1650+ qCDebug(scriptengine) << "loadEntityScript.contentAvailable -- aborting";
1651+#endif
1652+ }
1653+ // recheck whether us since may have been set to BAD_SCRIPT_UUID_PLACEHOLDER in entityScriptContentAvailable
1654+ if (_occupiedScriptURLs.contains(entityScript) && _occupiedScriptURLs[entityScript] == entityID) {
1655+ _occupiedScriptURLs.remove(entityScript);
1656+ }
1657+ });
1658+ }, forceRedownload);
15291659 }
15301660
15311661 // since all of these operations can be asynch we will always do the actual work in the response handler
@@ -1555,25 +1685,51 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co · 23 unmodified lines
15551685
15561686 auto scriptCache = DependencyManager::get<ScriptCache>();
15571687 bool isFileUrl = isURL && scriptOrURL.startsWith("file://");
1558− auto fileName = isURL ? scriptOrURL : "EmbeddedEntityScript";
1688+ auto fileName = isURL ? scriptOrURL : "about:EmbeddedEntityScript";
1689+
1690+ const EntityScriptDetails &oldDetails = _entityScripts[entityID];
1691+ const QString entityScript = oldDetails.scriptText;
15591692
15601693 EntityScriptDetails newDetails;
15611694 newDetails.scriptText = scriptOrURL;
15621695
1563− if (!success) {
1564− newDetails.status = EntityScriptStatus::ERROR_LOADING_SCRIPT;
1565− newDetails.errorInfo = "Failed to load script (" + status + ")";
1696+ // If an error happens below, we want to update newDetails with the new status info
1697+ // and also abort any pending Entity loads that are waiting on the exact same script URL.
1698+ auto setError = [&](const QString &errorInfo, const EntityScriptStatus& status) {
1699+ newDetails.errorInfo = errorInfo;
1700+ newDetails.status = status;
15661701 setEntityScriptDetails(entityID, newDetails);
1702+
1703+#ifdef DEBUG_ENTITY_STATES
1704+ qCDebug(scriptengine) << "entityScriptContentAvailable -- flagging " << entityScript << " as BAD_SCRIPT_UUID_PLACEHOLDER";
1705+#endif
1706+ // flag the original entityScript as unusuable
1707+ _occupiedScriptURLs[entityScript] = BAD_SCRIPT_UUID_PLACEHOLDER;
1708+ processDeferredEntityLoads(entityScript, entityID);
1709+ };
1710+
1711+ // NETWORK / FILESYSTEM ERRORS
1712+ if (!success) {
1713+ setError("Failed to load script (" + status + ")", EntityScriptStatus::ERROR_LOADING_SCRIPT);
15671714 return;
15681715 }
15691716
1717+ // SYNTAX ERRORS
15701718 auto syntaxError = lintScript(contents, fileName);
1719+ if (syntaxError.isError()) {
1720+ auto message = syntaxError.property("formatted").toString();
1721+ if (message.isEmpty()) {
1722+ message = syntaxError.toString();
1723+ }
1724+ setError(QString("Bad syntax (%1)").arg(message), EntityScriptStatus::ERROR_RUNNING_SCRIPT);
1725+ syntaxError.setProperty("detail", entityID.toString());
1726+ emit unhandledException(syntaxError);
1727+ return;
1728+ }
15711729 QScriptProgram program { contents, fileName };
1572− if (!syntaxError.isNull() || program.isNull()) {
1573− newDetails.status = EntityScriptStatus::ERROR_RUNNING_SCRIPT;
1574− newDetails.errorInfo = QString("Bad syntax (%1)").arg(syntaxError);
1575− setEntityScriptDetails(entityID, newDetails);
1576− qCDebug(scriptengine) << newDetails.errorInfo << scriptOrURL;
1730+ if (program.isNull()) {
1731+ setError("Bad program (isNull)", EntityScriptStatus::ERROR_RUNNING_SCRIPT);
1732+ emit unhandledException(makeError("program.isNull"));
15771733 return; // done processing script
15781734 }
15791735
@@ -1581,10 +1737,11 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co · 1 unmodified line
15811737 setParentURL(scriptOrURL);
15821738 }
15831739
1740+ // SANITY/PERFORMANCE CHECK USING SANDBOX
15841741 const int SANDBOX_TIMEOUT = 0.25 * MSECS_PER_SECOND;
15851742 BaseScriptEngine sandbox;
15861743 sandbox.setProcessEventsInterval(SANDBOX_TIMEOUT);
1587− QScriptValue testConstructor;
1744+ QScriptValue testConstructor, exception;
15881745 {
15891746 QTimer timeout;
15901747 timeout.setSingleShot(true);
@@ -1598,18 +1755,26 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co · 7 unmodified lines
15981755 context->throwError(QString("Timed out (entity constructors are limited to %1ms)").arg(SANDBOX_TIMEOUT));
15991756 }
16001757 });
1758+
16011759 testConstructor = sandbox.evaluate(program);
1760+
1761+ if (sandbox.hasUncaughtException()) {
1762+ exception = sandbox.cloneUncaughtException(QString("(preflight %1)").arg(entityID.toString()));
1763+ sandbox.clearExceptions();
1764+ } else if (testConstructor.isError()) {
1765+ exception = testConstructor;
1766+ }
16021767 }
16031768
1604− QString exceptionMessage = sandbox.formatUncaughtException(program.fileName());
1605− if (!exceptionMessage.isNull()) {
1606− newDetails.status = EntityScriptStatus::ERROR_RUNNING_SCRIPT;
1607− newDetails.errorInfo = exceptionMessage;
1608− setEntityScriptDetails(entityID, newDetails);
1609− qCDebug(scriptengine) << "----- ScriptEngine::entityScriptContentAvailable -- hadUncaughtExceptions (" << scriptOrURL << ")";
1769+ if (exception.isError()) {
1770+ // create a local copy using makeError to decouple from the sandbox engine
1771+ exception = makeError(exception);
1772+ setError(formatException(exception), EntityScriptStatus::ERROR_RUNNING_SCRIPT);
1773+ emit unhandledException(exception);
16101774 return;
16111775 }
16121776
1777+ // CONSTRUCTOR VIABILITY
16131778 if (!testConstructor.isFunction()) {
16141779 QString testConstructorType = QString(testConstructor.toVariant().typeName());
16151780 if (testConstructorType == "") {
@@ -1620,32 +1785,48 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co · 4 unmodified lines
16201785 if (testConstructorValue.size() > maxTestConstructorValueSize) {
16211786 testConstructorValue = testConstructorValue.mid(0, maxTestConstructorValueSize) + "...";
16221787 }
1623− scriptErrorMessage("Error -- ScriptEngine::loadEntityScript() entity:" + entityID.toString()
1624− + "failed to load entity script -- expected a function, got " + testConstructorType
1625− + "," + testConstructorValue
1626− + "," + scriptOrURL);
1788+ auto message = QString("failed to load entity script -- expected a function, got %1, %2")
1789+ .arg(testConstructorType).arg(testConstructorValue);
16271790
1628− newDetails.status = EntityScriptStatus::ERROR_RUNNING_SCRIPT;
1629− newDetails.errorInfo = "Could not find constructor";
1630− setEntityScriptDetails(entityID, newDetails);
1791+ auto err = makeError(message);
1792+ err.setProperty("fileName", scriptOrURL);
1793+ err.setProperty("detail", "(constructor " + entityID.toString() + ")");
16311794
1632− qCDebug(scriptengine) << "----- ScriptEngine::entityScriptContentAvailable -- failed to run (" << scriptOrURL << ")";
1795+ setError("Could not find constructor (" + testConstructorType + ")", EntityScriptStatus::ERROR_RUNNING_SCRIPT);
1796+ emit unhandledException(err);
16331797 return; // done processing script
16341798 }
16351799
1800+ // (this feeds into refreshFileScript)
16361801 int64_t lastModified = 0;
16371802 if (isFileUrl) {
16381803 QString file = QUrl(scriptOrURL).toLocalFile();
16391804 lastModified = (quint64)QFileInfo(file).lastModified().toMSecsSinceEpoch();
16401805 }
1806+
1807+ // THE ACTUAL EVALUATION AND CONSTRUCTION
16411808 QScriptValue entityScriptConstructor, entityScriptObject;
16421809 QUrl sandboxURL = currentSandboxURL.isEmpty() ? scriptOrURL : currentSandboxURL;
16431810 auto initialization = [&]{
16441811 entityScriptConstructor = evaluate(contents, fileName);
16451812 entityScriptObject = entityScriptConstructor.construct();
1813+
1814+ if (hasUncaughtException()) {
1815+ entityScriptObject = cloneUncaughtException("(construct " + entityID.toString() + ")");
1816+ clearExceptions();
1817+ }
16461818 };
1819+
16471820 doWithEnvironment(entityID, sandboxURL, initialization);
16481821
1822+ if (entityScriptObject.isError()) {
1823+ auto exception = entityScriptObject;
1824+ setError(formatException(exception), EntityScriptStatus::ERROR_RUNNING_SCRIPT);
1825+ emit unhandledException(exception);
1826+ return;
1827+ }
1828+
1829+ // ... AND WE HAVE LIFTOFF
16491830 newDetails.status = EntityScriptStatus::RUNNING;
16501831 newDetails.scriptObject = entityScriptObject;
16511832 newDetails.lastModified = lastModified;
@@ -1658,6 +1839,9 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co · 6 unmodified lines
16581839
16591840 // if we got this far, then call the preload method
16601841 callEntityScriptMethod(entityID, "preload");
1842+
1843+ _occupiedScriptURLs.remove(entityScript);
1844+ processDeferredEntityLoads(entityScript, entityID);
16611845 }
16621846
16631847 void ScriptEngine::unloadEntityScript(const EntityItemID& entityID) {
@@ -1677,13 +1861,25 @@ void ScriptEngine::unloadEntityScript(const EntityItemID& entityID) { · 13 unmodified lines
16771861 #endif
16781862
16791863 if (_entityScripts.contains(entityID)) {
1864+ const EntityScriptDetails &oldDetails = _entityScripts[entityID];
16801865 if (isEntityScriptRunning(entityID)) {
16811866 callEntityScriptMethod(entityID, "unload");
1867+ } else {
1868+ qCDebug(scriptengine) << "unload called while !running" << entityID << oldDetails.status;
1869+ }
1870+ if (oldDetails.status != EntityScriptStatus::UNLOADED) {
1871+ EntityScriptDetails newDetails;
1872+ newDetails.status = EntityScriptStatus::UNLOADED;
1873+ newDetails.lastModified = QDateTime::currentMSecsSinceEpoch();
1874+ // keep scriptText populated for the current need to "debouce" duplicate calls to unloadEntityScript
1875+ newDetails.scriptText = oldDetails.scriptText;
1876+ setEntityScriptDetails(entityID, newDetails);
16821877 }
1683− EntityScriptDetails newDetails;
1684− newDetails.status = EntityScriptStatus::UNLOADED;
1685− setEntityScriptDetails(entityID, newDetails);
16861878 stopAllTimersForEntityScript(entityID);
1879+ {
1880+ // FIXME: shouldn't have to do this here, but currently something seems to be firing unloads moments after firing initial load requests
1881+ processDeferredEntityLoads(oldDetails.scriptText, entityID);
1882+ }
16871883 }
16881884 }
16891885
@@ -1704,15 +1900,14 @@ void ScriptEngine::unloadAllEntityScripts() { · 14 unmodified lines
17041900 }
17051901 _entityScripts.clear();
17061902 emit entityScriptDetailsUpdated();
1903+ _occupiedScriptURLs.clear();
17071904
17081905 #ifdef DEBUG_ENGINE_STATE
1709− qCDebug(scriptengine) << "---- CURRENT STATE OF ENGINE: --------------------------";
1710− QScriptValueIterator it(globalObject());
1711− while (it.hasNext()) {
1712− it.next();
1713− qCDebug(scriptengine) << it.name() << ":" << it.value().toString();
1714− }
1715− qCDebug(scriptengine) << "--------------------------------------------------------";
1906+ _debugDump(
1907+ "---- CURRENT STATE OF ENGINE: --------------------------",
1908+ globalObject(),
1909+ "--------------------------------------------------------"
1910+ );
17161911 #endif // DEBUG_ENGINE_STATE
17171912 }
17181913
@@ -1734,17 +1929,7 @@ void ScriptEngine::refreshFileScript(const EntityItemID& entityID) { · 15 unmodified lines
17341929 auto lastModified = QFileInfo(filePath).lastModified().toMSecsSinceEpoch();
17351930 if (lastModified > details.lastModified) {
17361931 scriptInfoMessage("Reloading modified script " + details.scriptText);
1737−
1738− QFile file(filePath);
1739− file.open(QIODevice::ReadOnly);
1740− QString scriptContents = QTextStream(&file).readAll();
1741− this->unloadEntityScript(entityID);
1742− this->entityScriptContentAvailable(entityID, details.scriptText, scriptContents, true, true, "Success");
1743− if (!isEntityScriptRunning(entityID)) {
1744− scriptWarningMessage("Reload script " + details.scriptText + " failed");
1745− } else {
1746− details = _entityScripts[entityID];
1747− }
1932+ loadEntityScript(entityID, details.scriptText, true);
17481933 }
17491934 }
17501935 recurseGuard = false;
@@ -1768,14 +1953,14 @@ void ScriptEngine::doWithEnvironment(const EntityItemID& entityID, const QUrl& s · 17 unmodified lines
17681953 #else
17691954 operation();
17701955 #endif
1771− if (hasUncaughtException()) {
1772− reportUncaughtException();
1956+ if (!isEvaluating() && hasUncaughtException()) {
1957+ emit unhandledException(cloneUncaughtException(!entityID.isNull() ? entityID.toString() : __FUNCTION__));
17731958 clearExceptions();
17741959 }
1775−
17761960 currentEntityIdentifier = oldIdentifier;
17771961 currentSandboxURL = oldSandboxURL;
17781962 }
1963+
17791964 void ScriptEngine::callWithEnvironment(const EntityItemID& entityID, const QUrl& sandboxURL, QScriptValue function, QScriptValue thisObject, QScriptValueList args) {
17801965 auto operation = [&]() {
17811966 function.call(thisObject, args);
@@ -1850,7 +2035,6 @@ void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QS · 68 unmodified lines
18502035 }
18512036 }
18522037
1853−
18542038 void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QString& methodName, const EntityItemID& otherID, const Collision& collision) {
18552039 if (QThread::currentThread() != thread()) {
18562040 #ifdef THREAD_DEBUGGING
@@ -1885,3 +2069,4 @@ void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QS · 28 unmodified lines
18852069 }
18862070 }
18872071 }
2072+