KeyError on "subnet_dhcp_ip = subnet_to_interface_ip[subnet.id]"

[Richard Theis]

The networking-ovn gate-tempest-dsvm-networking-ovn job is seeing KeyErrors on "subnet_dhcp_ip = subnet_to_interface_ip[subnet.id]". It is unclear yet if this is contributing to the recent job failures.

LogStash Query:
http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22subnet_dhcp_ip%20%3D%20subnet_to_interface_ip%5Bsubnet.id%5D%5C%22

[Hirofumi Ichihara (ichihara-hirofumi)]

I can see many hits in Logstash. But I'm not sure whether neutron bug or ovn bug.

[Richard Theis (rtheis)]

I'm assuming this is a neutron bug since OVN isn't managing DHCP. Yesterday, Kevin Benton mentioned on IRC that he noticed an incorrect assumption being made. You may want to check with him on the details.

[Richard Theis (rtheis)]

I wonder if this may be related to the networking-ovn DHCP agent configuration: see https://review.openstack.org/#/c/374186/

[Richard Theis (rtheis)]

After a couple test runs with https://review.openstack.org/#/c/374186/, it appears that the problems may be related to the DHCP configuration options force_metadata=True and enable_isolated_metadata=True.

[Carl Baldwin (carl-baldwin)]

Just took a quick look at the traceback [1] and I thought I'd leave a few breadcrumbs behind. The index error happens here [2]. Looks like the interface for the subnet doesn't exist when it is expected to. Could it be a race between creating the interface and this code? That's just off the top of my head.

[1] http://paste.openstack.org/show/582442/
[2] https://github.com/openstack/neutron/blob/4ff772ff07c6f4275cdcdbf3ebaf1642ff721420/neutron/agent/linux/dhcp.py#L888

[Richard Theis (rtheis)]

In additional to the key error, the following errors are also seen in the DHCP logs.

Cannot remove namespace file:
http://logs.openstack.org/74/353074/7/check/gate-tempest-dsvm-networking-ovn/846e796/logs/screen-q-dhcp.txt.gz#_2016-09-22_11_22_37_032

NoFilterMatched:
http://logs.openstack.org/74/353074/7/check/gate-tempest-dsvm-networking-ovn/846e796/logs/screen-q-dhcp.txt.gz#_2016-09-22_11_34_59_137

With the networking-ovn workaround (https://review.openstack.org/#/c/374186/), the key errors and NoFilterMatched errors no longer occur. The workaround successfully completed the gate tests 7 times while the gate-tempest-dsvm-networking-ovn failure rate was around 50%.

[Richard Theis (rtheis)]

A couple more items to note:
1) "Timeout waiting for vif plugging" failures in nova are often seen with the errors because DHCP fails to complete port provisioning before the timeout.
2) Problems similar to https://bugs.launchpad.net/neutron/+bug/1622616 are often seen with the errors.

[Richard Theis (rtheis)]

I was able to recreate the failures noted in comments #6 and #7 with neutron as well. See https://review.openstack.org/#/c/374888/ and http://logs.openstack.org/88/374888/1/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/cf76519/

[Ihar Hrachyshka (ihar-hrachyshka)]

The subnet_to_interface_ip represents addresses on a tap device that also belong to one of subnets of the network. Looking for 'ip addr add' commands executed for a tap device in question in logs, I don't see any except for metadata ip. The list of ips to set inside init_l3 is build in DeviceManager.setup(). Apparently, setup_dhcp_port returned a port with some fixed ips missing. Can it suggest plugin somehow missing returning fixed ips for a port? Or not allocating any for ipv6 stateful network?

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/375562

[OpenStack Infra (hudson-openstack)]

Change abandoned by Ihar Hrachyshka (<email address hidden>) on branch: master
Review: https://review.openstack.org/375562
Reason: Wrong approach: the cache is supposed to reflect backend state not database.

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: stable/newton
Review: https://review.openstack.org/375645

[OpenStack Infra (hudson-openstack)]

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

commit d4f92ede9ed52cd0b9059d993e3cf1f42d5ff57e
Author: Brian Haley <email address hidden>
Date: Tue Sep 6 14:44:41 2016 -0400

    Fix dhcp_release6 error when not supported

    If the system does not have a version of dnsmasq that supports
    dhcp_release6, warn about but otherwise handle it gracefully, and also
    don't even try to execute it the next time.

    Closes-Bug: #1622002
    Related-Bug: #1624079
    Change-Id: I6bb9547f9d9a9fcfb2357521f3f5bd1dc1dd5136

[Kevin Benton (kevinbenton)]

According to logstash[1], these failures stopped at about the same time (~ Sept 21st, 2:00AM PDT) this pair of patches went in: [2], [3]. I think either one would have fixed the issue of reloading based on inconsistent data between the active DHCP subnets and the DHCP agent's interface due to stale update messages.

1. http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22subnet_dhcp_ip%20%3D%20subnet_to_interface_ip%5Bsubnet.id%5D%5C%22
2. https://github.com/openstack/neutron/commit/a7e528bc8fe2dc957187fdd7eb135dbed8a762cf
3. https://github.com/openstack/neutron/commit/2e14c087a9ec6773ed0072cc9c0d9a42785343a0

[Kevin Benton (kevinbenton)]

Proposed a revert to https://review.openstack.org/#/c/374186/ to confirm here: https://review.openstack.org/#/c/375729/

[Kevin Benton (kevinbenton)]

No luck. Logstash was just really far behind. Looking into it

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/375645
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=f74a6c047f02e077e4fd943e2eb256df82e05509
Submitter: Jenkins
Branch: stable/newton

commit f74a6c047f02e077e4fd943e2eb256df82e05509
Author: Brian Haley <email address hidden>
Date: Tue Sep 6 14:44:41 2016 -0400

    Fix dhcp_release6 error when not supported

    If the system does not have a version of dnsmasq that supports
    dhcp_release6, warn about but otherwise handle it gracefully, and also
    don't even try to execute it the next time.

    Closes-Bug: #1622002
    Related-Bug: #1624079

    (cherry picked from commit d4f92ede9ed52cd0b9059d993e3cf1f42d5ff57e)
    Change-Id: I6bb9547f9d9a9fcfb2357521f3f5bd1dc1dd5136

[OpenStack Infra (hudson-openstack)]

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

commit d1fb4238306f854ab610204a50c5cdc20ea5c770
Author: Kevin Benton <email address hidden>
Date: Thu Sep 22 23:38:33 2016 -0700

    Fixes for missing IPs on subnets in DHCP agent

    There is a race condition server-side where a port request containing
    a subnet_id is processed at the same time the subnet is being deleted,
    the port operation may be successful without having a fixed IP on the
    requested subnet. This patch makes the DHCP agent resillient to this
    bug by checking the port response and raising a SubnetMismatchForPort
    to trigger a resync if it doesn't have all of the requested subnet IDs.

    Additionally, it avoids skipping assignment of IPv6 addresses to the
    interface if they are stateless. The original logic to skip assignment
    was only meant to be for SLAAC addresses.

    Both of these issues were resulting in the KeyError observed in the
    bug report.

    Related-Bug: #1627480
    Closes-Bug: #1624079
    Change-Id: I85ef1f4d60efd0309d6a0706e29fdbcc16f0b59d

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/newton
Review: https://review.openstack.org/377089

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/377089
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=571af6bc37315ff023981904bd2592aa8ec0ec14
Submitter: Jenkins
Branch: stable/newton

commit 571af6bc37315ff023981904bd2592aa8ec0ec14
Author: Kevin Benton <email address hidden>
Date: Thu Sep 22 23:38:33 2016 -0700

    Fixes for missing IPs on subnets in DHCP agent

    There is a race condition server-side where a port request containing
    a subnet_id is processed at the same time the subnet is being deleted,
    the port operation may be successful without having a fixed IP on the
    requested subnet. This patch makes the DHCP agent resillient to this
    bug by checking the port response and raising a SubnetMismatchForPort
    to trigger a resync if it doesn't have all of the requested subnet IDs.

    Additionally, it avoids skipping assignment of IPv6 addresses to the
    interface if they are stateless. The original logic to skip assignment
    was only meant to be for SLAAC addresses.

    Both of these issues were resulting in the KeyError observed in the
    bug report.

    Related-Bug: #1627480
    Closes-Bug: #1624079
    Change-Id: I85ef1f4d60efd0309d6a0706e29fdbcc16f0b59d
    (cherry picked from commit d1fb4238306f854ab610204a50c5cdc20ea5c770)

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

[Armando Migliaccio (armando-migliaccio)]

Did didn't work as it should have. It's safer to back out and take this slow.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

commit c0d0986e8b7412f7c37db799177dc529ce9045d2
Author: Kevin Benton <email address hidden>
Date: Sun Sep 25 15:49:19 2016 -0700

    Correct fix for IPv6 auto address interfaces

    This is a partial revert of d1fb4238306f854ab610204a50c5cdc20ea5c770.
    That patch attempted to allow the DHCP agent to manage IPv6 interfaces
    to avoid a KeyError in the subnet_interface_map. However, this led
    to races with router advertisements and static configuration
    (see bug 1627902).

    The correct fix was actually a very simple conditional that was broken
    because this map shouldn't have been referenced for IPv6 subnets in
    the first place. The force metadata option was shortcutting the whole
    evaluation so the agent was trying to add a metadata route to a v6
    subnet.

    This patch undoes the v6 changes from
    d1fb4238306f854ab610204a50c5cdc20ea5c770, corrects the conditional,
    and adds a simple unit test that ensures the branch doesn't throw
    and error.

    Closes-Bug: #1624079
    Change-Id: Ide494b6333a4f1e279ab58aa27c0aa719e79545d

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/newton
Review: https://review.openstack.org/377793

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/377793
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=98c4c0876d4df31cf1eb34a2bcc40660e938a2ef
Submitter: Jenkins
Branch: stable/newton

commit 98c4c0876d4df31cf1eb34a2bcc40660e938a2ef
Author: Kevin Benton <email address hidden>
Date: Sun Sep 25 15:49:19 2016 -0700

    Correct fix for IPv6 auto address interfaces

    This is a partial revert of d1fb4238306f854ab610204a50c5cdc20ea5c770.
    That patch attempted to allow the DHCP agent to manage IPv6 interfaces
    to avoid a KeyError in the subnet_interface_map. However, this led
    to races with router advertisements and static configuration
    (see bug 1627902).

    The correct fix was actually a very simple conditional that was broken
    because this map shouldn't have been referenced for IPv6 subnets in
    the first place. The force metadata option was shortcutting the whole
    evaluation so the agent was trying to add a metadata route to a v6
    subnet.

    This patch undoes the v6 changes from
    d1fb4238306f854ab610204a50c5cdc20ea5c770, corrects the conditional,
    and adds a simple unit test that ensures the branch doesn't throw
    and error.

    Closes-Bug: #1624079
    Change-Id: Ide494b6333a4f1e279ab58aa27c0aa719e79545d
    (cherry picked from commit c0d0986e8b7412f7c37db799177dc529ce9045d2)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/neutron 9.0.0.0rc2 release candidate.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/neutron 10.0.0.0b1 development milestone.