#923 closed defect (fixed)

setting flogtool FLOG* environment variables causes spurious test failures

Reported by: davidsarah Owned by: warner
Priority: major Milestone: 1.7.1
Component: code-storage Version: 1.5.0
Keywords: foolscap logging flog test reviewed Cc:
Launchpad Bug:

Description

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.)

Attachments (3)

warn-about-test-failures-darcspatch.txt (37.7 KB) - added by davidsarah at 2010-01-24T22:14:18Z.
Warn about test failures due to setting FLOG* env vars
fix-test-storage-failures.dpatch (32.0 KB) - added by davidsarah at 2010-06-11T00:55:51Z.
test_storage.py: potential fix for failures when logging is enabled.
fix-test-storage-failures-rebased.dpatch (7.4 KB) - added by zooko at 2010-07-11T06:20:59Z.

Download all attachments as: .zip

Change History (15)

Changed at 2010-01-24T22:14:18Z by davidsarah

Warn about test failures due to setting FLOG* env vars

comment:1 Changed at 2010-01-24T22:15:12Z by davidsarah

  • Keywords review-needed added

comment:2 Changed at 2010-01-26T05:01:15Z by 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.

comment:3 Changed at 2010-01-26T18:10:26Z by davidsarah

  • Keywords review-needed removed

Changed at 2010-06-11T00:55:51Z by davidsarah

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

comment:4 Changed at 2010-06-11T00:56:21Z by davidsarah

  • Keywords review-needed added

comment:5 Changed at 2010-06-12T00:55:42Z by davidsarah

  • Owner changed from somebody to warner

comment:6 Changed at 2010-06-12T00:56:03Z by davidsarah

  • Component changed from code to code-storage

comment:7 Changed at 2010-06-12T22:14:37Z by davidsarah

  • Milestone changed from undecided to soon

comment:8 follow-up: Changed at 2010-07-11T06:21:09Z by zooko

  • Keywords reviewed added; review-needed removed

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.

comment:9 in reply to: ↑ 8 Changed at 2010-07-11T20:36:55Z by 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.

comment:10 Changed at 2010-07-11T20:42:45Z by davidsarah

  • Milestone changed from soon to 1.7.1

comment:11 Changed at 2010-07-12T05:02:06Z by davidsarah

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

comment:12 Changed at 2010-07-12T14:30:19Z by zooko

  • Resolution set to fixed
  • Status changed from new to closed
Note: See TracTickets for help on using tickets.