openstack/swift
Code Issues Proposed changes

Socket errors don't warrant tracebacks when talking to memcached

Browse Source 
Currently, timeouts when talking to memcached cause log lines like

   ERROR:root:Timeout connecting to memcached: 192.168.23.62:11211

Meanwhile, socket errors (which you'd expect to be about as common
as timeouts) cause log lines like

   ERROR:root:Error talking to memcached: 192.168.23.70:11211
   Traceback (most recent call last):
     File "/usr/lib/pymodules/python2.7/swift/common/memcached.py", line 293, in set
       (key, flags, timeout, len(value), value))
     File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 390, in sendall
       tail = self.send(data, flags)
     File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 384, in send
       return self._send_loop(self.fd.send, data, flags)
     File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 371, in _send_loop
       return send_method(data, *args)
   error: [Errno 32] Broken pipe

... or ...

   ERROR:root:Error connecting to memcached: 192.168.23.73:11211
   Traceback (most recent call last):
     File "/opt/ss/lib/python2.7/site-packages/swift/common/memcached.py", line 239, in _get_conns
       fp, sock = self._client_cache[server].get()
     File "/opt/ss/lib/python2.7/site-packages/swift/common/memcached.py", line 135, in get
       fp, sock = self.create()
     File "/opt/ss/lib/python2.7/site-packages/swift/common/memcached.py", line 128, in create
       sock.connect((host, int(port)))
     File "/opt/ss/lib/python2.7/site-packages/eventlet/greenio/base.py", line 237, in connect
       while not socket_connect(fd, address):
     File "/opt/ss/lib/python2.7/site-packages/eventlet/greenio/base.py", line 39, in socket_connect
       raise socket.error(err, errno.errorcode[err])
   error: [Errno 101] ENETUNREACH

... which seems excessive. Now, socket errors are logged as normal
errors, without the tracebacks.

Change-Id: I71a2c4786c0406dbc43b829cad5a0c7e2c45de21
This commit is contained in:
Tim Burke 2017-08-22 05:31:59 +00:00
parent b0142d0cd2
commit 73929539cc
2 changed files with 63 additions and 38 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

10
swift/common/memcached.py
View File

@ -49,7 +49,6 @@ import json
import logging import logging
import time import time
from bisect import bisect from bisect import bisect
from swift import gettext_ as _
from hashlib import md5 from hashlib import md5
from eventlet.green import socket from eventlet.green import socket
@ -163,10 +162,13 @@ class MemcacheRing(object):
def _exception_occurred(self, server, e, action='talking', def _exception_occurred(self, server, e, action='talking',
sock=None, fp=None, got_connection=True): sock=None, fp=None, got_connection=True):
if isinstance(e, Timeout): if isinstance(e, Timeout):
logging.error(_("Timeout %(action)s to memcached: %(server)s"), logging.error("Timeout %(action)s to memcached: %(server)s",
{'action': action, 'server': server}) {'action': action, 'server': server})
elif isinstance(e, socket.error):
logging.error("Error %(action)s to memcached: %(server)s: %(err)s",
{'action': action, 'server': server, 'err': e})
else: else:
logging.exception(_("Error %(action)s to memcached: %(server)s"), logging.exception("Error %(action)s to memcached: %(server)s",
{'action': action, 'server': server}) {'action': action, 'server': server})
try: try:
if fp: if fp:
@ -191,7 +193,7 @@ class MemcacheRing(object):
if err > now - ERROR_LIMIT_TIME] if err > now - ERROR_LIMIT_TIME]
if len(self._errors[server]) > ERROR_LIMIT_COUNT: if len(self._errors[server]) > ERROR_LIMIT_COUNT:
self._error_limited[server] = now + ERROR_LIMIT_DURATION self._error_limited[server] = now + ERROR_LIMIT_DURATION
logging.error(_('Error limiting server %s'), server) logging.error('Error limiting server %s', server)
def _get_conns(self, key): def _get_conns(self, key):
""" """

91
test/unit/common/test_memcached.py
View File

@ -17,19 +17,22 @@
"""Tests for swift.common.utils""" """Tests for swift.common.utils"""
from collections import defaultdict from collections import defaultdict
import errno
from hashlib import md5 from hashlib import md5
import logging
import socket import socket
import time import time
import unittest import unittest
from uuid import uuid4 from uuid import uuid4
import os
import mock
from eventlet import GreenPool, sleep, Queue from eventlet import GreenPool, sleep, Queue
from eventlet.pools import Pool from eventlet.pools import Pool
from swift.common import memcached from swift.common import memcached
from mock import patch, MagicMock from mock import patch, MagicMock
from test.unit import NullLoggingHandler from test.unit import debug_logger
class MockedMemcachePool(memcached.MemcacheConnPool): class MockedMemcachePool(memcached.MemcacheConnPool):
@ -48,15 +51,15 @@ class ExplodingMockMemcached(object):
def sendall(self, string): def sendall(self, string):
self.exploded = True self.exploded = True
raise socket.error() raise socket.error(errno.EPIPE, os.strerror(errno.EPIPE))
def readline(self): def readline(self):
self.exploded = True self.exploded = True
raise socket.error() raise socket.error(errno.EPIPE, os.strerror(errno.EPIPE))
def read(self, size): def read(self, size):
self.exploded = True self.exploded = True
raise socket.error() raise socket.error(errno.EPIPE, os.strerror(errno.EPIPE))
def close(self): def close(self):
pass pass
@ -169,6 +172,12 @@ class MockMemcached(object):
class TestMemcached(unittest.TestCase): class TestMemcached(unittest.TestCase):
"""Tests for swift.common.memcached""" """Tests for swift.common.memcached"""
def setUp(self):
self.logger = debug_logger()
patcher = mock.patch('swift.common.memcached.logging', self.logger)
self.addCleanup(patcher.stop)
patcher.start()
def test_get_conns(self): def test_get_conns(self):
sock1 = socket.socket(socket.AF_INET, socket.SOCK_STREAM) sock1 = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
sock1.bind(('127.0.0.1', 0)) sock1.bind(('127.0.0.1', 0))
@ -397,7 +406,6 @@ class TestMemcached(unittest.TestCase):
memcache_client.decr, 'some_key', delta=15) memcache_client.decr, 'some_key', delta=15)
def test_retry(self): def test_retry(self):
logging.getLogger().addHandler(NullLoggingHandler())
memcache_client = memcached.MemcacheRing( memcache_client = memcached.MemcacheRing(
['1.2.3.4:11211', '1.2.3.5:11211']) ['1.2.3.4:11211', '1.2.3.5:11211'])
mock1 = ExplodingMockMemcached() mock1 = ExplodingMockMemcached()
@ -405,10 +413,25 @@ class TestMemcached(unittest.TestCase):
memcache_client._client_cache['1.2.3.4:11211'] = MockedMemcachePool( memcache_client._client_cache['1.2.3.4:11211'] = MockedMemcachePool(
[(mock2, mock2)]) [(mock2, mock2)])
memcache_client._client_cache['1.2.3.5:11211'] = MockedMemcachePool( memcache_client._client_cache['1.2.3.5:11211'] = MockedMemcachePool(
[(mock1, mock1)]) [(mock1, mock1), (mock1, mock1)])
memcache_client.set('some_key', [1, 2, 3]) memcache_client.set('some_key', [1, 2, 3])
self.assertEqual(mock1.exploded, True)
self.assertEqual(self.logger.get_lines_for_level('error'), [
'Error talking to memcached: 1.2.3.5:11211: '
'[Errno 32] Broken pipe',
])
self.logger.clear()
mock1.exploded = False
self.assertEqual(memcache_client.get('some_key'), [1, 2, 3]) self.assertEqual(memcache_client.get('some_key'), [1, 2, 3])
self.assertEqual(mock1.exploded, True) self.assertEqual(mock1.exploded, True)
self.assertEqual(self.logger.get_lines_for_level('error'), [
'Error talking to memcached: 1.2.3.5:11211: '
'[Errno 32] Broken pipe',
])
# Check that we really did call create() twice
self.assertEqual(memcache_client._client_cache['1.2.3.5:11211'].mocks,
[])
def test_delete(self): def test_delete(self):
memcache_client = memcached.MemcacheRing(['1.2.3.4:11211']) memcache_client = memcached.MemcacheRing(['1.2.3.4:11211'])
@ -544,25 +567,23 @@ class TestMemcached(unittest.TestCase):
self.assertTrue(connections.empty()) self.assertTrue(connections.empty())
def test_connection_pool_timeout(self): def test_connection_pool_timeout(self):
orig_conn_pool = memcached.MemcacheConnPool connections = defaultdict(Queue)
try: pending = defaultdict(int)
connections = defaultdict(Queue) served = defaultdict(int)
pending = defaultdict(int)
served = defaultdict(int)
class MockConnectionPool(orig_conn_pool): class MockConnectionPool(memcached.MemcacheConnPool):
def get(self): def get(self):
pending[self.host] += 1 pending[self.host] += 1
conn = connections[self.host].get() conn = connections[self.host].get()
pending[self.host] -= 1 pending[self.host] -= 1
return conn return conn
def put(self, *args, **kwargs): def put(self, *args, **kwargs):
connections[self.host].put(*args, **kwargs) connections[self.host].put(*args, **kwargs)
served[self.host] += 1 served[self.host] += 1
memcached.MemcacheConnPool = MockConnectionPool
with mock.patch.object(memcached, 'MemcacheConnPool',
MockConnectionPool):
memcache_client = memcached.MemcacheRing(['1.2.3.4:11211', memcache_client = memcached.MemcacheRing(['1.2.3.4:11211',
'1.2.3.5:11211'], '1.2.3.5:11211'],
io_timeout=0.5, io_timeout=0.5,
@ -587,18 +608,20 @@ class TestMemcached(unittest.TestCase):
# Wait for the dust to settle. # Wait for the dust to settle.
p.waitall() p.waitall()
self.assertEqual(pending['1.2.3.5'], 8) self.assertEqual(pending['1.2.3.5'], 8)
self.assertEqual(len(memcache_client._errors['1.2.3.5:11211']), 8) self.assertEqual(len(memcache_client._errors['1.2.3.5:11211']), 8)
self.assertEqual(served['1.2.3.5'], 2) self.assertEqual(
self.assertEqual(pending['1.2.3.4'], 0) self.logger.get_lines_for_level('error'),
self.assertEqual(len(memcache_client._errors['1.2.3.4:11211']), 0) ['Timeout getting a connection to memcached: 1.2.3.5:11211'] * 8)
self.assertEqual(served['1.2.3.4'], 8) self.assertEqual(served['1.2.3.5'], 2)
self.assertEqual(pending['1.2.3.4'], 0)
self.assertEqual(len(memcache_client._errors['1.2.3.4:11211']), 0)
self.assertEqual(served['1.2.3.4'], 8)
# and we never got more put in that we gave out
self.assertEqual(connections['1.2.3.5'].qsize(), 2)
self.assertEqual(connections['1.2.3.4'].qsize(), 2)
# and we never got more put in that we gave out
self.assertEqual(connections['1.2.3.5'].qsize(), 2)
self.assertEqual(connections['1.2.3.4'].qsize(), 2)
finally:
memcached.MemcacheConnPool = orig_conn_pool
if __name__ == '__main__': if __name__ == '__main__':
unittest.main() unittest.main()