implements python logging for network connection plugin (#22817)

* enables logging for network_cli and paramiko
* enables logging for ansible-connection
* enabled logging for netconf connection
(cherry picked from commit ed7cace425)

bin/ansible-connection

@@ -39,6 +39,7 @@ import time
 import traceback
 import syslog
 import datetime
+import logging
 
 from io import BytesIO
 
@@ -49,8 +50,8 @@ from ansible.playbook.play_context import PlayContext
 from ansible.plugins import connection_loader
 from ansible.utils.path import unfrackpath, makedirs_safe
 from ansible.errors import AnsibleConnectionFailure
-from ansible.utils.display import Display
 
+logger = logging.getLogger('ansible-connection')
 
 def do_fork():
     '''
@@ -109,17 +110,24 @@ def recv_data(s):
         data += d
     return data
 
+def log(msg, host, user=None):
+    msg = 'h=%s u=%s %s' % (host, user, msg)
+    logger.debug(msg)
+
+
 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.log = lambda x: log(x, play_context.remote_addr, play_context.remote_user)
+
+        self.log("starting new persistent socket with path %s" % path)
 
         self._start_time = datetime.datetime.now()
 
-        display.vvv("using connection plugin %s" % self.play_context.connection, play_context.remote_addr)
+        self.log("using connection plugin %s" % self.play_context.connection)
 
         self.conn = connection_loader.get(play_context.connection, play_context, sys.stdin)
         self.conn._connect()
@@ -127,7 +135,7 @@ class Server():
             raise AnsibleConnectionFailure('unable to connect to remote host')
 
         connection_time = datetime.datetime.now() - self._start_time
-        display.vvvv('connection established in %s' % connection_time, play_context.remote_addr)
+        self.log('connection established in %s' % connection_time)
 
         self.socket = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM)
         self.socket.bind(path)
@@ -165,7 +173,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)
+                    self.log('incoming request accepted on persistent socket')
                     # clear the alarm
                     # FIXME: potential race condition here between the accept and
                     #        time to this call.
@@ -177,14 +185,13 @@ 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)
+                            self.log("socket operation is EXEC")
                             cmd = data.split(b'EXEC: ')[1]
                             (rc, stdout, stderr) = self.conn.exec_command(cmd)
                         elif data.startswith(b'PUT: ') or data.startswith(b'FETCH: '):
@@ -192,16 +199,16 @@ class Server():
                             stdout = stderr = ''
                             try:
                                 if op == 'FETCH:':
-                                    display.vvvv("socket operation is FETCH", self.play_context.remote_addr)
+                                    self.log("socket operation is FETCH")
                                     self.conn.fetch_file(src, dst)
                                 elif op == 'PUT:':
-                                    display.vvvv("socket operation is PUT", self.play_context.remote_addr)
+                                    self.log("socket operation is PUT")
                                     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)
+                            self.log("socket operation is CONTEXT")
                             pc_data = data.split(b'CONTEXT: ')[1]
 
                             src = StringIO(pc_data)
@@ -214,7 +221,7 @@ class Server():
                             self.dispatch(self.conn, 'update_play_context', pc)
                             continue
                         else:
-                            display.vvvv("socket operation is UNKNOWN", self.play_context.remote_addr)
+                            self.log("socket operation is UNKNOWN")
                             stdout = ''
                             stderr = 'Invalid action specified'
                     except:
@@ -223,20 +230,20 @@ class Server():
 
                     signal.alarm(0)
 
-                    display.vvvv("socket operation completed with rc %s" % rc, self.play_context.remote_addr)
+                    self.log("socket operation completed with rc %s" % rc)
 
                     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.vvvv(traceback.format_exc())
+            self.log(traceback.foramt_exec())
         finally:
             # when done, close the connection properly and cleanup
             # the socket file so it can be recreated
             end_time = datetime.datetime.now()
             delta = end_time - self._start_time
-            display.v('shutting down control socket, connection was active for %s secs' % delta, self.play_context.remote_addr)
+            self.log('shutting down control socket, connection was active for %s secs' % delta)
             try:
                 self.conn.close()
                 self.socket.close()
@@ -268,8 +275,6 @@ def main():
         sys.stderr.write(traceback.format_exc())
         sys.exit("FAIL: %s" % e)
 
-    display.verbosity = pc.verbosity
-
     ssh = connection_loader.get('ssh', class_only=True)
     m = ssh._create_control_path(pc.remote_addr, pc.port, pc.remote_user)
 
@@ -290,16 +295,18 @@ def main():
             try:
                 server = Server(sf_path, pc)
             except AnsibleConnectionFailure as exc:
-                display.vvv(str(exc), pc.remote_addr)
+                log(str(exc), pc.remote_addr, pc.remote_user)
                 rc = 1
             except Exception as exc:
-                display.vvv(traceback.format_exc(), pc.remote_addr)
+                log(traceback.format_exc(), pc.remote_addr, pc.remote_user)
                 rc = 1
             fcntl.lockf(lock_fd, fcntl.LOCK_UN)
             os.close(lock_fd)
             if rc == 0:
                 server.run()
             sys.exit(rc)
+    else:
+        log('re-using existing socket connection', pc.remote_addr, pc.remote_user)
     fcntl.lockf(lock_fd, fcntl.LOCK_UN)
     os.close(lock_fd)
 
@@ -324,8 +331,8 @@ def main():
                 time.sleep(C.PERSISTENT_CONNECT_INTERVAL)
                 attempts += 1
                 if attempts > C.PERSISTENT_CONNECT_RETRIES:
-                    display.vvvv('number of connection attempts exceeded, unable to connect to control socket')
-                    display.vvvv('persistent_connect_interval=%s, persistent_connect_retries=%s' % (C.PERSISTENT_CONNECT_INTERVAL, C.PERSISTENT_CONNECT_RETRIES))
+                    log('number of connection attempts exceeded, unable to connect to control socket', pc.remote_addr, pc.remote_user)
+                    log('persistent_connect_interval=%s, persistent_connect_retries=%s' % (C.PERSISTENT_CONNECT_INTERVAL, C.PERSISTENT_CONNECT_RETRIES), pc.remote_addr, pc.remote_user)
                     sys.stderr.write('failed to connect to control socket')
                     sys.exit(255)
 
@@ -350,5 +357,4 @@ def main():
     sys.exit(rc)
 
 if __name__ == '__main__':
-    display = Display()
     main()

lib/ansible/plugins/connection/netconf.py

@@ -23,6 +23,7 @@ import re
 import socket
 import json
 import signal
+import logging
 
 from ansible import constants as C
 from ansible.errors import AnsibleConnectionFailure, AnsibleError
@@ -37,11 +38,8 @@ try:
 except ImportError:
     raise AnsibleError("ncclient is not installed")
 
-try:
-    from __main__ import display
-except ImportError:
-    from ansible.utils.display import Display
-    display = Display()
+logger = logging.getLogger('ansible.netconf')
+logging.getLogger('ncclient').setLevel(logging.INFO)
 
 class Connection(ConnectionBase):
     ''' NetConf connections '''
@@ -53,14 +51,20 @@ class Connection(ConnectionBase):
         super(Connection, self).__init__(play_context, new_stdin, *args, **kwargs)
 
         self._network_os = self._play_context.network_os or 'default'
-        display.vvv('network_os is set to %s' % self._network_os, play_context.remote_addr)
+        self.log('network_os is set to %s' % self._network_os)
 
         self._manager = None
         self._connected = False
 
+    def log(self, msg):
+        msg = 'h=%s u=%s %s' % (self._play_context.remote_addr, self._play_context.remote_user, msg)
+        logger.debug(msg)
+
     def _connect(self):
         super(Connection, self)._connect()
 
+        self.log('ssh connection done, stating ncclient')
+
         allow_agent = True
         if self._play_context.password is not None:
             allow_agent = False
@@ -69,6 +73,9 @@ class Connection(ConnectionBase):
         if self._play_context.private_key_file:
             key_filename = os.path.expanduser(self._play_context.private_key_file)
 
+        if not self._network_os:
+            raise AnsibleConnectionError('network_os must be set for netconf connections')
+
         try:
             self._manager = manager.connect(
                 host=self._play_context.remote_addr,
@@ -88,6 +95,8 @@ class Connection(ConnectionBase):
         if not self._manager.connected:
             return (1, '', 'not connected')
 
+        self.log('ncclient manager object created successfully')
+
         self._connected = True
         return (0, self._manager.session_id, '')
 

lib/ansible/plugins/connection/network_cli.py

@@ -24,6 +24,7 @@ import json
 import signal
 import datetime
 import traceback
+import logging
 
 from ansible.errors import AnsibleConnectionFailure
 from ansible.module_utils.six.moves import StringIO
@@ -31,12 +32,7 @@ from ansible.plugins import terminal_loader
 from ansible.plugins.connection import ensure_connect
 from ansible.plugins.connection.paramiko_ssh import Connection as _Connection
 
-try:
-    from __main__ import display
-except ImportError:
-    from ansible.utils.display import Display
-    display = Display()
-
+logger = logging.getLogger('ansible.network_cli')
 
 class Connection(_Connection):
     ''' CLI (shell) SSH connections on Paramiko '''
@@ -54,9 +50,17 @@ class Connection(_Connection):
         self._last_response = None
         self._history = list()
 
+        if play_context.verbosity > 3:
+            logging.getLogger('paramiko').setLevel(logging.DEBUG)
+
+    def log(self, msg):
+        msg = 'h=%s u=%s %s' % (self._play_context.remote_addr, self._play_context.remote_user, msg)
+        logger.debug(msg)
+
     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)
+
+        self.log('updating play_context for connection')
 
         if self._play_context.become is False and play_context.become is True:
             auth_pass = play_context.become_pass
@@ -71,7 +75,7 @@ class Connection(_Connection):
         """Connections to the device and sets the terminal type"""
         super(Connection, self)._connect()
 
-        display.vvvv('ssh connection done, setting terminal', self._play_context.remote_addr)
+        self.log('ssh connection done, setting terminal')
 
         network_os = self._play_context.network_os
         if not network_os:
@@ -85,11 +89,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)
+        self.log('ssh connection has completed successfully')
 
     @ensure_connect
     def open_shell(self):
-        display.vvvv('attempting to open shell to device', self._play_context.remote_addr)
+        self.log('attempting to open shell to device')
         self._shell = self.ssh.invoke_shell()
         self._shell.settimeout(self._play_context.timeout)
 
@@ -102,18 +106,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)
+        self.log('shell successfully opened')
         return (0, 'ok', '')
 
     def close(self):
-        display.vvvv('closing connection', self._play_context.remote_addr)
+        self.log('closing connection')
         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)
+        self.log('closing shell on device')
         if self._shell:
             self._terminal.on_close_shell()
 
@@ -157,7 +161,7 @@ class Connection(_Connection):
                 return
             return self.receive(obj)
         except (socket.timeout, AttributeError) as exc:
-            display.vvv(traceback.format_exc())
+            self.log(traceback.format_exc())
             raise AnsibleConnectionFailure("timeout trying to send command: %s" % command.strip())
 
     def _strip(self, data):
@@ -209,7 +213,7 @@ class Connection(_Connection):
 
     def alarm_handler(self, signum, frame):
         """Alarm handler raised in case of command timeout """
-        display.vvvv('closing shell due to sigalarm', self._play_context.remote_addr)
+        self.log('closing shell due to sigalarm')
         self.close_shell()
 
     def exec_command(self, cmd):
@@ -241,8 +245,6 @@ class Connection(_Connection):
             return self.open_shell()
         elif obj['command'] == 'prompt()':
             return (0, self._matched_prompt, '')
-        elif obj['command'] == 'history()':
-            return (0, self._history, '')
 
         try:
             if self._shell is None:
@@ -252,7 +254,6 @@ class Connection(_Connection):
 
         try:
             if not signal.getsignal(signal.SIGALRM):
-                display.debug('setting alarm handler in network_cli')
                 signal.signal(signal.SIGALRM, self.alarm_handler)
             signal.alarm(self._play_context.timeout)
             out = self.send(obj)