setting flogtool FLOG* environment variables causes spurious test failures #923

New Issue

tahoe-lafs · 2010-01-22T00:42:14Z

davidsarah commented

2010-01-22 00:42:14 +00:00

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

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

tahoe-lafs added the

labels 2010-01-22 00:42:14 +00:00

tahoe-lafs added this to the undecided milestone 2010-01-22 00:42:14 +00:00

davidsarah commented

2010-01-24 22:14:18 +00:00

Attachment warn-about-test-failures-darcspatch.txt (38652 bytes) added

Warn about test failures due to setting FLOG* env vars

**Attachment** warn-about-test-failures-darcspatch.txt (38652 bytes) added Warn about test failures due to setting FLOG* env vars

warn-about-test-failures-darcspatch.txt

38 KiB

zooko commented

2010-01-26 05:01:15 +00:00

Okay, I reviewed warn-about-test-failures-darcspatch.txt and am applying it. changeset: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.

Okay, I reviewed warn-about-test-failures-darcspatch.txt and am applying it. changeset: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 commented

2010-06-11 00:55:51 +00:00

Attachment fix-test-storage-failures.dpatch (32796 bytes) added

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

**Attachment** fix-test-storage-failures.dpatch (32796 bytes) added test_storage.py: potential fix for failures when logging is enabled.

fix-test-storage-failures.dpatch

32 KiB

tahoe-lafs added

code-storage

and removed

code

labels 2010-06-12 00:56:03 +00:00

tahoe-lafs modified the milestone from undecided to soon

2010-06-12 22:14:37 +00:00

zooko commented

2010-07-11 06:20:59 +00:00

Attachment fix-test-storage-failures-rebased.dpatch (7567 bytes) added

**Attachment** fix-test-storage-failures-rebased.dpatch (7567 bytes) added

fix-test-storage-failures-rebased.dpatch

7.4 KiB

zooko commented

2010-07-11 06:21:09 +00:00

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 commented

2010-07-11 20:36:55 +00:00

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]source:docs/logging.txt@4434#L232, if we're sure this is fixed.

Replying to [zooko](/tahoe-lafs/trac-2024-07-25/issues/923#issuecomment-74917): > 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]source:docs/logging.txt@4434#L232, if we're sure this is fixed.

tahoe-lafs modified the milestone from soon to 1.7.1

2010-07-11 20:42:45 +00:00

davidsarah commented

2010-07-12 05:02:06 +00:00

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

zooko added the

fixed

label 2010-07-12 14:30:19 +00:00

zooko closed this issue

2010-07-12 14:30:19 +00:00

Sign in to join this conversation.