BaseJob: more careful error handling; unify and extend error signals in Connection

(Note: this commit breaks back-compatibility.)

BaseJob::gotReply() had a bold assumption that whenever there's no reasonable JSON body in case of error, that meant IncorrectRequestError (which of course was incorrect). This led to syncs dying in Quaternion because it (correctly) considered IncorrectRequestError to be grave enough to not retry. Closes #206.
Also: don't dump the whole payload to logs, limit with initial 500 characters (closes #205)

4 files changed, 66 insertions, 46 deletions

diff --git a/lib/connection.cpp b/lib/connection.cpp
index f21d6973..84557224 100644
--- a/lib/connection.cpp
+++ b/lib/connection.cpp
@@ -196,7 +196,7 @@ void Connection::doConnectToServer(const QString& user, const QString& password,
         });
     connect(loginJob, &BaseJob::failure, this,
         [this, loginJob] {
-            emit loginError(loginJob->errorString());
+            emit loginError(loginJob->errorString(), loginJob->errorDetails());
         });
 }
 
@@ -269,13 +269,18 @@ void Connection::sync(int timeout)
         d->syncJob = nullptr;
         emit syncDone();
     });
-    connect( job, &SyncJob::retryScheduled, this, &Connection::networkError);
+    connect( job, &SyncJob::retryScheduled, this,
+        [this,job] (int retriesTaken, int nextInMilliseconds)
+        {
+            emit networkError(job->errorString(), job->errorDetails(),
+                              retriesTaken, nextInMilliseconds);
+        });
     connect( job, &SyncJob::failure, this, [this, job] {
         d->syncJob = nullptr;
         if (job->error() == BaseJob::ContentAccessError)
-            emit loginError(job->errorString());
+            emit loginError(job->errorString(), job->errorDetails());
         else
-            emit syncError(job->errorString());
+            emit syncError(job->errorString(), job->errorDetails());
     });
 }
 
diff --git a/lib/connection.h b/lib/connection.h
index 6dd0db1d..4ce1d127 100644
--- a/lib/connection.h
+++ b/lib/connection.h
@@ -351,11 +351,12 @@ namespace QMatrixClient
             void connected();
             void reconnected(); //< Unused; use connected() instead
             void loggedOut();
-            void loginError(QString error);
-            void networkError(int retriesTaken, int inMilliseconds);
+            void loginError(QString message, QByteArray details);
+            void networkError(QString message, QByteArray details,
+                              int retriesTaken, int nextRetryInMilliseconds);
 
             void syncDone();
-            void syncError(QString error);
+            void syncError(QString message, QByteArray details);
 
             void newUser(User* user);
 
diff --git a/lib/jobs/basejob.cpp b/lib/jobs/basejob.cpp
index 7c3cb13b..63467d91 100644
--- a/lib/jobs/basejob.cpp
+++ b/lib/jobs/basejob.cpp
@@ -72,6 +72,7 @@ class BaseJob::Private
 
         QScopedPointer<QNetworkReply, NetworkReplyDeleter> reply;
         Status status = Pending;
+        QByteArray details; //< In case of error, contains the raw response body
 
         QTimer timer;
         QTimer retryTimer;
@@ -264,45 +265,41 @@ void BaseJob::checkReply()
 void BaseJob::gotReply()
 {
     checkReply();
-    qCDebug(d->logCat).nospace().noquote() << this << " returned HTTP code "
-        << d->reply->attribute(QNetworkRequest::HttpStatusCodeAttribute).toInt()
-        << ": " << (d->reply->error() == QNetworkReply::NoError ?
-                    "Success" : d->reply->errorString())
-        << " (URL: " << d->reply->url().toDisplayString() << ")";
     if (status().good())
         setStatus(parseReply(d->reply.data()));
     else {
-        const auto body = d->reply->readAll();
-        if (!body.isEmpty())
+        // FIXME: Factor out to smth like BaseJob::handleError()
+        d->details = d->reply->readAll();
+        const auto jsonBody =
+                d->reply->rawHeader("Content-Type") == "application/json";
+        qCDebug(d->logCat).noquote()
+                << "Error body (truncated if long):" << d->details.left(500);
+        if (jsonBody)
         {
-            qCDebug(d->logCat).noquote() << "Error body:" << body;
-            auto json = QJsonDocument::fromJson(body).object();
-            if (json.isEmpty())
-                setStatus(IncorrectRequestError, body);
-            else {
-                if (error() == TooManyRequestsError ||
-                        json.value("errcode").toString() == "M_LIMIT_EXCEEDED")
-                {
-                    QString msg = tr("Too many requests");
-                    auto retryInterval = json.value("retry_after_ms").toInt(-1);
-                    if (retryInterval != -1)
-                        msg += tr(", next retry advised after %1 ms")
-                                .arg(retryInterval);
-                    else // We still have to figure some reasonable interval
-                        retryInterval = getNextRetryInterval();
-
-                    setStatus(TooManyRequestsError, msg);
-
-                    // Shortcut to retry instead of executing finishJob()
-                    stop();
-                    qCWarning(d->logCat)
-                            << this << "will retry in" << retryInterval << "ms";
-                    d->retryTimer.start(retryInterval);
-                    emit retryScheduled(d->retriesTaken, retryInterval);
-                    return;
-                }
-                setStatus(IncorrectRequestError, json.value("error").toString());
+            auto json = QJsonDocument::fromJson(d->details).object();
+            if (error() == TooManyRequestsError ||
+                    json.value("errcode").toString() == "M_LIMIT_EXCEEDED")
+            {
+                QString msg = tr("Too many requests");
+                auto retryInterval = json.value("retry_after_ms").toInt(-1);
+                if (retryInterval != -1)
+                    msg += tr(", next retry advised after %1 ms")
+                            .arg(retryInterval);
+                else // We still have to figure some reasonable interval
+                    retryInterval = getNextRetryInterval();
+
+                setStatus(TooManyRequestsError, msg);
+
+                // Shortcut to retry instead of executing finishJob()
+                stop();
+                qCWarning(d->logCat)
+                        << this << "will retry in" << retryInterval << "ms";
+                d->retryTimer.start(retryInterval);
+                emit retryScheduled(d->retriesTaken, retryInterval);
+                return;
             }
+            if (!json.isEmpty())
+                setStatus(IncorrectRequestError, json.value("error").toString());
         }
     }
 
@@ -343,12 +340,21 @@ BaseJob::Status BaseJob::doCheckReply(QNetworkReply* reply) const
     // https://en.wikipedia.org/wiki/List_of_HTTP_status_codes
     const auto httpCodeHeader =
             reply->attribute(QNetworkRequest::HttpStatusCodeAttribute);
-    if (!httpCodeHeader.isValid()) // Woah, we didn't even get HTTP headers
+    if (!httpCodeHeader.isValid())
+    {
+        qCWarning(d->logCat) << this << "didn't get valid HTTP headers";
         return { NetworkError, reply->errorString() };
+    }
 
+    const QString replyState = reply->isRunning() ? "(tentative)" : "(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 (checkContentType(reply->rawHeader("Content-Type"),
                              d->expectedContentTypes))
             return NoError;
@@ -357,6 +363,8 @@ BaseJob::Status BaseJob::doCheckReply(QNetworkReply* reply) const
                      "Unexpected content type of the response" };
     }
 
+    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;
@@ -426,8 +434,8 @@ void BaseJob::finishJob()
         const auto retryInterval =
                 error() == TimeoutError ? 0 : getNextRetryInterval();
         ++d->retriesTaken;
-        qCWarning(d->logCat) << this << "will retry" << d->retriesTaken
-                   << "in" << retryInterval/1000 << "s";
+        qCWarning(d->logCat).nospace() << this << ": retry #" << d->retriesTaken
+                   << " in " << retryInterval/1000 << " s";
         d->retryTimer.start(retryInterval);
         emit retryScheduled(d->retriesTaken, retryInterval);
         return;
@@ -490,17 +498,22 @@ QString BaseJob::errorString() const
     return d->status.message;
 }
 
+QByteArray BaseJob::errorDetails() const
+{
+    return d->details;
+}
+
 void BaseJob::setStatus(Status s)
 {
-    d->status = s;
     if (!s.good())
         qCWarning(d->logCat) << this << "status" << s;
+    d->status = std::move(s);
 }
 
 void BaseJob::setStatus(int code, QString message)
 {
     message.replace(d->connection->accessToken(), "(REDACTED)");
-    setStatus({ code, message });
+    setStatus({ code, std::move(message) });
 }
 
 void BaseJob::abandon()
diff --git a/lib/jobs/basejob.h b/lib/jobs/basejob.h
index 319fc8a4..5bd98d68 100644
--- a/lib/jobs/basejob.h
+++ b/lib/jobs/basejob.h
@@ -123,6 +123,7 @@ namespace QMatrixClient
             Status status() const;
             int error() const;
             virtual QString errorString() const;
+            QByteArray errorDetails() const;
 
             int maxRetries() const;
             void setMaxRetries(int newMaxRetries);