From 363e3a4c91da353d99cf1af3d5089c9455d461de Mon Sep 17 00:00:00 2001 From: Julian Andres Klode Date: Tue, 13 Jul 2021 16:03:06 +0200 Subject: pkgAcqIndex::CommonFailed: Set StatIdle before calling Init() Enqueuing by calling Init(), and then resetting the status to idle means that the item can get enqueued twice if we call Cycle() from inside pkgAcquire::Run(). Reset the status to StatIdle before calling Init() --- apt-pkg/acquire-item.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/apt-pkg/acquire-item.cc b/apt-pkg/acquire-item.cc index 37a715390..7c23434ae 100644 --- a/apt-pkg/acquire-item.cc +++ b/apt-pkg/acquire-item.cc @@ -3205,8 +3205,8 @@ bool pkgAcqIndex::CommonFailed(std::string const &TargetURI, { if (CompressionExtensions.empty() == false) { - Init(TargetURI, Desc.Description, Desc.ShortDesc); Status = StatIdle; + Init(TargetURI, Desc.Description, Desc.ShortDesc); return true; } } -- cgit v1.2.3-70-g09d2 From 121ccd0e0c2612bab9ba5383d5599b54e29e4643 Mon Sep 17 00:00:00 2001 From: Julian Andres Klode Date: Thu, 8 Jul 2021 16:49:20 +0200 Subject: Implement exponential delay between retries Add a new Item field called FetchAfter, which determines the earliest time the item should be fetched at. Adjust insertion into queue to take it into account alongside priority, and only fill pipelines with items that are ready. --- apt-pkg/acquire-item.cc | 10 ++++++++++ apt-pkg/acquire-item.h | 3 +++ apt-pkg/acquire-worker.cc | 11 +++++++++++ apt-pkg/acquire.cc | 25 ++++++++++++++++++++++--- apt-pkg/acquire.h | 2 ++ doc/examples/configure-index | 4 +++- 6 files changed, 51 insertions(+), 4 deletions(-) diff --git a/apt-pkg/acquire-item.cc b/apt-pkg/acquire-item.cc index 7c23434ae..20d80edc0 100644 --- a/apt-pkg/acquire-item.cc +++ b/apt-pkg/acquire-item.cc @@ -290,6 +290,7 @@ public: std::vector BadAlternativeSites; std::vector PastRedirections; std::unordered_map CustomFields; + time_t FetchAfter = 0; Private() { @@ -1120,6 +1121,15 @@ std::string pkgAcquire::Item::HashSum() const /*{{{*/ return hs != NULL ? hs->toStr() : ""; } /*}}}*/ +void pkgAcquire::Item::FetchAfter(time_t FetchAfter) /*{{{*/ +{ + d->FetchAfter = FetchAfter; +} +time_t pkgAcquire::Item::FetchAfter() +{ + return d->FetchAfter; +} + /*}}}*/ bool pkgAcquire::Item::IsRedirectionLoop(std::string const &NewURI) /*{{{*/ { // store can fail due to permission errors and the item will "loop" then diff --git a/apt-pkg/acquire-item.h b/apt-pkg/acquire-item.h index 3be8a9c62..33106226f 100644 --- a/apt-pkg/acquire-item.h +++ b/apt-pkg/acquire-item.h @@ -301,6 +301,9 @@ class APT_PUBLIC pkgAcquire::Item : public WeakPointable /*{{{*/ /** \brief The priority of the item, used for queuing */ int APT_HIDDEN Priority(); + void APT_HIDDEN FetchAfter(time_t FetchAfter); + time_t APT_HIDDEN FetchAfter(); + protected: /** \brief The acquire object with which this item is associated. */ pkgAcquire * const Owner; diff --git a/apt-pkg/acquire-worker.cc b/apt-pkg/acquire-worker.cc index 3fbc5c09f..5272ae0cb 100644 --- a/apt-pkg/acquire-worker.cc +++ b/apt-pkg/acquire-worker.cc @@ -632,6 +632,7 @@ void pkgAcquire::Worker::HandleFailure(std::vector const &It pkgAcquire::MethodConfig *const Config, pkgAcquireStatus *const Log, std::string const &Message, bool const errTransient, bool const errAuthErr) { + time_t currentTime = time(nullptr); for (auto const Owner : ItmOwners) { std::string NewURI; @@ -640,6 +641,16 @@ void pkgAcquire::Worker::HandleFailure(std::vector const &It --Owner->Retries; Owner->FailMessage(Message); auto SavedDesc = Owner->GetItemDesc(); + if (_config->FindB("Acquire::Retries::Delay", true)) + { + auto Iter = _config->FindI("Acquire::Retries", 3) - Owner->Retries - 1; + Owner->FetchAfter(currentTime + (1 << Iter)); + } + else + { + Owner->FetchAfter(currentTime); + } + if (Log != nullptr) Log->Fail(SavedDesc); if (isDoomedItem(Owner) == false) diff --git a/apt-pkg/acquire.cc b/apt-pkg/acquire.cc index 8693de930..806f8e212 100644 --- a/apt-pkg/acquire.cc +++ b/apt-pkg/acquire.cc @@ -24,14 +24,15 @@ #include #include +#include #include #include #include #include #include #include +#include #include -#include #include #include @@ -962,6 +963,7 @@ bool pkgAcquire::Queue::Enqueue(ItemDesc &Item) }; QItem **OptimalI = &Items; QItem **I = &Items; + auto insertLocation = std::make_tuple(Item.Owner->FetchAfter(), -Item.Owner->Priority()); // move to the end of the queue and check for duplicates here for (; *I != 0; ) { if (Item.URI == (*I)->URI && MetaKeysMatch(Item, *I)) @@ -974,10 +976,12 @@ bool pkgAcquire::Queue::Enqueue(ItemDesc &Item) } // Determine the optimal position to insert: before anything with a // higher priority. - int priority = (*I)->GetPriority(); + auto queueLocation = std::make_tuple((*I)->GetFetchAfter(), + -(*I)->GetPriority()); I = &(*I)->Next; - if (priority >= Item.Owner->Priority()) { + if (queueLocation <= insertLocation) + { OptimalI = I; } } @@ -1153,6 +1157,7 @@ bool pkgAcquire::Queue::Cycle() // Look for a queable item QItem *I = Items; int ActivePriority = 0; + time_t currentTime = time(nullptr); while (PipeDepth < static_cast(MaxPipeDepth)) { for (; I != 0; I = I->Next) { @@ -1170,6 +1175,11 @@ bool pkgAcquire::Queue::Cycle() // the queue is idle if (I->GetPriority() < ActivePriority) return true; + + // Item is not ready yet, delay + if (I->GetFetchAfter() > currentTime) + return true; + I->Worker = Workers; for (auto const &O: I->Owners) O->Status = pkgAcquire::Item::StatFetching; @@ -1237,6 +1247,15 @@ APT_PURE int pkgAcquire::Queue::QItem::GetPriority() const /*{{{*/ return Priority; } /*}}}*/ +APT_PURE time_t pkgAcquire::Queue::QItem::GetFetchAfter() const /*{{{*/ +{ + time_t FetchAfter = 0; + for (auto const &O : Owners) + FetchAfter = std::max(FetchAfter, O->FetchAfter()); + + return FetchAfter; +} + /*}}}*/ void pkgAcquire::Queue::QItem::SyncDestinationFiles() const /*{{{*/ { /* ensure that the first owner has the best partial file of all and diff --git a/apt-pkg/acquire.h b/apt-pkg/acquire.h index a2c4fbc67..303554041 100644 --- a/apt-pkg/acquire.h +++ b/apt-pkg/acquire.h @@ -458,6 +458,8 @@ class APT_PUBLIC pkgAcquire::Queue std::string Custom600Headers() const; /** @return the maximum priority of this item */ int APT_HIDDEN GetPriority() const; + /** @return the maximum time to fetch this item at */ + time_t APT_HIDDEN GetFetchAfter() const; }; /** \brief The name of this queue. */ diff --git a/doc/examples/configure-index b/doc/examples/configure-index index 312ee27d6..e74ebc3d7 100644 --- a/doc/examples/configure-index +++ b/doc/examples/configure-index @@ -230,7 +230,9 @@ APT Acquire { Queue-Mode ""; // host or access - Retries ""; + Retries "" { + Delay ""; // whether to backoff between retries using the delay: method + }; Source-Symlinks ""; ForceHash ""; // hashmethod used for expected hash: sha256, sha1 or md5sum Send-URI-Encoded ""; // false does the old encode/decode dance even if we could avoid it -- cgit v1.2.3-70-g09d2 From 7e88def0548a92112f8295686c2a12379e4028be Mon Sep 17 00:00:00 2001 From: Julian Andres Klode Date: Tue, 13 Jul 2021 12:21:23 +0200 Subject: acquire: Automatically reduce select() timeout as needed If there is an item with fetchAfter at the top of a queue, reduce sleep() timeout so we can detect it and start it, by calling Cycle() on the queue in the next iteration. For some reasons we have to call select() with a 0s timeout if we just marked an item as ready. Oh well. Previous versions of this patch only called global Bump() after a timeout from select(); this was unfortunately incorrect - it meant that we never bumped a queue that did not start yet while other queues were running, potentially significantly delaying retries. --- apt-pkg/acquire.cc | 36 +++++++++++++++++++++++++++++++++++- 1 file changed, 35 insertions(+), 1 deletion(-) diff --git a/apt-pkg/acquire.cc b/apt-pkg/acquire.cc index 806f8e212..5b3d5906b 100644 --- a/apt-pkg/acquire.cc +++ b/apt-pkg/acquire.cc @@ -34,6 +34,7 @@ #include #include +#include #include #include #include @@ -714,7 +715,38 @@ pkgAcquire::RunResult pkgAcquire::Run(int PulseIntervall) FD_ZERO(&RFds); FD_ZERO(&WFds); SetFds(Highest,&RFds,&WFds); - + + // Shorten the select() cycle in case we have items about to become ready + time_t now = time(nullptr); + time_t fetchAfter = 0; + for (Queue *I = Queues; I != nullptr; I = I->Next) + { + if (I->Items == nullptr) + continue; + + auto f = I->Items->GetFetchAfter(); + + if (f == 0 || I->Items->Owner->Status != pkgAcquire::Item::StatIdle) + continue; + + if (f <= now) + { + I->Cycle(); // Queue got stuck, unstuck it. + fetchAfter = now; // need to time out in select() below + assert(I->Items->Owner->Status != pkgAcquire::Item::StatIdle); + } + else if (f < fetchAfter || fetchAfter == 0) + { + fetchAfter = f; + } + } + + if (fetchAfter && (fetchAfter - now) < (tv.tv_sec + tv.tv_usec / 1e6)) + { + tv.tv_sec = fetchAfter - now; + tv.tv_usec = 0; + } + int Res; do { @@ -734,7 +766,9 @@ pkgAcquire::RunResult pkgAcquire::Run(int PulseIntervall) // Timeout, notify the log class if (Res == 0 || (Log != 0 && Log->Update == true)) { + tv.tv_sec = 0; tv.tv_usec = PulseIntervall; + for (Worker *I = Workers; I != 0; I = I->NextAcquire) I->Pulse(); if (Log != 0 && Log->Pulse(this) == false) -- cgit v1.2.3-70-g09d2 From 48a7ece8d0e065240153a85089f544383e16137f Mon Sep 17 00:00:00 2001 From: Julian Andres Klode Date: Tue, 27 Jul 2021 16:40:38 +0200 Subject: Convert to monotonic clock This yields more accurate delays and avoids issues with clock skew. --- apt-pkg/acquire-item.cc | 6 +++--- apt-pkg/acquire-item.h | 5 +++-- apt-pkg/acquire-worker.cc | 5 +++-- apt-pkg/acquire.cc | 32 ++++++++++++++++++-------------- apt-pkg/acquire.h | 7 ++++++- 5 files changed, 33 insertions(+), 22 deletions(-) diff --git a/apt-pkg/acquire-item.cc b/apt-pkg/acquire-item.cc index 20d80edc0..eb8053feb 100644 --- a/apt-pkg/acquire-item.cc +++ b/apt-pkg/acquire-item.cc @@ -290,7 +290,7 @@ public: std::vector BadAlternativeSites; std::vector PastRedirections; std::unordered_map CustomFields; - time_t FetchAfter = 0; + time_point FetchAfter = {}; Private() { @@ -1121,11 +1121,11 @@ std::string pkgAcquire::Item::HashSum() const /*{{{*/ return hs != NULL ? hs->toStr() : ""; } /*}}}*/ -void pkgAcquire::Item::FetchAfter(time_t FetchAfter) /*{{{*/ +void pkgAcquire::Item::FetchAfter(time_point FetchAfter) /*{{{*/ { d->FetchAfter = FetchAfter; } -time_t pkgAcquire::Item::FetchAfter() +pkgAcquire::time_point pkgAcquire::Item::FetchAfter() { return d->FetchAfter; } diff --git a/apt-pkg/acquire-item.h b/apt-pkg/acquire-item.h index 33106226f..22da9815d 100644 --- a/apt-pkg/acquire-item.h +++ b/apt-pkg/acquire-item.h @@ -301,8 +301,9 @@ class APT_PUBLIC pkgAcquire::Item : public WeakPointable /*{{{*/ /** \brief The priority of the item, used for queuing */ int APT_HIDDEN Priority(); - void APT_HIDDEN FetchAfter(time_t FetchAfter); - time_t APT_HIDDEN FetchAfter(); + /** \brief internal clock definitions to avoid typing all that all over the place */ + void APT_HIDDEN FetchAfter(time_point FetchAfter); + time_point APT_HIDDEN FetchAfter(); protected: /** \brief The acquire object with which this item is associated. */ diff --git a/apt-pkg/acquire-worker.cc b/apt-pkg/acquire-worker.cc index 5272ae0cb..7be51d114 100644 --- a/apt-pkg/acquire-worker.cc +++ b/apt-pkg/acquire-worker.cc @@ -632,7 +632,7 @@ void pkgAcquire::Worker::HandleFailure(std::vector const &It pkgAcquire::MethodConfig *const Config, pkgAcquireStatus *const Log, std::string const &Message, bool const errTransient, bool const errAuthErr) { - time_t currentTime = time(nullptr); + auto currentTime = clock::now(); for (auto const Owner : ItmOwners) { std::string NewURI; @@ -644,7 +644,8 @@ void pkgAcquire::Worker::HandleFailure(std::vector const &It if (_config->FindB("Acquire::Retries::Delay", true)) { auto Iter = _config->FindI("Acquire::Retries", 3) - Owner->Retries - 1; - Owner->FetchAfter(currentTime + (1 << Iter)); + auto Dur = std::chrono::seconds(1 << Iter); + Owner->FetchAfter(currentTime + Dur); } else { diff --git a/apt-pkg/acquire.cc b/apt-pkg/acquire.cc index 5b3d5906b..e97f5e6f3 100644 --- a/apt-pkg/acquire.cc +++ b/apt-pkg/acquire.cc @@ -53,6 +53,14 @@ using namespace std; +// helper to convert time_point to a timeval +static struct timeval SteadyDurationToTimeVal(std::chrono::steady_clock::duration Time) +{ + auto const Time_sec = std::chrono::duration_cast(Time); + auto const Time_usec = std::chrono::duration_cast(Time - Time_sec); + return {Time_sec.count(), Time_usec.count()}; +} + std::string pkgAcquire::URIEncode(std::string const &part) /*{{{*/ { // The "+" is encoded as a workaround for an S3 bug (LP#1003633 and LP#1086997) @@ -717,8 +725,8 @@ pkgAcquire::RunResult pkgAcquire::Run(int PulseIntervall) SetFds(Highest,&RFds,&WFds); // Shorten the select() cycle in case we have items about to become ready - time_t now = time(nullptr); - time_t fetchAfter = 0; + auto now = clock::now(); + auto fetchAfter = time_point{}; for (Queue *I = Queues; I != nullptr; I = I->Next) { if (I->Items == nullptr) @@ -726,7 +734,7 @@ pkgAcquire::RunResult pkgAcquire::Run(int PulseIntervall) auto f = I->Items->GetFetchAfter(); - if (f == 0 || I->Items->Owner->Status != pkgAcquire::Item::StatIdle) + if (f == time_point() || I->Items->Owner->Status != pkgAcquire::Item::StatIdle) continue; if (f <= now) @@ -735,16 +743,15 @@ pkgAcquire::RunResult pkgAcquire::Run(int PulseIntervall) fetchAfter = now; // need to time out in select() below assert(I->Items->Owner->Status != pkgAcquire::Item::StatIdle); } - else if (f < fetchAfter || fetchAfter == 0) + else if (f < fetchAfter || fetchAfter == time_point{}) { fetchAfter = f; } } - if (fetchAfter && (fetchAfter - now) < (tv.tv_sec + tv.tv_usec / 1e6)) + if (fetchAfter != time_point{} && (fetchAfter - now) < std::chrono::seconds(tv.tv_sec) + std::chrono::microseconds(tv.tv_usec)) { - tv.tv_sec = fetchAfter - now; - tv.tv_usec = 0; + tv = SteadyDurationToTimeVal(fetchAfter - now); } int Res; @@ -1191,7 +1198,7 @@ bool pkgAcquire::Queue::Cycle() // Look for a queable item QItem *I = Items; int ActivePriority = 0; - time_t currentTime = time(nullptr); + auto currentTime = clock::now(); while (PipeDepth < static_cast(MaxPipeDepth)) { for (; I != 0; I = I->Next) { @@ -1281,9 +1288,9 @@ APT_PURE int pkgAcquire::Queue::QItem::GetPriority() const /*{{{*/ return Priority; } /*}}}*/ -APT_PURE time_t pkgAcquire::Queue::QItem::GetFetchAfter() const /*{{{*/ +APT_PURE pkgAcquire::time_point pkgAcquire::Queue::QItem::GetFetchAfter() const /*{{{*/ { - time_t FetchAfter = 0; + time_point FetchAfter{}; for (auto const &O : Owners) FetchAfter = std::max(FetchAfter, O->FetchAfter()); @@ -1347,10 +1354,7 @@ pkgAcquireStatus::pkgAcquireStatus() : d(NULL), Percent(-1), Update(true), MoreP as well as the current CPS estimate. */ static struct timeval GetTimevalFromSteadyClock() { - auto const Time = std::chrono::steady_clock::now().time_since_epoch(); - auto const Time_sec = std::chrono::duration_cast(Time); - auto const Time_usec = std::chrono::duration_cast(Time - Time_sec); - return { Time_sec.count(), Time_usec.count() }; + return SteadyDurationToTimeVal(std::chrono::steady_clock::now().time_since_epoch()); } bool pkgAcquireStatus::Pulse(pkgAcquire *Owner) { diff --git a/apt-pkg/acquire.h b/apt-pkg/acquire.h index 303554041..09bb408bc 100644 --- a/apt-pkg/acquire.h +++ b/apt-pkg/acquire.h @@ -69,6 +69,7 @@ #include #include +#include #include #include @@ -92,6 +93,10 @@ class metaIndex; class APT_PUBLIC pkgAcquire { private: + /** \brief The monotonic clock used by the Acquire system */ + using clock = std::chrono::steady_clock; + /** \brief Time point on our monotonic clock */ + using time_point = std::chrono::time_point; /** \brief FD of the Lock file we acquire in Setup (if any) */ int LockFD; /** \brief dpointer placeholder (for later in case we need it) */ @@ -459,7 +464,7 @@ class APT_PUBLIC pkgAcquire::Queue /** @return the maximum priority of this item */ int APT_HIDDEN GetPriority() const; /** @return the maximum time to fetch this item at */ - time_t APT_HIDDEN GetFetchAfter() const; + time_point APT_HIDDEN GetFetchAfter() const; }; /** \brief The name of this queue. */ -- cgit v1.2.3-70-g09d2 From 51ee79e385d8ccb2f32195cc01f3f9c943197603 Mon Sep 17 00:00:00 2001 From: Julian Andres Klode Date: Tue, 27 Jul 2021 17:14:23 +0200 Subject: Properly convert PulseInterval to timeval Fix the typo, and use the helper function to convert it, so we do not end up with 5 seconds encoded as 0s and 5*10^6 microseconds. --- apt-pkg/acquire.cc | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) diff --git a/apt-pkg/acquire.cc b/apt-pkg/acquire.cc index e97f5e6f3..c3682504f 100644 --- a/apt-pkg/acquire.cc +++ b/apt-pkg/acquire.cc @@ -696,7 +696,7 @@ static void CheckDropPrivsMustBeDisabled(pkgAcquire const &Fetcher) if (setgroups(old_gidlist_nr, old_gidlist.get())) _error->FatalE("setgroups", "setgroups %u failed", 0); } -pkgAcquire::RunResult pkgAcquire::Run(int PulseIntervall) +pkgAcquire::RunResult pkgAcquire::Run(int PulseInterval) { _error->PushToStack(); CheckDropPrivsMustBeDisabled(*this); @@ -712,9 +712,7 @@ pkgAcquire::RunResult pkgAcquire::Run(int PulseIntervall) bool WasCancelled = false; // Run till all things have been acquired - struct timeval tv; - tv.tv_sec = 0; - tv.tv_usec = PulseIntervall; + struct timeval tv = SteadyDurationToTimeVal(std::chrono::microseconds(PulseInterval)); while (ToFetch > 0) { fd_set RFds; @@ -773,8 +771,7 @@ pkgAcquire::RunResult pkgAcquire::Run(int PulseIntervall) // Timeout, notify the log class if (Res == 0 || (Log != 0 && Log->Update == true)) { - tv.tv_sec = 0; - tv.tv_usec = PulseIntervall; + tv = SteadyDurationToTimeVal(std::chrono::microseconds(PulseInterval)); for (Worker *I = Workers; I != 0; I = I->NextAcquire) I->Pulse(); -- cgit v1.2.3-70-g09d2 From 4001af8920389e2bb2672b673b181c4e92515872 Mon Sep 17 00:00:00 2001 From: Julian Andres Klode Date: Wed, 28 Jul 2021 12:43:56 +0200 Subject: Add support for a maximum delay and testing of delay This is very basic support on the testing side, we just test the debug output but not how long it actually took. Would be nice to check time really. --- apt-pkg/acquire-worker.cc | 5 ++++- doc/examples/configure-index | 5 ++++- test/integration/test-bug-869859-retry-downloads | 13 ++++++++++++- 3 files changed, 20 insertions(+), 3 deletions(-) diff --git a/apt-pkg/acquire-worker.cc b/apt-pkg/acquire-worker.cc index 7be51d114..1bf07e82a 100644 --- a/apt-pkg/acquire-worker.cc +++ b/apt-pkg/acquire-worker.cc @@ -644,7 +644,10 @@ void pkgAcquire::Worker::HandleFailure(std::vector const &It if (_config->FindB("Acquire::Retries::Delay", true)) { auto Iter = _config->FindI("Acquire::Retries", 3) - Owner->Retries - 1; - auto Dur = std::chrono::seconds(1 << Iter); + auto const MaxDur = _config->FindI("Acquire::Retries::Delay::Maximum", 30); + auto Dur = std::chrono::seconds(std::min(1 << Iter, MaxDur)); + if (_config->FindB("Debug::Acquire::Retries")) + std::clog << "Delaying " << SavedDesc.Description << " by " << Dur.count() << " seconds" << std::endl; Owner->FetchAfter(currentTime + Dur); } else diff --git a/doc/examples/configure-index b/doc/examples/configure-index index e74ebc3d7..4eca100f5 100644 --- a/doc/examples/configure-index +++ b/doc/examples/configure-index @@ -231,7 +231,9 @@ Acquire { Queue-Mode ""; // host or access Retries "" { - Delay ""; // whether to backoff between retries using the delay: method + Delay "" { // whether to backoff between retries using the delay: method + Maximum ""; // maximum number of seconds to delay an item per retry + }; }; Source-Symlinks ""; ForceHash ""; // hashmethod used for expected hash: sha256, sha1 or md5sum @@ -557,6 +559,7 @@ Debug Acquire::cdrom ""; // Show cdrom debug output Acquire::Transaction ""; Acquire::Progress ""; + Acquire::Retries ""; // Debugging for retries, especially delays aptcdrom ""; // Show found package files IdentCdrom ""; acquire::netrc ""; // netrc parser diff --git a/test/integration/test-bug-869859-retry-downloads b/test/integration/test-bug-869859-retry-downloads index 86203f794..66e158a9d 100755 --- a/test/integration/test-bug-869859-retry-downloads +++ b/test/integration/test-bug-869859-retry-downloads @@ -21,7 +21,18 @@ rm -f testpkg_1_all.deb msgmsg 'Fail after too many retries' webserverconfig 'aptwebserver::failrequest' '429' webserverconfig 'aptwebserver::failrequest::pool/testpkg_1_all.deb' '99' -testfailure apt download testpkg -o acquire::retries=3 +testfailureequal "Delaying http://localhost:${APTHTTPPORT} stable/main all testpkg all 1 by 1 seconds +Ign:1 http://localhost:${APTHTTPPORT} stable/main all testpkg all 1 + 429 Unknown HTTP code +Delaying http://localhost:${APTHTTPPORT} stable/main all testpkg all 1 by 2 seconds +Ign:1 http://localhost:${APTHTTPPORT} stable/main all testpkg all 1 + 429 Unknown HTTP code +Delaying http://localhost:${APTHTTPPORT} stable/main all testpkg all 1 by 4 seconds +Ign:1 http://localhost:${APTHTTPPORT} stable/main all testpkg all 1 + 429 Unknown HTTP code +Err:1 http://localhost:${APTHTTPPORT} stable/main all testpkg all 1 + 429 Unknown HTTP code +E: Failed to fetch http://localhost:${APTHTTPPORT}/pool/testpkg_1_all.deb 429 Unknown HTTP code" apt download testpkg -o acquire::retries=3 -o debug::acquire::retries=true -q testfailure test -f testpkg_1_all.deb msgmsg 'Success in the third try' -- cgit v1.2.3-70-g09d2 From 70ee96670bbc09e724aeeb6263ee6a3bdde8afdc Mon Sep 17 00:00:00 2001 From: Julian Andres Klode Date: Thu, 29 Jul 2021 11:46:47 +0200 Subject: Enhance test to check time spent This is subject to clock skew, unfortunately, as we cannot read monotonic time in shell. We check for >=5s out of the 7s it should take to reduce the risk of skew a bit. --- test/integration/test-bug-869859-retry-downloads | 18 +++++++++++++++++- 1 file changed, 17 insertions(+), 1 deletion(-) diff --git a/test/integration/test-bug-869859-retry-downloads b/test/integration/test-bug-869859-retry-downloads index 66e158a9d..12ca40c77 100755 --- a/test/integration/test-bug-869859-retry-downloads +++ b/test/integration/test-bug-869859-retry-downloads @@ -4,6 +4,22 @@ set -e TESTDIR="$(readlink -f "$(dirname "$0")")" . "$TESTDIR/framework" +testsecondsgreaterequal() { + seconds="$1" + shift + before=$(date +%s) + "$@" + after=$(date +%s) + msggroup 'testsecondsgreaterequal' + msgtest "Checking that previous test took more than $secondss" + if [ $((after - before)) -lt $seconds ]; then + msgfail "Took $((after - before)) second" + else + msgpass + fi + msggroup +} + setupenvironment configarchitecture 'amd64' @@ -21,7 +37,7 @@ rm -f testpkg_1_all.deb msgmsg 'Fail after too many retries' webserverconfig 'aptwebserver::failrequest' '429' webserverconfig 'aptwebserver::failrequest::pool/testpkg_1_all.deb' '99' -testfailureequal "Delaying http://localhost:${APTHTTPPORT} stable/main all testpkg all 1 by 1 seconds +testsecondsgreaterequal 5 testfailureequal "Delaying http://localhost:${APTHTTPPORT} stable/main all testpkg all 1 by 1 seconds Ign:1 http://localhost:${APTHTTPPORT} stable/main all testpkg all 1 429 Unknown HTTP code Delaying http://localhost:${APTHTTPPORT} stable/main all testpkg all 1 by 2 seconds -- cgit v1.2.3-70-g09d2 From 3ca5e18b1f0bb05697ccca7c98ced1176166024a Mon Sep 17 00:00:00 2001 From: Julian Andres Klode Date: Thu, 29 Jul 2021 11:49:05 +0200 Subject: tests (retry-downloads): Avoid delay in second test This delay of 4+2+1=7 seconds in unnecessary. --- test/integration/test-bug-869859-retry-downloads | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/integration/test-bug-869859-retry-downloads b/test/integration/test-bug-869859-retry-downloads index 12ca40c77..4e169b3b9 100755 --- a/test/integration/test-bug-869859-retry-downloads +++ b/test/integration/test-bug-869859-retry-downloads @@ -53,7 +53,7 @@ testfailure test -f testpkg_1_all.deb msgmsg 'Success in the third try' webserverconfig 'aptwebserver::failrequest::pool/testpkg_1_all.deb' '2' -testsuccess apt download testpkg -o acquire::retries=3 +testsuccess apt download testpkg -o acquire::retries=3 -o acquire::retries::delay=false testsuccess test -f testpkg_1_all.deb rm -f testpkg_1_all.deb -- cgit v1.2.3-70-g09d2