From c6db32e8a713f248e04a8989c085607df4b04fb0 Mon Sep 17 00:00:00 2001
From: rossella <rsblendido@suse.com>
Date: Thu, 4 Feb 2016 12:37:14 +0100
Subject: [PATCH] Improve logging for port binding

When binding a port fails, it's really hard right now to
understand the reasons of the failure, unless the log level
is set to debug. In addition to that many log statement
are duplicated.
The goal of this patch is to solve these problems.

Closes-bug: #1543510
Change-Id: I262973126e8ca5af2b20a3a5bc35dea4251c0a78
---
 neutron/plugins/ml2/drivers/mech_agent.py        |  9 ++++++++-
 .../openvswitch/agent/ovs_neutron_agent.py       |  4 +++-
 neutron/plugins/ml2/managers.py                  | 16 +++++++++++-----
 neutron/plugins/ml2/plugin.py                    |  4 ++--
 4 files changed, 24 insertions(+), 9 deletions(-)

diff --git a/neutron/plugins/ml2/drivers/mech_agent.py b/neutron/plugins/ml2/drivers/mech_agent.py
index 33bc99222f7..024d5f67794 100644
--- a/neutron/plugins/ml2/drivers/mech_agent.py
+++ b/neutron/plugins/ml2/drivers/mech_agent.py
@@ -64,7 +64,14 @@ class AgentMechanismDriverBase(api.MechanismDriver):
             LOG.debug("Refusing to bind due to unsupported vnic_type: %s",
                       vnic_type)
             return
-        for agent in context.host_agents(self.agent_type):
+        agents = context.host_agents(self.agent_type)
+        if not agents:
+            LOG.warning(_LW("Port %(pid)s on network %(network)s not bound, "
+                            "no agent registered on host %(host)s"),
+                        {'pid': context.current['id'],
+                         'network': context.network.current['id'],
+                         'host': context.host})
+        for agent in agents:
             LOG.debug("Checking agent: %s", agent)
             if agent['alive']:
                 for segment in context.segments_to_bind:
diff --git a/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py b/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py
index 13b5ced2621..cbcebe6d97d 100644
--- a/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py
+++ b/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py
@@ -1486,7 +1486,9 @@ class OVSNeutronAgent(sg_rpc.SecurityGroupAgentRpcCallbackMixin,
                                           details['network_id'])
                 self.ext_manager.handle_port(self.context, details)
             else:
-                LOG.warn(_LW("Device %s not defined on plugin"), device)
+                LOG.warning(
+                    _LW("Device %s not defined on plugin or binding failed"),
+                    device)
                 if (port and port.ofport != -1):
                     self.port_dead(port)
         return (skipped_devices, need_binding_devices,
diff --git a/neutron/plugins/ml2/managers.py b/neutron/plugins/ml2/managers.py
index 97c63434a69..e784ed9f05c 100644
--- a/neutron/plugins/ml2/managers.py
+++ b/neutron/plugins/ml2/managers.py
@@ -687,9 +687,13 @@ class MechanismManager(stevedore.named.NamedExtensionManager):
         if not self._bind_port_level(context, 0,
                                      context.network.network_segments):
             binding.vif_type = portbindings.VIF_TYPE_BINDING_FAILED
-            LOG.error(_LE("Failed to bind port %(port)s on host %(host)s"),
+            LOG.error(_LE("Failed to bind port %(port)s on host %(host)s "
+                          "for vnic_type %(vnic_type)s using segments "
+                          "%(segments)s"),
                       {'port': context.current['id'],
-                       'host': context.host})
+                       'host': context.host,
+                       'vnic_type': binding.vnic_type,
+                       'segments': context.network.network_segments})
 
     def _bind_port_level(self, context, level, segments_to_bind):
         binding = context._binding
@@ -730,6 +734,11 @@ class MechanismManager(stevedore.named.NamedExtensionManager):
                                                  next_segments):
                             return True
                         else:
+                            LOG.warning(_LW("Failed to bind port %(port)s on "
+                                            "host %(host)s at level %(lvl)s"),
+                                        {'port': context.current['id'],
+                                         'host': context.host,
+                                         'lvl': level + 1})
                             context._pop_binding_level()
                     else:
                         # Binding complete.
@@ -748,9 +757,6 @@ class MechanismManager(stevedore.named.NamedExtensionManager):
                 LOG.exception(_LE("Mechanism driver %s failed in "
                                   "bind_port"),
                               driver.name)
-        LOG.error(_LE("Failed to bind port %(port)s on host %(host)s"),
-                  {'port': context.current['id'],
-                   'host': binding.host})
 
     def _check_driver_to_bind(self, driver, segments_to_bind, binding_levels):
         # To prevent a possible binding loop, don't try to bind with
diff --git a/neutron/plugins/ml2/plugin.py b/neutron/plugins/ml2/plugin.py
index 76b2d94056e..8e514135ca4 100644
--- a/neutron/plugins/ml2/plugin.py
+++ b/neutron/plugins/ml2/plugin.py
@@ -1458,8 +1458,8 @@ class Ml2Plugin(db_base_plugin_v2.NeutronDbPluginV2,
                            filter(models_v2.Port.id.startswith(port_id)).
                            one())
             except sa_exc.NoResultFound:
-                LOG.debug("No ports have port_id starting with %s",
-                          port_id)
+                LOG.info(_LI("No ports have port_id starting with %s"),
+                         port_id)
                 return
             except sa_exc.MultipleResultsFound:
                 LOG.error(_LE("Multiple ports have port_id starting with %s"),