← Back to branch summary

~bzr-pqm/bzr/bzr.dev

« back to all changes in this revision

Viewing changes to bzrlib/tests/test_lockdir.py

  • Committer: Ian Clatworthy
  • Date: 2009-01-19 02:24:15 UTC
  • mto: This revision was merged to the branch mainline in revision 3944.
  • Revision ID: ian.clatworthy@canonical.com-20090119022415-mo0mcfeiexfktgwt
apply jam's log --short fix (Ian Clatworthy)

Show diffs side-by-side

added added

removed removed

Lines of Context:
bzrlib/tests/test_lockdir.py
1
 
# Copyright (C) 2006 Canonical Ltd
2
 
 
 
1
# Copyright (C) 2006, 2007, 2008 Canonical Ltd
 
2
#
3
3
# This program is free software; you can redistribute it and/or modify
4
4
# it under the terms of the GNU General Public License as published by
5
5
# the Free Software Foundation; either version 2 of the License, or
6
6
# (at your option) any later version.
7
 
 
 
7
#
8
8
# This program is distributed in the hope that it will be useful,
9
9
# but WITHOUT ANY WARRANTY; without even the implied warranty of
10
10
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
11
11
# GNU General Public License for more details.
12
 
 
 
12
#
13
13
# You should have received a copy of the GNU General Public License
14
14
# along with this program; if not, write to the Free Software
15
15
# Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
17
17
"""Tests for LockDir"""
18
18
 
19
19
from cStringIO import StringIO
20
 
from threading import Thread
 
20
import os
 
21
from threading import Thread, Lock
21
22
import time
22
23
 
23
24
import bzrlib
 
25
from bzrlib import (
 
26
    config,
 
27
    errors,
 
28
    lock,
 
29
    osutils,
 
30
    tests,
 
31
    transport,
 
32
    )
24
33
from bzrlib.errors import (
25
 
        LockBreakMismatch,
26
 
        LockContention, LockError, UnlockableTransport,
27
 
        LockNotHeld, LockBroken
28
 
        )
 
34
    LockBreakMismatch,
 
35
    LockBroken,
 
36
    LockContention,
 
37
    LockError,
 
38
    LockFailed,
 
39
    LockNotHeld,
 
40
    )
29
41
from bzrlib.lockdir import LockDir
30
42
from bzrlib.tests import TestCaseWithTransport
 
43
from bzrlib.trace import note
31
44
 
32
45
# These tests sometimes use threads to test the behaviour of lock files with
33
46
# concurrent actors.  This is not a typical (or necessarily supported) use;
42
55
class TestLockDir(TestCaseWithTransport):
43
56
    """Test LockDir operations"""
44
57
 
 
58
    def logging_report_function(self, fmt, *args):
 
59
        self._logged_reports.append((fmt, args))
 
60
 
 
61
    def setup_log_reporter(self, lock_dir):
 
62
        self._logged_reports = []
 
63
        lock_dir._report_function = self.logging_report_function
 
64
 
45
65
    def test_00_lock_creation(self):
46
66
        """Creation of lock file on a transport"""
47
67
        t = self.get_transport()
89
109
        """Fail to create lock on readonly transport"""
90
110
        t = self.get_readonly_transport()
91
111
        lf = LockDir(t, 'test_lock')
92
 
        self.assertRaises(UnlockableTransport, lf.create)
 
112
        self.assertRaises(LockFailed, lf.create)
93
113
 
94
114
    def test_12_lock_readonly_transport(self):
95
115
        """Fail to lock on readonly transport"""
96
116
        lf = LockDir(self.get_transport(), 'test_lock')
97
117
        lf.create()
98
118
        lf = LockDir(self.get_readonly_transport(), 'test_lock')
99
 
        self.assertRaises(UnlockableTransport, lf.attempt_lock)
 
119
        self.assertRaises(LockFailed, lf.attempt_lock)
100
120
 
101
121
    def test_20_lock_contested(self):
102
122
        """Contention to get a lock"""
156
176
        lf1 = LockDir(t, 'test_lock')
157
177
        lf1.create()
158
178
        lf2 = LockDir(t, 'test_lock')
 
179
        self.setup_log_reporter(lf2)
159
180
        lf1.attempt_lock()
160
181
        try:
161
182
            before = time.time()
168
189
                    "took %f seconds to detect lock contention" % (after - before))
169
190
        finally:
170
191
            lf1.unlock()
 
192
        lock_base = lf2.transport.abspath(lf2.path)
 
193
        self.assertEqual(1, len(self._logged_reports))
 
194
        lock_url = lf2.transport.abspath(lf2.path)
 
195
        self.assertEqual('%s %s\n'
 
196
                         '%s\n%s\n'
 
197
                         'Will continue to try until %s, unless '
 
198
                         'you press Ctrl-C\n'
 
199
                         'If you\'re sure that it\'s not being '
 
200
                         'modified, use bzr break-lock %s',
 
201
                         self._logged_reports[0][0])
 
202
        args = self._logged_reports[0][1]
 
203
        self.assertEqual('Unable to obtain', args[0])
 
204
        self.assertEqual('lock %s' % (lock_base,), args[1])
 
205
        self.assertStartsWith(args[2], 'held by ')
 
206
        self.assertStartsWith(args[3], 'locked ')
 
207
        self.assertEndsWith(args[3], ' ago')
 
208
        self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
171
209
 
172
210
    def test_31_lock_wait_easy(self):
173
211
        """Succeed when waiting on a lock with no contention.
175
213
        t = self.get_transport()
176
214
        lf1 = LockDir(t, 'test_lock')
177
215
        lf1.create()
 
216
        self.setup_log_reporter(lf1)
178
217
        try:
179
218
            before = time.time()
180
219
            lf1.wait_lock(timeout=0.4, poll=0.1)
182
221
            self.assertTrue(after - before <= 1.0)
183
222
        finally:
184
223
            lf1.unlock()
 
224
        self.assertEqual([], self._logged_reports)
185
225
 
186
226
    def test_32_lock_wait_succeed(self):
187
227
        """Succeed when trying to acquire a lock that gets released
189
229
        One thread holds on a lock and then releases it; another 
190
230
        tries to lock it.
191
231
        """
 
232
        # This test sometimes fails like this:
 
233
        # Traceback (most recent call last):
 
234
 
 
235
        #   File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/
 
236
        # test_lockdir.py", line 247, in test_32_lock_wait_succeed
 
237
        #     self.assertEqual(1, len(self._logged_reports))
 
238
        # AssertionError: not equal:
 
239
        # a = 1
 
240
        # b = 0
 
241
        raise tests.TestSkipped("Test fails intermittently")
192
242
        t = self.get_transport()
193
243
        lf1 = LockDir(t, 'test_lock')
194
244
        lf1.create()
201
251
        unlocker.start()
202
252
        try:
203
253
            lf2 = LockDir(t, 'test_lock')
 
254
            self.setup_log_reporter(lf2)
204
255
            before = time.time()
205
256
            # wait and then lock
206
257
            lf2.wait_lock(timeout=0.4, poll=0.1)
209
260
        finally:
210
261
            unlocker.join()
211
262
 
212
 
    def test_33_wait(self):
213
 
        """Succeed when waiting on a lock that gets released
 
263
        # There should be only 1 report, even though it should have to
 
264
        # wait for a while
 
265
        lock_base = lf2.transport.abspath(lf2.path)
 
266
        self.assertEqual(1, len(self._logged_reports))
 
267
        self.assertEqual('%s %s\n'
 
268
                         '%s\n%s\n'
 
269
                         'Will continue to try until %s\n',
 
270
                         self._logged_reports[0][0])
 
271
        args = self._logged_reports[0][1]
 
272
        self.assertEqual('Unable to obtain', args[0])
 
273
        self.assertEqual('lock %s' % (lock_base,), args[1])
 
274
        self.assertStartsWith(args[2], 'held by ')
 
275
        self.assertStartsWith(args[3], 'locked ')
 
276
        self.assertEndsWith(args[3], ' ago')
 
277
        self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
214
278
 
215
 
        The difference from test_32_lock_wait_succeed is that the second 
216
 
        caller does not actually acquire the lock, but just waits for it
217
 
        to be released.  This is done over a readonly transport.
218
 
        """
 
279
    def test_34_lock_write_waits(self):
 
280
        """LockDir.lock_write() will wait for the lock.""" 
 
281
        # the test suite sets the default to 0 to make deadlocks fail fast.
 
282
        # change it for this test, as we want to try a manual deadlock.
 
283
        raise tests.TestSkipped('Timing-sensitive test')
 
284
        bzrlib.lockdir._DEFAULT_TIMEOUT_SECONDS = 300
219
285
        t = self.get_transport()
220
286
        lf1 = LockDir(t, 'test_lock')
221
287
        lf1.create()
227
293
        unlocker = Thread(target=wait_and_unlock)
228
294
        unlocker.start()
229
295
        try:
230
 
            lf2 = LockDir(self.get_readonly_transport(), 'test_lock')
 
296
            lf2 = LockDir(t, 'test_lock')
 
297
            self.setup_log_reporter(lf2)
231
298
            before = time.time()
232
 
            # wait but don't lock
233
 
            lf2.wait(timeout=0.4, poll=0.1)
 
299
            # wait and then lock
 
300
            lf2.lock_write()
234
301
            after = time.time()
235
 
            self.assertTrue(after - before <= 1.0)
236
 
        finally:
237
 
            unlocker.join()
 
302
        finally:
 
303
            unlocker.join()
 
304
 
 
305
        # There should be only 1 report, even though it should have to
 
306
        # wait for a while
 
307
        lock_base = lf2.transport.abspath(lf2.path)
 
308
        self.assertEqual(1, len(self._logged_reports))
 
309
        self.assertEqual('%s %s\n'
 
310
                         '%s\n%s\n'
 
311
                         'Will continue to try until %s\n',
 
312
                         self._logged_reports[0][0])
 
313
        args = self._logged_reports[0][1]
 
314
        self.assertEqual('Unable to obtain', args[0])
 
315
        self.assertEqual('lock %s' % (lock_base,), args[1])
 
316
        self.assertStartsWith(args[2], 'held by ')
 
317
        self.assertStartsWith(args[3], 'locked ')
 
318
        self.assertEndsWith(args[3], ' ago')
 
319
        self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
 
320
 
 
321
    def test_35_wait_lock_changing(self):
 
322
        """LockDir.wait_lock() will report if the lock changes underneath.
 
323
        
 
324
        This is the stages we want to happen:
 
325
 
 
326
        0) Synchronization locks are created and locked.
 
327
        1) Lock1 obtains the lockdir, and releases the 'check' lock.
 
328
        2) Lock2 grabs the 'check' lock, and checks the lockdir.
 
329
           It sees the lockdir is already acquired, reports the fact, 
 
330
           and unsets the 'checked' lock.
 
331
        3) Thread1 blocks on acquiring the 'checked' lock, and then tells
 
332
           Lock1 to release and acquire the lockdir. This resets the 'check'
 
333
           lock.
 
334
        4) Lock2 acquires the 'check' lock, and checks again. It notices
 
335
           that the holder of the lock has changed, and so reports a new 
 
336
           lock holder.
 
337
        5) Thread1 blocks on the 'checked' lock, this time, it completely
 
338
           unlocks the lockdir, allowing Lock2 to acquire the lock.
 
339
        """
 
340
 
 
341
        raise tests.KnownFailure(
 
342
            "timing dependency in lock tests (#213182)")
 
343
 
 
344
        wait_to_check_lock = Lock()
 
345
        wait_until_checked_lock = Lock()
 
346
 
 
347
        wait_to_check_lock.acquire()
 
348
        wait_until_checked_lock.acquire()
 
349
        note('locked check and checked locks')
 
350
 
 
351
        class LockDir1(LockDir):
 
352
            """Use the synchronization points for the first lock."""
 
353
 
 
354
            def attempt_lock(self):
 
355
                # Once we have acquired the lock, it is okay for
 
356
                # the other lock to check it
 
357
                try:
 
358
                    return super(LockDir1, self).attempt_lock()
 
359
                finally:
 
360
                    note('lock1: releasing check lock')
 
361
                    wait_to_check_lock.release()
 
362
 
 
363
        class LockDir2(LockDir):
 
364
            """Use the synchronization points for the second lock."""
 
365
 
 
366
            def attempt_lock(self):
 
367
                note('lock2: waiting for check lock')
 
368
                wait_to_check_lock.acquire()
 
369
                note('lock2: acquired check lock')
 
370
                try:
 
371
                    return super(LockDir2, self).attempt_lock()
 
372
                finally:
 
373
                    note('lock2: releasing checked lock')
 
374
                    wait_until_checked_lock.release()
 
375
 
 
376
        t = self.get_transport()
 
377
        lf1 = LockDir1(t, 'test_lock')
 
378
        lf1.create()
 
379
 
 
380
        lf2 = LockDir2(t, 'test_lock')
 
381
        self.setup_log_reporter(lf2)
 
382
 
 
383
        def wait_and_switch():
 
384
            lf1.attempt_lock()
 
385
            # Block until lock2 has had a chance to check
 
386
            note('lock1: waiting 1 for checked lock')
 
387
            wait_until_checked_lock.acquire()
 
388
            note('lock1: acquired for checked lock')
 
389
            note('lock1: released lockdir')
 
390
            lf1.unlock()
 
391
            note('lock1: acquiring lockdir')
 
392
            # Create a new nonce, so the lock looks different.
 
393
            lf1.nonce = osutils.rand_chars(20)
 
394
            lf1.lock_write()
 
395
            note('lock1: acquired lockdir')
 
396
 
 
397
            # Block until lock2 has peeked again
 
398
            note('lock1: waiting 2 for checked lock')
 
399
            wait_until_checked_lock.acquire()
 
400
            note('lock1: acquired for checked lock')
 
401
            # Now unlock, and let lock 2 grab the lock
 
402
            lf1.unlock()
 
403
            wait_to_check_lock.release()
 
404
 
 
405
        unlocker = Thread(target=wait_and_switch)
 
406
        unlocker.start()
 
407
        try:
 
408
            # Wait and play against the other thread
 
409
            lf2.wait_lock(timeout=20.0, poll=0.01)
 
410
        finally:
 
411
            unlocker.join()
 
412
        lf2.unlock()
 
413
 
 
414
        # There should be 2 reports, because the lock changed
 
415
        lock_base = lf2.transport.abspath(lf2.path)
 
416
        self.assertEqual(2, len(self._logged_reports))
 
417
        lock_url = lf2.transport.abspath(lf2.path)
 
418
        self.assertEqual('%s %s\n'
 
419
                         '%s\n%s\n'
 
420
                         'Will continue to try until %s, unless '
 
421
                         'you press Ctrl-C\n'
 
422
                         'If you\'re sure that it\'s not being '
 
423
                         'modified, use bzr break-lock %s',
 
424
                         self._logged_reports[0][0])
 
425
        args = self._logged_reports[0][1]
 
426
        self.assertEqual('Unable to obtain', args[0])
 
427
        self.assertEqual('lock %s' % (lock_base,), args[1])
 
428
        self.assertStartsWith(args[2], 'held by ')
 
429
        self.assertStartsWith(args[3], 'locked ')
 
430
        self.assertEndsWith(args[3], ' ago')
 
431
        self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
 
432
 
 
433
        self.assertEqual('%s %s\n'
 
434
                         '%s\n%s\n'
 
435
                         'Will continue to try until %s, unless '
 
436
                         'you press Ctrl-C\n'
 
437
                         'If you\'re sure that it\'s not being '
 
438
                         'modified, use bzr break-lock %s',
 
439
                         self._logged_reports[1][0])
 
440
        args = self._logged_reports[1][1]
 
441
        self.assertEqual('Lock owner changed for', args[0])
 
442
        self.assertEqual('lock %s' % (lock_base,), args[1])
 
443
        self.assertStartsWith(args[2], 'held by ')
 
444
        self.assertStartsWith(args[3], 'locked ')
 
445
        self.assertEndsWith(args[3], ' ago')
 
446
        self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
238
447
 
239
448
    def test_40_confirm_easy(self):
240
449
        """Confirm a lock that's already held"""
352
561
            self.assertRaises(LockBroken, ld1.unlock)
353
562
        finally:
354
563
            bzrlib.ui.ui_factory = orig_factory
 
564
 
 
565
    def test_create_missing_base_directory(self):
 
566
        """If LockDir.path doesn't exist, it can be created
 
567
 
 
568
        Some people manually remove the entire lock/ directory trying
 
569
        to unlock a stuck repository/branch/etc. Rather than failing
 
570
        after that, just create the lock directory when needed.
 
571
        """
 
572
        t = self.get_transport()
 
573
        lf1 = LockDir(t, 'test_lock')
 
574
 
 
575
        lf1.create()
 
576
        self.failUnless(t.has('test_lock'))
 
577
 
 
578
        t.rmdir('test_lock')
 
579
        self.failIf(t.has('test_lock'))
 
580
 
 
581
        # This will create 'test_lock' if it needs to
 
582
        lf1.lock_write()
 
583
        self.failUnless(t.has('test_lock'))
 
584
        self.failUnless(t.has('test_lock/held/info'))
 
585
 
 
586
        lf1.unlock()
 
587
        self.failIf(t.has('test_lock/held/info'))
 
588
 
 
589
    def test__format_lock_info(self):
 
590
        ld1 = self.get_lock()
 
591
        ld1.create()
 
592
        ld1.lock_write()
 
593
        try:
 
594
            info_list = ld1._format_lock_info(ld1.peek())
 
595
        finally:
 
596
            ld1.unlock()
 
597
        self.assertEqual('lock %s' % (ld1.transport.abspath(ld1.path),),
 
598
                         info_list[0])
 
599
        self.assertContainsRe(info_list[1],
 
600
                              r'^held by .* on host .* \[process #\d*\]$')
 
601
        self.assertContainsRe(info_list[2], r'locked \d+ seconds? ago$')
 
602
 
 
603
    def test_lock_without_email(self):
 
604
        global_config = config.GlobalConfig()
 
605
        # Intentionally has no email address
 
606
        global_config.set_user_option('email', 'User Identity')
 
607
        ld1 = self.get_lock()
 
608
        ld1.create()
 
609
        ld1.lock_write()
 
610
        ld1.unlock()
 
611
 
 
612
    def test_lock_permission(self):
 
613
        if not osutils.supports_posix_readonly():
 
614
            raise tests.TestSkipped('Cannot induce a permission failure')
 
615
        ld1 = self.get_lock()
 
616
        lock_path = ld1.transport.local_abspath('test_lock')
 
617
        os.mkdir(lock_path)
 
618
        osutils.make_readonly(lock_path)
 
619
        self.assertRaises(errors.LockFailed, ld1.attempt_lock)
 
620
 
 
621
    def test_lock_by_token(self):
 
622
        ld1 = self.get_lock()
 
623
        token = ld1.lock_write()
 
624
        self.assertNotEqual(None, token)
 
625
        ld2 = self.get_lock()
 
626
        t2 = ld2.lock_write(token)
 
627
        self.assertEqual(token, t2)
 
628
 
 
629
    def test_lock_with_buggy_rename(self):
 
630
        # test that lock acquisition handles servers which pretend they
 
631
        # renamed correctly but that actually fail
 
632
        t = transport.get_transport('brokenrename+' + self.get_url())
 
633
        ld1 = LockDir(t, 'test_lock')
 
634
        ld1.create()
 
635
        ld1.attempt_lock()
 
636
        ld2 = LockDir(t, 'test_lock')
 
637
        # we should fail to lock
 
638
        e = self.assertRaises(errors.LockContention, ld2.attempt_lock)
 
639
        # now the original caller should succeed in unlocking
 
640
        ld1.unlock()
 
641
        # and there should be nothing left over
 
642
        self.assertEquals([], t.list_dir('test_lock'))
 
643
 
 
644
    def test_failed_lock_leaves_no_trash(self):
 
645
        # if we fail to acquire the lock, we don't leave pending directories
 
646
        # behind -- https://bugs.launchpad.net/bzr/+bug/109169
 
647
        ld1 = self.get_lock()
 
648
        ld2 = self.get_lock()
 
649
        # should be nothing before we start
 
650
        ld1.create()
 
651
        t = self.get_transport().clone('test_lock')
 
652
        def check_dir(a):
 
653
            self.assertEquals(a, t.list_dir('.'))
 
654
        check_dir([])
 
655
        # when held, that's all we see
 
656
        ld1.attempt_lock()
 
657
        check_dir(['held'])
 
658
        # second guy should fail
 
659
        self.assertRaises(errors.LockContention, ld2.attempt_lock)
 
660
        # no kibble
 
661
        check_dir(['held'])
 
662
 
 
663
    def record_hook(self, result):
 
664
        self._calls.append(result)
 
665
 
 
666
    def reset_hooks(self):
 
667
        self._old_hooks = lock.Lock.hooks
 
668
        self.addCleanup(self.restore_hooks)
 
669
        lock.Lock.hooks = lock.LockHooks()
 
670
 
 
671
    def restore_hooks(self):
 
672
        lock.Lock.hooks = self._old_hooks
 
673
 
 
674
    def test_LockDir_acquired_success(self):
 
675
        # the LockDir.lock_acquired hook fires when a lock is acquired.
 
676
        self._calls = []
 
677
        self.reset_hooks()
 
678
        LockDir.hooks.install_named_hook('lock_acquired',
 
679
            self.record_hook, 'record_hook')
 
680
        ld = self.get_lock()
 
681
        ld.create()
 
682
        self.assertEqual([], self._calls)
 
683
        result = ld.attempt_lock()
 
684
        lock_path = ld.transport.abspath(ld.path)
 
685
        self.assertEqual([lock.LockResult(lock_path, result)], self._calls)
 
686
        ld.unlock()
 
687
        self.assertEqual([lock.LockResult(lock_path, result)], self._calls)
 
688
 
 
689
    def test_LockDir_acquired_fail(self):
 
690
        # the LockDir.lock_acquired hook does not fire on failure.
 
691
        self._calls = []
 
692
        self.reset_hooks()
 
693
        ld = self.get_lock()
 
694
        ld.create()
 
695
        ld2 = self.get_lock()
 
696
        ld2.attempt_lock()
 
697
        # install a lock hook now, when the disk lock is locked
 
698
        LockDir.hooks.install_named_hook('lock_acquired',
 
699
            self.record_hook, 'record_hook')
 
700
        self.assertRaises(errors.LockContention, ld.attempt_lock)
 
701
        self.assertEqual([], self._calls)
 
702
        ld2.unlock()
 
703
        self.assertEqual([], self._calls)
 
704
 
 
705
    def test_LockDir_released_success(self):
 
706
        # the LockDir.lock_released hook fires when a lock is acquired.
 
707
        self._calls = []
 
708
        self.reset_hooks()
 
709
        LockDir.hooks.install_named_hook('lock_released',
 
710
            self.record_hook, 'record_hook')
 
711
        ld = self.get_lock()
 
712
        ld.create()
 
713
        self.assertEqual([], self._calls)
 
714
        result = ld.attempt_lock()
 
715
        self.assertEqual([], self._calls)
 
716
        ld.unlock()
 
717
        lock_path = ld.transport.abspath(ld.path)
 
718
        self.assertEqual([lock.LockResult(lock_path, result)], self._calls)
 
719
 
 
720
    def test_LockDir_released_fail(self):
 
721
        # the LockDir.lock_released hook does not fire on failure.
 
722
        self._calls = []
 
723
        self.reset_hooks()
 
724
        ld = self.get_lock()
 
725
        ld.create()
 
726
        ld2 = self.get_lock()
 
727
        ld.attempt_lock()
 
728
        ld2.force_break(ld2.peek())
 
729
        LockDir.hooks.install_named_hook('lock_released',
 
730
            self.record_hook, 'record_hook')
 
731
        self.assertRaises(LockBroken, ld.unlock)
 
732
        self.assertEqual([], self._calls)