HTTP 500 while retrieving metadata by non-existent key

Bug #1371160 reported by Ilya Shakhat
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Low
Unassigned
neutron
Fix Released
Medium
Armando Migliaccio

Bug Description

HTTP 500 error occurs when one tries to get metadata by path constructed from folder name with appended value.

Steps to repro:
1. Launch VM and access its terminal
2. curl http://169.254.169.254/latest/meta-data/instance-id -- this returns some string, i.e. i-00000001
3. curl http://169.254.169.254/latest/meta-data/instance-id/i-00000001 -- this returns HTTP 500
It's expected that the last call returns meaningful message and not produce trace backs in logs.

Errors:
----------
In VM terminal:
$ curl http://169.254.169.254/latest/meta-data/instance-id/i-00000001
<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>$

In Neutron metadata agent:
2014-09-18 14:44:37.563 ERROR neutron.agent.metadata.agent [-] Unexpected error.
2014-09-18 14:44:37.563 TRACE neutron.agent.metadata.agent Traceback (most recent call last):
2014-09-18 14:44:37.563 TRACE neutron.agent.metadata.agent File "/opt/stack/neutron/neutron/agent/metadata/agent.py", line 130, in __call__
2014-09-18 14:44:37.563 TRACE neutron.agent.metadata.agent return webob.exc.HTTPNotFound()
2014-09-18 14:44:37.563 TRACE neutron.agent.metadata.agent File "/opt/stack/neutron/neutron/agent/metadata/agent.py", line 248, in _proxy_request
2014-09-18 14:44:37.563 TRACE neutron.agent.metadata.agent def _sign_instance_id(self, instance_id):
2014-09-18 14:44:37.563 TRACE neutron.agent.metadata.agent Exception: Unexpected response code: 400
2014-09-18 14:44:37.563 TRACE neutron.agent.metadata.agent
2014-09-18 14:44:37.566 INFO eventlet.wsgi.server [-] 10.0.0.2,<local> - - [18/Sep/2014 14:44:37] "GET /latest/meta-data/instance-id/i-00000001 HTTP/1.1" 500 229 0.348877

In Nova API service:
2014-09-18 14:31:19.030 ERROR nova.api.ec2 [req-5c84e0ae-7d18-4113-a08b-ed068e5333ed None None] FaultWrapper: string indices must be integers, not unicode
2014-09-18 14:31:19.030 TRACE nova.api.ec2 Traceback (most recent call last):
2014-09-18 14:31:19.030 TRACE nova.api.ec2 File "/opt/stack/nova/nova/api/ec2/__init__.py", line 87, in __call__
2014-09-18 14:31:19.030 TRACE nova.api.ec2 return req.get_response(self.application)
2014-09-18 14:31:19.030 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2014-09-18 14:31:19.030 TRACE nova.api.ec2 application, catch_exc_info=False)
2014-09-18 14:31:19.030 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
2014-09-18 14:31:19.030 TRACE nova.api.ec2 app_iter = application(self.environ, start_response)
2014-09-18 14:31:19.030 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2014-09-18 14:31:19.030 TRACE nova.api.ec2 resp = self.call_func(req, *args, **self.kwargs)
2014-09-18 14:31:19.030 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2014-09-18 14:31:19.030 TRACE nova.api.ec2 return self.func(req, *args, **kwargs)
2014-09-18 14:31:19.030 TRACE nova.api.ec2 File "/opt/stack/nova/nova/api/ec2/__init__.py", line 99, in __call__
2014-09-18 14:31:19.030 TRACE nova.api.ec2 rv = req.get_response(self.application)
2014-09-18 14:31:19.030 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2014-09-18 14:31:19.030 TRACE nova.api.ec2 application, catch_exc_info=False)
2014-09-18 14:31:19.030 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
2014-09-18 14:31:19.030 TRACE nova.api.ec2 app_iter = application(self.environ, start_response)
2014-09-18 14:31:19.030 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2014-09-18 14:31:19.030 TRACE nova.api.ec2 resp = self.call_func(req, *args, **self.kwargs)
2014-09-18 14:31:19.030 TRACE nova.api.ec2 File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2014-09-18 14:31:19.030 TRACE nova.api.ec2 return self.func(req, *args, **kwargs)
2014-09-18 14:31:19.030 TRACE nova.api.ec2 File "/opt/stack/nova/nova/api/metadata/handler.py", line 128, in __call__
2014-09-18 14:31:19.030 TRACE nova.api.ec2 data = meta_data.lookup(req.path_info)
2014-09-18 14:31:19.030 TRACE nova.api.ec2 File "/opt/stack/nova/nova/api/metadata/base.py", line 418, in lookup
2014-09-18 14:31:19.030 TRACE nova.api.ec2 data = self.get_ec2_item(path_tokens[1:])
2014-09-18 14:31:19.030 TRACE nova.api.ec2 File "/opt/stack/nova/nova/api/metadata/base.py", line 300, in get_ec2_item
2014-09-18 14:31:19.030 TRACE nova.api.ec2 return find_path_in_tree(data, path_tokens[1:])
2014-09-18 14:31:19.030 TRACE nova.api.ec2 File "/opt/stack/nova/nova/api/metadata/base.py", line 565, in find_path_in_tree
2014-09-18 14:31:19.030 TRACE nova.api.ec2 data = data[path_tokens[i]]
2014-09-18 14:31:19.030 TRACE nova.api.ec2 TypeError: string indices must be integers, not unicode
2014-09-18 14:31:19.030 TRACE nova.api.ec2
2014-09-18 14:31:19.032 INFO nova.metadata.wsgi.server [req-5c84e0ae-7d18-4113-a08b-ed068e5333ed None None] 10.0.0.2,172.18.76.77 "GET /latest/meta-data/placement/availability-zone/nova HTTP/1.1" status: 400 len: 246 time: 0.5495760

Tags: ec2
Revision history for this message
Sean Dague (sdague) wrote :

So I agree that n-api should not stack trace... however it successfully returns a 400 to the service, which I think was expected. Neutron is exploding on that 400 though, which is not.

tags: added: ec2
Revision history for this message
Sean Dague (sdague) wrote :

On the Nova side eliminating the stack trace seems like:

def find_path_in_tree(data, path_tokens):
    # given a dict/list tree, and a path in that tree, return data found there.
    for i in range(0, len(path_tokens)):
        if isinstance(data, dict) or isinstance(data, list):
            if path_tokens[i] in data:
                data = data[path_tokens[i]]
            else:
                raise KeyError("/".join(path_tokens[0:i]))
        else:
            if i != len(path_tokens) - 1:
                raise KeyError("/".join(path_tokens[0:i]))
            data = data[path_tokens[i]]
    return data

Because we are in a for loop we have the possibility of assigning data to be the value of a lookup, which turns out to be a string, and then iterating again, it's not a dict, then trying to use the token to index a string... which is wrong.

I'm not actually sure what the right behavior is here. It sort of feels like an early return might be right, but I'm definitely not convinced I understand the implications there.

Changed in nova:
importance: Undecided → Low
status: New → Incomplete
Changed in neutron:
status: New → Confirmed
importance: Undecided → High
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to neutron (master)

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

Changed in neutron:
assignee: nobody → Armando Migliaccio (armando-migliaccio)
status: Confirmed → In Progress
Revision history for this message
Armando Migliaccio (armando-migliaccio) wrote :

My kneejerk reaction would be to rectify the error code here, but I am not sure whether masking underlying errors with 500 was done by design to obfuscate the metadata server behavior

Changed in neutron:
importance: High → Medium
Changed in neutron:
milestone: none → juno-rc1
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to neutron (master)

Reviewed: https://review.openstack.org/122483
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=f92d1300e1aca68b39b927282af038acc68c5013
Submitter: Jenkins
Branch: master

commit f92d1300e1aca68b39b927282af038acc68c5013
Author: armando-migliaccio <email address hidden>
Date: Thu Sep 18 11:00:12 2014 -0700

    Fix 500 error on retrieving metadata by invalid URI

    An invalid URI should return a BadRequest error rather
    than making the metadata proxy bomb out.

    Closes-bug: #1371160

    Change-Id: Ifb495f9e8929062a0c24d090c3e702109a38803a

Changed in neutron:
status: In Progress → Fix Committed
Thierry Carrez (ttx)
Changed in neutron:
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in neutron:
milestone: juno-rc1 → 2014.2
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to neutron (feature/lbaasv2)

Fix proposed to branch: feature/lbaasv2
Review: https://review.openstack.org/130864

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to neutron (feature/lbaasv2)
Download full text (72.6 KiB)

Reviewed: https://review.openstack.org/130864
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=c089154a94e5872efc95eab33d3d0c9de8619fe4
Submitter: Jenkins
Branch: feature/lbaasv2

commit 62588957fbeccfb4f80eaa72bef2b86b6f08dcf8
Author: Kevin Benton <email address hidden>
Date: Wed Oct 22 13:04:03 2014 -0700

    Big Switch: Switch to TLSv1 in server manager

    Switch to TLSv1 for the connections to the backend
    controllers. The default SSLv3 is no longer considered
    secure.

    TLSv1 was chosen over .1 or .2 because the .1 and .2 weren't
    added until python 2.7.9 so TLSv1 is the only compatible option
    for py26.

    Closes-Bug: #1384487
    Change-Id: I68bd72fc4d90a102003d9ce48c47a4a6a3dd6e03

commit 17204e8f02fdad046dabdb8b31397289d72c877b
Author: OpenStack Proposal Bot <email address hidden>
Date: Wed Oct 22 06:20:15 2014 +0000

    Imported Translations from Transifex

    For more information about this automatic import see:
    https://wiki.openstack.org/wiki/Translations/Infrastructure

    Change-Id: I58db0476c810aa901463b07c42182eef0adb5114

commit d712663b99520e6d26269b0ca193527603178742
Author: Carl Baldwin <email address hidden>
Date: Mon Oct 20 21:48:42 2014 +0000

    Move disabling of metadata and ipv6_ra to _destroy_router_namespace

    I noticed that disable_ipv6_ra is called from the wrong place and that
    in some cases it was called with a bogus router_id because the code
    made an incorrect assumption about the context. In other case, it was
    never called because _destroy_router_namespace was being called
    directly. This patch moves the disabling of metadata and ipv6_ra in
    to _destroy_router_namespace to ensure they get called correctly and
    avoid duplication.

    Change-Id: Ia76a5ff4200df072b60481f2ee49286b78ece6c4
    Closes-Bug: #1383495

commit f82a5117f6f484a649eadff4b0e6be9a5a4d18bb
Author: OpenStack Proposal Bot <email address hidden>
Date: Tue Oct 21 12:11:19 2014 +0000

    Updated from global requirements

    Change-Id: Idcbd730f5c781d21ea75e7bfb15959c8f517980f

commit be6bd82d43fbcb8d1512d8eb5b7a106332364c31
Author: Angus Lees <email address hidden>
Date: Mon Aug 25 12:14:29 2014 +1000

    Remove duplicate import of constants module

    .. and enable corresponding pylint check now the only offending instance
    is fixed.

    Change-Id: I35a12ace46c872446b8c87d0aacce45e94d71bae

commit 9902400039018d77aa3034147cfb24ca4b2353f6
Author: rajeev <email address hidden>
Date: Mon Oct 13 16:25:36 2014 -0400

    Fix race condition on processing DVR floating IPs

    Fip namespace and agent gateway port can be shared by multiple dvr routers.
    This change uses a set as the control variable for these shared resources
    and ensures that Test and Set operation on the control variable are
    performed atomically so that race conditions do not occur among
    multiple threads processing floating IPs.
    Limitation: The scope of this change is limited to addressing the race
    condition described in the bug report. It may not address other issues
    such as pre-existing issue wit...

Sean Dague (sdague)
Changed in nova:
status: Incomplete → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

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