← Back to team overview

yahoo-eng-team team mailing list archive

[Bug 2119218] [NEW] RecursionError when creating an instance with debug logging enabled

 

Public bug reported:

Description
===========
When debug logging is enabled in nova api, an error occurs when creating an instance.

Steps to reproduce
==================
Create an instance via CLI

Expected result
===============
Instance is created and no error occur.

Actual result
=============
Instance is created, but an error occurs:

No Server found for f17f59b0-268c-47fb-accd-c459030ed439: Server Error for url: https://xxx/v2.1/servers/f17f59b0-268c-47fb-accd-c459030ed439, Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'RecursionError'>

Environment
===========
Nova 2024.1

Logs & Configs
==============
Taking a deeper look in the logs reveals this stacktrace:

Traceback (most recent call last):
  File /usr/local/lib/python3.10/site-packages/nova/api/openstack/wsgi.py, line 658, in wrapped
    return f(*args, **kwargs)
  File /usr/local/lib/python3.10/site-packages/nova/api/openstack/compute/servers.py, line 477, in show
    return self._view_builder.show(
  File /usr/local/lib/python3.10/site-packages/nova/api/openstack/compute/views/servers.py, line 364, in show
    server[server][key[] = getattr(instance, attr)
  File /usr/local/lib/python3.10/site-packages/nova/objects/instance.py, line 305, in name
    base_name = CONF.instance_name_template % self.id
  File /usr/local/lib/python3.10/site-packages/oslo_versionedobjects/base.py, line 67, in getter
    self.obj_load_attr(name)
  File /usr/local/lib/python3.10/site-packages/nova/objects/base.py, line 120, in wrapper
    return fn(self, attrname)
  File /usr/local/lib/python3.10/site-packages/nova/objects/instance.py, line 1130, in obj_load_attr
    LOG.debug(
  File /usr/local/lib/python3.10/logging/__init__.py, line 1835, in debug
    self.log(DEBUG, msg, *args, **kwargs)
  File /usr/local/lib/python3.10/logging/__init__.py, line 1879, in log
    self.logger.log(level, msg, *args, **kwargs)
  File /usr/local/lib/python3.10/logging/__init__.py, line 1547, in log
    self._log(level, msg, args, **kwargs)
  File /usr/local/lib/python3.10/logging/__init__.py, line 1624, in _log
    self.handle(record)
  File /usr/local/lib/python3.10/logging/__init__.py, line 1634, in handle
    self.callHandlers(record)
  File /usr/local/lib/python3.10/logging/__init__.py, line 1696, in callHandlers
    hdlr.handle(record)
  File /usr/local/lib/python3.10/logging/__init__.py, line 968, in handle
    self.emit(record)
  File /usr/local/lib/python3.10/logging/__init__.py, line 1100, in emit
    msg = self.format(record)
  File /usr/local/lib/python3.10/site-packages/oslo_log/handlers.py, line 156, in format
    return logging.StreamHandler.format(self, record) + record.reset_color
  File /usr/local/lib/python3.10/logging/__init__.py, line 943, in format
    return fmt.format(record)
  File /usr/local/lib/python3.10/site-packages/oslo_log/formatters.py, line 271, in format
    return _json_dumps_with_fallback(message)
  File /usr/local/lib/python3.10/site-packages/oslo_log/formatters.py, line 181, in _json_dumps_with_fallback
    return jsonutils.dumps(obj, default=convert)
  File /usr/local/lib/python3.10/site-packages/oslo_serialization/jsonutils.py, line 206, in dumps
    return json.dumps(obj, default=default, **kwargs)
  File /usr/local/lib/python3.10/json/__init__.py, line 238, in dumps
    **kw).encode(obj)
  File /usr/local/lib/python3.10/json/encoder.py, line 199, in encode
    chunks = self.iterencode(o, _one_shot=True)
  File /usr/local/lib/python3.10/json/encoder.py, line 257, in iterencode
    return _iterencode(o, 0)
  File /usr/local/lib/python3.10/site-packages/oslo_serialization/jsonutils.py, line 171, in to_primitive
    return recursive(dict(value.items()), level=level + 1)
  File /usr/local/lib/python3.10/site-packages/oslo_versionedobjects/base.py, line 752, in items
    yield name, getattr(self, name)
  File /usr/local/lib/python3.10/site-packages/nova/objects/instance.py, line 305, in name
    base_name = CONF.instance_name_template % self.id
  File /usr/local/lib/python3.10/site-packages/oslo_versionedobjects/base.py, line 67, in getter
    self.obj_load_attr(name)
  File /usr/local/lib/python3.10/site-packages/nova/objects/base.py, line 120, in wrapper
    return fn(self, attrname)
  File /usr/local/lib/python3.10/site-packages/nova/objects/instance.py, line 1130, in obj_load_attr
    [...] Recursions
RecursionError: maximum recursion depth exceeded while encoding a JSON object

The reason for the error seems to be this Debug log statement:
LOG.debug(
    "Lazy-load of '%s' attempted by orphaned instance",
    attrname, instance=self
)

https://github.com/openstack/nova/blob/706642bde33a13834ed7095f87df718f0da0500f/nova/objects/instance.py#L1130

Which tries to serialize instance, which in turn tries to call
Instance.name which tries to get the id of the instance which again
causes this Debug log.

The same statement is also present in 2025.1

** Affects: nova
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/2119218

Title:
  RecursionError when creating an instance with debug logging enabled

Status in OpenStack Compute (nova):
  New

Bug description:
  Description
  ===========
  When debug logging is enabled in nova api, an error occurs when creating an instance.

  Steps to reproduce
  ==================
  Create an instance via CLI

  Expected result
  ===============
  Instance is created and no error occur.

  Actual result
  =============
  Instance is created, but an error occurs:

  No Server found for f17f59b0-268c-47fb-accd-c459030ed439: Server Error for url: https://xxx/v2.1/servers/f17f59b0-268c-47fb-accd-c459030ed439, Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
  <class 'RecursionError'>

  Environment
  ===========
  Nova 2024.1

  Logs & Configs
  ==============
  Taking a deeper look in the logs reveals this stacktrace:

  Traceback (most recent call last):
    File /usr/local/lib/python3.10/site-packages/nova/api/openstack/wsgi.py, line 658, in wrapped
      return f(*args, **kwargs)
    File /usr/local/lib/python3.10/site-packages/nova/api/openstack/compute/servers.py, line 477, in show
      return self._view_builder.show(
    File /usr/local/lib/python3.10/site-packages/nova/api/openstack/compute/views/servers.py, line 364, in show
      server[server][key[] = getattr(instance, attr)
    File /usr/local/lib/python3.10/site-packages/nova/objects/instance.py, line 305, in name
      base_name = CONF.instance_name_template % self.id
    File /usr/local/lib/python3.10/site-packages/oslo_versionedobjects/base.py, line 67, in getter
      self.obj_load_attr(name)
    File /usr/local/lib/python3.10/site-packages/nova/objects/base.py, line 120, in wrapper
      return fn(self, attrname)
    File /usr/local/lib/python3.10/site-packages/nova/objects/instance.py, line 1130, in obj_load_attr
      LOG.debug(
    File /usr/local/lib/python3.10/logging/__init__.py, line 1835, in debug
      self.log(DEBUG, msg, *args, **kwargs)
    File /usr/local/lib/python3.10/logging/__init__.py, line 1879, in log
      self.logger.log(level, msg, *args, **kwargs)
    File /usr/local/lib/python3.10/logging/__init__.py, line 1547, in log
      self._log(level, msg, args, **kwargs)
    File /usr/local/lib/python3.10/logging/__init__.py, line 1624, in _log
      self.handle(record)
    File /usr/local/lib/python3.10/logging/__init__.py, line 1634, in handle
      self.callHandlers(record)
    File /usr/local/lib/python3.10/logging/__init__.py, line 1696, in callHandlers
      hdlr.handle(record)
    File /usr/local/lib/python3.10/logging/__init__.py, line 968, in handle
      self.emit(record)
    File /usr/local/lib/python3.10/logging/__init__.py, line 1100, in emit
      msg = self.format(record)
    File /usr/local/lib/python3.10/site-packages/oslo_log/handlers.py, line 156, in format
      return logging.StreamHandler.format(self, record) + record.reset_color
    File /usr/local/lib/python3.10/logging/__init__.py, line 943, in format
      return fmt.format(record)
    File /usr/local/lib/python3.10/site-packages/oslo_log/formatters.py, line 271, in format
      return _json_dumps_with_fallback(message)
    File /usr/local/lib/python3.10/site-packages/oslo_log/formatters.py, line 181, in _json_dumps_with_fallback
      return jsonutils.dumps(obj, default=convert)
    File /usr/local/lib/python3.10/site-packages/oslo_serialization/jsonutils.py, line 206, in dumps
      return json.dumps(obj, default=default, **kwargs)
    File /usr/local/lib/python3.10/json/__init__.py, line 238, in dumps
      **kw).encode(obj)
    File /usr/local/lib/python3.10/json/encoder.py, line 199, in encode
      chunks = self.iterencode(o, _one_shot=True)
    File /usr/local/lib/python3.10/json/encoder.py, line 257, in iterencode
      return _iterencode(o, 0)
    File /usr/local/lib/python3.10/site-packages/oslo_serialization/jsonutils.py, line 171, in to_primitive
      return recursive(dict(value.items()), level=level + 1)
    File /usr/local/lib/python3.10/site-packages/oslo_versionedobjects/base.py, line 752, in items
      yield name, getattr(self, name)
    File /usr/local/lib/python3.10/site-packages/nova/objects/instance.py, line 305, in name
      base_name = CONF.instance_name_template % self.id
    File /usr/local/lib/python3.10/site-packages/oslo_versionedobjects/base.py, line 67, in getter
      self.obj_load_attr(name)
    File /usr/local/lib/python3.10/site-packages/nova/objects/base.py, line 120, in wrapper
      return fn(self, attrname)
    File /usr/local/lib/python3.10/site-packages/nova/objects/instance.py, line 1130, in obj_load_attr
      [...] Recursions
  RecursionError: maximum recursion depth exceeded while encoding a JSON object

  The reason for the error seems to be this Debug log statement:
  LOG.debug(
      "Lazy-load of '%s' attempted by orphaned instance",
      attrname, instance=self
  )

  https://github.com/openstack/nova/blob/706642bde33a13834ed7095f87df718f0da0500f/nova/objects/instance.py#L1130

  Which tries to serialize instance, which in turn tries to call
  Instance.name which tries to get the id of the instance which again
  causes this Debug log.

  The same statement is also present in 2025.1

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/2119218/+subscriptions