yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1604816] [NEW] native ovsdb seems to return before finishing adding/removing port

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Kevin Benton <1604816@xxxxxxxxxxxxxxxxxx>
Date: Wed, 20 Jul 2016 13:26:18 -0000
Reply-to: Bug 1604816 <1604816@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

When using AddPortCommand and DelPortCommand, there seems to be a delay
in when the DB returns and when the actual interface is visible for use
in the system.

In this failure, we can see an AddPortCommand completes and then an ip
link call is made on the tap device which fails because it does not
exist yet:

2016-07-20 12:18:18.555 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Running txn command(idx=0): AddPortCommand(bridge=test-brca25db6d, port=qr-10df58c6-8a, may_exist=False) do_commit neutron/agent/ovsdb/impl_idl.py:83
2016-07-20 12:18:18.556 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Running txn command(idx=1): DbSetCommand(table=Interface, record=qr-10df58c6-8a, col_values=(('type', 'internal'), ('external_ids', {'iface-status': 'active', 'iface-id': '10df58c6-8ad8-4f89-b3d1-36cf26ee5792', 'attached-mac': 'ca:fe:de:ad:be:ef'}))) do_commit neutron/agent/ovsdb/impl_idl.py:83
2016-07-20 12:18:18.570 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Running txn command(idx=0): DbGetCommand(table=Interface, column=ofport, record=qr-10df58c6-8a) do_commit neutron/agent/ovsdb/impl_idl.py:83
2016-07-20 12:18:18.570 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Transaction caused no change do_commit neutron/agent/ovsdb/impl_idl.py:111
2016-07-20 12:18:18.591 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Running txn command(idx=0): DbGetCommand(table=Interface, column=ofport, record=qr-10df58c6-8a) do_commit neutron/agent/ovsdb/impl_idl.py:83
2016-07-20 12:18:18.592 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Transaction caused no change do_commit neutron/agent/ovsdb/impl_idl.py:111
2016-07-20 12:18:18.634 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Running txn command(idx=0): DbGetCommand(table=Interface, column=ofport, record=qr-10df58c6-8a) do_commit neutron/agent/ovsdb/impl_idl.py:83
2016-07-20 12:18:18.634 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Transaction caused no change do_commit neutron/agent/ovsdb/impl_idl.py:111
2016-07-20 12:18:18.715 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Running txn command(idx=0): DbGetCommand(table=Interface, column=ofport, record=qr-10df58c6-8a) do_commit neutron/agent/ovsdb/impl_idl.py:83
2016-07-20 12:18:18.716 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Transaction caused no change do_commit neutron/agent/ovsdb/impl_idl.py:111
2016-07-20 12:18:18.716 28212 DEBUG neutron.agent.linux.utils [req-34784ee2-5510-47ce-af43-fe7691c9dcda - - - - -] Running command (rootwrap daemon): ['ip', 'link', 'set', 'qr-10df58c6-8a', 'address', 'ca:fe:de:ad:be:ef'] execute_rootwrap_daemon neutron/agent/linux/utils.py:99
2016-07-20 12:18:18.724 28212 ERROR neutron.agent.linux.utils [req-34784ee2-5510-47ce-af43-fe7691c9dcda - - - - -] Exit code: 1; Stdin: ; Stdout: ; Stderr: Cannot find device "qr-10df58c6-8a"


On examining the syslog, the interface shows up about 500ms later:

Jul 20 12:18:19 ubuntu-trusty-rax-ord-2672516 kernel: [  978.400048]
device qr-10df58c6-8a entered promiscuous mode


A similar effect is visible in the dhcp stale cleanup test where
DelPortCommand is issued but then the port remains visible afterwards to
a find via /sys/ : http://logs.openstack.org/31/344731/2/check/gate-
neutron-dsvm-functional/98c6b55/logs/dsvm-functional-
logs/neutron.tests.functional.agent.linux.test_dhcp.TestDhcp.test_cleanup_stale_devices.txt.gz

** Affects: neutron
     Importance: Undecided
     Assignee: Kevin Benton (kevinbenton)
         Status: New

** Changed in: neutron
     Assignee: (unassigned) => Kevin Benton (kevinbenton)

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1604816

Title:
  native ovsdb seems to return before finishing adding/removing port

Status in neutron:
  New

Bug description:
  When using AddPortCommand and DelPortCommand, there seems to be a
  delay in when the DB returns and when the actual interface is visible
  for use in the system.

  In this failure, we can see an AddPortCommand completes and then an ip
  link call is made on the tap device which fails because it does not
  exist yet:

  2016-07-20 12:18:18.555 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Running txn command(idx=0): AddPortCommand(bridge=test-brca25db6d, port=qr-10df58c6-8a, may_exist=False) do_commit neutron/agent/ovsdb/impl_idl.py:83
  2016-07-20 12:18:18.556 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Running txn command(idx=1): DbSetCommand(table=Interface, record=qr-10df58c6-8a, col_values=(('type', 'internal'), ('external_ids', {'iface-status': 'active', 'iface-id': '10df58c6-8ad8-4f89-b3d1-36cf26ee5792', 'attached-mac': 'ca:fe:de:ad:be:ef'}))) do_commit neutron/agent/ovsdb/impl_idl.py:83
  2016-07-20 12:18:18.570 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Running txn command(idx=0): DbGetCommand(table=Interface, column=ofport, record=qr-10df58c6-8a) do_commit neutron/agent/ovsdb/impl_idl.py:83
  2016-07-20 12:18:18.570 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Transaction caused no change do_commit neutron/agent/ovsdb/impl_idl.py:111
  2016-07-20 12:18:18.591 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Running txn command(idx=0): DbGetCommand(table=Interface, column=ofport, record=qr-10df58c6-8a) do_commit neutron/agent/ovsdb/impl_idl.py:83
  2016-07-20 12:18:18.592 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Transaction caused no change do_commit neutron/agent/ovsdb/impl_idl.py:111
  2016-07-20 12:18:18.634 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Running txn command(idx=0): DbGetCommand(table=Interface, column=ofport, record=qr-10df58c6-8a) do_commit neutron/agent/ovsdb/impl_idl.py:83
  2016-07-20 12:18:18.634 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Transaction caused no change do_commit neutron/agent/ovsdb/impl_idl.py:111
  2016-07-20 12:18:18.715 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Running txn command(idx=0): DbGetCommand(table=Interface, column=ofport, record=qr-10df58c6-8a) do_commit neutron/agent/ovsdb/impl_idl.py:83
  2016-07-20 12:18:18.716 28212 DEBUG neutron.agent.ovsdb.impl_idl [-] Transaction caused no change do_commit neutron/agent/ovsdb/impl_idl.py:111
  2016-07-20 12:18:18.716 28212 DEBUG neutron.agent.linux.utils [req-34784ee2-5510-47ce-af43-fe7691c9dcda - - - - -] Running command (rootwrap daemon): ['ip', 'link', 'set', 'qr-10df58c6-8a', 'address', 'ca:fe:de:ad:be:ef'] execute_rootwrap_daemon neutron/agent/linux/utils.py:99
  2016-07-20 12:18:18.724 28212 ERROR neutron.agent.linux.utils [req-34784ee2-5510-47ce-af43-fe7691c9dcda - - - - -] Exit code: 1; Stdin: ; Stdout: ; Stderr: Cannot find device "qr-10df58c6-8a"


  
  On examining the syslog, the interface shows up about 500ms later: 

  Jul 20 12:18:19 ubuntu-trusty-rax-ord-2672516 kernel: [  978.400048]
  device qr-10df58c6-8a entered promiscuous mode


  A similar effect is visible in the dhcp stale cleanup test where
  DelPortCommand is issued but then the port remains visible afterwards
  to a find via /sys/ : http://logs.openstack.org/31/344731/2/check
  /gate-neutron-dsvm-functional/98c6b55/logs/dsvm-functional-
  logs/neutron.tests.functional.agent.linux.test_dhcp.TestDhcp.test_cleanup_stale_devices.txt.gz

To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/1604816/+subscriptions
Follow ups

[Bug 1604816] Re: native ovsdb seems to return before finishing adding/removing port
From: OpenStack Infra, 2016-07-29