neutron

Bug #1760047
Comment #7

Comment 7 for bug 1760047

Revision history for this message

Piotr Misiak (piotr-misiak) wrote on 2018-04-05:

Here is code with my debug message:

    @_wait_if_syncing
    def port_update_end(self, context, payload):
        """Handle the port.update.end notification event."""
        updated_port = dhcp.DictModel(payload['port'])
        LOG.debug("PMDEBUG port_update_end: port %s , payload %s",updated_port,payload)
        with _net_lock(updated_port.network_id):
            if self.cache.is_port_message_stale(payload['port']):
                LOG.debug("Discarding stale port update: %s", updated_port)
                return

Here is log:

2018-04-04 13:38:45.697 7 DEBUG neutron.agent.dhcp.agent [req-a01c7740-95a0-44ab-8657-5e04ad82d1b5 aae866ac58414f81953c57df2494eaf9 579ef78d275a4019865bca2057af3caf - - -] PMDEBUG port_update_end: port 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-04T13:38:43Z, description=, device_id=64869685-5c86-4733-a947-bffbdc113f79, device_owner=, extra_dhcp_opts=[], fixed_ips=[{u'subnet_id': u'bd145992-d7fe-4fc8-acc7-ba510f8388e6', u'ip_address': u'10.7.0.5'}], id=2a00efeb-d5e6-4070-b2b8-64b484368808, mac_address=fa:16:3e:24:7e:40, 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-04T13:38:43Z , payload {u'port': {u'allowed_address_pairs': [], u'extra_dhcp_opts': [], u'updated_at': u'2018-04-04T13:38:43Z', u'device_owner': u'', u'revision_number': 3, u'binding:profile': {}, u'port_security_enabled': True, u'fixed_ips': [{u'subnet_id': u'bd145992-d7fe-4fc8-acc7-ba510f8388e6', u'ip_address': u'10.7.0.5'}], u'id': u'2a00efeb-d5e6-4070-b2b8-64b484368808', u'security_groups': [u'b165182d-cd0f-42a5-b5d4-5434b9079aa8'], u'binding:vif_details': {}, u'binding:vif_type': u'unbound', u'mac_address': u'fa:16:3e:24:7e:40', u'project_id': u'579ef78d275a4019865bca2057af3caf', u'status': u'DOWN', u'binding:host_id': u'', u'description': u'', u'tags': [], u'device_id': u'64869685-5c86-4733-a947-bffbdc113f79', u'name': u'', u'admin_state_up': True, u'network_id': u'b86c5078-65fe-480c-b658-300274dba0a2', u'tenant_id': u'579ef78d275a4019865bca2057af3caf', u'created_at': u'2018-04-04T13:38:43Z', u'binding:vnic_type': u'normal'}} port_update_end /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/agent/dhcp/agent.py:407
2018-04-04 13:48:50.457 7 DEBUG oslo_concurrency.lockutils [req-a01c7740-95a0-44ab-8657-5e04ad82d1b5 aae866ac58414f81953c57df2494eaf9 579ef78d275a4019865bca2057af3caf - - -] Acquired semaphore "dhcp-agent-network-lock-b86c5078-65fe-480c-b658-300274dba0a2" lock /var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212
2018-04-04 13:48:50.457 7 DEBUG neutron.agent.dhcp.agent [req-a01c7740-95a0-44ab-8657-5e04ad82d1b5 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:626
2018-04-04 13:48:50.457 7 DEBUG neutron.agent.dhcp.agent [req-a01c7740-95a0-44ab-8657-5e04ad82d1b5 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-04T13:38:43Z, description=, device_id=64869685-5c86-4733-a947-bffbdc113f79, device_owner=, extra_dhcp_opts=[], fixed_ips=[{u'subnet_id': u'bd145992-d7fe-4fc8-acc7-ba510f8388e6', u'ip_address': u'10.7.0.5'}], id=2a00efeb-d5e6-4070-b2b8-64b484368808, mac_address=fa:16:3e:24:7e:40, 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-04T13:38:43Z port_update_end /var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/agent/dhcp/agent.py:410
2018-04-04 13:48:50.457 7 DEBUG oslo_concurrency.lockutils [req-a01c7740-95a0-44ab-8657-5e04ad82d1b5 aae866ac58414f81953c57df2494eaf9 579ef78d275a4019865bca2057af3caf - - -] Releasing semaphore "dhcp-agent-network-lock-b86c5078-65fe-480c-b658-300274dba0a2" lock /var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:225

So it waited over 10 minutes on:

with _net_lock(updated_port.network_id):

But I see in the same DHCP agent logs that this semaphore was acquired and released many times during this period of time. Just a few lines as an example:

2018-04-04 13:38:47.762 7 DEBUG oslo_concurrency.lockutils [req-c18b71ce-a1f4-4d8d-aa0c-95aebff530fe aae866ac58414f81953c57df2494eaf9 579ef78d275a4019865bca2057af3caf - - -] Releasing semaphore "dhcp-agent-network-lock-b86c5078-65fe-480c-b658-300274dba0a2" lock /var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:225
2018-04-04 13:38:47.764 7 DEBUG oslo_concurrency.lockutils [req-70cabebf-dbbf-4b67-b5bb-0876d873ba2a 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] Acquired semaphore "dhcp-agent-network-lock-b86c5078-65fe-480c-b658-300274dba0a2" lock /var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212
2018-04-04 13:38:49.982 7 DEBUG oslo_concurrency.lockutils [req-70cabebf-dbbf-4b67-b5bb-0876d873ba2a 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] Releasing semaphore "dhcp-agent-network-lock-b86c5078-65fe-480c-b658-300274dba0a2" lock /var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:225
2018-04-04 13:38:49.983 7 DEBUG oslo_concurrency.lockutils [req-c98f4111-4083-4a06-ab91-ff01b8e3c55b 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] Acquired semaphore "dhcp-agent-network-lock-b86c5078-65fe-480c-b658-300274dba0a2" lock /var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212
2018-04-04 13:38:52.101 7 DEBUG oslo_concurrency.lockutils [req-c98f4111-4083-4a06-ab91-ff01b8e3c55b 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] Releasing semaphore "dhcp-agent-network-lock-b86c5078-65fe-480c-b658-300274dba0a2" lock /var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:225
2018-04-04 13:38:52.103 7 DEBUG oslo_concurrency.lockutils [req-5289fc1f-757b-4395-89ad-e0960d9387d7 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] Acquired semaphore "dhcp-agent-network-lock-b86c5078-65fe-480c-b658-300274dba0a2" lock /var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212
2018-04-04 13:38:54.330 7 DEBUG oslo_concurrency.lockutils [req-5289fc1f-757b-4395-89ad-e0960d9387d7 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] Releasing semaphore "dhcp-agent-network-lock-b86c5078-65fe-480c-b658-300274dba0a2" lock /var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:225
2018-04-04 13:38:54.331 7 DEBUG oslo_concurrency.lockutils [req-70cabebf-dbbf-4b67-b5bb-0876d873ba2a 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] Acquired semaphore "dhcp-agent-network-lock-b86c5078-65fe-480c-b658-300274dba0a2" lock /var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212
2018-04-04 13:38:56.721 7 DEBUG oslo_concurrency.lockutils [req-70cabebf-dbbf-4b67-b5bb-0876d873ba2a 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] Releasing semaphore "dhcp-agent-network-lock-b86c5078-65fe-480c-b658-300274dba0a2" lock /var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:225
2018-04-04 13:38:56.722 7 DEBUG oslo_concurrency.lockutils [req-faa632dc-a00e-42d7-9424-c1f2b3dec10f aae866ac58414f81953c57df2494eaf9 579ef78d275a4019865bca2057af3caf - - -] Acquired semaphore "dhcp-agent-network-lock-b86c5078-65fe-480c-b658-300274dba0a2" lock /var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212
2018-04-04 13:38:59.052 7 DEBUG oslo_concurrency.lockutils [req-faa632dc-a00e-42d7-9424-c1f2b3dec10f aae866ac58414f81953c57df2494eaf9 579ef78d275a4019865bca2057af3caf - - -] Releasing semaphore "dhcp-agent-network-lock-b86c5078-65fe-480c-b658-300274dba0a2" lock /var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:225
2018-04-04 13:38:59.053 7 DEBUG oslo_concurrency.lockutils [req-404f0285-7f16-4986-8910-5abc048a8a72 2f1c221e2bfb476bb9949244268b9596 fecb9ee2da694abeb723e2068b29ac3e - - -] Acquired semaphore "dhcp-agent-network-lock-b86c5078-65fe-480c-b658-300274dba0a2" lock /var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212

What is going on here?

Here is code with my debug message:

@_wait_if_syncing                                                           
    def port_update_end(self, context, payload):                                
        """Handle the port.update.end notification event."""                    
        updated_port = dhcp.DictModel(payload['port'])                          
        LOG.debug("PMDEBUG port_update_end: port %s , payload %s",updated_port,payload)
        with _net_lock(updated_port.network_id):                                
            if self.cache.is_port_message_stale(payload['port']):               
                LOG.debug("Discarding stale port update: %s", updated_port)     
                return

Here is log:

So it waited over 10 minutes on:

with _net_lock(updated_port.network_id):

But I see in the same DHCP agent logs that this semaphore was acquired and released many times during this period of time. Just a few lines as an example:

What is going on here?