OpenStack Compute (nova)

"FixedIpNotFoundForAddress: Fixed ip not found for address None." traces in gate runs

Bug #1439302 reported by Matt Riedemann
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
High
Matt Riedemann
OpenStack Compute (nova) 2015.1.0 "kilo"
Juno
Fix Released
Undecided
Unassigned
OpenStack Compute (nova) 2014.2.4

Bug Description

Seeing this quite a bit in normal gate runs:

http://logs.openstack.org/53/169753/2/check/check-tempest-dsvm-full-ceph/07dcae0/logs/screen-n-cpu.txt.gz?level=TRACE#_2015-04-01_14_34_37_110

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiRml4ZWRJcE5vdEZvdW5kRm9yQWRkcmVzczogRml4ZWQgaXAgbm90IGZvdW5kIGZvciBhZGRyZXNzIE5vbmUuXCIgQU5EIHRhZ3M6XCJzY3JlZW4tbi1jcHUudHh0XCIgQU5EIHRhZ3M6XCJtdWx0aWxpbmVcIiIsImZpZWxkcyI6W10sIm9mZnNldCI6MCwidGltZWZyYW1lIjoiNjA0ODAwIiwiZ3JhcGhtb2RlIjoiY291bnQiLCJ0aW1lIjp7InVzZXJfaW50ZXJ2YWwiOjB9LCJzdGFtcCI6MTQyNzkwMjQ0NTg4OSwibW9kZSI6IiIsImFuYWx5emVfZmllbGQiOiIifQ==

2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] FixedIpNotFoundForAddress: Fixed ip not found for address None.
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d]
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] Traceback (most recent call last):
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d]
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 142, in _dispatch_and_reply
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] executor_callback))
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d]
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 186, in _dispatch
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] executor_callback)
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d]
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 130, in _do_dispatch
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] result = func(ctxt, **new_args)
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d]
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] File "/opt/stack/new/nova/nova/network/floating_ips.py", line 186, in deallocate_for_instance
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] super(FloatingIP, self).deallocate_for_instance(context, **kwargs)
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d]
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] File "/opt/stack/new/nova/nova/network/manager.py", line 558, in deallocate_for_instance
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] instance=instance)
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d]
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] File "/opt/stack/new/nova/nova/network/manager.py", line 214, in deallocate_fixed_ip
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] context, address, expected_attrs=['network'])
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d]
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] File "/opt/stack/new/nova/nova/objects/base.py", line 161, in wrapper
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] args, kwargs)
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d]
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] File "/opt/stack/new/nova/nova/conductor/rpcapi.py", line 329, in object_class_action
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] objver=objver, args=args, kwargs=kwargs)
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d]
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 156, in call
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] retry=self.retry)
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d]
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 90, in _send
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] timeout=timeout, retry=retry)
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d]
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 350, in send
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] retry=retry)
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d]
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 341, in _send
2015-04-01 14:34:37.110 674 TRACE nova.compute.manager [instance: 2fc5caf4-8ff7-45bc-940f-c13d696a1d9d] raise result

In nova.compute.manager._do_build_and_run_instance we're hitting an UnexpectedDeletingTaskStateError exception:

http://logs.openstack.org/53/169753/2/check/check-tempest-dsvm-full-ceph/07dcae0/logs/screen-n-cpu.txt.gz#_2015-04-01_14_34_36_898

Then we start tearing down here:

http://logs.openstack.org/53/169753/2/check/check-tempest-dsvm-full-ceph/07dcae0/logs/screen-n-cpu.txt.gz#_2015-04-01_14_34_36_905

And for some reason there are no fixed_ips with no address once we try to deallocate in the network manager.

See original description
Sean Dague (sdague)
tags: added: ceph
Revision history for this message
Matt Riedemann (mriedem) wrote :

Also seeing it on InstanceNotFound:

http://logs.openstack.org/70/167370/6/check/check-tempest-dsvm-full/9924145/logs/screen-n-cpu.txt.gz#_2015-04-01_15_45_19_884

Changed in nova:
status: New → Confirmed
tags: added: compute network
removed: ceph
Sean Dague (sdague)
Changed in nova:
importance: Undecided → High
Matt Riedemann (mriedem)
description: updated
Revision history for this message
Matt Riedemann (mriedem) wrote :

I'm adding some debug logging in the deallocate_for_instance nova-network flow. I'm thinking this has to be happening from the requested_networks list of tuples that's passed in, otherwise the network manager would try to get the fixed IPs by the instance UUID from the DB and that would fail since nova.objects.FixedIP.address is a non-nullable field.

Revision history for this message
Matt Riedemann (mriedem) wrote :

This also appears to have started around 3/26 and I'm not seeing it on stable/juno.

Revision history for this message
Matt Riedemann (mriedem) wrote :

I'm not seeing much changing in nova compute manager or nova-network around 3/26. This is a possibly related change in tempest on 3/26 related to networks:

https://github.com/openstack/tempest/commit/9ce97dfa353e3659aa0ec0a7f62ed3a7e54c4bdf

Revision history for this message
Matt Riedemann (mriedem) wrote :

This is the error in the n-net logs:

http://logs.openstack.org/70/167370/6/check/check-tempest-dsvm-full/9924145/logs/screen-n-net.txt.gz#_2015-04-01_15_45_20_254

Revision history for this message
Matt Riedemann (mriedem) wrote :

We can see in the server create API that the fixed_ip address is optional:

https://github.com/openstack/nova/blob/2015.1.0b3/nova/api/openstack/compute/servers.py#L316

So with the change in tempest, we're being asked for a specific network now but not a fixed_ip, and when we teardown during build there is no fixed_ip in the request so we trace.

Changed in nova:
status: Confirmed → Triaged
assignee: nobody → Matt Riedemann (mriedem)
Revision history for this message
Matt Riedemann (mriedem) wrote :

Bingo, this is the request to create the instance in tempest:

http://logs.openstack.org/70/167370/6/check/check-tempest-dsvm-full/9924145/logs/tempest.txt.gz#_2015-04-01_15_45_17_878

Note the network uuid is specified but the fixed_ip address is not:

Body: {"server": {"imageRef": "328dba0f-f13b-47eb-bfce-6e3f6ab07eaa", "return_reservation_id": true, "flavorRef": "42", "name": "multiple-create-test-971632462", "min_count": 1, "networks": [{"uuid": "cf357903-a60c-4b1c-8524-a0aaa4bb2fe7"}], "max_count": 2}}

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (master)

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

Changed in nova:
status: Triaged → In Progress
Revision history for this message
Matt Riedemann (mriedem) wrote :

This is also in stable/juno because of this commit:

https://github.com/openstack/nova/commit/03d34c975586788dc25249b5e0b962fc0634008c

tags: added: juno-backport-potential
Changed in nova:
milestone: none → kilo-rc1
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (master)

Reviewed: https://review.openstack.org/169868
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=b42abdbced685e642f08b4ad48e9e64252f85f77
Submitter: Jenkins
Branch: master

commit b42abdbced685e642f08b4ad48e9e64252f85f77
Author: Matt Riedemann <email address hidden>
Date: Wed Apr 1 11:21:50 2015 -0700

    Filter fixed IPs from requested_networks in deallocate_for_instance

    With nova-network, the fixed IP address is optional on the server create
    request.

    Tempest commit 9ce97dfa353e3659aa0ec0a7f62ed3a7e54c4bdf merged on 3/26
    and we started seeing "FixedIpNotFoundForAddress: Fixed ip not found for
    address None." in successful gate runs because with the Tempest change
    the network uuid is passed in (if available) on the boot request but
    there is no address provided, e.g.:

    Body: {"server": {"imageRef": "328dba0f-f13b-47eb-bfce-6e3f6ab07eaa",
    "return_reservation_id": true, "flavorRef": "42", "name":
    "multiple-create-test-971632462", "min_count": 1, "networks": [{"uuid":
    "cf357903-a60c-4b1c-8524-a0aaa4bb2fe7"}], "max_count": 2}}

    When deleting an instance before it's completely built, we try to
    deallocate the network and that failed since deallocate_for_instance
    wasn't filtering out None addresses from requested_networks.

    This fixes the problem by simply filtering the list of fixed IPs from
    requested_networks before trying to deallocate the fixed IPs.

    Closes-Bug: #1439302

    Change-Id: I459a98151406a0b125a65b00fa0186eb5df97b1c

Changed in nova:
status: In Progress → Fix Committed
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (stable/juno)

Fix proposed to branch: stable/juno
Review: https://review.openstack.org/170295

Thierry Carrez (ttx)
Changed in nova:
status: Fix Committed → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (stable/juno)

Reviewed: https://review.openstack.org/170295
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=141bfd95294ebce8145d8a5719b3f7c9f47b7ce5
Submitter: Jenkins
Branch: stable/juno

commit 141bfd95294ebce8145d8a5719b3f7c9f47b7ce5
Author: Matt Riedemann <email address hidden>
Date: Wed Apr 1 11:21:50 2015 -0700

    Filter fixed IPs from requested_networks in deallocate_for_instance

    With nova-network, the fixed IP address is optional on the server create
    request.

    Tempest commit 9ce97dfa353e3659aa0ec0a7f62ed3a7e54c4bdf merged on 3/26
    and we started seeing "FixedIpNotFoundForAddress: Fixed ip not found for
    address None." in successful gate runs because with the Tempest change
    the network uuid is passed in (if available) on the boot request but
    there is no address provided, e.g.:

    Body: {"server": {"imageRef": "328dba0f-f13b-47eb-bfce-6e3f6ab07eaa",
    "return_reservation_id": true, "flavorRef": "42", "name":
    "multiple-create-test-971632462", "min_count": 1, "networks": [{"uuid":
    "cf357903-a60c-4b1c-8524-a0aaa4bb2fe7"}], "max_count": 2}}

    When deleting an instance before it's completely built, we try to
    deallocate the network and that failed since deallocate_for_instance
    wasn't filtering out None addresses from requested_networks.

    This fixes the problem by simply filtering the list of fixed IPs from
    requested_networks before trying to deallocate the fixed IPs.

    Conflicts:
            nova/tests/unit/network/test_manager.py

    NOTE(mriedem): The conflict was just on the test module being moved
    in Kilo.

    Closes-Bug: #1439302

    Change-Id: I459a98151406a0b125a65b00fa0186eb5df97b1c
    (cherry picked from commit b42abdbced685e642f08b4ad48e9e64252f85f77)

tags: added: in-stable-juno
Thierry Carrez (ttx)
Changed in nova:
milestone: kilo-rc1 → 2015.1.0
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

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