diff --git a/src/manage/urlutils.py b/src/manage/urlutils.py index edfd54a..f0a9975 100644 --- a/src/manage/urlutils.py +++ b/src/manage/urlutils.py @@ -148,6 +148,7 @@ def __init__(self, url, method="GET", headers={}, outfile=None): self.password = None self.outfile = Path(outfile) if outfile else None self.proxy_settings = _proxy_settings_from_env() + self._download_start = time.monotonic() self._on_progress = None self._on_auth_request = None self._on_cancel = None @@ -158,6 +159,15 @@ def __str__(self): def on_progress(self, progress): if self._on_progress: self._on_progress(progress) + elif (self._download_start is not None + and progress is not None and progress < 100 + and time.monotonic() - self._download_start > 5): + LOGGER.warn( + "Downloading %s is taking some time. Please continue to wait, " + "or press Ctrl+C to abort.", + self, + ) + self._download_start = None def on_auth_request(self, url=None): if url is None: @@ -236,7 +246,7 @@ def _bits_urlretrieve(request): # Returned HTTP status 404 (0x194) raise FileNotFoundError() from ex raise - if progress > last_progress: + if progress > last_progress or not request._on_progress: request.on_progress(progress) last_progress = progress time.sleep(0.1) @@ -320,6 +330,8 @@ def _urllib_urlopen(request): raise FileNotFoundError from ex else: raise + if not request._on_progress: + request.on_progress(0) with r: data = r.read() request.on_progress(100) @@ -349,6 +361,8 @@ def _urllib_urlretrieve(request): r = urlopen(req) else: raise + if not request._on_progress: + request.on_progress(0) with r: progress = 0 try: @@ -467,20 +481,23 @@ def _powershell_urlretrieve(request): stderr=subprocess.STDOUT, ) as p: request.on_progress(0) - start = time.time() + start = time.monotonic() + timeout = 10.0 if request._on_progress else 1.0 while True: try: try: - out = p.communicate(b'', timeout=10.0)[0].decode("utf-8", "replace") + out = p.communicate(b'', timeout=timeout)[0].decode("utf-8", "replace") if 'Invoke-WebRequest' in out: raise RuntimeError("Powershell download failed:" + out) request.on_progress(100) LOGGER.debug("PowerShell Output: %s", out) return except subprocess.TimeoutExpired: - if not request.outfile.exists(): + request.on_progress(0) + elapsed = time.monotonic() - start + if not request.outfile.exists() and elapsed >= 10: # Suppress the original exception to avoid leaking the command - raise subprocess.TimeoutExpired(powershell, int(time.time() - start)) from None + raise subprocess.TimeoutExpired(powershell, int(elapsed)) from None except: p.terminate() out = p.communicate()[0] diff --git a/tests/test_urlutils.py b/tests/test_urlutils.py index df32e45..33064b8 100644 --- a/tests/test_urlutils.py +++ b/tests/test_urlutils.py @@ -295,6 +295,145 @@ def local_withauth(localserver): yield req +def test_slow_download_warning(monkeypatch, assert_log): + now = [10.0] + monkeypatch.setattr(UU.time, "monotonic", lambda: now[0]) + + def urlopen(request): + request.on_progress(0) + now[0] += 5 + request.on_progress(50) + assert_log(assert_log.not_logged("Downloading .+ is taking some time.+")) + + now[0] += 0.1 + request.on_progress(50) + request.on_progress(75) + return b"download" + + monkeypatch.setattr(UU, "ENABLE_WINHTTP", True) + monkeypatch.setattr(UU, "_winhttp_urlopen", urlopen) + + result = UU.urlopen("https://user:pass@example.com/index.json") + + assert result == b"download" + assert_log( + ( + "Downloading %s is taking some time. Please continue to wait, " + "or press Ctrl\\+C to abort.", + ["https://example.com/index.json"], + ), + assert_log.end_of_log(), + ) + + +def test_slow_download_warning_not_emitted_on_completion(monkeypatch, assert_log): + now = [10.0] + monkeypatch.setattr(UU.time, "monotonic", lambda: now[0]) + request = UU._Request("https://example.com/index.json") + + now[0] += 5.1 + request.on_progress(100) + + assert_log(assert_log.not_logged("Downloading .+ is taking some time.+")) + + +def test_slow_download_warning_suppressed_by_progress(monkeypatch, assert_log): + now = [10.0] + monkeypatch.setattr(UU.time, "monotonic", lambda: now[0]) + request = UU._Request("https://example.com/index.json") + progress = [] + request._on_progress = progress.append + + now[0] += 5.1 + request.on_progress(50) + + assert progress == [50] + assert_log(assert_log.not_logged("Downloading .+ is taking some time.+")) + + +def test_powershell_slow_download_warning(monkeypatch, assert_log, tmp_path): + import shutil + import subprocess + + now = [10.0] + monkeypatch.setattr(UU.time, "monotonic", lambda: now[0]) + monkeypatch.setattr(shutil, "which", lambda _: "powershell.exe") + + class Process: + def __init__(self, *args, **kwargs): + pass + + def __enter__(self): + return self + + def __exit__(self, *exc_info): + pass + + def communicate(self, _=None, timeout=None): + if timeout is None: + return (b"",) + now[0] += timeout + if now[0] <= 16: + raise subprocess.TimeoutExpired("powershell.exe", timeout) + return (b"",) + + def terminate(self): + pass + + monkeypatch.setattr(subprocess, "Popen", Process) + + request = UU._Request("https://user:pass@example.com/index.json") + request.outfile = tmp_path / "index.json" + + UU._powershell_urlretrieve(request) + + warning = ( + "Downloading %s is taking some time. Please continue to wait, " + "or press Ctrl+C to abort." + ) + assert_log(assert_log.skip_until( + warning.replace("+", "\\+"), + ["https://example.com/index.json"], + )) + assert sum(1 for msg, _ in assert_log if msg == warning) == 1 + + +def test_bits_slow_download_warning(monkeypatch, assert_log, tmp_path): + bits = object() + job = object() + now = [10.0] + progress = iter([0] * 52 + [100]) + + def sleep(delay): + now[0] += delay + + monkeypatch.setattr(UU.time, "monotonic", lambda: now[0]) + monkeypatch.setattr(UU.time, "sleep", sleep) + monkeypatch.setattr(_native, "coinitialize", lambda: None, raising=False) + monkeypatch.setattr(_native, "bits_connect", lambda: bits, raising=False) + monkeypatch.setattr(_native, "bits_begin", lambda *a, **k: job, raising=False) + monkeypatch.setattr(_native, "bits_cancel", lambda *a: None, raising=False) + monkeypatch.setattr(_native, "bits_get_progress", lambda *a: next(progress), raising=False) + monkeypatch.setattr(_native, "bits_retry_with_auth", lambda *a: None, raising=False) + monkeypatch.setattr(_native, "bits_find_job", lambda *a: None, raising=False) + monkeypatch.setattr(_native, "bits_serialize_job", lambda *a: b"job-id", raising=False) + + request = UU._Request("https://user:pass@example.com/download.zip") + request.outfile = tmp_path / "download.zip" + + UU._bits_urlretrieve(request) + + warning = ( + "Downloading %s is taking some time. Please continue to wait, " + "or press Ctrl+C to abort." + ) + assert_log(assert_log.skip_until( + warning.replace("+", "\\+"), + ["https://example.com/download.zip"], + )) + assert sum(1 for msg, _ in assert_log if msg == warning) == 1 + + def test_urllib_urlretrieve(local_128kb, tmp_path): local_128kb.outfile = dest = tmp_path / "read.txt" progress = local_128kb.progress