output non reproducible inhibiting verification of changes

I see some efforts to keep order already:
1843 pkglist = sorted(pkgset)
1900 srclist = sorted(srcset)
1924 snaplist = sorted(snapset)
524 self._names = topo_sort(self._inherit)
...
So I'm not introducing an idea that would be the polar opposite how it is supposed to work :-)

I already have a commit that works for the log output, looking into the generated files now ...

Interesting, the small change I had does not make it slower and fixes more than I've expected.

Some of the noise in the actual files like "all" and "all+extra" always switched between things like:
-xserver-xorg-dev | Rescued from xorg-server
+xserver-xorg-dev | xorg-dev

And it was part of the non reproducibility which one was reported.
That also got resolved by my change that was targeted primarily at the console output of germinate.

This stopped to switch between the two - it stays steady at the same value on each re-run now.

Note: like before there are still cases that have "Rescued" and others that list the dependent package. But now in a reproducible fashion.

_rescue_includes does check if a package is already present and continues.

But in a run with some debug between flaky and sorted output I found modemmanager-dev toggling between "Rescued from modemmanager" (unsorted) and "libmm-glib-dev" (sorted)

I many times see "_add_dependency modemmanager" before we get to the rescue check.
And I'd assume that this makes it not rescuing it and be skipped.

unsorted/germinate.log:11974: D: rescue-check modemmanager-doc
unsorted/germinate.log:11975: D: Rescued modemmanager-doc from extra to supported
unsorted/germinate.log:11977: D: rescue-check gir1.2-modemmanager-1.0
unsorted/germinate.log:11978: D: Rescued gir1.2-modemmanager-1.0 from extra to supported
unsorted/germinate.log:11980: D: rescue-check modemmanager-dev
unsorted/germinate.log:11981: D: Rescued modemmanager-dev from extra to supported
unsorted/germinate.log:15661: D: rescue-check modemmanager-doc
unsorted/germinate.log:15663: D: rescue-check gir1.2-modemmanager-1.0
unsorted/germinate.log:15665: D: rescue-check modemmanager-dev

sorted/germinate.log:11970: D: rescue-check gir1.2-modemmanager-1.0
sorted/germinate.log:11971: D: Rescued gir1.2-modemmanager-1.0 from extra to supported
sorted/germinate.log:11980: D: rescue-check modemmanager-dev
sorted/germinate.log:11982: D: rescue-check modemmanager-doc
sorted/germinate.log:11983: D: Rescued modemmanager-doc from extra to supported
sorted/germinate.log:15658: D: rescue-check gir1.2-modemmanager-1.0
sorted/germinate.log:15664: D: rescue-check modemmanager-dev
sorted/germinate.log:15666: D: rescue-check modemmanager-doc

First of all we see that multiple rescue checks are done multiple times, there would be an optimization to skip duplicates here.

But more interestingly if we see that in one case it already was in output._all and skipped while it wasn't in the other. Looking further we see that "libmm-glib-dev" also is a rescued dependency. And in one case it was processed earlier, in the other later.

Due to that we all the time had flickering output, as the set was unsorted those that came early got the "Rescued from" entry and were added including their dependency tree.
But also they were further filling output._all and due to that reducing the chance for further entries to be marked as "Rescued"

We could kind of easily mark all that are "Rescued" as such by only considering the dependencies of Rescued packages also as Rescued. That sentence sounds odd, but consider this dependency graph:

src:A
bin:A
bin:A-dev (depends on B-dev)
src:B
bin:B
bin:B-dev

Seed: A & B

1. The seed would pull in src:A and bin:A
2. The seed would pull in src:B and bin:B
3. The processing of includes reaches A-dev and it would get "Rescued from A"
4. A-dev is added with Dependencies, this puts B-dev in _all
5. The processing of includes reaches B-dev and it is skipped being already present
Result:
A-dev Rescued from A
B-dev A-dev

But the same with different include processing order
1. The seed would pull in src:A and bin:A
2. The seed would pull in src:B and bin:B
3. The processing of includes reaches B-dev and it would get "Rescued from B"
4. B-dev is added with Dependencies, this puts A-dev in _all
5. The processing of includes reaches A-dev and it is skipped being already present
Result:
B-dev Rescued from B
A-dev B-dev

In both cases the same set of packages would be seeded.
But the reporting what dragged things in will be different and that makes debugging seed changes harder than it needs to be.

If a dependency out of the "actual seeding" (not includes) has pulled in a package it already is in _all. So I think we could make it more clear that much more package than we think are in due to auto-includes.

But we can't just keep output._all unchanged (which would simplify the check) as then we'd end up adding packages twice - once for a dependency from a "Rescue" include and once "itself" being an include.

The "why" argument in
 def _add_package(self, seed, pkg, why,
  self._remember_why(seed._reasons, pkg, why, build_tree, recommends)
  self._remember_why(output._all_reasons, pkg, why, build_tree,

But then it calls into "self._add_dependency_tree" which looses the reasoning the parent was brought in.

Well, the change I have that sorts it already makes it reproducible which this bug is about.
While later one can consider adding "indirectly rescued" labels somehow that would be too error prone to change atm.

Commit added to my open MP that also helps to understand the architectures better at
https://code.launchpad.net/~paelzer/germinate/+git/germinate/+merge/390466

This bug was fixed in the package germinate - 2.36

---------------
germinate (2.36) unstable; urgency=medium

  [ Christian Ehrhardt ]
  * Improve ordering of rescued packages (LP: #1895106).

 -- Colin Watson <email address hidden> Mon, 25 Jan 2021 12:56:40 +0000