From ca2f6d13b6aa79d5e3c184955280b4a3ea17cd7d Mon Sep 17 00:00:00 2001 From: Alistair Coles Date: Thu, 7 Jul 2016 11:31:31 +0100 Subject: [PATCH] Fix unicode errors in object controller logging Change swift.proxy.server.Application.error_occurred() to decode message as utf-8 in same way that the exception_occurred() method was changed in [1]. This prevents a unicode error when logging error responses in swift.proxy.controllers.base.Controller._make_request() for paths that have non-ascii characters. Although the unicode error is currently caught by a surrounding except clause, the logging and error limiting treatment is different for ascii vs non-ascii paths. This patch makes them consistent. Fix the server type reported in _make_request() to be the correct server type, not always 'Container Server'. Fix path arg passed to _get_conn_response in swift.proxy.controllers.obj.BaseObjectController to be req.path rather than req. Add unit tests for error_occurred() being called with non-ascii paths and extend tests for exception_occurred() (see Related-Bug). [1] Change-Id: Icb7284eb5abc9869c1620ee6366817112d8e5587 Related-Bug: #1597210 Change-Id: I285499d164bff94835bdddb25d2af6d73114c281 --- swift/proxy/controllers/base.py | 5 +- swift/proxy/controllers/obj.py | 2 +- swift/proxy/server.py | 2 +- test/unit/__init__.py | 4 +- test/unit/proxy/controllers/test_obj.py | 137 +++++++++++++++++++++++- test/unit/proxy/test_server.py | 54 ++++++++++ 6 files changed, 196 insertions(+), 8 deletions(-) diff --git a/swift/proxy/controllers/base.py b/swift/proxy/controllers/base.py index c1a909dad5..f9b1175e6d 100644 --- a/swift/proxy/controllers/base.py +++ b/swift/proxy/controllers/base.py @@ -1545,10 +1545,11 @@ class Controller(object): self.app.error_occurred( node, _('ERROR %(status)d ' 'Trying to %(method)s %(path)s' - 'From Container Server') % { + ' From %(type)s Server') % { 'status': resp.status, 'method': method, - 'path': path}) + 'path': path, + 'type': self.server_type}) except (Exception, Timeout): self.app.exception_occurred( node, self.server_type, diff --git a/swift/proxy/controllers/obj.py b/swift/proxy/controllers/obj.py index 54ee996aa7..a948bbb6d2 100644 --- a/swift/proxy/controllers/obj.py +++ b/swift/proxy/controllers/obj.py @@ -349,7 +349,7 @@ class BaseObjectController(Controller): for putter in putters: if putter.failed: continue - pile.spawn(self._get_conn_response, putter, req, + pile.spawn(self._get_conn_response, putter, req.path, self.app.logger.thread_locals, final_phase=final_phase) def _handle_response(putter, response): diff --git a/swift/proxy/server.py b/swift/proxy/server.py index 98072aaf26..c35a3e1a97 100644 --- a/swift/proxy/server.py +++ b/swift/proxy/server.py @@ -509,7 +509,7 @@ class Application(object): """ self._incr_node_errors(node) self.logger.error(_('%(msg)s %(ip)s:%(port)s/%(device)s'), - {'msg': msg, 'ip': node['ip'], + {'msg': msg.decode('utf-8'), 'ip': node['ip'], 'port': node['port'], 'device': node['device']}) def iter_nodes(self, ring, partition, node_iter=None): diff --git a/test/unit/__init__.py b/test/unit/__init__.py index 97df0004b2..7afc5a946e 100644 --- a/test/unit/__init__.py +++ b/test/unit/__init__.py @@ -959,9 +959,9 @@ def fake_http_connect(*code_iter, **kwargs): self.body = self.body[amt:] return rv - def send(self, amt=None): + def send(self, data=None): if self.give_send: - self.give_send(self, amt) + self.give_send(self, data) am_slow, value = self.get_slow() if am_slow: if self.received < 4: diff --git a/test/unit/proxy/controllers/test_obj.py b/test/unit/proxy/controllers/test_obj.py index e24d152d26..741be84b20 100755 --- a/test/unit/proxy/controllers/test_obj.py +++ b/test/unit/proxy/controllers/test_obj.py @@ -31,6 +31,7 @@ from six.moves import range import swift from swift.common import utils, swob, exceptions +from swift.common.exceptions import ChunkWriteTimeout from swift.common.header_key_dict import HeaderKeyDict from swift.proxy import server as proxy_server from swift.proxy.controllers import obj @@ -856,19 +857,151 @@ class TestReplicatedObjController(BaseObjectControllerMixin, node_error_count(self.app, object_ring.devs[1]), self.app.error_suppression_limit + 1) - def test_PUT_connect_exception_with_unicode_path_and_locale(self): + def test_PUT_connect_exception_with_unicode_path(self): expected = 201 statuses = ( Exception('Connection refused: Please insert ten dollars'), - 201, 201) + 201, 201, 201) req = swob.Request.blank('/v1/AUTH_kilroy/%ED%88%8E/%E9%90%89', method='PUT', body='life is utf-gr8') + self.app.logger.clear() with set_http_connect(*statuses): resp = req.get_response(self.app) self.assertEqual(resp.status_int, expected) + log_lines = self.app.logger.get_lines_for_level('error') + self.assertFalse(log_lines[1:]) + self.assertIn('ERROR with Object server', log_lines[0]) + self.assertIn(req.swift_entity_path.decode('utf-8'), log_lines[0]) + self.assertIn('re: Expect: 100-continue', log_lines[0]) + + def test_PUT_get_expect_errors_with_unicode_path(self): + def do_test(statuses): + req = swob.Request.blank('/v1/AUTH_kilroy/%ED%88%8E/%E9%90%89', + method='PUT', + body='life is utf-gr8') + self.app.logger.clear() + with set_http_connect(*statuses): + resp = req.get_response(self.app) + + self.assertEqual(resp.status_int, 201) + log_lines = self.app.logger.get_lines_for_level('error') + self.assertFalse(log_lines[1:]) + return log_lines + + log_lines = do_test((201, (507, None), 201, 201)) + self.assertIn('ERROR Insufficient Storage', log_lines[0]) + + log_lines = do_test((201, (503, None), 201, 201)) + self.assertIn('ERROR 503 Expect: 100-continue From Object Server', + log_lines[0]) + + def test_PUT_send_exception_with_unicode_path(self): + def do_test(exc): + conns = set() + + def capture_send(conn, data): + conns.add(conn) + if len(conns) == 2: + raise exc + + req = swob.Request.blank('/v1/AUTH_kilroy/%ED%88%8E/%E9%90%89', + method='PUT', + body='life is utf-gr8') + self.app.logger.clear() + with set_http_connect(201, 201, 201, give_send=capture_send): + resp = req.get_response(self.app) + + self.assertEqual(resp.status_int, 201) + log_lines = self.app.logger.get_lines_for_level('error') + self.assertFalse(log_lines[1:]) + self.assertIn('ERROR with Object server', log_lines[0]) + self.assertIn(req.swift_entity_path.decode('utf-8'), log_lines[0]) + self.assertIn('Trying to write to', log_lines[0]) + + do_test(Exception('Exception while sending data on connection')) + do_test(ChunkWriteTimeout()) + + def test_PUT_final_response_errors_with_unicode_path(self): + def do_test(statuses): + req = swob.Request.blank('/v1/AUTH_kilroy/%ED%88%8E/%E9%90%89', + method='PUT', + body='life is utf-gr8') + self.app.logger.clear() + with set_http_connect(*statuses): + resp = req.get_response(self.app) + + self.assertEqual(resp.status_int, 201) + log_lines = self.app.logger.get_lines_for_level('error') + self.assertFalse(log_lines[1:]) + return req, log_lines + + req, log_lines = do_test((201, (100, Exception('boom')), 201)) + self.assertIn('ERROR with Object server', log_lines[0]) + self.assertIn(req.path.decode('utf-8'), log_lines[0]) + self.assertIn('Trying to get final status of PUT', log_lines[0]) + + req, log_lines = do_test((201, (100, Timeout()), 201)) + self.assertIn('ERROR with Object server', log_lines[0]) + self.assertIn(req.path.decode('utf-8'), log_lines[0]) + self.assertIn('Trying to get final status of PUT', log_lines[0]) + + req, log_lines = do_test((201, (100, 507), 201)) + self.assertIn('ERROR Insufficient Storage', log_lines[0]) + + req, log_lines = do_test((201, (100, 500), 201)) + self.assertIn('ERROR 500 From Object Server', log_lines[0]) + self.assertIn(req.path.decode('utf-8'), log_lines[0]) + + def test_DELETE_errors(self): + # verify logged errors with and without non-ascii characters in path + def do_test(path, statuses): + + req = swob.Request.blank('/v1' + path, + method='DELETE', + body='life is utf-gr8') + self.app.logger.clear() + with set_http_connect(*statuses): + resp = req.get_response(self.app) + + self.assertEqual(resp.status_int, 201) + log_lines = self.app.logger.get_lines_for_level('error') + self.assertFalse(log_lines[1:]) + return req, log_lines + + req, log_lines = do_test('/AUTH_kilroy/ascii/ascii', + (201, 500, 201, 201)) + self.assertIn('Trying to DELETE', log_lines[0]) + self.assertIn(req.swift_entity_path.decode('utf-8'), log_lines[0]) + self.assertIn(' From Object Server', log_lines[0]) + + req, log_lines = do_test('/AUTH_kilroy/%ED%88%8E/%E9%90%89', + (201, 500, 201, 201)) + self.assertIn('Trying to DELETE', log_lines[0]) + self.assertIn(req.swift_entity_path.decode('utf-8'), log_lines[0]) + self.assertIn(' From Object Server', log_lines[0]) + + req, log_lines = do_test('/AUTH_kilroy/ascii/ascii', + (201, 507, 201, 201)) + self.assertIn('ERROR Insufficient Storage', log_lines[0]) + + req, log_lines = do_test('/AUTH_kilroy/%ED%88%8E/%E9%90%89', + (201, 507, 201, 201)) + self.assertIn('ERROR Insufficient Storage', log_lines[0]) + + req, log_lines = do_test('/AUTH_kilroy/ascii/ascii', + (201, Exception(), 201, 201)) + self.assertIn('Trying to DELETE', log_lines[0]) + self.assertIn(req.swift_entity_path.decode('utf-8'), log_lines[0]) + self.assertIn('ERROR with Object server', log_lines[0]) + + req, log_lines = do_test('/AUTH_kilroy/%ED%88%8E/%E9%90%89', + (201, Exception(), 201, 201)) + self.assertIn('Trying to DELETE', log_lines[0]) + self.assertIn(req.swift_entity_path.decode('utf-8'), log_lines[0]) + self.assertIn('ERROR with Object server', log_lines[0]) def test_PUT_error_during_transfer_data(self): class FakeReader(object): diff --git a/test/unit/proxy/test_server.py b/test/unit/proxy/test_server.py index 6452fb5b0c..44a23ef6f4 100644 --- a/test/unit/proxy/test_server.py +++ b/test/unit/proxy/test_server.py @@ -874,6 +874,60 @@ class TestProxyServer(unittest.TestCase): self.assertEqual(controller.__name__, 'InfoController') + def test_exception_occurred(self): + def do_test(additional_info): + logger = debug_logger('test') + app = proxy_server.Application({}, FakeMemcache(), + account_ring=FakeRing(), + container_ring=FakeRing(), + logger=logger) + node = app.container_ring.get_part_nodes(0)[0] + node_key = app._error_limit_node_key(node) + self.assertNotIn(node_key, app._error_limiting) # sanity + try: + raise Exception('kaboom1!') + except Exception as err: + app.exception_occurred(node, 'server-type', additional_info) + + self.assertEqual(1, app._error_limiting[node_key]['errors']) + line = logger.get_lines_for_level('error')[-1] + self.assertIn('server-type server', line) + self.assertIn(additional_info.decode('utf8'), line) + self.assertIn(node['ip'], line) + self.assertIn(str(node['port']), line) + self.assertIn(node['device'], line) + log_args, log_kwargs = logger.log_dict['error'][-1] + self.assertTrue(log_kwargs['exc_info']) + self.assertEqual(err, log_kwargs['exc_info'][1]) + + do_test('success') + do_test('succès') + do_test(u'success') + + def test_error_occurred(self): + def do_test(msg): + logger = debug_logger('test') + app = proxy_server.Application({}, FakeMemcache(), + account_ring=FakeRing(), + container_ring=FakeRing(), + logger=logger) + node = app.container_ring.get_part_nodes(0)[0] + node_key = app._error_limit_node_key(node) + self.assertNotIn(node_key, app._error_limiting) # sanity + + app.error_occurred(node, msg) + + self.assertEqual(1, app._error_limiting[node_key]['errors']) + line = logger.get_lines_for_level('error')[-1] + self.assertIn(msg.decode('utf8'), line) + self.assertIn(node['ip'], line) + self.assertIn(str(node['port']), line) + self.assertIn(node['device'], line) + + do_test('success') + do_test('succès') + do_test(u'success') + def test_error_limit_methods(self): logger = debug_logger('test') app = proxy_server.Application({}, FakeMemcache(),