nova show command sometimes don't includes ip address

[Sean Dague]

From this failed run - http://logs.openstack.org/05/35705/16/gate/gate-tempest-devstack-vm-neutron/59a5718/

2013-08-05 22:42:13.099 | ++ grep xtrace
2013-08-05 22:42:13.101 | + FXTRACE='set -o xtrace'
2013-08-05 22:42:13.101 | + set +o xtrace
2013-08-05 22:42:13.102 | + timeout 90 sh -c 'while ! nova show d0e9b096-a073-476a-9de7-ce67087bbf42 | grep status | grep -q ACTIVE; do sleep 1; done'
2013-08-05 22:42:18.243 | ++ nova show d0e9b096-a073-476a-9de7-ce67087bbf42
2013-08-05 22:42:18.243 | ++ grep private
2013-08-05 22:42:18.243 | ++ get_field 2
2013-08-05 22:42:18.280 | ++ read data
2013-08-05 22:42:19.086 | + IP=
2013-08-05 22:42:19.086 | + die_if_not_set 136 IP 'Failure retrieving IP address'
2013-08-05 22:42:19.086 | + local exitcode=0
2013-08-05 22:42:19.123 | ++ set +o
2013-08-05 22:42:19.123 | ++ grep xtrace
2013-08-05 22:42:19.123 | + FXTRACE='set -o xtrace'
2013-08-05 22:42:19.123 | + set +o xtrace
2013-08-05 22:42:19.124 | [ERROR] /opt/stack/new/devstack/exercises/floating_ips.sh:136 Failure retrieving IP address

The only mildly relevent logs I can find are:

http://logs.openstack.org/05/35705/16/gate/gate-tempest-devstack-vm-neutron/59a5718/logs/screen-q-svc.txt.gz

2013-08-05 22:42:14.014 3148 DEBUG neutron.api.v2.base [-] Policy rule:get_port:fixed_ips not found. Assuming no authZ check is defined for fixed_ips _is_visible /opt/stack/new/neutron/neutron/api/v2/base.py:143
2013-08-05 22:42:14.014 3148 DEBUG neutron.api.v2.base [-] Policy rule:get_port:mac_address not found. Assuming no authZ check is defined for mac_address _is_visible /opt/stack/new/neutron/neutron/api/v2/base.py:143
2013-08-05 22:42:14.015 3148 DEBUG neutron.openstack.common.rpc.amqp [-] Sending port.create.end on notifications.info notify /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:584
2013-08-05 22:42:14.015 3148 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is e1fecb822e5f470daafaa1a067ddc8e7. _add_unique_id /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:325
2013-08-05 22:42:14.018 3148 DEBUG amqp [-] Closed channel #1 _do_close /usr/local/lib/python2.7/dist-packages/amqp/channel.py:88
2013-08-05 22:42:14.018 3148 DEBUG amqp [-] using channel_id: 1 __init__ /usr/local/lib/python2.7/dist-packages/amqp/channel.py:70
2013-08-05 22:42:14.019 3148 DEBUG amqp [-] Channel open _open_ok /usr/local/lib/python2.7/dist-packages/amqp/channel.py:420
2013-08-05 22:42:14.033 3148 DEBUG neutron.scheduler.dhcp_agent_scheduler [-] Network f9263bb5-9c37-4314-baf9-0ef7eb873155 is hosted already schedule /opt/stack/new/neutron/neutron/scheduler/dhcp_agent_scheduler.py:61
2013-08-05 22:42:14.033 3148 WARNING neutron.db.agentschedulers_db [-] Fail scheduling network {'status': u'ACTIVE', 'subnets': [u'a95de632-f01e-442e-ac0f-d5b8fce10112'], 'name': u'private', 'provider:physical_network': None, 'admin_state_up': True, 'tenant_id': u'76a0f74cb5444da988c491270ecad774', 'provider:network_type': u'local', 'router:external': False, 'shared': False, 'id': u'f9263bb5-9c37-4314-baf9-0ef7eb873155', 'provider:segmentation_id': None}

However this is only a warning

[Nachi Ueno (nati-ueno)]

The error is caused by nova show didn't includes private network ip.
On that timing, it looks neutron returns the ip.

2013-08-05 22:42:18.894 3122 DEBUG neutronclient.client [-]
REQ: curl -i http://127.0.0.1:9696/v2.0/ports.json?device_id=d0e9b096-a073-476a-9de7-ce67087bbf42 -X GET -H "X-Auth-Token: MIIR2wYJKoZIhvcNAQcCoIIRzDCCEcgCAQExCTAHBgUrDgMCGjCCEDEGCSqGSIb3DQEHAaCCECIEghAeeyJhY2Nlc3MiOiB7InRva2VuIjogeyJpc3N1ZWRfYXQiOiAiMjAxMy0wOC0wNVQyMjo0MjoxOC43NTcxOTkiLCAiZXhwaXJlcyI6ICIyMDEzLTA4LTA2VDIyOjQyOjE4WiIsICJpZCI6ICJwbGFjZWhvbGRlciIsICJ0ZW5hbnQiOiB7ImRlc2NyaXB0aW9uIjogbnVsbCwgImVuYWJsZWQiOiB0cnVlLCAiaWQiOiAiNzZhMGY3NGNiNTQ0NGRhOTg4YzQ5MTI3MGVjYWQ3NzQiLCAibmFtZSI6ICJkZW1vIn19LCAic2VydmljZUNhdGFsb2ciOiBbeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjg3NzQvdjIvNzZhMGY3NGNiNTQ0NGRhOTg4YzQ5MTI3MGVjYWQ3NzQiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjg3NzQvdjIvNzZhMGY3NGNiNTQ0NGRhOTg4YzQ5MTI3MGVjYWQ3NzQiLCAiaWQiOiAiMzQ0NjFjYWNiYzFkNDYwMGIyOTU1NmI2MjRjMjM4ZTciLCAicHVibGljVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6ODc3NC92Mi83NmEwZjc0Y2I1NDQ0ZGE5ODhjNDkxMjcwZWNhZDc3NCJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJjb21wdXRlIiwgIm5hbWUiOiAibm92YSJ9LCB7ImVuZHBvaW50cyI6IFt7ImFkbWluVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6OTY5Ni8iLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjk2OTYvIiwgImlkIjogIjZlMzZlMTFmNGY4YjQyZGI5YzMxMzliMGE1MjYyZTdkIiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjk2OTYvIn1dLCAiZW5kcG9pbnRzX2xpbmtzIjogW10sICJ0eXBlIjogIm5ldHdvcmsiLCAibmFtZSI6ICJuZXV0cm9uIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4Nzc0L3YzIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4Nzc0L3YzIiwgImlkIjogIjI3OTE4NzFmOTY0YTRmNmJiNWRiZjQyZDUxNWU3NTFjIiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjg3NzQvdjMifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAiY29tcHV0ZXYzIiwgIm5hbWUiOiAibm92YSJ9LCB7ImVuZHBvaW50cyI6IFt7ImFkbWluVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6MzMzMyIsICJyZWdpb24iOiAiUmVnaW9uT25lIiwgImludGVybmFsVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6MzMzMyIsICJpZCI6ICIyMDZlZjMwNWM0MmU0NmYzYTVmNDYxODMxNWUyNmM2NSIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTozMzMzIn1dLCAiZW5kcG9pbnRzX2xpbmtzIjogW10sICJ0eXBlIjogInMzIiwgIm5hbWUiOiAiczMifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjkyOTIiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjkyOTIiLCAiaWQiOiAiNWE0N2I4OTYwOTVhNDJkNjg4YTFlOWE5ZjMwMDcxNmUiLCAicHVibGljVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6OTI5MiJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJpbWFnZSIsICJuYW1lIjogImdsYW5jZSJ9LCB7ImVuZHBvaW50cyI6IFt7ImFkbWluVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6ODc3NyIsICJyZWdpb24iOiAiUmVnaW9uT25lIiwgImludGVybmFsVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6ODc3NyIsICJpZCI6ICIyYWViYWE0YjI0NmU0OTJjYjkxOGVkY2IwMjVlYTBiMyIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4Nzc3In1dLCAiZW5kcG9pbnRzX2xpbmtzIjogW10sICJ0eXBlIjogIm1ldGVyaW5nIiwgIm5hbWUiOiAiY2VpbG9tZXRlciJ9LCB7ImVuZHBvaW50cyI6IFt7ImFkbWluVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6ODAwMC92MSIsICJyZWdpb24iOiAiUmVnaW9uT25lIiwgImludGVybmFsVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6ODAwMC92MSIsICJpZCI6ICIyYjUzNjc1MGNmYTM0NjRmODUzNDg5Y2EwZTZlMDAxYSIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4M...

[Sean Dague (sdague)]

So the race is because nova shows something active before we have allocated it a fixedip?

2013-08-05 22:42:13.102 | + timeout 90 sh -c 'while ! nova show d0e9b096-a073-476a-9de7-ce67087bbf42 | grep status | grep -q ACTIVE; do sleep 1; done'
2013-08-05 22:42:18.243 | ++ nova show d0e9b096-a073-476a-9de7-ce67087bbf42
2013-08-05 22:42:18.243 | ++ grep private
2013-08-05 22:42:18.243 | ++ get_field 2
2013-08-05 22:42:18.280 | ++ read data
2013-08-05 22:42:19.086 | + IP=
2013-08-05 22:42:19.086 | + die_if_not_set 136 IP 'Failure retrieving IP address'
2013-08-05 22:42:19.086 | + local exitcode=0
2013-08-05 22:42:19.123 | ++ set +o
2013-08-05 22:42:19.123 | ++ grep xtrace
2013-08-05 22:42:19.123 | + FXTRACE='set -o xtrace'
2013-08-05 22:42:19.123 | + set +o xtrace
2013-08-05 22:42:19.124 | [ERROR] /opt/stack/new/devstack/exercises/floating_ips.sh:136 Failure retrieving IP address

Can this be fixed with an exercise fix of waiting for an IP address to show up in the devstack exercise?

[Sean Dague (sdague)]

This might actually be a nova / devstack race. Title updated accordingly.

[Cyril Roelandt (cyril-roelandt)]

For what it's worth, I'm getting the same error when running volumes.sh. See the attached log for this test. There are multiples errors during the test:

ERROR: Unable to delete any of the specified servers.
ERROR: No server with a name or ID of 'ex-vol-inst' exists.
[ERROR] /home/vagrant/devstack/exercises/volumes.sh:139 Failure retrieving IP address

[Nachi Ueno (nati-ueno)]

IMO,the cause of this sequence error is
nova show didn't return IP address sometimes.

This fails another gating issue
https://bugs.launchpad.net/neutron/+bug/1210391

[Mark McClain (markmcclain)]

Doesn't seem to breaking the gate lately. Lowering priority after investigation by Nachi.

[Salvatore Orlando (salvatore-orlando)]

"Failure retrieving IP address" still shows up, but only in cell jobs running nova-network.
The information (traces, link, log excerpts) in this bug report are also too old to make a reliable analysis now (linked logs have long gone).

I am setting this bug as won't fix since it does not even have an associated e-r query which would have allowed us to do some analysis. If similar failures are seen again, we'll file a new bug.