yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1892870] [NEW] concurrent interface detach/attach may accidently unbind port

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Alexandre arents <1892870@xxxxxxxxxxxxxxxxxx>
Date: Tue, 25 Aug 2020 13:46:56 -0000
Reply-to: Bug 1892870 <1892870@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:


Description
===========

When we run multiple concurrent detach interface on the same instance uuid/port-id,
a lot of those requests are accepted (HTTP 202) an processed because info_cache is updated
only when first request finish, so all request after the first one will fail BUT will send
an unbind that may unbind a port that have been just legitly attached to another instance.

Ex of use case: a kube operator that move all interface from one
instance to another(rollout).

Steps to reproduce
==================

On devstack master:

INST=$(openstack server create  --flavor m1.small --image cirros-0.4.0-x86_64-disk   --nic net-id=private inst1 | awk '/ id/{print $4}')
HOST_IP=$(hostname -I | awk '{print $1}')
PORT=$(openstack port create --network private myport | awk '/ id/{print $4}')
openstack server add port $INST $PORT
TOKEN=$(openstack token issue|awk '/ id/{print $4}')

# create detach script with this content:
echo 'curl -g -i -X DELETE http://${HOST_IP}/compute/v2.1/servers/${INST}/os-interface/${PORT} -H "Accept: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: ${TOKEN}" -H "X-OpenStack-Nova-API-Version: 2.1"' > detach

# open in another terminal neutron logs filtering on PUT:
sudo journalctl -u devstack@q-svc.service  -f | grep -E PUT


# Now send plenty of detach:
for i in $(seq 1 20) ; do . detach ; sleep 0.2 ; done
HTTP/1.1 202 Accepted
...
HTTP/1.1 202 Accepted
...


In neutron logs you will see plenty of unbinding request:
 sudo journalctl -u devstack@q-svc.service  -f | grep -E PUT
Aug 25 12:15:01 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-9b454f98-a12c-49fb-8c39-e70094912029 req-914eaa3d-c139-416d-85b2-6d20e3e3c496 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1098 time: 1.1390624

                  ^^^ After the first PUT above, port is free to be
attach.. if the app attach here the port risk to be accidently unbinded
by other unbind PUT below:

Aug 25 12:15:01 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-a0f2c9ab-419c-46e4-9488-684c7e173241 req-b4d96937-27ee-4c3f-b114-f02e86979605 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1098 time: 1.2870913
Aug 25 12:15:02 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-91a3b2e6-bf4f-47b5-b05b-707ac48cb1e4 req-2a4c305e-ece6-4c4a-a7af-4c3371e12ea7 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1098 time: 1.7216117
Aug 25 12:15:02 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-e298313f-6b30-4815-ae52-4716e0df3e0f req-aed7f7f4-9dca-41a7-84b5-1e59ef6c50e9 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1098 time: 1.4968698
Aug 25 12:15:03 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-a7bc3121-13b4-484c-9f2f-c9b3fd4b225b req-424edb50-c998-4fa3-b26f-8d0d01ea474e service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 2.5676210
Aug 25 12:15:04 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-62ed888a-6f35-425e-a872-e4a5758b8a92 req-7ce9ce3e-503d-4845-8663-c1b6d02b89ca service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 3.3949170
Aug 25 12:15:05 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-4a10d91b-7431-4255-b27d-a72343d2482e req-5614949b-b1e7-4862-ad95-f06c4ba7936e service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 2.9760244
Aug 25 12:15:05 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-682d7521-af6b-4c9a-b90e-9a8ea6ed45bc req-76e2d9ec-f8a8-4882-b4d6-8ea3f1c7f818 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 4.5097113
Aug 25 12:15:06 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-ca379b27-7754-4125-8318-4e2ff7e97227 req-0e9ba555-6572-4388-a081-3b69cc92c2ec service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 5.1839015
Aug 25 12:15:06 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-f6881052-baf4-4fb7-9767-739563331058 req-7a3194ff-0fad-4917-8d34-851a850cbae2 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 4.4715307
Aug 25 12:15:07 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-1e7106c5-6dfa-4d36-a889-35198479add8 req-6c513399-c0f5-4d0b-9315-e2e30f1e6370 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 5.4051881
Aug 25 12:15:10 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-909107a5-f03a-4ac4-8312-dcef83210908 req-38a6ef2b-b9f1-44cf-a823-ca67159115a4 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 8.5914369

if an attach pass, and is accidently unbind as previously explain,
apps can detect port is free and try to reattach an interface that is already
attached in libvirt and you GOT HTTP 500 with those error message on compute node:
oslo_db.exception.DBDuplicateEntry: (pymysql.err.IntegrityError) (1062, "Duplicate entry 'fa:16:3e:d5:26:e1/0466658a-02ef-46da-a4ac-9a335c6d3352-0' for key 'uniq_virtual_interfaces0address
0deleted'").


Expected result
===============
Only one unbind should be sent.


Actual result
=============
Multiple unbind are sent and one of them can break a port just attached

** Affects: nova
     Importance: Undecided
         Status: New


** Tags: api race-condition

** Summary changed:

- concurent  interface detach/attach may accidently unbind port
+ concurrent  interface detach/attach may accidently unbind port

** Tags added: api race-condition

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1892870

Title:
  concurrent  interface detach/attach may accidently unbind port

Status in OpenStack Compute (nova):
  New

Bug description:
  
  Description
  ===========

  When we run multiple concurrent detach interface on the same instance uuid/port-id,
  a lot of those requests are accepted (HTTP 202) an processed because info_cache is updated
  only when first request finish, so all request after the first one will fail BUT will send
  an unbind that may unbind a port that have been just legitly attached to another instance.

  Ex of use case: a kube operator that move all interface from one
  instance to another(rollout).

  Steps to reproduce
  ==================

  On devstack master:

  INST=$(openstack server create  --flavor m1.small --image cirros-0.4.0-x86_64-disk   --nic net-id=private inst1 | awk '/ id/{print $4}')
  HOST_IP=$(hostname -I | awk '{print $1}')
  PORT=$(openstack port create --network private myport | awk '/ id/{print $4}')
  openstack server add port $INST $PORT
  TOKEN=$(openstack token issue|awk '/ id/{print $4}')

  # create detach script with this content:
  echo 'curl -g -i -X DELETE http://${HOST_IP}/compute/v2.1/servers/${INST}/os-interface/${PORT} -H "Accept: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: ${TOKEN}" -H "X-OpenStack-Nova-API-Version: 2.1"' > detach

  # open in another terminal neutron logs filtering on PUT:
  sudo journalctl -u devstack@q-svc.service  -f | grep -E PUT

  
  # Now send plenty of detach:
  for i in $(seq 1 20) ; do . detach ; sleep 0.2 ; done
  HTTP/1.1 202 Accepted
  ...
  HTTP/1.1 202 Accepted
  ...

  
  In neutron logs you will see plenty of unbinding request:
   sudo journalctl -u devstack@q-svc.service  -f | grep -E PUT
  Aug 25 12:15:01 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-9b454f98-a12c-49fb-8c39-e70094912029 req-914eaa3d-c139-416d-85b2-6d20e3e3c496 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1098 time: 1.1390624

                    ^^^ After the first PUT above, port is free to be
  attach.. if the app attach here the port risk to be accidently
  unbinded by other unbind PUT below:

  Aug 25 12:15:01 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-a0f2c9ab-419c-46e4-9488-684c7e173241 req-b4d96937-27ee-4c3f-b114-f02e86979605 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1098 time: 1.2870913
  Aug 25 12:15:02 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-91a3b2e6-bf4f-47b5-b05b-707ac48cb1e4 req-2a4c305e-ece6-4c4a-a7af-4c3371e12ea7 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1098 time: 1.7216117
  Aug 25 12:15:02 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-e298313f-6b30-4815-ae52-4716e0df3e0f req-aed7f7f4-9dca-41a7-84b5-1e59ef6c50e9 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1098 time: 1.4968698
  Aug 25 12:15:03 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-a7bc3121-13b4-484c-9f2f-c9b3fd4b225b req-424edb50-c998-4fa3-b26f-8d0d01ea474e service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 2.5676210
  Aug 25 12:15:04 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-62ed888a-6f35-425e-a872-e4a5758b8a92 req-7ce9ce3e-503d-4845-8663-c1b6d02b89ca service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 3.3949170
  Aug 25 12:15:05 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-4a10d91b-7431-4255-b27d-a72343d2482e req-5614949b-b1e7-4862-ad95-f06c4ba7936e service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 2.9760244
  Aug 25 12:15:05 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-682d7521-af6b-4c9a-b90e-9a8ea6ed45bc req-76e2d9ec-f8a8-4882-b4d6-8ea3f1c7f818 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 4.5097113
  Aug 25 12:15:06 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-ca379b27-7754-4125-8318-4e2ff7e97227 req-0e9ba555-6572-4388-a081-3b69cc92c2ec service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 5.1839015
  Aug 25 12:15:06 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-f6881052-baf4-4fb7-9767-739563331058 req-7a3194ff-0fad-4917-8d34-851a850cbae2 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 4.4715307
  Aug 25 12:15:07 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-1e7106c5-6dfa-4d36-a889-35198479add8 req-6c513399-c0f5-4d0b-9315-e2e30f1e6370 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 5.4051881
  Aug 25 12:15:10 alex-devstack neutron-server[1051]: INFO neutron.wsgi [req-909107a5-f03a-4ac4-8312-dcef83210908 req-38a6ef2b-b9f1-44cf-a823-ca67159115a4 service neutron] 54.39.183.136 "PUT /v2.0/ports/0466658a-02ef-46da-a4ac-9a335c6d3352 HTTP/1.1" status: 200  len: 1099 time: 8.5914369

  if an attach pass, and is accidently unbind as previously explain,
  apps can detect port is free and try to reattach an interface that is already
  attached in libvirt and you GOT HTTP 500 with those error message on compute node:
  oslo_db.exception.DBDuplicateEntry: (pymysql.err.IntegrityError) (1062, "Duplicate entry 'fa:16:3e:d5:26:e1/0466658a-02ef-46da-a4ac-9a335c6d3352-0' for key 'uniq_virtual_interfaces0address
  0deleted'").

  
  Expected result
  ===============
  Only one unbind should be sent.

  
  Actual result
  =============
  Multiple unbind are sent and one of them can break a port just attached

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

[Bug 1892870] Re: concurrent interface detach/attach may accidently unbind port
From: Elod Illes, 2020-11-24
[Bug 1892870] Re: concurrent interface detach/attach may accidently unbind port
From: OpenStack Infra, 2020-08-30