Comment 5 for bug 1760047

So in my case the port is stale in DHCP agent because it is in NetworkCache.deleted_ports set.

The fun fact is that those problematic ports never hit NetworkCache.put_port() function. I added extra debug message in this function but I have no messages with those problematic ports (I have messages with other ports).

For example port dbe7ba5a-7340-428c-a6a6-bda7843dede8.
The port has been created around 07:23:39 by Nova.
The port has been deleted around 07:28:46 by Nova after 300 sec timeout.

Log from neutron-server.log:

2018-04-04 07:23:39.071 33 DEBUG neutron.db.provisioning_blocks [req-de2bd147-5db1-435a-864b-c10b63a79c1f aae866ac58414f81953c57df2494eaf9 579ef78d275a4019865bca2057af3caf - default default] Transition to ACTIVE for port object dbe7ba5a-7340-428c-a6a6-bda7843dede8 will not be triggered until provisioned by entity DHCP. add_provisioning_component /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/db/provisioning_blocks.py:73

DHCP agent logs on ctrl3:

grep -B1 dbe7ba5a-7340-428c-a6a6-bda7843dede8 neutron-dhcp-agent.log

2018-04-04 07:29:35.504 7 DEBUG neutron.agent.dhcp.agent [req-de2bd147-5db1-435a-864b-c10b63a79c1f aae866ac58414f81953c57df2494eaf9 579ef78d275a4019865bca2057af3caf - - -] PMDEBUG is_port_message_stale: port in deleted_ports is_port_message_stale /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/agent/dhcp/agent.py:624
2018-04-04 07:29:35.504 7 DEBUG neutron.agent.dhcp.agent [req-de2bd147-5db1-435a-864b-c10b63a79c1f aae866ac58414f81953c57df2494eaf9 579ef78d275a4019865bca2057af3caf - - -] Discarding stale port update: admin_state_up=True, allowed_address_pairs=[], binding:host_id=, binding:profile=, binding:vif_details=, binding:vif_type=unbound, binding:vnic_type=normal, created_at=2018-04-04T07:23:38Z, description=, device_id=74ec5382-110f-4590-a897-2ecdd46bcf4f, device_owner=, extra_dhcp_opts=[], fixed_ips=[{u'subnet_id': u'bd145992-d7fe-4fc8-acc7-ba510f8388e6', u'ip_address': u'10.7.0.26'}], id=dbe7ba5a-7340-428c-a6a6-bda7843dede8, mac_address=fa:16:3e:eb:f2:64, name=, network_id=b86c5078-65fe-480c-b658-300274dba0a2, port_security_enabled=True, project_id=579ef78d275a4019865bca2057af3caf, revision_number=3, security_groups=[u'b165182d-cd0f-42a5-b5d4-5434b9079aa8'], status=DOWN, tags=[], tenant_id=579ef78d275a4019865bca2057af3caf, updated_at=2018-04-04T07:23:38Z port_update_end /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/agent/dhcp/agent.py:409
--
2018-04-04 07:29:35.512 7 DEBUG neutron.agent.dhcp.agent [req-fc24211e-33ef-4dcb-8104-8442dcbfe6f1 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] PMDEBUG is_port_message_stale: port in deleted_ports is_port_message_stale /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/agent/dhcp/agent.py:624
2018-04-04 07:29:35.513 7 DEBUG neutron.agent.dhcp.agent [req-fc24211e-33ef-4dcb-8104-8442dcbfe6f1 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] Discarding stale port update: admin_state_up=True, allowed_address_pairs=[], binding:host_id=cds-compute11, binding:profile=, binding:vif_details=, binding:vif_type=unbound, binding:vnic_type=normal, created_at=2018-04-04T07:23:38Z, description=, device_id=74ec5382-110f-4590-a897-2ecdd46bcf4f, device_owner=compute:nova, extra_dhcp_opts=[], fixed_ips=[{u'subnet_id': u'bd145992-d7fe-4fc8-acc7-ba510f8388e6', u'ip_address': u'10.7.0.26'}], id=dbe7ba5a-7340-428c-a6a6-bda7843dede8, mac_address=fa:16:3e:eb:f2:64, name=, network_id=b86c5078-65fe-480c-b658-300274dba0a2, port_security_enabled=True, project_id=579ef78d275a4019865bca2057af3caf, revision_number=4, security_groups=[u'b165182d-cd0f-42a5-b5d4-5434b9079aa8'], status=DOWN, tags=[], tenant_id=579ef78d275a4019865bca2057af3caf, updated_at=2018-04-04T07:23:39Z port_update_end /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/agent/dhcp/agent.py:409
--
2018-04-04 07:29:35.517 7 DEBUG neutron.agent.dhcp.agent [req-fc24211e-33ef-4dcb-8104-8442dcbfe6f1 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] PMDEBUG is_port_message_stale: port in deleted_ports is_port_message_stale /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/agent/dhcp/agent.py:624
2018-04-04 07:29:35.517 7 DEBUG neutron.agent.dhcp.agent [req-fc24211e-33ef-4dcb-8104-8442dcbfe6f1 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] Discarding stale port update: admin_state_up=True, allowed_address_pairs=[], binding:host_id=cds-compute11, binding:profile=, binding:vif_details=datapath_type=system, ovs_hybrid_plug=True, port_filter=True, binding:vif_type=ovs, binding:vnic_type=normal, created_at=2018-04-04T07:23:38Z, description=, device_id=74ec5382-110f-4590-a897-2ecdd46bcf4f, device_owner=compute:nova, extra_dhcp_opts=[], fixed_ips=[{u'subnet_id': u'bd145992-d7fe-4fc8-acc7-ba510f8388e6', u'ip_address': u'10.7.0.26'}], id=dbe7ba5a-7340-428c-a6a6-bda7843dede8, mac_address=fa:16:3e:eb:f2:64, name=, network_id=b86c5078-65fe-480c-b658-300274dba0a2, port_security_enabled=True, project_id=579ef78d275a4019865bca2057af3caf, revision_number=5, security_groups=[u'b165182d-cd0f-42a5-b5d4-5434b9079aa8'], status=DOWN, tags=[], tenant_id=579ef78d275a4019865bca2057af3caf, updated_at=2018-04-04T07:23:40Z port_update_end /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/agent/dhcp/agent.py:409

DHCP agent logs on ctrl2 (4 minutes later???):

grep -B1 dbe7ba5a-7340-428c-a6a6-bda7843dede8 neutron-dhcp-agent.log

2018-04-04 07:33:55.460 7 DEBUG neutron.agent.dhcp.agent [req-de2bd147-5db1-435a-864b-c10b63a79c1f aae866ac58414f81953c57df2494eaf9 579ef78d275a4019865bca2057af3caf - - -] PMDEBUG is_port_message_stale: port in deleted_ports is_port_message_stale /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/agent/dhcp/agent.py:624
2018-04-04 07:33:55.461 7 DEBUG neutron.agent.dhcp.agent [req-de2bd147-5db1-435a-864b-c10b63a79c1f aae866ac58414f81953c57df2494eaf9 579ef78d275a4019865bca2057af3caf - - -] Discarding stale port update: admin_state_up=True, allowed_address_pairs=[], binding:host_id=, binding:profile=, binding:vif_details=, binding:vif_type=unbound, binding:vnic_type=normal, created_at=2018-04-04T07:23:38Z, description=, device_id=74ec5382-110f-4590-a897-2ecdd46bcf4f, device_owner=, extra_dhcp_opts=[], fixed_ips=[{u'subnet_id': u'bd145992-d7fe-4fc8-acc7-ba510f8388e6', u'ip_address': u'10.7.0.26'}], id=dbe7ba5a-7340-428c-a6a6-bda7843dede8, mac_address=fa:16:3e:eb:f2:64, name=, network_id=b86c5078-65fe-480c-b658-300274dba0a2, port_security_enabled=True, project_id=579ef78d275a4019865bca2057af3caf, revision_number=3, security_groups=[u'b165182d-cd0f-42a5-b5d4-5434b9079aa8'], status=DOWN, tags=[], tenant_id=579ef78d275a4019865bca2057af3caf, updated_at=2018-04-04T07:23:38Z port_update_end /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/agent/dhcp/agent.py:409
--
2018-04-04 07:33:55.469 7 DEBUG neutron.agent.dhcp.agent [req-fc24211e-33ef-4dcb-8104-8442dcbfe6f1 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] PMDEBUG is_port_message_stale: port in deleted_ports is_port_message_stale /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/agent/dhcp/agent.py:624
2018-04-04 07:33:55.469 7 DEBUG neutron.agent.dhcp.agent [req-fc24211e-33ef-4dcb-8104-8442dcbfe6f1 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] Discarding stale port update: admin_state_up=True, allowed_address_pairs=[], binding:host_id=cds-compute11, binding:profile=, binding:vif_details=, binding:vif_type=unbound, binding:vnic_type=normal, created_at=2018-04-04T07:23:38Z, description=, device_id=74ec5382-110f-4590-a897-2ecdd46bcf4f, device_owner=compute:nova, extra_dhcp_opts=[], fixed_ips=[{u'subnet_id': u'bd145992-d7fe-4fc8-acc7-ba510f8388e6', u'ip_address': u'10.7.0.26'}], id=dbe7ba5a-7340-428c-a6a6-bda7843dede8, mac_address=fa:16:3e:eb:f2:64, name=, network_id=b86c5078-65fe-480c-b658-300274dba0a2, port_security_enabled=True, project_id=579ef78d275a4019865bca2057af3caf, revision_number=4, security_groups=[u'b165182d-cd0f-42a5-b5d4-5434b9079aa8'], status=DOWN, tags=[], tenant_id=579ef78d275a4019865bca2057af3caf, updated_at=2018-04-04T07:23:39Z port_update_end /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/agent/dhcp/agent.py:409
--
2018-04-04 07:33:55.473 7 DEBUG neutron.agent.dhcp.agent [req-fc24211e-33ef-4dcb-8104-8442dcbfe6f1 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] PMDEBUG is_port_message_stale: port in deleted_ports is_port_message_stale /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/agent/dhcp/agent.py:624
2018-04-04 07:33:55.473 7 DEBUG neutron.agent.dhcp.agent [req-fc24211e-33ef-4dcb-8104-8442dcbfe6f1 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] Discarding stale port update: admin_state_up=True, allowed_address_pairs=[], binding:host_id=cds-compute11, binding:profile=, binding:vif_details=datapath_type=system, ovs_hybrid_plug=True, port_filter=True, binding:vif_type=ovs, binding:vnic_type=normal, created_at=2018-04-04T07:23:38Z, description=, device_id=74ec5382-110f-4590-a897-2ecdd46bcf4f, device_owner=compute:nova, extra_dhcp_opts=[], fixed_ips=[{u'subnet_id': u'bd145992-d7fe-4fc8-acc7-ba510f8388e6', u'ip_address': u'10.7.0.26'}], id=dbe7ba5a-7340-428c-a6a6-bda7843dede8, mac_address=fa:16:3e:eb:f2:64, name=, network_id=b86c5078-65fe-480c-b658-300274dba0a2, port_security_enabled=True, project_id=579ef78d275a4019865bca2057af3caf, revision_number=5, security_groups=[u'b165182d-cd0f-42a5-b5d4-5434b9079aa8'], status=DOWN, tags=[], tenant_id=579ef78d275a4019865bca2057af3caf, updated_at=2018-04-04T07:23:40Z port_update_end /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/agent/dhcp/agent.py:409

No other logs from DHCP agents about this port! Look like they missed create port event?

I spawned 100 VMs: 95 OK, 5 ERROR.