Merge pull request #8730 from huffman/feat/script-req-retry

Add retrying of script requests

assignment-client/src/Agent.cpp

@@ -61,6 +61,7 @@ Agent::Agent(ReceivedMessage& message) :
     DependencyManager::set<recording::Deck>();
     DependencyManager::set<recording::Recorder>();
     DependencyManager::set<RecordingScriptingInterface>();
+    DependencyManager::set<ScriptCache>();
 
     auto& packetReceiver = DependencyManager::get<NodeList>()->getPacketReceiver();
 

libraries/networking/src/AssetClient.cpp

@@ -394,12 +394,14 @@ void AssetClient::handleCompleteCallback(const QWeakPointer<Node>& node, Message
     auto senderNode = node.toStrongRef();
 
     if (!senderNode) {
+        qCWarning(asset_client) << "Got completed asset for node that no longer exists";
         return;
     }
 
     // Check if we have any pending requests for this node
     auto messageMapIt = _pendingRequests.find(senderNode);
     if (messageMapIt == _pendingRequests.end()) {
+        qCWarning(asset_client) << "Got completed asset for a node that doesn't have any pending requests";
         return;
     }
 
@@ -409,6 +411,7 @@ void AssetClient::handleCompleteCallback(const QWeakPointer<Node>& node, Message
     // Check if we have this pending request
     auto requestIt = messageCallbackMap.find(messageID);
     if (requestIt == messageCallbackMap.end()) {
+        qCWarning(asset_client) << "Got completed asset for a request that doesn't exist";
         return;
     }
 
@@ -416,6 +419,7 @@ void AssetClient::handleCompleteCallback(const QWeakPointer<Node>& node, Message
     auto& message = callbacks.message;
 
     if (!message) {
+        qCWarning(asset_client) << "Got completed asset for a message that doesn't exist";
         return;
     }
 

libraries/networking/src/AssetRequest.cpp

@@ -107,9 +107,11 @@ void AssetRequest::start() {
         
         auto assetClient = DependencyManager::get<AssetClient>();
         auto that = QPointer<AssetRequest>(this); // Used to track the request's lifetime
+        auto hash = _hash;
         _assetRequestID = assetClient->getAsset(_hash, start, end,
-                [this, that, start, end](bool responseReceived, AssetServerError serverError, const QByteArray& data) {
+                [this, that, hash, start, end](bool responseReceived, AssetServerError serverError, const QByteArray& data) {
             if (!that) {
+                qCWarning(asset_client) << "Got reply for dead asset request " << hash << "- error code" << _error;
                 // If the request is dead, return
                 return;
             }

libraries/networking/src/AssetRequest.h

@@ -49,6 +49,7 @@ public:
     const State& getState() const { return _state; }
     const Error& getError() const { return _error; }
     QUrl getUrl() const { return ::getATPUrl(_hash); }
+    QString getHash() const { return _hash; }
 
 signals:
     void finished(AssetRequest* thisRequest);

libraries/networking/src/AssetResourceRequest.cpp

@@ -14,6 +14,7 @@
 #include "AssetClient.h"
 #include "AssetUtils.h"
 #include "MappingRequest.h"
+#include <QtCore/qloggingcategory.h>
 
 AssetResourceRequest::~AssetResourceRequest() {
     if (_assetMappingRequest) {
@@ -23,6 +24,10 @@ AssetResourceRequest::~AssetResourceRequest() {
     if (_assetRequest) {
         _assetRequest->deleteLater();
     }
+
+    if (_sendTimer) {
+        cleanupTimer();
+    }
 }
 
 bool AssetResourceRequest::urlIsAssetHash() const {
@@ -32,6 +37,24 @@ bool AssetResourceRequest::urlIsAssetHash() const {
     return hashRegex.exactMatch(_url.toString());
 }
 
+void AssetResourceRequest::setupTimer() {
+    Q_ASSERT(!_sendTimer);
+    static const int TIMEOUT_MS = 2000;
+
+    _sendTimer = new QTimer(this);
+    connect(_sendTimer, &QTimer::timeout, this, &AssetResourceRequest::onTimeout);
+
+    _sendTimer->setSingleShot(true);
+    _sendTimer->start(TIMEOUT_MS);
+}
+
+void AssetResourceRequest::cleanupTimer() {
+    Q_ASSERT(_sendTimer);
+    disconnect(_sendTimer, 0, this, 0);
+    _sendTimer->deleteLater();
+    _sendTimer = nullptr;
+}
+
 void AssetResourceRequest::doSend() {
     // We'll either have a hash or an ATP path to a file (that maps to a hash)
     if (urlIsAssetHash()) {
@@ -58,6 +81,8 @@ void AssetResourceRequest::requestMappingForPath(const AssetPath& path) {
         Q_ASSERT(_state == InProgress);
         Q_ASSERT(request == _assetMappingRequest);
 
+        cleanupTimer();
+
         switch (request->getError()) {
             case MappingRequest::NoError:
                 // we have no error, we should have a resulting hash - use that to send of a request for that asset
@@ -93,6 +118,7 @@ void AssetResourceRequest::requestMappingForPath(const AssetPath& path) {
         _assetMappingRequest = nullptr;
     });
 
+    setupTimer();
     _assetMappingRequest->start();
 }
 
@@ -102,11 +128,13 @@ void AssetResourceRequest::requestHash(const AssetHash& hash) {
     auto assetClient = DependencyManager::get<AssetClient>();
     _assetRequest = assetClient->createRequest(hash);
 
-    connect(_assetRequest, &AssetRequest::progress, this, &AssetResourceRequest::progress);
+    connect(_assetRequest, &AssetRequest::progress, this, &AssetResourceRequest::onDownloadProgress);
     connect(_assetRequest, &AssetRequest::finished, this, [this](AssetRequest* req) {
         Q_ASSERT(_state == InProgress);
         Q_ASSERT(req == _assetRequest);
         Q_ASSERT(req->getState() == AssetRequest::Finished);
+
+        cleanupTimer();
         
         switch (req->getError()) {
             case AssetRequest::Error::NoError:
@@ -134,9 +162,35 @@ void AssetResourceRequest::requestHash(const AssetHash& hash) {
         _assetRequest = nullptr;
     });
 
+    setupTimer();
     _assetRequest->start();
 }
 
 void AssetResourceRequest::onDownloadProgress(qint64 bytesReceived, qint64 bytesTotal) {
+    Q_ASSERT(_state == InProgress);
+
+    // We've received data, so reset the timer
+    _sendTimer->start();
+
     emit progress(bytesReceived, bytesTotal);
 }
+
+void AssetResourceRequest::onTimeout() {
+    if (_state == InProgress) {
+        qWarning() << "Asset request timed out: " << _url;
+        if (_assetRequest) {
+            disconnect(_assetRequest, 0, this, 0);
+            _assetRequest->deleteLater();
+            _assetRequest = nullptr;
+        }
+        if (_assetMappingRequest) {
+            disconnect(_assetMappingRequest, 0, this, 0);
+            _assetMappingRequest->deleteLater();
+            _assetMappingRequest = nullptr;
+        }
+        _result = Timeout;
+        _state = Finished;
+        emit finished();
+    }
+    cleanupTimer();
+}

libraries/networking/src/AssetResourceRequest.h

@@ -28,13 +28,19 @@ protected:
 
 private slots:
     void onDownloadProgress(qint64 bytesReceived, qint64 bytesTotal);
+    void onTimeout();
 
 private:
+    void setupTimer();
+    void cleanupTimer();
+
     bool urlIsAssetHash() const;
 
     void requestMappingForPath(const AssetPath& path);
     void requestHash(const AssetHash& hash);
 
+    QTimer* _sendTimer { nullptr };
+
     GetMappingRequest* _assetMappingRequest { nullptr };
     AssetRequest* _assetRequest { nullptr };
 };

libraries/script-engine/src/AssetScriptingInterface.cpp

@@ -21,7 +21,6 @@
 AssetScriptingInterface::AssetScriptingInterface(QScriptEngine* engine) :
     _engine(engine)
 {
-
 }
 
 void AssetScriptingInterface::uploadData(QString data, QScriptValue callback) {

libraries/script-engine/src/BatchLoader.cpp

@@ -13,12 +13,14 @@
 #include <QNetworkReply>
 
 #include <QFile>
+#include <QPointer>
 #include "ScriptEngineLogging.h"
 #include "BatchLoader.h"
 #include <NetworkAccessManager.h>
 #include <SharedUtil.h>
 #include "ResourceManager.h"
 #include "ScriptEngines.h"
+#include "ScriptCache.h"
 
 BatchLoader::BatchLoader(const QList<QUrl>& urls) 
     : QObject(),
@@ -38,30 +40,25 @@ void BatchLoader::start() {
 
     for (const auto& rawURL : _urls) {
         QUrl url = expandScriptUrl(normalizeScriptURL(rawURL));
-        auto request = ResourceManager::createResourceRequest(this, url);
+
-        if (!request) {
+        qCDebug(scriptengine) << "Loading script at " << url;
-            _data.insert(url, QString());
+
-            qCDebug(scriptengine) << "Could not load" << url;
+        QPointer<BatchLoader> self = this;
-            continue;
+        DependencyManager::get<ScriptCache>()->getScriptContents(url.toString(), [this, self](const QString& url, const QString& contents, bool isURL, bool success) {
-        }
+            if (!self) {
-        connect(request, &ResourceRequest::finished, this, [=]() {
+                return;
-            if (request->getResult() == ResourceRequest::Success) {
+            }
-                _data.insert(url, request->getData());
+            if (isURL && success) {
+                _data.insert(url, contents);
+                qCDebug(scriptengine) << "Loaded: " << url;
             } else {
                 _data.insert(url, QString());
                 qCDebug(scriptengine) << "Could not load" << url;
             }
-            request->deleteLater();
             checkFinished();
-        });
+        }, false);
-
-        // If we end up being destroyed before the reply finishes, clean it up
-        connect(this, &QObject::destroyed, request, &QObject::deleteLater);
-
-        qCDebug(scriptengine) << "Loading script at " << url;
-
-        request->send();
     }
+
     checkFinished();
 }
 

libraries/script-engine/src/ScriptCache.cpp

@@ -25,6 +25,7 @@
 
 #include "ScriptEngines.h"
 #include "ScriptEngineLogging.h"
+#include <QtCore/QTimer>
 
 ScriptCache::ScriptCache(QObject* parent) {
     // nothing to do here...
@@ -133,8 +134,11 @@ void ScriptCache::getScriptContents(const QString& scriptOrURL, contentAvailable
         qCDebug(scriptengine) << "Found script in cache:" << url.toString();
         contentAvailable(url.toString(), scriptContent, true, true);
     } else {
-        bool alreadyWaiting = _contentCallbacks.contains(url);
+        auto& scriptRequest = _activeScriptRequests[url];
-        _contentCallbacks.insert(url, contentAvailable);
+
+        bool alreadyWaiting = scriptRequest.scriptUsers.size() > 0;
+        scriptRequest.scriptUsers.push_back(contentAvailable);
+
         lock.unlock();
 
         if (alreadyWaiting) {
@@ -152,6 +156,9 @@ void ScriptCache::getScriptContents(const QString& scriptOrURL, contentAvailable
     }
 }
 
+static const int MAX_RETRIES = 5;
+static int START_DELAY_BETWEEN_RETRIES = 200;
+
 void ScriptCache::scriptContentAvailable() {
     #ifdef THREAD_DEBUGGING
     qCDebug(scriptengine) << "ScriptCache::scriptContentAvailable() on thread [" << QThread::currentThread() << "] expected thread [" << thread() << "]";
@@ -160,29 +167,59 @@ void ScriptCache::scriptContentAvailable() {
     QUrl url = req->getUrl();
 
     QString scriptContent;
-    QList<contentAvailableCallback> allCallbacks;
+    std::vector<contentAvailableCallback> allCallbacks;
+    bool finished { false };
     bool success { false };
 
     {
-        Lock lock(_containerLock);
-        allCallbacks = _contentCallbacks.values(url);
-        _contentCallbacks.remove(url);
         Q_ASSERT(req->getState() == ResourceRequest::Finished);
         success = req->getResult() == ResourceRequest::Success;
 
-        if (success) {
+        Lock lock(_containerLock);
-            _scriptCache[url] = scriptContent = req->getData();
+
-            qCDebug(scriptengine) << "Done downloading script at:" << url.toString();
+        if (_activeScriptRequests.contains(url)) {
-        } else {
+            auto& scriptRequest = _activeScriptRequests[url];
-            // Dubious, but retained here because it matches the behavior before fixing the threading
+
-            scriptContent = _scriptCache[url];
+            if (success) {
-            qCWarning(scriptengine) << "Error loading script from URL " << url;
+                allCallbacks = scriptRequest.scriptUsers;
+
+                _activeScriptRequests.remove(url);
+
+                _scriptCache[url] = scriptContent = req->getData();
+                finished = true;
+                qCDebug(scriptengine) << "Done downloading script at:" << url.toString();
+            } else {
+                if (scriptRequest.numRetries < MAX_RETRIES) {
+                    ++scriptRequest.numRetries;
+
+                    qDebug() << "Script request failed: " << url;
+
+                    int timeout = exp(scriptRequest.numRetries) * START_DELAY_BETWEEN_RETRIES;
+                    QTimer::singleShot(timeout, this, [this, url]() {
+                        qDebug() << "Retrying script request: " << url;
+
+                        auto request = ResourceManager::createResourceRequest(nullptr, url);
+                        Q_ASSERT(request);
+
+                        // We've already made a request, so the cache must be disabled or it wasn't there, so enabling
+                        // it will do nothing.
+                        request->setCacheEnabled(false);
+                        connect(request, &ResourceRequest::finished, this, &ScriptCache::scriptContentAvailable);
+                        request->send();
+                    });
+                } else {
+                    // Dubious, but retained here because it matches the behavior before fixing the threading
+                    scriptContent = _scriptCache[url];
+                    finished = true;
+                    qCWarning(scriptengine) << "Error loading script from URL " << url;
+                }
+            }
         }
     }
 
     req->deleteLater();
 
-    if (!DependencyManager::get<ScriptEngines>()->isStopped()) {
+    if (finished && !DependencyManager::get<ScriptEngines>()->isStopped()) {
         foreach(contentAvailableCallback thisCallback, allCallbacks) {
             thisCallback(url.toString(), scriptContent, true, success);
         }

libraries/script-engine/src/ScriptCache.h

@@ -15,13 +15,19 @@
 #include <mutex>
 #include <ResourceCache.h>
 
+using contentAvailableCallback = std::function<void(const QString& scriptOrURL, const QString& contents, bool isURL, bool contentAvailable)>;
+
 class ScriptUser {
 public:
     virtual void scriptContentsAvailable(const QUrl& url, const QString& scriptContents) = 0;
     virtual void errorInLoadingScript(const QUrl& url) = 0;
 };
 
-using contentAvailableCallback = std::function<void(const QString& scriptOrURL, const QString& contents, bool isURL, bool contentAvailable)>;
+class ScriptRequest {
+public:
+    std::vector<contentAvailableCallback> scriptUsers { };
+    int numRetries { 0 };
+};
 
 /// Interface for loading scripts
 class ScriptCache : public QObject, public Dependency {
@@ -51,11 +57,11 @@ private:
     ScriptCache(QObject* parent = NULL);
     
     Mutex _containerLock;
-    QMultiMap<QUrl, contentAvailableCallback> _contentCallbacks;
+    QMap<QUrl, ScriptRequest> _activeScriptRequests;
     
     QHash<QUrl, QString> _scriptCache;
     QMultiMap<QUrl, ScriptUser*> _scriptUsers;
     QSet<QUrl> _badScripts;
 };
 
-#endif // hifi_ScriptCache_h
+#endif // hifi_ScriptCache_h