libstore: exponential backoff for downloads

Closes #932

`connect-timeout` gets replaced by an exponential backoff for the
download timeout where the initial value is controlled by the setting
`initial-connect-timeout`.

Per iteration, the upper limit of the timeout is increased set to

    timeout := min(max_connect_timeout, initial_connect_timeout * 2^i)

I decided to move the entire timeout / tracking of attempts into its own
class to not make the filetransfer implementation more complex. Also,
that allows us to write unit-tests for it.

Setting `--download-attempts` to `0` is forbidden now and an exception
will be thrown. For `--offline` we set it to `1`, the behavior is
equivalent to what it was before: whether the max tries were exceeded is
only checked after the first download exception got thrown, i.e. there's
still one attempt being made.

The end-result - with timeouts being caused by a wrongly set proxy -
looks like this:

    $ env HTTPS_PROXY=1.1.1.1 nix store ping --store https://example.com
    warning: error: unable to download 'https://example.com/nix-cache-info': Connection timed out after 5006 milliseconds (curl error code=28); retrying in 422ms ms (attempt 1/5)
    warning: error: unable to download 'https://example.com/nix-cache-info': Connection timed out after 10010 milliseconds (curl error code=28); retrying in 1003ms ms (attempt 2/5)
    warning: error: unable to download 'https://example.com/nix-cache-info': Connection timed out after 20020 milliseconds (curl error code=28); retrying in 2018ms ms (attempt 3/5)
    warning: error: unable to download 'https://example.com/nix-cache-info': Connection timed out after 40007 milliseconds (curl error code=28); retrying in 4087ms ms (attempt 4/5)
    error: unable to download 'https://example.com/nix-cache-info': Connection timed out after 80074 milliseconds (curl error code=28)

Change-Id: I9e8d08d78275bcf60080d663febc9e075243d36b

doc/manual/rl-next/exponential-backoff.md

@@ -0,0 +1,12 @@
+---
+synopsis: "libstore: exponential backoff for downloads"
+issues: [lix#932]
+cls: [3856]
+category: Fixes
+credits: [ma27]
+---
+
+The connection timeout when downloading from e.g. a binary cache is exponentially
+increased per failure. The option `connect-timeout` is now an alias to `max-connect-timeout`
+which is the maximum value for a timeout. The start value is controlled
+by `initial-connect-timeout` which is `5` by default.

lix/libstore/daemon.cc

@@ -1,4 +1,5 @@
 #include "lix/libstore/daemon.hh"
+#include "filetransfer.hh"
 #include "lix/libutil/async-io.hh"
 #include "lix/libutil/monitor-fd.hh"
 #include "lix/libstore/worker-protocol.hh"
@@ -218,15 +219,15 @@ struct ClientSettings
                     if (tokenizeString<Paths>(value) != settings.pluginFiles.get())
                         warn("Ignoring the client-specified plugin-files.\n"
                              "The client specifying plugins to the daemon never made sense, and was removed in Nix.");
-                }
-                else if (trusted
-                    || name == settings.buildTimeout.name
-                    || name == settings.maxSilentTime.name
-                    || name == settings.pollInterval.name
-                    || name == "connect-timeout"
-                    || (name == "builders" && value == ""))
+                } else if (trusted || name == settings.buildTimeout.name
+                           || name == settings.maxSilentTime.name
+                           || name == settings.pollInterval.name
+                           || name == fileTransferSettings.maxConnectTimeout.name
+                           || fileTransferSettings.initialConnectTimeout.isNameOrAlias(name)
+                           || (name == "builders" && value == ""))
+                {
                     settings.set(name, value);
-                else if (setSubstituters(settings.substituters))
+                } else if (setSubstituters(settings.substituters))
                     ;
                 else
                     warn("Ignoring the client-specified setting '%s', because it is a restricted setting and you are not a trusted user", name);

lix/libstore/file-transfer-settings/connect-timeout.md

@@ -1,9 +0,0 @@
----
-name: connect-timeout
-internalName: connectTimeout
-type: unsigned long
-default: 5
----
-The timeout (in seconds) for establishing connections in the
-binary cache substituter. It corresponds to `curl`’s
-`--connect-timeout` option. A value of 0 means no limit.

lix/libstore/file-transfer-settings/initial-connect-timeout.md

@@ -0,0 +1,18 @@
+---
+name: initial-connect-timeout
+internalName: initialConnectTimeout
+type: unsigned long
+default: 5
+---
+The timeout for the first attempt to establish connections for file transfers
+such as tarball fetches or binary cache substitutions in seconds.
+
+Lix increases the timeout per failed attempt via exponential backoff.
+For attempt `i` (starting at `0`) the timeout is determined by
+
+    timeout := min(max_connect_timeout, initial_connect_timeout * 2^i)
+
+The value is capped by the option [`max-connect-timeout`](#conf-max-connect-timeout).
+
+The option [`download-attempts`](#conf-download-attempts) controls how many
+attempts to download a file there are before giving up.

lix/libstore/file-transfer-settings/max-connect-timeout.md

@@ -0,0 +1,14 @@
+---
+name: max-connect-timeout
+internalName: maxConnectTimeout
+type: unsigned long
+default: 300
+aliases: [connect-timeout]
+---
+The maximum timeout for establishing connections for file transfers
+such as tarball fetches or binary cache substitutions in seconds.
+This is the maximum value Lix
+sets for `curl`'s `--connect-timeout` option.
+
+See [`initial-connect-timeout`](#conf-initial-connect-timeout)
+for further information.

lix/libstore/filetransfer.cc

@@ -12,6 +12,7 @@
 #include "lix/libutil/strings.hh"
 #include "lix/libutil/thread-name.hh"
 #include "lix/libutil/tracepoint.hh"
+#include "lix/libutil/backoff.hh"
 
 #include <cstddef>
 #include <cstdio>
@@ -36,7 +37,6 @@
 #include <algorithm>
 #include <cmath>
 #include <cstring>
-#include <random>
 #include <thread>
 #include <regex>
 
@@ -145,7 +145,8 @@ struct curlFileTransfer : public FileTransfer
             std::optional<std::string_view> uploadData,
             bool noBody,
             curl_off_t writtenToSink,
-            kj::Own<kj::CrossThreadPromiseFulfiller<Result<FileTransferResult>>> metadataPromise
+            kj::Own<kj::CrossThreadPromiseFulfiller<Result<FileTransferResult>>> metadataPromise,
+            const std::chrono::milliseconds & connectTimeout
         )
             : uri(uri)
             , act(*logger,
@@ -223,7 +224,7 @@ struct curlFileTransfer : public FileTransfer
             if (settings.caFile != "")
                 curl_easy_setopt(req.get(), CURLOPT_CAINFO, settings.caFile.get().c_str());
 
-            curl_easy_setopt(req.get(), CURLOPT_CONNECTTIMEOUT, fileTransferSettings.connectTimeout.get());
+            curl_easy_setopt(req.get(), CURLOPT_CONNECTTIMEOUT_MS, connectTimeout.count());
 
             curl_easy_setopt(req.get(), CURLOPT_LOW_SPEED_LIMIT, 1L);
             curl_easy_setopt(req.get(), CURLOPT_LOW_SPEED_TIME, fileTransferSettings.stalledDownloadTimeout.get());
@@ -909,10 +910,11 @@ struct curlFileTransfer : public FileTransfer
         std::string chunk;
         std::string_view buffered;
 
-        unsigned int attempt = 0;
         const size_t tries = fileTransferSettings.tries;
         curl_off_t totalReceived = 0;
 
+        Generator<BackoffTiming> backoff;
+
         TransferStream(
             curlFileTransfer & parent,
             const std::string & uri,
@@ -927,6 +929,12 @@ struct curlFileTransfer : public FileTransfer
             , data(std::move(data))
             , noBody(noBody)
             , parentAct(context ? context->id : 0)
+            , backoff(backoffTimeouts(
+                  fileTransferSettings.tries,
+                  std::chrono::seconds(fileTransferSettings.maxConnectTimeout.get()),
+                  std::chrono::seconds(fileTransferSettings.initialConnectTimeout.get()),
+                  std::chrono::milliseconds(parent.baseRetryTimeMs)
+              ))
         {
         }
 
@@ -944,8 +952,16 @@ struct curlFileTransfer : public FileTransfer
 
         kj::Promise<Result<void>> init()
         try {
-            auto setup = [&] { return startTransfer(uri); };
-            metadata = TRY_AWAIT(withRetries(setup, setup));
+            metadata = TRY_AWAIT(withRetries(
+                [&]() {
+                    return startTransfer(
+                        uri, std::chrono::seconds(fileTransferSettings.initialConnectTimeout.get())
+                    );
+                },
+                [&](const std::chrono::milliseconds & timeout) {
+                    return startTransfer(uri, timeout);
+                }
+            ));
             co_return result::success();
         } catch (...) {
             co_return result::current_exception();
@@ -954,34 +970,39 @@ struct curlFileTransfer : public FileTransfer
         auto withRetries(auto && initial, auto && retry) -> decltype(initial())
         try {
             std::optional<std::string> retryContext;
+            BackoffTiming timings;
             while (true) {
                 try {
                     if (retryContext) {
-                        TRY_AWAIT(prepareRetry(*retryContext));
-                        co_return TRY_AWAIT(retry());
+                        TRY_AWAIT(prepareRetry(*retryContext, timings.waitTime, timings.attempt));
+                        co_return TRY_AWAIT(retry(timings.downloadTimeout));
                     } else {
                         co_return TRY_AWAIT(initial());
                     }
                 } catch (FileTransferError & e) {
+                    auto next = backoff.next();
                     // If this is a transient error, then maybe retry after a while. after any
                     // bytes have been received we require range support to proceed, otherwise
                     // we'd need to start from scratch and discard everything we already have.
-                    if (e.error != Transient || data.has_value() || attempt >= tries
+                    if (e.error != Transient || data.has_value() || !next.has_value()
                         || (totalReceived > 0 && !transfer->acceptsRanges()))
                     {
                         throw;
                     }
                     retryContext = e.what();
+                    timings = *next;
                 }
             }
         } catch (...) {
             co_return result::current_exception();
         }
 
-        kj::Promise<Result<FileTransferResult>>
-        startTransfer(const std::string & uri, curl_off_t offset = 0)
+        kj::Promise<Result<FileTransferResult>> startTransfer(
+            const std::string & uri,
+            const std::chrono::milliseconds & timeout,
+            curl_off_t offset = 0
+        )
         try {
-            attempt += 1;
             auto uploadData = data ? std::optional(std::string_view(*data)) : std::nullopt;
             auto pfp = kj::newPromiseAndCrossThreadFulfiller<Result<FileTransferResult>>();
             transfer = std::make_shared<TransferItem>(
@@ -991,7 +1012,8 @@ struct curlFileTransfer : public FileTransfer
                 uploadData,
                 noBody,
                 offset,
-                std::move(pfp.fulfiller)
+                std::move(pfp.fulfiller),
+                timeout
             );
             parent.enqueueItem(transfer);
             co_return TRY_AWAIT(pfp.promise);
@@ -1008,30 +1030,38 @@ struct curlFileTransfer : public FileTransfer
             }
         }
 
-        kj::Promise<Result<void>> prepareRetry(const std::string & context)
+        kj::Promise<Result<void>> prepareRetry(
+            const std::string & context,
+            const std::chrono::milliseconds & waitTime,
+            unsigned int attempt
+        )
         try {
-            thread_local std::minstd_rand random{std::random_device{}()};
-            std::uniform_real_distribution<> dist(0.0, 0.5);
-            int ms = parent.baseRetryTimeMs * std::pow(2.0f, attempt - 1 + dist(random));
             if (totalReceived) {
-                warn("%s; retrying from offset %d in %d ms (attempt %d/%d)", context, totalReceived, ms, attempt, tries);
+                warn(
+                    "%s; retrying from offset %d in %d ms (attempt %d/%d)",
+                    context,
+                    totalReceived,
+                    waitTime,
+                    attempt,
+                    tries
+                );
             } else {
-                warn("%s; retrying in %d ms (attempt %d/%d)", context, ms, attempt, tries);
+                warn("%s; retrying in %d ms (attempt %d/%d)", context, waitTime, attempt, tries);
             }
 
-            co_await AIO().provider.getTimer().afterDelay(ms * kj::MILLISECONDS);
+            co_await AIO().provider.getTimer().afterDelay(waitTime.count() * kj::MILLISECONDS);
             co_return result::success();
         } catch (...) {
             co_return result::current_exception();
         }
 
-        kj::Promise<Result<void>> restartTransfer()
+        kj::Promise<Result<void>> restartTransfer(const std::chrono::milliseconds & timeout)
         try {
             // use the effective URI of the previous transfer for retries. this avoids
             // some silent corruption if a redirect changes between starting and retry
             const auto & uri = metadata.effectiveUri.empty() ? this->uri : metadata.effectiveUri;
 
-            auto newMeta = TRY_AWAIT(startTransfer(uri, totalReceived));
+            auto newMeta = TRY_AWAIT(startTransfer(uri, timeout, totalReceived));
             throwChangedTarget("final destination", metadata.effectiveUri, newMeta.effectiveUri);
             throwChangedTarget("ETag", metadata.etag, newMeta.etag);
             throwChangedTarget(
@@ -1078,9 +1108,9 @@ struct curlFileTransfer : public FileTransfer
             co_return result::current_exception();
         }
 
-        kj::Promise<Result<bool>> restartAndWaitForData()
+        kj::Promise<Result<bool>> restartAndWaitForData(const std::chrono::milliseconds & timeout)
         try {
-            TRY_AWAIT(restartTransfer());
+            TRY_AWAIT(restartTransfer(timeout));
             co_return TRY_AWAIT(waitForData());
         } catch (...) {
             co_return result::current_exception();
@@ -1088,9 +1118,12 @@ struct curlFileTransfer : public FileTransfer
 
         kj::Promise<Result<bool>> awaitData()
         try {
-            co_return TRY_AWAIT(
-                withRetries([&] { return waitForData(); }, [&] { return restartAndWaitForData(); })
-            );
+            co_return TRY_AWAIT(withRetries(
+                [&] { return waitForData(); },
+                [&](const std::chrono::milliseconds & timeout) {
+                    return restartAndWaitForData(timeout);
+                }
+            ));
         } catch (...) {
             co_return result::current_exception();
         }

lix/libstore/meson.build

@@ -52,10 +52,11 @@ libstore_settings_headers = []
 
 file_transfer_setting_definitions = files(
   # keep-sorted start
-  'file-transfer-settings/connect-timeout.md',
   'file-transfer-settings/download-attempts.md',
   'file-transfer-settings/http-connections.md',
   'file-transfer-settings/http2.md',
+  'file-transfer-settings/initial-connect-timeout.md',
+  'file-transfer-settings/max-connect-timeout.md',
   'file-transfer-settings/stalled-download-timeout.md',
   'file-transfer-settings/user-agent-suffix.md',
   # keep-sorted end

lix/libutil/backoff.hh

@@ -0,0 +1,52 @@
+#pragma once
+/// @file
+
+#include "generator.hh"
+#include "lix/libutil/error.hh"
+#include <cassert>
+#include <chrono>
+#include <cmath>
+#include <random>
+
+namespace nix {
+struct BackoffTiming
+{
+    std::chrono::milliseconds downloadTimeout;
+    std::chrono::milliseconds waitTime;
+    unsigned int attempt;
+};
+
+/**
+ * Generator which computes for each attempt of a retriable action (e.g. a download)
+ * the action's timeout and the time to wait in between using exponential backoff.
+ *
+ * The formula to compute the timeout of the ith attempt is
+ *
+ *     timeout := min(max_connect_timeout, initial_connect_timeout * 2^i)
+ *
+ * The increase factor 2^i is capped at 2^48, the initial backoff value is capped at 30s
+ * (30000ms) to prevent overflows.
+ */
+Generator<BackoffTiming> backoffTimeouts(
+    unsigned int maxAttempts,
+    std::chrono::milliseconds maxBackoff,
+    std::chrono::milliseconds initialBackoff,
+    std::chrono::milliseconds retryTime
+)
+{
+    thread_local std::default_random_engine generator(std::random_device{}());
+    std::uniform_real_distribution<> waitDist(-0.5, 0.5);
+
+    auto initialBackoffCapped = std::min(initialBackoff, std::chrono::milliseconds(30000));
+
+    for (unsigned int attempt = 1; attempt < maxAttempts; attempt++) {
+        int64_t increaseFactor = std::pow(2, std::min(attempt, 48u));
+        auto next = std::min(maxBackoff, initialBackoffCapped * increaseFactor);
+        auto wait = std::chrono::round<std::chrono::milliseconds>(
+            retryTime * std::pow(2, attempt) + retryTime * waitDist(generator)
+        );
+
+        co_yield BackoffTiming{next, wait, attempt};
+    }
+}
+}

lix/libutil/config.hh

@@ -294,6 +294,21 @@ public:
     void convertToArg(Args & args, const std::string & category) override;
 
     std::map<std::string, JSON> toJSONObject() const override;
+
+    bool isNameOrAlias(const std::string & requestedName)
+    {
+        if (requestedName == name) {
+            return true;
+        }
+
+        for (auto & alias : aliases) {
+            if (alias == requestedName) {
+                return true;
+            }
+        }
+
+        return false;
+    }
 };
 
 template<typename T>

lix/nix/main.cc

@@ -616,8 +616,9 @@ void mainWrapped(AsyncIoRoot & aio, int argc, char * * argv)
         // FIXME: should check for command line overrides only.
         settings.useSubstitutes.setDefault(false);
         settings.tarballTtl.setDefault(std::numeric_limits<unsigned int>::max());
-        fileTransferSettings.tries.setDefault(0);
-        fileTransferSettings.connectTimeout.setDefault(1);
+        fileTransferSettings.tries.setDefault(1);
+        fileTransferSettings.maxConnectTimeout.setDefault(1);
+        fileTransferSettings.initialConnectTimeout.setDefault(1);
     }
 
     if (args.refresh) {

tests/unit/libutil/backoff.cc

@@ -0,0 +1,52 @@
+#include <gtest/gtest.h>
+#include <lix/libutil/backoff.hh>
+
+namespace nix {
+TEST(Backoff, defaults)
+{
+    auto initial = 5;
+    auto backoff = backoffTimeouts(
+        5, std::chrono::seconds(300), std::chrono::seconds(initial), std::chrono::milliseconds(1000)
+    );
+
+    BackoffTiming timings = *backoff.next();
+    ASSERT_EQ(10000, timings.downloadTimeout.count());
+    ASSERT_LE(1500, timings.waitTime.count());
+    ASSERT_GE(2500, timings.waitTime.count());
+
+    timings = *backoff.next();
+    ASSERT_EQ(20000, timings.downloadTimeout.count());
+    ASSERT_LE(3500, timings.waitTime.count());
+    ASSERT_GE(4500, timings.waitTime.count());
+
+    ASSERT_TRUE(backoff.next().has_value());
+
+    timings = *backoff.next();
+    ASSERT_EQ(80000, timings.downloadTimeout.count());
+    ASSERT_LE(15500, timings.waitTime.count());
+    ASSERT_GE(16500, timings.waitTime.count());
+
+    ASSERT_FALSE(backoff.next().has_value());
+}
+
+TEST(Backoff, capped)
+{
+    auto initial = 10;
+    auto upper = 300;
+    auto backoff = backoffTimeouts(
+        7,
+        std::chrono::seconds(upper),
+        std::chrono::seconds(initial),
+        std::chrono::milliseconds(1000)
+    );
+
+    BackoffTiming timings = *backoff.next();
+    *backoff.next();
+    *backoff.next();
+    *backoff.next();
+    *backoff.next();
+    timings = *backoff.next();
+    ASSERT_EQ(300000, timings.downloadTimeout.count());
+    ASSERT_FALSE(backoff.next().has_value());
+}
+}

tests/unit/meson.build

@@ -47,6 +47,7 @@ libutil_tests_sources = files(
   'libutil/async-collect.cc',
   'libutil/async-io.cc',
   'libutil/async-semaphore.cc',
+  'libutil/backoff.cc',
   'libutil/canon-path.cc',
   'libutil/checked-arithmetic.cc',
   'libutil/chunked-vector.cc',