metadata: don't crash proxy on non-unicode user data

We attempt to log every successful metadata response with LOG.debug. But
as per oslo.log docs [1], we should make sure that what we pass into the
library is unicode.

Http.request returns a tuple of Response object and a string, which is
bytes in Python 2.x [2].

That's why we need to convert the response content to unicode before
passing it into oslo.log.

To achieve it, we utilize encodeutils.safe_decode with 'replace' errors
handling strategy, so that we don't get exceptions on input that does
not conform unicode.

For the unit test case, we pass a string that is not expected to convert
to unicode with errors='strict' strategy or similar, and check that we
still don't crash.

While at it, we remove a check for the number of log calls being
triggered, because it's something that we should avoid validating in
test cases, and it cannot trigger a real bug. The mock that was used to
count the number would also hide the bug that we try to reproduce.

Note that the bug does not require debug to be set because the crash
occurs before oslo.log machinery decides it should not log the message.

[1]: http://docs.openstack.org/developer/oslo.log/usage.html#no-more-implicit-conversion-to-unicode-str
[2]: http://bitworking.org/projects/httplib2/doc/html/libhttplib2.html#httplib2.Http.request

Closes-Bug: #1501772
Change-Id: I6a32c40ff117fae43913386134c8981539697ce8
(cherry picked from commit 80e3d9be49)

neutron/agent/metadata/namespace_proxy.py

@@ -15,6 +15,7 @@
 import httplib2
 from oslo_config import cfg
 from oslo_log import log as logging
+from oslo_utils import encodeutils
 import six
 import six.moves.urllib.parse as urlparse
 import webob
@@ -88,7 +89,7 @@ class NetworkMetadataProxyHandler(object):
 
         if resp.status == 200:
             LOG.debug(resp)
-            LOG.debug(content)
+            LOG.debug(encodeutils.safe_decode(content, errors='replace'))
             response = webob.Response()
             response.status = resp.status
             response.headers['Content-Type'] = resp['content-type']

neutron/tests/unit/agent/metadata/test_namespace_proxy.py

@@ -21,6 +21,7 @@ from neutron.agent.metadata import namespace_proxy as ns_proxy
 from neutron.common import exceptions
 from neutron.common import utils
 from neutron.tests import base
+from neutron import wsgi
 
 
 class FakeConf(object):
@@ -38,9 +39,6 @@ class FakeConf(object):
 class TestNetworkMetadataProxyHandler(base.BaseTestCase):
     def setUp(self):
         super(TestNetworkMetadataProxyHandler, self).setUp()
-        self.log_p = mock.patch.object(ns_proxy, 'LOG')
-        self.log = self.log_p.start()
-
         self.handler = ns_proxy.NetworkMetadataProxyHandler('router_id')
 
     def test_call(self):
@@ -67,7 +65,6 @@ class TestNetworkMetadataProxyHandler(base.BaseTestCase):
             proxy_req.side_effect = Exception
             retval = self.handler(req)
             self.assertIsInstance(retval, webob.exc.HTTPInternalServerError)
-            self.assertEqual(len(self.log.mock_calls), 2)
             self.assertTrue(proxy_req.called)
 
     def test_proxy_request_router_200(self):
@@ -100,13 +97,13 @@ class TestNetworkMetadataProxyHandler(base.BaseTestCase):
             self.assertEqual(retval.headers['Content-Type'], 'text/plain')
             self.assertEqual(b'content', retval.body)
 
-    def test_proxy_request_network_200(self):
+    def _test_proxy_request_network_200(self, content):
         self.handler.network_id = 'network_id'
 
         resp = mock.MagicMock(status=200)
         with mock.patch('httplib2.Http') as mock_http:
             resp.__getitem__.return_value = "application/json"
-            mock_http.return_value.request.return_value = (resp, '{}')
+            mock_http.return_value.request.return_value = (resp, content)
 
             retval = self.handler._proxy_request('192.168.1.1',
                                                  'GET',
@@ -129,7 +126,13 @@ class TestNetworkMetadataProxyHandler(base.BaseTestCase):
 
             self.assertEqual(retval.headers['Content-Type'],
                              'application/json')
-            self.assertEqual(b'{}', retval.body)
+            self.assertEqual(wsgi.encode_body(content), retval.body)
+
+    def test_proxy_request_network_200(self):
+        self._test_proxy_request_network_200('{}')
+
+    def test_proxy_request_network_200_unicode_in_content(self):
+        self._test_proxy_request_network_200('Gl\xfcck')
 
     def _test_proxy_request_network_4xx(self, status, method, expected):
         self.handler.network_id = 'network_id'