191
188
# it should only take about 0.4 seconds, but we allow more time in
192
189
# case the machine is heavily loaded
193
190
self.assertTrue(after - before <= 8.0,
194
"took %f seconds to detect lock contention" % (after - before))
191
"took %f seconds to detect lock contention" % (after - before))
194
lock_base = lf2.transport.abspath(lf2.path)
197
195
self.assertEqual(1, len(self._logged_reports))
198
self.assertContainsRe(self._logged_reports[0][0],
199
r'Unable to obtain lock .* held by jrandom@example\.com on .*'
200
r' \(process #\d+\), acquired .* ago\.\n'
201
r'Will continue to try until \d{2}:\d{2}:\d{2}, unless '
202
r'you press Ctrl-C.\n'
203
r'See "bzr help break-lock" for more.')
196
lock_url = lf2.transport.abspath(lf2.path)
197
self.assertEqual('%s %s\n'
199
'Will continue to try until %s, unless '
201
'If you\'re sure that it\'s not being '
202
'modified, use bzr break-lock %s',
203
self._logged_reports[0][0])
204
args = self._logged_reports[0][1]
205
self.assertEqual('Unable to obtain', args[0])
206
self.assertEqual('lock %s' % (lock_base,), args[1])
207
self.assertStartsWith(args[2], 'held by ')
208
self.assertStartsWith(args[3], 'locked ')
209
self.assertEndsWith(args[3], ' ago')
210
self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
205
212
def test_31_lock_wait_easy(self):
206
213
"""Succeed when waiting on a lock with no contention.
219
226
self.assertEqual([], self._logged_reports)
228
def test_32_lock_wait_succeed(self):
229
"""Succeed when trying to acquire a lock that gets released
231
One thread holds on a lock and then releases it; another
234
# This test sometimes fails like this:
235
# Traceback (most recent call last):
237
# File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/
238
# test_lockdir.py", line 247, in test_32_lock_wait_succeed
239
# self.assertEqual(1, len(self._logged_reports))
240
# AssertionError: not equal:
243
raise tests.TestSkipped("Test fails intermittently")
244
t = self.get_transport()
245
lf1 = LockDir(t, 'test_lock')
249
def wait_and_unlock():
252
unlocker = Thread(target=wait_and_unlock)
255
lf2 = LockDir(t, 'test_lock')
256
self.setup_log_reporter(lf2)
259
lf2.wait_lock(timeout=0.4, poll=0.1)
261
self.assertTrue(after - before <= 1.0)
265
# There should be only 1 report, even though it should have to
267
lock_base = lf2.transport.abspath(lf2.path)
268
self.assertEqual(1, len(self._logged_reports))
269
self.assertEqual('%s %s\n'
271
'Will continue to try until %s\n',
272
self._logged_reports[0][0])
273
args = self._logged_reports[0][1]
274
self.assertEqual('Unable to obtain', args[0])
275
self.assertEqual('lock %s' % (lock_base,), args[1])
276
self.assertStartsWith(args[2], 'held by ')
277
self.assertStartsWith(args[3], 'locked ')
278
self.assertEndsWith(args[3], ' ago')
279
self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
281
def test_34_lock_write_waits(self):
282
"""LockDir.lock_write() will wait for the lock."""
283
# the test suite sets the default to 0 to make deadlocks fail fast.
284
# change it for this test, as we want to try a manual deadlock.
285
raise tests.TestSkipped('Timing-sensitive test')
286
bzrlib.lockdir._DEFAULT_TIMEOUT_SECONDS = 300
287
t = self.get_transport()
288
lf1 = LockDir(t, 'test_lock')
292
def wait_and_unlock():
295
unlocker = Thread(target=wait_and_unlock)
298
lf2 = LockDir(t, 'test_lock')
299
self.setup_log_reporter(lf2)
307
# There should be only 1 report, even though it should have to
309
lock_base = lf2.transport.abspath(lf2.path)
310
self.assertEqual(1, len(self._logged_reports))
311
self.assertEqual('%s %s\n'
313
'Will continue to try until %s\n',
314
self._logged_reports[0][0])
315
args = self._logged_reports[0][1]
316
self.assertEqual('Unable to obtain', args[0])
317
self.assertEqual('lock %s' % (lock_base,), args[1])
318
self.assertStartsWith(args[2], 'held by ')
319
self.assertStartsWith(args[3], 'locked ')
320
self.assertEndsWith(args[3], ' ago')
321
self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
323
def test_35_wait_lock_changing(self):
324
"""LockDir.wait_lock() will report if the lock changes underneath.
326
This is the stages we want to happen:
328
0) Synchronization locks are created and locked.
329
1) Lock1 obtains the lockdir, and releases the 'check' lock.
330
2) Lock2 grabs the 'check' lock, and checks the lockdir.
331
It sees the lockdir is already acquired, reports the fact,
332
and unsets the 'checked' lock.
333
3) Thread1 blocks on acquiring the 'checked' lock, and then tells
334
Lock1 to release and acquire the lockdir. This resets the 'check'
336
4) Lock2 acquires the 'check' lock, and checks again. It notices
337
that the holder of the lock has changed, and so reports a new
339
5) Thread1 blocks on the 'checked' lock, this time, it completely
340
unlocks the lockdir, allowing Lock2 to acquire the lock.
343
raise tests.KnownFailure(
344
"timing dependency in lock tests (#213182)")
346
wait_to_check_lock = Lock()
347
wait_until_checked_lock = Lock()
349
wait_to_check_lock.acquire()
350
wait_until_checked_lock.acquire()
351
note('locked check and checked locks')
353
class LockDir1(LockDir):
354
"""Use the synchronization points for the first lock."""
356
def attempt_lock(self):
357
# Once we have acquired the lock, it is okay for
358
# the other lock to check it
360
return super(LockDir1, self).attempt_lock()
362
note('lock1: releasing check lock')
363
wait_to_check_lock.release()
365
class LockDir2(LockDir):
366
"""Use the synchronization points for the second lock."""
368
def attempt_lock(self):
369
note('lock2: waiting for check lock')
370
wait_to_check_lock.acquire()
371
note('lock2: acquired check lock')
373
return super(LockDir2, self).attempt_lock()
375
note('lock2: releasing checked lock')
376
wait_until_checked_lock.release()
378
t = self.get_transport()
379
lf1 = LockDir1(t, 'test_lock')
382
lf2 = LockDir2(t, 'test_lock')
383
self.setup_log_reporter(lf2)
385
def wait_and_switch():
387
# Block until lock2 has had a chance to check
388
note('lock1: waiting 1 for checked lock')
389
wait_until_checked_lock.acquire()
390
note('lock1: acquired for checked lock')
391
note('lock1: released lockdir')
393
note('lock1: acquiring lockdir')
394
# Create a new nonce, so the lock looks different.
395
lf1.nonce = osutils.rand_chars(20)
397
note('lock1: acquired lockdir')
399
# Block until lock2 has peeked again
400
note('lock1: waiting 2 for checked lock')
401
wait_until_checked_lock.acquire()
402
note('lock1: acquired for checked lock')
403
# Now unlock, and let lock 2 grab the lock
405
wait_to_check_lock.release()
407
unlocker = Thread(target=wait_and_switch)
410
# Wait and play against the other thread
411
lf2.wait_lock(timeout=20.0, poll=0.01)
416
# There should be 2 reports, because the lock changed
417
lock_base = lf2.transport.abspath(lf2.path)
418
self.assertEqual(2, len(self._logged_reports))
419
lock_url = lf2.transport.abspath(lf2.path)
420
self.assertEqual('%s %s\n'
422
'Will continue to try until %s, unless '
424
'If you\'re sure that it\'s not being '
425
'modified, use bzr break-lock %s',
426
self._logged_reports[0][0])
427
args = self._logged_reports[0][1]
428
self.assertEqual('Unable to obtain', args[0])
429
self.assertEqual('lock %s' % (lock_base,), args[1])
430
self.assertStartsWith(args[2], 'held by ')
431
self.assertStartsWith(args[3], 'locked ')
432
self.assertEndsWith(args[3], ' ago')
433
self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
435
self.assertEqual('%s %s\n'
437
'Will continue to try until %s, unless '
439
'If you\'re sure that it\'s not being '
440
'modified, use bzr break-lock %s',
441
self._logged_reports[1][0])
442
args = self._logged_reports[1][1]
443
self.assertEqual('Lock owner changed for', args[0])
444
self.assertEqual('lock %s' % (lock_base,), args[1])
445
self.assertStartsWith(args[2], 'held by ')
446
self.assertStartsWith(args[3], 'locked ')
447
self.assertEndsWith(args[3], ' ago')
448
self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
221
450
def test_40_confirm_easy(self):
222
451
"""Confirm a lock that's already held"""
223
452
t = self.get_transport()
340
569
bzrlib.ui.ui_factory = orig_factory
342
def test_break_lock_corrupt_info(self):
343
"""break_lock works even if the info file is corrupt (and tells the UI
347
ld2 = self.get_lock()
350
ld.transport.put_bytes_non_atomic('test_lock/held/info', '\0')
352
class LoggingUIFactory(bzrlib.ui.SilentUIFactory):
356
def get_boolean(self, prompt):
357
self.prompts.append(('boolean', prompt))
360
ui = LoggingUIFactory()
361
self.overrideAttr(bzrlib.ui, 'ui_factory', ui)
363
self.assertLength(1, ui.prompts)
364
self.assertEqual('boolean', ui.prompts[0][0])
365
self.assertStartsWith(ui.prompts[0][1], 'Break (corrupt LockDir')
366
self.assertRaises(LockBroken, ld.unlock)
368
def test_break_lock_missing_info(self):
369
"""break_lock works even if the info file is missing (and tells the UI
373
ld2 = self.get_lock()
376
ld.transport.delete('test_lock/held/info')
378
class LoggingUIFactory(bzrlib.ui.SilentUIFactory):
382
def get_boolean(self, prompt):
383
self.prompts.append(('boolean', prompt))
386
ui = LoggingUIFactory()
387
orig_factory = bzrlib.ui.ui_factory
388
bzrlib.ui.ui_factory = ui
391
self.assertRaises(LockBroken, ld.unlock)
392
self.assertLength(0, ui.prompts)
394
bzrlib.ui.ui_factory = orig_factory
395
# Suppress warnings due to ld not being unlocked
396
# XXX: if lock_broken hook was invoked in this case, this hack would
397
# not be necessary. - Andrew Bennetts, 2010-09-06.
398
del self._lock_actions[:]
400
571
def test_create_missing_base_directory(self):
401
572
"""If LockDir.path doesn't exist, it can be created
500
670
check_dir(['held'])
502
def test_no_lockdir_info(self):
503
"""We can cope with empty info files."""
504
# This seems like a fairly common failure case - see
505
# <https://bugs.launchpad.net/bzr/+bug/185103> and all its dupes.
506
# Processes are often interrupted after opening the file
507
# before the actual contents are committed.
508
t = self.get_transport()
510
t.mkdir('test_lock/held')
511
t.put_bytes('test_lock/held/info', '')
512
lf = LockDir(t, 'test_lock')
514
formatted_info = info.to_readable_dict()
516
dict(user='<unknown>', hostname='<unknown>', pid='<unknown>',
517
time_ago='(unknown)'),
520
def test_corrupt_lockdir_info(self):
521
"""We can cope with corrupt (and thus unparseable) info files."""
522
# This seems like a fairly common failure case too - see
523
# <https://bugs.launchpad.net/bzr/+bug/619872> for instance.
524
# In particular some systems tend to fill recently created files with
525
# nul bytes after recovering from a system crash.
526
t = self.get_transport()
528
t.mkdir('test_lock/held')
529
t.put_bytes('test_lock/held/info', '\0')
530
lf = LockDir(t, 'test_lock')
531
self.assertRaises(errors.LockCorrupt, lf.peek)
532
# Currently attempt_lock gives LockContention, but LockCorrupt would be
533
# a reasonable result too.
535
(errors.LockCorrupt, errors.LockContention), lf.attempt_lock)
536
self.assertRaises(errors.LockCorrupt, lf.validate_token, 'fake token')
538
def test_missing_lockdir_info(self):
539
"""We can cope with absent info files."""
540
t = self.get_transport()
542
t.mkdir('test_lock/held')
543
lf = LockDir(t, 'test_lock')
544
# In this case we expect the 'not held' result from peek, because peek
545
# cannot be expected to notice that there is a 'held' directory with no
547
self.assertEqual(None, lf.peek())
548
# And lock/unlock may work or give LockContention (but not any other
552
except LockContention:
553
# LockContention is ok, and expected on Windows
556
# no error is ok, and expected on POSIX (because POSIX allows
557
# os.rename over an empty directory).
559
# Currently raises TokenMismatch, but LockCorrupt would be reasonable
562
(errors.TokenMismatch, errors.LockCorrupt),
563
lf.validate_token, 'fake token')
566
673
class TestLockDirHooks(TestCaseWithTransport):
653
760
ld2.force_break(holder_info)
654
761
lock_path = ld.transport.abspath(ld.path)
655
762
self.assertEqual([], self._calls)
658
class TestLockHeldInfo(TestCase):
659
"""Can get information about the lock holder, and detect whether they're
663
info = LockHeldInfo.for_this_process(None)
664
self.assertContainsRe(repr(info), r"LockHeldInfo\(.*\)")
666
def test_unicode(self):
667
info = LockHeldInfo.for_this_process(None)
668
self.assertContainsRe(unicode(info),
669
r'held by .* on .* \(process #\d+\), acquired .* ago')
671
def test_is_locked_by_this_process(self):
672
info = LockHeldInfo.for_this_process(None)
673
self.assertTrue(info.is_locked_by_this_process())
675
def test_is_not_locked_by_this_process(self):
676
info = LockHeldInfo.for_this_process(None)
677
info.info_dict['pid'] = '123123123123123'
678
self.assertFalse(info.is_locked_by_this_process())
680
def test_lock_holder_live_process(self):
681
"""Detect that the holder (this process) is still running."""
682
info = LockHeldInfo.for_this_process(None)
683
self.assertFalse(info.is_lock_holder_known_dead())
685
def test_lock_holder_dead_process(self):
686
"""Detect that the holder (this process) is still running."""
687
info = LockHeldInfo.for_this_process(None)
688
info.info_dict['pid'] = '123123123'
689
if sys.platform == 'win32':
691
'live lock holder detection not implemented yet on win32')
692
self.assertTrue(info.is_lock_holder_known_dead())
694
def test_lock_holder_other_machine(self):
695
"""The lock holder isn't here so we don't know if they're alive."""
696
info = LockHeldInfo.for_this_process(None)
697
info.info_dict['hostname'] = 'egg.example.com'
698
info.info_dict['pid'] = '123123123'
699
self.assertFalse(info.is_lock_holder_known_dead())
701
def test_lock_holder_other_user(self):
702
"""Only auto-break locks held by this user."""
703
info = LockHeldInfo.for_this_process(None)
704
info.info_dict['user'] = 'notme@example.com'
705
info.info_dict['pid'] = '123123123'
706
self.assertFalse(info.is_lock_holder_known_dead())
708
def test_no_good_hostname(self):
709
"""Correctly handle ambiguous hostnames.
711
If the lock's recorded with just 'localhost' we can't really trust
712
it's the same 'localhost'. (There are quite a few of them. :-)
713
So even if the process is known not to be alive, we can't say that's
716
self.overrideAttr(lockdir, 'get_host_name',
718
info = LockHeldInfo.for_this_process(None)
719
info.info_dict['pid'] = '123123123'
720
self.assertFalse(info.is_lock_holder_known_dead())
723
class TestStaleLockDir(TestCaseWithTransport):
724
"""Can automatically break stale locks.
726
:see: https://bugs.launchpad.net/bzr/+bug/220464
729
def test_auto_break_stale_lock(self):
730
"""Locks safely known to be stale are just cleaned up.
732
This generates a warning but no other user interaction.
734
# This is off by default at present; see the discussion in the bug.
735
# If you change the default, don't forget to update the docs.
736
config.GlobalConfig().set_user_option('locks.steal_dead', True)
737
# Create a lock pretending to come from a different nonexistent
738
# process on the same machine.
739
l1 = LockDir(self.get_transport(), 'a',
740
extra_holder_info={'pid': '12312313'})
741
token_1 = l1.attempt_lock()
742
l2 = LockDir(self.get_transport(), 'a')
743
token_2 = l2.attempt_lock()
744
# l1 will notice its lock was stolen.
745
self.assertRaises(errors.LockBroken,
749
def test_auto_break_stale_lock_configured_off(self):
750
"""Automatic breaking can be turned off"""
751
l1 = LockDir(self.get_transport(), 'a',
752
extra_holder_info={'pid': '12312313'})
753
token_1 = l1.attempt_lock()
754
self.addCleanup(l1.unlock)
755
l2 = LockDir(self.get_transport(), 'a')
756
# This fails now, because dead lock breaking is off by default.
757
self.assertRaises(LockContention,
759
# and it's in fact not broken