Merge "tests: relocate some logging related unit tests"

This commit is contained in:
Zuul 2025-01-07 23:46:14 +00:00 committed by Gerrit Code Review
commit c10ca639e6
4 changed files with 280 additions and 368 deletions

View File

@ -307,6 +307,7 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None,
then the tail prefix defaults to the value of ``name``.
:return: an instance of ``SwiftLogAdapter``.
"""
conf = conf or {}
swift_logger = get_swift_logger(
conf, name, log_to_console, log_route, fmt)
@ -315,6 +316,7 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None,
statsd_client = get_statsd_client(conf, tail_prefix, swift_logger.logger)
swift_logger.logger.statsd_client = statsd_client
_patch_statsd_methods(swift_logger, swift_logger.logger)
return swift_logger

View File

@ -25,15 +25,13 @@ import warnings
import mock
import six
from six.moves.queue import Queue, Empty
from mock import patch
from swift.common import utils
from swift.common import statsd_client
from swift.common.statsd_client import StatsdClient
from swift.common.statsd_client import StatsdClient, get_statsd_client
from test.debug_logger import debug_logger
from swift.common.swob import Response
class MockUdpSocket(object):
@ -52,7 +50,7 @@ class MockUdpSocket(object):
pass
class BaseTestStasdClient(unittest.TestCase):
class BaseTestStatsdClient(unittest.TestCase):
def setUp(self):
self.getaddrinfo_calls = []
@ -76,9 +74,10 @@ class BaseTestStasdClient(unittest.TestCase):
statsd_client.socket, 'getaddrinfo', fake_getaddrinfo)
self.mock_getaddrinfo = self.getaddrinfo_patcher.start()
self.addCleanup(self.getaddrinfo_patcher.stop)
self.logger = debug_logger()
class TestStatsdClient(BaseTestStasdClient):
class TestStatsdClient(BaseTestStatsdClient):
def test_init_host(self):
client = StatsdClient('myhost', 1234)
self.assertEqual([('myhost', 1234)], self.getaddrinfo_calls)
@ -117,106 +116,14 @@ class TestStatsdClient(BaseTestStasdClient):
self.assertFalse(mock_open1.mock_calls)
self.assertFalse(self.getaddrinfo_calls)
class TestStatsdLogging(BaseTestStasdClient):
def test_get_logger_statsd_client_not_specified(self):
logger = utils.get_logger({}, 'some-name', log_route='some-route')
# white-box construction validation:
# there may be a client instance, but it won't send anything;
# won't even open a socket
self.assertIsInstance(logger.logger.statsd_client,
statsd_client.StatsdClient)
self.assertIsNone(logger.logger.statsd_client._host)
with mock.patch.object(logger.logger.statsd_client,
'_open_socket') as mock_open:
logger.increment('tunafish')
self.assertFalse(mock_open.mock_calls)
def test_get_logger_statsd_client_defaults(self):
logger = utils.get_logger({'log_statsd_host': 'some.host.com'},
'some-name', log_route='some-route')
# white-box construction validation
self.assertIsInstance(logger.logger.statsd_client,
statsd_client.StatsdClient)
self.assertEqual(logger.logger.statsd_client._host, 'some.host.com')
self.assertEqual(logger.logger.statsd_client._port, 8125)
self.assertEqual(logger.logger.statsd_client._prefix, 'some-name.')
self.assertEqual(logger.logger.statsd_client._default_sample_rate, 1)
logger2 = utils.get_logger(
{'log_statsd_host': 'some.host.com'},
'other-name', log_route='some-route',
statsd_tail_prefix='some-name.more-specific')
self.assertEqual(logger.logger.statsd_client._prefix,
'some-name.more-specific.')
self.assertEqual(logger2.logger.statsd_client._prefix,
'some-name.more-specific.')
# note: set_statsd_prefix is deprecated
logger2 = utils.get_logger({'log_statsd_host': 'some.host.com'},
'other-name', log_route='some-route')
with warnings.catch_warnings():
warnings.filterwarnings(
'ignore', r'set_statsd_prefix\(\) is deprecated')
logger.set_statsd_prefix('some-name.more-specific')
self.assertEqual(logger.logger.statsd_client._prefix,
'some-name.more-specific.')
self.assertEqual(logger2.logger.statsd_client._prefix,
'some-name.more-specific.')
with warnings.catch_warnings():
warnings.filterwarnings(
'ignore', r'set_statsd_prefix\(\) is deprecated')
logger.set_statsd_prefix('')
self.assertEqual(logger.logger.statsd_client._prefix, '')
self.assertEqual(logger2.logger.statsd_client._prefix, '')
def test_get_logger_statsd_client_non_defaults(self):
conf = {
'log_statsd_host': 'another.host.com',
'log_statsd_port': '9876',
'log_statsd_default_sample_rate': '0.75',
'log_statsd_sample_rate_factor': '0.81',
'log_statsd_metric_prefix': 'tomato.sauce',
}
logger = utils.get_logger(conf, 'some-name', log_route='some-route')
self.assertEqual(logger.logger.statsd_client._prefix,
'tomato.sauce.some-name.')
logger = utils.get_logger(conf, 'other-name', log_route='some-route',
statsd_tail_prefix='some-name.more-specific')
self.assertEqual(logger.logger.statsd_client._prefix,
'tomato.sauce.some-name.more-specific.')
# note: set_statsd_prefix is deprecated
with warnings.catch_warnings():
warnings.filterwarnings(
'ignore', r'set_statsd_prefix\(\) is deprecated')
logger.set_statsd_prefix('some-name.more-specific')
self.assertEqual(logger.logger.statsd_client._prefix,
'tomato.sauce.some-name.more-specific.')
with warnings.catch_warnings():
warnings.filterwarnings(
'ignore', r'set_statsd_prefix\(\) is deprecated')
logger.set_statsd_prefix('')
self.assertEqual(logger.logger.statsd_client._prefix, 'tomato.sauce.')
self.assertEqual(logger.logger.statsd_client._host, 'another.host.com')
self.assertEqual(logger.logger.statsd_client._port, 9876)
self.assertEqual(logger.logger.statsd_client._default_sample_rate,
0.75)
self.assertEqual(logger.logger.statsd_client._sample_rate_factor,
0.81)
def test_statsd_set_prefix_deprecation(self):
conf = {'log_statsd_host': 'another.host.com'}
with warnings.catch_warnings(record=True) as cm:
if six.PY2:
getattr(utils, '__warningregistry__', {}).clear()
warnings.resetwarnings()
warnings.simplefilter('always', DeprecationWarning)
logger = utils.get_logger(
conf, 'some-name', log_route='some-route')
logger.logger.statsd_client.set_prefix('some-name.more-specific')
client = StatsdClient(None, None)
client.set_prefix('some-name.more-specific')
msgs = [str(warning.message)
for warning in cm
if str(warning.message).startswith('set_prefix')]
@ -224,20 +131,47 @@ class TestStatsdLogging(BaseTestStasdClient):
['set_prefix() is deprecated; use the ``tail_prefix`` argument of '
'the constructor when instantiating the class instead.'],
msgs)
self.assertEqual('some-name.more-specific.', client._prefix)
with warnings.catch_warnings(record=True) as cm:
warnings.resetwarnings()
warnings.simplefilter('always', DeprecationWarning)
logger = utils.get_logger(
conf, 'some-name', log_route='some-route')
logger.set_statsd_prefix('some-name.more-specific')
msgs = [str(warning.message)
for warning in cm
if str(warning.message).startswith('set_statsd_prefix')]
self.assertEqual(
['set_statsd_prefix() is deprecated; use the '
'``statsd_tail_prefix`` argument to ``get_logger`` instead.'],
msgs)
class TestModuleFunctions(BaseTestStatsdClient):
def test_get_statsd_client_defaults(self):
# no options configured
client = statsd_client.get_statsd_client({})
self.assertIsInstance(client, StatsdClient)
self.assertIsNone(client._host)
self.assertEqual(8125, client._port)
self.assertEqual('', client._base_prefix)
self.assertEqual('', client._prefix)
self.assertEqual(1.0, client._default_sample_rate)
self.assertEqual(1.0, client._sample_rate_factor)
self.assertIsNone(client.logger)
with mock.patch.object(client, '_open_socket') as mock_open:
client.increment('tunafish')
self.assertFalse(mock_open.mock_calls)
def test_get_statsd_client_options(self):
# legacy options...
conf = {
'log_statsd_host': 'example.com',
'log_statsd_port': '6789',
'log_statsd_metric_prefix': 'banana',
'log_statsd_default_sample_rate': '3.3',
'log_statsd_sample_rate_factor': '4.4',
'log_junk': 'ignored',
}
client = statsd_client.get_statsd_client(
conf, tail_prefix='milkshake', logger=self.logger)
self.assertIsInstance(client, StatsdClient)
self.assertEqual('example.com', client._host)
self.assertEqual(6789, client._port)
self.assertEqual('banana', client._base_prefix)
self.assertEqual('banana.milkshake.', client._prefix)
self.assertEqual(3.3, client._default_sample_rate)
self.assertEqual(4.4, client._sample_rate_factor)
self.assertEqual(self.logger, client.logger)
warn_lines = self.logger.get_lines_for_level('warning')
self.assertEqual([], warn_lines)
def test_ipv4_or_ipv6_hostname_defaults_to_ipv4(self):
def stub_getaddrinfo_both_ipv4_and_ipv6(host, port, family, *rest):
@ -252,11 +186,10 @@ class TestStatsdLogging(BaseTestStasdClient):
with mock.patch.object(statsd_client.socket, 'getaddrinfo',
new=stub_getaddrinfo_both_ipv4_and_ipv6):
logger = utils.get_logger({
client = get_statsd_client({
'log_statsd_host': 'localhost',
'log_statsd_port': '9876',
}, 'some-name', log_route='some-route')
client = logger.logger.statsd_client
}, 'some-name', logger=self.logger)
self.assertEqual(client._sock_family, socket.AF_INET)
self.assertEqual(client._target, ('localhost', 9876))
@ -265,16 +198,15 @@ class TestStatsdLogging(BaseTestStasdClient):
self.assertEqual(got_sock.family, socket.AF_INET)
def test_ipv4_instantiation_and_socket_creation(self):
logger = utils.get_logger({
client = get_statsd_client({
'log_statsd_host': '127.0.0.1',
'log_statsd_port': '9876',
}, 'some-name', log_route='some-route')
statsd_client = logger.logger.statsd_client
}, 'some-name', logger=self.logger)
self.assertEqual(statsd_client._sock_family, socket.AF_INET)
self.assertEqual(statsd_client._target, ('127.0.0.1', 9876))
self.assertEqual(client._sock_family, socket.AF_INET)
self.assertEqual(client._target, ('127.0.0.1', 9876))
got_sock = statsd_client._open_socket()
got_sock = client._open_socket()
self.assertEqual(got_sock.family, socket.AF_INET)
def test_ipv6_instantiation_and_socket_creation(self):
@ -305,11 +237,10 @@ class TestStatsdLogging(BaseTestStasdClient):
with mock.patch.object(statsd_client.socket,
'getaddrinfo', fake_getaddrinfo):
logger = utils.get_logger({
client = get_statsd_client({
'log_statsd_host': '::1',
'log_statsd_port': '9876',
}, 'some-name', log_route='some-route')
client = logger.logger.statsd_client
}, 'some-name', logger=self.logger)
self.assertEqual([socket.AF_INET, socket.AF_INET6], calls)
self.assertEqual(client._sock_family, socket.AF_INET6)
self.assertEqual(client._target, ('::1', 9876, 0, 0))
@ -321,11 +252,10 @@ class TestStatsdLogging(BaseTestStasdClient):
stub_err = statsd_client.socket.gaierror('whoops')
with mock.patch.object(statsd_client.socket, 'getaddrinfo',
side_effect=stub_err):
logger = utils.get_logger({
client = get_statsd_client({
'log_statsd_host': 'i-am-not-a-hostname-or-ip',
'log_statsd_port': '9876',
}, 'some-name', log_route='some-route')
client = logger.logger.statsd_client
}, 'some-name', logger=self.logger)
self.assertEqual(client._sock_family, socket.AF_INET)
self.assertEqual(client._target,
@ -354,50 +284,46 @@ class TestStatsdLogging(BaseTestStasdClient):
with mock.patch.object(statsd_client.socket, 'getaddrinfo',
fake_getaddrinfo):
logger = utils.get_logger({
client = get_statsd_client({
'log_statsd_host': '::1',
'log_statsd_port': '9876',
}, 'some-name', log_route='some-route')
client = logger.logger.statsd_client
}, 'some-name', logger=self.logger)
fl = debug_logger()
client.logger = fl
mock_socket = MockUdpSocket()
client._open_socket = lambda *_: mock_socket
logger.increment('tunafish')
client.increment('tunafish')
self.assertEqual(fl.get_lines_for_level('warning'), [])
self.assertEqual(mock_socket.sent,
[(b'some-name.tunafish:1|c', ('::1', 9876, 0, 0))])
def test_no_exception_when_cant_send_udp_packet(self):
logger = utils.get_logger({'log_statsd_host': 'some.host.com'})
client = logger.logger.statsd_client
client = get_statsd_client({'log_statsd_host': 'some.host.com'})
fl = debug_logger()
client.logger = fl
mock_socket = MockUdpSocket(sendto_errno=errno.EPERM)
client._open_socket = lambda *_: mock_socket
logger.increment('tunafish')
client.increment('tunafish')
expected = ["Error sending UDP message to ('some.host.com', 8125): "
"[Errno 1] test errno 1"]
self.assertEqual(fl.get_lines_for_level('warning'), expected)
def test_sample_rates(self):
logger = utils.get_logger({'log_statsd_host': 'some.host.com'})
client = get_statsd_client({'log_statsd_host': 'some.host.com'})
mock_socket = MockUdpSocket()
# encapsulation? what's that?
client = logger.logger.statsd_client
self.assertTrue(client.random is random.random)
client._open_socket = lambda *_: mock_socket
client.random = lambda: 0.50001
self.assertIsNone(logger.increment('tribbles', sample_rate=0.5))
self.assertIsNone(client.increment('tribbles', sample_rate=0.5))
self.assertEqual(len(mock_socket.sent), 0)
client.random = lambda: 0.49999
rv = logger.increment('tribbles', sample_rate=0.5)
rv = client.increment('tribbles', sample_rate=0.5)
self.assertIsInstance(rv, int)
self.assertEqual(len(mock_socket.sent), 1)
@ -405,7 +331,7 @@ class TestStatsdLogging(BaseTestStasdClient):
self.assertTrue(payload.endswith(b"|@0.5"))
def test_sample_rates_with_sample_rate_factor(self):
logger = utils.get_logger({
client = get_statsd_client({
'log_statsd_host': 'some.host.com',
'log_statsd_default_sample_rate': '0.82',
'log_statsd_sample_rate_factor': '0.91',
@ -413,18 +339,16 @@ class TestStatsdLogging(BaseTestStasdClient):
effective_sample_rate = 0.82 * 0.91
mock_socket = MockUdpSocket()
# encapsulation? what's that?
client = logger.logger.statsd_client
self.assertTrue(client.random is random.random)
client._open_socket = lambda *_: mock_socket
client.random = lambda: effective_sample_rate + 0.001
logger.increment('tribbles')
client.increment('tribbles')
self.assertEqual(len(mock_socket.sent), 0)
client.random = lambda: effective_sample_rate - 0.001
logger.increment('tribbles')
client.increment('tribbles')
self.assertEqual(len(mock_socket.sent), 1)
payload = mock_socket.sent[0][0]
@ -435,7 +359,7 @@ class TestStatsdLogging(BaseTestStasdClient):
effective_sample_rate = 0.587 * 0.91
client.random = lambda: effective_sample_rate - 0.001
logger.increment('tribbles', sample_rate=0.587)
client.increment('tribbles', sample_rate=0.587)
self.assertEqual(len(mock_socket.sent), 2)
payload = mock_socket.sent[1][0]
@ -444,107 +368,8 @@ class TestStatsdLogging(BaseTestStasdClient):
suffix = suffix.encode('utf-8')
self.assertTrue(payload.endswith(suffix), payload)
def test_timing_stats(self):
class MockController(object):
def __init__(self, status):
self.status = status
self.logger = self
self.args = ()
self.called = 'UNKNOWN'
def timing_since(self, *args):
self.called = 'timing'
self.args = args
@utils.timing_stats()
def METHOD(controller):
return Response(status=controller.status)
mock_controller = MockController(200)
METHOD(mock_controller)
self.assertEqual(mock_controller.called, 'timing')
self.assertEqual(len(mock_controller.args), 2)
self.assertEqual(mock_controller.args[0], 'METHOD.timing')
self.assertTrue(mock_controller.args[1] > 0)
mock_controller = MockController(400)
METHOD(mock_controller)
self.assertEqual(len(mock_controller.args), 2)
self.assertEqual(mock_controller.called, 'timing')
self.assertEqual(mock_controller.args[0], 'METHOD.timing')
self.assertTrue(mock_controller.args[1] > 0)
mock_controller = MockController(404)
METHOD(mock_controller)
self.assertEqual(len(mock_controller.args), 2)
self.assertEqual(mock_controller.called, 'timing')
self.assertEqual(mock_controller.args[0], 'METHOD.timing')
self.assertTrue(mock_controller.args[1] > 0)
mock_controller = MockController(412)
METHOD(mock_controller)
self.assertEqual(len(mock_controller.args), 2)
self.assertEqual(mock_controller.called, 'timing')
self.assertEqual(mock_controller.args[0], 'METHOD.timing')
self.assertTrue(mock_controller.args[1] > 0)
mock_controller = MockController(416)
METHOD(mock_controller)
self.assertEqual(len(mock_controller.args), 2)
self.assertEqual(mock_controller.called, 'timing')
self.assertEqual(mock_controller.args[0], 'METHOD.timing')
self.assertTrue(mock_controller.args[1] > 0)
mock_controller = MockController(500)
METHOD(mock_controller)
self.assertEqual(len(mock_controller.args), 2)
self.assertEqual(mock_controller.called, 'timing')
self.assertEqual(mock_controller.args[0], 'METHOD.errors.timing')
self.assertTrue(mock_controller.args[1] > 0)
mock_controller = MockController(507)
METHOD(mock_controller)
self.assertEqual(len(mock_controller.args), 2)
self.assertEqual(mock_controller.called, 'timing')
self.assertEqual(mock_controller.args[0], 'METHOD.errors.timing')
self.assertTrue(mock_controller.args[1] > 0)
def test_memcached_timing_stats(self):
class MockMemcached(object):
def __init__(self):
self.logger = self
self.args = ()
self.called = 'UNKNOWN'
def timing_since(self, *args):
self.called = 'timing'
self.args = args
@utils.memcached_timing_stats()
def set(cache):
pass
@utils.memcached_timing_stats()
def get(cache):
pass
mock_cache = MockMemcached()
with patch('time.time',) as mock_time:
mock_time.return_value = 1000.99
set(mock_cache)
self.assertEqual(mock_cache.called, 'timing')
self.assertEqual(len(mock_cache.args), 2)
self.assertEqual(mock_cache.args[0], 'memcached.set.timing')
self.assertEqual(mock_cache.args[1], 1000.99)
mock_time.return_value = 2000.99
get(mock_cache)
self.assertEqual(mock_cache.called, 'timing')
self.assertEqual(len(mock_cache.args), 2)
self.assertEqual(mock_cache.args[0], 'memcached.get.timing')
self.assertEqual(mock_cache.args[1], 2000.99)
class TestStatsdLoggingDelegation(unittest.TestCase):
class TestStatsdClientOutput(unittest.TestCase):
def setUp(self):
self.sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
@ -554,19 +379,19 @@ class TestStatsdLoggingDelegation(unittest.TestCase):
self.reader_thread = threading.Thread(target=self.statsd_reader)
self.reader_thread.daemon = True
self.reader_thread.start()
self.client = None
def tearDown(self):
# The "no-op when disabled" test doesn't set up a real logger, so
# create one here so we can tell the reader thread to stop.
if not getattr(self, 'logger', None):
self.logger = utils.get_logger({
if not self.client:
self.client = get_statsd_client({
'log_statsd_host': 'localhost',
'log_statsd_port': str(self.port),
}, 'some-name')
self.logger.increment('STOP')
self.client.increment('STOP')
self.reader_thread.join(timeout=4)
self.sock.close()
del self.logger
def statsd_reader(self):
while True:
@ -607,215 +432,175 @@ class TestStatsdLoggingDelegation(unittest.TestCase):
[got, expected_regexp])
def test_methods_are_no_ops_when_not_enabled(self):
logger = utils.get_logger({
self.client = get_statsd_client({
# No "log_statsd_host" means "disabled"
'log_statsd_port': str(self.port),
}, 'some-name')
# Delegate methods are no-ops
self.assertIsNone(logger.update_stats('foo', 88))
self.assertIsNone(logger.update_stats('foo', 88, 0.57))
self.assertIsNone(logger.update_stats('foo', 88,
sample_rate=0.61))
self.assertIsNone(logger.increment('foo'))
self.assertIsNone(logger.increment('foo', 0.57))
self.assertIsNone(logger.increment('foo', sample_rate=0.61))
self.assertIsNone(logger.decrement('foo'))
self.assertIsNone(logger.decrement('foo', 0.57))
self.assertIsNone(logger.decrement('foo', sample_rate=0.61))
self.assertIsNone(logger.timing('foo', 88.048))
self.assertIsNone(logger.timing('foo', 88.57, 0.34))
self.assertIsNone(logger.timing('foo', 88.998, sample_rate=0.82))
self.assertIsNone(logger.timing_since('foo', 8938))
self.assertIsNone(logger.timing_since('foo', 8948, 0.57))
self.assertIsNone(logger.timing_since('foo', 849398,
sample_rate=0.61))
self.assertIsNone(self.client.update_stats('foo', 88))
self.assertIsNone(self.client.update_stats('foo', 88, 0.57))
self.assertIsNone(self.client.update_stats('foo', 88,
sample_rate=0.61))
self.assertIsNone(self.client.increment('foo'))
self.assertIsNone(self.client.increment('foo', 0.57))
self.assertIsNone(self.client.increment('foo', sample_rate=0.61))
self.assertIsNone(self.client.decrement('foo'))
self.assertIsNone(self.client.decrement('foo', 0.57))
self.assertIsNone(self.client.decrement('foo', sample_rate=0.61))
self.assertIsNone(self.client.timing('foo', 88.048))
self.assertIsNone(self.client.timing('foo', 88.57, 0.34))
self.assertIsNone(self.client.timing('foo', 88.998, sample_rate=0.82))
self.assertIsNone(self.client.timing_since('foo', 8938))
self.assertIsNone(self.client.timing_since('foo', 8948, 0.57))
self.assertIsNone(self.client.timing_since('foo', 849398,
sample_rate=0.61))
# Now, the queue should be empty (no UDP packets sent)
self.assertRaises(Empty, self.queue.get_nowait)
def test_delegate_methods_with_no_default_sample_rate(self):
self.logger = utils.get_logger({
self.client = get_statsd_client({
'log_statsd_host': 'localhost',
'log_statsd_port': str(self.port),
}, 'some-name')
self.assertStat('some-name.some.counter:1|c', self.logger.increment,
self.assertStat('some-name.some.counter:1|c', self.client.increment,
'some.counter')
self.assertStat('some-name.some.counter:-1|c', self.logger.decrement,
self.assertStat('some-name.some.counter:-1|c', self.client.decrement,
'some.counter')
self.assertStat('some-name.some.operation:4900.0|ms',
self.logger.timing, 'some.operation', 4.9 * 1000)
self.client.timing, 'some.operation', 4.9 * 1000)
self.assertStatMatches(r'some-name\.another\.operation:\d+\.\d+\|ms',
self.logger.timing_since, 'another.operation',
self.client.timing_since, 'another.operation',
time.time())
self.assertStat('some-name.another.counter:42|c',
self.logger.update_stats, 'another.counter', 42)
self.client.update_stats, 'another.counter', 42)
# Each call can override the sample_rate (also, bonus prefix test)
with warnings.catch_warnings():
warnings.filterwarnings(
'ignore', r'set_statsd_prefix\(\) is deprecated')
self.logger.set_statsd_prefix('pfx')
self.assertStat('pfx.some.counter:1|c|@0.972', self.logger.increment,
self.client.set_prefix('pfx')
self.assertStat('pfx.some.counter:1|c|@0.972', self.client.increment,
'some.counter', sample_rate=0.972)
self.assertStat('pfx.some.counter:-1|c|@0.972', self.logger.decrement,
self.assertStat('pfx.some.counter:-1|c|@0.972', self.client.decrement,
'some.counter', sample_rate=0.972)
self.assertStat('pfx.some.operation:4900.0|ms|@0.972',
self.logger.timing, 'some.operation', 4.9 * 1000,
self.client.timing, 'some.operation', 4.9 * 1000,
sample_rate=0.972)
self.assertStat(
'pfx.some.hi-res.operation:3141.5927|ms|@0.367879441171',
self.logger.timing, 'some.hi-res.operation',
self.client.timing, 'some.hi-res.operation',
3.141592653589793 * 1000, sample_rate=0.367879441171)
self.assertStatMatches(r'pfx\.another\.op:\d+\.\d+\|ms|@0.972',
self.logger.timing_since, 'another.op',
self.client.timing_since, 'another.op',
time.time(), sample_rate=0.972)
self.assertStat('pfx.another.counter:3|c|@0.972',
self.logger.update_stats, 'another.counter', 3,
self.client.update_stats, 'another.counter', 3,
sample_rate=0.972)
# Can override sample_rate with non-keyword arg
with warnings.catch_warnings():
warnings.filterwarnings(
'ignore', r'set_statsd_prefix\(\) is deprecated')
self.logger.set_statsd_prefix('')
self.assertStat('some.counter:1|c|@0.939', self.logger.increment,
self.client.set_prefix('')
self.assertStat('some.counter:1|c|@0.939', self.client.increment,
'some.counter', 0.939)
self.assertStat('some.counter:-1|c|@0.939', self.logger.decrement,
self.assertStat('some.counter:-1|c|@0.939', self.client.decrement,
'some.counter', 0.939)
self.assertStat('some.operation:4900.0|ms|@0.939',
self.logger.timing, 'some.operation',
self.client.timing, 'some.operation',
4.9 * 1000, 0.939)
self.assertStatMatches(r'another\.op:\d+\.\d+\|ms|@0.939',
self.logger.timing_since, 'another.op',
self.client.timing_since, 'another.op',
time.time(), 0.939)
self.assertStat('another.counter:3|c|@0.939',
self.logger.update_stats, 'another.counter', 3, 0.939)
self.client.update_stats, 'another.counter', 3, 0.939)
def test_delegate_methods_with_default_sample_rate(self):
self.logger = utils.get_logger({
self.client = get_statsd_client({
'log_statsd_host': 'localhost',
'log_statsd_port': str(self.port),
'log_statsd_default_sample_rate': '0.93',
}, 'pfx')
self.assertStat('pfx.some.counter:1|c|@0.93', self.logger.increment,
self.assertStat('pfx.some.counter:1|c|@0.93', self.client.increment,
'some.counter')
self.assertStat('pfx.some.counter:-1|c|@0.93', self.logger.decrement,
self.assertStat('pfx.some.counter:-1|c|@0.93', self.client.decrement,
'some.counter')
self.assertStat('pfx.some.operation:4760.0|ms|@0.93',
self.logger.timing, 'some.operation', 4.76 * 1000)
self.client.timing, 'some.operation', 4.76 * 1000)
self.assertStatMatches(r'pfx\.another\.op:\d+\.\d+\|ms|@0.93',
self.logger.timing_since, 'another.op',
self.client.timing_since, 'another.op',
time.time())
self.assertStat('pfx.another.counter:3|c|@0.93',
self.logger.update_stats, 'another.counter', 3)
self.client.update_stats, 'another.counter', 3)
# Each call can override the sample_rate
self.assertStat('pfx.some.counter:1|c|@0.9912', self.logger.increment,
self.assertStat('pfx.some.counter:1|c|@0.9912', self.client.increment,
'some.counter', sample_rate=0.9912)
self.assertStat('pfx.some.counter:-1|c|@0.9912', self.logger.decrement,
self.assertStat('pfx.some.counter:-1|c|@0.9912', self.client.decrement,
'some.counter', sample_rate=0.9912)
self.assertStat('pfx.some.operation:4900.0|ms|@0.9912',
self.logger.timing, 'some.operation', 4.9 * 1000,
self.client.timing, 'some.operation', 4.9 * 1000,
sample_rate=0.9912)
self.assertStatMatches(r'pfx\.another\.op:\d+\.\d+\|ms|@0.9912',
self.logger.timing_since, 'another.op',
self.client.timing_since, 'another.op',
time.time(), sample_rate=0.9912)
self.assertStat('pfx.another.counter:3|c|@0.9912',
self.logger.update_stats, 'another.counter', 3,
self.client.update_stats, 'another.counter', 3,
sample_rate=0.9912)
# Can override sample_rate with non-keyword arg
with warnings.catch_warnings():
warnings.filterwarnings(
'ignore', r'set_statsd_prefix\(\) is deprecated')
self.logger.set_statsd_prefix('')
self.assertStat('some.counter:1|c|@0.987654', self.logger.increment,
self.client.set_prefix('')
self.assertStat('some.counter:1|c|@0.987654', self.client.increment,
'some.counter', 0.987654)
self.assertStat('some.counter:-1|c|@0.987654', self.logger.decrement,
self.assertStat('some.counter:-1|c|@0.987654', self.client.decrement,
'some.counter', 0.987654)
self.assertStat('some.operation:4900.0|ms|@0.987654',
self.logger.timing, 'some.operation',
self.client.timing, 'some.operation',
4.9 * 1000, 0.987654)
self.assertStatMatches(r'another\.op:\d+\.\d+\|ms|@0.987654',
self.logger.timing_since, 'another.op',
self.client.timing_since, 'another.op',
time.time(), 0.987654)
self.assertStat('another.counter:3|c|@0.987654',
self.logger.update_stats, 'another.counter',
self.client.update_stats, 'another.counter',
3, 0.987654)
def test_delegate_methods_with_metric_prefix(self):
self.logger = utils.get_logger({
self.client = get_statsd_client({
'log_statsd_host': 'localhost',
'log_statsd_port': str(self.port),
'log_statsd_metric_prefix': 'alpha.beta',
}, 'pfx')
self.assertStat('alpha.beta.pfx.some.counter:1|c',
self.logger.increment, 'some.counter')
self.client.increment, 'some.counter')
self.assertStat('alpha.beta.pfx.some.counter:-1|c',
self.logger.decrement, 'some.counter')
self.client.decrement, 'some.counter')
self.assertStat('alpha.beta.pfx.some.operation:4760.0|ms',
self.logger.timing, 'some.operation', 4.76 * 1000)
self.client.timing, 'some.operation', 4.76 * 1000)
self.assertStatMatches(
r'alpha\.beta\.pfx\.another\.op:\d+\.\d+\|ms',
self.logger.timing_since, 'another.op', time.time())
self.client.timing_since, 'another.op', time.time())
self.assertStat('alpha.beta.pfx.another.counter:3|c',
self.logger.update_stats, 'another.counter', 3)
self.client.update_stats, 'another.counter', 3)
with warnings.catch_warnings():
warnings.filterwarnings(
'ignore', r'set_statsd_prefix\(\) is deprecated')
self.logger.set_statsd_prefix('')
self.client.set_prefix('')
self.assertStat('alpha.beta.some.counter:1|c|@0.9912',
self.logger.increment, 'some.counter',
self.client.increment, 'some.counter',
sample_rate=0.9912)
self.assertStat('alpha.beta.some.counter:-1|c|@0.9912',
self.logger.decrement, 'some.counter', 0.9912)
self.client.decrement, 'some.counter', 0.9912)
self.assertStat('alpha.beta.some.operation:4900.0|ms|@0.9912',
self.logger.timing, 'some.operation', 4.9 * 1000,
self.client.timing, 'some.operation', 4.9 * 1000,
sample_rate=0.9912)
self.assertStatMatches(
r'alpha\.beta\.another\.op:\d+\.\d+\|ms|@0.9912',
self.logger.timing_since, 'another.op',
self.client.timing_since, 'another.op',
time.time(), sample_rate=0.9912)
self.assertStat('alpha.beta.another.counter:3|c|@0.9912',
self.logger.update_stats, 'another.counter', 3,
self.client.update_stats, 'another.counter', 3,
sample_rate=0.9912)
class TestModuleFunctions(unittest.TestCase):
def setUp(self):
self.logger = debug_logger()
def test_get_statsd_client_defaults(self):
# no options configured
client = statsd_client.get_statsd_client({})
self.assertIsInstance(client, StatsdClient)
self.assertIsNone(client._host)
self.assertEqual(8125, client._port)
self.assertEqual('', client._base_prefix)
self.assertEqual('', client._prefix)
self.assertEqual(1.0, client._default_sample_rate)
self.assertEqual(1.0, client._sample_rate_factor)
self.assertIsNone(client.logger)
def test_get_statsd_client_options(self):
# legacy options...
conf = {
'log_statsd_host': 'example.com',
'log_statsd_port': '6789',
'log_statsd_metric_prefix': 'banana',
'log_statsd_default_sample_rate': '3.3',
'log_statsd_sample_rate_factor': '4.4',
'log_junk': 'ignored',
}
client = statsd_client.get_statsd_client(
conf, tail_prefix='milkshake', logger=self.logger)
self.assertIsInstance(client, StatsdClient)
self.assertEqual('example.com', client._host)
self.assertEqual(6789, client._port)
self.assertEqual('banana', client._base_prefix)
self.assertEqual('banana.milkshake.', client._prefix)
self.assertEqual(3.3, client._default_sample_rate)
self.assertEqual(4.4, client._sample_rate_factor)
self.assertEqual(self.logger, client.logger)
warn_lines = self.logger.get_lines_for_level('warning')
self.assertEqual([], warn_lines)

View File

@ -20,6 +20,7 @@ import argparse
import hashlib
import itertools
from swift.common.statsd_client import StatsdClient
from test.debug_logger import debug_logger, FakeStatsdClient
from test.unit import temptree, make_timestamp_iter, with_tempdir, \
mock_timestamp_now, FakeIterable
@ -7503,15 +7504,36 @@ class TestLoggerStatsdClientDelegation(unittest.TestCase):
client = swift_logger.logger.statsd_client
self.assertEqual(exp, client.calls)
def test_get_logger_statsd_client_default_conf(self):
logger = utils.get_logger({}, 'some-name', log_route='some-route')
# white-box construction validation
self.assertIsInstance(logger.logger.statsd_client, StatsdClient)
self.assertIsNone(logger.logger.statsd_client._host)
self.assertEqual(logger.logger.statsd_client._port, 8125)
self.assertEqual(logger.logger.statsd_client._prefix, 'some-name.')
self.assertEqual(logger.logger.statsd_client._default_sample_rate, 1)
def test_get_logger_statsd_client_non_default_conf(self):
logger = utils.get_logger({'log_statsd_host': 'some.host.com',
'log_statsd_port': 1234,
'log_statsd_default_sample_rate': 1.2,
'log_statsd_sample_rate_factor': 3.4},
'some-name', log_route='some-route')
# white-box construction validation
self.assertIsInstance(logger.logger.statsd_client, StatsdClient)
self.assertEqual(logger.logger.statsd_client._host, 'some.host.com')
self.assertEqual(logger.logger.statsd_client._port, 1234)
self.assertEqual(logger.logger.statsd_client._default_sample_rate, 1.2)
self.assertEqual(logger.logger.statsd_client._sample_rate_factor, 3.4)
self.assertEqual(logger.logger.statsd_client._prefix, 'some-name.')
def test_get_logger_statsd_client_prefix(self):
def call_get_logger(conf, name, statsd_tail_prefix):
with mock.patch('swift.common.statsd_client.StatsdClient',
FakeStatsdClient):
swift_logger = utils.get_logger(
conf, name=name, statsd_tail_prefix=statsd_tail_prefix)
swift_logger = utils.get_logger(
conf, name=name, statsd_tail_prefix=statsd_tail_prefix)
self.assertTrue(hasattr(swift_logger.logger, 'statsd_client'))
self.assertIsInstance(swift_logger.logger.statsd_client,
FakeStatsdClient)
StatsdClient)
return swift_logger.logger.statsd_client
# tail prefix defaults to swift
@ -7648,3 +7670,110 @@ class TestLoggerStatsdClientDelegation(unittest.TestCase):
self.assertFalse(hasattr(prefixed_logger, 'statsd_client_source'))
self.assertFalse(hasattr(prefixed_logger.logger, 'statsd_client'))
self.assertFalse(hasattr(prefixed_logger, 'increment'))
def test_statsd_set_prefix_deprecation(self):
conf = {'log_statsd_host': 'another.host.com'}
with warnings.catch_warnings(record=True) as cm:
warnings.resetwarnings()
warnings.simplefilter('always', DeprecationWarning)
logger = utils.get_logger(
conf, 'some-name', log_route='some-route')
logger.set_statsd_prefix('some-name.more-specific')
msgs = [str(warning.message)
for warning in cm
if str(warning.message).startswith('set_statsd_prefix')]
self.assertEqual(
['set_statsd_prefix() is deprecated; use the '
'``statsd_tail_prefix`` argument to ``get_logger`` instead.'],
msgs)
class TestTimingStatsDecorators(unittest.TestCase):
def test_timing_stats(self):
class MockController(object):
def __init__(self, status):
self.status = status
with mock.patch(
'swift.common.statsd_client.StatsdClient',
FakeStatsdClient):
self.logger = utils.get_logger({}, 'name')
@utils.timing_stats()
def METHOD(controller):
return Response(status=controller.status)
now = time.time()
mock_controller = MockController(200)
with mock.patch('swift.common.utils.time.time', return_value=now):
METHOD(mock_controller)
self.assertEqual({'timing_since': [(('METHOD.timing', now), {})]},
mock_controller.logger.logger.statsd_client.calls)
mock_controller = MockController(400)
with mock.patch('swift.common.utils.time.time', return_value=now):
METHOD(mock_controller)
self.assertEqual({'timing_since': [(('METHOD.timing', now), {})]},
mock_controller.logger.logger.statsd_client.calls)
mock_controller = MockController(404)
with mock.patch('swift.common.utils.time.time', return_value=now):
METHOD(mock_controller)
self.assertEqual({'timing_since': [(('METHOD.timing', now), {})]},
mock_controller.logger.logger.statsd_client.calls)
mock_controller = MockController(412)
with mock.patch('swift.common.utils.time.time', return_value=now):
METHOD(mock_controller)
self.assertEqual({'timing_since': [(('METHOD.timing', now), {})]},
mock_controller.logger.logger.statsd_client.calls)
mock_controller = MockController(416)
with mock.patch('swift.common.utils.time.time', return_value=now):
METHOD(mock_controller)
self.assertEqual({'timing_since': [(('METHOD.timing', now), {})]},
mock_controller.logger.logger.statsd_client.calls)
mock_controller = MockController(500)
with mock.patch('swift.common.utils.time.time', return_value=now):
METHOD(mock_controller)
self.assertEqual(
{'timing_since': [(('METHOD.errors.timing', now), {})]},
mock_controller.logger.logger.statsd_client.calls)
mock_controller = MockController(507)
with mock.patch('swift.common.utils.time.time', return_value=now):
METHOD(mock_controller)
self.assertEqual(
{'timing_since': [(('METHOD.errors.timing', now), {})]},
mock_controller.logger.logger.statsd_client.calls)
def test_memcached_timing_stats(self):
class MockMemcached(object):
def __init__(self):
with mock.patch(
'swift.common.statsd_client.StatsdClient',
FakeStatsdClient):
self.logger = utils.get_logger({}, 'name')
@utils.memcached_timing_stats()
def set(cache):
pass
@utils.memcached_timing_stats()
def get(cache):
pass
mock_cache = MockMemcached()
with patch('time.time', return_value=1000.99):
set(mock_cache)
self.assertEqual(
{'timing_since': [(('memcached.set.timing', 1000.99), {})]},
mock_cache.logger.logger.statsd_client.calls)
mock_cache = MockMemcached()
with patch('time.time', return_value=2000.99):
get(mock_cache)
self.assertEqual(
{'timing_since': [(('memcached.get.timing', 2000.99), {})]},
mock_cache.logger.logger.statsd_client.calls)

View File

@ -283,10 +283,8 @@ class TestUtilsLogs(unittest.TestCase):
self.assertEqual('swift: testing\n', sio.getvalue())
# same log_route, different names...
logger1 = utils.get_swift_logger({'log_statsd_host': '1.2.3.4'},
name='name1', log_route='route')
logger2 = utils.get_swift_logger({'log_statsd_host': '1.2.3.5'},
name='name2', log_route='route')
logger1 = utils.get_swift_logger({}, name='name1', log_route='route')
logger2 = utils.get_swift_logger({}, name='name2', log_route='route')
self.assertEqual('route', logger1.name)
self.assertEqual('route', logger1.logger.name)
self.assertEqual('name1', logger1.server)
@ -302,10 +300,8 @@ class TestUtilsLogs(unittest.TestCase):
self.assertEqual('name2: testing\n', sio.getvalue())
# different log_route, different names...
logger1 = utils.get_swift_logger({'log_statsd_host': '1.2.3.4'},
name='name1', log_route='route1')
logger2 = utils.get_swift_logger({'log_statsd_host': '1.2.3.5'},
name='name2', log_route='route2')
logger1 = utils.get_swift_logger({}, name='name1', log_route='route1')
logger2 = utils.get_swift_logger({}, name='name2', log_route='route2')
self.assertEqual('route1', logger1.name)
self.assertEqual('route1', logger1.logger.name)
self.assertEqual('name1', logger1.server)