OpenStack Compute (nova)

Metadata API server fails to provide VM data

Bug #2000318 reported by Nicolas Melot on 2022-12-22

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Compute (nova)	Triaged	Medium	Rajesh Tailor

Bug Description

Nova Metadata API server experiences an internal error when a cirros image requests metadata.

This is how metadata are requested from a cirros VM, and the results I get:
$ curl http://169.254.169.254/latest/meta-data/placement/availability-zone/nova
<html>
<head>
  <title>500 Internal Server Error</title>
</head>
<body>
  <h1>500 Internal Server Error</h1>
  Remote metadata server experienced an internal server error.<br /><br />

</body>
</html>$

And here are the logs from openstack-nova-metadata-api service:

2022-12-22 14:19:57.854 675968 INFO nova.metadata.wsgi.server [None req-23bd0dbb-b50c-46ce-bd34-d399601bf697 - - - - - -] Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/eventlet/wsgi.py", line 569, in handle_one_response
    result = self.application(self.environ, start_response)
  File "/usr/lib/python3.9/site-packages/paste/urlmap.py", line 216, in __call__
    return app(environ, start_response)
  File "/usr/lib/python3.9/site-packages/webob/dec.py", line 129, in __call__
    resp = self.call_func(req, *args, **kw)
  File "/usr/lib/python3.9/site-packages/webob/dec.py", line 193, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python3.9/site-packages/oslo_middleware/base.py", line 124, in __call__
    response = req.get_response(self.application)
  File "/usr/lib/python3.9/site-packages/webob/request.py", line 1313, in send
    status, headers, app_iter = self.call_application(
  File "/usr/lib/python3.9/site-packages/webob/request.py", line 1278, in call_application
    app_iter = application(self.environ, start_response)
  File "/usr/lib/python3.9/site-packages/webob/dec.py", line 129, in __call__
    resp = self.call_func(req, *args, **kw)
  File "/usr/lib/python3.9/site-packages/webob/dec.py", line 193, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python3.9/site-packages/oslo_middleware/base.py", line 124, in __call__
    response = req.get_response(self.application)
  File "/usr/lib/python3.9/site-packages/webob/request.py", line 1313, in send
    status, headers, app_iter = self.call_application(
  File "/usr/lib/python3.9/site-packages/webob/request.py", line 1278, in call_application
    app_iter = application(self.environ, start_response)
  File "/usr/lib/python3.9/site-packages/webob/dec.py", line 129, in __call__
    resp = self.call_func(req, *args, **kw)
  File "/usr/lib/python3.9/site-packages/webob/dec.py", line 193, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python3.9/site-packages/nova/api/metadata/handler.py", line 129, in __call__
    data = meta_data.lookup(req.path_info)
  File "/usr/lib/python3.9/site-packages/nova/api/metadata/base.py", line 576, in lookup
    data = self.get_ec2_item(path_tokens[1:])
  File "/usr/lib/python3.9/site-packages/nova/api/metadata/base.py", line 308, in get_ec2_item
    return find_path_in_tree(data, path_tokens[1:])
  File "/usr/lib/python3.9/site-packages/nova/api/metadata/base.py", line 746, in find_path_in_tree
    data = data[path_tokens[i]]
TypeError: string indices must be integers

2022-12-22 14:19:57.855 675968 INFO nova.metadata.wsgi.server [None req-23bd0dbb-b50c-46ce-bd34-d399601bf697 - - - - - -] 10.18.85.3,172.20.119.1 "GET /latest/meta-data/placement/availability-zone/nova HTTP/1.1" status: 500 len: 139 time: 0.2591183

To troubleshoot the error, I checked the code in /usr/lib/python3.9/site-packages/nova/api/metadata/base.py, and I added additional log output:

726 def find_path_in_tree(data, path_tokens):
727 # given a dict/list tree, and a path in that tree, return data found there.
728 LOG.warning("asdqwedasdqwed 1 data = \"{data}\"".format(data=data))
729 for i in range(0, len(path_tokens)):
730 LOG.warning("asdqwedasdqwed 1 i = \"{i}\"".format(i=i))
731 LOG.warning("asdqwedasdqwed 2 data = \"{data}\"".format(data=data))
732 if isinstance(data, dict) or isinstance(data, list):
733 LOG.warning("asdqwedasdqwed 3 data = \"{data}\"".format(data=data))
734 if path_tokens[i] in data:
735 LOG.warning("asdqwedasdqwed 4 data = \"{data}\"".format(data=data))
736 data = data[path_tokens[i]]
737 LOG.warning("asdqwedasdqwed 5 data = \"{data}\"".format(data=data))
738 else:
739 raise KeyError("/".join(path_tokens[0:i]))
740 else:
741 LOG.warning("asdqwedasdqwed path_tokens = \"{path_tokens}\"".format(path_tokens=path_tokens))
742 LOG.warning("asdqwedasdqwed 6 data = \"{data}\"".format(data=data))
743 LOG.warning("asdqwedasdqwed 2 i = \"{i}\"".format(i=i))
744 if i != len(path_tokens) - 1:
745 raise KeyError("/".join(path_tokens[0:i]))
746 data = data[path_tokens[i]]
747 return data

After restarting openstack-nova-metadata-api service, Here is the trace I obtain:
2022-12-22 14:19:57.852 675968 WARNING nova.api.metadata.base [None req-23bd0dbb-b50c-46ce-bd34-d399601bf697 - - - - - -] asdqwedasdqwed 1 i = "2"
2022-12-22 14:19:57.852 675968 WARNING nova.api.metadata.base [None req-23bd0dbb-b50c-46ce-bd34-d399601bf697 - - - - - -] asdqwedasdqwed 2 data = "{'availability-zone': 'nova'}"
2022-12-22 14:19:57.852 675968 WARNING nova.api.metadata.base [None req-23bd0dbb-b50c-46ce-bd34-d399601bf697 - - - - - -] asdqwedasdqwed 3 data = "{'availability-zone': 'nova'}"
2022-12-22 14:19:57.852 675968 WARNING nova.api.metadata.base [None req-23bd0dbb-b50c-46ce-bd34-d399601bf697 - - - - - -] asdqwedasdqwed 4 data = "{'availability-zone': 'nova'}"
2022-12-22 14:19:57.853 675968 WARNING nova.api.metadata.base [None req-23bd0dbb-b50c-46ce-bd34-d399601bf697 - - - - - -] asdqwedasdqwed 5 data = "nova"
2022-12-22 14:19:57.853 675968 WARNING nova.api.metadata.base [None req-23bd0dbb-b50c-46ce-bd34-d399601bf697 - - - - - -] asdqwedasdqwed 1 i = "3"
2022-12-22 14:19:57.853 675968 WARNING nova.api.metadata.base [None req-23bd0dbb-b50c-46ce-bd34-d399601bf697 - - - - - -] asdqwedasdqwed 2 data = "nova"
2022-12-22 14:19:57.853 675968 WARNING nova.api.metadata.base [None req-23bd0dbb-b50c-46ce-bd34-d399601bf697 - - - - - -] asdqwedasdqwed path_tokens = "['meta-data', 'placement', 'availability-zone', 'nova']"
2022-12-22 14:19:57.853 675968 WARNING nova.api.metadata.base [None req-23bd0dbb-b50c-46ce-bd34-d399601bf697 - - - - - -] asdqwedasdqwed 6 data = "nova"
2022-12-22 14:19:57.853 675968 WARNING nova.api.metadata.base [None req-23bd0dbb-b50c-46ce-bd34-d399601bf697 - - - - - -] asdqwedasdqwed 2 i = "3"

I see that data turns from a dictionary to a string as soon as the code finds path_tokens[i] in data. The problem is the else branch tries to look for path_tokens[i] in data. Since data is now a string, it can only be indexed with an integer, as the logs indicate.

I commented out line 746 and restarted openstack-nova-metadata-api. Now it seems my instance is sometime able to retrieve metadata:

2022-12-22 14:38:34.797 679181 WARNING nova.api.metadata.base [None req-d5e4cdf8-6fc5-4141-9c97-a5226cf5ef20 - - - - - -] asdqwedasdqwed 5 data = "{'availability-zone': 'nova'}"
2022-12-22 14:38:34.797 679181 WARNING nova.api.metadata.base [None req-d5e4cdf8-6fc5-4141-9c97-a5226cf5ef20 - - - - - -] asdqwedasdqwed 1 i = "2"
2022-12-22 14:38:34.797 679181 WARNING nova.api.metadata.base [None req-d5e4cdf8-6fc5-4141-9c97-a5226cf5ef20 - - - - - -] asdqwedasdqwed 2 data = "{'availability-zone': 'nova'}"
2022-12-22 14:38:34.797 679181 WARNING nova.api.metadata.base [None req-d5e4cdf8-6fc5-4141-9c97-a5226cf5ef20 - - - - - -] asdqwedasdqwed 3 data = "{'availability-zone': 'nova'}"
2022-12-22 14:38:34.798 679181 WARNING nova.api.metadata.base [None req-d5e4cdf8-6fc5-4141-9c97-a5226cf5ef20 - - - - - -] asdqwedasdqwed 4 data = "{'availability-zone': 'nova'}"
2022-12-22 14:38:34.798 679181 WARNING nova.api.metadata.base [None req-d5e4cdf8-6fc5-4141-9c97-a5226cf5ef20 - - - - - -] asdqwedasdqwed 5 data = "nova"
2022-12-22 14:38:34.798 679181 WARNING nova.api.metadata.base [None req-d5e4cdf8-6fc5-4141-9c97-a5226cf5ef20 - - - - - -] asdqwedasdqwed 1 i = "3"
2022-12-22 14:38:34.798 679181 WARNING nova.api.metadata.base [None req-d5e4cdf8-6fc5-4141-9c97-a5226cf5ef20 - - - - - -] asdqwedasdqwed 2 data = "nova"
2022-12-22 14:38:34.798 679181 WARNING nova.api.metadata.base [None req-d5e4cdf8-6fc5-4141-9c97-a5226cf5ef20 - - - - - -] asdqwedasdqwed path_tokens = "['meta-data', 'placement', 'availability-zone', 'nova']"
2022-12-22 14:38:34.798 679181 WARNING nova.api.metadata.base [None req-d5e4cdf8-6fc5-4141-9c97-a5226cf5ef20 - - - - - -] asdqwedasdqwed 6 data = "nova"
2022-12-22 14:38:34.799 679181 WARNING nova.api.metadata.base [None req-d5e4cdf8-6fc5-4141-9c97-a5226cf5ef20 - - - - - -] asdqwedasdqwed 2 i = "3"
2022-12-22 14:38:34.799 679181 INFO nova.metadata.wsgi.server [None req-d5e4cdf8-6fc5-4141-9c97-a5226cf5ef20 - - - - - -] 10.18.85.95,172.20.119.1 "GET /latest/meta-data/placement/availability-zone/nova HTTP/1.1" status: 200 len: 144 time: 0.1608348

sometimes it reports the remote metadata server experienced an internal server error:

2022-12-22 14:39:10.644 21760 INFO nova.metadata.wsgi.server [None req-53d9a388-dfa9-4e29-bce2-745516a4270a - - - - - -] Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/eventlet/wsgi.py", line 569, in handle_one_response
    result = self.application(self.environ, start_response)
  File "/usr/lib/python3.9/site-packages/paste/urlmap.py", line 216, in __call__
    return app(environ, start_response)
  File "/usr/lib/python3.9/site-packages/webob/dec.py", line 129, in __call__
    resp = self.call_func(req, *args, **kw)
  File "/usr/lib/python3.9/site-packages/webob/dec.py", line 193, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python3.9/site-packages/oslo_middleware/base.py", line 124, in __call__
    response = req.get_response(self.application)
  File "/usr/lib/python3.9/site-packages/webob/request.py", line 1313, in send
    status, headers, app_iter = self.call_application(
  File "/usr/lib/python3.9/site-packages/webob/request.py", line 1278, in call_application
    app_iter = application(self.environ, start_response)
  File "/usr/lib/python3.9/site-packages/webob/dec.py", line 129, in __call__
    resp = self.call_func(req, *args, **kw)
  File "/usr/lib/python3.9/site-packages/webob/dec.py", line 193, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python3.9/site-packages/oslo_middleware/base.py", line 124, in __call__
    response = req.get_response(self.application)
  File "/usr/lib/python3.9/site-packages/webob/request.py", line 1313, in send
    status, headers, app_iter = self.call_application(
  File "/usr/lib/python3.9/site-packages/webob/request.py", line 1278, in call_application
    app_iter = application(self.environ, start_response)
  File "/usr/lib/python3.9/site-packages/webob/dec.py", line 129, in __call__
    resp = self.call_func(req, *args, **kw)
  File "/usr/lib/python3.9/site-packages/webob/dec.py", line 193, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python3.9/site-packages/nova/api/metadata/handler.py", line 129, in __call__
    data = meta_data.lookup(req.path_info)
  File "/usr/lib/python3.9/site-packages/nova/api/metadata/base.py", line 576, in lookup
    data = self.get_ec2_item(path_tokens[1:])
  File "/usr/lib/python3.9/site-packages/nova/api/metadata/base.py", line 308, in get_ec2_item
    return find_path_in_tree(data, path_tokens[1:])
  File "/usr/lib/python3.9/site-packages/nova/api/metadata/base.py", line 737, in find_path_in_tree
    LOG.warning("asdqwedasdqwed 5 data = \"{data}\"".format(data=data))
TypeError: string indices must be integers

2022-12-22 14:39:10.644 21760 INFO nova.metadata.wsgi.server [None req-53d9a388-dfa9-4e29-bce2-745516a4270a - - - - - -] 10.18.85.95,172.20.119.1 "GET /latest/meta-data/placement/availability-zone/nova HTTP/1.1" status: 500 len: 139 time: 0.1553872

It looks like my "fix" is not sufficient to solve the issue. Regardless, I am under the impression that this code cannot work as it is, whether my "fix" is applied or not. This might be the sign I configured something else very wrong, but I cannot find out what this could be.

I run Openstack Zed, freshly installed on Rocky Linux 9, also freshly installed.

Tags:

Revision history for this message

Nicolas Melot (nicmel) wrote on 2023-01-09:

Anyone? I have no clue on how to solve this.

Revision history for this message

Balazs Gibizer (balazs-gibizer) wrote on 2023-01-24:

Which openstack version are you using?

The stack trace `line 746, in find_path_in_tree` does not match with any version I looked at (master ->...-> stable/train) There is no line:746. Did you locally modified that file before the first error? If so could you reproduce the problem without those local modifications?

But I think I see what can cause the error in[1]:

        if isinstance(data, dict) or isinstance(data, list):
            if path_tokens[i] in data:
                data = data[path_tokens[i]]

If data is a list and path_tokens[i] is an item in the data list then data[path_tokens[i]] is a type error as you reported. I guess we need to split the code to handle the isinstance(data, list) branch separately.

[1]https://github.com/openstack/nova/blob/d8b4b7bebdc0f55353cd99f372044b9e30315a6d/nova/api/metadata/base.py#L729-L731

Changed in nova:
status:	New → Triaged
importance:	Undecided → Medium
tags:	added: low-hanging-fruit metadata

Rajesh Tailor (ratailor) on 2023-03-11

Changed in nova:
assignee:	nobody → Rajesh Tailor (ratailor)

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.