error when connecting to metadata service with neutron

Bug #1211829 reported by Lorin Hochstein on 2013-08-13
14
This bug affects 2 people
Affects Status Importance Assigned to Milestone
neutron
Critical
Nachi Ueno

Bug Description

When configured with neutron, I'm able to start a cirros instance and ssh to it, but it fails to connect to the metadata service. From the cirros console:

checking http://169.254.169.254/2009-04-04/instance-id
failed 1/20: up 9.25. iid had '<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 />

From /opt/stack/logs/screen-q-l3.log:

REQ: curl -i http://localhost:35357/v2.0/tokens -X POST -H "Content-Type: application/json" -H "Accept: application/json" -H "User-Agent: python-neutronclient" -d '{"auth": {"tenantName": "%SERVICE_TENANT_NAME%", "passwordCredentials": {"username": "%SERVICE_USER%", "password": "REDACTED"}}}'
 http_log_req /opt/stack/python-neutronclient/neutronclient/common/utils.py:173
2013-08-13 13:03:45.559 10939 DEBUG neutronclient.client [-] RESP:{'date': 'Tue, 13 Aug 2013 13:03:45 GMT', 'vary': 'X-Auth-Token', 'content-length': '100', 'status': '401', 'content-type': 'application/json'} {"error": {"message": "Could not find user, %SERVICE_USER%.", "code": 401, "title": "Unauthorized"}}
 http_log_resp /opt/stack/python-neutronclient/neutronclient/common/utils.py:179
2013-08-13 13:03:45.560 10939 ERROR neutron.agent.metadata.agent [-] Unexpected error.
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent Traceback (most recent call last):
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent File "/opt/stack/neutron/neutron/agent/metadata/agent.py", line 94, in __call__
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent instance_id = self._get_instance_id(req)
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent File "/opt/stack/neutron/neutron/agent/metadata/agent.py", line 118, in _get_instance_id
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent device_owner=DEVICE_OWNER_ROUTER_INTF)['ports']
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 108, in with_params
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent ret = self.function(instance, *args, **kwargs)
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 278, in list_ports
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent **_params)
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 992, in list
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent for r in self._pagination(collection, path, **params):
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 1005, in _pagination
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent res = self.get(path, params=params)
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 978, in get
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent headers=headers, params=params)
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 963, in retry_request
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent headers=headers, params=params)
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 892, in do_request
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent self.httpclient.authenticate_and_fetch_endpoint_url()
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent File "/opt/stack/python-neutronclient/neutronclient/client.py", line 172, in authenticate_and_fetch_endpoint_url
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent self.authenticate()
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent File "/opt/stack/python-neutronclient/neutronclient/client.py", line 231, in authenticate
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent content_type="application/json")
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent File "/opt/stack/python-neutronclient/neutronclient/client.py", line 156, in _cs_request
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent raise exceptions.Unauthorized(message=body)
2013-08-13 13:03:45.560 10939 TRACE neutron.agent.metadata.agent Unauthorized: {"error": {"message": "Could not find user, %SERVICE_USER%.", "code": 401, "title":

It looks like devstack is not setting the keystone authentication options in /etc/neutron/metadata_agent.ini. Here are some lines from that file in my deployment:

# The Neutron user information for accessing the Neutron API.
auth_url = http://localhost:35357/v2.0
auth_region = RegionOne
admin_tenant_name = %SERVICE_TENANT_NAME%
admin_user = %SERVICE_USER%
admin_password = %SERVICE_PASSWORD%

Here's what my localrc looks like:

# Default passwords
ADMIN_PASSWORD=password
MYSQL_PASSWORD=password
RABBIT_PASSWORD=password
SERVICE_PASSWORD=password
SERVICE_TOKEN=password

SCREEN_LOGDIR=/opt/stack/logs

HOST_IP=192.168.27.100

#
# Quantum
#
# https://wiki.openstack.org/wiki/NeutronDevstack
disable_service n-net
enable_service q-svc
enable_service q-agt
enable_service q-dhcp
enable_service q-l3
enable_service q-meta
enable_service neutron

PUBLIC_NETWORK_GATEWAY=192.168.50.1
Q_FLOATING_ALLOCATION_POOL=start=192.168.50.2,end=192.168.50.50
FLOATING_RANGE=192.168.50.0/24
Q_USE_SECGROUP=False

I'm running ubuntu 12.04 inside of VirtualBox.

Lorin Hochstein (lorinh) wrote :

I think this is a duplicate of https://bugs.launchpad.net/neutron/+bug/1210664

Supposedly, this was fixed in bf10ac55a99d226a81bdbc7e6bd1e85b4f48652d

However, my cirros instance still can't retrieve metadata. Now the console says "request failed" rather than seeing a 500 error:

checking http://169.254.169.254/2009-04-04/instance-id
failed 1/20: up 9.58. request failed
failed 2/20: up 21.93. request failed
failed 3/20: up 34.05. request failed
failed 4/20: up 46.17. request failed
failed 5/20: up 58.28. request failed
failed 6/20: up 70.48. request failed
failed 7/20: up 82.64. request failed
failed 8/20: up 94.84. request failed
failed 9/20: up 107.07. request failed
failed 10/20: up 119.18. request failed
failed 11/20: up 131.38. request failed
failed 12/20: up 143.51. request failed
failed 13/20: up 155.68. request failed
failed 14/20: up 167.88. request failed
failed 15/20: up 179.99. request failed
failed 16/20: up 192.22. request failed
failed 17/20: up 204.33. request failed
failed 18/20: up 216.45. request failed
failed 19/20: up 228.57. request failed
failed 20/20: up 240.76. request failed
failed to read iid from metadata. tried 20
no results found for mode=net. up 253.15. searched: nocloud configdrive ec2

Maru Newby (maru) wrote :

The exception in the bug description indicates that the problem you are experiencing should have been fixed by https://review.openstack.org/#/c/41270/. Did the log from your comment appear after you updated devstack to include the fix?

Lorin Hochstein (lorinh) wrote :

@maru See my comment #1 above <https://bugs.launchpad.net/devstack/+bug/1211829/comments/1>.

I've updated my devstack, and I don't get the original error message anymore, but cirros still fails to access metadata. Can you confirm that the metadata service works for you under DevStack with Neutron?

Maru Newby (maru) wrote :

It was working for me when I submitted that patch, but as you say it appears to be broken now.

Changed in devstack:
assignee: nobody → Maru Newby (maru)
Maru Newby (maru) on 2013-08-15
Changed in devstack:
status: New → In Progress
Maru Newby (maru) wrote :

The problem is due to the following nat rule being cleared on router sync from the router namespace:

-A neutron-l3-agent-PREROUTING -d 169.254.169.254/32 -p tcp -m tcp --dport 80 -j REDIRECT --to-ports 9697

I'm not clear on why this is happening.

Changed in devstack:
status: In Progress → Confirmed
assignee: Maru Newby (maru) → nobody
affects: devstack → neutron
Changed in neutron:
importance: Undecided → Critical
assignee: nobody → Maru Newby (maru)
Maru Newby (maru) wrote :

To reproduce:

 - clean devstack run with neutron enabled
 - check the router namespace for the nat rule in question:

sudo ip netns qrouter-[router id] iptables-save | grep 9697

Checking the l3 agent logs should show the nat rule being added and then being subsequently removed.

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

Changed in neutron:
assignee: Maru Newby (maru) → Nachi Ueno (nati-ueno)
status: Confirmed → In Progress
Maru Newby (maru) wrote :

Nati discovered that a recent change started clearing the nat rules, which caused this problem:

https://github.com/openstack/neutron/commit/9382ee659212285a203550cf60476dd146d27a29#L0R424

Maru Newby (maru) wrote :

This bug will hopefully fixed when the commit in question is reverted:

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

Reviewed: https://review.openstack.org/42390
Committed: http://github.com/openstack/neutron/commit/77a1d0c95a83a9697782a7e3ab6e8dea16cd4174
Submitter: Jenkins
Branch: master

commit 77a1d0c95a83a9697782a7e3ab6e8dea16cd4174
Author: Nachi Ueno <email address hidden>
Date: Fri Aug 16 10:17:48 2013 -0700

    Revert "Refactor configuring of floating ips on a router."

    This patch breaks gating job.
    Because nat rule for metadata will be only added on the
    router_add.
    Revert it for now.

    Fixes bug 1211829
    This reverts commit 9382ee659212285a203550cf60476dd146d27a29.

    Change-Id: I05925798cddc7a706e922025ef6ce27b6638ffb6

Changed in neutron:
status: In Progress → Fix Committed
Lorin Hochstein (lorinh) wrote :

Confirmed, this patch resolves the issue for me.

Jay Pipes (jaypipes) wrote :

Note that this:

auth_url = http://localhost:35357/v2.0

Is incorrect. It should be:

auth_url = http://localhost:5000/v2.0

per Dolph's commentary here:

http://lists.openstack.org/pipermail/openstack-dev/2013-August/012886.html

Lorin Hochstein (lorinh) wrote :

@jaypipes:

I logged a new bug based on your comment: https://bugs.launchpad.net/neutron/+bug/1214921

Changed in neutron:
milestone: none → havana-3
tags: added: l3-ipam-dhcp
Thierry Carrez (ttx) on 2013-09-05
Changed in neutron:
status: Fix Committed → Fix Released
Thierry Carrez (ttx) on 2013-10-17
Changed in neutron:
milestone: havana-3 → 2013.2
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers