more debug logs for free, network_cli, paramiko and add hostname cont…

…ext to debugging messages (ansible#39205)

* Add hostname context to debugging messages
* Set paramiko's channel

lib/ansible/plugins/connection/network_cli.py

@@ -157,6 +157,7 @@
       - name: ANSIBLE_PERSISTENT_COMMAND_TIMEOUT
 """
 
+import getpass
 import json
 import logging
 import re
@@ -221,6 +222,11 @@ def __getattr__(self, name):
                 raise AttributeError("'%s' object has no attribute '%s'" % (self.__class__.__name__, name))
             return getattr(self._cliconf, name)
 
+    def _get_log_channel(self):
+        name = "p=%s u=%s | " % (os.getpid(), getpass.getuser())
+        name += "paramiko [%s]" % self._play_context.remote_addr
+        return name
+
     def get_prompt(self):
         """Returns the current prompt from the device"""
         return self._matched_prompt
@@ -284,6 +290,7 @@ def _connect(self):
             return
 
         self.paramiko_conn = connection_loader.get('paramiko', self._play_context, '/dev/null')
+        self.paramiko_conn._set_log_channel(self._get_log_channel())
         self.paramiko_conn.set_options(direct={'look_for_keys': not bool(self._play_context.password and not self._play_context.private_key_file)})
         self.paramiko_conn.force_persistence = self.force_persistence
         ssh = self.paramiko_conn._connect()
@@ -363,7 +370,7 @@ def close(self):
         '''
         # only close the connection if its connected.
         if self._connected:
-            display.debug("closing ssh connection to device")
+            display.debug("closing ssh connection to device", host=self._play_context.remote_addr)
             if self._ssh_shell:
                 display.debug("firing event: on_close_shell()")
                 self._terminal.on_close_shell()

lib/ansible/plugins/connection/paramiko_ssh.py

@@ -228,6 +228,7 @@ class Connection(ConnectionBase):
     ''' SSH based connections with Paramiko '''
 
     transport = 'paramiko'
+    _log_channel = None
 
     def _cache_key(self):
         return "%s__%s__" % (self._play_context.remote_addr, self._play_context.remote_user)
@@ -240,6 +241,10 @@ def _connect(self):
             self.ssh = SSH_CONNECTION_CACHE[cache_key] = self._connect_uncached()
         return self
 
+    def _set_log_channel(self, name):
+        '''Mimic paramiko.SSHClient.set_log_channel'''
+        self._log_channel = name
+
     def _parse_proxy_command(self, port=22):
         proxy_command = None
         # Parse ansible_ssh_common_args, specifically looking for ProxyCommand
@@ -297,6 +302,10 @@ def _connect_uncached(self):
 
         ssh = paramiko.SSHClient()
 
+        # override paramiko's default logger name
+        if self._log_channel is not None:
+            ssh.set_log_channel(self._log_channel)
+
         self.keyfile = os.path.expanduser("~/.ssh/known_hosts")
 
         if self.get_option('host_key_checking'):

lib/ansible/plugins/strategy/free.py

@@ -91,15 +91,15 @@ def run(self, iterator, play_context):
                 # peek at the next task for the host, to see if there's
                 # anything to do do for this host
                 (state, task) = iterator.get_next_task_for_host(host, peek=True)
-                display.debug("free host state: %s" % state)
-                display.debug("free host task: %s" % task)
+                display.debug("free host state: %s" % state, host=host_name)
+                display.debug("free host task: %s" % task, host=host_name)
                 if host_name not in self._tqm._unreachable_hosts and task:
 
                     # set the flag so the outer loop knows we've still found
                     # some work which needs to be done
                     work_to_do = True
 
-                    display.debug("this host has work to do")
+                    display.debug("this host has work to do", host=host_name)
 
                     # check to see if this host is blocked (still executing a previous task)
                     if host_name not in self._blocked_hosts or not self._blocked_hosts[host_name]:
@@ -114,19 +114,19 @@ def run(self, iterator, play_context):
                             # corresponding action plugin
                             action = None
 
-                        display.debug("getting variables")
+                        display.debug("getting variables", host=host_name)
                         task_vars = self._variable_manager.get_vars(play=iterator._play, host=host, task=task)
                         self.add_tqm_variables(task_vars, play=iterator._play)
                         templar = Templar(loader=self._loader, variables=task_vars)
-                        display.debug("done getting variables")
+                        display.debug("done getting variables", host=host_name)
 
                         try:
                             task.name = to_text(templar.template(task.name, fail_on_undefined=False), nonstring='empty')
-                            display.debug("done templating")
+                            display.debug("done templating", host=host_name)
                         except:
                             # just ignore any errors during task name templating,
                             # we don't care if it just shows the raw name
-                            display.debug("templating failed for some reason")
+                            display.debug("templating failed for some reason", host=host_name)
 
                         run_once = templar.template(task.run_once) or action and getattr(action, 'BYPASS_HOST_LOOP', False)
                         if run_once:
@@ -143,7 +143,7 @@ def run(self, iterator, play_context):
                             # If there is no metadata, the default behavior is to not allow duplicates,
                             # if there is metadata, check to see if the allow_duplicates flag was set to true
                             if task._role._metadata is None or task._role._metadata and not task._role._metadata.allow_duplicates:
-                                display.debug("'%s' skipped because role has already run" % task)
+                                display.debug("'%s' skipped because role has already run" % task, host=host_name)
                                 del self._blocked_hosts[host_name]
                                 continue
 

lib/ansible/utils/display.py

@@ -191,9 +191,12 @@ def vvvvv(self, msg, host=None):
     def vvvvvv(self, msg, host=None):
         return self.verbose(msg, host=host, caplevel=5)
 
-    def debug(self, msg):
+    def debug(self, msg, host=None):
         if C.DEFAULT_DEBUG:
-            self.display("%6d %0.5f: %s" % (os.getpid(), time.time(), msg), color=C.COLOR_DEBUG)
+            if host is None:
+                self.display("%6d %0.5f: %s" % (os.getpid(), time.time(), msg), color=C.COLOR_DEBUG)
+            else:
+                self.display("%6d %0.5f [%s]: %s" % (os.getpid(), time.time(), host, msg), color=C.COLOR_DEBUG)
 
     def verbose(self, msg, host=None, caplevel=2):
         if self.verbosity > caplevel: