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

@@ -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:

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,

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

neutron/plugins/ml2/plugin.py

@@ -1458,7 +1458,7 @@ 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",
+                LOG.info(_LI("No ports have port_id starting with %s"),
                          port_id)
                 return
             except sa_exc.MultipleResultsFound: