yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1251422] Re: deleting security-group fails when neutron and nvp are out of sync

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Alan Pevec <1251422@xxxxxxxxxxxxxxxxxx>
Date: Mon, 22 Sep 2014 22:29:29 -0000
Reply-to: Bug 1251422 <1251422@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Changed in: neutron/havana
       Status: Fix Committed => Fix Released

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

Title:
  deleting security-group fails when neutron and nvp are out of sync

Status in OpenStack Neutron (virtual network service):
  Fix Released
Status in neutron havana series:
  Fix Released
Status in The OpenStack VMwareAPI subTeam:
  New

Bug description:
  %neutron security-group-list
  +--------------------------------------+-----------------------------+--------------------------------+
  | id                                   | name                        | description                    |
  +--------------------------------------+-----------------------------+--------------------------------+
  | 0163fc21-e0d2-4219-9efc-47c71e102ba8 | default                     | default                        |
  | 1023c62b-029f-4faf-9257-97ffc870fffd | default                     | default                        |
  | 7c096113-2e5d-4fc3-b3ba-8462ec5e6964 | default                     | default                        |
  | b9fc7dc0-c22b-45ee-a811-d2a11b7e864f | security-tempest-1342522857 | description-tempest-1430856972 |
  | dfc6bff9-b412-4f47-b38b-6d0079412a4d | default                     | default                        |
  +--------------------------------------+-----------------------------
  %neutron security-group-delete b9fc7dc0-c22b-45ee-a811-d2a11b7e864f
  500-{u'NeutronError': {u'message': u'An unknown exception occurred.', u'type': u'NeutronException', u'detail': u''}}

  
  neutron:/var/log/neutron.log
  2013-11-14 05:08:05,037 (neutron.plugins.nicira.api_client.request): DEBUG request _issue_request [6997] Completed request 'POST https://x.x.x.x:443//ws.v1/security-profile': 201 (0.06 seconds)
  2013-11-14 05:08:05,037 (neutron.plugins.nicira.api_client.request): DEBUG request _issue_request Reading X-Nvp-config-Generation response header: '37774691'
  2013-11-14 05:08:05,038 (neutron.plugins.nicira.api_client.client): DEBUG client release_connection [6997] Released connection https://x.x.x.x:443. 9 connection(s) available.
  2013-11-14 05:08:05,038 (neutron.plugins.nicira.api_client.request_eventlet): DEBUG request_eventlet _handle_request [6997] Completed request 'POST /ws.v1/security-profile': 201
  2013-11-14 05:08:05,039 (neutron.plugins.nicira.nvplib): DEBUG nvplib create_security_profile Created Security Profile: {u'display_name': u'security-tempest-1342522857', u'_href': u'/ws.v1/security-profile/b9fc7dc0-c22b-45ee-a811-d2a11b7e864f', u'tags': [{u'scope': u'quan
  tum', u'tag': u'2014.1.a230.g5c9c9b9'}, {u'scope': u'os_tid', u'tag': u'csi-tenant-tempest'}], u'logical_port_egress_rules': [{u'ethertype': u'IPv4', u'port_range_max': 68, u'port_range_min': 68, u'protocol': 17}], u'_schema': u'/ws.v1/schema/SecurityProfileConfig', u'log
  ical_port_ingress_rules': [{u'ethertype': u'IPv4'}, {u'ethertype': u'IPv6'}], u'uuid': u'b9fc7dc0-c22b-45ee-a811-d2a11b7e864f'}
  2013-11-14 05:08:05,063 (neutron.openstack.common.rpc.amqp): DEBUG amqp notify Sending security_group.create.end on notifications.info
  2013-11-14 05:08:05,063 (neutron.openstack.common.rpc.amqp): DEBUG amqp _add_unique_id UNIQUE_ID is 3221f6dd937e4657993532db6910d7fc.
  2013-11-14 05:08:05,069 (amqp): DEBUG channel _do_close Closed channel #1
  2013-11-14 05:08:05,070 (amqp): DEBUG channel __init__ using channel_id: 1
  2013-11-14 05:08:05,071 (amqp): DEBUG channel _open_ok Channel open
  2013-11-14 05:08:05,072 (neutron.wsgi): INFO log write x.x.x.x,x.x.x.x - - [14/Nov/2013 05:08:05] "POST /v2.0/security-groups.json HTTP/1.1" 201 954 0.180143

  2013-11-14 05:08:05,280 (keystoneclient.middleware.auth_token): DEBUG auth_token __call__ Authenticating user token
  2013-11-14 05:08:05,280 (keystoneclient.middleware.auth_token): DEBUG auth_token _remove_auth_headers Removing headers from request environment: X-Identity-Status,X-Domain-Id,X-Domain-Name,X-Project-Id,X-Project-Name,X-Project-Domain-Id,X-Project-Domain-Name,X-User-Id,X-User-Name,X-User-Domain-Id,X-User-Domain-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant-Id,X-Tenant-Name,X-Tenant,X-Role
  2013-11-14 05:08:05,283 (iso8601.iso8601): DEBUG iso8601 parse_date Parsed 2013-11-15T05:08:04.000000Z into {'tz_sign': None, 'second_fraction': u'000000', 'hour': u'05', 'tz_hour': None, 'month': u'11', 'timezone': u'Z', 'second': u'04', 'tz_minute': None, 'year': u'2013', 'separator': u'T', 'day': u'15', 'minute': u'08'} with default timezone <iso8601.iso8601.Utc object at 0x1798c50>
  2013-11-14 05:08:05,284 (iso8601.iso8601): DEBUG iso8601 to_int Got u'2013' for 'year' with default None
  2013-11-14 05:08:05,284 (iso8601.iso8601): DEBUG iso8601 to_int Got u'11' for 'month' with default None
  2013-11-14 05:08:05,284 (iso8601.iso8601): DEBUG iso8601 to_int Got u'15' for 'day' with default None
  2013-11-14 05:08:05,284 (iso8601.iso8601): DEBUG iso8601 to_int Got u'05' for 'hour' with default None
  2013-11-14 05:08:05,284 (iso8601.iso8601): DEBUG iso8601 to_int Got u'08' for 'minute' with default None
  2013-11-14 05:08:05,285 (iso8601.iso8601): DEBUG iso8601 to_int Got u'04' for 'second' with default None
  2013-11-14 05:08:05,285 (keystoneclient.middleware.auth_token): DEBUG auth_token _cache_get Returning cached token 2df68c733e72f70e2b09ac49a953f98d
  2013-11-14 05:08:05,285 (keystoneclient.middleware.auth_token): DEBUG auth_token _build_user_headers Received request from user: tempest with project_id : csi-tenant-tempest and roles: csi-tenant-tempest 
  2013-11-14 05:08:05,287 (routes.middleware): DEBUG middleware __call__ Matched GET /security-groups/b9fc7dc0-c22b-45ee-a811-d2a11b7e864f.json
  2013-11-14 05:08:05,287 (routes.middleware): DEBUG middleware __call__ Route path: '/security-groups/:(id).:(format)', defaults: {'action': u'show', 'controller': <wsgify at 41021840 wrapping <function resource at 0x270ae60>>}
  2013-11-14 05:08:05,288 (routes.middleware): DEBUG middleware __call__ Match dict: {'action': u'show', 'controller': <wsgify at 41021840 wrapping <function resource at 0x270ae60>>, 'id': u'b9fc7dc0-c22b-45ee-a811-d2a11b7e864f', 'format': u'json'}
  2013-11-14 05:08:05,303 (neutron.wsgi): INFO log write x.x.x.x,x.x.x.x - - [14/Nov/2013 05:08:05] "GET /v2.0/security-groups/b9fc7dc0-c22b-45ee-a811-d2a11b7e864f.json HTTP/1.1" 200 949 0.023315

  2013-11-14 05:08:05,308 (keystoneclient.middleware.auth_token): DEBUG auth_token __call__ Authenticating user token
  2013-11-14 05:08:05,308 (keystoneclient.middleware.auth_token): DEBUG auth_token _remove_auth_headers Removing headers from request environment: X-Identity-Status,X-Domain-Id,X-Domain-Name,X-Project-Id,X-Project-Name,X-Project-Domain-Id,X-Project-Domain-Name,X-User-Id,X-User-Name,X-User-Domain-Id,X-User-Domain-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant-Id,X-Tenant-Name,X-Tenant,X-Role
  2013-11-14 05:08:05,311 (iso8601.iso8601): DEBUG iso8601 parse_date Parsed 2013-11-15T05:08:04.000000Z into {'tz_sign': None, 'second_fraction': u'000000', 'hour': u'05', 'tz_hour': None, 'month': u'11', 'timezone': u'Z', 'second': u'04', 'tz_minute': None, 'year': u'2013', 'separator': u'T', 'day': u'15', 'minute': u'08'} with default timezone <iso8601.iso8601.Utc object at 0x1798c50>
  2013-11-14 05:08:05,311 (iso8601.iso8601): DEBUG iso8601 to_int Got u'2013' for 'year' with default None
  2013-11-14 05:08:05,311 (iso8601.iso8601): DEBUG iso8601 to_int Got u'11' for 'month' with default None
  2013-11-14 05:08:05,311 (iso8601.iso8601): DEBUG iso8601 to_int Got u'15' for 'day' with default None
  2013-11-14 05:08:05,312 (iso8601.iso8601): DEBUG iso8601 to_int Got u'05' for 'hour' with default None
  2013-11-14 05:08:05,312 (iso8601.iso8601): DEBUG iso8601 to_int Got u'08' for 'minute' with default None
  2013-11-14 05:08:05,312 (iso8601.iso8601): DEBUG iso8601 to_int Got u'04' for 'second' with default None
  2013-11-14 05:08:05,312 (keystoneclient.middleware.auth_token): DEBUG auth_token _cache_get Returning cached token 2df68c733e72f70e2b09ac49a953f98d
  2013-11-14 05:08:05,312 (keystoneclient.middleware.auth_token): DEBUG auth_token _build_user_headers Received request from user: tempest with project_id : csi-tenant-tempest and roles: csi-tenant-tempest 
  2013-11-14 05:08:05,314 (routes.middleware): DEBUG middleware __call__ Matched POST /security-group-rules.json
  2013-11-14 05:08:05,314 (routes.middleware): DEBUG middleware __call__ Route path: '/security-group-rules.:(format)', defaults: {'action': u'create', 'controller': <wsgify at 41022736 wrapping <function resource at 0x270aed8>>}
  2013-11-14 05:08:05,315 (routes.middleware): DEBUG middleware __call__ Match dict: {'action': u'create', 'controller': <wsgify at 41022736 wrapping <function resource at 0x270aed8>>, 'format': u'json'}
  2013-11-14 05:08:05,316 (neutron.openstack.common.rpc.amqp): DEBUG amqp notify Sending security_group_rule.create.start on notifications.info
  2013-11-14 05:08:05,317 (neutron.openstack.common.rpc.amqp): DEBUG amqp _add_unique_id UNIQUE_ID is 66fa31f3dc8d4f2eb9cd7fb561a17f49.

  2013-11-14 05:08:05,324 (amqp): DEBUG channel __init__ using channel_id: 1
  2013-11-14 05:08:05,325 (amqp): DEBUG channel _open_ok Channel open
  2013-11-14 05:08:05,383 (keystoneclient.middleware.auth_token): DEBUG auth_token __call__ Authenticating user token
  2013-11-14 05:08:05,383 (keystoneclient.middleware.auth_token): DEBUG auth_token _remove_auth_headers Removing headers from request environment: X-Identity-Status,X-Domain-Id,X-Domain-Name,X-Project-Id,X-Project-Name,X-Project-Domain-Id,X-Project-Domain-Name,X-User-Id,X-User-Name,X-User-Domain-Id,X-User-Domain-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant-Id,X-Tenant-Name,X-Tenant,X-Role
  2013-11-14 05:08:05,394 (neutron.plugins.nicira.api_client.client): DEBUG client acquire_connection [6998] Acquired connection https://x.x.x.x:443. 8 connection(s) available.
  2013-11-14 05:08:05,394 (neutron.plugins.nicira.api_client.request): DEBUG request _issue_request [6998] Issuing - request PUT https://x.x.x.x:443//ws.v1/security-profile/b9fc7dc0-c22b-45ee-a811-d2a11b7e864f
  2013-11-14 05:08:05,394 (neutron.plugins.nicira.api_client.request): DEBUG request _issue_request Setting X-Nvp-Wait-For-Config-Generation request header: '37774691'
  2013-11-14 05:08:05,400 (iso8601.iso8601): DEBUG iso8601 parse_date Parsed 2013-11-15T05:08:05Z into {'tz_sign': None, 'second_fraction': None, 'hour': u'05', 'tz_hour': None, 'month': u'11', 'timezone': u'Z', 'second': u'05', 'tz_minute': None, 'year': u'2013', 'separator': u'T', 'day': u'15', 'minute': u'08'} with default timezone <iso8601.iso8601.Utc object at 0x1798c50>
  2013-11-14 05:08:05,400 (iso8601.iso8601): DEBUG iso8601 to_int Got u'2013' for 'year' with default None
  2013-11-14 05:08:05,400 (iso8601.iso8601): DEBUG iso8601 to_int Got u'11' for 'month' with default None
  2013-11-14 05:08:05,401 (iso8601.iso8601): DEBUG iso8601 to_int Got u'15' for 'day' with default None
  2013-11-14 05:08:05,401 (iso8601.iso8601): DEBUG iso8601 to_int Got u'05' for 'hour' with default None
  2013-11-14 05:08:05,401 (iso8601.iso8601): DEBUG iso8601 to_int Got u'08' for 'minute' with default None
  2013-11-14 05:08:05,401 (iso8601.iso8601): DEBUG iso8601 to_int Got u'05' for 'second' with default None
  2013-11-14 05:08:05,401 (keystoneclient.middleware.auth_token): DEBUG auth_token _cache_put Storing 81224fd97e0fca9805338cbbb08a3900 token in memcache
  2013-11-14 05:08:05,402 (keystoneclient.middleware.auth_token): DEBUG auth_token _build_user_headers Received request from user: service-user with project_id : csi-tenant-admin and roles: csi-tenant-admin,csi-role-admin 
  2013-11-14 05:08:05,404 (routes.middleware): DEBUG middleware __call__ No route matched for GET /ports.json
  2013-11-14 05:08:05,405 (routes.middleware): DEBUG middleware __call__ Matched GET /ports.json
  2013-11-14 05:08:05,405 (routes.middleware): DEBUG middleware __call__ Route path: '/ports{.format}', defaults: {'action': u'index', 'controller': <wsgify at 40952784 wrapping <function resource at 0x270ad70>>}
  2013-11-14 05:08:05,405 (routes.middleware): DEBUG middleware __call__ Match dict: {'action': u'index', 'controller': <wsgify at 40952784 wrapping <function resource at 0x270ad70>>, 'format': u'json'}
  2013-11-14 05:08:05,423 (neutron.wsgi): INFO log write 10.140.129.30,x.x.x.x - - [14/Nov/2013 05:08:05] "GET /v2.0/ports.json?network_id=07490058-67bd-4038-9ae2-bcc7aa973b02&device_owner=network%3Adhcp HTTP/1.1" 200 136 0.039706

  2013-11-14 05:08:05,456 (neutron.plugins.nicira.api_client.request): DEBUG request _issue_request [6998] Completed request 'PUT https://x.x.x.x:443//ws.v1/security-profile/b9fc7dc0-c22b-45ee-a811-d2a11b7e864f': 200 (0.06 seconds)
  2013-11-14 05:08:05,456 (neutron.plugins.nicira.api_client.request): DEBUG request _issue_request Reading X-Nvp-config-Generation response header: '37774694'
  2013-11-14 05:08:05,457 (neutron.plugins.nicira.api_client.client): DEBUG client release_connection [6998] Released connection https://x.x.x.x:443. 9 connection(s) available.
  2013-11-14 05:08:05,457 (neutron.plugins.nicira.api_client.request_eventlet): DEBUG request_eventlet _handle_request [6998] Completed request 'PUT /ws.v1/security-profile/b9fc7dc0-c22b-45ee-a811-d2a11b7e864f': 200
  2013-11-14 05:08:05,458 (neutron.plugins.nicira.nvplib): DEBUG nvplib update_security_group_rules Updated Security Profile: {u'display_name': u'security-tempest-1342522857', u'_href': u'/ws.v1/security-profile/b9fc7dc0-c22b-45ee-a811-d2a11b7e864f', u'tags': [{u'scope': u'quantum', u'tag': u'2014.1.a230.g5c9c9b9'}, {u'scope': u'os_tid', u'tag': u'csi-tenant-tempest'}], u'logical_port_egress_rules': [{u'ethertype': u'IPv4', u'port_range_max': 22, u'port_range_min': 22, u'protocol': 6}, {u'ethertype': u'IPv4', u'port_range_max': 68, u'port_range_min': 68, u'protocol': 17}], u'_schema': u'/ws.v1/schema/SecurityProfileConfig', u'logical_port_ingress_rules': [{u'ethertype': u'IPv4'}, {u'ethertype': u'IPv6'}], u'uuid': u'b9fc7dc0-c22b-45ee-a811-d2a11b7e864f'}
  2013-11-14 05:08:05,490 (neutron.openstack.common.rpc.amqp): DEBUG amqp notify Sending security_group_rule.create.end on notifications.info
  2013-11-14 05:08:05,490 (neutron.openstack.common.rpc.amqp): DEBUG amqp _add_unique_id UNIQUE_ID is d7b3139142a04511867d57090f7e22cf.
  2013-11-14 05:08:05,497 (amqp): DEBUG channel _do_close Closed channel #1

  2013-11-14 05:08:11,993 (routes.middleware): DEBUG middleware __call__ Matched GET /security-groups/b9fc7dc0-c22b-45ee-a811-d2a11b7e864f.json
  2013-11-14 05:08:11,993 (routes.middleware): DEBUG middleware __call__ Route path: '/security-groups/:(id).:(format)', defaults: {'action': u'show', 'controller': <wsgify at 41021840 wrapping <function resource at 0x270ae60>>}
  2013-11-14 05:08:11,993 (routes.middleware): DEBUG middleware __call__ Match dict: {'action': u'show', 'controller': <wsgify at 41021840 wrapping <function resource at 0x270ae60>>, 'id': u'b9fc7dc0-c22b-45ee-a811-d2a11b7e864f', 'format': u'json'}
  2013-11-14 05:08:12,001 (neutron.api.v2.resource): ERROR resource resource show failed
  Traceback (most recent call last):
    File "/usr/local/csi/share/csi-neutron.venv/lib/python2.6/site-packages/neutron/api/v2/resource.py", line 84, in resource
      result = method(request=request, **args)
    File "/usr/local/csi/share/csi-neutron.venv/lib/python2.6/site-packages/neutron/api/v2/base.py", line 290, in show
      parent_id=parent_id),
    File "/usr/local/csi/share/csi-neutron.venv/lib/python2.6/site-packages/neutron/api/v2/base.py", line 258, in _item
      obj = obj_getter(request.context, id, **kwargs)
    File "/usr/local/csi/share/csi-neutron.venv/lib/python2.6/site-packages/neutron/db/securitygroups_db.py", line 180, in get_security_group
      context, id), fields)
    File "/usr/local/csi/share/csi-neutron.venv/lib/python2.6/site-packages/neutron/db/securitygroups_db.py", line 194, in _get_security_group
      raise ext_sg.SecurityGroupNotFound(id=id)
  SecurityGroupNotFound: Security group b9fc7dc0-c22b-45ee-a811-d2a11b7e864f does not exist
  2013-11-14 05:08:12,002 (neutron.wsgi): INFO log write x.x.x.x,x.x.x.x - - [14/Nov/2013 05:08:12] "GET /v2.0/security-groups/b9fc7dc0-c22b-45ee-a811-d2a11b7e864f.json HTTP/1.1" 404 277 0.032987

  * Delete
  2013-11-14 18:50:04,498 (neutron.plugins.nicira.api_client.request_eventlet): DEBUG request_eventlet _handle_request [8422] Completed request 'DELETE /ws.v1/security-profile/b9fc7dc0-c22b-45ee-a811-d2a11b7e864f': 404
  2013-11-14 18:50:04,498 (NVPApiHelper): ERROR NvpApiClient request Received error code: 404
  2013-11-14 18:50:04,498 (NVPApiHelper): ERROR NvpApiClient request Server Error Message: Security Profile 'b9fc7dc0-c22b-45ee-a811-d2a11b7e864f' not registered.
  2013-11-14 18:50:04,498 (neutron.plugins.nicira.nvplib): ERROR nvplib delete_security_profile Error. Unknown exception: An unknown exception occurred.. locals=[{'path': u'/ws.v1/security-profile/b9fc7dc0-c22b-45ee-a811-d2a11b7e864f', 'e': NotFound(u'An unknown exception occurred.',), 'spid': u'b9fc7dc0-c22b-45ee-a811-d2a11b7e864f', 'cluster': <neutron.plugins.nicira.nvp_cluster.NVPCluster object at 0x2d96f10>}]
  2013-11-14 18:50:04,499 (neutron.api.v2.resource): ERROR resource resource delete failed
  Traceback (most recent call last):
    File "/usr/local/csi/share/csi-neutron.venv/lib/python2.6/site-packages/neutron/api/v2/resource.py", line 84, in resource
      result = method(request=request, **args)
    File "/usr/local/csi/share/csi-neutron.venv/lib/python2.6/site-packages/neutron/api/v2/base.py", line 432, in delete
      obj_deleter(request.context, id, **kwargs)   
      security_group['id'])
    File "/usr/local/csi/share/csi-neutron.venv/lib/python2.6/site-packages/neutron/plugins/nicira/nvplib.py", line 1148, in delete_security_profile
      raise exception.NeutronException()
  NeutronException: An unknown exception occurred.
  2013-11-14 18:50:04,500 (neutron.wsgi): INFO log write x.x.x.x,x.x.x.x - - [14/Nov/2013 18:50:04] "DELETE /v2.0/security-groups/b9fc7dc0-c22b-45ee-a811-d2a11b7e864f.json HTTP/1.1" 500 248 0.071508

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