Added some observability into depsolving with a special log file

closes pulp#2343
pulp#2343

CHANGES/2343.feature

@@ -0,0 +1 @@
+Added a debug option for greater visibility into dependency solving.

pulp_rpm/app/depsolving.py

@@ -4,6 +4,8 @@
 
 from pulp_rpm.app import models
 
+from django.conf import settings
+
 
 logger = logging.getLogger(__name__)
 
@@ -779,28 +781,6 @@ def resolve_dependencies(self, unit_repo_map):
         self._pool.createwhatprovides()
         flags = solv.Job.SOLVER_INSTALL | solv.Job.SOLVER_SOLVABLE
 
-        def run_solver_jobs(jobs):
-            """Execute the libsolv jobs, return results.
-
-            Take a list of jobs, get a solution, return the set of solvables that needed to
-            be installed.
-            """
-            solver = self._pool.Solver()
-            raw_problems = solver.solve(jobs)
-            # The solver is simply ignoring the problems encountered and proceeds associating
-            # any new solvables/units. This might be reported back to the user one day over
-            # the REST API. For now, log only "real" dependency issues (typically some variant
-            # of "can't find the package"
-            dependency_warnings = self._build_warnings(raw_problems)
-            if dependency_warnings:
-                logger.warning(
-                    "Encountered problems solving dependencies, "
-                    "copy may be incomplete: {}".format(", ".join(dependency_warnings))
-                )
-
-            transaction = solver.transaction()
-            return set(transaction.newsolvables())
-
         solvables_to_copy = set(solvables)
         result_solvables = set()
         install_jobs = []
@@ -830,12 +810,149 @@ def run_solver_jobs(jobs):
                 unit_install_job = self._pool.Job(flags, solvable.id)
                 install_jobs.append(unit_install_job)
 
-        # Depsolve using the list of unit install jobs, add them to the results
-        solvables_copied = run_solver_jobs(install_jobs)
-        result_solvables.update(solvables_copied)
+        # Take a list of jobs, get a solution, return the set of solvables that needed to
+        # be installed.
+        solver = self._pool.Solver()
+        solver.set_flag(solv.Solver.SOLVER_FLAG_FOCUS_INSTALLED, 1)
+
+        raw_problems = solver.solve(install_jobs)
+        # The solver is simply ignoring the problems encountered and proceeds associating
+        # any new solvables/units. This might be reported back to the user one day over
+        # the REST API. For now, log only "real" dependency issues (typically some variant
+        # of "can't find the package"
+        dependency_warnings = self._build_warnings(raw_problems)
+        if dependency_warnings:
+            logger.warning(
+                "Encountered problems solving dependencies, "
+                "copy may be incomplete: {}".format(", ".join(dependency_warnings))
+            )
+
+        transaction = solver.transaction()
+        write_solver_debug_data(solver, full=False)
+        result_solvables.update(set(transaction.newsolvables()))
 
         solved_units = self.mapping.get_units_from_solvables(result_solvables)
         for k in unit_repo_map.keys():
             solved_units[k] |= passthrough[k]
 
         return solved_units
+
+
+# Descriptions copied from the libsolv documentation
+# https://github.com/openSUSE/libsolv/blob/master/doc/libsolv-bindings.txt
+def write_solver_debug_data(solver, full=False):
+    """Dump the state of the solver including actions decided upon and problems encountered."""
+    from pulpcore.plugin.models import Task
+    from pathlib import Path
+
+    debugdata_dir = Path("/var/tmp/pulp") / str(Task.current().pulp_id)
+    debugdata_dir.mkdir(parents=True, exist_ok=True)
+    logger.info("Writing solver debug data to {}".format(debugdata_dir))
+
+    transaction = solver.transaction()
+    summary_path = debugdata_dir / "copy_summary.txt"
+
+    def reason_desc(reason):
+        if reason == solv.Solver.SOLVER_REASON_UNRELATED:
+            return "The package status did not change as it was not related to any job."
+        elif reason == solv.Solver.SOLVER_REASON_UNIT_RULE:
+            return (
+                "The package was installed/erased/kept because of a unit rule, "
+                "i.e. a rule where all literals but one were false."
+            )
+        elif reason == solv.Solver.SOLVER_REASON_KEEP_INSTALLED:
+            return (
+                "The package was chosen when trying to keep as many packages installed as possible."
+            )
+        elif reason == solv.Solver.SOLVER_REASON_RESOLVE_JOB:
+            return "The decision happened to fulfill a job rule."
+        elif reason == solv.Solver.SOLVER_REASON_UPDATE_INSTALLED:
+            return "The decision happened to fulfill a package update request."
+        elif reason == solv.Solver.SOLVER_REASON_RESOLVE:
+            return "The package was installed to fulfill package dependencies."
+        elif reason in (
+            solv.Solver.SOLVER_REASON_WEAKDEP,
+            solv.Solver.SOLVER_REASON_RECOMMENDED,
+            solv.Solver.SOLVER_REASON_SUPPLEMENTED,
+        ):
+            return "The package was installed because of a weak dependency (Recommends or Supplements)."
+
+    def rule_desc(rule):
+        if rule == solv.Solver.SOLVER_RULE_UNKNOWN:
+            return "A rule of an unknown class. You should never encounter those."
+        elif rule == solv.Solver.SOLVER_RULE_PKG:
+            return "A package dependency rule."
+        elif rule == solv.Solver.SOLVER_RULE_UPDATE:
+            return "A rule to implement the update policy of installed packages. Every installed package has an update rule that consists of the packages that may replace the installed package."
+        elif rule == solv.Solver.SOLVER_RULE_FEATURE:
+            return "Feature rules are fallback rules used when an update rule is disabled. They include all packages that may replace the installed package ignoring the update policy, i.e. they contain downgrades, arch changes and so on. Without them, the solver would simply erase installed packages if their update rule gets disabled."
+        elif rule == solv.Solver.SOLVER_RULE_JOB:
+            return "Job rules implement the job given to the solver."
+        elif rule == solv.Solver.SOLVER_RULE_DISTUPGRADE:
+            return "These are simple negative assertions that make sure that only packages are kept that are also available in one of the repositories."
+        elif rule == solv.Solver.SOLVER_RULE_INFARCH:
+            return "Infarch rules are also negative assertions, they disallow the installation of packages when there are packages of the same name but with a better architecture."
+        elif rule == solv.Solver.SOLVER_RULE_CHOICE:
+            return "Choice rules are used to make sure that the solver prefers updating to installing different packages when some dependency is provided by multiple packages with different names. The solver may always break choice rules, so you will not see them when a problem is found."
+        elif rule == solv.Solver.SOLVER_RULE_LEARNT:
+            return "These rules are generated by the solver to keep it from running into the same problem multiple times when it has to backtrack. They are the main reason why a sat solver is faster than other dependency solver implementations."
+
+        # Special dependency rule types:
+
+        elif rule == solv.Solver.SOLVER_RULE_PKG_NOT_INSTALLABLE:
+            return "This rule was added to prevent the installation of a package of an architecture that does not work on the system."
+        elif rule == solv.Solver.SOLVER_RULE_PKG_NOTHING_PROVIDES_DEP:
+            return (
+                "The package contains a required dependency which was not provided by any package."
+            )
+        elif rule == solv.Solver.SOLVER_RULE_PKG_REQUIRES:
+            return "Similar to SOLVER_RULE_PKG_NOTHING_PROVIDES_DEP, but in this case some packages provided the dependency but none of them could be installed due to other dependency issues."
+        elif rule == solv.Solver.SOLVER_RULE_PKG_SELF_CONFLICT:
+            return "The package conflicts with itself. This is not allowed by older rpm versions."
+        elif rule == solv.Solver.SOLVER_RULE_PKG_CONFLICTS:
+            return "To fulfill the dependencies two packages need to be installed, but one of the packages contains a conflict with the other one."
+        elif rule == solv.Solver.SOLVER_RULE_PKG_SAME_NAME:
+            return "The dependencies can only be fulfilled by multiple versions of a package, but installing multiple versions of the same package is not allowed."
+        elif rule == solv.Solver.SOLVER_RULE_PKG_OBSOLETES:
+            return "To fulfill the dependencies two packages need to be installed, but one of the packages obsoletes the other one."
+        elif rule == solv.Solver.SOLVER_RULE_PKG_IMPLICIT_OBSOLETES:
+            return "To fulfill the dependencies two packages need to be installed, but one of the packages has provides a dependency that is obsoleted by the other one. See the POOL_FLAG_IMPLICITOBSOLETEUSESPROVIDES flag."
+        elif rule == solv.Solver.SOLVER_RULE_PKG_INSTALLED_OBSOLETES:
+            return "To fulfill the dependencies a package needs to be installed that is obsoleted by an installed package. See the POOL_FLAG_NOINSTALLEDOBSOLETES flag."
+        elif rule == solv.Solver.SOLVER_RULE_JOB_NOTHING_PROVIDES_DEP:
+            return "The user asked for installation of a package providing a specific dependency, but no available package provides it."
+        elif rule == solv.Solver.SOLVER_RULE_JOB_UNKNOWN_PACKAGE:
+            return "The user asked for installation of a package with a specific name, but no available package has that name."
+        elif rule == solv.Solver.SOLVER_RULE_JOB_PROVIDED_BY_SYSTEM:
+            return "The user asked for the erasure of a dependency that is provided by the system (i.e. for special hardware or language dependencies), this cannot be done with a job."
+        elif rule == solv.Solver.SOLVER_RULE_JOB_UNSUPPORTED:
+            return "The user asked for something that is not yet implemented, e.g. the installation of all packages at once."
+
+    with summary_path.open("wt") as summary:
+        print("Packages transferred:", file=summary)
+        print("=====================", file=summary)
+        print(file=summary)
+
+        for solvable in transaction.newsolvables():
+            (reason, rule) = solver.describe_decision(solvable)
+
+            print(
+                "{name}-{evr}.{arch}".format(
+                    name=solvable.name, evr=solvable.evr, arch=solvable.arch
+                ),
+                file=summary,
+            )
+            import pydevd_pycharm
+
+            pydevd_pycharm.settrace(
+                "localhost", port=12735, stdoutToServer=True, stderrToServer=True
+            )
+            print("\tReason: {}".format(reason_desc(reason)), file=summary)
+            print("\tDetails:", file=summary)
+            for info in rule.allinfos():
+                print("\t\t type={}".format(rule_desc(info.type)), file=summary)
+
+            print(file=summary)
+
+    if full:
+        solver.write_testcase(str(debugdata_dir))

pulp_rpm/app/settings.py

@@ -10,3 +10,4 @@
 DEFAULT_ULN_SERVER_BASE_URL = "https://linux-update.oracle.com/"
 RPM_ITERATIVE_PARSING = True
 KEEP_CHANGELOG_LIMIT = 10
+SOLVER_DEBUG_LOGS = True

pulp_rpm/app/tasks/copy.py

@@ -109,11 +109,18 @@ def find_children_of_content(content, src_repo_version):
 
 
 @transaction.atomic
-def copy_content(config, dependency_solving):
+def copy_content(config, dependency_solving, debug=False):
     """
     Copy content from one repo to another.
 
     Args:
+        config: Details of how the copy should be performed.
+        dependency_solving: Use dependency solving to find additional content units to copy.
+
+    Kwargs:
+        debug (bool): Print log files to /var/lib/pulp/rpm_debug_logs/
+
+    Config format details:
         source_repo_version_pk: repository version primary key to copy units from
         dest_repo_pk: repository primary key to copy units into
         criteria: a dict that maps type to a list of criteria to filter content by. Note that this
@@ -172,7 +179,7 @@ def process_entry(entry):
         libsolv_repo_names = {}
         base_versions = {}
 
-        solver = Solver()
+        solver = Solver(debug=debug)
 
         for entry in config:
             (