Reset stuck chunked uploads eventually #5344 (#5443)

Previously this wasn't happening for errors that were not
NormalErrors because they don't end up in the blacklist.

This revises the resetting logic to be independent of the
error blacklist and make use of UploadInfo::errorCount
instead.

412 errors should reset chunked uploads because they might be
indicative of a checksum error.

Additionally, server bugs might require that additional
errors cause an upload reset. To allow that, a new capability
is added that can be used to advise the client about this.

src/libsync/capabilities.cpp

@@ -121,4 +121,13 @@ bool Capabilities::chunkingParallelUploadDisabled() const
     return _capabilities["dav"].toMap()["chunkingParallelUploadDisabled"].toBool();
 }
 
+QList<int> Capabilities::httpErrorCodesThatResetFailingChunkedUploads() const
+{
+    QList<int> list;
+    foreach (const auto & t, _capabilities["dav"].toMap()["httpErrorCodesThatResetFailingChunkedUploads"].toList()) {
+        list.push_back(t.toInt());
+    }
+    return list;
+}
+
 }

src/libsync/capabilities.h

@@ -81,6 +81,25 @@ public:
      */
     QByteArray uploadChecksumType() const;
 
+    /**
+     * List of HTTP error codes should be guaranteed to eventually reset
+     * failing chunked uploads.
+     *
+     * The resetting works by tracking UploadInfo::errorCount.
+     *
+     * Note that other error codes than the ones listed here may reset the
+     * upload as well.
+     *
+     * Motivation: See #5344. They should always be reset on 412 (possibly
+     * checksum error), but broken servers may also require resets on
+     * unusual error codes such as 503.
+     *
+     * Path: dav/httpErrorCodesThatResetFailingChunkedUploads
+     * Default: []
+     * Example: [503, 500]
+     */
+    QList<int> httpErrorCodesThatResetFailingChunkedUploads() const;
+
 private:
     QVariantMap _capabilities;
 };

src/libsync/owncloudpropagator.cpp

@@ -99,7 +99,7 @@ int OwncloudPropagator::hardMaximumActiveJob()
 
 /** Updates, creates or removes a blacklist entry for the given item.
  *
- * Returns whether the file is in the blacklist now.
+ * Returns whether the error should be suppressed.
  */
 static bool blacklistCheck(SyncJournalDb* journal, const SyncFileItem& item)
 {
@@ -108,16 +108,13 @@ static bool blacklistCheck(SyncJournalDb* journal, const SyncFileItem& item)
 
     if (newEntry.isValid()) {
         journal->updateErrorBlacklistEntry(newEntry);
-        // Also clear upload info if any so we don't resume from the same transfer-id if there was too many failures (#5344)
-        // (maybe the reason is that the state for this transfer id is broken on the server.)
-        if (newEntry._retryCount > 3) {
-            journal->setUploadInfo(item._file, SyncJournalDb::UploadInfo());
-        }
     } else if (oldEntry.isValid()) {
         journal->wipeErrorBlacklistEntry(item._file);
     }
 
-    return newEntry.isValid();
+    // In some cases we add errors to the blacklist for tracking, but don't
+    // want to actively suppress them.
+    return newEntry.isValid() && newEntry._ignoreDuration > 0;
 }
 
 void PropagateItemJob::done(SyncFileItem::Status status, const QString &errorString)
@@ -144,10 +141,12 @@ void PropagateItemJob::done(SyncFileItem::Status status, const QString &errorStr
     switch( status ) {
     case SyncFileItem::SoftError:
     case SyncFileItem::FatalError:
-        // do not blacklist in case of soft error or fatal error.
-        break;
     case SyncFileItem::NormalError:
-        if (blacklistCheck(_propagator->_journal, *_item) && _item->_hasBlacklistEntry) {
+        // For normal errors, we blacklist aggressively, otherwise only on
+        // explicit request.
+        if ((status == SyncFileItem::NormalError || _item->_errorMayBeBlacklisted)
+                && blacklistCheck(_propagator->_journal, *_item)
+                && _item->_hasBlacklistEntry) {
             // do not error if the item was, and continues to be, blacklisted
             status = SyncFileItem::FileIgnored;
             _item->_errorString.prepend(tr("Continue blacklisting:") + " ");

src/libsync/propagateupload.cpp

@@ -493,6 +493,27 @@ void PropagateUploadFileCommon::slotPollFinished()
     finalize();
 }
 
+void PropagateUploadFileCommon::checkResettingErrors()
+{
+    if (_item->_httpErrorCode == 412
+            || _propagator->account()->capabilities().httpErrorCodesThatResetFailingChunkedUploads()
+                   .contains(_item->_httpErrorCode)) {
+        auto uploadInfo = _propagator->_journal->getUploadInfo(_item->_file);
+        uploadInfo._errorCount += 1;
+        if (uploadInfo._errorCount > 3) {
+            qDebug() << "Reset transfer of" << _item->_file
+                     << "due to repeated error" << _item->_httpErrorCode;
+            uploadInfo = SyncJournalDb::UploadInfo();
+        } else {
+            qDebug() << "Error count for maybe-reset error" << _item->_httpErrorCode
+                     << "on file" << _item->_file
+                     << "is" << uploadInfo._errorCount;
+        }
+        _propagator->_journal->setUploadInfo(_item->_file, uploadInfo);
+        _propagator->_journal->commit("Upload info");
+    }
+}
+
 void PropagateUploadFileCommon::slotJobDestroyed(QObject* job)
 {
     _jobs.erase(std::remove(_jobs.begin(), _jobs.end(), job) , _jobs.end());

src/libsync/propagateupload.h

@@ -232,6 +232,13 @@ private slots:
     void slotPollFinished();
 
 protected:
+    /**
+     * Checks whether the current error is one that should reset the whole
+     * transfer if it happens too often. If so: Bump UploadInfo::errorCount
+     * and maybe perform the reset.
+     */
+    void checkResettingErrors();
+
     // Bases headers that need to be sent with every chunk
     QMap<QByteArray, QByteArray> headers();
 

src/libsync/propagateuploadng.cpp

@@ -373,13 +373,8 @@ void PropagateUploadFileNG::slotPutFinished()
             errorString = job->reply()->rawHeader("OC-ErrorString");
         }
 
-        // FIXME!  can this happen for the chunks?
-        if (_item->_httpErrorCode == 412) {
-            // Precondition Failed:   Maybe the bad etag is in the database, we need to clear the
-            // parent folder etag so we won't read from DB next sync.
-            _propagator->_journal->avoidReadFromDbOnNextSync(_item->_file);
-            _propagator->_anotherSyncNeeded = true;
-        }
+        // Ensure errors that should eventually reset the chunked upload are tracked.
+        checkResettingErrors();
 
         SyncFileItem::Status status = classifyError(err, _item->_httpErrorCode,
                                                     &_propagator->_anotherSyncNeeded);
@@ -416,6 +411,12 @@ void PropagateUploadFileNG::slotPutFinished()
             _propagator->_journal->wipeErrorBlacklistEntry(_item->_file);
             _item->_hasBlacklistEntry = false;
         }
+
+        // Reset the error count on successful chunk upload
+        auto uploadInfo = _propagator->_journal->getUploadInfo(_item->_file);
+        uploadInfo._errorCount = 0;
+        _propagator->_journal->setUploadInfo(_item->_file, uploadInfo);
+        _propagator->_journal->commit("Upload info");
     }
     startNextChunk();
 }
@@ -429,6 +430,18 @@ void PropagateUploadFileNG::slotMoveJobFinished()
     _item->_httpErrorCode = job->reply()->attribute(QNetworkRequest::HttpStatusCodeAttribute).toInt();
 
     if (err != QNetworkReply::NoError) {
+        if (_item->_httpErrorCode == 412) {
+            // Precondition Failed: Either an etag or a checksum mismatch.
+
+            // Maybe the bad etag is in the database, we need to clear the
+            // parent folder etag so we won't read from DB next sync.
+            _propagator->_journal->avoidReadFromDbOnNextSync(_item->_file);
+            _propagator->_anotherSyncNeeded = true;
+        }
+
+        // Ensure errors that should eventually reset the chunked upload are tracked.
+        checkResettingErrors();
+
         SyncFileItem::Status status = classifyError(err, _item->_httpErrorCode,
                                                     &_propagator->_anotherSyncNeeded);
         QString errorString = errorMessage(job->errorString(), job->reply()->readAll());

src/libsync/propagateuploadv1.cpp

@@ -101,6 +101,7 @@ void PropagateUploadFileV1::startNextChunk()
         // if there's only one chunk, it's the final one
         isFinalChunk = true;
     }
+    qDebug() << _chunkCount << isFinalChunk << chunkStart << currentChunkSize;
 
     if (isFinalChunk && !_transmissionChecksumType.isEmpty()) {
         headers[checkSumHeaderC] = makeChecksumHeader(
@@ -215,12 +216,17 @@ void PropagateUploadFileV1::slotPutFinished()
         }
 
         if (_item->_httpErrorCode == 412) {
-            // Precondition Failed:   Maybe the bad etag is in the database, we need to clear the
+            // Precondition Failed: Either an etag or a checksum mismatch.
+
+            // Maybe the bad etag is in the database, we need to clear the
             // parent folder etag so we won't read from DB next sync.
             _propagator->_journal->avoidReadFromDbOnNextSync(_item->_file);
             _propagator->_anotherSyncNeeded = true;
         }
 
+        // Ensure errors that should eventually reset the chunked upload are tracked.
+        checkResettingErrors();
+
         SyncFileItem::Status status = classifyError(err, _item->_httpErrorCode,
                                                     &_propagator->_anotherSyncNeeded);
         abortWithError(status, errorString);
@@ -304,6 +310,7 @@ void PropagateUploadFileV1::slotPutFinished()
         pi._chunk = (currentChunk + _startChunk + 1) % _chunkCount ; // next chunk to start with
         pi._transferid = _transferId;
         pi._modtime =  Utility::qDateTimeFromTime_t(_item->_modtime);
+        pi._errorCount = 0; // successful chunk upload resets
         _propagator->_journal->setUploadInfo(_item->_file, pi);
         _propagator->_journal->commit("Upload info");
         startNextChunk();

src/libsync/syncjournalfilerecord.cpp

@@ -121,7 +121,7 @@ bool SyncJournalErrorBlacklistRecord::isValid() const
 {
     return ! _file.isEmpty()
         && (!_lastTryEtag.isEmpty() || _lastTryModtime != 0)
-        && _lastTryTime > 0 && _ignoreDuration > 0;
+        && _lastTryTime > 0;
 }
 
 SyncJournalErrorBlacklistRecord SyncJournalErrorBlacklistRecord::update(
@@ -163,6 +163,7 @@ SyncJournalErrorBlacklistRecord SyncJournalErrorBlacklistRecord::update(
         qDebug() << "Fatal Error condition" << item._httpErrorCode << ", maximum blacklist ignore time!";
         entry._ignoreDuration = maxBlacklistTime;
     }
+
     entry._ignoreDuration = qBound(minBlacklistTime, entry._ignoreDuration, maxBlacklistTime);
 
     qDebug() << "blacklisting " << item._file

test/CMakeLists.txt

@@ -48,6 +48,7 @@ if(HAVE_QT5 AND NOT BUILD_WITH_QT4)
     owncloud_add_test(SyncEngine "syncenginetestutils.h")
     owncloud_add_test(SyncFileStatusTracker "syncenginetestutils.h")
     owncloud_add_test(ChunkingNg "syncenginetestutils.h")
+    owncloud_add_test(UploadReset "syncenginetestutils.h")
 endif(HAVE_QT5 AND NOT BUILD_WITH_QT4)
 
 SET(FolderMan_SRC ../src/gui/folderman.cpp)

test/syncenginetestutils.h

@@ -64,6 +64,7 @@ public:
     virtual void appendByte(const QString &relativePath) = 0;
     virtual void mkdir(const QString &relativePath) = 0;
     virtual void rename(const QString &relativePath, const QString &relativeDestinationDirectory) = 0;
+    virtual void setModTime(const QString &relativePath, const QDateTime &modTime) = 0;
 };
 
 class DiskFileModifier : public FileModifier
@@ -114,6 +115,9 @@ public:
         QVERIFY(_rootDir.exists(from));
         QVERIFY(_rootDir.rename(from, to));
     }
+    void setModTime(const QString &relativePath, const QDateTime &modTime) override {
+        OCC::FileSystem::setModTime(_rootDir.filePath(relativePath), OCC::Utility::qDateTimeToTime_t(modTime));
+    }
 };
 
 class FileInfo : public FileModifier
@@ -201,6 +205,12 @@ public:
         dir->children.insert(newPathComponents.fileName(), std::move(fi));
     }
 
+    void setModTime(const QString &relativePath, const QDateTime &modTime) override {
+        FileInfo *file = findInvalidatingEtags(relativePath);
+        Q_ASSERT(file);
+        file->lastModified = modTime;
+    }
+
     FileInfo *find(const PathComponents &pathComponents, const bool invalidateEtags = false) {
         if (pathComponents.isEmpty()) {
             if (invalidateEtags)
@@ -641,6 +651,7 @@ public:
 
     Q_INVOKABLE void respond() {
         setAttribute(QNetworkRequest::HttpStatusCodeAttribute, 500);
+        setError(InternalServerError, "Internal Server Fake Error");
         emit metaDataChanged();
         emit finished();
     }

test/testuploadreset.cpp

@@ -0,0 +1,75 @@
+/*
+ *    This software is in the public domain, furnished "as is", without technical
+ *    support, and with no warranty, express or implied, as to its usefulness for
+ *    any purpose.
+ *
+ */
+
+#include <QtTest>
+#include "syncenginetestutils.h"
+#include <syncengine.h>
+#include <syncjournaldb.h>
+
+using namespace OCC;
+
+class TestUploadReset : public QObject
+{
+    Q_OBJECT
+
+private slots:
+
+    // Verify that the chunked transfer eventually gets reset with the new chunking
+    void testFileUploadNg() {
+        FakeFolder fakeFolder{FileInfo::A12_B12_C12_S12()};
+
+        fakeFolder.syncEngine().account()->setCapabilities({ { "dav", QVariantMap{
+                {"chunking", "1.0"},
+                {"httpErrorCodesThatResetFailingChunkedUploads", QVariantList{500} } } } });
+
+        const int size = 100 * 1000 * 1000; // 100 MB
+        fakeFolder.localModifier().insert("A/a0", size);
+        QDateTime modTime = QDateTime::currentDateTime();
+        fakeFolder.localModifier().setModTime("A/a0", modTime);
+
+        // Create a transfer id, so we can make the final MOVE fail
+        SyncJournalDb::UploadInfo uploadInfo;
+        uploadInfo._transferid = 1;
+        uploadInfo._valid = true;
+        uploadInfo._modtime = modTime;
+        fakeFolder.syncEngine().journal()->setUploadInfo("A/a0", uploadInfo);
+
+        fakeFolder.uploadState().mkdir("1");
+        fakeFolder.serverErrorPaths().append("1/.file");
+
+        QVERIFY(!fakeFolder.syncOnce());
+
+        uploadInfo = fakeFolder.syncEngine().journal()->getUploadInfo("A/a0");
+        QCOMPARE(uploadInfo._errorCount, 1);
+        QCOMPARE(uploadInfo._transferid, 1);
+
+        fakeFolder.syncEngine().journal()->wipeErrorBlacklist();
+        QVERIFY(!fakeFolder.syncOnce());
+
+        uploadInfo = fakeFolder.syncEngine().journal()->getUploadInfo("A/a0");
+        QCOMPARE(uploadInfo._errorCount, 2);
+        QCOMPARE(uploadInfo._transferid, 1);
+
+        fakeFolder.syncEngine().journal()->wipeErrorBlacklist();
+        QVERIFY(!fakeFolder.syncOnce());
+
+        uploadInfo = fakeFolder.syncEngine().journal()->getUploadInfo("A/a0");
+        QCOMPARE(uploadInfo._errorCount, 3);
+        QCOMPARE(uploadInfo._transferid, 1);
+
+        fakeFolder.syncEngine().journal()->wipeErrorBlacklist();
+        QVERIFY(!fakeFolder.syncOnce());
+
+        uploadInfo = fakeFolder.syncEngine().journal()->getUploadInfo("A/a0");
+        QCOMPARE(uploadInfo._errorCount, 0);
+        QCOMPARE(uploadInfo._transferid, 0);
+        QVERIFY(!uploadInfo._valid);
+    }
+};
+
+QTEST_GUILESS_MAIN(TestUploadReset)
+#include "testuploadreset.moc"