gh-48: Report slow downloads

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 '<S S="Error">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]

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