Improve debugging of dependency resolution

CHANGELOG.md

@@ -10,6 +10,7 @@
 
 - Dependency resolution caches now use sha256 hashes.
 - Changed CLI error style.
+- Improved debugging of dependency resolution.
 
 
 ## [0.8.3] - 2018-04-16

poetry/console/commands/add.py

@@ -24,6 +24,10 @@ class AddCommand(VenvCommand):
 If you do not specify a version constraint, poetry will choose a suitable one based on the available package versions.
 """
 
+    _loggers = [
+        'poetry.repositories.pypi_repository'
+    ]
+
     def handle(self):
         from poetry.installation import Installer
         from poetry.semver.version_parser import VersionParser

poetry/console/commands/command.py

+import logging
+
 from cleo import Command as BaseCommand
 
 from ..styles.poetry import PoetryStyle
 
 
+class CommandFormatter(logging.Formatter):
+
+    _colors = {
+        'error': 'fg=red',
+        'warning': 'fg=yellow',
+        'debug': 'fg=blue',
+    }
+
+    def format(self, record):
+        if not record.exc_info:
+            level = record.levelname.lower()
+            msg = record.msg
+
+            if level in self._colors:
+                msg = '<{}>{}</>'.format(self._colors[level], msg)
+
+            return msg
+
+        return super(CommandFormatter, self).format(record)
+
+
+class CommandHandler(logging.Handler):
+
+    def __init__(self, command):
+        self._command = command
+
+        output = self._command.output
+        level = logging.WARNING
+        if output.is_debug():
+            level = logging.DEBUG
+        elif output.is_very_verbose() or output.is_verbose():
+            level = logging.INFO
+
+        super(CommandHandler, self).__init__(level)
+
+    def emit(self, record):
+        try:
+            msg = self.format(record)
+            level = record.levelname.lower()
+            err = level in ('warning', 'error', 'exception', 'critical')
+            if err:
+                self._command.output.write_error(msg, newline=True)
+            else:
+                self._command.line(msg)
+        except Exception:
+            self.handleError(record)
+
+
 class Command(BaseCommand):
 
+    _loggers = []
+
     @property
     def poetry(self):
         return self.get_application().poetry
@@ -19,4 +71,25 @@ class Command(BaseCommand):
         self.input = i
         self.output = PoetryStyle(i, o)
 
+        for logger in self._loggers:
+            self.register_logger(logging.getLogger(logger))
+
         return super(BaseCommand, self).run(i, o)
+
+    def register_logger(self, logger):
+        """
+        Register a new logger.
+        """
+        handler = CommandHandler(self)
+        handler.setFormatter(CommandFormatter())
+        logger.handlers = [handler]
+        logger.propagate = False
+
+        output = self.output
+        level = logging.WARNING
+        if output.is_debug():
+            level = logging.DEBUG
+        elif output.is_very_verbose() or output.is_verbose():
+            level = logging.INFO
+
+        logger.setLevel(level)

poetry/console/commands/debug/resolve.py

@@ -13,6 +13,10 @@ class DebugResolveCommand(Command):
         { package?* : packages to resolve. }
     """
 
+    _loggers = [
+        'poetry.repositories.pypi_repository'
+    ]
+
     def handle(self):
         from poetry.packages import Dependency
         from poetry.puzzle import Solver

poetry/console/commands/install.py

@@ -21,6 +21,10 @@ exist it will look for <comment>pyproject.toml</> and do the same.
 <info>poetry install</info>    
 """
 
+    _loggers = [
+        'poetry.repositories.pypi_repository'
+    ]
+
     def handle(self):
         from poetry.installation import Installer
 

poetry/console/commands/lock.py

@@ -14,6 +14,10 @@ the current directory, processes it, and locks the depdencies in the <comment>py
 <info>poetry lock</info>    
 """
 
+    _loggers = [
+        'poetry.repositories.pypi_repository'
+    ]
+
     def handle(self):
         from poetry.installation import Installer
 

poetry/console/commands/remove.py

@@ -17,6 +17,10 @@ list of installed packages
 
 <info>poetry remove</info>"""
 
+    _loggers = [
+        'poetry.repositories.pypi_repository'
+    ]
+
     def handle(self):
         from poetry.installation import Installer
 

poetry/console/commands/update.py

@@ -12,6 +12,10 @@ class UpdateCommand(VenvCommand):
                       (implicitly enables --verbose). }
     """
 
+    _loggers = [
+        'poetry.repositories.pypi_repository'
+    ]
+
     def handle(self):
         from poetry.installation import Installer
 

poetry/console/commands/venv_command.py

@@ -3,10 +3,10 @@ from .command import Command
 
 class VenvCommand(Command):
 
-    def __init__(self, name=None):
+    def __init__(self):
         self._venv = None
 
-        super(VenvCommand, self).__init__(name)
+        super(VenvCommand, self).__init__()
 
     def initialize(self, i, o):
         from poetry.utils.venv import Venv

poetry/puzzle/solver.py

@@ -13,7 +13,6 @@ from .operations import Update
 from .operations.operation import Operation
 
 from .provider import Provider
-from .ui import UI
 
 
 class Solver:

poetry/puzzle/ui.py

-from cleo.styles import CleoStyle
-from poetry.mixology.contracts import UI as BaseUI
-
-
-class UI(BaseUI):
-
-    def __init__(self, io):  # type: (CleoStyle) -> None
-        self._io = io
-        self._progress = None
-
-        super(UI, self).__init__(self._io.is_debug())
-
-    @property
-    def output(self):
-        return self._io
-
-    def before_resolution(self):
-        self._io.write('<info>Resolving dependencies</>')
-
-        if self.is_debugging():
-            self._io.new_line()
-
-    def indicate_progress(self):
-        if not self.is_debugging():
-            self._io.write('.')
-
-    def after_resolution(self):
-        self._io.new_line()
-
-    def debug(self, message, depth):
-        if self.is_debugging():
-            debug_info = str(message)
-            debug_info = '\n'.join([
-                '<comment>:{}:</> {}'.format(str(depth).rjust(4), s)
-                for s in debug_info.split('\n')
-            ]) + '\n'
-
-            self.output.write(debug_info)

poetry/repositories/pypi_repository.py

+import logging
 import os
 import tarfile
 import zipfile
@@ -38,12 +39,16 @@ from poetry.version.markers import InvalidMarker
 from .repository import Repository
 
 
+logger = logging.getLogger(__name__)
+
+
 class PyPiRepository(Repository):
 
     def __init__(self,
                  url='https://pypi.org/',
                  disable_cache=False,
                  fallback=True):
+        self._name = 'PyPI'
         self._url = url
         self._disable_cache = disable_cache
         self._fallback = fallback
@@ -91,6 +96,12 @@ class PyPiRepository(Repository):
         for version, release in info['releases'].items():
             if not release:
                 # Bad release
+                self._log(
+                    'No release information found for {}-{}, skipping'.format(
+                        name, version
+                    ),
+                    level='debug'
+                )
                 continue
 
             if (
@@ -102,6 +113,13 @@ class PyPiRepository(Repository):
         for version in versions:
             packages.append(Package(name, version))
 
+        self._log(
+            '{} packages found for {} {}'.format(
+                len(packages), name, str(constraint)
+            ),
+            level='debug'
+        )
+
         return packages
 
     def package(self,
@@ -125,6 +143,10 @@ class PyPiRepository(Repository):
                 and '_fallback' not in release_info
             ):
                 # Force cache update
+                self._log(
+                    'No dependencies found, downloading archives',
+                    level='debug'
+                )
                 self._cache.forget('{}:{}'.format(name, version))
                 release_info = self.get_release_info(name, version)
 
@@ -141,6 +163,13 @@ class PyPiRepository(Repository):
                     dependency = dependency_from_pep_508(req)
                 except ValueError:
                     # Likely unable to parse constraint so we skip it
+                    self._log(
+                        'Invalid constraint ({}) found in {}-{} dependencies, '
+                        'skipping'.format(
+                            req, package.name, package.version
+                        ),
+                        level='debug'
+                    )
                     continue
 
                 if dependency.extras:
@@ -438,3 +467,6 @@ class PyPiRepository(Repository):
 
         if requires_dist:
             return requires_dist
+
+    def _log(self, msg, level='info'):
+        getattr(logger, level)('{}: {}'.format(self._name, msg))