"UserWarning: Cannot convert <oslo_db.sqlalchemy.enginefacade._Default object at 0x7f5db695a2b8> to primitive, will raise ValueError instead of warning in version 3.0" seen in nova functional tests due to CheatingSerializer

[Matt Riedemann]

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22UserWarning%3A%20Cannot%20convert%20%3Coslo_db.sqlalchemy.enginefacade._Default%20object%20at%5C%22&from=7d

This shows up in nova functional test runs. This is the stacktrace from one of the tests:

    2018-10-22 11:16:41,704 ERROR [root] Original exception being dropped: ['Traceback (most recent call last):\n', ' File "nova/exception_wrapper.py", line 69, in wrapped\n return f(self, context, *args, **kw)\n', ' File "nova/compute/utils.py", line 1157, in decorated_function\n return function(self, context, *args, **kwargs)\n', ' File "nova/compute/manager.py", line 216, in decorated_function\n kwargs[\'instance\'], e, sys.exc_info())\n', ' File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__\n self.force_reraise()\n', ' File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise\n six.reraise(self.type_, self.value, self.tb)\n', ' File "nova/compute/manager.py", line 204, in decorated_function\n return function(self, context, *args, **kwargs)\n', ' File "nova/compute/manager.py", line 6077, in check_can_live_migrate_destination\n block_migration, disk_over_commit)\n', ' File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 1062, in __call__\n return _mock_self._mock_call(*args, **kwargs)\n', ' File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 1128, in _mock_call\n ret_val = effect(*args, **kwargs)\n', ' File "nova/tests/functional/test_servers.py", line 2864, in fake_check_can_live_migrate_destination\n reason=\'test_live_migrate_pre_check_fails\')\n', 'MigrationPreCheckError: Migration pre-check error: test_live_migrate_pre_check_fails\n']
    2018-10-22 11:16:41,704 ERROR [oslo_messaging.rpc.server] Exception during message handling
    Traceback (most recent call last):
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 163, in _process_incoming
        res = self.dispatcher.dispatch(message)
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 265, in dispatch
        return self._do_dispatch(endpoint, method, ctxt, args)
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 194, in _do_dispatch
        result = func(ctxt, **new_args)
      File "nova/exception_wrapper.py", line 79, in wrapped
        function_name, call_dict, binary, tb)
      File "nova/exception_wrapper.py", line 33, in _emit_exception_notification
        args)
      File "nova/exception_wrapper.py", line 56, in _emit_legacy_exception_notification
        notifier.error(context, function_name, payload)
      File "nova/rpc.py", line 402, in _notify
        getattr(self.notifier, priority)(ctxt, event_type, payload)
      File "nova/tests/unit/fake_notifier.py", line 99, in _notify
        payload = self._serializer.serialize_entity(ctxt, payload)
      File "nova/rpc.py", line 134, in serialize_entity
        return self._base.serialize_entity(context, entity)
      File "nova/rpc.py", line 123, in serialize_entity
        return jsonutils.to_primitive(entity, convert_instances=True)
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 170, in to_primitive
        for k, v in value.items()}
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 170, in <dictcomp>
        for k, v in value.items()}
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 170, in to_primitive
        for k, v in value.items()}
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 170, in <dictcomp>
        for k, v in value.items()}
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 181, in to_primitive
        return recursive(value.__dict__, level=level + 1)
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 170, in to_primitive
        for k, v in value.items()}
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 170, in <dictcomp>
        for k, v in value.items()}
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 181, in to_primitive
        return recursive(value.__dict__, level=level + 1)
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 170, in to_primitive
        for k, v in value.items()}
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 170, in <dictcomp>
        for k, v in value.items()}
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 181, in to_primitive
        return recursive(value.__dict__, level=level + 1)
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 170, in to_primitive
        for k, v in value.items()}
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 170, in <dictcomp>
        for k, v in value.items()}
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 170, in to_primitive
        for k, v in value.items()}
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 170, in <dictcomp>
        for k, v in value.items()}
      File "/home/osboxes/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_serialization/jsonutils.py", line 192, in to_primitive
        "instead of warning in version 3.0" % (value,))
    UserWarning: Cannot convert <oslo_db.sqlalchemy.enginefacade._Default object at 0x7f364c63f6a8> to primitive, will raise ValueError instead of warning in version 3.0

So there is something in the notification payload that has an instance of oslo_db.sqlalchemy.enginefacade._Default in it and the serializer doesn't know how to handle that. My guess would be there are versioned objects in the payload and those versioned objects have a context which has a db_connection engine facade in it, maybe because of using the CheatingSerializer fixture in nova?

[Matt Riedemann (mriedem)]

This is the payload generated from the exception wrapper code:

{'args': {'block_migration': True, 'instance': Instance(access_ip_v4=None,access_ip_v6=None,architecture='x86_64',auto_disk_config=False,availability_zone='nova',cell_name=None,cleaned=False,config_drive='',created_at=2018-10-22T15:42:32Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=<?>,disable_terminate=False,display_description=None,display_name='some-server',ec2_ids=<?>,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=<?>,host='host1',hostname='some-server',id=1,image_ref='155d900f-4e14-4e4c-a73d-069cbf4541e6',info_cache=InstanceInfoCache,instance_type_id=1,kernel_id='',key_data=None,key_name=None,keypairs=<?>,launch_index=0,launched_at=2018-10-22T15:42:33Z,launched_on='host1',locked=False,locked_by=None,memory_mb=512,metadata={},migration_context=<?>,new_flavor=<?>,node='host1',numa_topology=<?>,old_flavor=<?>,os_type=None,pci_devices=<?>,pci_requests=<?>,power_state=1,progress=0,project_id='6f70656e737461636b20342065766572',ramdisk_id='',reservation_id='r-irn39bnk',root_device_name='/dev/sda',root_gb=1,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='',image_architecture='x86_64',image_base_image_ref='155d900f-4e14-4e4c-a73d-069cbf4541e6',image_container_format='raw',image_disk_format='raw',image_kernel_id='nokernel',image_min_disk='1',image_ramdisk_id='nokernel',owner_project_name=None,owner_user_name=None},tags=<?>,task_state='migrating',terminated_at=None,trusted_certs=<?>,updated_at=2018-10-22T15:42:33Z,user_data=None,user_id='admin',uuid=cda73dc0-0db6-4974-8c46-26731b30d471,vcpu_model=<?>,vcpus=1,vm_mode=None,vm_state='active'), 'disk_over_commit': None, 'ctxt': <nova.context.RequestContext object at 0x7f5a2354bfd0>}, 'exception': {'kwargs': {'code': 500, 'reason': 'test_live_migrate_pre_check_fails'}, 'class': 'MigrationPreCheckError', 'message': u'Migration pre-check error: test_live_migrate_pre_check_fails'}}

https://github.com/openstack/nova/blob/6cec655a680bbafd7e0d51e5bd97fa88ec13c626/nova/exception_wrapper.py#L55

Those are the args from the ComputeManager.check_can_live_migrate_destination method called during the functional test.

So my guess is the fake notifier's serializer is trying to serialize a RequestContext, because it's an argument in the payload, and blows up since the db_connection engine factory is still in the request context object.

[Matt Riedemann (mriedem)]

The CheatingSerializer fixture is definitely the problem because if you remove that the error goes away.

[Matt Riedemann (mriedem)]

We probably don't need to fix this on stable, nor do we really need to, since the fallback kwarg was added to oslo.serialization jsonutils.to_primitive in 2.21.1:

https://review.openstack.org/#/c/503993/

But we didn't require that minimum version yet, so we should really only be able to fix on master and bump the minimum required version of oslo.serialization.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/612445

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/612445
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=5316a8a0cdb5a121a6af268d8bb078aee3ead4c4
Submitter: Zuul
Branch: master

commit 5316a8a0cdb5a121a6af268d8bb078aee3ead4c4
Author: Matt Riedemann <email address hidden>
Date: Mon Oct 22 12:37:37 2018 -0400

    Fix jsonutils.to_primitive UserWarning

    The CheatingSerializer fixture used in nova tests keeps
    the RequestContext.db_connection set on the context object
    which otherwise wouldn't normally happen. The context object
    can show up in error notification payloads because of how
    nova.exception_wrapper.wrap_exception works. That payload
    is eventually serialized for notifications and since the
    cheated RequestContext.db_connection is set and cannot be
    serialized, it results in a UserWarning from the
    jsonutils.to_primitive method (called via JsonPayloadSerializer).

    This will eventually result in failures when that UserWarning
    is made into an error.

    To fix this, we can pass a fallback method to to_primitive()
    which will serialize a RequestContext object the same way that
    RequestContextSerializer serializes a context - by simply
    converting it to dict form.

    Since this only affects test runs, because of using the
    CheatingSerializer fixture, it should have no impact on
    runtime serializations.

    Error logging is added to the FakeNotifier since it's hard
    to know what is wrong in the payload unless it is logged.

    Also, the WarningsFixture is updated to make sure we don't
    introduce new UserWarnings for the serialization issue.

    The jsonutils.to_primitive() fallback method was added to
    oslo.serialization via commit cdb2f60d26e3b65b6370f87b2e9864045651c117
    in 2.21.1 so we have to bump our minimum required version
    of that library as well.

    Change-Id: Id9f960a0c7c8897dbb9edf53b4723154341412d6
    Closes-Bug: #1799249

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 19.0.0.0rc1 release candidate.