adds more logging output to network_cli and ansible-connection (#21716)

2 files changed, 23 insertions, 8 deletions

diff --git a/bin/ansible-connection b/bin/ansible-connection
index c0b159dfc3..cca24df7a2 100755
--- a/bin/ansible-connection
+++ b/bin/ansible-connection
@@ -112,12 +112,14 @@ def recv_data(s):
 class Server():
 
     def __init__(self, path, play_context):
+        display.vvvv("starting new persistent socket with path %s" % path, play_context.remote_addr)
+
         self.path = path
         self.play_context = play_context
 
         self._start_time = datetime.datetime.now()
 
-        display.vvv("using connection %s" % self.play_context.connection, play_context.remote_addr)
+        display.vvv("using connection plugin %s" % self.play_context.connection, play_context.remote_addr)
 
         self.conn = connection_loader.get(play_context.connection, play_context, sys.stdin)
         self.conn._connect()
@@ -160,6 +162,7 @@ class Server():
                 signal.alarm(C.PERSISTENT_CONNECT_TIMEOUT)
                 try:
                     (s, addr) = self.socket.accept()
+                    display.vvvv('incoming request accepted on persistent socket', self.play_context.remote_addr)
                     # clear the alarm
                     # FIXME: potential race condition here between the accept and
                     #        time to this call.
@@ -171,12 +174,14 @@ class Server():
                     data = recv_data(s)
                     if not data:
                         break
+                    display.vvvv("received data on socket with len %s" % len(data), self.play_context.remote_addr)
 
                     signal.alarm(C.DEFAULT_TIMEOUT)
 
                     rc = 255
                     try:
                         if data.startswith(b'EXEC: '):
+                            display.vvvv("socket operation is EXEC", self.play_context.remote_addr)
                             cmd = data.split(b'EXEC: ')[1]
                             (rc, stdout, stderr) = self.conn.exec_command(cmd)
                         elif data.startswith(b'PUT: ') or data.startswith(b'FETCH: '):
@@ -184,13 +189,16 @@ class Server():
                             stdout = stderr = ''
                             try:
                                 if op == 'FETCH:':
+                                    display.vvvv("socket operation is FETCH", self.play_context.remote_addr)
                                     self.conn.fetch_file(src, dst)
                                 elif op == 'PUT:':
+                                    display.vvvv("socket operation is PUT", self.play_context.remote_addr)
                                     self.conn.put_file(src, dst)
                                 rc = 0
                             except:
                                 pass
                         elif data.startswith(b'CONTEXT: '):
+                            display.vvvv("socket operation is CONTEXT", self.play_context.remote_addr)
                             pc_data = data.split(b'CONTEXT: ')[1]
 
                             src = StringIO(pc_data)
@@ -203,6 +211,7 @@ class Server():
                             self.dispatch(self.conn, 'update_play_context', pc)
                             continue
                         else:
+                            display.vvvv("socket operation is UNKNOWN", self.play_context.remote_addr)
                             stdout = ''
                             stderr = 'Invalid action specified'
                     except:
@@ -211,12 +220,14 @@ class Server():
 
                     signal.alarm(0)
 
+                    display.vvvv("socket operation completed with rc %s" % rc, self.play_context.remote_addr)
+
                     send_data(s, to_bytes(str(rc)))
                     send_data(s, to_bytes(stdout))
                     send_data(s, to_bytes(stderr))
                 s.close()
         except Exception as e:
-            display.debug(traceback.format_exc())
+            display.vvvv(traceback.format_exc())
         finally:
             # when done, close the connection properly and cleanup
             # the socket file so it can be recreated
diff --git a/lib/ansible/plugins/connection/network_cli.py b/lib/ansible/plugins/connection/network_cli.py
index 8cd5f3d889..0724e25026 100644
--- a/lib/ansible/plugins/connection/network_cli.py
+++ b/lib/ansible/plugins/connection/network_cli.py
@@ -56,6 +56,8 @@ class Connection(_Connection):
 
     def update_play_context(self, play_context):
         """Updates the play context information for the connection"""
+        display.vvvv('updating play_context for connection', self._play_context.remote_addr)
+
         if self._play_context.become is False and play_context.become is True:
             auth_pass = play_context.become_pass
             self._terminal.on_authorize(passwd=auth_pass)
@@ -69,8 +71,7 @@ class Connection(_Connection):
         """Connections to the device and sets the terminal type"""
         super(Connection, self)._connect()
 
-        display.debug('starting network_cli._connect()')
-        display.vvvv('starting network_cli._connect()')
+        display.vvvv('ssh connection done, setting terminal', self._play_context.remote_addr)
 
         network_os = self._play_context.network_os
         if not network_os:
@@ -84,9 +85,11 @@ class Connection(_Connection):
             raise AnsibleConnectionFailure('network os %s is not supported' % network_os)
 
         self._connected = True
+        display.vvvv('ssh connection has completed successfully', self._play_context.remote_addr)
 
     @ensure_connect
     def open_shell(self):
+        display.vvvv('attempting to open shell to device', self._play_context.remote_addr)
         self._shell = self.ssh.invoke_shell()
         self._shell.settimeout(self._play_context.timeout)
 
@@ -99,16 +102,18 @@ class Connection(_Connection):
             auth_pass = self._play_context.become_pass
             self._terminal.on_authorize(passwd=auth_pass)
 
+        display.vvvv('shell successfully opened', self._play_context.remote_addr)
         return (0, 'ok', '')
 
     def close(self):
-        display.vvv('closing connection', host=self._play_context.remote_addr)
+        display.vvvv('closing connection', self._play_context.remote_addr)
         self.close_shell()
         super(Connection, self).close()
         self._connected = False
 
     def close_shell(self):
         """Closes the vty shell if the device supports multiplexing"""
+        display.vvvv('closing shell on device', self._play_context.remote_addr)
         if self._shell:
             self._terminal.on_close_shell()
 
@@ -204,7 +209,7 @@ class Connection(_Connection):
 
     def alarm_handler(self, signum, frame):
         """Alarm handler raised in case of command timeout """
-        display.debug('alarm_handler fired!')
+        display.vvvv('closing shell due to sigalarm', self._play_context.remote_addr)
         self.close_shell()
 
     def exec_command(self, cmd):
@@ -217,7 +222,7 @@ class Connection(_Connection):
         Keywords supported for cmd:
             * command - the command string to execute
             * prompt - the expected prompt generated by executing command
-            * response - the string to respond to the prompt with
+            * answer - the string to respond to the prompt with
             * sendonly - bool to disable waiting for response
 
         :arg cmd: the string that represents the command to be executed
@@ -225,7 +230,6 @@ class Connection(_Connection):
         :returns: a tuple of (return code, stdout, stderr).  The return
             code is an integer and stdout and stderr are strings
         """
-        display.vvv('cmd: %s' % cmd)
         try:
             obj = json.loads(cmd)
         except (ValueError, TypeError):