yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1849796] Re: port status is down after vm migration

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Slawek Kaplonski <1849796@xxxxxxxxxxxxxxxxxx>
Date: Fri, 25 Oct 2019 12:47:55 -0000
Reply-to: Bug 1849796 <1849796@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Project changed: neutron => networking-ovn

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

Title:
  port status is down after vm migration

Status in networking-ovn:
  New

Bug description:
  I'm using networking-ovn as the mechanism driver,  sometimes the port
  status of vm is down after vm migration.

  This is because the bind port is not completed when ovn reports status
  up for the port

  See the details below.

  2019-10-25 10:24:03.183 16030 INFO networking_ovn.ml2.mech_driver [req-8dce69eb-0668-4c95-81da-e3a91d484cc9 - - - - -] OVN reports status up for port: 6f60a6b4-0c6f-4529-9541-d9e523f371d2
  2019-10-25 10:24:03.187 16030 DEBUG oslo_concurrency.lockutils [req-d037496a-62cc-4132-96ba-fddd7cd4f065 - - - - -] Lock "update_segment_host_mapping" acquired by "neutron.services.segments.db.update_segment_host_mapping" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
  2019-10-25 10:24:03.192 16030 DEBUG oslo_concurrency.lockutils [req-d037496a-62cc-4132-96ba-fddd7cd4f065 - - - - -] Lock "update_segment_host_mapping" released by "neutron.services.segments.db.update_segment_host_mapping" :: held 0.006s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
  2019-10-25 10:24:03.208 16024 INFO networking_ovn.db.revision [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] Successfully bumped revision number for resource 6f60a6b4-0c6f-4529-9541-d9e523f371d2 (type: ports) to 27
  2019-10-25 10:24:03.238 16024 DEBUG neutron.plugins.ml2.managers [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] Attempting to bind port 6f60a6b4-0c6f-4529-9541-d9e523f371d2 on host node-44795-15156 for vnic_type normal with profile  bind_port /usr/lib/python2.7/site-packages/neutron/plugins/ml2/managers.py:747
  2019-10-25 10:24:03.238 16024 DEBUG neutron.plugins.ml2.managers [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] Attempting to bind port 6f60a6b4-0c6f-4529-9541-d9e523f371d2 on host node-44795-15156 at level 0 using segments [{'network_id': '722eeddf-af9a-4d92-a4c5-e2d4b83e9c54', 'segmentation_id': 29, 'physical_network': None, 'id': '3d35c69a-01ba-4182-bc23-1ace3a20bbfd', 'network_type': u'geneve'}] _bind_port_level /usr/lib/python2.7/site-packages/neutron/plugins/ml2/managers.py:768
  2019-10-25 10:24:03.239 16024 DEBUG networking_ovn.ml2.mech_driver [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] Attempting to bind port 6f60a6b4-0c6f-4529-9541-d9e523f371d2 on host node-44795-15156 for network segment with type geneve, segmentation ID 29, physical network None bind_port /usr/lib/python2.7/site-packages/networking_ovn/ml2/mech_driver.py:644
  2019-10-25 10:24:03.239 16024 DEBUG neutron.plugins.ml2.managers [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] Bound port: 6f60a6b4-0c6f-4529-9541-d9e523f371d2, host: node-44795-15156, vif_type: ovs, vif_details: {"port_filter": true}, binding_levels: [{'bound_driver': 'ovn', 'bound_segment': {'network_id': '722eeddf-af9a-4d92-a4c5-e2d4b83e9c54', 'segmentation_id': 29, 'physical_network': None, 'id': '3d35c69a-01ba-4182-bc23-1ace3a20bbfd', 'network_type': u'geneve'}}] _bind_port_level /usr/lib/python2.7/site-packages/neutron/plugins/ml2/managers.py:816
  2019-10-25 10:24:03.240 16024 DEBUG neutron_lib.callbacks.manager [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] Notify callbacks ['neutron.plugins.ml2.plugin.Ml2Plugin._ensure_default_security_group_handler--9223372036853843044'] for port, before_update _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:193
  2019-10-25 10:24:03.242 16030 DEBUG neutron.db.provisioning_blocks [req-8dce69eb-0668-4c95-81da-e3a91d484cc9 - - - - -] Provisioning for port 6f60a6b4-0c6f-4529-9541-d9e523f371d2 completed by entity L2. provisioning_complete /usr/lib/python2.7/site-packages/neutron/db/provisioning_blocks.py:132
  2019-10-25 10:24:03.248 16030 DEBUG oslo_concurrency.lockutils [req-d037496a-62cc-4132-96ba-fddd7cd4f065 - - - - -] Lock "update_segment_host_mapping" acquired by "neutron.services.segments.db.update_segment_host_mapping" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
  2019-10-25 10:24:03.251 16030 DEBUG neutron.db.provisioning_blocks [req-8dce69eb-0668-4c95-81da-e3a91d484cc9 - - - - -] Provisioning complete for port 6f60a6b4-0c6f-4529-9541-d9e523f371d2 triggered by entity L2. provisioning_complete /usr/lib/python2.7/site-packages/neutron/db/provisioning_blocks.py:138
  2019-10-25 10:24:03.251 16030 DEBUG neutron_lib.callbacks.manager [req-8dce69eb-0668-4c95-81da-e3a91d484cc9 - - - - -] Notify callbacks ['neutron.plugins.ml2.plugin.Ml2Plugin._port_provisioned--9223372036821954182'] for port, provisioning_complete _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:193
  2019-10-25 10:24:03.273 16030 DEBUG oslo_concurrency.lockutils [req-d037496a-62cc-4132-96ba-fddd7cd4f065 - - - - -] Lock "update_segment_host_mapping" released by "neutron.services.segments.db.update_segment_host_mapping" :: held 0.025s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
  2019-10-25 10:24:03.303 16024 DEBUG neutron.plugins.ml2.db [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] For port 6f60a6b4-0c6f-4529-9541-d9e523f371d2, host node-44795-15156, cleared binding levels clear_binding_levels /usr/lib/python2.7/site-packages/neutron/plugins/ml2/db.py:90
  2019-10-25 10:24:03.305 16024 DEBUG neutron.plugins.ml2.db [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] For port 6f60a6b4-0c6f-4529-9541-d9e523f371d2, host node-44795-15156, set binding levels [<neutron.plugins.ml2.driver_context.InstanceSnapshot object at 0x7f080c889d10>] set_binding_levels /usr/lib/python2.7/site-packages/neutron/plugins/ml2/db.py:61
  2019-10-25 10:24:03.307 16024 DEBUG networking_ovn.ml2.mech_driver [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] No provisioning block for port 6f60a6b4-0c6f-4529-9541-d9e523f371d2 since host unchanged _is_port_provisioning_required /usr/lib/python2.7/site-packages/networking_ovn/ml2/mech_driver.py:428
  2019-10-25 10:24:03.308 16024 DEBUG neutron_lib.callbacks.manager [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] Notify callbacks ['neutron.plugins.ml2.plugin.Ml2Plugin.notify_sg_on_port_change--9223372036853843112', 'neutron.plugins.ml2.ovo_rpc._ObjectChangeHandler.handle_event-23186942', 'networking_ovn.l3.l3_ovn._port_update--9223363307320551277', 'neutron.api.rpc.agentnotifiers.dhcp_rpc_agent_api.DhcpAgentNotifyAPI._native_event_send_dhcp_notification--9223372036831097911'] for port, after_update _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:193
  2019-10-25 10:24:03.320 16024 DEBUG oslo_concurrency.lockutils [-] Lock "event-dispatch" acquired by "neutron.plugins.ml2.ovo_rpc.dispatch_events" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
  2019-10-25 10:24:03.340 16030 DEBUG neutron.plugins.ml2.plugin [req-8dce69eb-0668-4c95-81da-e3a91d484cc9 - - - - -] Port 6f60a6b4-0c6f-4529-9541-d9e523f371d2 cannot update to ACTIVE because it is not bound. _port_provisioned /usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py:291
  2019-10-25 10:24:03.360 16030 DEBUG oslo_concurrency.lockutils [req-d037496a-62cc-4132-96ba-fddd7cd4f065 - - - - -] Lock "update_segment_host_mapping" acquired by "neutron.services.segments.db.update_segment_host_mapping" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
  2019-10-25 10:24:03.372 16030 DEBUG oslo_concurrency.lockutils [req-d037496a-62cc-4132-96ba-fddd7cd4f065 - - - - -] Lock "update_segment_host_mapping" released by "neutron.services.segments.db.update_segment_host_mapping" :: held 0.012s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
  2019-10-25 10:24:03.430 16024 DEBUG neutron.api.rpc.handlers.resources_rpc [req-631c9280-ec1a-4616-861f-5ae30b510786 - - - - -] Pushing event updated for resources: {'Port': ['ID=6f60a6b4-0c6f-4529-9541-d9e523f371d2,revision_number=28']} push /usr/lib/python2.7/site-packages/neutron/api/rpc/handlers/resources_rpc.py:241
  2019-10-25 10:24:03.434 16024 DEBUG oslo_concurrency.lockutils [req-631c9280-ec1a-4616-861f-5ae30b510786 - - - - -] Lock "event-dispatch" released by "neutron.plugins.ml2.ovo_rpc.dispatch_events" :: held 0.114s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
  2019-10-25 10:24:03.453 16024 DEBUG neutron.api.rpc.agentnotifiers.dhcp_rpc_agent_api [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] Network 722eeddf-af9a-4d92-a4c5-e2d4b83e9c54 is not hosted by any dhcp agent _notify_agents /usr/lib/python2.7/site-packages/neutron/api/rpc/agentnotifiers/dhcp_rpc_agent_api.py:218
  2019-10-25 10:24:03.493 16024 DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=0): CheckRevisionNumberCommand(if_exists=True, resource={'status': u'DOWN', 'binding:host_id': u'node-44795-15156', 'description': u'', 'allowed_address_pairs': [], 'tags': [], 'extra_dhcp_opts': [], 'updated_at': '2019-10-25T02:24:02Z', 'device_owner': u'compute:nova', 'revision_number': 27, 'port_security_enabled': False, 'network': {'provider:physical_network': None, 'ipv6_address_scope': None, 'revision_number': 4, 'port_security_enabled': True, 'provider:network_type': u'geneve', 'id': u'722eeddf-af9a-4d92-a4c5-e2d4b83e9c54', 'router:external': False, 'availability_zone_hints': [], 'availability_zones': [], 'ipv4_address_scope': None, 'shared': False, 'project_id': u'e487a13b6dfd32a2016dfd618d7401d5', 'status': u'ACTIVE', 'subnets': [u'7f5d0ee0-5912-4680-b060-9b83711a1638'], 'description': u'', 'tags': [], 'updated_at': '2019-10-24T13:37:57Z', 'provider:segmentation_id': 29, 'name': u'ss', 'admin_state_up': True, 'tenant_id': u'e487a13b6dfd32a2016dfd618d7401d5', 'created_at': '2019-10-24T10:48:12Z', 'mtu': 1442, 'vlan_transparent': None}, 'binding:profile': {}, 'fixed_ips': [{'subnet_id': u'7f5d0ee0-5912-4680-b060-9b83711a1638', 'ip_address': u'192.168.12.3'}], 'id': u'6f60a6b4-0c6f-4529-9541-d9e523f371d2', 'security_groups': [], 'device_id': u'i-00000C', 'name': u'vna72813370', 'admin_state_up': True, 'network_id': u'722eeddf-af9a-4d92-a4c5-e2d4b83e9c54', 'tenant_id': u'icsAdmin', 'binding:vif_details': {u'port_filter': True}, 'binding:vnic_type': u'normal', 'binding:vif_type': 'ovs', 'mac_address': u'00:16:3e:a3:91:9b', 'project_id': u'icsAdmin', 'created_at': '2019-10-24T10:55:25Z'}, name=6f60a6b4-0c6f-4529-9541-d9e523f371d2, resource_type=ports) do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84
  2019-10-25 10:24:03.493 16024 DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=1): SetLSwitchPortCommand(lport=6f60a6b4-0c6f-4529-9541-d9e523f371d2, if_exists=False, columns={'parent_name': [], 'addresses': [u'00:16:3e:a3:91:9b 192.168.12.3'], 'enabled': True, 'port_security': [], 'dhcpv6_options': [], 'external_ids': {'neutron:cidrs': '192.168.12.3/24', 'neutron:device_id': u'i-00000C', 'neutron:revision_number': '27', 'neutron:port_name': u'vna72813370', 'neutron:network_name': u'neutron-722eeddf-af9a-4d92-a4c5-e2d4b83e9c54', 'neutron:project_id': u'icsAdmin', 'neutron:device_owner': u'compute:nova', 'neutron:security_group_ids': ''}, 'tag': [], 'type': '', 'options': {'requested-chassis': u'node-44795-15156'}, 'dhcpv4_options': [UUID('770c3daa-3128-4a7a-9a3a-6f27b55aa0f8')]}) do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84
  2019-10-25 10:24:03.494 16024 DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=2): PgDelPortCommand(if_exists=False, lsp=[u'6f60a6b4-0c6f-4529-9541-d9e523f371d2'], port_group=neutron_pg_drop) do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84
  2019-10-25 10:24:03.502 16030 DEBUG ovsdbapp.backend.ovs_idl.event [-] ChassisEvent : Matched Chassis, ('create', 'update', 'delete'), None None matches /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/event.py:40
  2019-10-25 10:24:03.503 16030 DEBUG ovsdbapp.backend.ovs_idl.event [-] ChassisEvent : Matched Chassis, ('create', 'update', 'delete'), None None matches /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/event.py:40
  2019-10-25 10:24:03.503 16030 DEBUG ovsdbapp.backend.ovs_idl.event [-] ChassisEvent : Matched Chassis, ('create', 'update', 'delete'), None None matches /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/event.py:40
  2019-10-25 10:24:03.515 16030 DEBUG oslo_concurrency.lockutils [req-d037496a-62cc-4132-96ba-fddd7cd4f065 - - - - -] Lock "update_segment_host_mapping" acquired by "neutron.services.segments.db.update_segment_host_mapping" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
  2019-10-25 10:24:03.518 16030 DEBUG oslo_concurrency.lockutils [req-d037496a-62cc-4132-96ba-fddd7cd4f065 - - - - -] Lock "update_segment_host_mapping" released by "neutron.services.segments.db.update_segment_host_mapping" :: held 0.004s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
  2019-10-25 10:24:03.565 16030 DEBUG oslo_concurrency.lockutils [req-d037496a-62cc-4132-96ba-fddd7cd4f065 - - - - -] Lock "update_segment_host_mapping" acquired by "neutron.services.segments.db.update_segment_host_mapping" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
  2019-10-25 10:24:03.568 16030 DEBUG oslo_concurrency.lockutils [req-d037496a-62cc-4132-96ba-fddd7cd4f065 - - - - -] Lock "update_segment_host_mapping" released by "neutron.services.segments.db.update_segment_host_mapping" :: held 0.003s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
  2019-10-25 10:24:03.616 16030 DEBUG oslo_concurrency.lockutils [req-d037496a-62cc-4132-96ba-fddd7cd4f065 - - - - -] Lock "update_segment_host_mapping" acquired by "neutron.services.segments.db.update_segment_host_mapping" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
  2019-10-25 10:24:03.619 16030 DEBUG oslo_concurrency.lockutils [req-d037496a-62cc-4132-96ba-fddd7cd4f065 - - - - -] Lock "update_segment_host_mapping" released by "neutron.services.segments.db.update_segment_host_mapping" :: held 0.003s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
  2019-10-25 10:24:03.776 16024 INFO networking_ovn.db.revision [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] Successfully bumped revision number for resource 6f60a6b4-0c6f-4529-9541-d9e523f371d2 (type: ports) to 27
  2019-10-25 10:24:03.787 16024 DEBUG neutron.pecan_wsgi.hooks.policy_enforcement [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] Attributes excluded by policy engine: [u'network'] _exclude_attributes_by_policy /usr/lib/python2.7/site-packages/neutron/pecan_wsgi/hooks/policy_enforcement.py:256
  2019-10-25 10:24:03.788 16024 DEBUG neutron_lib.callbacks.manager [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] Notify callbacks ['neutron.api.rpc.agentnotifiers.dhcp_rpc_agent_api.DhcpAgentNotifyAPI._send_dhcp_notification--9223372036831097890', 'neutron.notifiers.nova.Notifier._send_nova_notification-6708'] for port, before_response _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:193
  2019-10-25 10:24:03.790 16024 INFO neutron.wsgi [req-b6ea06db-db6c-44de-b957-1d139411ecf0 - - - - -] 127.0.0.1 "PUT /v2.0/ports/6f60a6b4-0c6f-4529-9541-d9e523f371d2 HTTP/1.1" status: 200  len: 967 time: 1.2829940

To manage notifications about this bug go to:
https://bugs.launchpad.net/networking-ovn/+bug/1849796/+subscriptions
References

[Bug 1849796] [NEW] port status is down after vm migration
From: Frank Wang, 2019-10-25