Merge "Fix unicode errors in object controller logging"

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,

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):

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):

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:

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):

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(),