FTBFS breezy 3.2.1-1

In Debian this build issue is not present, compare these s390x builds for example (done on almost the same time - so not as it often happens months apart introducing a lot of build environment differences)

failing:
https://launchpadlibrarian.net/547563235/buildlog_ubuntu-impish-s390x.breezy_3.2.1-1_BUILDING.txt.gz

working:
https://buildd.debian.org/status/fetch.php?pkg=breezy&arch=s390x&ver=3.2.1-1&stamp=1625762685&raw=0

The issue is the same across architectures

Locally reproducible in sbuild of impish
Most obvious difference is a newer python 3.9.2-3 -> 3.9.4-1

A re-build in Debian unstable works fine

Even Re-runnning the test in Impish after a failed build (chrooted into the sbuild environment)

a) as a whole
BRZ_CONCURRENCY=3 BRZ_HOME=debian/brzhome BRZ_PLUGIN_PATH=-site:-user LC_ALL=C.UTF-8 PYTHONPATH=/build/breezy-xbGxjH/breezy-3.2.1/.pybuild/cpython3_3.9_breezy/build python3.9 ./brz -Derror selftest -v

b) and a formerly failing test individually
BRZ_CONCURRENCY=3 BRZ_HOME=debian/brzhome BRZ_PLUGIN_PATH=-site:-user LC_ALL=C.UTF-8 PYTHONPATH=/build/breezy-xbGxjH/breezy-3.2.1/.pybuild/cpython3_3.9_breezy/build python3.9 ./brz -Derror selftest -v breezy.tests.test_plugins.TestLoadingPlugins.test_plugin_with_error
/build/breezy-xbGxjH/breezy-3.2.1/breezy/tests/test_source.py:23: DeprecationWarning: The parser module is deprecated and will be removed in future versions of Python
  import parser
/build/breezy-xbGxjH/breezy-3.2.1/breezy/tests/test_source.py:25: DeprecationWarning: The symbol module is deprecated and will be removed in future versions of Python
  import symbol
running 2 tests...
brz selftest: /build/breezy-xbGxjH/breezy-3.2.1/brz
   /build/breezy-xbGxjH/breezy-3.2.1/breezy
   bzr-3.2.1 python-3.9.6 Linux-5.4.0-73-generic-x86_64-with-glibc2.33

test_plugins.TestLoadingPlugins.test_plugin_with_error OK 24ms
test_plugins.TestLoadingPlugins.test_plugin_with_error_suppress OK 4ms
----------------------------------------------------------------------
Ran 2 tests in 0.035s

OK

It only fails right at the build, and so far I have not found what makes the difference between this and the re-run.

Finally I found a command that fails in bad and works in good env

$ BRZ_CONCURRENCY=3 BRZ_HOME=debian/brzhome BRZ_PLUGIN_PATH=-site:-user LC_ALL=C.UTF-8 PYTHONPATH=/build/breezy-xbGxjH/breezy-3.2.1/.pybuild/cpython3_3.9_breezy/build python3.9 ./brz -Derror selftest -v breezy.tests.test_plugins.TestLoadingPlugins
=> BAD

Reducing concurrency makes no difference:
$ BRZ_PLUGIN_PATH=-site:-user LC_ALL=C.UTF-8 PYTHONPATH=/build/breezy-xbGxjH/breezy-3.2.1/.pybuild/cpython3_3.9_breezy/build python3.9 ./brz -Derror selftest -v breezy.tests.test_plugins.TestLoadingPlugins
=> Still bad

But one has to remember that running a single subtest of it works.
like:
$ BRZ_PLUGIN_PATH=-site:-user LC_ALL=C.UTF-8 PYTHONPATH=/build/breezy-xbGxjH/breezy-3.2.1/.pybuild/cpython3_3.9_breezy/build python3.9 ./brz -Derror selftest -v breezy.tests.test_plugins.TestLoadingPlugins.test_plugins_can_load_from_directory_with_trailing_slash
=> GOOD

Even running all of them one after the other works:
$ for t in test_plugins.TestLoadingPlugins.test_plugin_with_bad_api_version_reports test_plugins.TestLoadingPlugins.test_plugin_with_bad_name_does_not_load test_plugins.TestLoadingPlugins.test_plugin_with_error test_plugins.TestLoadingPlugins.test_plugin_with_error_suppress test_plugins.TestLoadingPlugins.test_plugins_can_load_from_directory_with_trailing_slash test_plugins.TestLoadingPlugins.test_plugins_from_different_dirs_can_demand_load test_plugins.TestLoadingPlugins.test_plugins_with_the_same_name_are_not_loaded; do BRZ_PLUGIN_PATH=-site:-user LC_ALL=C.UTF-8 PYTHONPATH=/build/breezy-xbGxjH/breezy-3.2.1/.pybuild/cpython3_3.9_breezy/build python3.9 ./brz -Derror selftest -v $t; printf "\n\n\n\n\n\n\n\n\n"; done

=> All of them are good now, but while running them at once as shown above they fail.

This blocks breezy, but also breezy-debian, lintian-brush and dulwich (see bug 1933034).
Once the FTFBS here is resolved there is a series of rebuilds and combined tests that need to be executed.
I outlined them at
  https://bugs.launchpad.net/ubuntu/+source/breezy-debian/+bug/1933034/comments/6

To be clear a bunch of the warnings are intentional e.g. on the try to load breezy.testingplugins.some_error

But I tried to reduce the variables:

test_plugins_with_the_same_name_are_not_loaded was failing when run combined.

Overall we have:
test_plugins.TestLoadingPlugins.test_plugin_with_bad_api_version_reports
test_plugins.TestLoadingPlugins.test_plugin_with_bad_name_does_not_load
test_plugins.TestLoadingPlugins.test_plugin_with_error
test_plugins.TestLoadingPlugins.test_plugin_with_error_suppress
test_plugins.TestLoadingPlugins.test_plugins_can_load_from_directory_with_trailing_slash
test_plugins.TestLoadingPlugins.test_plugins_from_different_dirs_can_demand_load
test_plugins.TestLoadingPlugins.test_plugins_with_the_same_name_are_not_loaded

Let us see which few are enough to make it fail.

It seems if either of:
- test_plugins_from_different_dirs_can_demand_load
- test_plugin_with_error
are enabled, then a few fails.

But these combinations are complex I need some more runs.
I want a combination of just two for debugging.

Ok, I found a pair.

test_plugin_with_bad_api_version_reports and test_plugin_with_error work individually.
But if run after one another the second one fails.
I changed their order and it is always the second that fails.

Of the test test_plugin_with_error seems the most simple and even if the same is executed twice the second one fails.
So i leaves something yet unknown behind in the test environment that breaks the second execution
.

brz selftest: /build/breezy-xbGxjH/breezy-3.2.1/brz
   /build/breezy-xbGxjH/breezy-3.2.1/breezy
   bzr-3.2.1 python-3.9.6 Linux-5.4.0-73-generic-x86_64-with-glibc2.33

test_plugins.TestLoadingPlugins.test_plugin_with_error OK 25ms
test_plugins.TestLoadingPlugins.test_plugin_with_error2 FAIL 5ms
    log: {{{
1.650 loading plugins!
1.650 using _Path('breezy.testingplugins', [], [], ['.'])
1.650 Traceback (most recent call last):
  File "/build/breezy-xbGxjH/breezy-3.2.1/breezy/plugin.py", line 430, in _load_plugin_module
    __import__(_MODULE_PREFIX + name)
ModuleNotFoundError: No module named 'breezy.testingplugins.some_error'

1.650 Unable to load plugin 'some_error' from '.': No module named 'breezy.testingplugins.some_error'
 WARNING Unable to load plugin 'some_error' from '.': No module named 'breezy.testingplugins.some_error'
1.652 removed breezy.testingplugins from sys.modules
}}}

Traceback (most recent call last):
  File "/build/breezy-xbGxjH/breezy-3.2.1/breezy/tests/test_plugins.py", line 340, in test_plugin_with_error2
    self.assertEqual(
  File "/build/breezy-xbGxjH/breezy-3.2.1/breezy/tests/__init__.py", line 1307, in assertEqual
    raise AssertionError("%snot equal:\na = %s\nb = %s\n"
AssertionError: not equal:
a = "Unable to load plugin 'some_error' from '.': bad\n"
b = ("Unable to load plugin 'some_error' from '.': No module named "
 "'breezy.testingplugins.some_error'\n")

======================================================================
FAIL: breezy.tests.test_plugins.TestLoadingPlugins.test_plugin_with_error2
----------------------------------------------------------------------
Traceback (most recent call last):
testtools.testresult.real._StringException: log: {{{
1.650 loading plugins!
1.650 using _Path('breezy.testingplugins', [], [], ['.'])
1.650 Traceback (most recent call last):
  File "/build/breezy-xbGxjH/breezy-3.2.1/breezy/plugin.py", line 430, in _load_plugin_module
    __import__(_MODULE_PREFIX + name)
ModuleNotFoundError: No module named 'breezy.testingplugins.some_error'

1.650 Unable to load plugin 'some_error' from '.': No module named 'breezy.testingplugins.some_error'
 WARNING Unable to load plugin 'some_error' from '.': No module named 'breezy.testingplugins.some_error'
1.652 removed breezy.testingplugins from sys.modules
}}}

Traceback (most recent call last):
  File "/build/breezy-xbGxjH/breezy-3.2.1/breezy/tests/test_plugins.py", line 340, in test_plugin_with_error2
    self.assertEqual(
  File "/build/breezy-xbGxjH/breezy-3.2.1/breezy/tests/__init__.py", line 1307, in assertEqual
    raise AssertionError("%snot equal:\na = %s\nb = %s\n"
AssertionError: not equal:
a = "Unable to load plugin 'some_error' from '.': bad\...

The load error is intentional (it is a bad module name).
But the test expects the stringified exception
  bad
while on the second execution it gets:
  No module named 'breezy.testingplugins.some_error'

This checked error message comes from breezy/plugin.py
It is set by:
  return record_plugin_warning(
      'Unable to load plugin %r from %r: %s' % (name, dir, e))

On the first call the exception is of type 'Exception', the second time 'ModuleNotFoundError'.
The test prepares a simple .py file "some_error.py" which contains the
    raise Exception("bad")
which it checks upon.

The load does directly call __import__ with the same string each time.
  __import__("breezy.testingplugins.some_error")

In the good case the raised exception thereby is like:
  File "/build/breezy-xbGxjH/breezy-3.2.1/breezy/plugin.py", line 431, in _load_plugin_module
    __import__(_MODULE_PREFIX + name)
  File "/tmp/testbzr-e53aok06.tmp/breezy.tests.test_plugins.TestLoadingPlugins.test_plugin_with_error/work/./some_error.py", line 1, in <module>
    raise Exception("bad")

And in the bad case it does not find the file.
If I call the __import__ function myself twice it reports "ModuleNotFoundError" every time.
Semething in the setup must make it able to load that and this is what breaks in the second execution.

load_with_paths (tests/test_plugins.py) from sets up the paths that are needed for this to work.
It reached load_plugins (from breezy/plugin.py) with
  path _Path('breezy.testingplugins', [], [], ['.'])

I wondered if the python cache might keep the (failed) module and remember that it failed to load.
And that might make the first load execute code (the one that raises "bad") and the second load fails immediately.

I checked sys.modules.items and tried sys.modules.pop but it never makes it there officially.
So I can't remove it either.
I also changed the name of the module, but that didn't help

I found that I can successfully call self.load_and_capture multiple times with warn_load_problems=False and they are all good.

But any subsequent warn_load_problems=True fails.

True - only working if it is the first
False - always working also later and multiple times.

In the following example
A = test with warn_load_problems=True
B = test with warn_load_problems=False

A - good
A - bad
B - good
B - good
B - good
A - bad
A - bad
B - good
B - good
A - bad
A - bad
A - bad
A - bad

As if we could only get one log, and anything else later does then no more report the raised "bad" but the "ModuleNotFound"

I have also lead in with two tests of type B and then it is

B - good
B - good
A - bad

So it seems like the ones that want to evaluate the log for the raised "bad" can only go first and once. So it still could be that python no more re-loads the code at all and thereby no more triggered "bad".
That leads it to continue and then come up with the "not found".

I mentioned before that giving each test an individual file name does NOT help to resolve the issue. Still the latter modules are not (re)-loaded and do not trigger the
  'raise Exception("bad")\n'
I wondered if python might not keep it's cache by path/filename but instead per-hash.
In which case since all have the very same content they would be the same for the module loader.
But using slightly changed content also did not resolve the issue.

I think I have laid some debugging groundwork here, but I'm lost.
This probably needs a reset and a new pair of eyes :-/

This may also be a duplicate of https://bugs.launchpad.net/ubuntu/+source/breezy/+bug/1932313 , which includes an upstream python commit that introduces the breakage

Note: this affects the version of brz which is already in the archive, so it's not really a regression in brz. Reproducible on Impish with:

  bzr selftest breezy.tests.test_plugins

Focal is also affected; Bionic is not. But in Bionic brz is python2, so there is quite a big step.

https://launchpad.net/ubuntu/+source/breezy/3.2.1-1ubuntu1 fixes the FTBFS due to test failures. (autopkgtest is still processing and may get stuck due to other packages.)

This is accepted in Debian now and works fine on a test build.
The former upload is still stuck in proposed anyway:
  breezy | 3.2.1-1ubuntu1 | jammy-proposed/universe | source

I synced the new version as it can replace the one in proposed without a drawback and keeps auto-syncing from there.

This is Fix Released I believe.