setting flogtool FLOG* environment variables causes spurious test failures

[davidsarah]

The following FLOG* environment variables are supposed to control foolscap/flogtool logging:

FLOGFILE=flog.out.bz2
FLOGLEVEL=1
FLOGTOTWISTED=1

However, setting these variables causes spurious errors like the following when running setup.py trial:

===============================================================================
[FAIL]: allmydata.test.test_storage.BucketCounter.test_bucket_counter

Traceback (most recent call last):
  File "d:\tahoe\new5\tahoe\src\allmydata\test\test_storage.py",
line 1413, in _check
    ss.bucket_counter.prefixes[0])
twisted.trial.unittest.FailTest: not equal:
a = None
b = '22'

===============================================================================
[FAIL]: allmydata.test.test_storage.BucketCounter.test_bucket_counter_cleanup

Traceback (most recent call last):
  File "d:\tahoe\new5\tahoe\src\allmydata\test\test_storage.py",
line 1453, in _after_first_prefix
    ss.bucket_counter.prefixes[0])
twisted.trial.unittest.FailTest: not equal:
a = None
b = '22'

===============================================================================
[FAIL]: allmydata.test.test_storage.LeaseCrawler.test_basic

Traceback (most recent call last):
  File "d:\tahoe\new5\tahoe\src\allmydata\test\test_storage.py",
line 1636, in _after_first_bucket
    self.failUnless("cycle-to-date" in initial_state)
twisted.trial.unittest.FailTest: None
===============================================================================
[FAIL]: allmydata.test.test_storage.LeaseCrawler.test_expire_age

Traceback (most recent call last):
  File "d:\tahoe\new5\tahoe\src\allmydata\test\test_storage.py",
line 1834, in _after_first_bucket
    self.failUnless(p["cycle-in-progress"])
twisted.trial.unittest.FailTest: None
===============================================================================
[FAIL]: allmydata.test.test_storage.LeaseCrawler.test_expire_cutoff_date

Traceback (most recent call last):
  File "d:\tahoe\new5\tahoe\src\allmydata\test\test_storage.py",
line 1975, in _after_first_bucket
    self.failUnless(p["cycle-in-progress"])
twisted.trial.unittest.FailTest: None
===============================================================================
[FAIL]: allmydata.test.test_storage.LeaseCrawler.test_unpredictable_future

Traceback (most recent call last):
  File "d:\tahoe\new5\tahoe\src\allmydata\test\test_storage.py",
line 2248, in _check
    self.failUnless("cycle-to-date" in s)
twisted.trial.unittest.FailTest: None
===============================================================================
[ERROR]: allmydata.test.test_storage.LeaseCrawler.test_share_corruption

Traceback (most recent call last):
  File "d:\tahoe\new5\tahoe\src\allmydata\test\test_storage.py",
line 2364, in _after_first_bucket
    so_far = lc.get_state()["cycle-to-date"]
exceptions.KeyError: 'cycle-to-date'
===============================================================================

(Both Zooko and I have fallen foul of this -- it can be a serious time-waster.)

[davidsarah]

Warn about test failures due to setting FLOG* env vars

[zooko]

Okay, I reviewed warn-about-test-failures-darcspatch.txt and am applying it. 66646d9dd6c09873

A good fix for this issue would be to make the tests pass even when FLOG* is set, if possible. Another fairly reasonable fix would be for those tests which for some reason can't work with FLOG* (presumably because they are asserting that the code under test doesn't spew to output pipes) raise ~SkipTest? if FLOG* are set.

[davidsarah]

test_storage.py: potential fix for failures when logging is enabled.

[zooko]

I don't actually understand what this patch does, but I applied it (or actually the rebase of it to trunk as attached by me just now) and it made unit tests pass even while flogging was turned on, so I guess it is good.

[davidsarah]

Replying to zooko:

I don't actually understand what this patch does...

It fixes some race conditions where test_storage.py wasn't waiting long enough for the conditions it was testing. These race condition failures had also been seen in some rare cases without flogging turned on.

We should now remove the warning from logging.txt, if we're sure this is fixed.

[davidsarah]

Applied in 3b1b0147a867759c (which wasn't really written 40 years ago ;-)