nova scheduler debug logs TypeError

[Friedrich Hiekel]

Description
===========

while activating nova scheduler logs for debugging I face this issue creating a new vm.
The vm is created anyway.

Steps to reproduce
==================
1. set debug in nova-scheduler to ture
 [DEFAULT]
 debug = true
2. create a vm
3. look into a nova-scheduler logs

Expected result
===============
debug log should shown without any stacktraces

Actual result
=============
an error/stacktrace is thrown

Environment
===========

Openstack: Yoga
Python: Python 3.10.6

Logs & Configs
==============
Stacktrace:
Traceback (most recent call last):
  File "/usr/lib/python3.10/logging/__init__.py", line 1100, in emit
    msg = self.format(record)
  File "/usr/local/lib/python3.10/dist-packages/oslo_log/handlers.py", line 156, in format
    return logging.StreamHandler.format(self, record) + record.reset_color
  File "/usr/lib/python3.10/logging/__init__.py", line 943, in format
    return fmt.format(record)
  File "/usr/local/lib/python3.10/dist-packages/oslo_log/formatters.py", line 271, in format
    return _json_dumps_with_fallback(message)
  File "/usr/local/lib/python3.10/dist-packages/oslo_log/formatters.py", line 181, in _json_dumps_with_fallback
    return jsonutils.dumps(obj, default=convert)
  File "/usr/local/lib/python3.10/dist-packages/oslo_serialization/jsonutils.py", line 202, in dumps
    return json.dumps(obj, default=default, **kwargs)
  File "/usr/lib/python3.10/json/__init__.py", line 238, in dumps
    **kw).encode(obj)
  File "/usr/lib/python3.10/json/encoder.py", line 199, in encode
    chunks = self.iterencode(o, _one_shot=True)
  File "/usr/lib/python3.10/json/encoder.py", line 257, in iterencode
    return _iterencode(o, 0)
TypeError: keys must be str, int, float, bool or None, not tuple
Call stack:
  File "/usr/local/lib/python3.10/dist-packages/eventlet/greenpool.py", line 88, in _spawn_n_impl
    func(*args, **kwargs)
  File "/usr/local/lib/python3.10/dist-packages/futurist/_green.py", line 71, in __call__
    self.work.run()
  File "/usr/local/lib/python3.10/dist-packages/futurist/_utils.py", line 49, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.10/dist-packages/oslo_messaging/rpc/server.py", line 165, in _process_incoming
    res = self.dispatcher.dispatch(message)
  File "/usr/local/lib/python3.10/dist-packages/oslo_messaging/rpc/dispatcher.py", line 309, in dispatch
    return self._do_dispatch(endpoint, method, ctxt, args)
  File "/usr/local/lib/python3.10/dist-packages/oslo_messaging/rpc/dispatcher.py", line 229, in _do_dispatch
    result = func(ctxt, **new_args)
  File "/usr/local/lib/python3.10/dist-packages/oslo_messaging/rpc/server.py", line 241, in inner
    return func(*args, **kwargs)
  File "/usr/local/lib/python3.10/dist-packages/nova/scheduler/manager.py", line 223, in select_destinations
    selections = self._select_destinations(
  File "/usr/local/lib/python3.10/dist-packages/nova/scheduler/manager.py", line 250, in _select_destinations
    selections = self._schedule(
  File "/usr/local/lib/python3.10/dist-packages/nova/scheduler/manager.py", line 360, in _schedule
    hosts = self._get_sorted_hosts(spec_obj, hosts, num)
  File "/usr/local/lib/python3.10/dist-packages/nova/scheduler/manager.py", line 615, in _get_sorted_hosts
    weighed_hosts = self.host_manager.get_weighed_hosts(
  File "/usr/local/lib/python3.10/dist-packages/nova/scheduler/host_manager.py", line 606, in get_weighed_hosts
    return self.weight_handler.get_weighed_objects(self.weighers,
  File "/usr/local/lib/python3.10/dist-packages/nova/weights.py", line 136, in get_weighed_objects
    LOG.debug(
Message: '%s: raw weights %s'
Arguments: ('CPUWeigher', {('compute-01', 'compute-01): 127.0, ('worker-01', 'worker-01'): 125.0})

[Friedrich Hiekel (fhiekel)]

https://review.opendev.org/c/openstack/nova/+/889311

[Uggla (rene-ribaud)]

Hello Friedrich,

Thanks for submitting this bug and the associated patch.
That sounds good to me so I traiged it as "fix committed"

[sean mooney (sean-k-mooney)]

the patch has not been merged and the one submitted to gerrit is doing the reverse fo the one attached
so setting this back to new

[Artom Lifshitz (notartom)]

I know in [1] Amit is saying that he can't see the TypeErrors in the logs, but I'm not sure how this ever worked. Tuple keys, while supported in Python, are not supported by json.dumps (which is what oslo_serialization.jsonutils.dumps calls under the hood). See for yourself:

artom@zoe:~/src/nova$ python3.6
Python 3.6.15 (default, Aug 2 2023, 00:00:00)
[GCC 13.2.1 20230728 (Red Hat 13.2.1-1)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> foo = {(1, 2): 'bar'}
>>> import json
>>> json.dumps(foo)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/lib64/python3.6/json/__init__.py", line 231, in dumps
    return _default_encoder.encode(obj)
  File "/usr/lib64/python3.6/json/encoder.py", line 199, in encode
    chunks = self.iterencode(o, _one_shot=True)
  File "/usr/lib64/python3.6/json/encoder.py", line 257, in iterencode
    return _iterencode(o, 0)
TypeError: keys must be a string

The commit that introduced the logging, 154ab7b2f9ad80fe432d2c036d5e8c4ee171897b, merged without any tests, so I don't think it ever worked.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/nova/+/904060