Merge pull request #88 from frostming/feature/log-file

Feature/log file

news/84.feature

+Redirect output messages to log file for installation and locking.

pdm/cli/actions.py

@@ -4,7 +4,6 @@ from pathlib import Path
 from typing import Dict, Iterable, Optional, Sequence
 
 import click
-import halo
 import pythonfinder
 import tomlkit
 from pkg_resources import safe_name
@@ -48,8 +47,9 @@ def do_lock(
     provider = project.get_provider(strategy, tracked_names)
     requirements = requirements or project.all_dependencies
 
-    # TODO: switch reporter at io level.
-    with halo.Halo(text="Resolving dependencies", spinner="dots") as spin:
+    with stream.open_spinner(
+        title="Resolving dependencies", spinner="dots"
+    ) as spin, stream.logging("lock"):
         reporter = project.get_reporter(requirements, tracked_names, spin)
         resolver = project.core.resolver_class(provider, reporter)
         mapping, dependencies, summaries = resolve(

pdm/exceptions.py

@@ -48,6 +48,10 @@ class ProjectError(PdmException):
     pass
 
 
+class InstallationError(PdmException):
+    pass
+
+
 class NoConfigError(PdmException, KeyError):
     def __init__(self, key):
         super().__init__("No such config item: {}".format(key))

pdm/installers.py

 import contextlib
 import functools
 import importlib
+import os
 import subprocess
 import traceback
 from collections import defaultdict
@@ -15,6 +16,7 @@ from pip._vendor.pkg_resources import Distribution, EggInfoDistribution, safe_na
 from pip_shims import shims
 from vistir import cd
 
+from pdm.exceptions import InstallationError
 from pdm.iostream import stream
 from pdm.models.candidates import Candidate
 from pdm.models.environment import Environment
@@ -316,8 +318,8 @@ class Installer:  # pragma: no cover
             paths["scripts"],
         ]
         with self.environment.activate(), cd(ireq.unpacked_source_directory):
-            capture_output = stream.verbosity < stream.DETAIL
-            subprocess.run(install_args, capture_output=capture_output, check=True)
+            result = subprocess.run(install_args, capture_output=True, check=True)
+            stream.logger.debug(result.stdout.decode("utf-8"))
 
     def uninstall(self, dist: Distribution) -> None:
         req = parse_requirement(dist.project_name)
@@ -379,7 +381,7 @@ class DummyExecutor:
 class Synchronizer:
     """Synchronize the working set with given installation candidates"""
 
-    BAR_FILLED_CHAR = "▉"
+    BAR_FILLED_CHAR = "=" if os.name == "nt" else "▉"
     BAR_EMPTY_CHAR = " "
     RETRY_TIMES = 1
 
@@ -407,7 +409,10 @@ class Synchronizer:
         else:
             executor = DummyExecutor()
         with executor:
-            yield bar, executor
+            try:
+                yield bar, executor
+            except KeyboardInterrupt:
+                pass
 
     def get_installer(self) -> Installer:
         return Installer(self.environment)
@@ -474,11 +479,12 @@ class Synchronizer:
     def summarize(self, result, dry_run=False):
         added, updated, removed = result["add"], result["update"], result["remove"]
         if added:
+            stream.echo("\n")
             self._print_section_title("installed", len(added), dry_run)
             for item in sorted(added, key=lambda x: x.name):
                 stream.echo(f"  - {item.format()}")
-            stream.echo()
         if updated:
+            stream.echo("\n")
             self._print_section_title("updated", len(updated), dry_run)
             for old, can in sorted(updated, key=lambda x: x[1].name):
                 stream.echo(
@@ -486,8 +492,8 @@ class Synchronizer:
                     f"{stream.yellow(old.version)} "
                     f"-> {stream.yellow(can.version)}"
                 )
-            stream.echo()
         if removed:
+            stream.echo("\n")
             self._print_section_title("removed", len(removed), dry_run)
             for dist in sorted(removed, key=lambda x: x.key):
                 stream.echo(
@@ -540,29 +546,9 @@ class Synchronizer:
                 result[section].append(future.result())
             bar.update(1)
 
-        with self.progressbar(
-            "Synchronizing:", sum(len(l) for l in to_do.values())
-        ) as (bar, pool):
-
-            for section in to_do:
-                for key in to_do[section]:
-                    future = pool.submit(handlers[section], key)
-                    future.add_done_callback(
-                        functools.partial(
-                            update_progress, section=section, key=key, bar=bar
-                        )
-                    )
-
-        # Retry for failed items
-        for i in range(self.RETRY_TIMES):
-            if not any(failed.values()):
-                break
-            to_do = failed
-            failed = defaultdict(list)
-            errors.clear()
+        with stream.logging("install"):
             with self.progressbar(
-                f"Retrying ({i + 1}/{self.RETRY_TIMES}):",
-                sum(len(l) for l in to_do.values()),
+                "Synchronizing:", sum(len(l) for l in to_do.values())
             ) as (bar, pool):
 
                 for section in to_do:
@@ -573,7 +559,31 @@ class Synchronizer:
                                 update_progress, section=section, key=key, bar=bar
                             )
                         )
-        stream.echo()
+
+            # Retry for failed items
+            for i in range(self.RETRY_TIMES):
+                if not any(failed.values()):
+                    break
+                stream.echo(
+                    stream.yellow("\nSome packages failed to install, retrying...")
+                )
+                to_do = failed
+                failed = defaultdict(list)
+                errors.clear()
+                with self.progressbar(
+                    f"Retrying ({i + 1}/{self.RETRY_TIMES}):",
+                    sum(len(l) for l in to_do.values()),
+                ) as (bar, pool):
+
+                    for section in to_do:
+                        for key in to_do[section]:
+                            future = pool.submit(handlers[section], key)
+                            future.add_done_callback(
+                                functools.partial(
+                                    update_progress, section=section, key=key, bar=bar
+                                )
+                            )
+        # End installation
         self.summarize(result)
         if not any(failed.values()):
             return
@@ -591,3 +601,4 @@ class Synchronizer:
                 ),
                 verbosity=stream.DEBUG,
             )
+        raise InstallationError()

pdm/iostream.py

 import contextlib
 import functools
+import logging
+import os
 import re
 from itertools import zip_longest
+from tempfile import mktemp
 from typing import List, Optional
 
 import click
+import halo
 
 COLORS = ("red", "green", "yellow", "blue", "black", "magenta", "cyan", "white")
 
@@ -29,6 +33,7 @@ class IOStream:
         self.verbosity = verbosity
         self._disable_colors = disable_colors
         self._indent = ""
+        self.logger = None
 
         for color in COLORS:
             setattr(self, color, functools.partial(self._style, fg=color))
@@ -80,5 +85,32 @@ class IOStream:
         yield
         self._indent = _indent
 
+    @contextlib.contextmanager
+    def logging(self, type_: str = "install"):
+        file_name = mktemp(".log", f"pdm-{type_}-")
+
+        logger = logging.getLogger(__name__)
+        logger.setLevel(logging.DEBUG)
+        handler = logging.FileHandler(file_name, encoding="utf-8")
+        handler.setLevel(logging.DEBUG)
+        logger.addHandler(handler)
+        pip_logger = logging.getLogger("pip")
+        pip_logger.handlers[:] = [handler]
+        try:
+            self.logger = logger
+            yield logger
+        except Exception:
+            self.echo(self.yellow(f"See {file_name} for detailed debug log."))
+        else:
+            try:
+                os.remove(file_name)
+            except OSError:
+                pass
+
+    @contextlib.contextmanager
+    def open_spinner(self, title: str, spinner: str = "dots"):
+        with halo.Halo(title, spinner=spinner) as spin:
+            yield spin
+
 
 stream = IOStream()

pdm/project/core.py

@@ -249,7 +249,10 @@ class Project:
         :param spinner: optional spinner object
         :returns: a reporter
         """
-        return SpinnerReporter(spinner)
+        flat_reqs = [
+            req for req_set in requirements.values() for req in req_set.values()
+        ]
+        return SpinnerReporter(spinner, flat_reqs)
 
     def get_project_metadata(self) -> Dict[str, Any]:
         content_hash = self.get_content_hash("md5")

pdm/resolver/__init__.py

@@ -7,7 +7,7 @@ from pdm.resolver.providers import (  # noqa
     EagerUpdateProvider,
     ReusePinProvider,
 )
-from pdm.resolver.reporters import SimpleReporter  # noqa
+from pdm.resolver.reporters import SpinnerReporter  # noqa
 from pdm.resolver.resolvers import Resolver  # noqa
 
 

pdm/resolver/reporters.py

 from __future__ import annotations
 
-import time
 from typing import TYPE_CHECKING, Dict, List, Optional
 
 import halo
@@ -13,27 +12,26 @@ if TYPE_CHECKING:
     from pdm.resolver.resolvers import State
 
 
-def print_title(title):
-    print("=" * 20 + " " + title + " " + "=" * 20)
+def log_title(title):
+    stream.logger.info("=" * 8 + title + "=" * 8)
 
 
-class SimpleReporter:
-    def __init__(self, requirements: List[Requirement]) -> None:
+class SpinnerReporter:
+    def __init__(self, spinner: halo.Halo, requirements: List[Requirement]) -> None:
+        self.spinner = spinner
         self.requirements = requirements
-        self.start_at = None  # type: Optional[float]
         self._previous = None  # type: Optional[Dict[str, Candidate]]
 
     def starting_round(self, index: int) -> None:
+        # self.spinner.hide_and_write(f"Resolving ROUND {index}")
         pass
 
     def starting(self) -> None:
         """Called before the resolution actually starts.
         """
-        self._previous = None
-        print_title("Start resolving requirements...")
-        self.start_at = time.time()
-        for r in self.requirements:
-            print(r.as_line())
+        log_title("Start resolving requirements")
+        for req in self.requirements:
+            stream.logger.info("\t" + req.as_line())
 
     def ending_round(self, index: int, state: State) -> None:
         """Called before each round of resolution ends.
@@ -41,8 +39,7 @@ class SimpleReporter:
         This is NOT called if the resolution ends at this round. Use `ending`
         if you want to report finalization. The index is zero-based.
         """
-        print_title(f"Ending ROUND {index}")
-
+        log_title("Ending round {}".format(index))
         if not self._previous:
             added = state.mapping.values()
             changed = []
@@ -54,62 +51,33 @@ class SimpleReporter:
                 if k in self._previous and self._previous[k] != can
             ]
         if added:
-            print("New pins:")
+            stream.logger.info("New pins:")
             for can in added:
-                print(f"\t{can.name}\t{can.version}")
+                stream.logger.info(f"\t{can.name}\t{can.version}")
         if changed:
-            print("Changed pins:")
+            stream.logger.info("Changed pins:")
             for (old, new) in changed:
-                print(f"\t{new.name}\t{old.version} -> {new.version}")
+                stream.logger.info(f"\t{new.name}\t{old.version} -> {new.version}")
         self._previous = state.mapping
 
-    def ending(self, state: State) -> None:
-        """Called before the resolution ends successfully.
-        """
-        print("End resolving...")
-        print("Stable pins:")
-        for k, can in state.mapping.items():
-            print(f"\t{can.name}\t{can.version}")
-
-    def resolve_criteria(self, name):
-        pass
-
-    def pin_candidate(self, name, criterion, candidate, child_names):
-        pass
-
-    def extract_metadata(self):
-        pass
-
-
-class SpinnerReporter:
-    def __init__(self, spinner: halo.Halo) -> None:
-        self.spinner = spinner
-
-    def starting_round(self, index: int) -> None:
-        # self.spinner.hide_and_write(f"Resolving ROUND {index}")
-        pass
-
-    def starting(self) -> None:
-        """Called before the resolution actually starts.
-        """
-
-    def ending_round(self, index: int, state: State) -> None:
-        """Called before each round of resolution ends.
-
-        This is NOT called if the resolution ends at this round. Use `ending`
-        if you want to report finalization. The index is zero-based.
-        """
-
     def ending(self, state: State) -> None:
         """Called before the resolution ends successfully.
         """
         self.spinner.stop_and_persist(text="Finish resolving")
 
-    def resolve_criteria(self, name):
-        self.spinner.text = f"Resolving {stream.green(name, bold=True)}"
+        log_title("Resolution Result")
+        stream.logger.info("Stable pins:")
+        for k, can in state.mapping.items():
+            stream.logger.info(f"\t{can.name}\t{can.version}")
 
     def pin_candidate(self, name, criterion, candidate, child_names):
         self.spinner.text = f"Resolved: {candidate.format()}"
+        stream.logger.info("Package constraints:")
+        for req, parent in criterion.information:
+            stream.logger.info(
+                f"\t{req.as_line()}\t<= {getattr(parent, 'name', parent)}"
+            )
+        stream.logger.info(f"Found candidate\t{candidate.name} {candidate.version}")
 
     def extract_metadata(self):
         self.spinner.start("Extracting package metadata")

pdm/resolver/resolvers.py

@@ -15,7 +15,7 @@ if TYPE_CHECKING:
     from pdm.models.candidates import Candidate
     from pdm.models.requirements import Requirement
     from pdm.resolver.providers import BaseProvider
-    from pdm.resolver.reporters import SimpleReporter
+    from pdm.resolver.reporters import SpinnerReporter
 
 RequirementInformation = collections.namedtuple(
     "RequirementInformation", ["requirement", "parent"]
@@ -86,7 +86,7 @@ class Resolution(object):
     the resolution process, and holds the results afterwards.
     """
 
-    def __init__(self, provider: BaseProvider, reporter: SimpleReporter):
+    def __init__(self, provider: BaseProvider, reporter: SpinnerReporter):
         self._p = provider
         self._r = reporter
         self._roots = []  # type: List[str]
@@ -204,7 +204,6 @@ class Resolution(object):
             # Any pin may modify any criterion during the loop. Criteria are
             # replaced, not updated in-place, so we need to read this value
             # in the loop instead of outside. (sarugaku/resolvelib#5)
-            self._r.resolve_criteria(name)
             criterion = self._criteria[name]
 
             if self._is_current_pin_satisfying(name, criterion):
@@ -265,7 +264,7 @@ class Resolver(object):
     """The thing that performs the actual resolution work.
     """
 
-    def __init__(self, provider: BaseProvider, reporter: SimpleReporter) -> None:
+    def __init__(self, provider: BaseProvider, reporter: SpinnerReporter) -> None:
         self.provider = provider
         self.reporter = reporter
 

tests/resolver/test_resolve.py

@@ -3,6 +3,7 @@ import itertools
 import pytest
 
 from pdm.exceptions import NoVersionsAvailable, ResolutionImpossible
+from pdm.iostream import stream
 from pdm.models.candidates import identify
 from pdm.models.requirements import parse_requirement
 from pdm.models.specifiers import PySpecSet
@@ -11,7 +12,7 @@ from pdm.resolver import (
     EagerUpdateProvider,
     Resolver,
     ReusePinProvider,
-    SimpleReporter,
+    SpinnerReporter,
     resolve,
 )
 from tests import FIXTURES
@@ -50,9 +51,10 @@ def resolve_requirements(
     flat_reqs = list(
         itertools.chain(*[deps.values() for _, deps in requirements.items()])
     )
-    reporter = SimpleReporter(flat_reqs)
-    resolver = Resolver(provider, reporter)
-    mapping, *_ = resolve(resolver, requirements, requires_python)
+    with stream.open_spinner("Resolving dependencies") as spin:
+        reporter = SpinnerReporter(spin, flat_reqs)
+        resolver = Resolver(provider, reporter)
+        mapping, *_ = resolve(resolver, requirements, requires_python)
     return mapping