From 9b6591b5828bf0aa5e37dddb10387f936ee5af04 Mon Sep 17 00:00:00 2001
From: Slawek Kaplonski <skaplons@redhat.com>
Date: Tue, 19 Jan 2021 13:00:28 +0100
Subject: [PATCH] Improve DHCP agent's debug messages

When new port is created dhcp agent checks if IP addresses which are
assigned to that port aren't already associated with different ports
which are in agent's cache.
When it finds such duplicate IPs, resync of the network is scheduled.

The problem is that debug message which informs about such duplicate
IPs isn't very "verbose".
With this patch it will log new and cached port ids as well as ip
addresses on both of those ports. That should make easier to understand
why such duplicates are in the cache.

This patch also adds logging when methods like
_{network|subnet|port}_{create|update|delete} are called and with what
arguments exactly. This should help investigation what exactly happens
with some specific port in the dhcp agent.

Related-bug: #1828423

Change-Id: I964a3d843aeedef424a4466932bf702ea1b4320e
(cherry picked from commit 9c2029c2c81fe32a41a39bf7e1265bf1d90f61ea)
---
 neutron/agent/dhcp/agent.py | 27 +++++++++++++++++++++++----
 1 file changed, 23 insertions(+), 4 deletions(-)

diff --git a/neutron/agent/dhcp/agent.py b/neutron/agent/dhcp/agent.py
index 0d20a45b88e..4b74735cf34 100644
--- a/neutron/agent/dhcp/agent.py
+++ b/neutron/agent/dhcp/agent.py
@@ -24,6 +24,7 @@ from neutron_lib import context
 from neutron_lib import exceptions
 from oslo_concurrency import lockutils
 from oslo_config import cfg
+from oslo_log import helpers as log_helpers
 from oslo_log import log as logging
 import oslo_messaging
 from oslo_service import loopingcall
@@ -374,6 +375,7 @@ class DhcpAgent(manager.Manager):
         self._queue.add(update)
 
     @_wait_if_syncing
+    @log_helpers.log_method_call
     def _network_create(self, payload):
         network_id = payload['network']['id']
         self.enable_dhcp_helper(network_id)
@@ -388,6 +390,7 @@ class DhcpAgent(manager.Manager):
         self._queue.add(update)
 
     @_wait_if_syncing
+    @log_helpers.log_method_call
     def _network_update(self, payload):
         network_id = payload['network']['id']
         if payload['network']['admin_state_up']:
@@ -405,6 +408,7 @@ class DhcpAgent(manager.Manager):
         self._queue.add(update)
 
     @_wait_if_syncing
+    @log_helpers.log_method_call
     def _network_delete(self, payload):
         network_id = payload['network_id']
         self.disable_dhcp_helper(network_id)
@@ -419,6 +423,7 @@ class DhcpAgent(manager.Manager):
         self._queue.add(update)
 
     @_wait_if_syncing
+    @log_helpers.log_method_call
     def _subnet_update(self, payload):
         network_id = payload['subnet']['network_id']
         self.refresh_dhcp_helper(network_id)
@@ -457,6 +462,7 @@ class DhcpAgent(manager.Manager):
         self._queue.add(update)
 
     @_wait_if_syncing
+    @log_helpers.log_method_call
     def _subnet_delete(self, payload):
         network_id = self._get_network_lock_id(payload)
         if not network_id:
@@ -493,6 +499,7 @@ class DhcpAgent(manager.Manager):
         self._queue.add(update)
 
     @_wait_if_syncing
+    @log_helpers.log_method_call
     def _port_update(self, updated_port):
         if self.cache.is_port_message_stale(updated_port):
             LOG.debug("Discarding stale port update: %s", updated_port)
@@ -504,7 +511,8 @@ class DhcpAgent(manager.Manager):
         self.reload_allocations(updated_port, network, prio=True)
 
     def reload_allocations(self, port, network, prio=False):
-        LOG.info("Trigger reload_allocations for port %s", port)
+        LOG.info("Trigger reload_allocations for port %s on network %s",
+                 port, network)
         driver_action = 'reload_allocations'
         if self._is_port_on_this_agent(port):
             orig = self.cache.get_port_by_id(port['id'])
@@ -551,6 +559,7 @@ class DhcpAgent(manager.Manager):
         self._queue.add(update)
 
     @_wait_if_syncing
+    @log_helpers.log_method_call
     def _port_create(self, created_port):
         network = self.cache.get_network_by_id(created_port.network_id)
         if not network:
@@ -565,9 +574,18 @@ class DhcpAgent(manager.Manager):
             if (new_ips.intersection(cached_ips) and
                 (created_port['id'] != port_cached['id'] or
                  created_port['mac_address'] != port_cached['mac_address'])):
-                self.schedule_resync("Duplicate IP addresses found, "
-                                     "DHCP cache is out of sync",
-                                     created_port.network_id)
+                resync_reason = (
+                    "Duplicate IP addresses found, "
+                    "Port in cache: {cache_port_id}, "
+                    "Created port: {port_id}, "
+                    "IPs in cache: {cached_ips}, "
+                    "new IPs: {new_ips}."
+                    "DHCP cache is out of sync").format(
+                        cache_port_id=port_cached['id'],
+                        port_id=created_port['id'],
+                        cached_ips=cached_ips,
+                        new_ips=new_ips)
+                self.schedule_resync(resync_reason, created_port.network_id)
                 return
         self.reload_allocations(created_port, network, prio=True)
 
@@ -584,6 +602,7 @@ class DhcpAgent(manager.Manager):
         self._queue.add(update)
 
     @_wait_if_syncing
+    @log_helpers.log_method_call
     def _port_delete(self, payload):
         network_id = self._get_network_lock_id(payload)
         if not network_id: