Use six.text_type() when logging Instance object

We're seeing a trace in gate jobs, for example:

  UnicodeDecodeError: 'ascii' codec can't decode byte 0xc3 in position
  402: ordinal not in range(128)

when attempting to log an Instance object with a unicode display name.

This resurfaced relatively recently because of the change in devstack
to use the new OSJournalHandler with use_journal=True which is
suspected of causing some deadlock issues [1] unrelated to this bug.

The problem occurs in code that logs an entire Instance object when
the object has a field with unicode characters in it (display_name).
When the object is sent to logging, the UnicodeDecodeError is raised
while formatting the log record here [2]. This implies an implicit
conversion attempt to unicode at this point.

I found that with the Instance object, the conversion to unicode fails
with the UnicodeDecodeError unless the encoding 'utf-8' is explicitly
specified to six.text_type(). And when specifying an encoding to
six.text_type(), the argument to convert must be a string, not an
Instance object, so this does the conversion in two steps as a utility
function:

  1. Get the string representation of the Instance with repr()
  2. Call six.text_type(instance_repr, 'utf-8') passing the encoding
     if not six.PY3

Closes-Bug: #1580728

[1] https://review.openstack.org/#/c/462163
[2] https://github.com/python/cpython/blob/2e576f5/Lib/logging/__init__.py#L338

Change-Id: I0fc3ae02cb2e401b3240faf0d8b6aa5dc52b91fc
(cherry picked from commit 564958dba6)

nova/cells/messaging.py

@@ -1008,8 +1008,10 @@ class _BroadcastMessageMethods(_BaseMessageMethods):
         instance.obj_reset_changes(items_to_remove)
         instance.cell_name = _reverse_path(message.routing_path)
 
+        # instance.display_name could be unicode
+        instance_repr = utils.get_obj_repr_unicode(instance)
         LOG.debug("Got update for instance: %(instance)s",
-                  {'instance': instance}, instance_uuid=instance.uuid)
+                  {'instance': instance_repr}, instance_uuid=instance.uuid)
 
         expected_vm_state = self._get_expected_vm_state(instance)
         expected_task_state = self._get_expected_task_state(instance)

nova/tests/unit/test_utils.py

@@ -38,6 +38,7 @@ import nova
 from nova import context
 from nova import exception
 from nova.objects import base as obj_base
+from nova.objects import instance as instance_obj
 from nova import test
 from nova.tests.unit.objects import test_objects
 from nova.tests.unit import utils as test_utils
@@ -243,6 +244,14 @@ class GenericUtilsTestCase(test.NoDBTestCase):
         self.assertEqual(
             value, utils.get_hash_str(base_unicode))
 
+    def test_get_obj_repr_unicode(self):
+        instance = instance_obj.Instance()
+        instance.display_name = u'\u00CD\u00F1st\u00E1\u00F1c\u00E9'
+        # should be a bytes string if python2 before conversion
+        self.assertIs(str, type(repr(instance)))
+        self.assertIs(six.text_type,
+                      type(utils.get_obj_repr_unicode(instance)))
+
     def test_use_rootwrap(self):
         self.flags(disable_rootwrap=False, group='workarounds')
         self.flags(rootwrap_config='foo')

nova/utils.py

@@ -1258,6 +1258,18 @@ def get_sha256_str(base_str):
     return hashlib.sha256(base_str).hexdigest()
 
 
+def get_obj_repr_unicode(obj):
+    """Returns a string representation of an object converted to unicode.
+
+    In the case of python 3, this just returns the repr() of the object,
+    else it converts the repr() to unicode.
+    """
+    obj_repr = repr(obj)
+    if not six.PY3:
+        obj_repr = six.text_type(obj_repr, 'utf-8')
+    return obj_repr
+
+
 def filter_and_format_resource_metadata(resource_type, resource_list,
         search_filts, metadata_type=None):
     """Get all metadata for a list of resources after filtering.

nova/virt/libvirt/vif.py

@@ -521,9 +521,11 @@ class LibvirtGenericVIFDriver(object):
         vif_type = vif['type']
         vnic_type = vif['vnic_type']
 
+        # instance.display_name could be unicode
+        instance_repr = utils.get_obj_repr_unicode(instance)
         LOG.debug('vif_type=%(vif_type)s instance=%(instance)s '
                   'vif=%(vif)s virt_type=%(virt_type)s',
-                  {'vif_type': vif_type, 'instance': instance,
+                  {'vif_type': vif_type, 'instance': instance_repr,
                    'vif': vif, 'virt_type': virt_type})
 
         if vif_type is None:
@@ -766,9 +768,11 @@ class LibvirtGenericVIFDriver(object):
     def plug(self, instance, vif):
         vif_type = vif['type']
 
+        # instance.display_name could be unicode
+        instance_repr = utils.get_obj_repr_unicode(instance)
         LOG.debug('vif_type=%(vif_type)s instance=%(instance)s '
                   'vif=%(vif)s',
-                  {'vif_type': vif_type, 'instance': instance,
+                  {'vif_type': vif_type, 'instance': instance_repr,
                    'vif': vif})
 
         if vif_type is None:
@@ -954,9 +958,11 @@ class LibvirtGenericVIFDriver(object):
     def unplug(self, instance, vif):
         vif_type = vif['type']
 
+        # instance.display_name could be unicode
+        instance_repr = utils.get_obj_repr_unicode(instance)
         LOG.debug('vif_type=%(vif_type)s instance=%(instance)s '
                   'vif=%(vif)s',
-                  {'vif_type': vif_type, 'instance': instance,
+                  {'vif_type': vif_type, 'instance': instance_repr,
                    'vif': vif})
 
         if vif_type is None: