From c093d14697786f257b75186cf0a8f2fda96cc714 Mon Sep 17 00:00:00 2001 From: Peter Sprygada Date: Mon, 20 Mar 2017 19:26:18 -0700 Subject: [PATCH] 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 ed7cace425ddff33c0cc4ee4b0dfff3c1c78529f) --- bin/ansible-connection | 48 +++++++++++-------- lib/ansible/plugins/connection/netconf.py | 21 +++++--- lib/ansible/plugins/connection/network_cli.py | 37 +++++++------- 3 files changed, 61 insertions(+), 45 deletions(-) diff --git a/bin/ansible-connection b/bin/ansible-connection index 9c053e0531a..a86cfec0746 100755 --- a/bin/ansible-connection +++ b/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() diff --git a/lib/ansible/plugins/connection/netconf.py b/lib/ansible/plugins/connection/netconf.py index f3232529216..9ff5dd17bf3 100644 --- a/lib/ansible/plugins/connection/netconf.py +++ b/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, '') diff --git a/lib/ansible/plugins/connection/network_cli.py b/lib/ansible/plugins/connection/network_cli.py index 0bb9ee00ed6..d3d95035f70 100644 --- a/lib/ansible/plugins/connection/network_cli.py +++ b/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)