Intermittent test failure during _finishLogFile

[Andrew Bennetts]

I just got this failure in a branch based on current lp:bzr:

$ ./bzr --no-plugins selftest '(?i)smart' '(?i)hpss' '(?i)remote' -1
bzr selftest: /home/andrew/warthogs/bzr/no_until_no_eintr/bzr
   /home/andrew/warthogs/bzr/no_until_no_eintr/bzrlib
   bzr-2.2.0dev1 python-2.6.4 Linux-2.6.31-20-generic-i686-with-Ubuntu-9.10-karmic
[...]
======================================================================
ERROR: bzrlib.tests.per_repository_reference.test_initialize.TestInitialize.test_remote_initialize_on_transport_ex(RepositoryFormatKnitPack5)
----------------------------------------------------------------------
_StringException: Text attachment: log
------------
394.455 creating repository in file:///tmp/testbzr-VinK9A.tmp/bzrlib.tests.per_repository_reference.test_initialize.TestInitialize.test_remote_initialize_on_transport_ex%28RepositoryFormatKnitPack5%29/work/base/.bzr/.
394.459 creating branch <bzrlib.branch.BzrBranchFormat7 object at 0xa8cca4c> in file:///tmp/testbzr-VinK9A.tmp/bzrlib.tests.per_repository_reference.test_initialize.TestInitialize.test_remote_initialize_on_transport_ex%28RepositoryFormatKnitPack5%29/work/base/.bzr/
394.470 creating repository in chroot-311407180:///stacked/.bzr/.
394.487 opening working tree '/tmp/testbzr-VinK9A.tmp'
------------
Text attachment: traceback
------------
Traceback (most recent call last):
  File "/usr/lib/python2.6/dist-packages/testtools/testcase.py", line 153, in _runCleanups
    function(*arguments, **keywordArguments)
  File "/home/andrew/warthogs/bzr/no_until_no_eintr/bzrlib/tests/__init__.py", line 1465, in _finishLogFile
    self._get_log(False)
  File "/home/andrew/warthogs/bzr/no_until_no_eintr/bzrlib/tests/__init__.py", line 1674, in _get_log
    self._log_file.close()
IOError: close() called during concurrent operation on the same file object.
------------

The changes in this branch are not AFAICT relevant to this test, so I assume this is a rare race condition in our test cleanup. I haven't been able to reproduce by running just that one test in isolation, so it's presumably a tricky race to hit, but it must be possible because it did happen. No other tests failed during that run.

Being a difficult-to-reproduce failure, perhaps we'll give up on this bug in a few months with no further activity. But perhaps other people will encounter it, in which case this bug can start collecting data points.

[Andrew Bennetts (spiv)]

If I re-run that command line, I can sometimes reproduce the failure, although the specific test varies, e.g.:

======================================================================
ERROR: bzrlib.tests.per_branch.test_http.InaccessibleParentTests.test_get_parent_invalid(RemoteBranchFormat-default)
----------------------------------------------------------------------
_StringException: Text attachment: log
------------
130.539 creating repository in chroot-221198540:///parent/path/to/a/.bzr/.
130.549 creating branch <bzrlib.branch.BzrBranchFormat7 object at 0xd39dcac> in chroot-221198540:///parent/path/to/a/.bzr/
130.597 creating repository in chroot-221198540:///child/path/to/b/.bzr/.
130.604 Using fetch logic to copy between RemoteRepository(bzr://127.0.0.1:42139/extra/parent/path/to/a/.bzr/)(<RemoteRepositoryFormat>) and RemoteRepository(bzr://127.0.0.1:42139/extra/child/path/to/b/.bzr/)(<RemoteRepositoryFormat>)
130.604 fetch up to rev {None}
130.628 creating branch <bzrlib.branch.BzrBranchFormat7 object at 0xd3a00cc> in chroot-221198540:///child/path/to/b/.bzr/
130.666 created new branch RemoteBranch(bzr://127.0.0.1:42139/extra/child/path/to/b/)
130.709 opening working tree '/tmp/testbzr-mlvEn4.tmp'
------------
Text attachment: traceback
------------
Traceback (most recent call last):
  File "/usr/lib/python2.6/dist-packages/testtools/testcase.py", line 153, in _runCleanups
    function(*arguments, **keywordArguments)
  File "/home/andrew/warthogs/bzr/no_until_no_eintr/bzrlib/tests/__init__.py", line 1465, in _finishLogFile
    self._get_log(False)
  File "/home/andrew/warthogs/bzr/no_until_no_eintr/bzrlib/tests/__init__.py", line 1674, in _get_log
    self._log_file.close()
IOError: close() called during concurrent operation on the same file object.
------------

[Vincent Ladeuil (vila)]

From 15000 kms away, both tests use a server running in a separate thread. Both servers certainly may write into the log file.

I don't know if such writes are atomics as far as python thread handling is concerned.
If they aren't, this sounds like yet another fallout from the thread/socket leaks.

A reliable way to reproduce this bug will be welcome but... if it's related to the leaks,
I won't hold my breath.