test failure (TestHashCache)

[Thomas Klausner]

One of bzr-0.12's self tests fails on NetBSD-4.99.3/amd64, with python-2.4.3 and medusa-0.5.4:
FAIL: test_hashcache_load (bzrlib.tests.test_hashcache.TestHashCache)

vvvv[log from bzrlib.tests.test_hashcache.TestHashCache.test_hashcache_load]--

^^^^[log from bzrlib.tests.test_hashcache.TestHashCache.test_hashcache_load]--
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/obj/devel/bzr/work.x86_64/bzr-0.12/bzrlib/tests/test_hashcache.py", line 92, in test_hashcache_load
    self.assertEquals(hc.hit_count, 1)
AssertionError: 0 != 1

----------------------------------------------------------------------
Ran 3788 tests in 508.776s

FAILED (failures=1)
tests failed
*** Error code 1

[Martin Pool (mbp)]

Thankyou for the bug report. Thomas, is this error reproducible? It may be this test is just overly timing-sensitive.

[Thomas Klausner (tk-giga)]

I tried it again with bzr-0.13 and exactly the same test case failed.
If you tell me how to run the single test separately, I can run it a few times and check how reproducible it is.

[John A Meinel (jameinel)]

bzr selftest REGEX

So you can do:

bzr selftest hashcache

To run all of the tests that match "hashcache". Or you could also do:

bzr selftest test_hashcache_load

I usually run this with --verbose, to double check what tests are actually being run.

[Thomas Klausner (tk-giga)]

It seems to be timing-related after all (or there is a random element).
I ran the test in a tight loop
(for i in `jot 100 1 100`; do ./bzr selftest test_hashcache_load --verbose; done)
and it failed 95 times, but was ok 5 times.

Here's the full --verbose output of a failing run:
# ./bzr selftest test_hashcache_load --verbose
       bzr: /usr/obj/devel/bzr/work.x86_64/bzr-0.13/bzr
    bzrlib: /usr/obj/devel/bzr/work.x86_64/bzr-0.13/bzrlib

running 1 tests...
test_hashcache.TestHashCache.test_hashcache_load FAIL 5154ms
    0 != 1

======================================================================
FAIL: test_hashcache_load (bzrlib.tests.test_hashcache.TestHashCache)

vvvv[log from bzrlib.tests.test_hashcache.TestHashCache.test_hashcache_load]--
created control directory in file:///usr/obj/devel/bzr/work.x86_64/bzr-0.13/test0000.tmp/
creating repository in file:///usr/obj/devel/bzr/work.x86_64/bzr-0.13/test0000.tmp/.bzr/.
creating branch <bzrlib.branch.BzrBranchFormat5 object at 0xbd1b50> in file:///usr/obj/devel/bzr/work.x86_64/bzr-0.13/test0000.tmp/.bzr/
got branch format Bazaar-NG Metadir branch format 5
got branch format Bazaar-NG Metadir branch format 5
opening working tree '/usr/obj/devel/bzr/work.x86_64/bzr-0.13/test0000.tmp'
failed to open /usr/obj/devel/bzr/work.x86_64/bzr-0.13/test0000.tmp/.bzr/checkout/stat-cache: [Errno 2] No such file or directory: u'/usr/obj/devel/bzr/work.x86_64/bzr-0.13/test0000.tmp/.bzr/checkout/stat-cache'
write hc

^^^^[log from bzrlib.tests.test_hashcache.TestHashCache.test_hashcache_load]--
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/obj/devel/bzr/work.x86_64/bzr-0.13/bzrlib/tests/test_hashcache.py", line 92, in test_hashcache_load
    self.assertEquals(hc.hit_count, 1)
AssertionError: 0 != 1

----------------------------------------------------------------------
Ran 1 test in 5.156s

FAILED (failures=1)
tests failed

For completeness, here's one OK run output:
       bzr: /usr/obj/devel/bzr/work.x86_64/bzr-0.13/bzr
    bzrlib: /usr/obj/devel/bzr/work.x86_64/bzr-0.13/bzrlib

running 1 tests...
test_hashcache.TestHashCache.test_hashcache_load OK 5034ms

----------------------------------------------------------------------
Ran 1 test in 5.036s

OK
tests passed

[John A Meinel (jameinel)]

I can't really see why the test would be so sensitive, since it is giving a 5 second delay between writing the file, and checking its stat and sha hash.
And our code is written to cache the sha hash if the timestamp is older than 2 seconds or so.

Can you try this patch:
=== modified file 'bzrlib/tests/test_hashcache.py'
--- bzrlib/tests/test_hashcache.py 2006-09-20 14:03:05 +0000
+++ bzrlib/tests/test_hashcache.py 2006-12-10 15:13:17 +0000
@@ -87,6 +87,7 @@
         pause()
         self.assertEquals(hc.get_sha1('foo'), sha1('contents'))
         hc.write()
+ pause()
         hc = self.reopen_hashcache()
         self.assertEquals(hc.get_sha1('foo'), sha1('contents'))
         self.assertEquals(hc.hit_count, 1)

It really is weird that we would be treating the file as recently modified. Even more so that you have a 95% miss rate.

[Thomas Klausner (tk-giga)]

Strangely (or not?), that pause doesn't help at all:

# ./bzr selftest test_hashcache_load --verbose
       bzr: /usr/obj/devel/bzr/work.x86_64/bzr-0.13/bzr
    bzrlib: /usr/obj/devel/bzr/work.x86_64/bzr-0.13/bzrlib

running 1 tests...
test_hashcache.TestHashCache.test_hashcache_load FAIL 10045ms
    0 != 1

======================================================================
FAIL: test_hashcache_load (bzrlib.tests.test_hashcache.TestHashCache)

vvvv[log from bzrlib.tests.test_hashcache.TestHashCache.test_hashcache_load]--
created control directory in file:///usr/obj/devel/bzr/work.x86_64/bzr-0.13/test0000.tmp/
creating repository in file:///usr/obj/devel/bzr/work.x86_64/bzr-0.13/test0000.tmp/.bzr/.
creating branch <bzrlib.branch.BzrBranchFormat5 object at 0xa1a410> in file:///usr/obj/devel/bzr/work.x86_64/bzr-0.13/test0000.tmp/.bzr/
got branch format Bazaar-NG Metadir branch format 5
got branch format Bazaar-NG Metadir branch format 5
opening working tree '/usr/obj/devel/bzr/work.x86_64/bzr-0.13/test0000.tmp'
failed to open /usr/obj/devel/bzr/work.x86_64/bzr-0.13/test0000.tmp/.bzr/checkout/stat-cache: [Errno 2] No such file or directory: u'/usr/obj/devel/bzr/work.x86_64/bzr-0.13/test0000.tmp/.bzr/checkout/stat-cache'
write hc

^^^^[log from bzrlib.tests.test_hashcache.TestHashCache.test_hashcache_load]--
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/obj/devel/bzr/work.x86_64/bzr-0.13/bzrlib/tests/test_hashcache.py", line 93, in test_hashcache_load
    self.assertEquals(hc.hit_count, 1)
AssertionError: 0 != 1

----------------------------------------------------------------------
Ran 1 test in 10.051s

FAILED (failures=1)
tests failed

[Vincent Ladeuil (vila)]

I've seen similar failures on babune (not for quite some time though) so these tests are known to be time sensitive