test_create_router_set_gateway_with_fixed_ip fails in dvr-ha job

[Oleg Bondarev]

test_create_router_set_gateway_with_fixed_ip periodically fails in neutron-tempest-dvr-ha-multinode-full.
Failure start to happen after new engine facade switch in L3 code.
Failure is due to router failed to be deleted (neutron returns 500), see first line in below traceback.

Traceback:

2021-01-28 13:36:26,139 81948 INFO [tempest.lib.common.rest_client] Request (RoutersAdminTest:test_create_router_set_gateway_with_fixed_ip): 500 DELETE https://10.209.160.170:9696/v2.0/routers/3f337e0e-3bed-44f7-a8f9-e43c01787445 10.779s
2021-01-28 13:36:26,139 81948 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Thu, 28 Jan 2021 13:36:26 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-type': 'application/json', 'content-length': '150', 'x-openstack-request-id': 'req-2392442f-a3b0-4c79-a79c-c765c7cab834', 'connection': 'close', 'status': '500', 'content-location': 'https://10.209.160.170:9696/v2.0/routers/3f337e0e-3bed-44f7-a8f9-e43c01787445'}
        Body: b'{"NeutronError": {"type": "HTTPInternalServerError", "message": "Request Failed: internal server error while processing your request.", "detail": ""}}'
2021-01-28 13:36:26,305 81948 INFO [tempest.lib.common.rest_client] Request (RoutersAdminTest:_run_cleanups): 409 DELETE https://10.209.160.170:9696/v2.0/subnets/812a9855-15a2-4a8e-b246-c6ea68cdadcd 0.165s
2021-01-28 13:36:26,306 81948 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Thu, 28 Jan 2021 13:36:26 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-type': 'application/json', 'content-length': '204', 'x-openstack-request-id': 'req-9eb0af8b-9154-489b-94b8-93d3da458c05', 'connection': 'close', 'status': '409', 'content-location': 'https://10.209.160.170:9696/v2.0/subnets/812a9855-15a2-4a8e-b246-c6ea68cdadcd'}
        Body: b'{"NeutronError": {"type": "SubnetInUse", "message": "Unable to complete operation on subnet 812a9855-15a2-4a8e-b246-c6ea68cdadcd: One or more ports have an IP allocation from this subnet.", "detail": ""}}'
2021-01-28 13:36:26,544 81948 INFO [tempest.lib.common.rest_client] Request (RoutersAdminTest:_run_cleanups): 409 DELETE https://10.209.160.170:9696/v2.0/networks/c06258a3-d817-4ffd-b9c6-1c20eaedd688 0.238s
2021-01-28 13:36:26,545 81948 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Thu, 28 Jan 2021 13:36:26 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-type': 'application/json', 'content-length': '205', 'x-openstack-request-id': 'req-a412a0f0-832c-45f4-9e9d-40deef43cde2', 'connection': 'close', 'status': '409', 'content-location': 'https://10.209.160.170:9696/v2.0/networks/c06258a3-d817-4ffd-b9c6-1c20eaedd688'}
        Body: b'{"NeutronError": {"type": "NetworkInUse", "message": "Unable to complete operation on network c06258a3-d817-4ffd-b9c6-1c20eaedd688. There are one or more ports still in use on the network.", "detail": ""}}'
}}}

traceback-1: {{{
Traceback (most recent call last):
  File "/opt/stack/tempest/tempest/lib/common/utils/test_utils.py", line 87, in call_and_ignore_notfound_exc
    return func(*args, **kwargs)
  File "/opt/stack/tempest/tempest/lib/services/network/subnets_client.py", line 52, in delete_subnet
    return self.delete_resource(uri)
  File "/opt/stack/tempest/tempest/lib/services/network/base.py", line 41, in delete_resource
    resp, body = self.delete(req_uri)
  File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 331, in delete
    return self.request('DELETE', url, extra_headers, headers, body)
  File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 704, in request
    self._error_checker(resp, resp_body)
  File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 825, in _error_checker
    raise exceptions.Conflict(resp_body, resp=resp)
tempest.lib.exceptions.Conflict: Conflict with state of target resource
Details: {'type': 'SubnetInUse', 'message': 'Unable to complete operation on subnet 812a9855-15a2-4a8e-b246-c6ea68cdadcd: One or more ports have an IP allocation from this subnet.', 'detail': ''}
}}}

traceback-2: {{{
Traceback (most recent call last):
  File "/opt/stack/tempest/tempest/lib/common/utils/test_utils.py", line 87, in call_and_ignore_notfound_exc
    return func(*args, **kwargs)
  File "/opt/stack/tempest/tempest/lib/services/network/networks_client.py", line 52, in delete_network
    return self.delete_resource(uri)
  File "/opt/stack/tempest/tempest/lib/services/network/base.py", line 41, in delete_resource
    resp, body = self.delete(req_uri)
  File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 331, in delete
    return self.request('DELETE', url, extra_headers, headers, body)
  File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 704, in request
    self._error_checker(resp, resp_body)
  File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 825, in _error_checker
    raise exceptions.Conflict(resp_body, resp=resp)
tempest.lib.exceptions.Conflict: Conflict with state of target resource
Details: {'type': 'NetworkInUse', 'message': 'Unable to complete operation on network c06258a3-d817-4ffd-b9c6-1c20eaedd688. There are one or more ports still in use on the network.', 'detail': ''}
}}}

Traceback (most recent call last):
  File "/opt/stack/tempest/tempest/common/utils/__init__.py", line 109, in wrapper
    return func(*func_args, **func_kwargs)
  File "/opt/stack/tempest/tempest/api/network/admin/test_routers.py", line 254, in test_create_router_set_gateway_with_fixed_ip
    self.admin_routers_client.delete_router(router['id'])
  File "/opt/stack/tempest/tempest/lib/services/network/routers_client.py", line 52, in delete_router
    return self.delete_resource(uri)
  File "/opt/stack/tempest/tempest/lib/services/network/base.py", line 41, in delete_resource
    resp, body = self.delete(req_uri)
  File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 331, in delete
    return self.request('DELETE', url, extra_headers, headers, body)
  File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 704, in request
    self._error_checker(resp, resp_body)
  File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 880, in _error_checker
    raise exceptions.ServerFault(resp_body, resp=resp,
tempest.lib.exceptions.ServerFault: Got server fault
Details: Request Failed: internal server error while processing your request.

[Oleg Bondarev (obondarev)]

Traceback regarding failed router delete request:

Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager [None req-2392442f-a3b0-4c79-a79c-c765c7cab834 tempest-RoutersAdminTest-40700298 tempest-RoutersAdminTest-40700298-project-admin] Error during notification for neutron.services.l3_router.l3_router_plugin.DVRResourceOperationHandler._delete_dvr_internal_ports-711840 router_gateway, after_delete: sqlalchemy.orm.exc.StaleDataError: DELETE statement on table 'standardattributes' expected to delete 1 row(s); 0 were matched. Please set confirm_deleted_rows=False within the mapper configuration to prevent this warning.
Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager Traceback (most recent call last):
Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager File "/usr/local/lib/python3.8/dist-packages/neutron_lib/callbacks/manager.py", line 197, in _notify_loop
Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager callback(resource, event, trigger, **kwargs)
Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager File "/opt/stack/neutron/neutron/db/l3_dvr_db.py", line 369, in _delete_dvr_internal_ports
Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager self.delete_floatingip_agent_gateway_port(
Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager File "/opt/stack/neutron/neutron/db/l3_dvr_db.py", line 407, in delete_floatingip_agent_gateway_port
Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager self._core_plugin.ipam.delete_port(context, p['id'])
Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager File "/opt/stack/neutron/neutron/db/ipam_pluggable_backend.py", line 495, in delete_port
Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager self._ipam_deallocate_ips(context, ipam_driver, port,
Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager File "/opt/stack/neutron/neutron/db/ipam_pluggable_backend.py", line 95, in _ipam_deallocate_ips
Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager return
Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager File "/usr/local/lib/python3.8/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager self.force_reraise()
Jan 28 13:36:26.127967 ubuntu-focal-rax-ord-0022763382 neutron-server[65890]: ERROR neutron_lib.callbacks.manager File "/usr/local/lib/python3.8/dist-packages/osl...

[Oleg Bondarev (obondarev)]

Analysis:

1) _delete_current_gw_port is now called within a transaction: https://github.com/openstack/neutron/blob/a3dc80b509d72c8d1a3ea007cb657a9e217ba66a/neutron/db/l3_db.py#L524
2) _delete_current_gw_port notifies callbacks in the end: https://github.com/openstack/neutron/blob/a3dc80b509d72c8d1a3ea007cb657a9e217ba66a/neutron/db/l3_db.py#L397
3) _delete_dvr_internal_ports callback may fail while deleting ports with some retriable exception (StaleDataError)
4) this error is actually ignored by callback manager for AFTER_* events: https://github.com/openstack/neutron-lib/blob/2dabcc5cf7d68bf2a4640f07d5e170aa8b911390/neutron_lib/callbacks/manager.py#L168-L177
5) delete router proceeds with db session being in "half-rollback" state
6) InvalidRequestError is raised on next DB fetch: https://github.com/openstack/neutron/blob/a3dc80b509d72c8d1a3ea007cb657a9e217ba66a/neutron/db/l3_db.py#L528

[Oleg Bondarev (obondarev)]

Patch: https://review.opendev.org/c/openstack/neutron/+/774785

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/neutron 18.0.0.0rc1 release candidate.