189
189
# it should only take about 0.4 seconds, but we allow more time in
190
190
# case the machine is heavily loaded
191
191
self.assertTrue(after - before <= 8.0,
192
"took %f seconds to detect lock contention" % (after - before))
192
"took %f seconds to detect lock contention" % (after - before))
195
195
self.assertEqual(1, len(self._logged_reports))
196
self.assertContainsRe(self._logged_reports[0][0],
197
r'Unable to obtain lock .* held by jrandom@example\.com on .*'
198
r' \(process #\d+\), acquired .* ago\.\n'
199
r'Will continue to try until \d{2}:\d{2}:\d{2}, unless '
200
r'you press Ctrl-C.\n'
201
r'See "bzr help break-lock" for more.')
196
self.assertEqual(self._logged_reports[0][0],
197
'%s lock %s held by %s\n'
198
'at %s [process #%s], acquired %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
start, lock_url, user, hostname, pid, time_ago, deadline_str = \
203
self._logged_reports[0][1]
204
self.assertEqual(start, u'Unable to obtain')
205
self.assertEqual(user, u'jrandom@example.com')
207
self.assertContainsRe(pid, r'\d+')
208
self.assertContainsRe(time_ago, r'.* ago')
209
self.assertContainsRe(deadline_str, r'\d{2}:\d{2}:\d{2}')
203
211
def test_31_lock_wait_easy(self):
204
212
"""Succeed when waiting on a lock with no contention.
217
225
self.assertEqual([], self._logged_reports)
227
def test_32_lock_wait_succeed(self):
228
"""Succeed when trying to acquire a lock that gets released
230
One thread holds on a lock and then releases it; another
233
# This test sometimes fails like this:
234
# Traceback (most recent call last):
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:
242
raise tests.TestSkipped("Test fails intermittently")
243
t = self.get_transport()
244
lf1 = LockDir(t, 'test_lock')
248
def wait_and_unlock():
251
unlocker = Thread(target=wait_and_unlock)
254
lf2 = LockDir(t, 'test_lock')
255
self.setup_log_reporter(lf2)
258
lf2.wait_lock(timeout=0.4, poll=0.1)
260
self.assertTrue(after - before <= 1.0)
264
# There should be only 1 report, even though it should have to
266
lock_base = lf2.transport.abspath(lf2.path)
267
self.assertEqual(1, len(self._logged_reports))
268
self.assertEqual('%s %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')
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')
291
def wait_and_unlock():
294
unlocker = Thread(target=wait_and_unlock)
297
lf2 = LockDir(t, 'test_lock')
298
self.setup_log_reporter(lf2)
306
# There should be only 1 report, even though it should have to
308
lock_base = lf2.transport.abspath(lf2.path)
309
self.assertEqual(1, len(self._logged_reports))
310
self.assertEqual('%s %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')
322
def test_35_wait_lock_changing(self):
323
"""LockDir.wait_lock() will report if the lock changes underneath.
325
This is the stages we want to happen:
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'
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
338
5) Thread1 blocks on the 'checked' lock, this time, it completely
339
unlocks the lockdir, allowing Lock2 to acquire the lock.
342
raise tests.KnownFailure(
343
"timing dependency in lock tests (#213182)")
345
wait_to_check_lock = Lock()
346
wait_until_checked_lock = Lock()
348
wait_to_check_lock.acquire()
349
wait_until_checked_lock.acquire()
350
note('locked check and checked locks')
352
class LockDir1(LockDir):
353
"""Use the synchronization points for the first lock."""
355
def attempt_lock(self):
356
# Once we have acquired the lock, it is okay for
357
# the other lock to check it
359
return super(LockDir1, self).attempt_lock()
361
note('lock1: releasing check lock')
362
wait_to_check_lock.release()
364
class LockDir2(LockDir):
365
"""Use the synchronization points for the second lock."""
367
def attempt_lock(self):
368
note('lock2: waiting for check lock')
369
wait_to_check_lock.acquire()
370
note('lock2: acquired check lock')
372
return super(LockDir2, self).attempt_lock()
374
note('lock2: releasing checked lock')
375
wait_until_checked_lock.release()
377
t = self.get_transport()
378
lf1 = LockDir1(t, 'test_lock')
381
lf2 = LockDir2(t, 'test_lock')
382
self.setup_log_reporter(lf2)
384
def wait_and_switch():
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')
392
note('lock1: acquiring lockdir')
393
# Create a new nonce, so the lock looks different.
394
lf1.nonce = osutils.rand_chars(20)
396
note('lock1: acquired lockdir')
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
404
wait_to_check_lock.release()
406
unlocker = Thread(target=wait_and_switch)
409
# Wait and play against the other thread
410
lf2.wait_lock(timeout=20.0, poll=0.01)
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'
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')
433
self.assertEqual('%s %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')
219
447
def test_40_confirm_easy(self):
220
448
"""Confirm a lock that's already held"""
221
449
t = self.get_transport()
652
871
ld2.force_break(holder_info)
653
872
lock_path = ld.transport.abspath(ld.path)
654
873
self.assertEqual([], self._calls)
657
class TestLockHeldInfo(TestCase):
658
"""Can get information about the lock holder, and detect whether they're
662
info = LockHeldInfo.for_this_process(None)
663
self.assertContainsRe(repr(info), r"LockHeldInfo\(.*\)")
665
def test_unicode(self):
666
info = LockHeldInfo.for_this_process(None)
667
self.assertContainsRe(unicode(info),
668
r'held by .* on .* \(process #\d+\), acquired .* ago')
670
def test_is_locked_by_this_process(self):
671
info = LockHeldInfo.for_this_process(None)
672
self.assertTrue(info.is_locked_by_this_process())
674
def test_is_not_locked_by_this_process(self):
675
info = LockHeldInfo.for_this_process(None)
676
info.info_dict['pid'] = '123123123123123'
677
self.assertFalse(info.is_locked_by_this_process())
679
def test_lock_holder_live_process(self):
680
"""Detect that the holder (this process) is still running."""
681
info = LockHeldInfo.for_this_process(None)
682
self.assertFalse(info.is_lock_holder_known_dead())
684
def test_lock_holder_dead_process(self):
685
"""Detect that the holder (this process) is still running."""
686
self.overrideAttr(lockdir, 'get_host_name',
687
lambda: 'aproperhostname')
688
info = LockHeldInfo.for_this_process(None)
689
info.info_dict['pid'] = '123123123'
690
self.assertTrue(info.is_lock_holder_known_dead())
692
def test_lock_holder_other_machine(self):
693
"""The lock holder isn't here so we don't know if they're alive."""
694
info = LockHeldInfo.for_this_process(None)
695
info.info_dict['hostname'] = 'egg.example.com'
696
info.info_dict['pid'] = '123123123'
697
self.assertFalse(info.is_lock_holder_known_dead())
699
def test_lock_holder_other_user(self):
700
"""Only auto-break locks held by this user."""
701
info = LockHeldInfo.for_this_process(None)
702
info.info_dict['user'] = 'notme@example.com'
703
info.info_dict['pid'] = '123123123'
704
self.assertFalse(info.is_lock_holder_known_dead())
706
def test_no_good_hostname(self):
707
"""Correctly handle ambiguous hostnames.
709
If the lock's recorded with just 'localhost' we can't really trust
710
it's the same 'localhost'. (There are quite a few of them. :-)
711
So even if the process is known not to be alive, we can't say that's
714
self.overrideAttr(lockdir, 'get_host_name',
716
info = LockHeldInfo.for_this_process(None)
717
info.info_dict['pid'] = '123123123'
718
self.assertFalse(info.is_lock_holder_known_dead())
721
class TestStaleLockDir(TestCaseWithTransport):
722
"""Can automatically break stale locks.
724
:see: https://bugs.launchpad.net/bzr/+bug/220464
727
def test_auto_break_stale_lock(self):
728
"""Locks safely known to be stale are just cleaned up.
730
This generates a warning but no other user interaction.
732
self.overrideAttr(lockdir, 'get_host_name',
733
lambda: 'aproperhostname')
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