Fixing --eta

This commit is contained in:
Miroslav Štampar 2026-07-09 13:25:50 +02:00
parent 767feba3a7
commit 4c12dda2f7
7 changed files with 285 additions and 19 deletions

View file

@ -56,7 +56,9 @@ class TestProgressBar(unittest.TestCase):
def test_progress_draws_eta_after_second_call(self):
captured = []
real = progress_mod.dataToStdout
realTty = progress_mod.IS_TTY
progress_mod.dataToStdout = lambda data, *a, **k: captured.append(data)
progress_mod.IS_TTY = True # draw() only animates on a terminal
try:
pb = ProgressBar(0, 10, 78)
pb.progress(0) # first call only seeds the timer (eta None)
@ -64,6 +66,7 @@ class TestProgressBar(unittest.TestCase):
pb.progress(5) # second call computes and draws a real ETA
finally:
progress_mod.dataToStdout = real
progress_mod.IS_TTY = realTty
self.assertTrue(captured, msg="progress() never wrote to stdout")
last = captured[-1]
@ -73,6 +76,134 @@ class TestProgressBar(unittest.TestCase):
self.assertTrue(re.search(r"\(ETA \d{2}:\d{2}\)", last),
msg="ETA token missing an mm:ss timer: %r" % last)
def test_eta_available_from_first_completed_item(self):
captured = []
real = progress_mod.dataToStdout
realTty = progress_mod.IS_TTY
progress_mod.dataToStdout = lambda data, *a, **k: captured.append(data)
progress_mod.IS_TTY = True
try:
pb = ProgressBar(0, 5, 78)
pb._start = pb._lastTime = time.time() - 2.0 # one item took ~2s -> estimate must appear now, at 1/5
pb.progress(1)
finally:
progress_mod.dataToStdout = real
progress_mod.IS_TTY = realTty
last = captured[-1]
self.assertNotIn("??:??", last, msg="no ETA at the first item: %r" % last)
m = re.search(r"\(ETA (\d{2}):(\d{2})\)", last)
secs = int(m.group(1)) * 60 + int(m.group(2))
self.assertTrue(7 <= secs <= 9, msg="ETA not ~8s (2s/item x 4 remaining): %r" % last) # not the 2x-optimistic ~4s
def test_eta_reflects_remaining_item_count(self):
# at a constant 10s/item pace: 1/3 must estimate the 2 items left (~20s), 2/3 the 1 left (~10s) -
# i.e. (max - done) items, not just the current one. Fresh bars so each is a first (unsmoothed) estimate.
captured = []
real = progress_mod.dataToStdout
realTty = progress_mod.IS_TTY
progress_mod.dataToStdout = lambda data, *a, **k: captured.append(data)
progress_mod.IS_TTY = True
def drawnEta():
m = re.search(r"\(ETA (\d{2}):(\d{2})\)", captured[-1])
self.assertTrue(m, msg="no ETA drawn: %r" % captured[-1])
return int(m.group(1)) * 60 + int(m.group(2))
try:
a = ProgressBar(0, 3, 78)
a._start = time.time() - 10.0 # 1 done in 10s -> 10s/item, 2 remaining -> ~20s
a.progress(1)
eta1 = drawnEta()
b = ProgressBar(0, 3, 78)
b._start = time.time() - 20.0 # 2 done in 20s -> 10s/item, 1 remaining -> ~10s
b.progress(2)
eta2 = drawnEta()
finally:
progress_mod.dataToStdout = real
progress_mod.IS_TTY = realTty
self.assertTrue(18 <= eta1 <= 22, msg="1/3 should estimate 2 remaining (~20s): %ds" % eta1)
self.assertTrue(8 <= eta2 <= 12, msg="2/3 should estimate 1 remaining (~10s): %ds" % eta2)
def test_new_estimate_is_eased_not_snapped(self):
# when a fresh estimate is far from the value currently on screen, the drawn ETA must land
# between the two (smoothed), not snap straight to the new target
captured = []
real = progress_mod.dataToStdout
realTty = progress_mod.IS_TTY
progress_mod.dataToStdout = lambda data, *a, **k: captured.append(data)
progress_mod.IS_TTY = True
try:
pb = ProgressBar(0, 10, 78)
pb._eta = 8.0 # currently showing ~8s...
pb._etaAt = time.time()
pb._start = time.time() - 2.0 # ...but the fresh target is (2/1)*(10-1) = 18s
pb.progress(1)
finally:
progress_mod.dataToStdout = real
progress_mod.IS_TTY = realTty
m = re.search(r"\(ETA (\d{2}):(\d{2})\)", captured[-1])
secs = int(m.group(1)) * 60 + int(m.group(2))
self.assertTrue(10 <= secs <= 16, msg="ETA snapped instead of easing between 8 and 18: %ds" % secs)
def test_tick_counts_down_from_stored_eta(self):
captured = []
real = progress_mod.dataToStdout
realTty = progress_mod.IS_TTY
progress_mod.dataToStdout = lambda data, *a, **k: captured.append(data)
progress_mod.IS_TTY = True
try:
pb = ProgressBar(0, 10, 78)
pb.update(5)
pb._eta = 100 # a 100s estimate...
pb._etaAt = time.time() - 30 # ...taken 30s ago -> tick() must show ~70s
pb.tick()
finally:
progress_mod.dataToStdout = real
progress_mod.IS_TTY = realTty
m = re.search(r"\(ETA (\d{2}):(\d{2})\)", captured[-1])
self.assertTrue(m, msg="no mm:ss ETA drawn: %r" % captured[-1])
secs = int(m.group(1)) * 60 + int(m.group(2))
self.assertTrue(66 <= secs <= 71, msg="ETA not decremented to ~70s: %r" % captured[-1])
def test_tick_clamps_at_zero_when_overdue(self):
captured = []
real = progress_mod.dataToStdout
realTty = progress_mod.IS_TTY
progress_mod.dataToStdout = lambda data, *a, **k: captured.append(data)
progress_mod.IS_TTY = True
try:
pb = ProgressBar(0, 10, 78)
pb.update(5)
pb._eta = 5
pb._etaAt = time.time() - 60 # long overdue -> must clamp to 00:00, never negative
pb.tick()
finally:
progress_mod.dataToStdout = real
progress_mod.IS_TTY = realTty
self.assertIn("(ETA 00:00)", captured[-1], msg=captured[-1])
def test_no_draw_when_not_tty(self):
captured = []
real = progress_mod.dataToStdout
realTty = progress_mod.IS_TTY
progress_mod.dataToStdout = lambda data, *a, **k: captured.append(data)
progress_mod.IS_TTY = False # piped/redirected: no animated bar should reach the stream
try:
pb = ProgressBar(0, 10, 78)
for i in range(1, 11):
pb.progress(i)
finally:
progress_mod.dataToStdout = real
progress_mod.IS_TTY = realTty
self.assertEqual(captured, [], msg="progress bar leaked to a non-TTY stream: %r" % captured)
if __name__ == "__main__":
unittest.main()

View file

@ -48,6 +48,7 @@ from lib.core.agent import agent
from lib.core.unescaper import unescaper
from lib.request.connect import Connect
from lib.request.connect import Connect as Request
from lib.request import inject
from lib.utils.hashdb import HashDB
import lib.techniques.union.use as uu
@ -1516,6 +1517,47 @@ class TestConfigUnion(unittest.TestCase):
self.assertEqual(kb.uChar, "SENTINEL")
class TestValueParallelEligibility(unittest.TestCase):
"""
inject.valueParallelEligible() picks the value-parallel path (job-level '--eta' bar / concurrency).
Safety invariant under test: classic time-based must never run concurrently (interfering SLEEP
measurements), so it qualifies only single-threaded under '--eta'; a concurrency-safe channel
(boolean or the timeless oracle) may run under either '--threads' or '--eta'.
"""
def setUp(self):
self._avail = set()
self._realAvail = inject.isTechniqueAvailable
inject.isTechniqueAvailable = lambda t: t in self._avail
self._saved = (conf.threads, conf.eta, kb.get("timeless"))
def tearDown(self):
inject.isTechniqueAvailable = self._realAvail
conf.threads, conf.eta, kb.timeless = self._saved
def _elig(self, threads, eta, techniques, timeless=None):
conf.threads, conf.eta, kb.timeless = threads, eta, timeless
self._avail = set(techniques)
return inject.valueParallelEligible()
def test_single_thread_eta_time_based_qualifies(self):
self.assertTrue(self._elig(1, True, {PAYLOAD.TECHNIQUE.TIME}))
def test_multi_thread_time_based_never_parallel(self):
self.assertFalse(self._elig(8, True, {PAYLOAD.TECHNIQUE.TIME}))
self.assertFalse(self._elig(8, False, {PAYLOAD.TECHNIQUE.TIME}))
def test_boolean_qualifies_under_threads_or_eta(self):
self.assertTrue(self._elig(8, False, {PAYLOAD.TECHNIQUE.BOOLEAN}))
self.assertTrue(self._elig(1, True, {PAYLOAD.TECHNIQUE.BOOLEAN}))
def test_plain_single_thread_no_eta_stays_classic(self):
self.assertFalse(self._elig(1, False, {PAYLOAD.TECHNIQUE.BOOLEAN}))
def test_timeless_is_concurrency_safe(self):
self.assertTrue(self._elig(8, True, {PAYLOAD.TECHNIQUE.TIME}, timeless=object()))
if __name__ == "__main__":
unittest.main(verbosity=2)