def test_release_logs(self, uuid1):
"""
When lock is released, it logs with time the lock was held
"""
lock_uuid = 'lock_uuid'
log = mock.MagicMock(spec=['msg'])
clock = task.Clock()
lock = BasicLock(self.client,
self.table_name,
lock_uuid,
max_retry=1,
retry_wait=3,
reactor=clock,
log=log)
self.responses = [
None, # _write_lock
[{
'lockId': lock._lock_id,
'claimId': lock._claim_id
}], # _read_lock
None # delete for release lock
]
lock.acquire()
clock.advance(34)
lock.release()
log.msg.assert_called_with('Released lock. Was held for 34.0 seconds',
lock_held_time=34.0,
lock_id=lock_uuid,
claim_id='claim_uuid',
result=None)
def test_acquire_retry_never_acquired(self):
"""BasicLock.acquire will retry max_retry times and then give up."""
lock_uuid = uuid.uuid1()
clock = task.Clock()
lock = BasicLock(self.client, self.table_name, lock_uuid, max_retry=1, reactor=clock)
responses = [
defer.fail(BusyLockError('', '')),
defer.fail(BusyLockError('', ''))
]
def _new_verify_lock(response):
return responses.pop(0)
lock._verify_lock = _new_verify_lock
def _side_effect(*args, **kwargs):
return defer.succeed([])
self.client.execute.side_effect = _side_effect
d = lock.acquire()
clock.advance(20)
result = self.failureResultOf(d)
self.assertTrue(result.check(BusyLockError))
self.assertEqual(self.client.execute.call_count, 4)
def test_acquire_retry_never_acquired(self):
"""BasicLock.acquire will retry max_retry times and then give up."""
lock_uuid = uuid.uuid1()
clock = task.Clock()
lock = BasicLock(self.client,
self.table_name,
lock_uuid,
max_retry=1,
reactor=clock)
responses = [
defer.fail(BusyLockError('', '')),
defer.fail(BusyLockError('', ''))
]
def _new_verify_lock(response):
return responses.pop(0)
lock._verify_lock = _new_verify_lock
def _side_effect(*args, **kwargs):
return defer.succeed([])
self.client.execute.side_effect = _side_effect
d = lock.acquire()
clock.advance(20)
result = self.failureResultOf(d)
self.assertTrue(result.check(BusyLockError))
self.assertEqual(self.client.execute.call_count, 4)
def test_acquire_retry_not_lock_error(self):
"""If an error occurs that is not lock related, it is propagated."""
lock_uuid = uuid.uuid1()
clock = task.Clock()
lock = BasicLock(self.client,
self.table_name,
lock_uuid,
max_retry=1,
reactor=clock)
responses = [
defer.fail(
NameError('Keep your foot off the blasted samoflange.')),
]
def _new_verify_lock(response):
return responses.pop(0)
lock._verify_lock = _new_verify_lock
def _side_effect(*args, **kwargs):
return defer.succeed([])
self.client.execute.side_effect = _side_effect
d = lock.acquire()
result = self.failureResultOf(d)
self.assertTrue(result.check(NameError))
def test_acquire(self):
"""Lock acquire should write and then read back its write."""
lock_uuid = uuid.uuid1()
lock = BasicLock(self.client, self.table_name, lock_uuid)
def _side_effect(*args, **kwargs):
return defer.succeed([{
'lockId': lock._lock_id,
'claimId': lock._claim_id
}])
self.client.execute.side_effect = _side_effect
d = lock.acquire()
self.assertEqual(self.assertFired(d), True)
expected = [
mock.call(
'INSERT INTO lock ("lockId","claimId") VALUES (:lockId,:claimId) USING TTL 300;',
{
'lockId': lock._lock_id,
'claimId': lock._claim_id
}, 2),
mock.call(
'SELECT * FROM lock WHERE "lockId"=:lockId ORDER BY "claimId";',
{'lockId': lock._lock_id}, 2)
]
self.assertEqual(self.client.execute.call_args_list, expected)
def test_acquire_retries_on_NoLockClaimsError(self):
"""
acquire retries when _verify_lock fails with a NoLockClaimsError.
"""
lock_uuid = uuid.uuid1()
clock = task.Clock()
lock = BasicLock(self.client,
self.table_name,
lock_uuid,
max_retry=1,
reactor=clock)
responses = [
defer.fail(NoLockClaimsError('', '')),
defer.succeed(True)
]
def _new_verify_lock(response):
return responses.pop(0)
lock._verify_lock = _new_verify_lock
def _side_effect(*args, **kwargs):
return defer.succeed([])
self.client.execute.side_effect = _side_effect
d = lock.acquire()
clock.advance(20)
self.assertEqual(self.assertFired(d), True)
self.assertEqual(self.client.execute.call_count, 4)
def test_lock_acquire_anyfailure_logged(self, uuid1):
"""
If lock acquisition fails due to any error, it is logged along with time taken
"""
lock_uuid = 'lock_uuid'
log = mock.MagicMock(spec=['msg'])
clock = task.Clock()
lock = BasicLock(self.client, self.table_name, lock_uuid, max_retry=1,
retry_wait=3, reactor=clock, log=log)
self.responses = [
None, # _write_lock
[{'lockId': lock._lock_id, 'claimId': 'wait for it..'}], # _read_lock
None, # delete for release lock
None, # _write_lock again
]
def _execute(*args, **kwargs):
if not self.responses:
return defer.fail(ValueError('hmm'))
return defer.succeed(self.responses.pop(0))
self.client.execute.side_effect = _execute
d = lock.acquire()
clock.advance(3)
f = self.failureResultOf(d, ValueError)
log.msg.assert_called_with('Could not acquire lock in 3.0 seconds due to ' + str(f),
lock_acquire_fail_time=3.0, reason=f, lock_id=lock_uuid,
claim_id='claim_uuid')
def test_acquire_logs(self, uuid1):
"""
When lock is acquired, it logs with time taken to acquire the log. Different claim ids
message is also logged. Intermittent 'release lock' messages are not logged
"""
lock_uuid = 'lock_uuid'
log = mock.MagicMock(spec=['msg'])
clock = task.Clock()
lock = BasicLock(self.client, self.table_name, lock_uuid, max_retry=1,
retry_wait=3, reactor=clock, log=log)
self.responses = [
None, # _write_lock
[{'lockId': lock._lock_id, 'claimId': 'wait for it..'}], # _read_lock
None, # delete for release lock
None, # _write_lock again
[{'lockId': lock._lock_id, 'claimId': lock._claim_id}] # _read_lock
]
d = lock.acquire()
clock.advance(5)
self.assertEqual(self.assertFired(d), True)
log.msg.assert_has_calls(
[mock.call('Got different claimId: wait for it..', diff_claim_id='wait for it..',
lock_id=lock_uuid, claim_id='claim_uuid'),
mock.call('Acquired lock in 5.0 seconds', lock_acquire_time=5.0,
lock_id=lock_uuid, claim_id='claim_uuid')])
def test_acquire_retries_on_NoLockClaimsError(self):
"""
acquire retries when _verify_lock fails with a NoLockClaimsError.
"""
lock_uuid = uuid.uuid1()
clock = task.Clock()
lock = BasicLock(self.client, self.table_name, lock_uuid, max_retry=1, reactor=clock)
responses = [
defer.fail(NoLockClaimsError('', '')),
defer.succeed(True)
]
def _new_verify_lock(response):
return responses.pop(0)
lock._verify_lock = _new_verify_lock
def _side_effect(*args, **kwargs):
return defer.succeed([])
self.client.execute.side_effect = _side_effect
d = lock.acquire()
clock.advance(20)
self.assertEqual(self.assertFired(d), True)
self.assertEqual(self.client.execute.call_count, 4)
def test_release_logs(self, uuid1):
"""
When lock is released, it logs with time the lock was held
"""
lock_uuid = 'lock_uuid'
log = mock.MagicMock(spec=['msg'])
clock = task.Clock()
lock = BasicLock(self.client, self.table_name, lock_uuid, max_retry=1,
retry_wait=3, reactor=clock, log=log)
self.responses = [
None, # _write_lock
[{'lockId': lock._lock_id, 'claimId': lock._claim_id}], # _read_lock
None # delete for release lock
]
lock.acquire()
clock.advance(34)
lock.release()
log.msg.assert_called_with('Released lock. Was held for 34.0 seconds',
lock_held_time=34.0, lock_id=lock_uuid,
claim_id='claim_uuid', result=None)
def test_acquire_logs(self, uuid1):
"""
When lock is acquired, it logs with time taken to acquire the log. Different claim ids
message is also logged. Intermittent 'release lock' messages are not logged
"""
lock_uuid = 'lock_uuid'
log = mock.MagicMock(spec=['msg'])
clock = task.Clock()
lock = BasicLock(self.client,
self.table_name,
lock_uuid,
max_retry=1,
retry_wait=3,
reactor=clock,
log=log)
self.responses = [
None, # _write_lock
[{
'lockId': lock._lock_id,
'claimId': 'wait for it..'
}], # _read_lock
None, # delete for release lock
None, # _write_lock again
[{
'lockId': lock._lock_id,
'claimId': lock._claim_id
}] # _read_lock
]
d = lock.acquire()
clock.advance(5)
self.assertEqual(self.assertFired(d), True)
log.msg.assert_has_calls([
mock.call('Got different claimId: wait for it..',
diff_claim_id='wait for it..',
lock_id=lock_uuid,
claim_id='claim_uuid'),
mock.call('Acquired lock in 5.0 seconds',
lock_acquire_time=5.0,
lock_id=lock_uuid,
claim_id='claim_uuid')
])
def test_acquire(self):
"""Lock acquire should write and then read back its write."""
lock_uuid = uuid.uuid1()
lock = BasicLock(self.client, self.table_name, lock_uuid)
def _side_effect(*args, **kwargs):
return defer.succeed([{'lockId': lock._lock_id,
'claimId': lock._claim_id}])
self.client.execute.side_effect = _side_effect
d = lock.acquire()
self.assertEqual(self.assertFired(d), True)
expected = [
mock.call('INSERT INTO lock ("lockId","claimId") VALUES (:lockId,:claimId) USING TTL 300;',
{'lockId': lock._lock_id, 'claimId': lock._claim_id}, 2),
mock.call('SELECT * FROM lock WHERE "lockId"=:lockId ORDER BY "claimId";',
{'lockId': lock._lock_id}, 2)]
self.assertEqual(self.client.execute.call_args_list, expected)
def test_lock_acquire_anyfailure_logged(self, uuid1):
"""
If lock acquisition fails due to any error, it is logged along with time taken
"""
lock_uuid = 'lock_uuid'
log = mock.MagicMock(spec=['msg'])
clock = task.Clock()
lock = BasicLock(self.client,
self.table_name,
lock_uuid,
max_retry=1,
retry_wait=3,
reactor=clock,
log=log)
self.responses = [
None, # _write_lock
[{
'lockId': lock._lock_id,
'claimId': 'wait for it..'
}], # _read_lock
None, # delete for release lock
None, # _write_lock again
]
def _execute(*args, **kwargs):
if not self.responses:
return defer.fail(ValueError('hmm'))
return defer.succeed(self.responses.pop(0))
self.client.execute.side_effect = _execute
d = lock.acquire()
clock.advance(3)
f = self.failureResultOf(d, ValueError)
log.msg.assert_called_with(
'Could not acquire lock in 3.0 seconds due to ' + str(f),
lock_acquire_fail_time=3.0,
reason=f,
lock_id=lock_uuid,
claim_id='claim_uuid')
def test_lock_acquire_failure_logged(self, uuid1):
"""
If lock acquisition fails due to BusyLockError, it is logged along with time taken
"""
lock_uuid = 'lock_uuid'
log = mock.MagicMock(spec=['msg'])
clock = task.Clock()
lock = BasicLock(self.client,
self.table_name,
lock_uuid,
max_retry=1,
retry_wait=3,
reactor=clock,
log=log)
self.responses = [
None, # _write_lock
[{
'lockId': lock._lock_id,
'claimId': 'wait for it..'
}], # _read_lock
None, # delete for release lock
None, # _write_lock again
[{
'lockId': lock._lock_id,
'claimId': 'nope'
}], # _read_lock
None # delete again for release lock
]
d = lock.acquire()
clock.advance(3)
f = self.failureResultOf(d, BusyLockError)
log.msg.assert_called_with(
'Could not acquire lock in 3.0 seconds due to ' + str(f),
lock_acquire_fail_time=3.0,
reason=f,
lock_id=lock_uuid,
claim_id='claim_uuid')
def test_acquire_retry_not_lock_error(self):
"""If an error occurs that is not lock related, it is propagated."""
lock_uuid = uuid.uuid1()
clock = task.Clock()
lock = BasicLock(self.client, self.table_name, lock_uuid, max_retry=1, reactor=clock)
responses = [
defer.fail(NameError('Keep your foot off the blasted samoflange.')),
]
def _new_verify_lock(response):
return responses.pop(0)
lock._verify_lock = _new_verify_lock
def _side_effect(*args, **kwargs):
return defer.succeed([])
self.client.execute.side_effect = _side_effect
d = lock.acquire()
result = self.failureResultOf(d)
self.assertTrue(result.check(NameError))
def test_lock_acquire_failure_logged(self, uuid1):
"""
If lock acquisition fails due to BusyLockError, it is logged along with time taken
"""
lock_uuid = 'lock_uuid'
log = mock.MagicMock(spec=['msg'])
clock = task.Clock()
lock = BasicLock(self.client, self.table_name, lock_uuid, max_retry=1,
retry_wait=3, reactor=clock, log=log)
self.responses = [
None, # _write_lock
[{'lockId': lock._lock_id, 'claimId': 'wait for it..'}], # _read_lock
None, # delete for release lock
None, # _write_lock again
[{'lockId': lock._lock_id, 'claimId': 'nope'}], # _read_lock
None # delete again for release lock
]
d = lock.acquire()
clock.advance(3)
f = self.failureResultOf(d, BusyLockError)
log.msg.assert_called_with('Could not acquire lock in 3.0 seconds due to ' + str(f),
lock_acquire_fail_time=3.0, reason=f, lock_id=lock_uuid,
claim_id='claim_uuid')
