Newly created DVR router as a result of new VM does not get ARP neighbors update, new VM has no connectivity

Um...wondering if this is a regression. Any chance you can back out to see how far back this used to work?

I wonder if 3f3874717c07e2b469ea6c6fd52bcb4da7b380c7 is the culprit.

Um...I remember I had seen something similar. Is this a duplicate of bug #1411883? Please confirm.

If my (wild) guess is correct, then the culprit is: https://review.openstack.org/#/c/113999/ and the attempted fix has somewhat stalled.

The problem here is not calling "_set_subnet_arp_info" from the "process_router" in L3-agent.
Originially in "Juno" the "_set_subnet_arp_info" was called in process_router. So even when the "arp_update" message has been dropped because of the non-existence of the "ri.router_info" for the given router_id it was able to update the router.

But now this "_set_subnet_arp_info" is only called when "internal_network" is added to the router.

That is the reason for this failure.

Also previously in "Juno" the "dvr_vmarp_table_update" was called from the ML2 plugin only for the "port-delete" and not the "port-create".

This bug got introduced by the l3 agent refactor and not by the https://review.openstack.org/#/c/113999/

This bug is not the same as "bug#1411883".

This is a valid bug.

Swami, looking at the code in the server it looks to me like the L3 agents won't receive the ARP messages at all because the routers are not scheduled yet. I'd love to know I'm wrong and the agents do receive the message but because of some agent bug the ip neigh command is not being executed. Can you confirm that the agents actually receive the ARP RPC messages when you spawn a new VM on a new compute?

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

Assaf yes the "RPC message is received by the agent" when you spawn an new VM on a Compute.

Most of the times I do see that it immediately returns with "ri.router_info" not found.

But once or twice I did see a "race condition" were the "arp_update" came in and the check for "ri.router_info" succeeded and then it errored when it was trying to add the arp entry into the given "qrouter-namespace".

2015-04-02 23:47:09.381 WARNING neutron.agent.l3.dvr [req-ae682b32-73cf-4ef5-b86d-4a7fe331bd9f None None] Inside Add arp entry
2015-04-02 23:47:09.381 DEBUG neutron.agent.linux.utils [req-ae682b32-73cf-4ef5-b86d-4a7fe331bd9f None None] Running command (rootwrap daemon): ['ip', 'netns', 'exec', 'qrouter-8070a83f-d16b-4990-ab33-732c9fc2d6ed', 'ip', '-4', 'neigh', 'replace', '10.1.0.3', 'lladdr', 'fa:16:3e:90:2d:10', 'nud', 'permanent', 'dev', 'qr-534334b1-c8'] from (pid=22638) execute_rootwrap_daemon /opt/stack/neutron/neutron/agent/linux/utils.py:98
2015-04-02 23:47:09.446 DEBUG neutron.agent.linux.utils [-]
Command: ['ip', '-o', 'netns', 'list']
Exit code: 0
Stdin:
Stdout:
Stderr: from (pid=22638) execute /opt/stack/neutron/neutron/agent/linux/utils.py:132
2015-04-02 23:47:09.446 DEBUG neutron.agent.linux.utils [-] Running command (rootwrap daemon): ['ip', 'netns', 'add', 'qrouter-8070a83f-d16b-4990-ab33-732c9fc2d6ed'] from (pid=22638) execute_rootwrap_daemon /opt/stack/neutron/neutron/agent/linux/utils.py:98
2015-04-02 23:47:09.447 ERROR neutron.agent.linux.utils [req-ae682b32-73cf-4ef5-b86d-4a7fe331bd9f None None]
Command: ['ip', 'netns', 'exec', u'qrouter-8070a83f-d16b-4990-ab33-732c9fc2d6ed', 'ip', '-4', 'neigh', 'replace', u'10.1.0.3', 'lladdr', u'fa:16:3e:90:2d:10', 'nud', 'permanent', 'dev', u'qr-534334b1-c8']
Exit code: 1
Stdin:
Stdout:
Stderr: Cannot open network namespace "qrouter-8070a83f-d16b-4990-ab33-732c9fc2d6ed": No such file or directory

2015-04-02 23:47:09.447 ERROR neutron.agent.l3.dvr_router [req-ae682b32-73cf-4ef5-b86d-4a7fe331bd9f None None] DVR: Failed updating arp entry
2015-04-02 23:47:09.447 TRACE neutron.agent.l3.dvr_router Traceback (most recent call last):
2015-04-02 23:47:09.447 TRACE neutron.agent.l3.dvr_router File "/opt/stack/neutron/neutron/agent/l3/dvr_router.py", line 195, in _update_arp_entry
2015-04-02 23:47:09.447 TRACE neutron.agent.l3.dvr_router device.neigh.add(ip, mac)
2015-04-02 23:47:09.447 TRACE neutron.agent.l3.dvr_router File "/opt/stack/neutron/neutron/agent/linux/ip_lib.py", line 538, in add
2015-04-02 23:47:09.447 TRACE neutron.agent.l3.dvr_router 'dev', self.name))
2015-04-02 23:47:09.447 TRACE neutron.agent.l3.dvr_router File "/opt/stack/neutron/neutron/agent/linux/ip_lib.py", line 222, in _as_root
2015-04-02 23:47:09.447 TRACE neutron.agent.l3.dvr_router use_root_namespace=use_root_namespace)
2015-04-02 23:47:09.447 TRACE neutron.agent.l3.dvr_router File "/opt/stack/neutron/neutron/agent/linux/ip_lib.py", line 69, in _as_root
2015-04-02 23:47:09.447 TRACE neutron.agent.l3.dvr_router log_fail_as_error=self.log_fail_as_error)
2015-04-02 23:47:09.447 TRACE neutron.agent.l3.dvr_router File "/opt/stack/neutron/neutron/agent/linux/ip_lib.py", line 78, in _execute
201...

Swami said: 'But now this "_set_subnet_arp_info" is only called when "internal_network" is added to the router.

That is the reason for this failure. [...] This bug got introduced by the l3 agent refactor '

Here is where _set_subnet_info is called in Juno:

        for p in new_ports:
            self._set_subnet_info(p)
            self.internal_network_added(ri, p)
            ri.internal_ports.append(p)
            self._set_subnet_arp_info(ri, p)

So, it was only called when "internal_network" is added to the router. The refactoring moved things around but as far as I can tell it is called under the same conditions as it was before. So, we need more information about how _set_subnet_info is involved in this.

Swami said: 'previously in "Juno" the "dvr_vmarp_table_update" was called from the ML2 plugin only for the "port-delete" and not the "port-create".'

In Juno, dvr_vmarp_table_update was also called from neutron.plugins.ml2.rpc.RpcCallbacks.update_device_up called from treat_devices_added_or_updated in ovs_neutron_agent. Wouldn't this me called in the create port code path also?

It would help if we could pinpoint how far back this was broken. Git bisect could help here.

I think the comment thread here has ignored Armando's first comment (comment #1). Have you looked in to that commit as the potential culprit?

Hi Carl,
You right about the sequence "internal_network_added" and then calling the "_set_subnet_arp_info".
But now inside the "internal_network_added" it checks for external_gateway, snat and then calls the "_set_subnet_arp_info.
If anyone of this is not valid it quits.

So it does not hit the "_set_subnet_arp_info".

The new changes have altered the condition to call this function. That is what I was trying to say.

Carl yes I got that clarified that the dvr_vmarp_table_update is called for port_update. ( This is the same behavior for Juno and kilo).
Armando clarified it.

Looking deeper in to my comment #8. I do believe that https://review.openstack.org/#/c/154513 did change the behavior here. I just didn't see it at first. It moves _set_subnet_arp_info under internal_network_added in dvr_router.py but makes it conditional on a number of things where it was called unconditionally before. So, I think we found the culprit.

Bumping to critical, as without this bug fix, the first VM booted by a tenant with a DVR router will not get an IP address from the DHCP agent.

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

commit e585c822e38919451beeb95406c521b09b18e9fc
Author: Swaminathan Vasudevan <email address hidden>
Date: Thu Apr 2 17:25:39 2015 -0700

    Fix dynamic arp populate error for dvr routers

    Recent refactor to the L3 Agent have introduced
    this problem. When we create a VM after we
    attach an interface to a router or when we add
    an interface with an existing VM to a router, in
    both cases the arp entries for the dvr serviced
    ports are not getting populated in the Router
    Namespace.

    Closes-Bug: #1438969

    Change-Id: I4a82e2435d176f3d9336d7f0dab9726c063840b9
    Co-authored-by: Armando Migliaccio <email address hidden>

To complete the discussion going on in comments 5 and 7, even if a router doesn't get an ARP RPC message (Because it wasn't yet scheduled, or because it was scheduled but not yet configured on the agent), when the router is configured on the agent it uses an RPC method to get all ports on its subnets and configures ARP entries for them. So I'm confident that feature should work as expected with this fix.

Fix proposed to branch: neutron-pecan
Review: https://review.openstack.org/185072