From 29f9facf763324a507f8fe7016a3078fb0350bbc Mon Sep 17 00:00:00 2001 From: Philip Wilk Date: Fri, 30 May 2025 20:40:42 +0100 Subject: [PATCH 1/2] Gracefully fallback from failing substituters --- src/libstore/build/substitution-goal.cc | 17 ++++++++++++++--- src/libstore/http-binary-cache-store.cc | 10 ++++------ src/libstore/store-api.cc | 14 +++++++++++--- 3 files changed, 29 insertions(+), 12 deletions(-) diff --git a/src/libstore/build/substitution-goal.cc b/src/libstore/build/substitution-goal.cc index 9ffc8219d..59afc12cd 100644 --- a/src/libstore/build/substitution-goal.cc +++ b/src/libstore/build/substitution-goal.cc @@ -60,6 +60,10 @@ Goal::Co PathSubstitutionGoal::init() for (const auto & sub : subs) { trace("trying next substituter"); + // If sub is not first, previous one must have failed, so warn + if (&sub != &subs.front()) { + warn("trying next substituter, '%s'", sub->getUri()); + } cleanup(); @@ -80,14 +84,21 @@ Goal::Co PathSubstitutionGoal::init() continue; } + auto path = subPath ? *subPath : storePath; try { // FIXME: make async - info = sub->queryPathInfo(subPath ? *subPath : storePath); + info = sub->queryPathInfo(path); + // Because the path doesn't exist } catch (InvalidPath &) { continue; + // Because the substituter has failed recently } catch (SubstituterDisabled & e) { - if (settings.tryFallback) continue; - else throw e; + warn( + "Substituter '%s' was disabled when getting info for path '%s'", + sub->getUri(), + sub->printStorePath(path)); + continue; + // Any other error } catch (Error & e) { if (settings.tryFallback) { logError(e.info()); diff --git a/src/libstore/http-binary-cache-store.cc b/src/libstore/http-binary-cache-store.cc index e44d146b9..7fa9203b5 100644 --- a/src/libstore/http-binary-cache-store.cc +++ b/src/libstore/http-binary-cache-store.cc @@ -97,12 +97,10 @@ protected: void maybeDisable() { auto state(_state.lock()); - if (state->enabled && settings.tryFallback) { - int t = 60; - printError("disabling binary cache '%s' for %s seconds", getUri(), t); - state->enabled = false; - state->disabledUntil = std::chrono::steady_clock::now() + std::chrono::seconds(t); - } + int t = 60; + warn("disabling binary cache '%s' for %s seconds", getUri(), t); + state->enabled = false; + state->disabledUntil = std::chrono::steady_clock::now() + std::chrono::seconds(t); } void checkEnabled() diff --git a/src/libstore/store-api.cc b/src/libstore/store-api.cc index 296f2251a..4aaffdbd6 100644 --- a/src/libstore/store-api.cc +++ b/src/libstore/store-api.cc @@ -520,7 +520,8 @@ StorePathSet Store::queryDerivationOutputs(const StorePath & path) void Store::querySubstitutablePathInfos(const StorePathCAMap & paths, SubstitutablePathInfos & infos) { if (!settings.useSubstitutes) return; - for (auto & sub : getDefaultSubstituters()) { + auto substituters = getDefaultSubstituters(); + for (auto & sub : substituters) { for (auto & path : paths) { if (infos.count(path.first)) // Choose first succeeding substituter. @@ -557,10 +558,17 @@ void Store::querySubstitutablePathInfos(const StorePathCAMap & paths, Substituta } catch (InvalidPath &) { } catch (SubstituterDisabled &) { } catch (Error & e) { - if (settings.tryFallback) + // if last substituter, THEN log error and throw, otherwise warn + if (&sub == &substituters.back() && settings.tryFallback) { logError(e.info()); - else throw; + } else { + warn( + "Unable to download '%s' from subsituter '%s'\n%s", + sub->printStorePath(subPath), + sub->getUri(), + e.message()); + } } } } From 245bc5d547864f19fe253263cc923b2082ab916e Mon Sep 17 00:00:00 2001 From: Philip Wilk Date: Mon, 2 Jun 2025 02:57:52 +0100 Subject: [PATCH 2/2] silence logs because it gets overwhelming --- src/libstore/build/substitution-goal.cc | 7 ++----- src/libstore/store-api.cc | 8 +++++--- 2 files changed, 7 insertions(+), 8 deletions(-) diff --git a/src/libstore/build/substitution-goal.cc b/src/libstore/build/substitution-goal.cc index 59afc12cd..bd8d200fb 100644 --- a/src/libstore/build/substitution-goal.cc +++ b/src/libstore/build/substitution-goal.cc @@ -60,10 +60,6 @@ Goal::Co PathSubstitutionGoal::init() for (const auto & sub : subs) { trace("trying next substituter"); - // If sub is not first, previous one must have failed, so warn - if (&sub != &subs.front()) { - warn("trying next substituter, '%s'", sub->getUri()); - } cleanup(); @@ -88,15 +84,16 @@ Goal::Co PathSubstitutionGoal::init() try { // FIXME: make async info = sub->queryPathInfo(path); - // Because the path doesn't exist } catch (InvalidPath &) { continue; // Because the substituter has failed recently } catch (SubstituterDisabled & e) { + /* This is also VERY spammy warn( "Substituter '%s' was disabled when getting info for path '%s'", sub->getUri(), sub->printStorePath(path)); + */ continue; // Any other error } catch (Error & e) { diff --git a/src/libstore/store-api.cc b/src/libstore/store-api.cc index 4aaffdbd6..08fd02489 100644 --- a/src/libstore/store-api.cc +++ b/src/libstore/store-api.cc @@ -559,15 +559,17 @@ void Store::querySubstitutablePathInfos(const StorePathCAMap & paths, Substituta } catch (SubstituterDisabled &) { } catch (Error & e) { // if last substituter, THEN log error and throw, otherwise warn - if (&sub == &substituters.back() && settings.tryFallback) { + if (&sub == &substituters.back() && !settings.tryFallback) { logError(e.info()); throw; } else { - warn( - "Unable to download '%s' from subsituter '%s'\n%s", + /* This gets VERY spammy + warn( "Unable to download '%s' from subsituter '%s'\n%s", sub->printStorePath(subPath), sub->getUri(), e.message()); + */ + continue; } } }