* Switch trigger for deferred loads from timer to using leading entity completion

* Bring back notion of tracking "bad scripts" to fail stampeding entities as a set
* Update stampede JS tests to highlight/troubleshoot preexisting unload issue

libraries/script-engine/src/ScriptEngine.cpp

@@ -1496,67 +1496,58 @@ const auto RETRY_ATTEMPT_BATCH = 100; //glm::clamp(qgetenv("RETRY_ATTEMPT_BATCH"
 const auto RETRY_ATTEMPT_MSECS = 250; //glm::clamp(qgetenv("RETRY_ATTEMPT_MSECS").toInt(), 50, 1000);
 const static EntityItemID BAD_SCRIPT_UUID_PLACEHOLDER { "{20170224-dead-face-0000-cee000021114}" };
 
-void ScriptEngine::deferLoadEntityScript(const EntityItemID& entityID, const QString& entityScript, bool forceRedownload) {
+void ScriptEngine::processDeferredEntityLoads(const QString& entityScript, const EntityItemID& leaderID) {
-    const auto needTimer = _pendingLoadEntities.isEmpty();
+    QList<DeferredLoadEntity> retryLoads;
-    // NOTE: forceRedownload isn't forwarded here because deferLoadEntityScript() is only ever called when another entity has taken lead for the script
+    QMutableListIterator<DeferredLoadEntity> i(_deferredEntityLoads);
-    _pendingLoadEntities.push_back({ entityID, entityScript/*, forceRedownload*/ });
+    while (i.hasNext()) {
+        auto retry = i.next();
+        if (retry.entityScript == entityScript) {
+            retryLoads << retry;
+            i.remove();
+        }
+    }
+    foreach(auto &retry, retryLoads) {
+        // check whether entity was since been deleted
+        if (!_entityScripts.contains(retry.entityID)) {
+            qCDebug(scriptengine) << "processDeferredEntityLoads -- entity details gone (entity deleted?)"
+                                  << retry.entityID;
+            continue;
+        }
 
-    auto processDeferredEntities = [this](QScriptContext* context, QScriptEngine*) -> QScriptValue {
+        // check whether entity has since been unloaded or otherwise errored-out
-        QList<DeferredLoadEntity> stillPending;
+        auto details = _entityScripts[retry.entityID];
+        if (details.status != EntityScriptStatus::PENDING) {
+            qCDebug(scriptengine) << "processDeferredEntityLoads -- entity status no longer PENDING; "
+                                  << retry.entityID << details.status;
+            continue;
+        }
 
-        for (int i=0; i < RETRY_ATTEMPT_BATCH && !_pendingLoadEntities.isEmpty(); i++) {
+        // propagate leader's failure reasons to the pending entity
-            auto retry = _pendingLoadEntities.takeFirst();
+        const auto leaderDetails = _entityScripts[leaderID];
-            qCDebug(scriptengine) << "deferLoadEntityScript.retry[" << i << "]:" << retry.entityID << retry.entityScript;
+        if (leaderDetails.status != EntityScriptStatus::RUNNING) {
-            if (!_entityScripts.contains(retry.entityID)) {
+            qCDebug(scriptengine) << QString("... pending load of %1 cancelled (leader: %2 status: %3)")
-                qCDebug(scriptengine) << "deferLoadEntityScript.retry -- entity details gone (entity deleted?)";
+                .arg(retry.entityID.toString()).arg(leaderID.toString()).arg(leaderDetails.status);
+
+            auto extraDetail = "\n(propagated from " + leaderID.toString() + ")";
+            if (leaderDetails.status == EntityScriptStatus::ERROR_LOADING_SCRIPT ||
+                leaderDetails.status == EntityScriptStatus::ERROR_RUNNING_SCRIPT) {
+                // propagate same error so User doesn't have to hunt down stampede's leader
+                updateEntityScriptStatus(retry.entityID, leaderDetails.status, leaderDetails.errorInfo + extraDetail);
             } else {
-                auto details = _entityScripts[retry.entityID];
+                // the leader Entity somehow ended up in some other state (rapid-fire delete or unload could cause)
-                if (details.status != EntityScriptStatus::PENDING) {
+                updateEntityScriptStatus(retry.entityID, EntityScriptStatus::ERROR_LOADING_SCRIPT,
-                    qCDebug(scriptengine) << "deferLoadEntityScript.retry -- entity status no longer PENDING; " << details.status;
+                    "A previous Entity failed to load using this script URL; reload to try again." + extraDetail);
-                } else {
-                    if (!_occupiedScriptURLs.contains(retry.entityScript)) {
-                        // the URL is no longer busy with another Entity, so now it's our turn
-                        loadEntityScript(retry.entityID, retry.entityScript, false);
-                    } else {
-                        auto entityID = _occupiedScriptURLs[retry.entityScript];
-                        if (entityID == BAD_SCRIPT_UUID_PLACEHOLDER) {
-                            // the URL was marked bad by an earlier load attempt, so abort the retry mission
-                            qCDebug(scriptengine) << "... pending load of " << retry.entityID << " cancelled";
-                        } else {
-                            // the URL is still occupied by another Entity, so add to next retry pass
-                            stillPending << retry;
-                        }
-                    }
-                }
             }
+            continue;
         }
-        foreach(const DeferredLoadEntity& retry, stillPending) {
+
-            _pendingLoadEntities.push_back(retry);
+        if (_occupiedScriptURLs.contains(retry.entityScript)) {
+            qCWarning(scriptengine) << "--- SHOULD NOT HAPPEN -- recursive call into processDeferredEntityLoads" << retry.entityScript;
+            continue;
         }
-        if (_pendingLoadEntities.isEmpty()) {
-            QObject *interval = context->callee().property("interval").toQObject();
-            // we're done processing so can kill the timer
-            qCDebug(scriptengine) << "loadEntityScript.retry queue processing complete -- exiting" << interval;
-            if (interval) {
-                clearInterval(interval);
-            }
-        }
-        return QScriptValue();
-    };
 
-    if (needTimer) {
+        // if we made it here then the leading entity was successful so proceed with normal load
-        // we were the first to get queued -- so set up an interval timer for deferred processing
+        loadEntityScript(retry.entityID, retry.entityScript, false);
-        qCDebug(scriptengine) << "deferLoadEntityScript -- scheduling timer " << RETRY_ATTEMPT_MSECS;
-
-        // processDeferredEntities gets wrapped as a "regular" JavaScript callback so that it can then
-        // be scheduled using setInterval per usual -- allowing the script engine to own its lifecycle.
-        // we stil need to call clearInterval manually when done, so its passed to callee() above as a property.
-
-        QScriptValue function = newLambdaFunction(processDeferredEntities, "processDeferredEntities-loader");
-        QObject *interval = setInterval( function, RETRY_ATTEMPT_MSECS );
-
-        // make the interval reachable from the handler
-        function.setProperty("interval", newQObject(interval));
     }
 }
 
@@ -1587,28 +1578,33 @@ void ScriptEngine::loadEntityScript(const EntityItemID& entityID, const QString&
     // This "occupied" approach allows multiple Entities to boot from the same script URL while still taking
     // full advantage of cacheable require modules.  This only affects Entities literally coming in back-to-back
     // before the first one has time to finish loading.
-    if (!_occupiedScriptURLs.contains(entityScript)) {
+    if (_occupiedScriptURLs.contains(entityScript)) {
-        // the scriptURL is available -- flag as in-use and proceed
-        _occupiedScriptURLs[entityScript] = entityID;
-    } else {
-        // another Entity is either still booting from this script URL or has failed and marked it "out of order"
         auto currentEntityID = _occupiedScriptURLs[entityScript];
-        if (currentEntityID == BAD_SCRIPT_UUID_PLACEHOLDER && !forceRedownload) {
+        if (currentEntityID == BAD_SCRIPT_UUID_PLACEHOLDER) {
-            // since not force-reloading, assume that the exact same input would produce the exact same output again
+            if (forceRedownload) {
-            // note: this state gets reset with "reload all scripts," leaving/returning to a Domain, clear cache, etc.
+                // script was previously marked unusable, but we're reloading so reset it
-            qCDebug(scriptengine) << QString("loadEntityScript.cancelled entity: %1 script: %2 (previous script failure)")
+                _occupiedScriptURLs.remove(entityScript);
-                .arg(entityID.toString()).arg(entityScript);
+            } else {
-            updateEntityScriptStatus(entityID, EntityScriptStatus::ERROR_LOADING_SCRIPT,
+                // since not reloading, assume that the exact same input would produce the exact same output again
-                                     "Cached Script was marked invalid by previous Entity load failure.");
+                // note: this state gets reset with "reload all scripts," leaving/returning to a Domain, clear cache, etc.
+                qCDebug(scriptengine) << QString("loadEntityScript.cancelled entity: %1 script: %2 (previous script failure)")
+                    .arg(entityID.toString()).arg(entityScript);
+                updateEntityScriptStatus(entityID, EntityScriptStatus::ERROR_LOADING_SCRIPT,
+                                         "A previous Entity failed to load using this script URL; reload to try again.");
+                return;
+            }
         } else {
             // another entity is busy loading from this script URL so wait for them to finish
-            qCDebug(scriptengine) << QString("loadEntityScript.deferring[%0] entity: %1 script: %2")
+            qCDebug(scriptengine) << QString("loadEntityScript.deferring[%0] entity: %1 script: %2 (waiting on %3)")
-                .arg( _pendingLoadEntities.size()).arg(entityID.toString()).arg(entityScript);
+                .arg( _deferredEntityLoads.size()).arg(entityID.toString()).arg(entityScript).arg(currentEntityID.toString());
-            deferLoadEntityScript(entityID, entityScript, forceRedownload);
+            _deferredEntityLoads.push_back({ entityID, entityScript });
+            return;
         }
-        return;
     }
 
+    // the scriptURL slot is available; flag as in-use
+    _occupiedScriptURLs[entityScript] = entityID;
+
 #ifdef DEBUG_ENTITY_STATES
     auto previousStatus = _entityScripts.contains(entityID) ? _entityScripts[entityID].status : EntityScriptStatus::PENDING;
     qCDebug(scriptengine) << "loadEntityScript.LOADING: " << entityScript << entityID.toString()
@@ -1642,7 +1638,7 @@ void ScriptEngine::loadEntityScript(const EntityItemID& entityID, const QString&
 #endif
                 }
                 // recheck whether us since may have been set to BAD_SCRIPT_UUID_PLACEHOLDER in entityScriptContentAvailable
-                if (_occupiedScriptURLs[entityScript] == entityID) {
+                if (_occupiedScriptURLs.contains(entityScript) && _occupiedScriptURLs[entityScript] == entityID) {
                     _occupiedScriptURLs.remove(entityScript);
                 }
             });
@@ -1679,6 +1675,8 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co
     auto fileName = isURL ? scriptOrURL : "about:EmbeddedEntityScript";
 
     const EntityScriptDetails &oldDetails = _entityScripts[entityID];
+    const auto entityScript = oldDetails.scriptText;
+
     EntityScriptDetails newDetails;
     newDetails.scriptText = scriptOrURL;
 
@@ -1689,10 +1687,10 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co
         newDetails.status = status;
         setEntityScriptDetails(entityID, newDetails);
 
-        qCDebug(scriptengine) << "entityScriptContentAvailable -- flagging " << oldDetails.scriptText << " as BAD_SCRIPT_UUID_PLACEHOLDER";
+        qCDebug(scriptengine) << "entityScriptContentAvailable -- flagging " << entityScript << " as BAD_SCRIPT_UUID_PLACEHOLDER";
-        // flag this scriptURL as unusuable
+        // flag the original entityScript as unusuable
-        // note: we want the *original* entityScript string (not the potentially normalized one from ScriptCache results)
+        _occupiedScriptURLs[entityScript] = BAD_SCRIPT_UUID_PLACEHOLDER;
-        _occupiedScriptURLs[oldDetails.scriptText] = BAD_SCRIPT_UUID_PLACEHOLDER;
+        processDeferredEntityLoads(entityScript, entityID);
     };
 
     // NETWORK / FILESYSTEM ERRORS
@@ -1826,6 +1824,9 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co
 
     // if we got this far, then call the preload method
     callEntityScriptMethod(entityID, "preload");
+
+    _occupiedScriptURLs.remove(entityScript);
+    processDeferredEntityLoads(entityScript, entityID);
 }
 
 void ScriptEngine::unloadEntityScript(const EntityItemID& entityID) {
@@ -1845,14 +1846,25 @@ void ScriptEngine::unloadEntityScript(const EntityItemID& entityID) {
 #endif
 
     if (_entityScripts.contains(entityID)) {
+        auto oldDetails = _entityScripts[entityID];
         if (isEntityScriptRunning(entityID)) {
             callEntityScriptMethod(entityID, "unload");
+        } else {
+            qCDebug(scriptengine) << "unload called while !running" << entityID << oldDetails.status;
+        }
+        if (oldDetails.status != EntityScriptStatus::UNLOADED) {
+            EntityScriptDetails newDetails;
+            newDetails.status = EntityScriptStatus::UNLOADED;
+            newDetails.lastModified = QDateTime::currentMSecsSinceEpoch();
+            // keep scriptText populated for the current need to "debouce" duplicate calls to unloadEntityScript
+            newDetails.scriptText = oldDetails.scriptText;
+            setEntityScriptDetails(entityID, newDetails);
         }
-        EntityScriptDetails newDetails;
-        newDetails.status = EntityScriptStatus::UNLOADED;
-        newDetails.lastModified = QDateTime::currentMSecsSinceEpoch();
-        setEntityScriptDetails(entityID, newDetails);
         stopAllTimersForEntityScript(entityID);
+        {
+            // FIXME: shouldn't have to do this here, but currently something seems to be firing unloads moments after firing initial load requests
+            processDeferredEntityLoads(oldDetails.scriptText, entityID);
+        }
     }
 }
 
@@ -1902,17 +1914,7 @@ void ScriptEngine::refreshFileScript(const EntityItemID& entityID) {
         auto lastModified = QFileInfo(filePath).lastModified().toMSecsSinceEpoch();
         if (lastModified > details.lastModified) {
             scriptInfoMessage("Reloading modified script " + details.scriptText);
-
+            loadEntityScript(entityID, details.scriptText, true);
-            QFile file(filePath);
-            file.open(QIODevice::ReadOnly);
-            QString scriptContents = QTextStream(&file).readAll();
-            this->unloadEntityScript(entityID);
-            this->entityScriptContentAvailable(entityID, details.scriptText, scriptContents, true, true, "Success");
-            if (!isEntityScriptRunning(entityID)) {
-                scriptWarningMessage("Reload script " + details.scriptText + " failed");
-            } else {
-                details = _entityScripts[entityID];
-            }
         }
     }
     recurseGuard = false;

libraries/script-engine/src/ScriptEngine.h

@@ -170,7 +170,6 @@ public:
     Q_INVOKABLE bool isEntityScriptRunning(const EntityItemID& entityID) {
         return _entityScripts.contains(entityID) && _entityScripts[entityID].status == EntityScriptStatus::RUNNING;
     }
-    Q_INVOKABLE void deferLoadEntityScript(const EntityItemID& entityID, const QString& entityScript, bool forceRedownload);
     Q_INVOKABLE void loadEntityScript(const EntityItemID& entityID, const QString& entityScript, bool forceRedownload);
     Q_INVOKABLE void unloadEntityScript(const EntityItemID& entityID); // will call unload method
     Q_INVOKABLE void unloadAllEntityScripts();
@@ -247,6 +246,7 @@ protected:
     void updateEntityScriptStatus(const EntityItemID& entityID, const EntityScriptStatus& status, const QString& errorInfo = QString());
     void setEntityScriptDetails(const EntityItemID& entityID, const EntityScriptDetails& details);
     void setParentURL(const QString& parentURL) { _parentURL = parentURL; }
+    void processDeferredEntityLoads(const QString& entityScript, const EntityItemID& leaderID);
 
     QObject* setupTimerWithInterval(const QScriptValue& function, int intervalMS, bool isSingleShot);
     void stopTimer(QTimer* timer);
@@ -271,7 +271,7 @@ protected:
     QSet<QUrl> _includedURLs;
     QHash<EntityItemID, EntityScriptDetails> _entityScripts;
     QHash<QString, EntityItemID> _occupiedScriptURLs;
-    QList<DeferredLoadEntity> _pendingLoadEntities;
+    QList<DeferredLoadEntity> _deferredEntityLoads;
 
     bool _isThreaded { false };
     QScriptEngineDebugger* _debugger { nullptr };

scripts/developer/tests/entityServerStampedeTest-entity.js

@@ -0,0 +1,21 @@
+(function() {
+    return {
+        preload: function(uuid) {
+            var props = Entities.getEntityProperties(uuid);
+            var shape = props.shape === 'Sphere' ? 'Hexagon' : 'Sphere';
+
+            Entities.editEntity(uuid, {
+                shape: shape,
+                color: { red: 0xff, green: 0xff, blue: 0xff },
+            });
+            this.name = props.name;
+            print("preload", this.name);
+        },
+        unload: function(uuid) {
+            print("unload", this.name);
+            Entities.editEntity(uuid, {
+                color: { red: 0x0f, green: 0x0f, blue: 0xff },
+            });
+        },
+    };
+})

scripts/developer/tests/entityServerStampedeTest.js

@@ -1,7 +1,7 @@
 var NUM_ENTITIES = 100;
 var RADIUS = 2;
 var DIV = NUM_ENTITIES / Math.PI / 2;
-var PASS_SCRIPT_URL = Script.resolvePath('entityStampedeTest-entity.js');
+var PASS_SCRIPT_URL = Script.resolvePath('entityServerStampedeTest-entity.js');
 var FAIL_SCRIPT_URL = Script.resolvePath('entityStampedeTest-entity-fail.js');
 
 var origin = Vec3.sum(MyAvatar.position, Vec3.multiply(5, Quat.getFront(MyAvatar.orientation)));

scripts/developer/tests/entityStampedeTest-entity.js

@@ -1,12 +1,21 @@
 (function() {
     return {
         preload: function(uuid) {
-            var shape = Entities.getEntityProperties(uuid).shape === 'Sphere' ? 'Cube' : 'Sphere';
+            var props = Entities.getEntityProperties(uuid);
+            var shape = props.shape === 'Sphere' ? 'Cube' : 'Sphere';
 
             Entities.editEntity(uuid, {
                 shape: shape,
                 color: { red: 0xff, green: 0xff, blue: 0xff },
             });
-        }
+            this.name = props.name;
+            print("preload", this.name);
+        },
+        unload: function(uuid) {
+            print("unload", this.name);
+            Entities.editEntity(uuid, {
+                color: { red: 0xff, green: 0x0f, blue: 0x0f },
+            });
+        },
     };
 })