IpAddressGenerationFailure while handling dhcp ports

[Armando Migliaccio]

Due to timing issues, if a subnet is deleted concurrently with a request from the dhcp agent the following stacktraces can be seen:

2013-11-20 18:01:57.523 2727 DEBUG neutron.db.dhcp_rpc_base [-] Create dhcp port {u'port': {u'name': u'', u'admin_state_up': True, u'network_id': u'5c86cd4c-b37b-49fb-b3c4-ca43c4f9835c', u'tenant_id': u'5caf7376a94a483a9b0ba7fbabdd8843', u'fixed_ips': [{u'subnet_id': u'9610bd56-552f-4ad7-a8f0-d9ec2c75cbba'}], u'device_id': u'dhcp83d3530b-d4a1-5fee-8532-f3249772754b-5c86cd4c-b37b-49fb-b3c4-ca43c4f9835c'}} from devstack-precise-check-rax-iad-700557.slave.openstack.org. create_dhcp_port /opt/stack/new/neutron/neutron/db/dhcp_rpc_base.py:228
2013-11-20 18:01:57.527 2727 DEBUG neutron.plugins.ml2.plugin [-] Deleting subnet record delete_subnet /opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:517
2013-11-20 18:01:57.539 2727 DEBUG neutron.db.db_base_plugin_v2 [-] Generated mac for network 5c86cd4c-b37b-49fb-b3c4-ca43c4f9835c is fa:16:3e:d7:d4:cf _generate_mac /opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py:302
2013-11-20 18:01:57.547 2727 DEBUG neutron.plugins.ml2.plugin [-] Committing transaction delete_subnet /opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:521
2013-11-20 18:01:57.552 2727 DEBUG neutron.db.db_base_plugin_v2 [-] All IPs from subnet 9610bd56-552f-4ad7-a8f0-d9ec2c75cbba (10.100.0.0/24) allocated _generate_ip /opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py:466
2013-11-20 18:01:57.553 2727 DEBUG neutron.openstack.common.rpc.amqp [-] Sending subnet.delete.end on notifications.info notify /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:598
2013-11-20 18:01:57.553 2727 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is b697e0b56ef74e44b3f3ea564b21b864. _add_unique_id /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:339
2013-11-20 18:01:57.554 2727 ERROR neutron.openstack.common.rpc.amqp [-] Exception during message handling
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp Traceback (most recent call last):
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py", line 438, in _process_data
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp **args)
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/common/rpc.py", line 44, in dispatch
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp neutron_ctxt, version, method, namespace, **kwargs)
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/openstack/common/rpc/dispatcher.py", line 172, in dispatch
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp result = getattr(proxyobj, method)(ctxt, **kwargs)
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/db/dhcp_rpc_base.py", line 235, in create_dhcp_port
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp return plugin.create_port(context, port)
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/plugins/ml2/plugin.py", line 551, in create_port
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp result = super(Ml2Plugin, self).create_port(context, port)
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py", line 1332, in create_port
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp ips = self._allocate_ips_for_port(context, network, port)
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py", line 704, in _allocate_ips_for_port
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp ips = self._allocate_fixed_ips(context, network, configured_ips)
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py", line 648, in _allocate_fixed_ips
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp result = self._generate_ip(context, subnets)
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py", line 483, in _generate_ip
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp raise q_exc.IpAddressGenerationFailure(net_id=subnets[0]['network_id'])
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp IpAddressGenerationFailure: No more IP addresses available on network 5c86cd4c-b37b-49fb-b3c4-ca43c4f9835c.
2013-11-20 18:01:57.554 2727 TRACE neutron.openstack.common.rpc.amqp

Or similarly:

2013-11-20 17:48:31.865 32606 DEBUG neutron.plugins.ml2.plugin [-] Deleting subnet record delete_subnet /opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:525
2013-11-20 17:48:31.880 32606 DEBUG neutron.plugins.ml2.plugin [-] Committing transaction delete_subnet /opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:529
2013-11-20 17:48:31.882 32606 DEBUG neutron.db.db_base_plugin_v2 [-] Generated mac for network ad5c76d7-96ff-4089-a9d7-d31ef5869f84 is fa:16:3e:7a:cd:2d _generate_mac /opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py:302
2013-11-20 17:48:31.893 32606 DEBUG neutron.db.db_base_plugin_v2 [-] All IPs from subnet 656f7834-ee5f-4ddf-8ae2-b36025f116e0 (10.100.0.0/24) allocated _generate_ip /opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py:466
2013-11-20 17:48:31.894 32606 DEBUG neutron.openstack.common.rpc.amqp [-] Sending subnet.delete.end on notifications.info notify /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:598
2013-11-20 17:48:31.894 32606 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is 2a6e2cc37d324a4cafcad46c12cc6754. _add_unique_id /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:339
2013-11-20 17:48:31.895 32606 ERROR neutron.openstack.common.rpc.amqp [-] Exception during message handling
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp Traceback (most recent call last):
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py", line 438, in _process_data
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp **args)
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/common/rpc.py", line 44, in dispatch
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp neutron_ctxt, version, method, namespace, **kwargs)
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/openstack/common/rpc/dispatcher.py", line 172, in dispatch
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp result = getattr(proxyobj, method)(ctxt, **kwargs)
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/db/dhcp_rpc_base.py", line 169, in get_dhcp_port
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp retval = plugin.create_port(context, dict(port=port_dict))
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/plugins/ml2/plugin.py", line 557, in create_port
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp result = super(Ml2Plugin, self).create_port(context, port)
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py", line 1332, in create_port
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp ips = self._allocate_ips_for_port(context, network, port)
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py", line 704, in _allocate_ips_for_port
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp ips = self._allocate_fixed_ips(context, network, configured_ips)
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py", line 648, in _allocate_fixed_ips
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp result = self._generate_ip(context, subnets)
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp File "/opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py", line 483, in _generate_ip
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp raise q_exc.IpAddressGenerationFailure(net_id=subnets[0]['network_id'])
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp IpAddressGenerationFailure: No more IP addresses available on network ad5c76d7-96ff-4089-a9d7-d31ef5869f84.
2013-11-20 17:48:31.895 32606 TRACE neutron.openstack.common.rpc.amqp

These are rather harmless but it'd be good to get rid of them

[Armando Migliaccio (armando-migliaccio)]

106 hits during the the past 7days:

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

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/57775
Committed: http://github.com/openstack/neutron/commit/8faa5f076bc8c7906d8d987931b7c817acfcbe8b
Submitter: Jenkins
Branch: master

commit 8faa5f076bc8c7906d8d987931b7c817acfcbe8b
Author: armando-migliaccio <email address hidden>
Date: Thu Nov 21 13:07:28 2013 -0800

    Handle IPAddressGenerationFailure during get_dhcp_port

    If a network/subnet is deleted while the dhcp agent is trying
    to get/create a dhcp port for that network, the exception
    will be raised because no IP Allocation Range is available.

    However, this particular failure mode causes just noise, because
    the dhcp agent can cope with it without problems.

    A follow-up patch will deal with the other exception traces during
    create_dhcp_port

    Partial-bug: #1253344

    Change-Id: I7fe35455ce905daa22ff96367e120864a7d3fb92

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/57812
Committed: http://github.com/openstack/neutron/commit/bff120a4775a1b1f3846a27c38d8eff4a678fd24
Submitter: Jenkins
Branch: master

commit bff120a4775a1b1f3846a27c38d8eff4a678fd24
Author: armando-migliaccio <email address hidden>
Date: Thu Nov 21 18:42:08 2013 -0800

    Handle exceptions on create_dhcp_port

    If a network/subnet is deleted while creating the dhcp
    port, the agent will detect a conflict on state of the
    network and deal with it accordingly.

    A concurrent delete may manifest itself via a number
    of exceptions, IPAddressGenerationFailure amongst others,
    hence the refactoring of the error handling logic into its
    own utility method.

    Partial-bug: #1253344
    Related-bug: #1243726

    Change-Id: I442beb5f82f3db8786eea53926903ef0ba0efbf1

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/59664
Committed: http://github.com/openstack/neutron/commit/b48ddb648b4fe1b428328a91d0a045b837119f29
Submitter: Jenkins
Branch: master

commit b48ddb648b4fe1b428328a91d0a045b837119f29
Author: armando-migliaccio <email address hidden>
Date: Tue Nov 26 14:45:24 2013 -0800

    Handle failures on update_dhcp_port

    Ensure exceptions due to conflicting
    state of network or subnet resources
    are dealt with by the dhcp agent.

    Closes-bug: #1253344
    Related-bug: #1243726

    Change-Id: I4fd51442c034fabc91d5a3f065f4df98f5fad35b

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/havana
Review: https://review.openstack.org/60570

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/havana
Review: https://review.openstack.org/60571

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/havana
Review: https://review.openstack.org/60572

[ZhiQiang Fan (aji-zqfan)]

is it necessary to merge into stable/havana? (I think the misleading log should be fixed but I don't know whether it is an urgent bug or not)

or more generally, under what condition should we merge into stable branch when we fix a bug?

[Alan Pevec (apevec)]

> under what condition should we merge into stable branch when we fix a bug?

https://wiki.openstack.org/wiki/StableBranch#Appropriate_Fixes

In addition to what's listed in that wiki, I'd welcome fixes which improve gate job stability.