183
184
after = time.time()
184
185
# it should only take about 0.4 seconds, but we allow more time in
185
186
# case the machine is heavily loaded
186
self.assertTrue(after - before <= 8.0,
187
self.assertTrue(after - before <= 8.0,
187
188
"took %f seconds to detect lock contention" % (after - before))
191
lock_base = lf2.transport.abspath(lf2.path)
190
192
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')
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}')
193
self.assertEqual('%s %s\n'
195
'Will continue to try until %s\n',
196
self._logged_reports[0][0])
197
args = self._logged_reports[0][1]
198
self.assertEqual('Unable to obtain', args[0])
199
self.assertEqual('lock %s' % (lock_base,), args[1])
200
self.assertStartsWith(args[2], 'held by ')
201
self.assertStartsWith(args[3], 'locked ')
202
self.assertEndsWith(args[3], ' ago')
203
self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
206
205
def test_31_lock_wait_easy(self):
207
206
"""Succeed when waiting on a lock with no contention.
220
219
self.assertEqual([], self._logged_reports)
221
def test_32_lock_wait_succeed(self):
222
"""Succeed when trying to acquire a lock that gets released
224
One thread holds on a lock and then releases it; another
227
# This test sometimes fails like this:
228
# Traceback (most recent call last):
230
# File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/
231
# test_lockdir.py", line 247, in test_32_lock_wait_succeed
232
# self.assertEqual(1, len(self._logged_reports))
233
# AssertionError: not equal:
236
raise tests.TestSkipped("Test fails intermittently")
237
t = self.get_transport()
238
lf1 = LockDir(t, 'test_lock')
242
def wait_and_unlock():
245
unlocker = Thread(target=wait_and_unlock)
248
lf2 = LockDir(t, 'test_lock')
249
self.setup_log_reporter(lf2)
252
lf2.wait_lock(timeout=0.4, poll=0.1)
254
self.assertTrue(after - before <= 1.0)
258
# There should be only 1 report, even though it should have to
260
lock_base = lf2.transport.abspath(lf2.path)
261
self.assertEqual(1, len(self._logged_reports))
262
self.assertEqual('%s %s\n'
264
'Will continue to try until %s\n',
265
self._logged_reports[0][0])
266
args = self._logged_reports[0][1]
267
self.assertEqual('Unable to obtain', args[0])
268
self.assertEqual('lock %s' % (lock_base,), args[1])
269
self.assertStartsWith(args[2], 'held by ')
270
self.assertStartsWith(args[3], 'locked ')
271
self.assertEndsWith(args[3], ' ago')
272
self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
274
def test_34_lock_write_waits(self):
275
"""LockDir.lock_write() will wait for the lock."""
276
# the test suite sets the default to 0 to make deadlocks fail fast.
277
# change it for this test, as we want to try a manual deadlock.
278
raise tests.TestSkipped('Timing-sensitive test')
279
bzrlib.lockdir._DEFAULT_TIMEOUT_SECONDS = 300
280
t = self.get_transport()
281
lf1 = LockDir(t, 'test_lock')
285
def wait_and_unlock():
288
unlocker = Thread(target=wait_and_unlock)
291
lf2 = LockDir(t, 'test_lock')
292
self.setup_log_reporter(lf2)
300
# There should be only 1 report, even though it should have to
302
lock_base = lf2.transport.abspath(lf2.path)
303
self.assertEqual(1, len(self._logged_reports))
304
self.assertEqual('%s %s\n'
306
'Will continue to try until %s\n',
307
self._logged_reports[0][0])
308
args = self._logged_reports[0][1]
309
self.assertEqual('Unable to obtain', args[0])
310
self.assertEqual('lock %s' % (lock_base,), args[1])
311
self.assertStartsWith(args[2], 'held by ')
312
self.assertStartsWith(args[3], 'locked ')
313
self.assertEndsWith(args[3], ' ago')
314
self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
316
def test_35_wait_lock_changing(self):
317
"""LockDir.wait_lock() will report if the lock changes underneath.
319
This is the stages we want to happen:
321
0) Synchronization locks are created and locked.
322
1) Lock1 obtains the lockdir, and releases the 'check' lock.
323
2) Lock2 grabs the 'check' lock, and checks the lockdir.
324
It sees the lockdir is already acquired, reports the fact,
325
and unsets the 'checked' lock.
326
3) Thread1 blocks on acquiring the 'checked' lock, and then tells
327
Lock1 to release and acquire the lockdir. This resets the 'check'
329
4) Lock2 acquires the 'check' lock, and checks again. It notices
330
that the holder of the lock has changed, and so reports a new
332
5) Thread1 blocks on the 'checked' lock, this time, it completely
333
unlocks the lockdir, allowing Lock2 to acquire the lock.
336
wait_to_check_lock = Lock()
337
wait_until_checked_lock = Lock()
339
wait_to_check_lock.acquire()
340
wait_until_checked_lock.acquire()
341
note('locked check and checked locks')
343
class LockDir1(LockDir):
344
"""Use the synchronization points for the first lock."""
346
def attempt_lock(self):
347
# Once we have acquired the lock, it is okay for
348
# the other lock to check it
350
return super(LockDir1, self).attempt_lock()
352
note('lock1: releasing check lock')
353
wait_to_check_lock.release()
355
class LockDir2(LockDir):
356
"""Use the synchronization points for the second lock."""
358
def attempt_lock(self):
359
note('lock2: waiting for check lock')
360
wait_to_check_lock.acquire()
361
note('lock2: acquired check lock')
363
return super(LockDir2, self).attempt_lock()
365
note('lock2: releasing checked lock')
366
wait_until_checked_lock.release()
368
t = self.get_transport()
369
lf1 = LockDir1(t, 'test_lock')
372
lf2 = LockDir2(t, 'test_lock')
373
self.setup_log_reporter(lf2)
375
def wait_and_switch():
377
# Block until lock2 has had a chance to check
378
note('lock1: waiting 1 for checked lock')
379
wait_until_checked_lock.acquire()
380
note('lock1: acquired for checked lock')
381
note('lock1: released lockdir')
383
note('lock1: acquiring lockdir')
384
# Create a new nonce, so the lock looks different.
385
lf1.nonce = osutils.rand_chars(20)
387
note('lock1: acquired lockdir')
389
# Block until lock2 has peeked again
390
note('lock1: waiting 2 for checked lock')
391
wait_until_checked_lock.acquire()
392
note('lock1: acquired for checked lock')
393
# Now unlock, and let lock 2 grab the lock
395
wait_to_check_lock.release()
397
unlocker = Thread(target=wait_and_switch)
400
# Wait and play against the other thread
401
lf2.wait_lock(timeout=20.0, poll=0.01)
406
# There should be 2 reports, because the lock changed
407
lock_base = lf2.transport.abspath(lf2.path)
408
self.assertEqual(2, len(self._logged_reports))
410
self.assertEqual('%s %s\n'
412
'Will continue to try until %s\n',
413
self._logged_reports[0][0])
414
args = self._logged_reports[0][1]
415
self.assertEqual('Unable to obtain', args[0])
416
self.assertEqual('lock %s' % (lock_base,), args[1])
417
self.assertStartsWith(args[2], 'held by ')
418
self.assertStartsWith(args[3], 'locked ')
419
self.assertEndsWith(args[3], ' ago')
420
self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
422
self.assertEqual('%s %s\n'
424
'Will continue to try until %s\n',
425
self._logged_reports[1][0])
426
args = self._logged_reports[1][1]
427
self.assertEqual('Lock owner changed for', args[0])
428
self.assertEqual('lock %s' % (lock_base,), args[1])
429
self.assertStartsWith(args[2], 'held by ')
430
self.assertStartsWith(args[3], 'locked ')
431
self.assertEndsWith(args[3], ' ago')
432
self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
222
434
def test_40_confirm_easy(self):
223
435
"""Confirm a lock that's already held"""
224
436
t = self.get_transport()
225
437
lf1 = LockDir(t, 'test_lock')
227
439
lf1.attempt_lock()
228
self.addCleanup(lf1.unlock)
231
442
def test_41_confirm_not_held(self):
333
539
# do this without IO redirection to ensure it doesn't prompt.
334
540
self.assertRaises(AssertionError, ld1.break_lock)
335
541
orig_factory = bzrlib.ui.ui_factory
336
bzrlib.ui.ui_factory = bzrlib.ui.CannedInputUIFactory([True])
542
# silent ui - no need for stdout
543
bzrlib.ui.ui_factory = bzrlib.ui.SilentUIFactory()
544
bzrlib.ui.ui_factory.stdin = StringIO("y\n")
339
547
self.assertRaises(LockBroken, ld1.unlock)
341
549
bzrlib.ui.ui_factory = orig_factory
343
def test_break_lock_corrupt_info(self):
344
"""break_lock works even if the info file is corrupt (and tells the UI
348
ld2 = self.get_lock()
351
ld.transport.put_bytes_non_atomic('test_lock/held/info', '\0')
352
class LoggingUIFactory(bzrlib.ui.SilentUIFactory):
355
def get_boolean(self, prompt):
356
self.prompts.append(('boolean', prompt))
358
ui = LoggingUIFactory()
359
self.overrideAttr(bzrlib.ui, 'ui_factory', ui)
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)
366
def test_break_lock_missing_info(self):
367
"""break_lock works even if the info file is missing (and tells the UI
371
ld2 = self.get_lock()
374
ld.transport.delete('test_lock/held/info')
375
class LoggingUIFactory(bzrlib.ui.SilentUIFactory):
378
def get_boolean(self, prompt):
379
self.prompts.append(('boolean', prompt))
381
ui = LoggingUIFactory()
382
orig_factory = bzrlib.ui.ui_factory
383
bzrlib.ui.ui_factory = ui
386
self.assertRaises(LockBroken, ld.unlock)
387
self.assertLength(0, ui.prompts)
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[:]
395
551
def test_create_missing_base_directory(self):
396
552
"""If LockDir.path doesn't exist, it can be created
487
641
# when held, that's all we see
488
642
ld1.attempt_lock()
489
self.addCleanup(ld1.unlock)
490
643
check_dir(['held'])
491
644
# second guy should fail
492
645
self.assertRaises(errors.LockContention, ld2.attempt_lock)
494
647
check_dir(['held'])
496
def test_no_lockdir_info(self):
497
"""We can cope with empty info files."""
498
# This seems like a fairly common failure case - see
499
# <https://bugs.launchpad.net/bzr/+bug/185103> and all its dupes.
500
# Processes are often interrupted after opening the file
501
# before the actual contents are committed.
502
t = self.get_transport()
504
t.mkdir('test_lock/held')
505
t.put_bytes('test_lock/held/info', '')
506
lf = LockDir(t, 'test_lock')
508
formatted_info = lf._format_lock_info(info)
510
['<unknown>', '<unknown>', '<unknown>', '(unknown)'],
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()
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.
528
(errors.LockCorrupt, errors.LockContention), lf.attempt_lock)
529
self.assertRaises(errors.LockCorrupt, lf.validate_token, 'fake token')
531
def test_missing_lockdir_info(self):
532
"""We can cope with absent info files."""
533
t = self.get_transport()
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
540
self.assertEqual(None, lf.peek())
541
# And lock/unlock may work or give LockContention (but not any other
545
except LockContention:
546
# LockContention is ok, and expected on Windows
549
# no error is ok, and expected on POSIX (because POSIX allows
550
# os.rename over an empty directory).
552
# Currently raises TokenMismatch, but LockCorrupt would be reasonable
555
(errors.TokenMismatch, errors.LockCorrupt),
556
lf.validate_token, 'fake token')
559
class TestLockDirHooks(TestCaseWithTransport):
562
super(TestLockDirHooks, self).setUp()
566
return LockDir(self.get_transport(), 'test_lock')
568
def record_hook(self, result):
569
self._calls.append(result)
571
def test_LockDir_acquired_success(self):
572
# the LockDir.lock_acquired hook fires when a lock is acquired.
573
LockDir.hooks.install_named_hook('lock_acquired',
574
self.record_hook, 'record_hook')
577
self.assertEqual([], self._calls)
578
result = ld.attempt_lock()
579
lock_path = ld.transport.abspath(ld.path)
580
self.assertEqual([lock.LockResult(lock_path, result)], self._calls)
582
self.assertEqual([lock.LockResult(lock_path, result)], self._calls)
584
def test_LockDir_acquired_fail(self):
585
# the LockDir.lock_acquired hook does not fire on failure.
588
ld2 = self.get_lock()
590
# install a lock hook now, when the disk lock is locked
591
LockDir.hooks.install_named_hook('lock_acquired',
592
self.record_hook, 'record_hook')
593
self.assertRaises(errors.LockContention, ld.attempt_lock)
594
self.assertEqual([], self._calls)
596
self.assertEqual([], self._calls)
598
def test_LockDir_released_success(self):
599
# the LockDir.lock_released hook fires when a lock is acquired.
600
LockDir.hooks.install_named_hook('lock_released',
601
self.record_hook, 'record_hook')
604
self.assertEqual([], self._calls)
605
result = ld.attempt_lock()
606
self.assertEqual([], self._calls)
608
lock_path = ld.transport.abspath(ld.path)
609
self.assertEqual([lock.LockResult(lock_path, result)], self._calls)
611
def test_LockDir_released_fail(self):
612
# the LockDir.lock_released hook does not fire on failure.
615
ld2 = self.get_lock()
617
ld2.force_break(ld2.peek())
618
LockDir.hooks.install_named_hook('lock_released',
619
self.record_hook, 'record_hook')
620
self.assertRaises(LockBroken, ld.unlock)
621
self.assertEqual([], self._calls)
623
def test_LockDir_broken_success(self):
624
# the LockDir.lock_broken hook fires when a lock is broken.
627
ld2 = self.get_lock()
628
result = ld.attempt_lock()
629
LockDir.hooks.install_named_hook('lock_broken',
630
self.record_hook, 'record_hook')
631
ld2.force_break(ld2.peek())
632
lock_path = ld.transport.abspath(ld.path)
633
self.assertEqual([lock.LockResult(lock_path, result)], self._calls)
635
def test_LockDir_broken_failure(self):
636
# the LockDir.lock_broken hook does not fires when a lock is already
640
ld2 = self.get_lock()
641
result = ld.attempt_lock()
642
holder_info = ld2.peek()
644
LockDir.hooks.install_named_hook('lock_broken',
645
self.record_hook, 'record_hook')
646
ld2.force_break(holder_info)
647
lock_path = ld.transport.abspath(ld.path)
648
self.assertEqual([], self._calls)