diff --git a/docs/changelog/1880.bufix.rst b/docs/changelog/1880.bugfix.rst similarity index 100% rename from docs/changelog/1880.bufix.rst rename to docs/changelog/1880.bugfix.rst diff --git a/docs/changelog/1883.bugfix.rst b/docs/changelog/1883.bugfix.rst new file mode 100644 index 000000000..f5f3670f4 --- /dev/null +++ b/docs/changelog/1883.bugfix.rst @@ -0,0 +1,8 @@ +Improve periodic update handling: + +- better logging output while running and enable logging on background process call ( + ``_VIRTUALENV_PERIODIC_UPDATE_INLINE`` may be used to debug behaviour inline) +- fallback to unverified context when querying the PyPi for release date, +- stop downloading wheels once we reach the embedded version, + +by :user:`gaborbernat`. diff --git a/src/virtualenv/report.py b/src/virtualenv/report.py index 8d5c35871..665b293cb 100644 --- a/src/virtualenv/report.py +++ b/src/virtualenv/report.py @@ -18,7 +18,7 @@ LOGGER = logging.getLogger() -def setup_report(verbosity): +def setup_report(verbosity, show_pid=False): _clean_handlers(LOGGER) if verbosity > MAX_LEVEL: verbosity = MAX_LEVEL # pragma: no cover @@ -31,7 +31,8 @@ def setup_report(verbosity): filelock_logger.setLevel(level) else: filelock_logger.setLevel(logging.WARN) - + if show_pid: + msg_format = "[%(process)d] " + msg_format formatter = logging.Formatter(ensure_str(msg_format)) stream_handler = logging.StreamHandler(stream=sys.stdout) stream_handler.setLevel(level) @@ -47,3 +48,10 @@ def setup_report(verbosity): def _clean_handlers(log): for log_handler in list(log.handlers): # remove handlers of libraries log.removeHandler(log_handler) + + +__all__ = ( + "LEVELS", + "MAX_LEVEL", + "setup_report", +) diff --git a/src/virtualenv/seed/wheels/acquire.py b/src/virtualenv/seed/wheels/acquire.py index 8c88725f9..823d3484d 100644 --- a/src/virtualenv/seed/wheels/acquire.py +++ b/src/virtualenv/seed/wheels/acquire.py @@ -39,12 +39,14 @@ def get_wheel(distribution, version, for_py_version, search_dirs, download, app_ def download_wheel(distribution, version_spec, for_py_version, search_dirs, app_data, to_folder): to_download = "{}{}".format(distribution, version_spec or "") - logging.debug("download wheel %s", to_download) + logging.debug("download wheel %s %s to %s", to_download, for_py_version, to_folder) cmd = [ sys.executable, "-m", "pip", "download", + "--progress-bar", + "off", "--disable-pip-version-check", "--only-binary=:all:", "--no-deps", @@ -65,6 +67,12 @@ def download_wheel(distribution, version_spec, for_py_version, search_dirs, app_ else: kwargs["stderr"] = err raise subprocess.CalledProcessError(process.returncode, cmd, **kwargs) + result = _find_downloaded_wheel(distribution, version_spec, for_py_version, to_folder, out) + logging.debug("downloaded wheel %s", result.name) + return result + + +def _find_downloaded_wheel(distribution, version_spec, for_py_version, to_folder, out): for line in out.splitlines(): line = line.lstrip() for marker in ("Saved ", "File was already downloaded "): diff --git a/src/virtualenv/seed/wheels/periodic_update.py b/src/virtualenv/seed/wheels/periodic_update.py index 25270ad6d..4a8e8bc81 100644 --- a/src/virtualenv/seed/wheels/periodic_update.py +++ b/src/virtualenv/seed/wheels/periodic_update.py @@ -7,13 +7,16 @@ import json import logging import os +import ssl import subprocess import sys from datetime import datetime, timedelta from itertools import groupby from shutil import copy2 +from textwrap import dedent from threading import Thread +from six.moves.urllib.error import URLError from six.moves.urllib.request import urlopen from virtualenv.app_data import AppDataDiskFolder @@ -168,10 +171,16 @@ def trigger_update(distribution, for_py_version, wheel, search_dirs, app_data, p cmd = [ sys.executable, "-c", - "from virtualenv.seed.wheels.periodic_update import do_update;" - "do_update({!r}, {!r}, {!r}, {!r}, {!r}, {!r})".format( - distribution, for_py_version, wheel_path, str(app_data), [str(p) for p in search_dirs], periodic, - ), + dedent( + """ + from virtualenv.report import setup_report, MAX_LEVEL + from virtualenv.seed.wheels.periodic_update import do_update + setup_report(MAX_LEVEL, show_pid=True) + do_update({!r}, {!r}, {!r}, {!r}, {!r}, {!r}) + """, + ) + .strip() + .format(distribution, for_py_version, wheel_path, str(app_data), [str(p) for p in search_dirs], periodic), ] debug = os.environ.get(str("_VIRTUALENV_PERIODIC_UPDATE_INLINE")) == str("1") pipe = None if debug else subprocess.PIPE @@ -191,29 +200,35 @@ def trigger_update(distribution, for_py_version, wheel, search_dirs, app_data, p def do_update(distribution, for_py_version, embed_filename, app_data, search_dirs, periodic): + versions = None + try: + versions = _run_do_update(app_data, distribution, embed_filename, for_py_version, periodic, search_dirs) + finally: + logging.debug("done %s %s with %s", distribution, for_py_version, versions) + return versions + +def _run_do_update(app_data, distribution, embed_filename, for_py_version, periodic, search_dirs): from virtualenv.seed.wheels import acquire wheel_filename = None if embed_filename is None else Path(embed_filename) + embed_version = None if wheel_filename is None else Wheel(wheel_filename).version_tuple app_data = AppDataDiskFolder(app_data) if isinstance(app_data, str) else app_data search_dirs = [Path(p) if isinstance(p, str) else p for p in search_dirs] wheelhouse = app_data.house embed_update_log = app_data.embed_update_log(distribution, for_py_version) u_log = UpdateLog.from_dict(embed_update_log.read()) - now = datetime.now() - if wheel_filename is not None: dest = wheelhouse / wheel_filename.name if not dest.exists(): copy2(str(wheel_filename), str(wheelhouse)) - - last, versions = None, [] + last, last_version, versions = None, None, [] while last is None or not last.use(now): download_time = datetime.now() dest = acquire.download_wheel( distribution=distribution, - version_spec=None if last is None else "<{}".format(Wheel(Path(last.filename)).version), + version_spec=None if last_version is None else "<{}".format(last_version), for_py_version=for_py_version, search_dirs=search_dirs, app_data=app_data, @@ -221,10 +236,15 @@ def do_update(distribution, for_py_version, embed_filename, app_data, search_dir ) if dest is None or (u_log.versions and u_log.versions[0].filename == dest.name): break - release_date = _get_release_date(dest.path) + release_date = release_date_for_wheel_path(dest.path) last = NewVersion(filename=dest.path.name, release_date=release_date, found_date=download_time) logging.info("detected %s in %s", last, datetime.now() - download_time) versions.append(last) + last_wheel = Wheel(Path(last.filename)) + last_version = last_wheel.version + if embed_version is not None: + if embed_version >= last_wheel.version_tuple: # stop download if we reach the embed version + break u_log.periodic = periodic if not u_log.periodic: u_log.started = now @@ -234,16 +254,48 @@ def do_update(distribution, for_py_version, embed_filename, app_data, search_dir return versions -def _get_release_date(dest): +def release_date_for_wheel_path(dest): wheel = Wheel(dest) # the most accurate is to ask PyPi - e.g. https://pypi.org/pypi/pip/json, # see https://warehouse.pypa.io/api-reference/json/ for more details + content = _pypi_get_distribution_info_cached(wheel.distribution) + if content is not None: + try: + upload_time = content["releases"][wheel.version][0]["upload_time"] + return datetime.strptime(upload_time, "%Y-%m-%dT%H:%M:%S") + except Exception as exception: + logging.error("could not load release date %s because %r", content, exception) + return None + + +def _request_context(): + yield None + # fallback to non verified HTTPS (the information we request is not sensitive, so fallback) + yield ssl._create_unverified_context() # noqa + + +_PYPI_CACHE = {} + + +def _pypi_get_distribution_info_cached(distribution): + if distribution not in _PYPI_CACHE: + _PYPI_CACHE[distribution] = _pypi_get_distribution_info(distribution) + return _PYPI_CACHE[distribution] + + +def _pypi_get_distribution_info(distribution): + content, url = None, "https://pypi.org/pypi/{}/json".format(distribution) try: - with urlopen("https://pypi.org/pypi/{}/json".format(wheel.distribution)) as file_handler: - content = json.load(file_handler) - return datetime.strptime(content["releases"][wheel.version][0]["upload_time"], "%Y-%m-%dT%H:%M:%S") - except Exception: # noqa - return None + for context in _request_context(): + try: + with urlopen(url, context=context) as file_handler: + content = json.load(file_handler) + break + except URLError as exception: + logging.error("failed to access %s because %r", url, exception) + except Exception as exception: + logging.error("failed to access %s because %r", url, exception) + return content def manual_upgrade(app_data): @@ -308,4 +360,5 @@ def _run_manual_upgrade(app_data, distribution, for_py_version): "load_datetime", "dump_datetime", "trigger_update", + "release_date_for_wheel_path", ) diff --git a/tests/unit/seed/wheels/test_acquire.py b/tests/unit/seed/wheels/test_acquire.py index 944ed4cea..7918c602a 100644 --- a/tests/unit/seed/wheels/test_acquire.py +++ b/tests/unit/seed/wheels/test_acquire.py @@ -55,6 +55,8 @@ def test_download_fails(mocker, for_py_version, session_app_data): "-m", "pip", "download", + "--progress-bar", + "off", "--disable-pip-version-check", "--only-binary=:all:", "--no-deps", diff --git a/tests/unit/seed/wheels/test_periodic_update.py b/tests/unit/seed/wheels/test_periodic_update.py index 9a728cbad..c31491b1a 100644 --- a/tests/unit/seed/wheels/test_periodic_update.py +++ b/tests/unit/seed/wheels/test_periodic_update.py @@ -6,10 +6,12 @@ from collections import defaultdict from contextlib import contextmanager from datetime import datetime, timedelta +from textwrap import dedent import pytest from six import StringIO from six.moves import zip_longest +from six.moves.urllib.error import URLError from virtualenv import cli_run from virtualenv.app_data import AppDataDiskFolder @@ -23,12 +25,20 @@ load_datetime, manual_upgrade, periodic_update, + release_date_for_wheel_path, trigger_update, ) from virtualenv.util.path import Path from virtualenv.util.subprocess import DETACHED_PROCESS +@pytest.fixture(autouse=True) +def clear_pypi_info_cache(): + from virtualenv.seed.wheels.periodic_update import _PYPI_CACHE + + _PYPI_CACHE.clear() + + def test_manual_upgrade(session_app_data, caplog, mocker, for_py_version): wheel = get_embed_wheel("pip", for_py_version) new_version = NewVersion(wheel.path, datetime.now(), datetime.now() - timedelta(days=20)) @@ -192,16 +202,25 @@ def test_trigger_update_no_debug(for_py_version, session_app_data, tmp_path, moc assert Popen.call_count == 1 args, kwargs = Popen.call_args cmd = ( - "from virtualenv.seed.wheels.periodic_update import do_update;" - "do_update({!r}, {!r}, {!r}, {!r}, [{!r}, {!r}], True)".format( + dedent( + """ + from virtualenv.report import setup_report, MAX_LEVEL + from virtualenv.seed.wheels.periodic_update import do_update + setup_report(MAX_LEVEL, show_pid=True) + do_update({!r}, {!r}, {!r}, {!r}, {!r}, {!r}) + """, + ) + .strip() + .format( "setuptools", for_py_version, str(current.path), str(session_app_data), - str(tmp_path / "a"), - str(tmp_path / "b"), + [str(tmp_path / "a"), str(tmp_path / "b")], + True, ) ) + assert args == ([sys.executable, "-c", cmd],) expected = {"stdout": subprocess.PIPE, "stderr": subprocess.PIPE} if sys.platform == "win32": @@ -223,9 +242,22 @@ def test_trigger_update_debug(for_py_version, session_app_data, tmp_path, mocker assert Popen.call_count == 1 args, kwargs = Popen.call_args cmd = ( - "from virtualenv.seed.wheels.periodic_update import do_update;" - "do_update({!r}, {!r}, {!r}, {!r}, [{!r}, {!r}], False)".format( - "pip", for_py_version, str(current.path), str(session_app_data), str(tmp_path / "a"), str(tmp_path / "b"), + dedent( + """ + from virtualenv.report import setup_report, MAX_LEVEL + from virtualenv.seed.wheels.periodic_update import do_update + setup_report(MAX_LEVEL, show_pid=True) + do_update({!r}, {!r}, {!r}, {!r}, {!r}, {!r}) + """, + ) + .strip() + .format( + "pip", + for_py_version, + str(current.path), + str(session_app_data), + [str(tmp_path / "a"), str(tmp_path / "b")], + False, ) ) assert args == ([sys.executable, "-c", cmd],) @@ -268,8 +300,9 @@ def _download_wheel(distribution, version_spec, for_py_version, search_dirs, app pypi_release = json.dumps({"releases": releases}) @contextmanager - def _release(of): + def _release(of, context): assert of == "https://pypi.org/pypi/pip/json" + assert context is None yield StringIO(pypi_release) url_o = mocker.patch("virtualenv.seed.wheels.periodic_update.urlopen", side_effect=_release) @@ -282,7 +315,7 @@ def _release(of): versions = do_update("pip", "3.9", str(pip_version_remote[-1][0]), str(app_data_outer), [str(extra)], True) assert download_wheel.call_count == len(pip_version_remote) - assert url_o.call_count == len(pip_version_remote) + assert url_o.call_count == 1 expected = [ NewVersion(Path(wheel).name, _UP_NOW, None if release is None else release.replace(microsecond=0)) @@ -356,3 +389,64 @@ def test_new_version_ne(): assert NewVersion("a", datetime.now(), datetime.now()) != NewVersion( "a", datetime.now(), datetime.now() + timedelta(hours=1), ) + + +def test_get_release_unsecure(mocker, caplog): + @contextmanager + def _release(of, context): + assert of == "https://pypi.org/pypi/pip/json" + if context is None: + raise URLError("insecure") + assert context + yield StringIO(json.dumps({"releases": {"20.1": [{"upload_time": "2020-12-22T12:12:12"}]}})) + + url_o = mocker.patch("virtualenv.seed.wheels.periodic_update.urlopen", side_effect=_release) + + result = release_date_for_wheel_path(Path("pip-20.1.whl")) + + assert result == datetime(year=2020, month=12, day=22, hour=12, minute=12, second=12) + assert url_o.call_count == 2 + assert "insecure" in caplog.text + assert " failed " in caplog.text + + +def test_get_release_fails(mocker, caplog): + exc = RuntimeError("oh no") + url_o = mocker.patch("virtualenv.seed.wheels.periodic_update.urlopen", side_effect=exc) + + result = release_date_for_wheel_path(Path("pip-20.1.whl")) + + assert result is None + assert url_o.call_count == 1 + assert repr(exc) in caplog.text + + +def test_download_stop_with_embed(tmp_path, mocker, freezer): + freezer.move_to(_UP_NOW) + wheel = get_embed_wheel("pip", "3.9") + app_data_outer = AppDataDiskFolder(str(tmp_path / "app")) + pip_version_remote = [wheel_path(wheel, (0, 0, 2)), wheel_path(wheel, (0, 0, 1)), wheel_path(wheel, (-1, 0, 0))] + at = {"index": 0} + + def download(): + while True: + path = pip_version_remote[at["index"]] + at["index"] += 1 + yield Wheel(Path(path)) + + do = download() + download_wheel = mocker.patch("virtualenv.seed.wheels.acquire.download_wheel", side_effect=lambda *a, **k: next(do)) + url_o = mocker.patch("virtualenv.seed.wheels.periodic_update.urlopen", side_effect=URLError("unavailable")) + + last_update = _UP_NOW - timedelta(days=14) + u_log = UpdateLog(started=last_update, completed=last_update, versions=[], periodic=True) + read_dict = mocker.patch("virtualenv.app_data.via_disk_folder.JSONStoreDisk.read", return_value=u_log.to_dict()) + write = mocker.patch("virtualenv.app_data.via_disk_folder.JSONStoreDisk.write") + + do_update("pip", "3.9", str(wheel.path), str(app_data_outer), [], True) + + assert download_wheel.call_count == 3 + assert url_o.call_count == 2 + + assert read_dict.call_count == 1 + assert write.call_count == 1