From 62a5b4bd206d6feb509cd397cea51dcd3620a21e Mon Sep 17 00:00:00 2001 From: melanie witt Date: Tue, 2 May 2017 21:47:12 +0000 Subject: [PATCH] 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 564958dba6c280eb8e11ae9bbc819c7da6e204bd) --- nova/cells/messaging.py | 4 +++- nova/tests/unit/test_utils.py | 9 +++++++++ nova/utils.py | 12 ++++++++++++ nova/virt/libvirt/vif.py | 12 +++++++++--- 4 files changed, 33 insertions(+), 4 deletions(-) diff --git a/nova/cells/messaging.py b/nova/cells/messaging.py index d8463df9dce6..c1ff9c4fdab9 100644 --- a/nova/cells/messaging.py +++ b/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) diff --git a/nova/tests/unit/test_utils.py b/nova/tests/unit/test_utils.py index 1d0a14838b8f..eb96b4450b45 100644 --- a/nova/tests/unit/test_utils.py +++ b/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') diff --git a/nova/utils.py b/nova/utils.py index a7979609f9ab..5e8a2223c59a 100644 --- a/nova/utils.py +++ b/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. diff --git a/nova/virt/libvirt/vif.py b/nova/virt/libvirt/vif.py index 249cde15e3b9..8c30ba832a75 100644 --- a/nova/virt/libvirt/vif.py +++ b/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: