Merge pull request #348 from quotient-im/kitsune-better-basejob

Better BaseJob

1 files changed, 164 insertions, 130 deletions

diff --git a/lib/jobs/basejob.cpp b/lib/jobs/basejob.cpp
index f3ba00b5..54931c83 100644
--- a/lib/jobs/basejob.cpp
+++ b/lib/jobs/basejob.cpp
@@ -31,6 +31,8 @@
 #include <array>
 
 using namespace Quotient;
+using std::chrono::seconds, std::chrono::milliseconds;
+using namespace std::chrono_literals;
 
 struct NetworkReplyDeleter : public QScopedPointerDeleteLater {
     static inline void cleanup(QNetworkReply* reply)
@@ -43,6 +45,11 @@ struct NetworkReplyDeleter : public QScopedPointerDeleteLater {
 
 class BaseJob::Private {
 public:
+    struct JobTimeoutConfig {
+        seconds jobTimeout;
+        seconds nextRetryInterval;
+    };
+
     // Using an idiom from clang-tidy:
     // http://clang.llvm.org/extra/clang-tidy/checks/modernize-pass-by-value.html
     Private(HttpVerb v, QString endpoint, const QUrlQuery& q, Data&& data,
@@ -52,12 +59,14 @@ public:
         , requestQuery(q)
         , requestData(std::move(data))
         , needsToken(nt)
-    {}
+    {
+        timer.setSingleShot(true);
+        retryTimer.setSingleShot(true);
+    }
 
-    void sendRequest(bool inBackground);
-    const JobTimeoutConfig& getCurrentTimeoutConfig() const;
+    void sendRequest();
 
-    const ConnectionData* connection = nullptr;
+    ConnectionData* connection = nullptr;
 
     // Contents for the network request
     HttpVerb verb;
@@ -67,26 +76,41 @@ public:
     Data requestData;
     bool needsToken;
 
+    bool inBackground = false;
+
     // There's no use of QMimeType here because we don't want to match
     // content types against the known MIME type hierarchy; and at the same
     // type QMimeType is of little help with MIME type globs (`text/*` etc.)
-    QByteArrayList expectedContentTypes;
+    QByteArrayList expectedContentTypes { "application/json" };
 
     QScopedPointer<QNetworkReply, NetworkReplyDeleter> reply;
-    Status status = Pending;
+    Status status = Unprepared;
     QByteArray rawResponse;
     QUrl errorUrl; //< May contain a URL to help with some errors
 
+    LoggingCategory logCat = JOBS;
+
     QTimer timer;
     QTimer retryTimer;
 
-    QVector<JobTimeoutConfig> errorStrategy = { { 90, 5 },
-                                                { 90, 10 },
-                                                { 120, 30 } };
-    int maxRetries = errorStrategy.size();
+    static constexpr std::array<const JobTimeoutConfig, 3> errorStrategy {
+        { { 90s, 5s }, { 90s, 10s }, { 120s, 30s } }
+    };
+    int maxRetries = int(errorStrategy.size());
     int retriesTaken = 0;
 
-    LoggingCategory logCat = JOBS;
+    const JobTimeoutConfig& getCurrentTimeoutConfig() const
+    {
+        return errorStrategy[std::min(size_t(retriesTaken),
+                                      errorStrategy.size() - 1)];
+    }
+
+    QString urlForLog() const
+    {
+        return reply
+                   ? reply->url().toString(QUrl::RemoveQuery)
+                   : makeRequestUrl(connection->baseUrl(), apiEndpoint).toString();
+    }
 };
 
 BaseJob::BaseJob(HttpVerb verb, const QString& name, const QString& endpoint,
@@ -99,9 +123,11 @@ BaseJob::BaseJob(HttpVerb verb, const QString& name, const QString& endpoint,
     : d(new Private(verb, endpoint, query, std::move(data), needsToken))
 {
     setObjectName(name);
-    setExpectedContentTypes({ "application/json" });
-    d->timer.setSingleShot(true);
     connect(&d->timer, &QTimer::timeout, this, &BaseJob::timeout);
+    connect(&d->retryTimer, &QTimer::timeout, this, [this] {
+        setStatus(Pending);
+        sendRequest();
+    });
 }
 
 BaseJob::~BaseJob()
@@ -112,15 +138,12 @@ BaseJob::~BaseJob()
 
 QUrl BaseJob::requestUrl() const
 {
-    return d->reply ? d->reply->request().url() : QUrl();
+    return d->reply ? d->reply->url() : QUrl();
 }
 
 bool BaseJob::isBackground() const
 {
-    return d->reply
-           && d->reply->request()
-                  .attribute(QNetworkRequest::BackgroundRequestAttribute)
-                  .toBool();
+    return d->inBackground;
 }
 
 const QString& BaseJob::apiEndpoint() const { return d->apiEndpoint; }
@@ -184,7 +207,7 @@ QUrl BaseJob::makeRequestUrl(QUrl baseUrl, const QString& path,
     return baseUrl;
 }
 
-void BaseJob::Private::sendRequest(bool inBackground)
+void BaseJob::Private::sendRequest()
 {
     QNetworkRequest req { makeRequestUrl(connection->baseUrl(), apiEndpoint,
                                          requestQuery) };
@@ -193,17 +216,13 @@ void BaseJob::Private::sendRequest(bool inBackground)
     req.setRawHeader("Authorization",
                      QByteArray("Bearer ") + connection->accessToken());
     req.setAttribute(QNetworkRequest::BackgroundRequestAttribute, inBackground);
-#if (QT_VERSION >= QT_VERSION_CHECK(5, 6, 0))
     req.setAttribute(QNetworkRequest::FollowRedirectsAttribute, true);
     req.setMaximumRedirectsAllowed(10);
-#endif
     req.setAttribute(QNetworkRequest::HttpPipeliningAllowedAttribute, true);
-#if QT_VERSION >= QT_VERSION_CHECK(5, 9, 0)
-    // some sources claim that there are issues with QT 5.8
     req.setAttribute(QNetworkRequest::HTTP2AllowedAttribute, true);
-#endif
     for (auto it = requestHeaders.cbegin(); it != requestHeaders.cend(); ++it)
         req.setRawHeader(it.key(), it.value());
+
     switch (verb) {
     case HttpVerb::Get:
         reply.reset(connection->nam()->get(req));
@@ -220,36 +239,31 @@ void BaseJob::Private::sendRequest(bool inBackground)
     }
 }
 
-void BaseJob::beforeStart(const ConnectionData*) {}
+void BaseJob::doPrepare() {}
 
-void BaseJob::afterStart(const ConnectionData*, QNetworkReply*) {}
+void BaseJob::onSentRequest(QNetworkReply*) {}
 
 void BaseJob::beforeAbandon(QNetworkReply*) {}
 
-void BaseJob::start(const ConnectionData* connData, bool inBackground)
+void BaseJob::prepare(ConnectionData* connData, bool inBackground)
 {
+    d->inBackground = inBackground;
     d->connection = connData;
-    d->retryTimer.setSingleShot(true);
-    connect(&d->retryTimer, &QTimer::timeout, this,
-            [this, inBackground] { sendRequest(inBackground); });
-
-    beforeStart(connData);
-    if (status().good())
-        sendRequest(inBackground);
-    if (status().good())
-        afterStart(connData, d->reply.data());
-    if (!status().good())
+    doPrepare();
+    if (status().code != Unprepared && status().code != Pending)
         QTimer::singleShot(0, this, &BaseJob::finishJob);
+    setStatus(Pending);
 }
 
-void BaseJob::sendRequest(bool inBackground)
+void BaseJob::sendRequest()
 {
-    emit aboutToStart();
-    d->retryTimer.stop(); // In case we were counting down at the moment
-    qCDebug(d->logCat) << this << "sending request to" << d->apiEndpoint;
-    if (!d->requestQuery.isEmpty())
-        qCDebug(d->logCat) << "  query:" << d->requestQuery.toString();
-    d->sendRequest(inBackground);
+    if (status().code == Abandoned)
+        return;
+    Q_ASSERT(d->connection && status().code == Pending);
+    qCDebug(d->logCat) << "Making request to" << d->urlForLog();
+    emit aboutToSendRequest();
+    d->sendRequest();
+    Q_ASSERT(d->reply);
     connect(d->reply.data(), &QNetworkReply::finished, this, &BaseJob::gotReply);
     if (d->reply->isRunning()) {
         connect(d->reply.data(), &QNetworkReply::metaDataChanged, this,
@@ -259,10 +273,12 @@ void BaseJob::sendRequest(bool inBackground)
         connect(d->reply.data(), &QNetworkReply::downloadProgress, this,
                 &BaseJob::downloadProgress);
         d->timer.start(getCurrentTimeout());
-        qCDebug(d->logCat) << this << "request has been sent";
-        emit started();
+        qCInfo(d->logCat).noquote() << "Request sent to" << d->urlForLog();
+        onSentRequest(d->reply.data());
+        emit sentRequest();
     } else
-        qCWarning(d->logCat) << this << "request could not start";
+        qCWarning(d->logCat).noquote()
+            << "Request could not start:" << d->urlForLog();
 }
 
 void BaseJob::checkReply() { setStatus(doCheckReply(d->reply.data())); }
@@ -283,13 +299,7 @@ void BaseJob::gotReply()
                 parseError(d->reply.data(),
                            QJsonDocument::fromJson(d->rawResponse).object()));
     }
-
-    if (status().code != TooManyRequestsError)
-        finishJob();
-    else {
-        stop();
-        emit retryScheduled(d->retriesTaken, d->retryTimer.interval());
-    }
+    finishJob();
 }
 
 bool checkContentType(const QByteArray& type, const QByteArrayList& patterns)
@@ -318,6 +328,47 @@ bool checkContentType(const QByteArray& type, const QByteArrayList& patterns)
     return false;
 }
 
+BaseJob::Status BaseJob::Status::fromHttpCode(int httpCode, QString msg)
+{
+    // clang-format off
+    return { [httpCode]() -> StatusCode {
+            if (httpCode / 10 == 41) // 41x errors
+                return httpCode == 410 ? IncorrectRequestError : NotFoundError;
+            switch (httpCode) {
+            case 401: case 403: case 407:
+                return ContentAccessError;
+            case 404:
+                return NotFoundError;
+            case 400: case 405: case 406: case 426: case 428: case 505:
+            case 494: // Unofficial nginx "Request header too large"
+            case 497: // Unofficial nginx "HTTP request sent to HTTPS port"
+                return IncorrectRequestError;
+            case 429:
+                return TooManyRequestsError;
+            case 501: case 510:
+                return RequestNotImplementedError;
+            case 511:
+                return NetworkAuthRequiredError;
+            default:
+                return NetworkError;
+            }
+        }(), std::move(msg) };
+    // clang-format on
+}
+
+QDebug BaseJob::Status::dumpToLog(QDebug dbg) const
+{
+    QDebugStateSaver _s(dbg);
+    dbg.noquote().nospace();
+    if (auto* const k = QMetaEnum::fromType<StatusCode>().valueToKey(code)) {
+        const QByteArray b = k;
+        dbg << b.mid(b.lastIndexOf(':'));
+    } else
+        dbg << code;
+    return dbg << ": " << message;
+
+}
+
 BaseJob::Status BaseJob::doCheckReply(QNetworkReply* reply) const
 {
     // QNetworkReply error codes seem to be flawed when it comes to HTTP;
@@ -327,62 +378,30 @@ BaseJob::Status BaseJob::doCheckReply(QNetworkReply* reply) const
     const auto httpCodeHeader =
         reply->attribute(QNetworkRequest::HttpStatusCodeAttribute);
     if (!httpCodeHeader.isValid()) {
-        qCWarning(d->logCat) << this << "didn't get valid HTTP headers";
+        qCWarning(d->logCat) << "No valid HTTP headers from" << d->urlForLog();
         return { NetworkError, reply->errorString() };
     }
 
-    const QString replyState = reply->isRunning()
-                                   ? QStringLiteral("(tentative)")
-                                   : QStringLiteral("(final)");
-    const auto urlString = '|' + d->reply->url().toDisplayString();
     const auto httpCode = httpCodeHeader.toInt();
-    const auto reason =
-        reply->attribute(QNetworkRequest::HttpReasonPhraseAttribute).toString();
     if (httpCode / 100 == 2) // 2xx
     {
-        qCDebug(d->logCat).noquote().nospace() << this << urlString;
-        qCDebug(d->logCat).noquote() << "  " << httpCode << reason << replyState;
+        if (reply->isFinished())
+            qCInfo(d->logCat) << httpCode << "<-" << d->urlForLog();
         if (!checkContentType(reply->rawHeader("Content-Type"),
                               d->expectedContentTypes))
             return { UnexpectedResponseTypeWarning,
                      "Unexpected content type of the response" };
         return NoError;
     }
+    if (reply->isFinished())
+        qCWarning(d->logCat) << httpCode << "<-" << d->urlForLog();
 
-    qCWarning(d->logCat).noquote().nospace() << this << urlString;
-    qCWarning(d->logCat).noquote() << "  " << httpCode << reason << replyState;
-    return { [httpCode]() -> StatusCode {
-                if (httpCode / 10 == 41)
-                    return httpCode == 410 ? IncorrectRequestError
-                                           : NotFoundError;
-                switch (httpCode) {
-                case 401:
-                case 403:
-                case 407:
-                    return ContentAccessError;
-                case 404:
-                    return NotFoundError;
-                case 400:
-                case 405:
-                case 406:
-                case 426:
-                case 428:
-                case 505:
-                case 494: // Unofficial nginx "Request header too large"
-                case 497: // Unofficial nginx "HTTP request sent to HTTPS port"
-                    return IncorrectRequestError;
-                case 429:
-                    return TooManyRequestsError;
-                case 501:
-                case 510:
-                    return RequestNotImplementedError;
-                case 511:
-                    return NetworkAuthRequiredError;
-                default:
-                    return NetworkError;
-                }
-            }(),
-             reply->errorString() };
+    auto message = reply->errorString();
+    if (message.isEmpty())
+        message = reply->attribute(QNetworkRequest::HttpReasonPhraseAttribute)
+                      .toString();
+
+    return Status::fromHttpCode(httpCode, message);
 }
 
 BaseJob::Status BaseJob::parseReply(QNetworkReply* reply)
@@ -398,20 +417,19 @@ BaseJob::Status BaseJob::parseReply(QNetworkReply* reply)
 
 BaseJob::Status BaseJob::parseJson(const QJsonDocument&) { return Success; }
 
-BaseJob::Status BaseJob::parseError(QNetworkReply* reply,
+BaseJob::Status BaseJob::parseError(QNetworkReply*  /*reply*/,
                                     const QJsonObject& errorJson)
 {
     const auto errCode = errorJson.value("errcode"_ls).toString();
     if (error() == TooManyRequestsError || errCode == "M_LIMIT_EXCEEDED") {
         QString msg = tr("Too many requests");
-        auto retryInterval = errorJson.value("retry_after_ms"_ls).toInt(-1);
-        if (retryInterval != -1)
-            msg += tr(", next retry advised after %1 ms").arg(retryInterval);
+        int64_t retryAfterMs = errorJson.value("retry_after_ms"_ls).toInt(-1);
+        if (retryAfterMs >= 0)
+            msg += tr(", next retry advised after %1 ms").arg(retryAfterMs);
         else // We still have to figure some reasonable interval
-            retryInterval = getNextRetryInterval();
+            retryAfterMs = getNextRetryMs();
 
-        qCWarning(d->logCat) << this << "will retry in" << retryInterval << "ms";
-        d->retryTimer.start(retryInterval);
+        d->connection->limitRate(milliseconds(retryAfterMs));
 
         return { TooManyRequestsError, msg };
     }
@@ -441,7 +459,7 @@ BaseJob::Status BaseJob::parseError(QNetworkReply* reply,
 
 void BaseJob::stop()
 {
-    // This method is used to semi-finalise the job before retrying; so
+    // This method is (also) used to semi-finalise the job before retrying; so
     // stop the timeout timer but keep the retry timer running.
     d->timer.stop();
     if (d->reply) {
@@ -449,7 +467,7 @@ void BaseJob::stop()
         if (d->reply->isRunning()) {
             qCWarning(d->logCat)
                 << this << "stopped without ready network reply";
-            d->reply->abort();
+            d->reply->abort(); // Keep the reply object in case clients need it
         }
     } else
         qCWarning(d->logCat) << this << "stopped with empty network reply";
@@ -458,26 +476,30 @@ void BaseJob::stop()
 void BaseJob::finishJob()
 {
     stop();
-    if ((error() == NetworkError || error() == TimeoutError)
+    if (error() == TooManyRequests) {
+        emit rateLimited();
+        setStatus(Pending);
+        d->connection->submit(this);
+        return;
+    }
+    if ((error() == NetworkError || error() == Timeout)
         && d->retriesTaken < d->maxRetries) {
-        // TODO: The whole retrying thing should be put to ConnectionManager
+        // TODO: The whole retrying thing should be put to Connection(Manager)
         // otherwise independently retrying jobs make a bit of notification
         // storm towards the UI.
-        const auto retryInterval = error() == TimeoutError
-                                       ? 0
-                                       : getNextRetryInterval();
+        const seconds retryIn = error() == Timeout ? 0s : getNextRetryInterval();
         ++d->retriesTaken;
         qCWarning(d->logCat).nospace() << this << ": retry #" << d->retriesTaken
-                                       << " in " << retryInterval / 1000 << " s";
-        d->retryTimer.start(retryInterval);
-        emit retryScheduled(d->retriesTaken, retryInterval);
+                                       << " in " << retryIn.count() << " s";
+        d->retryTimer.start(retryIn);
+        emit retryScheduled(d->retriesTaken, milliseconds(retryIn).count());
         return;
     }
 
-    // Notify those interested in any completion of the job (including killing)
+    // Notify those interested in any completion of the job including abandon()
     emit finished(this);
 
-    emit result(this);
+    emit result(this); // abandon() doesn't emit this
     if (error())
         emit failure(this);
     else
@@ -486,24 +508,35 @@ void BaseJob::finishJob()
     deleteLater();
 }
 
-const JobTimeoutConfig& BaseJob::Private::getCurrentTimeoutConfig() const
+seconds BaseJob::getCurrentTimeout() const
 {
-    return errorStrategy[std::min(retriesTaken, errorStrategy.size() - 1)];
+    return d->getCurrentTimeoutConfig().jobTimeout;
 }
 
-BaseJob::duration_t BaseJob::getCurrentTimeout() const
+BaseJob::duration_ms_t BaseJob::getCurrentTimeoutMs() const
 {
-    return d->getCurrentTimeoutConfig().jobTimeout * 1000;
+    return milliseconds(getCurrentTimeout()).count();
 }
 
-BaseJob::duration_t BaseJob::getNextRetryInterval() const
+seconds BaseJob::getNextRetryInterval() const
 {
-    return d->getCurrentTimeoutConfig().nextRetryInterval * 1000;
+    return d->getCurrentTimeoutConfig().nextRetryInterval;
 }
 
-BaseJob::duration_t BaseJob::millisToRetry() const
+BaseJob::duration_ms_t BaseJob::getNextRetryMs() const
 {
-    return d->retryTimer.isActive() ? d->retryTimer.remainingTime() : 0;
+    return milliseconds(getNextRetryInterval()).count();
+}
+
+milliseconds BaseJob::timeToRetry() const
+{
+    return d->retryTimer.isActive() ? d->retryTimer.remainingTimeAsDuration()
+                                    : 0s;
+}
+
+BaseJob::duration_ms_t BaseJob::millisToRetry() const
+{
+    return timeToRetry().count();
 }
 
 int BaseJob::maxRetries() const { return d->maxRetries; }
@@ -582,21 +615,22 @@ void BaseJob::setStatus(Status s)
 {
     // The crash that led to this code has been reported in
     // https://github.com/quotient-im/Quaternion/issues/566 - basically,
-    // when cleaning up childrent of a deleted Connection, there's a chance
+    // when cleaning up children of a deleted Connection, there's a chance
     // of pending jobs being abandoned, calling setStatus(Abandoned).
     // There's nothing wrong with this; however, the safety check for
     // cleartext access tokens below uses d->connection - which is a dangling
     // pointer.
     // To alleviate that, a stricter condition is applied, that for Abandoned
     // and to-be-Abandoned jobs the status message will be disregarded entirely.
-    // For 0.6 we might rectify the situation by making d->connection
-    // a QPointer<> (and derive ConnectionData from QObject, respectively).
-    if (d->status.code == Abandoned || s.code == Abandoned)
-        s.message.clear();
-
+    // We could rectify the situation by making d->connection a QPointer<>
+    // (and deriving ConnectionData from QObject, respectively) but it's
+    // a too edge case for the hassle.
     if (d->status == s)
         return;
 
+    if (d->status.code == Abandoned || s.code == Abandoned)
+        s.message.clear();
+
     if (!s.message.isEmpty() && d->connection
         && !d->connection->accessToken().isEmpty())
         s.message.replace(d->connection->accessToken(), "(REDACTED)");