← 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: Jelmer Vernooij
  • Date: 2010-04-30 11:03:59 UTC
  • mto: This revision was merged to the branch mainline in revision 5197.
  • Revision ID: jelmer@samba.org-20100430110359-ow3e3grh7sxy93pa
Remove more unused imports.

Show diffs side-by-side

added added

removed removed

Lines of Context:
bzrlib/tests/test_lockdir.py
1
 
# Copyright (C) 2006-2011 Canonical Ltd
 
1
# Copyright (C) 2006-2010 Canonical Ltd
2
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
16
16
 
17
17
"""Tests for LockDir"""
18
18
 
 
19
from cStringIO import StringIO
19
20
import os
 
21
from threading import Thread, Lock
20
22
import time
21
23
 
22
24
import bzrlib
32
34
    LockBreakMismatch,
33
35
    LockBroken,
34
36
    LockContention,
 
37
    LockError,
35
38
    LockFailed,
36
39
    LockNotHeld,
37
40
    )
38
41
from bzrlib.lockdir import LockDir
39
 
from bzrlib.tests import (
40
 
    features,
41
 
    TestCaseWithTransport,
42
 
    )
 
42
from bzrlib.tests import TestCaseWithTransport
43
43
from bzrlib.trace import note
44
44
 
 
45
# These tests sometimes use threads to test the behaviour of lock files with
 
46
# concurrent actors.  This is not a typical (or necessarily supported) use;
 
47
# they're really meant for guarding between processes.
 
48
 
45
49
# These tests are run on the default transport provided by the test framework
46
50
# (typically a local disk transport).  That can be changed by the --transport
47
51
# option to bzr selftest.  The required properties of the transport
187
191
                    "took %f seconds to detect lock contention" % (after - before))
188
192
        finally:
189
193
            lf1.unlock()
 
194
        lock_base = lf2.transport.abspath(lf2.path)
190
195
        self.assertEqual(1, len(self._logged_reports))
191
 
        self.assertEqual(self._logged_reports[0][0],
192
 
            '%s lock %s held by %s\n'
193
 
            'at %s [process #%s], acquired %s.\n'
194
 
            'Will continue to try until %s, unless '
195
 
            'you press Ctrl-C.\n'
196
 
            'See "bzr help break-lock" for more.')
197
 
        start, lock_url, user, hostname, pid, time_ago, deadline_str = \
198
 
            self._logged_reports[0][1]
199
 
        self.assertEqual(start, u'Unable to obtain')
200
 
        self.assertEqual(user, u'jrandom@example.com')
201
 
        # skip hostname
202
 
        self.assertContainsRe(pid, r'\d+')
203
 
        self.assertContainsRe(time_ago, r'.* ago')
204
 
        self.assertContainsRe(deadline_str, r'\d{2}:\d{2}:\d{2}')
 
196
        lock_url = lf2.transport.abspath(lf2.path)
 
197
        self.assertEqual('%s %s\n'
 
198
                         '%s\n%s\n'
 
199
                         'Will continue to try until %s, unless '
 
200
                         'you press Ctrl-C.\n'
 
201
                         'See "bzr help break-lock" for more.',
 
202
                         self._logged_reports[0][0])
 
203
        args = self._logged_reports[0][1]
 
204
        self.assertEqual('Unable to obtain', args[0])
 
205
        self.assertEqual('lock %s' % (lock_base,), args[1])
 
206
        self.assertStartsWith(args[2], 'held by ')
 
207
        self.assertStartsWith(args[3], 'locked ')
 
208
        self.assertEndsWith(args[3], ' ago')
 
209
        self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
205
210
 
206
211
    def test_31_lock_wait_easy(self):
207
212
        """Succeed when waiting on a lock with no contention.
219
224
            lf1.unlock()
220
225
        self.assertEqual([], self._logged_reports)
221
226
 
 
227
    def test_32_lock_wait_succeed(self):
 
228
        """Succeed when trying to acquire a lock that gets released
 
229
 
 
230
        One thread holds on a lock and then releases it; another
 
231
        tries to lock it.
 
232
        """
 
233
        # This test sometimes fails like this:
 
234
        # Traceback (most recent call last):
 
235
 
 
236
        #   File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/
 
237
        # test_lockdir.py", line 247, in test_32_lock_wait_succeed
 
238
        #     self.assertEqual(1, len(self._logged_reports))
 
239
        # AssertionError: not equal:
 
240
        # a = 1
 
241
        # b = 0
 
242
        raise tests.TestSkipped("Test fails intermittently")
 
243
        t = self.get_transport()
 
244
        lf1 = LockDir(t, 'test_lock')
 
245
        lf1.create()
 
246
        lf1.attempt_lock()
 
247
 
 
248
        def wait_and_unlock():
 
249
            time.sleep(0.1)
 
250
            lf1.unlock()
 
251
        unlocker = Thread(target=wait_and_unlock)
 
252
        unlocker.start()
 
253
        try:
 
254
            lf2 = LockDir(t, 'test_lock')
 
255
            self.setup_log_reporter(lf2)
 
256
            before = time.time()
 
257
            # wait and then lock
 
258
            lf2.wait_lock(timeout=0.4, poll=0.1)
 
259
            after = time.time()
 
260
            self.assertTrue(after - before <= 1.0)
 
261
        finally:
 
262
            unlocker.join()
 
263
 
 
264
        # There should be only 1 report, even though it should have to
 
265
        # wait for a while
 
266
        lock_base = lf2.transport.abspath(lf2.path)
 
267
        self.assertEqual(1, len(self._logged_reports))
 
268
        self.assertEqual('%s %s\n'
 
269
                         '%s\n%s\n'
 
270
                         'Will continue to try until %s\n',
 
271
                         self._logged_reports[0][0])
 
272
        args = self._logged_reports[0][1]
 
273
        self.assertEqual('Unable to obtain', args[0])
 
274
        self.assertEqual('lock %s' % (lock_base,), args[1])
 
275
        self.assertStartsWith(args[2], 'held by ')
 
276
        self.assertStartsWith(args[3], 'locked ')
 
277
        self.assertEndsWith(args[3], ' ago')
 
278
        self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
 
279
 
 
280
    def test_34_lock_write_waits(self):
 
281
        """LockDir.lock_write() will wait for the lock."""
 
282
        # the test suite sets the default to 0 to make deadlocks fail fast.
 
283
        # change it for this test, as we want to try a manual deadlock.
 
284
        raise tests.TestSkipped('Timing-sensitive test')
 
285
        bzrlib.lockdir._DEFAULT_TIMEOUT_SECONDS = 300
 
286
        t = self.get_transport()
 
287
        lf1 = LockDir(t, 'test_lock')
 
288
        lf1.create()
 
289
        lf1.attempt_lock()
 
290
 
 
291
        def wait_and_unlock():
 
292
            time.sleep(0.1)
 
293
            lf1.unlock()
 
294
        unlocker = Thread(target=wait_and_unlock)
 
295
        unlocker.start()
 
296
        try:
 
297
            lf2 = LockDir(t, 'test_lock')
 
298
            self.setup_log_reporter(lf2)
 
299
            before = time.time()
 
300
            # wait and then lock
 
301
            lf2.lock_write()
 
302
            after = time.time()
 
303
        finally:
 
304
            unlocker.join()
 
305
 
 
306
        # There should be only 1 report, even though it should have to
 
307
        # wait for a while
 
308
        lock_base = lf2.transport.abspath(lf2.path)
 
309
        self.assertEqual(1, len(self._logged_reports))
 
310
        self.assertEqual('%s %s\n'
 
311
                         '%s\n%s\n'
 
312
                         'Will continue to try until %s\n',
 
313
                         self._logged_reports[0][0])
 
314
        args = self._logged_reports[0][1]
 
315
        self.assertEqual('Unable to obtain', args[0])
 
316
        self.assertEqual('lock %s' % (lock_base,), args[1])
 
317
        self.assertStartsWith(args[2], 'held by ')
 
318
        self.assertStartsWith(args[3], 'locked ')
 
319
        self.assertEndsWith(args[3], ' ago')
 
320
        self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
 
321
 
 
322
    def test_35_wait_lock_changing(self):
 
323
        """LockDir.wait_lock() will report if the lock changes underneath.
 
324
 
 
325
        This is the stages we want to happen:
 
326
 
 
327
        0) Synchronization locks are created and locked.
 
328
        1) Lock1 obtains the lockdir, and releases the 'check' lock.
 
329
        2) Lock2 grabs the 'check' lock, and checks the lockdir.
 
330
           It sees the lockdir is already acquired, reports the fact,
 
331
           and unsets the 'checked' lock.
 
332
        3) Thread1 blocks on acquiring the 'checked' lock, and then tells
 
333
           Lock1 to release and acquire the lockdir. This resets the 'check'
 
334
           lock.
 
335
        4) Lock2 acquires the 'check' lock, and checks again. It notices
 
336
           that the holder of the lock has changed, and so reports a new
 
337
           lock holder.
 
338
        5) Thread1 blocks on the 'checked' lock, this time, it completely
 
339
           unlocks the lockdir, allowing Lock2 to acquire the lock.
 
340
        """
 
341
 
 
342
        raise tests.KnownFailure(
 
343
            "timing dependency in lock tests (#213182)")
 
344
 
 
345
        wait_to_check_lock = Lock()
 
346
        wait_until_checked_lock = Lock()
 
347
 
 
348
        wait_to_check_lock.acquire()
 
349
        wait_until_checked_lock.acquire()
 
350
        note('locked check and checked locks')
 
351
 
 
352
        class LockDir1(LockDir):
 
353
            """Use the synchronization points for the first lock."""
 
354
 
 
355
            def attempt_lock(self):
 
356
                # Once we have acquired the lock, it is okay for
 
357
                # the other lock to check it
 
358
                try:
 
359
                    return super(LockDir1, self).attempt_lock()
 
360
                finally:
 
361
                    note('lock1: releasing check lock')
 
362
                    wait_to_check_lock.release()
 
363
 
 
364
        class LockDir2(LockDir):
 
365
            """Use the synchronization points for the second lock."""
 
366
 
 
367
            def attempt_lock(self):
 
368
                note('lock2: waiting for check lock')
 
369
                wait_to_check_lock.acquire()
 
370
                note('lock2: acquired check lock')
 
371
                try:
 
372
                    return super(LockDir2, self).attempt_lock()
 
373
                finally:
 
374
                    note('lock2: releasing checked lock')
 
375
                    wait_until_checked_lock.release()
 
376
 
 
377
        t = self.get_transport()
 
378
        lf1 = LockDir1(t, 'test_lock')
 
379
        lf1.create()
 
380
 
 
381
        lf2 = LockDir2(t, 'test_lock')
 
382
        self.setup_log_reporter(lf2)
 
383
 
 
384
        def wait_and_switch():
 
385
            lf1.attempt_lock()
 
386
            # Block until lock2 has had a chance to check
 
387
            note('lock1: waiting 1 for checked lock')
 
388
            wait_until_checked_lock.acquire()
 
389
            note('lock1: acquired for checked lock')
 
390
            note('lock1: released lockdir')
 
391
            lf1.unlock()
 
392
            note('lock1: acquiring lockdir')
 
393
            # Create a new nonce, so the lock looks different.
 
394
            lf1.nonce = osutils.rand_chars(20)
 
395
            lf1.lock_write()
 
396
            note('lock1: acquired lockdir')
 
397
 
 
398
            # Block until lock2 has peeked again
 
399
            note('lock1: waiting 2 for checked lock')
 
400
            wait_until_checked_lock.acquire()
 
401
            note('lock1: acquired for checked lock')
 
402
            # Now unlock, and let lock 2 grab the lock
 
403
            lf1.unlock()
 
404
            wait_to_check_lock.release()
 
405
 
 
406
        unlocker = Thread(target=wait_and_switch)
 
407
        unlocker.start()
 
408
        try:
 
409
            # Wait and play against the other thread
 
410
            lf2.wait_lock(timeout=20.0, poll=0.01)
 
411
        finally:
 
412
            unlocker.join()
 
413
        lf2.unlock()
 
414
 
 
415
        # There should be 2 reports, because the lock changed
 
416
        lock_base = lf2.transport.abspath(lf2.path)
 
417
        self.assertEqual(2, len(self._logged_reports))
 
418
        lock_url = lf2.transport.abspath(lf2.path)
 
419
        self.assertEqual('%s %s\n'
 
420
                         '%s\n%s\n'
 
421
                         'Will continue to try until %s, unless '
 
422
                         'you press Ctrl-C.\n'
 
423
                         'See "bzr help break-lock" for more.',
 
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
                         'See "bzr help break-lock" for more.',
 
438
                         self._logged_reports[1][0])
 
439
        args = self._logged_reports[1][1]
 
440
        self.assertEqual('Lock owner changed for', args[0])
 
441
        self.assertEqual('lock %s' % (lock_base,), args[1])
 
442
        self.assertStartsWith(args[2], 'held by ')
 
443
        self.assertStartsWith(args[3], 'locked ')
 
444
        self.assertEndsWith(args[3], ' ago')
 
445
        self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
 
446
 
222
447
    def test_40_confirm_easy(self):
223
448
        """Confirm a lock that's already held"""
224
449
        t = self.get_transport()
340
565
        finally:
341
566
            bzrlib.ui.ui_factory = orig_factory
342
567
 
343
 
    def test_break_lock_corrupt_info(self):
344
 
        """break_lock works even if the info file is corrupt (and tells the UI
345
 
        that it is corrupt).
346
 
        """
347
 
        ld = self.get_lock()
348
 
        ld2 = self.get_lock()
349
 
        ld.create()
350
 
        ld.lock_write()
351
 
        ld.transport.put_bytes_non_atomic('test_lock/held/info', '\0')
352
 
        class LoggingUIFactory(bzrlib.ui.SilentUIFactory):
353
 
            def __init__(self):
354
 
                self.prompts = []
355
 
            def get_boolean(self, prompt):
356
 
                self.prompts.append(('boolean', prompt))
357
 
                return True
358
 
        ui = LoggingUIFactory()
359
 
        self.overrideAttr(bzrlib.ui, 'ui_factory', ui)
360
 
        ld2.break_lock()
361
 
        self.assertLength(1, ui.prompts)
362
 
        self.assertEqual('boolean', ui.prompts[0][0])
363
 
        self.assertStartsWith(ui.prompts[0][1], 'Break (corrupt LockDir')
364
 
        self.assertRaises(LockBroken, ld.unlock)
365
 
 
366
 
    def test_break_lock_missing_info(self):
367
 
        """break_lock works even if the info file is missing (and tells the UI
368
 
        that it is corrupt).
369
 
        """
370
 
        ld = self.get_lock()
371
 
        ld2 = self.get_lock()
372
 
        ld.create()
373
 
        ld.lock_write()
374
 
        ld.transport.delete('test_lock/held/info')
375
 
        class LoggingUIFactory(bzrlib.ui.SilentUIFactory):
376
 
            def __init__(self):
377
 
                self.prompts = []
378
 
            def get_boolean(self, prompt):
379
 
                self.prompts.append(('boolean', prompt))
380
 
                return True
381
 
        ui = LoggingUIFactory()
382
 
        orig_factory = bzrlib.ui.ui_factory
383
 
        bzrlib.ui.ui_factory = ui
384
 
        try:
385
 
            ld2.break_lock()
386
 
            self.assertRaises(LockBroken, ld.unlock)
387
 
            self.assertLength(0, ui.prompts)
388
 
        finally:
389
 
            bzrlib.ui.ui_factory = orig_factory
390
 
        # Suppress warnings due to ld not being unlocked
391
 
        # XXX: if lock_broken hook was invoked in this case, this hack would
392
 
        # not be necessary.  - Andrew Bennetts, 2010-09-06.
393
 
        del self._lock_actions[:]
394
 
 
395
568
    def test_create_missing_base_directory(self):
396
569
        """If LockDir.path doesn't exist, it can be created
397
570
 
403
576
        lf1 = LockDir(t, 'test_lock')
404
577
 
405
578
        lf1.create()
406
 
        self.assertTrue(t.has('test_lock'))
 
579
        self.failUnless(t.has('test_lock'))
407
580
 
408
581
        t.rmdir('test_lock')
409
 
        self.assertFalse(t.has('test_lock'))
 
582
        self.failIf(t.has('test_lock'))
410
583
 
411
584
        # This will create 'test_lock' if it needs to
412
585
        lf1.lock_write()
413
 
        self.assertTrue(t.has('test_lock'))
414
 
        self.assertTrue(t.has('test_lock/held/info'))
 
586
        self.failUnless(t.has('test_lock'))
 
587
        self.failUnless(t.has('test_lock/held/info'))
415
588
 
416
589
        lf1.unlock()
417
 
        self.assertFalse(t.has('test_lock/held/info'))
 
590
        self.failIf(t.has('test_lock/held/info'))
418
591
 
419
592
    def test__format_lock_info(self):
420
593
        ld1 = self.get_lock()
424
597
            info_list = ld1._format_lock_info(ld1.peek())
425
598
        finally:
426
599
            ld1.unlock()
427
 
        self.assertEqual(info_list[0], u'jrandom@example.com')
428
 
        # info_list[1] is hostname. we skip this.
429
 
        self.assertContainsRe(info_list[2], '^\d+$') # pid
430
 
        self.assertContainsRe(info_list[3], r'^\d+ seconds? ago$') # time_ago
 
600
        self.assertEqual('lock %s' % (ld1.transport.abspath(ld1.path),),
 
601
                         info_list[0])
 
602
        self.assertContainsRe(info_list[1],
 
603
                              r'^held by .* on host .* \[process #\d*\]$')
 
604
        self.assertContainsRe(info_list[2], r'locked \d+ seconds? ago$')
431
605
 
432
606
    def test_lock_without_email(self):
433
607
        global_config = config.GlobalConfig()
439
613
        ld1.unlock()
440
614
 
441
615
    def test_lock_permission(self):
442
 
        self.requireFeature(features.not_running_as_root)
443
616
        if not osutils.supports_posix_readonly():
444
617
            raise tests.TestSkipped('Cannot induce a permission failure')
445
618
        ld1 = self.get_lock()
496
669
    def test_no_lockdir_info(self):
497
670
        """We can cope with empty info files."""
498
671
        # This seems like a fairly common failure case - see
499
 
        # <https://bugs.launchpad.net/bzr/+bug/185103> and all its dupes.
 
672
        # <https://bugs.edge.launchpad.net/bzr/+bug/185103> and all its dupes.
500
673
        # Processes are often interrupted after opening the file
501
674
        # before the actual contents are committed.
502
675
        t = self.get_transport()
507
680
        info = lf.peek()
508
681
        formatted_info = lf._format_lock_info(info)
509
682
        self.assertEquals(
510
 
            ['<unknown>', '<unknown>', '<unknown>', '(unknown)'],
 
683
            ['lock %s' % t.abspath('test_lock'),
 
684
             'held by <unknown> on host <unknown> [process #<unknown>]',
 
685
             'locked (unknown)'],
511
686
            formatted_info)
512
687
 
513
 
    def test_corrupt_lockdir_info(self):
514
 
        """We can cope with corrupt (and thus unparseable) info files."""
515
 
        # This seems like a fairly common failure case too - see
516
 
        # <https://bugs.launchpad.net/bzr/+bug/619872> for instance.
517
 
        # In particular some systems tend to fill recently created files with
518
 
        # nul bytes after recovering from a system crash.
519
 
        t = self.get_transport()
520
 
        t.mkdir('test_lock')
521
 
        t.mkdir('test_lock/held')
522
 
        t.put_bytes('test_lock/held/info', '\0')
523
 
        lf = LockDir(t, 'test_lock')
524
 
        self.assertRaises(errors.LockCorrupt, lf.peek)
525
 
        # Currently attempt_lock gives LockContention, but LockCorrupt would be
526
 
        # a reasonable result too.
527
 
        self.assertRaises(
528
 
            (errors.LockCorrupt, errors.LockContention), lf.attempt_lock)
529
 
        self.assertRaises(errors.LockCorrupt, lf.validate_token, 'fake token')
530
 
 
531
 
    def test_missing_lockdir_info(self):
532
 
        """We can cope with absent info files."""
533
 
        t = self.get_transport()
534
 
        t.mkdir('test_lock')
535
 
        t.mkdir('test_lock/held')
536
 
        lf = LockDir(t, 'test_lock')
537
 
        # In this case we expect the 'not held' result from peek, because peek
538
 
        # cannot be expected to notice that there is a 'held' directory with no
539
 
        # 'info' file.
540
 
        self.assertEqual(None, lf.peek())
541
 
        # And lock/unlock may work or give LockContention (but not any other
542
 
        # error).
543
 
        try:
544
 
            lf.attempt_lock()
545
 
        except LockContention:
546
 
            # LockContention is ok, and expected on Windows
547
 
            pass
548
 
        else:
549
 
            # no error is ok, and expected on POSIX (because POSIX allows
550
 
            # os.rename over an empty directory).
551
 
            lf.unlock()
552
 
        # Currently raises TokenMismatch, but LockCorrupt would be reasonable
553
 
        # too.
554
 
        self.assertRaises(
555
 
            (errors.TokenMismatch, errors.LockCorrupt),
556
 
            lf.validate_token, 'fake token')
557
 
 
558
688
 
559
689
class TestLockDirHooks(TestCaseWithTransport):
560
690