Use extended python logging

.gitignore

@@ -2,6 +2,7 @@ pip3 # Python compiled files
 *.py[cod]
 
 # virtualenv and other misc bits
+.venv
 /src/*.egg-info
 *.egg-info
 /dist

src/python_inspector/__init__.py

@@ -13,3 +13,4 @@
 pyinspector_settings = settings.Settings()
 
 settings.create_cache_directory(pyinspector_settings.CACHE_THIRDPARTY_DIR)
+

src/python_inspector/api.py

@@ -9,6 +9,7 @@
 # See https://aboutcode.org for more information about nexB OSS projects.
 #
 import asyncio
+import logging
 import os
 from netrc import netrc
 from typing import Dict
@@ -32,6 +33,7 @@
 from python_inspector import pyinspector_settings
 from python_inspector import utils
 from python_inspector import utils_pypi
+from python_inspector.logging import logger
 from python_inspector.package_data import get_pypi_data_from_purl
 from python_inspector.resolution import PythonInputProvider
 from python_inspector.resolution import format_pdt_tree
@@ -88,10 +90,8 @@ def resolve_dependencies(
     max_rounds=200000,
     use_cached_index=False,
     use_pypi_json_api=False,
-    verbose=False,
     analyze_setup_py_insecurely=False,
     prefer_source=False,
-    printer=print,
     generic_paths=False,
     ignore_errors=False,
 ):
@@ -124,8 +124,7 @@ def resolve_dependencies(
             f"Must be one of: {', '.join(valid_python_versions)}"
         )
 
-    if verbose:
-        printer("Resolving dependencies...")
+    logger.info("Resolving dependencies...")
 
     if netrc_file:
         if not os.path.exists(netrc_file):
@@ -139,8 +138,7 @@ def resolve_dependencies(
                 netrc_file = None
 
     if netrc_file:
-        if verbose:
-            printer(f"Using netrc file {netrc_file}")
+        logger.info(f"Using netrc file {netrc_file}")
         parsed_netrc = netrc(netrc_file)
     else:
         parsed_netrc = None
@@ -235,28 +233,28 @@ def resolve_dependencies(
             files=files,
         )
 
-    if verbose:
-        printer("direct_dependencies:")
+    logger.info("direct_dependencies:")
+    if logger.level <= logging.INFO:
         for dep in direct_dependencies:
-            printer(f" {dep}")
+            logging.info(f" {dep}")
 
     # create a resolution environments
     environment = utils_pypi.Environment.from_pyver_and_os(
         python_version=python_version, operating_system=operating_system
     )
 
-    if verbose:
-        printer(f"environment: {environment}")
+    logging.info(f"environment: {environment}")
 
     repos_by_url = {}
     if not use_pypi_json_api:
         # Collect PyPI repos
         use_only_confed = pyinspector_settings.USE_ONLY_CONFIGURED_INDEX_URLS
         for index_url in index_urls:
             index_url = index_url.strip("/")
+
             if use_only_confed and index_url not in pyinspector_settings.INDEX_URL:
-                if verbose:
-                    printer(f"Skipping index URL unknown in settings: {index_url!r}")
+                logger.info(f"Skipping index URL unknown in settings: {index_url!r}")
+
                 continue
             if index_url in repos_by_url:
                 continue
@@ -274,10 +272,10 @@ def resolve_dependencies(
             repos_by_url[index_url] = repo
 
     repos = repos_by_url.values()
-    if verbose:
-        printer("repos:")
+    logger.info("repos:")
+    if logger.level <= logging.INFO:
         for repo in repos:
-            printer(f" {repo}")
+            logger.info(f" {repo}")
 
     # resolve dependencies proper
     resolution, purls = resolve(
@@ -289,8 +287,6 @@ def resolve_dependencies(
         pdt_output=pdt_output,
         analyze_setup_py_insecurely=analyze_setup_py_insecurely,
         ignore_errors=ignore_errors,
-        verbose=verbose,
-        printer=printer,
     )
 
     async def gather_pypi_data():
@@ -299,20 +295,17 @@ async def get_pypi_data(package):
                 package, repos=repos, environment=environment, prefer_source=prefer_source
             )
 
-            if verbose:
-                printer(f"  retrieved package '{package}'")
+            logger.info(f"  retrieved package '{package}'")
 
             return data
 
-        if verbose:
-            printer(f"retrieve package data from pypi:")
+        logger.info(f"retrieve package data from pypi:")
 
         return await asyncio.gather(*[get_pypi_data(package) for package in purls])
 
     packages = [pkg.to_dict() for pkg in asyncio.run(gather_pypi_data()) if pkg is not None]
 
-    if verbose:
-        printer("done!")
+    logger.info("done!")
 
     return Resolution(
         packages=packages,
@@ -352,8 +345,6 @@ def resolve(
     pdt_output: bool = False,
     analyze_setup_py_insecurely: bool = False,
     ignore_errors: bool = False,
-    verbose: bool = False,
-    printer=print,
 ):
     """
     Resolve dependencies given a ``direct_dependencies`` list of
@@ -380,8 +371,6 @@ def resolve(
         pdt_output=pdt_output,
         analyze_setup_py_insecurely=analyze_setup_py_insecurely,
         ignore_errors=ignore_errors,
-        verbose=verbose,
-        printer=printer,
     )
 
     return resolved_dependencies, packages
@@ -396,8 +385,6 @@ def get_resolved_dependencies(
     pdt_output: bool = False,
     analyze_setup_py_insecurely: bool = False,
     ignore_errors: bool = False,
-    verbose: bool = False,
-    printer=print,
 ) -> Tuple[List[Dict], List[str]]:
     """
     Return resolved dependencies of a ``requirements`` list of Requirement for
@@ -420,13 +407,11 @@ async def gather_version_data():
         async def get_version_data(name: str):
             versions = await provider.fill_versions_for_package(name)
 
-            if verbose:
-                printer(f"  retrieved versions for package '{name}'")
+            logger.info(f"  retrieved versions for package '{name}'")
 
             return versions
 
-        if verbose:
-            printer(f"versions:")
+        logger.info(f"versions:")
 
         return await asyncio.gather(
             *[get_version_data(requirement.name) for requirement in requirements]
@@ -446,11 +431,9 @@ async def get_dependencies(requirement: Requirement):
                 candidate = Candidate(requirement.name, purl.version, requirement.extras)
                 await provider.fill_requirements_for_package(purl, candidate)
 
-                if verbose:
-                    printer(f"  retrieved dependencies for requirement '{str(purl)}'")
+                logger.info(f"  retrieved dependencies for requirement '{str(purl)}'")
 
-        if verbose:
-            printer(f"dependencies:")
+        logger.info(f"dependencies:")
 
         return await asyncio.gather(
             *[get_dependencies(requirement) for requirement in requirements]

src/python_inspector/dependencies.py

@@ -19,6 +19,8 @@
 from _packagedcode.pypi import PipRequirementsFileHandler
 from _packagedcode.pypi import get_requirements_txt_dependencies
 
+from python_inspector.logging import logger
+
 """
 Utilities to resolve dependencies.
 """
@@ -36,10 +38,9 @@ def get_dependencies_from_requirements(
         location=requirements_file, include_nested=True
     )
     for dependent_package in dependent_packages:
-        if TRACE:
-            print(
-                "dependent_package.extracted_requirement:",
-                dependent_package.extracted_requirement,
+        logger.debug(
+                "dependent_package.extracted_requirement: "
+                f"{dependent_package.extracted_requirement}",
             )
         yield dependent_package
 

src/python_inspector/logging.py

@@ -0,0 +1,112 @@
+#
+# Copyright (c) nexB Inc. and others. All rights reserved.
+# ScanCode is a trademark of nexB Inc.
+# SPDX-License-Identifier: Apache-2.0
+# See http://www.apache.org/licenses/LICENSE-2.0 for the license text.
+# See https://github.com/aboutcode-org/python-inspector for support or download.
+# See https://aboutcode.org for more information about nexB OSS projects.
+#
+
+import logging
+from pathlib import Path
+from types import TracebackType
+from typing import Any, Optional, Tuple, Type, Union
+
+# Add TRACE custom level to be third leve, as verbose will match
+# -v == logLevel INFO
+# -vv == logLevel DEBUG
+# -vvv == logLevel TRACE
+TRACE_LEVEL: int = 5
+DEEP_LEVEL: int = 4
+
+
+class CustomLogger(logging.Logger):
+    def trace(
+        self: logging.Logger,
+        msg: Any,
+        *args: Any,
+        exc_info: Union[
+            bool,
+            BaseException,
+            Tuple[Type[BaseException], BaseException, TracebackType],
+            None,
+        ] = None,
+        stack_info: bool = False,
+        stacklevel: int = 1,
+        extra: Optional[dict[str, Any]] = None,
+    ) -> None:
+        if self.isEnabledFor(TRACE_LEVEL):
+            self._log(
+                TRACE_LEVEL,
+                msg,
+                args,
+                exc_info=exc_info,
+                extra=extra,
+                stack_info=stack_info,
+                stacklevel=stacklevel,
+            )
+
+    def deep(
+        self: logging.Logger,
+        msg: Any,
+        *args: Any,
+        exc_info: Union[
+            bool,
+            BaseException,
+            Tuple[Type[BaseException], BaseException, TracebackType],
+            None,
+        ] = None,
+        stack_info: bool = False,
+        stacklevel: int = 1,
+        extra: Optional[dict[str, Any]] = None,
+    ) -> None:
+        if self.isEnabledFor(DEEP_LEVEL):
+            self._log(
+                DEEP_LEVEL,
+                msg,
+                args,
+                exc_info=exc_info,
+                extra=extra,
+                stack_info=stack_info,
+                stacklevel=stacklevel,
+            )
+
+
+    logging.Logger.trace = trace
+    logging.Logger.deep = deep
+
+
+def setup_logger(level: str = "WARNING", log_file: Optional[Path] = None) -> None:
+    """
+    Configures the logger for the 'python-inspector' application.
+
+    This function sets up a custom logging level, assigns a custom logger class,
+    and configures the logger with the specified logging level. If no handlers are present,
+    it adds a stream handler with a simple formatter.
+
+    Args:
+        level (str): The logging level to set for the logger (e.g., 'DEBUG', 'INFO', 'WARNING', "TRACE").
+    """
+    # Setup out trace level
+    logging.addLevelName(TRACE_LEVEL, "TRACE")
+    logging.addLevelName(DEEP_LEVEL, "DEEP")
+    logging.setLoggerClass(CustomLogger)
+
+    _logger = logging.getLogger("python-inspector")
+    _logger.setLevel(level)
+    _logger.propagate = False
+
+    if not _logger.hasHandlers():
+        handler = logging.StreamHandler()
+        formatter = logging.Formatter("[%(levelname)s] %(message)s")
+        handler.setFormatter(formatter)
+        _logger.addHandler(handler)
+
+        if log_file:
+            file_handler = logging.FileHandler(log_file, encoding="utf-8")
+            file_handler.setFormatter(formatter)
+            logger.addHandler(file_handler)
+
+
+# Logger as a singleton
+logger: logging.Logger = logging.getLogger("python-inspector")

src/python_inspector/resolution.py

@@ -43,6 +43,7 @@
 from python_inspector import pyinspector_settings as settings
 from python_inspector import utils_pypi
 from python_inspector.error import NoVersionsFound
+from python_inspector.logging import logger
 from python_inspector.setup_py_live_eval import iter_requirements
 from python_inspector.utils import Candidate
 from python_inspector.utils import contain_string
@@ -330,8 +331,8 @@ def get_requirements_from_python_manifest(
                     )
                 ]
                 if len(setup_fct) > 1:
-                    print(
-                        f"Warning: identified multiple definitions of 'setup()' in {setup_py_location}, "
+                    logger.warning(
+                        f"Identified multiple definitions of 'setup()' in {setup_py_location}, "
                         "defaulting to the first occurrence"
                     )
                 setup_fct = setup_fct[0]
@@ -340,8 +341,8 @@ def get_requirements_from_python_manifest(
                 ]
                 if install_requires:
                     if len(install_requires) > 1:
-                        print(
-                            f"Warning: identified multiple definitions of 'install_requires' in "
+                        logger.warning(
+                            f"Identified multiple definitions of 'install_requires' in "
                             "{setup_py_location}, defaulting to the first occurrence"
                         )
                     install_requires = install_requires[0].elts