Merge pull request #499 from dhellmann/improve-formatting-resolver-er…

…rors

improve error and debugging info during bootstrapping

src/fromager/__main__.py

@@ -238,6 +238,13 @@ def main(
     main.add_command(cmd)
 
 
+def _format_exception(exc):
+    if exc.__cause__:
+        cause = _format_exception(exc.__cause__)
+        return f"{exc} because {cause}"
+    return str(exc)
+
+
 def invoke_main() -> None:
     # Wrapper for the click main command that ensures any exceptions
     # are logged so that build pipeline outputs include the traceback.
@@ -248,7 +255,7 @@ def invoke_main() -> None:
             err,
             exc_info=True,
         )  # log the full traceback details to the debug log file, if any
-        logger.error(f"ERROR: {err}")
+        logger.error(f"ERROR: {_format_exception(err)}")
         if _DEBUG:
             raise
         sys.exit(1)

src/fromager/bootstrapper.py

@@ -83,7 +83,7 @@ def bootstrap(self, req: Requirement, req_type: RequirementType) -> Version:
         # Avoid cyclic dependencies and redundant processing.
         if self._has_been_seen(req, resolved_version):
             logger.debug(
-                f"{req.name}: redundant {req_type} requirement {self.why} -> {req} resolves to {resolved_version}"
+                f"{req.name}: redundant {req_type} dependency {req} ({resolved_version}) for {self._explain}"
             )
             return resolved_version
         self._mark_as_seen(req, resolved_version)
@@ -133,16 +133,22 @@ def bootstrap(self, req: Requirement, req_type: RequirementType) -> Version:
             try:
                 self.bootstrap(dep, RequirementType.INSTALL)
             except Exception as err:
-                raise ValueError(
-                    f"could not handle {RequirementType.INSTALL} dependency {dep} for {self.why}"
-                ) from err
+                raise ValueError(f"could not handle {self._explain}") from err
             self.progressbar.update()
 
         # we are done processing this req, so lets remove it from the why chain
         self.why.pop()
         self._cleanup(req, sdist_root_dir, build_env)
         return resolved_version
 
+    @property
+    def _explain(self) -> str:
+        """Return message formatting current version of why stack."""
+        return " for ".join(
+            f"{req_type} dependency {req} ({resolved_version})"
+            for req_type, req, resolved_version in reversed(self.why)
+        )
+
     def _is_wheel_built(
         self, req: Requirement, resolved_version: Version
     ) -> pathlib.Path | None:
@@ -194,6 +200,7 @@ def _build(
         except Exception as err:
             logger.warning(f"{req.name}: failed to build source distribution: {err}")
 
+        logger.info(f"{req.name}: starting build of {self._explain}")
         built_filename = wheels.build_wheel(
             ctx=self.ctx,
             req=req,
@@ -262,9 +269,7 @@ def _handle_build_requirements(
             try:
                 resolved = self.bootstrap(req=dep, req_type=build_type)
             except Exception as err:
-                raise ValueError(
-                    f"could not handle {build_type} dependency {dep} for {self.why}"
-                ) from err
+                raise ValueError(f"could not handle {self._explain}") from err
             # We may need these dependencies installed in order to run build hooks
             # Example: frozenlist build-system.requires includes expandvars because
             # it is used by the packaging/pep517_backend/ build backend

src/fromager/overrides.py

@@ -50,7 +50,12 @@ def find_and_invoke(
         fn = default_fn
 
     result = invoke(fn, **kwargs)
-    logger.info(f"{distname}: override method {fn.__name__} returned {result}")
+    if fn is default_fn:
+        log_method = logger.debug
+    else:
+        log_method = logger.info
+    log_method(f"{distname}: override method {fn.__name__} returned {result}")
+
     return result
 
 

tests/test_bootstrapper.py

@@ -361,3 +361,21 @@ def test_build_order_name_canonicalization(tmp_context):
         },
     ]
     assert expected == contents
+
+
+def test_explain(tmp_context: WorkContext):
+    bt = bootstrapper.Bootstrapper(tmp_context, None, old_graph)
+    bt.why = [(RequirementType.TOP_LEVEL, Requirement("foo"), Version("1.0.0"))]
+    assert bt._explain == f"{RequirementType.TOP_LEVEL} dependency foo (1.0.0)"
+
+    bt.why = []
+    assert bt._explain == ""
+
+    bt.why = [
+        (RequirementType.TOP_LEVEL, Requirement("foo"), Version("1.0.0")),
+        (RequirementType.BUILD, Requirement("bar==4.0.0"), Version("4.0.0")),
+    ]
+    assert (
+        bt._explain
+        == f"{RequirementType.BUILD} dependency bar==4.0.0 (4.0.0) for {RequirementType.TOP_LEVEL} dependency foo (1.0.0)"
+    )