[IP mgr] 412 Precondition Failed Ip address conflict with exist

[yanmo96]

When doing create-and-delete-ports_concurrent 50 times with 5 concurrent.
During delete port will trough the following error:

Traceback (most recent call last):
  File "/root/rally_venv/lib/python3.6/site-packages/rally/task/runner.py", line 69, in _run_scenario_once
    getattr(scenario_inst, method_name)(**scenario_kwargs)
  File "/root/rally_venv/lib/python3.6/site-packages/rally_openstack/task/scenarios/neutron/network.py", line 671, in run
    self.neutron.delete_port(port["id"])
  File "/root/rally_venv/lib/python3.6/site-packages/rally/task/service.py", line 114, in wrapper
    return func(instance, *args, **kwargs)
  File "/root/rally_venv/lib/python3.6/site-packages/rally/task/atomic.py", line 91, in func_atomic_actions
    f = func(self, *args, **kwargs)
  File "/root/rally_venv/lib/python3.6/site-packages/rally_openstack/common/services/network/neutron.py", line 876, in delete_port
    self.client.delete_port(port["id"])
  File "/root/rally_venv/lib/python3.6/site-packages/neutronclient/v2_0/client.py", line 821, in delete_port
    return self.delete(self.port_path % (port))
  File "/root/rally_venv/lib/python3.6/site-packages/neutronclient/v2_0/client.py", line 353, in delete
    headers=headers, params=params)
  File "/root/rally_venv/lib/python3.6/site-packages/neutronclient/v2_0/client.py", line 334, in retry_request
    headers=headers, params=params)
  File "/root/rally_venv/lib/python3.6/site-packages/neutronclient/v2_0/client.py", line 297, in do_request
    self._handle_fault_response(status_code, replybody, resp)
  File "/root/rally_venv/lib/python3.6/site-packages/neutronclient/v2_0/client.py", line 272, in _handle_fault_response
    exception_handler_v20(status_code, error_body)
  File "/root/rally_venv/lib/python3.6/site-packages/neutronclient/v2_0/client.py", line 92, in exception_handler_v20
    request_ids=request_ids)
neutronclient.common.exceptions.InternalServerError: 412 : [{"timestamp":"2021-07-12T20:02:37.846+0000","status":412,"error":"Precondition Failed","message":"Ip address conflict with exist","path":"/ips"}]

Rally report and log:

• http://10.213.43.169:8082/7_12_2021/create-and-delete-ports_concurrent.html#/NeutronNetworks.create_and_delete_ports/failures
• http://10.213.43.169:8082/7_12_2021/ym_log/create-and-delete-ports_concurrent

Below are the log from IP manager:

{"ip_version":0,"vpc_id":null,"subnet_id":null,"range_id":"5f0e3ae3-7f87-4c27-8185-c9d430a4aa00","ip":"10.2.2.3","state":null}]
2021-07-12 20:02:37.840 DEBUG 1 --- [io-8080-exec-10] .w.s.m.a.ResponseStatusExceptionResolver : Resolved [com.futurewei.alcor.privateipmanager.exception.IpAddrConflictException]
2021-07-12 20:02:37.840 DEBUG 1 --- [io-8080-exec-10] o.s.web.servlet.DispatcherServlet        : Completed 412 PRECONDITION_FAILED
2021-07-12 20:02:37.841 DEBUG 1 --- [nio-8080-exec-9] o.apache.catalina.valves.RemoteIpValve   : Incoming request /ips with originalRemoteAddr [172.16.247.211], originalRemoteHost=[172.16.247.211], originalSecure=[false], originalScheme=[http], originalServerName=[ipmanager-service.default.svc.cluster.local], originalServerPort=[9004] will be seen as newRemoteAddr=[172.16.247.211], newRemoteHost=[172.16.247.211], newSecure=[false], newScheme=[http], newServerName=[ipmanager-service.default.svc.cluster.local], newServerPort=[9004]
2021-07-12 20:02:37.841 DEBUG 1 --- [nio-8080-exec-9] o.a.c.authenticator.AuthenticatorBase    : Security checking request POST /ips
2021-07-12 20:02:37.841 DEBUG 1 --- [nio-8080-exec-9] org.apache.catalina.realm.RealmBase      :   No applicable constraints defined
2021-07-12 20:02:37.841 DEBUG 1 --- [nio-8080-exec-9] o.a.c.authenticator.AuthenticatorBase    : Not subject to any constraint
2021-07-12 20:02:37.841  INFO 1 --- [io-8080-exec-10] i.j.internal.reporters.LoggingReporter   : Span reported: a31f419e0d190754:b4b02f8193329662:f937dac5534cc61:1 - allocateIpAddr
2021-07-12 20:02:37.841 DEBUG 1 --- [nio-8080-exec-9] org.apache.tomcat.util.http.Parameters   : Set encoding to UTF-8
2021-07-12 20:02:37.841 DEBUG 1 --- [nio-8080-exec-9] o.s.web.servlet.DispatcherServlet        : POST "/ips", parameters={}
2021-07-12 20:02:37.841 DEBUG 1 --- [io-8080-exec-10] o.a.c.c.C.[Tomcat].[localhost]           : Processing ErrorPage[errorCode=0, location=/error]
2021-07-12 20:02:37.841 DEBUG 1 --- [nio-8080-exec-9] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.futurewei.alcor.privateipmanager.controller.IpAddrController#allocateIpAddr(IpAddrRequest)
2021-07-12 20:02:37.842 DEBUG 1 --- [io-8080-exec-10] o.s.web.servlet.DispatcherServlet        : "ERROR" dispatch for POST "/error", parameters={}
2021-07-12 20:02:37.842 DEBUG 1 --- [nio-8080-exec-9] m.m.a.RequestResponseBodyMethodProcessor : Read "application/json;charset=UTF-8" to [IpAddrRequest{ipVersion=0, vpcId='null', subnetId='null', rangeId='5f0e3ae3-7f87-4c27-8185-c9d430a4a (truncated)...]
2021-07-12 20:02:37.842 DEBUG 1 --- [nio-8080-exec-9] c.f.alcor.common.stats.StatisticsAspect  : Calculating duration of com.futurewei.alcor.privateipmanager.controller.IpAddrController.allocateIpAddr()...
2021-07-12 20:02:37.842 DEBUG 1 --- [nio-8080-exec-9] c.f.alcor.common.stats.StatisticsAspect  : Calculating duration of com.futurewei.alcor.privateipmanager.service.implement.IpAddrServiceImpl.allocateIpAddr()...
2021-07-12 20:02:37.842 DEBUG 1 --- [nio-8080-exec-9] c.f.a.p.s.implement.IpAddrServiceImpl    : Allocate ip address, request: IpAddrRequest{ipVersion=0, vpcId='null', subnetId='null', rangeId='5f0e3ae3-7f87-4c27-8185-c9d430a4aa00', ip='10.2.2.3', state='null'}
2021-07-12 20:02:37.842 DEBUG 1 --- [nio-8080-exec-9] c.f.alcor.common.stats.StatisticsAspect  : Calculating duration of com.futurewei.alcor.privateipmanager.repo.IpAddrRangeRepo.allocateIpAddr()...
2021-07-12 20:02:37.842 DEBUG 1 --- [io-8080-exec-10] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController#error(HttpServletRequest)
2021-07-12 20:02:37.843 DEBUG 1 --- [io-8080-exec-10] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Using 'application/json', given [application/json, application/*+json] and supported [application/json, application/*+json, application/json, application/*+json]
2021-07-12 20:02:37.843 DEBUG 1 --- [io-8080-exec-10] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Writing [{timestamp=Mon Jul 12 20:02:37 UTC 2021, status=412, error=Precondition Failed, message=Ip address c (truncated)...]
2021-07-12 20:02:37.844  INFO 1 --- [nio-8080-exec-9] global                                   : Cache IpAddrCache-5f0e3ae3-7f87-4c27-8185-c9d430a4aa00 AtomicityMode is ATOMIC
2021-07-12 20:02:37.844  INFO 1 --- [io-8080-exec-10] i.j.internal.reporters.LoggingReporter   : Span reported: a31f419e0d190754:72d4d984f588adb8:b4b02f8193329662:1 - error
2021-07-12 20:02:37.844 DEBUG 1 --- [io-8080-exec-10] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 412
2021-07-12 20:02:37.844 DEBUG 1 --- [io-8080-exec-10] o.a.c.c.C.[.[.[/].[dispatcherServlet]    :  Disabling the response for further output
2021-07-12 20:02:37.845 DEBUG 1 --- [io-8080-exec-10] o.a.tomcat.util.net.SocketWrapperBase    : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@29eedfa1:org.apache.tomcat.util.net.NioChannel@ad671b0:java.nio.channels.SocketChannel[connected local=ipmanager-866b956469-r946b/172.16.247.217:8080 remote=/172.16.247.211:45068]], Read from buffer: [0]
2021-07-12 20:02:37.845 DEBUG 1 --- [io-8080-exec-10] org.apache.tomcat.util.net.NioEndpoint   : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@29eedfa1:org.apache.tomcat.util.net.NioChannel@ad671b0:java.nio.channels.SocketChannel[connected local=ipmanager-866b956469-r946b/172.16.247.217:8080 remote=/172.16.247.211:45068]], Read direct from socket: [0]
2021-07-12 20:02:37.845 DEBUG 1 --- [io-8080-exec-10] o.apache.coyote.http11.Http11Processor   : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@29eedfa1:org.apache.tomcat.util.net.NioChannel@ad671b0:java.nio.channels.SocketChannel[connected local=ipmanager-866b956469-r946b/172.16.247.217:8080 remote=/172.16.247.211:45068]], Status in: [OPEN_READ], State out: [OPEN]
2021-07-12 20:02:37.845 DEBUG 1 --- [io-8080-exec-10] org.apache.tomcat.util.net.NioEndpoint   : Registered read interest for [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@29eedfa1:org.apache.tomcat.util.net.NioChannel@ad671b0:java.nio.channels.SocketChannel[connected local=ipmanager-866b956469-r946b/172.16.247.217:8080 remote=/172.16.247.211:45068]]
2021-07-12 20:02:37.845 DEBUG 1 --- [nio-8080-exec-9] .w.s.m.a.ResponseStatusExceptionResolver : Resolved [com.futurewei.alcor.privateipmanager.exception.IpAddrConflictException]
2021-07-12 20:02:37.845 DEBUG 1 --- [nio-8080-exec-9] o.s.web.servlet.DispatcherServlet        : Completed 412 PRECONDITION_FAILED
2021-07-12 20:02:37.845  INFO 1 --- [nio-8080-exec-9] i.j.internal.reporters.LoggingReporter   : Span reported: 56d5de8c8aaca6f0:f89cf2fde55b6f16:d56c8ac60c9da2ab:1 - allocateIpAddr
2021-07-12 20:02:37.845 DEBUG 1 --- [nio-8080-exec-9] o.a.c.c.C.[Tomcat].[localhost]           : Processing ErrorPage[errorCode=0, location=/error]
2021-07-12 20:02:37.845 DEBUG 1 --- [nio-8080-exec-9] o.s.web.servlet.DispatcherServlet        : "ERROR" dispatch for POST "/error", parameters={}
2021-07-12 20:02:37.846 DEBUG 1 --- [nio-8080-exec-9] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController#error(HttpServletRequest)
2021-07-12 20:02:37.846 DEBUG 1 --- [nio-8080-exec-9] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Using 'application/json', given [application/json, application/*+json] and supported [application/json, application/*+json, application/json, application/*+json]
2021-07-12 20:02:37.846 DEBUG 1 --- [nio-8080-exec-9] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Writing [{timestamp=Mon Jul 12 20:02:37 UTC 2021, status=412, error=Precondition Failed, message=Ip address c (truncated)...]
2021-07-12 20:02:37.847  INFO 1 --- [nio-8080-exec-9] i.j.internal.reporters.LoggingReporter   : Span reported: 56d5de8c8aaca6f0:8129067b647745bd:f89cf2fde55b6f16:1 - error
2021-07-12 20:02:37.847 DEBUG 1 --- [nio-8080-exec-9] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 412
2021-07-12 20:02:37.847 DEBUG 1 --- [nio-8080-exec-9] o.a.c.c.C.[.[.[/].[dispatcherServlet]    :  Disabling the response for further output
2021-07-12 20:02:37.847 DEBUG 1 --- [nio-8080-exec-9] o.a.tomcat.util.net.SocketWrapperBase    : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@4d4a46be:org.apache.tomcat.util.net.NioChannel@ac8424e:java.nio.channels.SocketChannel[connected local=ipmanager-866b956469-r946b/172.16.247.217:8080 remote=/172.16.247.211:45128]], Read from buffer: [0]
2021-07-12 20:02:37.847 DEBUG 1 --- [nio-8080-exec-9] org.apache.tomcat.util.net.NioEndpoint   : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@4d4a46be:org.apache.tomcat.util.net.NioChannel@ac8424e:java.nio.channels.SocketChannel[connected local=ipmanager-866b956469-r946b/172.16.247.217:8080 remote=/172.16.247.211:45128]], Read direct from socket: [0]
2021-07-12 20:02:37.847 DEBUG 1 --- [nio-8080-exec-9] o.apache.coyote.http11.Http11Processor   : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@4d4a46be:org.apache.tomcat.util.net.NioChannel@ac8424e:java.nio.channels.SocketChannel[connected local=ipmanager-866b956469-r946b/172.16.247.217:8080 remote=/172.16.247.211:45128]], Status in: [OPEN_READ], State out: [OPEN]
2021-07-12 20:02:37.847 DEBUG 1 --- [nio-8080-exec-9] org.apache.tomcat.util.net.NioEndpoint   : Registered read interest for [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@4d4a46be:org.apache.tomcat.util.net.NioChannel@ac8424e:java.nio.channels.SocketChannel[connected local=ipmanager-866b956469-r946b/172.16.247.217:8080 remote=/172.16.247.211:45128]]
2021-07-12 20:02:37.865 DEBUG 1 --- [nio-8080-exec-1] o.a.tomcat.util.net.SocketWrapperBase    : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@29eedfa1:org.apache.tomcat.util.net.NioChannel@ad671b0:java.nio.channels.SocketChannel[connected local=ipmanager-866b956469-r946b/172.16.247.217:8080 remote=/172.16.247.211:45068]], Read from buffer: [0]
2021-07-12 20:02:37.866 DEBUG 1 --- [nio-8080-exec-1] org.apache.tomcat.util.net.NioEndpoint   : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@29eedfa1:org.apache.tomcat.util.net.NioChannel@ad671b0:java.nio.channels.SocketChannel[connected local=ipmanager-866b956469-r946b/172.16.247.217:8080 remote=/172.16.247.211:45068]], Read direct from socket: [273]