Bug #1738337 “[neutron-db] neutron-server report error “UPDATE s...” : Bugs : neutron

Zachary Ma (mazengxie) on 2017-12-15

tags:

added: db

Revision history for this message

Zachary Ma (mazengxie) wrote on 2017-12-15:

#1

[root@10e131e73e121 ~]# grep -rin "standardattribute" /var/log/neutron/server.log
83922:2017-12-15 10:07:05.128 65701 DEBUG neutron.db.api [req-fe4da6c8-763f-41fa-9dac-537863c11740 - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:128
84013:2017-12-15 10:07:05.325 65703 DEBUG neutron.db.api [req-2632a1a7-f65e-45d9-be7b-ab4ce3c7372b - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:128

description:

updated

Revision history for this message

Slawek Kaplonski (slaweq) wrote on 2017-12-15:

#2

Can You provide some more details about:
* what You was doing when it happend?
* what version of OpenStack You are using?
* what Neutron configuration do You have?

Revision history for this message

Zachary Ma (mazengxie) wrote on 2017-12-19:

#3

@Slawek Kaplonski (slaweq)

1.I don't know how to recur problem. I just create vm and attach network.

2.pike

3.use ml2/ovs, no special configuration

Revision history for this message

Lujin Luo (luo-lujin) wrote on 2017-12-19:

#4

Did you see anything fail?, i.e. can you still attach a network to the created VM and do ping?

I had some experience working with standardattributes. It looks probably that you had some race conditions, say when one thread updated the resource in the middle of another thread trying to do other update to this resource. Then the second one fails because the revision_number does not match, because we use compare-and-swap mechanism.

Revision history for this message

Lujin Luo (luo-lujin) wrote on 2017-12-19:

#5

Also, when I asked if you see anything actually failed, I am asking failures like being unable to create network.

Revision history for this message

Zachary Ma (mazengxie) wrote on 2017-12-19:

#6

@Lujin Luo yes, I can still create network. Because @_retry_db_errors will try 10 times at most.
But I will occur the "doesn't match" log several days， and I wanna know you how to solve it?

Revision history for this message

Lujin Luo (luo-lujin) wrote on 2017-12-19:

#7

We still need to know after executing which commands, you started to see such error logs. Without knowing that, there is no way we can tell for sure. As I said, it may be a potential bug, or it may be what's expected as this is how we avoid race conditions.

Revision history for this message

Zachary Ma (mazengxie) wrote on 2017-12-19:

#8

Then the second one fails because the revision_number does not match, because we use compare-and-swap mechanism.

sorry, I do not understand why the revision_number does not match ? I saw the "standardattributes" from neutron db.

Revision history for this message

Zachary Ma (mazengxie) wrote on 2017-12-19:

#9

Download full text (25.5 KiB)

[root@10e131e73e121 ~]# grep -rin "standardattri" /var/log/neutron/server.log
87580:2017-12-19 10:08:57.725 33834 DEBUG neutron.db.api [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:128
165658:2017-12-19 15:52:53.345 33832 DEBUG neutron.db.api [req-4846cd7b-94f2-4334-9324-df87a390d862 - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattrbutes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:128

the req:
req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3

[root@10e131e73e121 ~]# grep -rin "req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3" /var/log/neutron/server.log
87202:2017-12-19 10:08:56.189 33834 DEBUG neutron.db.l3_hamode_db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] neutron.services.l3_router.l3_router_plugin.L3RouterPlugin method get_ha_sync_data_for_host called with arguments (<neutron_lib.context.Context object at 0x8cb7590>, u'10e131e73e28', <neutron.db.models.agent.Agent[object at 77417d0] {id=u'66cb0a91-18c4-49bf-99ee-50f0787fb023', agent_type=u'L3 agent', binary=u'neutron-l3-agent', topic=u'l3_agent', host=u'10e131e73e28', availability_zone=u'nova', admin_state_up=True, created_at=datetime.datetime(2017, 11, 3, 7, 45, 27), started_at=datetime.datetime(2017, 12, 17, 12, 30, 9), heartbeat_timestamp=datetime.datetime(2017, 12, 19, 2, 8, 43), description=None, configurations=u'{"agent_mode": "dvr", "gateway_external_network_id": "", "handle_internal_only_routers": true, "routers": 11, "interfaces": 17, "floating_ips": 3, "interface_driver": "openvswitch", "log_agent_heartbeats": false, "external_network_bridge": "", "ex_gw_ports": 11}', resource_versions=None, load=0}>) {'active': True, 'router_ids': [u'7513735a-67d0-42e5-9cfd-edbbcccec0e9']} wrapper /usr/lib/python2.7/site-packages/oslo_log/helpers.py:66
87203:2017-12-19 10:08:56.189 33834 DEBUG neutron.db.l3_dvr_db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] neutron.services.l3_router.l3_router_plugin.L3RouterPlugin method _get_dvr_sync_data called with arguments (<neutron_lib.context.Context object at 0x8cb7590>, u'10e131e73e28', <neutron.db.models.agent.Agent[object at 77417d0] {id=u'66cb0a91-18c4-49bf-99ee-50f0787fb023', agent_type=u'L3 agent', binary=u'neutron-l3-agent', topic=u'l3_agent', host=u'10e131e73e28', availability_zone=u'nova', admin_state_up=True, created_at=datetime.datetime(2017, 11, 3, 7, 45, 27), started_at=datetime.datetime(2017, 12, 17, 12, 30, 9), heartbeat_timestamp=datetime.datetime(2017, 12, 19, 2, 8, 43), description=None, configurations=u'{"agent_mode": "dvr", "gateway_external_network_id": "", "handle_internal_only_routers": true, "routers": 11, "interfaces": 17, "floating_ips": 3, "interface_driver": "openvswitch", "log_agent_heartbeats": false, "external_network_bridge": "", "ex_gw_ports": 11}', resource_versions=None, load=0}>, [u'7513735a-67d0-42e5-9cfd-edbbcccec0e9'], True) {} wrapper /usr/lib/python2.7/site-packages/oslo_log/helpers.py:66
87205:2017-12-19 10:08:...

[root@10e131e73e121 ~]# grep -rin "standardattri" /var/log/neutron/server.log 
87580:2017-12-19 10:08:57.725 33834 DEBUG neutron.db.api [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:128
165658:2017-12-19 15:52:53.345 33832 DEBUG neutron.db.api [req-4846cd7b-94f2-4334-9324-df87a390d862 - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattrbutes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:128

the req:
req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3

[root@10e131e73e121 ~]# grep -rin "req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3" /var/log/neutron/server.log
87202:2017-12-19 10:08:56.189 33834 DEBUG neutron.db.l3_hamode_db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] neutron.services.l3_router.l3_router_plugin.L3RouterPlugin method get_ha_sync_data_for_host called with arguments (<neutron_lib.context.Context object at 0x8cb7590>, u'10e131e73e28', <neutron.db.models.agent.Agent[object at 77417d0] {id=u'66cb0a91-18c4-49bf-99ee-50f0787fb023', agent_type=u'L3 agent', binary=u'neutron-l3-agent', topic=u'l3_agent', host=u'10e131e73e28', availability_zone=u'nova', admin_state_up=True, created_at=datetime.datetime(2017, 11, 3, 7, 45, 27), started_at=datetime.datetime(2017, 12, 17, 12, 30, 9), heartbeat_timestamp=datetime.datetime(2017, 12, 19, 2, 8, 43), description=None, configurations=u'{"agent_mode": "dvr", "gateway_external_network_id": "", "handle_internal_only_routers": true, "routers": 11, "interfaces": 17, "floating_ips": 3, "interface_driver": "openvswitch", "log_agent_heartbeats": false, "external_network_bridge": "", "ex_gw_ports": 11}', resource_versions=None, load=0}>) {'active': True, 'router_ids': [u'7513735a-67d0-42e5-9cfd-edbbcccec0e9']} wrapper /usr/lib/python2.7/site-packages/oslo_log/helpers.py:66
87203:2017-12-19 10:08:56.189 33834 DEBUG neutron.db.l3_dvr_db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] neutron.services.l3_router.l3_router_plugin.L3RouterPlugin method _get_dvr_sync_data called with arguments (<neutron_lib.context.Context object at 0x8cb7590>, u'10e131e73e28', <neutron.db.models.agent.Agent[object at 77417d0] {id=u'66cb0a91-18c4-49bf-99ee-50f0787fb023', agent_type=u'L3 agent', binary=u'neutron-l3-agent', topic=u'l3_agent', host=u'10e131e73e28', availability_zone=u'nova', admin_state_up=True, created_at=datetime.datetime(2017, 11, 3, 7, 45, 27), started_at=datetime.datetime(2017, 12, 17, 12, 30, 9), heartbeat_timestamp=datetime.datetime(2017, 12, 19, 2, 8, 43), description=None, configurations=u'{"agent_mode": "dvr", "gateway_external_network_id": "", "handle_internal_only_routers": true, "routers": 11, "interfaces": 17, "floating_ips": 3, "interface_driver": "openvswitch", "log_agent_heartbeats": false, "external_network_bridge": "", "ex_gw_ports": 11}', resource_versions=None, load=0}>, [u'7513735a-67d0-42e5-9cfd-edbbcccec0e9'], True) {} wrapper /usr/lib/python2.7/site-packages/oslo_log/helpers.py:66
87205:2017-12-19 10:08:56.261 33834 DEBUG neutron.db.l3_dvr_db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] No snat is bound to router 7513735a-67d0-42e5-9cfd-edbbcccec0e9 _build_routers_list /usr/lib/python2.7/site-packages/neutron/db/l3_dvr_db.py:599
87210:2017-12-19 10:08:56.367 33834 DEBUG neutron.db.l3_dvr_db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Return the SNAT ports: defaultdict(<type 'list'>, {'7513735a-67d0-42e5-9cfd-edbbcccec0e9': [{'status': u'DOWN', 'binding:host_id': u'', 'description': u'', 'allowed_address_pairs': [], 'tags': [], 'extra_dhcp_opts': [], 'updated_at': '2017-12-19T02:08:54Z', 'device_owner': u'network:router_centralized_snat', 'revision_number': 3, 'port_security_enabled': False, 'binding:profile': {}, 'fixed_ips': [{'subnet_id': u'181da985-3771-4d10-93a6-dd325f124d54', 'ip_address': u'10.10.10.5'}], 'id': u'ef6ffd27-7bc2-4bbd-a643-6e6d1762649e', 'security_groups': [], 'device_id': u'7513735a-67d0-42e5-9cfd-edbbcccec0e9', 'name': u'', 'admin_state_up': True, 'network_id': u'42c9d7b5-dedd-494a-9506-ecb3e65e3c5f', 'tenant_id': u'', 'binding:vif_details': {}, 'binding:vnic_type': u'normal', 'binding:vif_type': u'unbound', 'qos_policy_id': None, 'mac_address': u'fa:16:3e:8e:e7:9c', 'project_id': u'', 'created_at': '2017-12-19T02:08:54Z'}]}) _get_snat_sync_interfaces /usr/lib/python2.7/site-packages/neutron/db/l3_dvr_db.py:579
87211:2017-12-19 10:08:56.367 33834 DEBUG neutron.db.l3_dvr_db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] FIP Agent: 66cb0a91-18c4-49bf-99ee-50f0787fb023  _process_routers /usr/lib/python2.7/site-packages/neutron/db/l3_dvr_db.py:613
87212:2017-12-19 10:08:56.367 33834 DEBUG neutron.db.l3_dvr_db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] SNAT ports returned: [{'status': u'DOWN', 'binding:host_id': u'', 'description': u'', 'allowed_address_pairs': [], 'tags': [], 'extra_dhcp_opts': [], 'updated_at': '2017-12-19T02:08:54Z', 'device_owner': u'network:router_centralized_snat', 'revision_number': 3, 'port_security_enabled': False, 'binding:profile': {}, 'fixed_ips': [{'subnet_id': u'181da985-3771-4d10-93a6-dd325f124d54', 'ip_address': u'10.10.10.5'}], 'id': u'ef6ffd27-7bc2-4bbd-a643-6e6d1762649e', 'security_groups': [], 'device_id': u'7513735a-67d0-42e5-9cfd-edbbcccec0e9', 'name': u'', 'admin_state_up': True, 'network_id': u'42c9d7b5-dedd-494a-9506-ecb3e65e3c5f', 'tenant_id': u'', 'binding:vif_details': {}, 'binding:vnic_type': u'normal', 'binding:vif_type': u'unbound', 'qos_policy_id': None, 'mac_address': u'fa:16:3e:8e:e7:9c', 'project_id': u'', 'created_at': '2017-12-19T02:08:54Z'}]  _process_routers /usr/lib/python2.7/site-packages/neutron/db/l3_dvr_db.py:618
87216:2017-12-19 10:08:56.417 33834 DEBUG neutron.db.l3_dvr_db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Return the FIP ports: [{'status': u'ACTIVE', 'binding:host_id': u'10e131e73e28', 'description': u'', 'allowed_address_pairs': [], 'tags': [], 'extra_dhcp_opts': [], 'updated_at': '2017-11-06T00:20:38Z', 'device_owner': u'network:floatingip_agent_gateway', 'revision_number': 5, 'port_security_enabled': False, 'binding:profile': {}, 'fixed_ips': [{'subnet_id': u'd7338e15-1c8f-4bae-a669-0d51a3c00cdd', 'ip_address': u'36.111.0.113'}], 'id': u'296af337-1b37-4851-8ec7-87e4189e8789', 'security_groups': [], 'device_id': u'66cb0a91-18c4-49bf-99ee-50f0787fb023', 'name': u'', 'admin_state_up': True, 'network_id': u'b458da46-d4d6-432d-8837-e9045d80eb41', 'tenant_id': u'', 'binding:vif_details': {u'port_filter': True, u'datapath_type': u'system', u'ovs_hybrid_plug': False}, 'binding:vnic_type': u'normal', 'binding:vif_type': u'ovs', 'qos_policy_id': None, 'mac_address': u'fa:16:3e:d1:79:11', 'project_id': u'', 'created_at': '2017-11-06T00:20:34Z'}]  _get_fip_agent_gw_ports /usr/lib/python2.7/site-packages/neutron/db/l3_dvr_db.py:688
87217:2017-12-19 10:08:56.417 33834 DEBUG neutron.db.l3_dvr_db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] FIP Agent ports: [{'status': u'ACTIVE', 'binding:host_id': u'10e131e73e28', 'description': u'', 'allowed_address_pairs': [], 'tags': [], 'extra_dhcp_opts': [], 'updated_at': '2017-11-06T00:20:38Z', 'device_owner': u'network:floatingip_agent_gateway', 'revision_number': 5, 'port_security_enabled': False, 'binding:profile': {}, 'fixed_ips': [{'subnet_id': u'd7338e15-1c8f-4bae-a669-0d51a3c00cdd', 'ip_address': u'36.111.0.113'}], 'id': u'296af337-1b37-4851-8ec7-87e4189e8789', 'security_groups': [], 'device_id': u'66cb0a91-18c4-49bf-99ee-50f0787fb023', 'name': u'', 'admin_state_up': True, 'network_id': u'b458da46-d4d6-432d-8837-e9045d80eb41', 'tenant_id': u'', 'binding:vif_details': {u'port_filter': True, u'datapath_type': u'system', u'ovs_hybrid_plug': False}, 'binding:vnic_type': u'normal', 'binding:vif_type': u'ovs', 'qos_policy_id': None, 'mac_address': u'fa:16:3e:d1:79:11', 'project_id': u'', 'created_at': '2017-11-06T00:20:34Z'}] _process_routers /usr/lib/python2.7/site-packages/neutron/db/l3_dvr_db.py:623
87218:2017-12-19 10:08:56.417 33834 DEBUG neutron.db.l3_dvr_db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] FIP Agent : 66cb0a91-18c4-49bf-99ee-50f0787fb023  _process_floating_ips_dvr /usr/lib/python2.7/site-packages/neutron/db/l3_dvr_db.py:631
87223:2017-12-19 10:08:56.599 33834 DEBUG neutron.plugins.ml2.managers [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Network 30761292-2dd6-42f0-8e51-0ea0afe82653 has no segments _extend_network_dict_provider /usr/lib/python2.7/site-packages/neutron/plugins/ml2/managers.py:165
87224:2017-12-19 10:08:56.599 33834 DEBUG neutron.plugins.ml2.managers [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Network 77fd8180-5960-4ca4-af41-488fe97cf614 has no segments _extend_network_dict_provider /usr/lib/python2.7/site-packages/neutron/plugins/ml2/managers.py:165
87231:2017-12-19 10:08:56.995 33834 DEBUG neutron.db.l3_hamode_db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] neutron.services.l3_router.l3_router_plugin.L3RouterPlugin method _process_sync_ha_data called with arguments (<neutron_lib.context.Context object at 0x8cb7590>, [{'status': u'ACTIVE', '_interfaces': [{'status': u'DOWN', 'subnets': [{'dns_nameservers': [u'114.114.114.114'], 'ipv6_ra_mode': None, 'gateway_ip': u'10.10.10.1', 'cidr': u'10.10.10.0/24', 'id': u'181da985-3771-4d10-93a6-dd325f124d54', 'subnetpool_id': None}], 'binding:host_id': '', 'description': u'', 'allowed_address_pairs': [], 'tags': [], 'extra_dhcp_opts': [], 'updated_at': '2017-12-19T02:08:55Z', 'device_owner': u'network:router_interface_distributed', 'revision_number': 4, 'port_security_enabled': False, 'binding:profile': {}, 'mtu': 1500, 'fixed_ips': [{'subnet_id': u'181da985-3771-4d10-93a6-dd325f124d54', 'prefixlen': 24, 'ip_address': u'10.10.10.1'}], 'id': u'0b8f0c2c-db65-4814-994d-766546ef1815', 'security_groups': [], 'device_id': u'7513735a-67d0-42e5-9cfd-edbbcccec0e9', 'name': u'', 'admin_state_up': True, 'network_id': u'42c9d7b5-dedd-494a-9506-ecb3e65e3c5f', 'tenant_id': u'8ce361fbf0f44f87b3b6c072de64fcf1', 'binding:vif_details': {}, 'address_scopes': {4: None, 6: None}, 'binding:vnic_type': u'normal', 'binding:vif_type': 'distributed', 'qos_policy_id': None, 'mac_address': u'fa:16:3e:55:f0:65', 'project_id': u'8ce361fbf0f44f87b3b6c072de64fcf1', 'extra_subnets': [], 'created_at': '2017-12-19T02:08:53Z'}], 'enable_snat': False, 'ha_vr_id': 0, 'description': u'', 'tags': [], 'gw_port': {'status': u'DOWN', 'subnets': [{'dns_nameservers': [], 'ipv6_ra_mode': None, 'gateway_ip': u'36.111.0.1', 'cidr': u'36.111.0.0/24', 'id': u'd7338e15-1c8f-4bae-a669-0d51a3c00cdd', 'subnetpool_id': None}], 'binding:host_id': u'', 'description': u'', 'allowed_address_pairs': [], 'tags': [], 'extra_dhcp_opts': [], 'updated_at': '2017-12-19T02:08:46Z', 'device_owner': u'network:router_gateway', 'revision_number': 3, 'port_security_enabled': False, 'binding:profile': {}, 'mtu': 1550, 'fixed_ips': [{'subnet_id': u'd7338e15-1c8f-4bae-a669-0d51a3c00cdd', 'prefixlen': 24, 'ip_address': u'36.111.0.177'}], 'id': u'37aff8cd-aae5-4321-b530-2203fa5375a0', 'security_groups': [], 'device_id': u'7513735a-67d0-42e5-9cfd-edbbcccec0e9', 'name': u'', 'admin_state_up': True, 'network_id': u'b458da46-d4d6-432d-8837-e9045d80eb41', 'tenant_id': u'', 'binding:vif_details': {}, 'address_scopes': {4: None, 6: None}, 'binding:vnic_type': u'normal', 'binding:vif_type': u'unbound', 'qos_policy_id': None, 'mac_address': u'fa:16:3e:09:7b:d9', 'project_id': u'', 'extra_subnets': [], 'created_at': '2017-12-19T02:08:46Z'}, 'updated_at': '2017-12-19T02:08:55Z', '_floatingip_agent_interfaces': [{'status': u'ACTIVE', 'subnets': [{'dns_nameservers': [], 'ipv6_ra_mode': None, 'gateway_ip': u'36.111.0.1', 'cidr': u'36.111.0.0/24', 'id': u'd7338e15-1c8f-4bae-a669-0d51a3c00cdd', 'subnetpool_id': None}], 'binding:host_id': u'10e131e73e28', 'description': u'', 'allowed_address_pairs': [], 'tags': [], 'extra_dhcp_opts': [], 'updated_at': '2017-11-06T00:20:38Z', 'device_owner': u'network:floatingip_agent_gateway', 'revision_number': 5, 'port_security_enabled': False, 'binding:profile': {}, 'mtu': 1550, 'fixed_ips': [{'subnet_id': u'd7338e15-1c8f-4bae-a669-0d51a3c00cdd', 'prefixlen': 24, 'ip_address': u'36.111.0.113'}], 'id': u'296af337-1b37-4851-8ec7-87e4189e8789', 'security_groups': [], 'device_id': u'66cb0a91-18c4-49bf-99ee-50f0787fb023', 'name': u'', 'admin_state_up': True, 'network_id': u'b458da46-d4d6-432d-8837-e9045d80eb41', 'tenant_id': u'', 'binding:vif_details': {u'port_filter': True, u'datapath_type': u'system', u'ovs_hybrid_plug': False}, 'address_scopes': {4: None, 6: None}, 'binding:vnic_type': u'normal', 'binding:vif_type': u'ovs', 'qos_policy_id': None, 'mac_address': u'fa:16:3e:d1:79:11', 'project_id': u'', 'extra_subnets': [], 'created_at': '2017-11-06T00:20:34Z'}], 'revision_number': 4, 'ha': False, 'id': u'7513735a-67d0-42e5-9cfd-edbbcccec0e9', 'gw_port_host': None, 'external_gateway_info': {'network_id': u'b458da46-d4d6-432d-8837-e9045d80eb41', 'enable_snat': False, 'external_fixed_ips': [{'subnet_id': u'd7338e15-1c8f-4bae-a669-0d51a3c00cdd', 'ip_address': u'36.111.0.177'}]}, 'availability_zone_hints': [], 'availability_zones': [], 'name': u'openstack-route', 'gw_port_id': u'37aff8cd-aae5-4321-b530-2203fa5375a0', 'admin_state_up': True, 'tenant_id': u'8ce361fbf0f44f87b3b6c072de64fcf1', 'created_at': '2017-12-19T02:08:42Z', 'distributed': True, '_snat_router_interfaces': [{'status': u'DOWN', 'subnets': [{'dns_nameservers': [u'114.114.114.114'], 'ipv6_ra_mode': None, 'gateway_ip': u'10.10.10.1', 'cidr': u'10.10.10.0/24', 'id': u'181da985-3771-4d10-93a6-dd325f124d54', 'subnetpool_id': None}], 'binding:host_id': u'', 'description': u'', 'allowed_address_pairs': [], 'tags': [], 'extra_dhcp_opts': [], 'updated_at': '2017-12-19T02:08:54Z', 'device_owner': u'network:router_centralized_snat', 'revision_number': 3, 'port_security_enabled': False, 'binding:profile': {}, 'mtu': 1500, 'fixed_ips': [{'subnet_id': u'181da985-3771-4d10-93a6-dd325f124d54', 'prefixlen': 24, 'ip_address': u'10.10.10.5'}], 'id': u'ef6ffd27-7bc2-4bbd-a643-6e6d1762649e', 'security_groups': [], 'device_id': u'7513735a-67d0-42e5-9cfd-edbbcccec0e9', 'name': u'', 'admin_state_up': True, 'network_id': u'42c9d7b5-dedd-494a-9506-ecb3e65e3c5f', 'tenant_id': u'', 'binding:vif_details': {}, 'address_scopes': {4: None, 6: None}, 'binding:vnic_type': u'normal', 'binding:vif_type': u'unbound', 'qos_policy_id': None, 'mac_address': u'fa:16:3e:8e:e7:9c', 'project_id': u'', 'extra_subnets': [], 'created_at': '2017-12-19T02:08:54Z'}], 'flavor_id': None, 'routes': [], 'project_id': u'8ce361fbf0f44f87b3b6c072de64fcf1'}], u'10e131e73e28', u'dvr') {} wrapper /usr/lib/python2.7/site-packages/oslo_log/helpers.py:66
87232:2017-12-19 10:08:56.999 33834 DEBUG neutron.api.rpc.handlers.l3_rpc [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Checking router: 7513735a-67d0-42e5-9cfd-edbbcccec0e9 for host: 10e131e73e28 _ensure_host_set_on_ports /usr/lib/python2.7/site-packages/neutron/api/rpc/handlers/l3_rpc.py:135
87233:2017-12-19 10:08:57.000 33834 DEBUG neutron_lib.callbacks.manager [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Notify callbacks [] for port, before_update _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:167
87240:2017-12-19 10:08:57.194 33834 DEBUG neutron_lib.callbacks.manager [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Notify callbacks ['neutron.services.qos.qos_plugin.QoSPlugin._validate_update_port_callback-1259385'] for port, precommit_update _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:167
87241:2017-12-19 10:08:57.209 33834 DEBUG neutron_lib.callbacks.manager [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Notify callbacks ['neutron.plugins.ml2.ovo_rpc._ObjectChangeHandler.handle_event-3816566', 'neutron.db.l3_dvrscheduler_db._notify_l3_agent_port_update-8392513', 'neutron.db.l3_hascheduler_db._notify_l3_agent_ha_port_update-8392588', 'neutron.api.rpc.agentnotifiers.dhcp_rpc_agent_api.DhcpAgentNotifyAPI._native_event_send_dhcp_notification--9223372036852510818', 'neutron.plugins.ml2.plugin.Ml2Plugin.notify_sg_on_port_change--9223372036854121960'] for port, after_update _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:167
87242:2017-12-19 10:08:57.210 33834 DEBUG neutron_lib.callbacks.manager [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Notify callbacks [] for port, before_update _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:167
87567:2017-12-19 10:08:57.503 33834 DEBUG neutron_lib.callbacks.manager [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Notify callbacks ['neutron.services.qos.qos_plugin.QoSPlugin._validate_update_port_callback-1259385'] for port, precommit_update _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:167
87569:2017-12-19 10:08:57.521 33834 DEBUG neutron.db.provisioning_blocks [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Ignored duplicate provisioning block setup for port ef6ffd27-7bc2-4bbd-a643-6e6d1762649e by entity DHCP. add_provisioning_component /usr/lib/python2.7/site-packages/neutron/db/provisioning_blocks.py:67
87571:2017-12-19 10:08:57.524 33834 DEBUG neutron_lib.callbacks.manager [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Notify callbacks ['neutron.plugins.ml2.ovo_rpc._ObjectChangeHandler.handle_event-3816566', 'neutron.db.l3_dvrscheduler_db._notify_l3_agent_port_update-8392513', 'neutron.db.l3_hascheduler_db._notify_l3_agent_ha_port_update-8392588', 'neutron.api.rpc.agentnotifiers.dhcp_rpc_agent_api.DhcpAgentNotifyAPI._native_event_send_dhcp_notification--9223372036852510818', 'neutron.plugins.ml2.plugin.Ml2Plugin.notify_sg_on_port_change--9223372036854121960'] for port, after_update _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:167
87575:2017-12-19 10:08:57.571 33834 DEBUG neutron.plugins.ml2.db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] No binding for distributed port 0b8f0c2c-db65-4814-994d-766546ef1815 with host 10e131e73e28 get_distributed_port_binding_by_host /usr/lib/python2.7/site-packages/neutron/plugins/ml2/db.py:281
87580:2017-12-19 10:08:57.725 33834 DEBUG neutron.db.api [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:128
87581:2017-12-19 10:08:57.726 33834 DEBUG oslo_db.api [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c - - - - -] Performing DB retry for function neutron.plugins.ml2.plugin.update_distributed_port_binding wrapper /usr/lib/python2.7/site-packages/oslo_db/api.py:152
87595:2017-12-19 10:08:57.833 33834 DEBUG neutron.plugins.ml2.db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] No binding for distributed port 0b8f0c2c-db65-4814-994d-766546ef1815 with host 10e131e73e28 get_distributed_port_binding_by_host /usr/lib/python2.7/site-packages/neutron/plugins/ml2/db.py:281
87599:2017-12-19 10:08:58.004 33834 DEBUG neutron.plugins.ml2.db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] For port 0b8f0c2c-db65-4814-994d-766546ef1815, host 10e131e73e28, got binding levels [] get_binding_levels /usr/lib/python2.7/site-packages/neutron/plugins/ml2/db.py:106
87600:2017-12-19 10:08:58.032 33834 DEBUG neutron.plugins.ml2.managers [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Attempting to bind port 0b8f0c2c-db65-4814-994d-766546ef1815 on host 10e131e73e28 for vnic_type normal with profile  bind_port /usr/lib/python2.7/site-packages/neutron/plugins/ml2/managers.py:744
87601:2017-12-19 10:08:58.032 33834 DEBUG neutron.plugins.ml2.managers [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Attempting to bind port 0b8f0c2c-db65-4814-994d-766546ef1815 on host 10e131e73e28 at level 0 using segments [{'network_id': '42c9d7b5-dedd-494a-9506-ecb3e65e3c5f', 'segmentation_id': 60, 'physical_network': None, 'id': '7f2a1cbd-2a88-492c-ad35-8f4340a5fa11', 'network_type': u'vxlan'}] _bind_port_level /usr/lib/python2.7/site-packages/neutron/plugins/ml2/managers.py:765
87602:2017-12-19 10:08:58.033 33834 DEBUG neutron.plugins.ml2.drivers.mech_agent [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Attempting to bind port 0b8f0c2c-db65-4814-994d-766546ef1815 on network 42c9d7b5-dedd-494a-9506-ecb3e65e3c5f bind_port /usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/mech_agent.py:88
87603:2017-12-19 10:08:58.039 33834 DEBUG neutron.plugins.ml2.drivers.mech_agent [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Checking agent: {'binary': u'neutron-openvswitch-agent', 'description': None, 'admin_state_up': True, 'heartbeat_timestamp': datetime.datetime(2017, 12, 19, 2, 8, 44), 'availability_zone': None, 'alive': True, 'topic': u'N/A', 'host': u'10e131e73e28', 'agent_type': u'Open vSwitch agent', 'resource_versions': {u'Subnet': u'1.0', u'Network': u'1.0', u'SubPort': u'1.0', u'SecurityGroup': u'1.0', u'SecurityGroupRule': u'1.0', u'Trunk': u'1.1', u'QosPolicy': u'1.6', u'Port': u'1.1', u'Log': u'1.0'}, 'created_at': datetime.datetime(2017, 11, 3, 7, 45, 39), 'started_at': datetime.datetime(2017, 12, 17, 12, 30, 10), 'id': u'6dd661c2-dedb-45a5-a9b8-fff0ec574239', 'configurations': {u'ovs_hybrid_plug': False, u'in_distributed_mode': True, u'datapath_type': u'system', u'vhostuser_socket_dir': u'/var/run/openvswitch', u'tunneling_ip': u'10.131.72.28', u'arp_responder_enabled': True, u'devices': 0, u'ovs_capabilities': {u'datapath_types': [u'netdev', u'system'], u'iface_types': [u'geneve', u'gre', u'internal', u'lisp', u'patch', u'stt', u'system', u'tap', u'vxlan']}, u'log_agent_heartbeats': False, u'l2_population': True, u'tunnel_types': [u'vxlan'], u'extensions': [u'qos'], u'enable_distributed_routing': True, u'bridge_mappings': {u'external': u'br-ex'}}} bind_port /usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/mech_agent.py:104
87604:2017-12-19 10:08:58.040 33834 DEBUG neutron.plugins.ml2.drivers.mech_agent [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Checking segment: {'network_id': '42c9d7b5-dedd-494a-9506-ecb3e65e3c5f', 'segmentation_id': 60, 'physical_network': None, 'id': '7f2a1cbd-2a88-492c-ad35-8f4340a5fa11', 'network_type': u'vxlan'} for mappings: {u'external': u'br-ex'} with network types: [u'vxlan', 'local', 'flat', 'vlan'] check_segment_for_agent /usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/mech_agent.py:237
87605:2017-12-19 10:08:58.041 33834 DEBUG neutron_lib.callbacks.manager [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Notify callbacks [] for ovs_bridge_name, before_read _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:167
87606:2017-12-19 10:08:58.041 33834 DEBUG neutron.plugins.ml2.drivers.mech_agent [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Bound using segment: {'network_id': '42c9d7b5-dedd-494a-9506-ecb3e65e3c5f', 'segmentation_id': 60, 'physical_network': None, 'id': '7f2a1cbd-2a88-492c-ad35-8f4340a5fa11', 'network_type': u'vxlan'} bind_port /usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/mech_agent.py:109
87607:2017-12-19 10:08:58.042 33834 DEBUG neutron.plugins.ml2.managers [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Bound port: 0b8f0c2c-db65-4814-994d-766546ef1815, host: 10e131e73e28, vif_type: ovs, vif_details: {"port_filter": true, "datapath_type": "system", "ovs_hybrid_plug": false}, binding_levels: [{'bound_driver': 'openvswitch', 'bound_segment': {'network_id': '42c9d7b5-dedd-494a-9506-ecb3e65e3c5f', 'segmentation_id': 60, 'physical_network': None, 'id': '7f2a1cbd-2a88-492c-ad35-8f4340a5fa11', 'network_type': u'vxlan'}}] _bind_port_level /usr/lib/python2.7/site-packages/neutron/plugins/ml2/managers.py:813
87608:2017-12-19 10:08:58.043 33834 DEBUG neutron_lib.callbacks.manager [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Notify callbacks [] for port, before_update _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:167
87609:2017-12-19 10:08:58.093 33834 DEBUG neutron.plugins.ml2.db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] For port 0b8f0c2c-db65-4814-994d-766546ef1815, host 10e131e73e28, cleared binding levels clear_binding_levels /usr/lib/python2.7/site-packages/neutron/plugins/ml2/db.py:119
87610:2017-12-19 10:08:58.095 33834 DEBUG neutron.plugins.ml2.db [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] For port 0b8f0c2c-db65-4814-994d-766546ef1815, host 10e131e73e28, set binding levels [<neutron.plugins.ml2.driver_context.InstanceSnapshot object at 0x91c9d90>] set_binding_levels /usr/lib/python2.7/site-packages/neutron/plugins/ml2/db.py:90
87611:2017-12-19 10:08:58.099 33834 DEBUG neutron_lib.callbacks.manager [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Notify callbacks ['neutron.plugins.ml2.ovo_rpc._ObjectChangeHandler.handle_event-3816566', 'neutron.db.l3_dvrscheduler_db._notify_l3_agent_port_update-8392513', 'neutron.db.l3_hascheduler_db._notify_l3_agent_ha_port_update-8392588', 'neutron.api.rpc.agentnotifiers.dhcp_rpc_agent_api.DhcpAgentNotifyAPI._native_event_send_dhcp_notification--9223372036852510818', 'neutron.plugins.ml2.plugin.Ml2Plugin.notify_sg_on_port_change--9223372036854121960'] for port, after_update _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:167
87613:2017-12-19 10:08:58.163 33834 DEBUG neutron.plugins.ml2.drivers.l2pop.rpc [req-b6dec2c3-cc8a-4f0a-b8d8-aecac3d205c3 - - - - -] Fanout notify l2population agents at q-agent-notifier the message remove_fdb_entries with {u'42c9d7b5-dedd-494a-9506-ecb3e65e3c5f': {'ports': {u'10.131.72.28': []}, 'network_type': u'vxlan', 'segment_id': 60}} _notification_fanout /usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/l2pop/rpc.py:46

and the same as req-4846cd7b-94f2-4334-9324-df87a390d862.

Revision history for this message

Zachary Ma (mazengxie) wrote on 2017-12-19:

#10

it may be a potential bug

Revision history for this message

shihanzhang (shihanzhang) wrote on 2017-12-21:

#11

i oslo have the same problem, in dvr envirentment, sometimes it will lost ovs flow for l2 pop on compute node

Revision history for this message

Zachary Ma (mazengxie) wrote on 2017-12-21:

#12

@shihanzhang, we meet the same problem that it lost ovs flow for in dvr envirentment sometimes.
It is very bad for our china telecom public cloud.
Do you find the reason ?

Zachary Ma (mazengxie) on 2017-12-21

Changed in neutron:
assignee:	nobody → Zachary Ma (mazengxie)

Revision history for this message

shihanzhang (shihanzhang) wrote on 2017-12-22:

#13

@Zachary Ma, it is caused by this patch:https://review.openstack.org/#/c/503517/

Revision history for this message

Zachary Ma (mazengxie) wrote on 2017-12-22:

#14

yes, I know the patch and it can fix the some problem. Now it never occur the following error logs when merged in September in our public cloud.

4124:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api [req-3a38738f-efbf-45b0-ae65-3af84f6aae2c - - - - -] DB exceeded retry limit.: StaleDataError: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched.
4125:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api Traceback (most recent call last):
4126:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 138, in wrapper

But, now, it sometimes reports the following debug logs when created dvr router and bound network.
I am not sure whether it is a potential bug or not.
Because it large probability occur race conditions.

[root@10e131e73e121 ~]# grep -rin "standardattribute" /var/log/neutron/server.log
83922:2017-12-15 10:07:05.128 65701 DEBUG neutron.db.api [req-fe4da6c8-763f-41fa-9dac-537863c11740 - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:128
84013:2017-12-15 10:07:05.325 65703 DEBUG neutron.db.api [req-2632a1a7-f65e-45d9-be7b-ab4ce3c7372b - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:128

Revision history for this message

Ann Taraday (akamyshnikova) wrote on 2017-12-22:

#15

>>3.use ml2/ovs, no special configuration
You use DVR as I see, do you use L3 HA as well? They are special configurations actually.
I still missing some information from the report:
You create a network and a vm - then something happened (what do you notice?) and in logs there were these errors.

Changed in neutron:
importance:	Undecided → Low

Revision history for this message

Zachary Ma (mazengxie) wrote on 2017-12-22:

#16

@Ann Taraday never use L3 HA

Now, there are no error logs, but debug logs about "standardattribute" when we merged the patch
https://review.openstack.org/#/c/503517/ in our environment.

[root@10e131e73e121 ~]# grep -rin "standardattribute" /var/log/neutron/server.log
83922:2017-12-15 10:07:05.128 65701 DEBUG neutron.db.api [req-fe4da6c8-763f-41fa-9dac-537863c11740 - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:128
84013:2017-12-15 10:07:05.325 65703 DEBUG neutron.db.api [req-2632a1a7-f65e-45d9-be7b-ab4ce3c7372b - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:128

Revision history for this message

Zachary Ma (mazengxie) wrote on 2018-01-03:

#17

176302 2017-12-26 18:53:25.187 11925 DEBUG neutron.plugins.ml2.rpc [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] Update DVR po rt a8f7751a-0564-4e11-9dc5-553b732c51a7 at host 10e131e78e34 status to active. update_port_status_to_active /usr/lib/python2.7 /site-packages/neutron/plugins/ml2/rpc.py:278
176303 2017-12-26 18:53:25.194 11921 DEBUG neutron.wsgi [-] (11921) accepted ('10.131.78.148', 60032) server /usr/lib/python2.7/site- packages/eventlet/wsgi.py:883
176304 2017-12-26 18:53:25.196 11921 INFO neutron.wsgi [-] 10.131.78.148 "OPTIONS / HTTP/1.0" status: 200 len: 251 time: 0.0011199
176305 2017-12-26 18:53:25.228 11925 DEBUG neutron_lib.callbacks.manager [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] Notify callbacks [] for port, before_update _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:167
176306 2017-12-26 18:53:25.238 11925 DEBUG neutron.plugins.ml2.plugin [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] The update d value of port a8f7751a-0564-4e11-9dc5-553b732c51a7 is True. _update_individual_port_db_status /usr/lib/python2.7/site-packag es/neutron/plugins/ml2/plugin.py:1759
176307 2017-12-26 18:53:25.425 11925 DEBUG neutron.db.api [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] Retry wrapper got retr iable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/ python2.7/site-packages/neutron/db/api.py:128
176308 2017-12-26 18:53:25.425 11925 DEBUG oslo_db.api [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] Performing DB retry for f unction neutron.plugins.ml2.plugin.update_port_statuses wrapper /usr/lib/python2.7/site-packages/oslo_db/api.py:152
176309 2017-12-26 18:53:25.567 11925 DEBUG neutron_lib.callbacks.manager [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] Notify callbacks [] for port, before_update _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:167
176310 2017-12-26 18:53:25.571 11925 DEBUG neutron.plugins.ml2.plugin [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] The update d value of port a8f7751a-0564-4e11-9dc5-553b732c51a7 is False. _update_individual_port_db_status /usr/lib/python2.7/site-packa ges/neutron/plugins/ml2/plugin.py:1759
176311 2017-12-26 18:53:25.817 11925 DEBUG neutron.plugins.ml2.db [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] For port a8f77 51a-0564-4e11-9dc5-553b732c51a7, host 10e131e78e34, got binding levels [<neutron.plugins.ml2.models.PortBindingLevel[object at 5d4f510] {port_id=u'a8f7751a-0564-4e11-9dc5-553b732c51a7', host=u'10e131e78e34', level=0, driver=u'openvswitch', segment_id=u '4f9fde68-f2ce-43cc-bab3-097721affb3c'}>] get_binding_levels /usr/lib/python2.7/site-packages/neutron/plugins/ml2/db.py:106

Like this log,
the function _update_individual_port_db_status sometimes cause neutron.plugins.ml2.plugin.update_port_statuses performing DB retry, but the port.status has been chanaged.
So, it will be caused the ovs flow miss.

176302 2017-12-26 18:53:25.187 11925 DEBUG neutron.plugins.ml2.rpc [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] Update DVR po       rt a8f7751a-0564-4e11-9dc5-553b732c51a7 at host 10e131e78e34 status to active. update_port_status_to_active /usr/lib/python2.7       /site-packages/neutron/plugins/ml2/rpc.py:278
176303 2017-12-26 18:53:25.194 11921 DEBUG neutron.wsgi [-] (11921) accepted ('10.131.78.148', 60032) server /usr/lib/python2.7/site-       packages/eventlet/wsgi.py:883
176304 2017-12-26 18:53:25.196 11921 INFO neutron.wsgi [-] 10.131.78.148 "OPTIONS / HTTP/1.0" status: 200  len: 251 time: 0.0011199
176305 2017-12-26 18:53:25.228 11925 DEBUG neutron_lib.callbacks.manager [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] Notify        callbacks [] for port, before_update _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:167
176306 2017-12-26 18:53:25.238 11925 DEBUG neutron.plugins.ml2.plugin [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] The update       d value of port a8f7751a-0564-4e11-9dc5-553b732c51a7 is True. _update_individual_port_db_status /usr/lib/python2.7/site-packag       es/neutron/plugins/ml2/plugin.py:1759
176307 2017-12-26 18:53:25.425 11925 DEBUG neutron.db.api [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] Retry wrapper got retr       iable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/       python2.7/site-packages/neutron/db/api.py:128
176308 2017-12-26 18:53:25.425 11925 DEBUG oslo_db.api [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] Performing DB retry for f       unction neutron.plugins.ml2.plugin.update_port_statuses wrapper /usr/lib/python2.7/site-packages/oslo_db/api.py:152
176309 2017-12-26 18:53:25.567 11925 DEBUG neutron_lib.callbacks.manager [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] Notify        callbacks [] for port, before_update _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:167
176310 2017-12-26 18:53:25.571 11925 DEBUG neutron.plugins.ml2.plugin [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] The update       d value of port a8f7751a-0564-4e11-9dc5-553b732c51a7 is False. _update_individual_port_db_status /usr/lib/python2.7/site-packa       ges/neutron/plugins/ml2/plugin.py:1759
176311 2017-12-26 18:53:25.817 11925 DEBUG neutron.plugins.ml2.db [req-37d49036-2d6d-4548-9bed-2fa880fcd77a - - - - -] For port a8f77       51a-0564-4e11-9dc5-553b732c51a7, host 10e131e78e34, got binding levels [<neutron.plugins.ml2.models.PortBindingLevel[object at        5d4f510] {port_id=u'a8f7751a-0564-4e11-9dc5-553b732c51a7', host=u'10e131e78e34', level=0, driver=u'openvswitch', segment_id=u       '4f9fde68-f2ce-43cc-bab3-097721affb3c'}>] get_binding_levels /usr/lib/python2.7/site-packages/neutron/plugins/ml2/db.py:106

Like this log,
the function _update_individual_port_db_status sometimes cause neutron.plugins.ml2.plugin.update_port_statuses performing DB retry, but the port.status has been chanaged.
So, it will be caused the ovs flow miss.

summary:

[neutron-db] neutron-server report error "UPDATE statement on table
- 'standardattributes' expected to update 1 row(s); 0 were matched'
+ 'standardattributes' expected to update 1 row(s); 0 were matched'. It
+ will be caused the ovs flow miss

Revision history for this message

Ryan Tidwell (ryan-tidwell) wrote on 2019-01-29:

#18

Download full text (5.8 KiB)

I am also observing this behavior. It occurs when attempting to live-migrate a handful of VM's in rapid succession to the same host. This quick and dirty script is able to make the issue appear:

for i in `openstack server list --all-projects --host <origin> -c ID -f value`; do openstack server migrate $i --live <target>; done

From the neutron server logs:

DB exceeded retry limit.: StaleDataError: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched.
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api Traceback (most recent call last):
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api File "/opt/stack/venv/neutron-20181030T130300Z/lib/python2.7/site-packages/oslo_db/api.py", line 138, in wrapper
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api return f(*args, **kwargs)
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api File "/opt/stack/venv/neutron-20181030T130300Z/lib/python2.7/site-packages/neutron/db/api.py", line 128, in wrapped
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api LOG.debug("Retry wrapper got retriable exception: %s", e)
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api File "/opt/stack/venv/neutron-20181030T130300Z/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api self.force_reraise()
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api File "/opt/stack/venv/neutron-20181030T130300Z/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api six.reraise(self.type_, self.value, self.tb)
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api File "/opt/stack/venv/neutron-20181030T130300Z/lib/python2.7/site-packages/neutron/db/api.py", line 124, in wrapped
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api return f(*dup_args, **dup_kwargs)
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api File "/opt/stack/venv/neutron-20181030T130300Z/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 1346, in update_port
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api mech_context, attrs)
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api File "/opt/stack/venv/neutron-20181030T130300Z/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 354, in _process_port_binding
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api db.clear_binding_levels(plugin_context, port_id, original_host)
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api File "/opt/stack/venv/neutron-20181030T130300Z/lib/python2.7/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 979, in wrapper
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api return fn(*args, **kwargs)
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api File "/usr/lib64/python2.7/contextlib.py", line 24, in __exit__
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api self.gen.next()
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api File "/opt/stack/venv/neutron-20181030T130300Z/lib/python2.7/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 1029, in _transaction_scope
2019-01-24 09:57:34.959 255478 ERROR oslo_db.api yield resource
2019-01-24 09:57:34.959 255478 ERROR oslo_d...

neutron

[neutron-db] neutron-server report error "UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched'. It will be caused the ovs flow miss

Bug Description

Other bug subscribers

Remote bug watches