Log device interaction and push labeled logs back to controller (ansi…

…ble#50028)

* Add session tracing support for network_cli, netconf and httapi connection

*  Add `persistent_log_messages` configuration option to log device inteaction
   in log file for network_cli, netconf and httapi connection
   type
*  Log jsonrpc request and response in log file is configuration option
   is enabled

* Update docs to talk about warning shown when persistent_log_messages is on

bin/ansible-connection

@@ -131,17 +131,18 @@ class ConnectionProcess(object):
                 self.exception = None
                 (s, addr) = self.sock.accept()
                 signal.alarm(0)
-
                 signal.signal(signal.SIGALRM, self.command_timeout)
                 while True:
                     data = recv_data(s)
                     if not data:
                         break
+                    self.connection._log_messages("jsonrpc request: %s" % data)
 
                     signal.alarm(self.connection.get_option('persistent_command_timeout'))
                     resp = self.srv.handle_request(data)
                     signal.alarm(0)
 
+                    self.connection._log_messages("jsonrpc response: %s" % resp)
                     send_data(s, to_bytes(resp))
 
                 s.close()

docs/docsite/rst/network/user_guide/network_debug_troubleshooting.rst

@@ -99,6 +99,64 @@ Because the log files are verbose, you can use grep to look for specific informa
 
   grep "p=28990" $ANSIBLE_LOG_PATH
 
+
+Enabling Networking device interaction logging
+----------------------------------------------
+
+**Platforms:** Any
+
+Ansible 2.8 features added logging of device interaction in log file to help diagnose and troubleshoot
+issues regarding Ansible Networking modules. The messages are logged in file pointed by ``log_path`` configuration
+option in Ansible configuration file or by set :envvar:`ANSIBLE_LOG_PATH` as mentioned in above section.
+
+.. warning::
+  The device interaction messages consist of command executed on target device and the returned response, as this
+  log data can contain sensitive information including passwords in plain text it is disabled by default.
+  Additionally, in order to prevent accidental leakage of data, a warning will be shown on every task with this
+  setting eneabled specifying which host has it enabled and where the data is being logged.
+
+Be sure to fully understand the security implications of enabling this option. The device interaction logging can be enabled either globally by setting in configuration file or by setting environment or enabled on per task basis by passing special variable to task.
+
+Before running ``ansible-playbook`` run the following commands to enable logging::
+
+   # Specify the location for the log file
+   export ANSIBLE_LOG_PATH=~/ansible.log
+
+
+Enable device interaction logging for a given task
+
+.. code-block:: yaml
+
+  - name: get version information
+    ios_command:
+      commands:
+        - show version
+    vars:
+      ansible_persistent_log_messages: True
+
+
+To make this a global setting, add the following to your ``ansible.cfg`` file:
+
+.. code-block:: ini
+
+   [persistent_connection]
+   log_messages = True
+
+or enable environment variable `ANSIBLE_PERSISTENT_LOG_MESSAGES`
+
+   # Enable device interaction logging
+   export ANSIBLE_PERSISTENT_LOG_MESSAGES=True
+
+If the task is failing at the time on connection initialization itself it is recommended to enable this option
+globally else if an individual task is failing intermittently this option can be enabled for that task itself to
+find the root cause.
+
+After Ansible has finished running you can inspect the log file which has been created on the ansible-controller
+
+.. note:: Be sure to fully understand the security implications of enabling this option as it can log sensitive
+          information in log file thus creating security vulnerability.
+
+
 Isolating an error
 ------------------
 

lib/ansible/plugins/connection/__init__.py

@@ -357,6 +357,12 @@ def close(self):
 
     def set_options(self, task_keys=None, var_options=None, direct=None):
         super(NetworkConnectionBase, self).set_options(task_keys=task_keys, var_options=var_options, direct=direct)
+        if self.get_option('persistent_log_messages'):
+            warning = "Persistent connection logging is enabled for %s. This will log ALL interactions" % self._play_context.remote_addr
+            logpath = getattr(C, 'DEFAULT_LOG_PATH')
+            if logpath is not None:
+                warning += " to %s" % logpath
+            self.queue_message('warning', "%s and WILL NOT redact sensitive configuration like passwords. USE WITH CAUTION!" % warning)
 
         if self._sub_plugin.get('obj') and self._sub_plugin.get('type') != 'external':
             try:
@@ -386,3 +392,7 @@ def _update_connection_state(self):
         if os.path.exists(socket_path):
             self._connected = True
             self._socket_path = socket_path
+
+    def _log_messages(self, message):
+        if self.get_option('persistent_log_messages'):
+            self.queue_message('log', message)

lib/ansible/plugins/connection/httpapi.py

@@ -143,6 +143,22 @@
       - name: ANSIBLE_PERSISTENT_COMMAND_TIMEOUT
     vars:
       - name: ansible_command_timeout
+  persistent_log_messages:
+    type: boolean
+    description:
+      - This flag will enable logging the command executed and response received from
+        target device in the ansible log file. For this option to work 'log_path' ansible
+        configuration option is required to be set to a file path with write access.
+      - Be sure to fully understand the security implications of enabling this
+        option as it could create a security vulnerability by logging sensitive information in log file.
+    default: False
+    ini:
+      - section: persistent_connection
+        key: log_messages
+    env:
+      - name: ANSIBLE_PERSISTENT_LOG_MESSAGES
+    vars:
+      - name: ansible_persistent_log_messages
 """
 
 from io import BytesIO
@@ -248,7 +264,9 @@ def send(self, path, data, **kwargs):
             url_kwargs['url_password'] = self.get_option('password')
 
         try:
-            response = open_url(self._url + path, data=data, **url_kwargs)
+            url = self._url + path
+            self._log_messages("send url '%s' with data '%s' and kwargs '%s'" % (url, data, url_kwargs))
+            response = open_url(url, data=data, **url_kwargs)
         except HTTPError as exc:
             is_handled = self.handle_httperror(exc)
             if is_handled is True:
@@ -261,7 +279,9 @@ def send(self, path, data, **kwargs):
             raise AnsibleConnectionFailure('Could not connect to {0}: {1}'.format(self._url + path, exc.reason))
 
         response_buffer = BytesIO()
-        response_buffer.write(response.read())
+        resp_data = response.read()
+        self._log_messages("received response: '%s'" % resp_data)
+        response_buffer.write(resp_data)
 
         # Try to assign a new auth token if one is given
         self._auth = self.update_auth(response, response_buffer) or self._auth

lib/ansible/plugins/connection/netconf.py

@@ -170,6 +170,22 @@
     vars:
       - name: ansible_netconf_ssh_config
         version_added: '2.7'
+  persistent_log_messages:
+    type: boolean
+    description:
+      - This flag will enable logging the command executed and response received from
+        target device in the ansible log file. For this option to work 'log_path' ansible
+        configuration option is required to be set to a file path with write access.
+      - Be sure to fully understand the security implications of enabling this
+        option as it could create a security vulnerability by logging sensitive information in log file.
+    default: False
+    ini:
+      - section: persistent_connection
+        key: log_messages
+    env:
+      - name: ANSIBLE_PERSISTENT_LOG_MESSAGES
+    vars:
+      - name: ansible_persistent_log_messages
 """
 
 import os

lib/ansible/plugins/connection/network_cli.py

@@ -172,6 +172,22 @@
       - name: ANSIBLE_PERSISTENT_BUFFER_READ_TIMEOUT
     vars:
       - name: ansible_buffer_read_timeout
+  persistent_log_messages:
+    type: boolean
+    description:
+      - This flag will enable logging the command executed and response received from
+        target device in the ansible log file. For this option to work 'log_path' ansible
+        configuration option is required to be set to a file path with write access.
+      - Be sure to fully understand the security implications of enabling this
+        option as it could create a security vulnerability by logging sensitive information in log file.
+    default: False
+    ini:
+      - section: persistent_connection
+        key: log_messages
+    env:
+      - name: ANSIBLE_PERSISTENT_LOG_MESSAGES
+    vars:
+      - name: ansible_persistent_log_messages
 """
 
 import getpass
@@ -374,13 +390,15 @@ def receive(self, command=None, prompts=None, answer=None, newline=True, prompt_
         buffer_read_timeout = self.get_option('persistent_buffer_read_timeout')
         self._validate_timeout_value(buffer_read_timeout, "persistent_buffer_read_timeout")
 
+        self._log_messages("command: %s" % command)
         while True:
             if command_prompt_matched:
                 try:
                     signal.signal(signal.SIGALRM, self._handle_buffer_read_timeout)
                     signal.setitimer(signal.ITIMER_REAL, buffer_read_timeout)
                     data = self._ssh_shell.recv(256)
                     signal.alarm(0)
+                    self._log_messages("response-%s: %s" % (window_count + 1, data))
                     # if data is still received on channel it indicates the prompt string
                     # is wrongly matched in between response chunks, continue to read
                     # remaining response.
@@ -396,7 +414,7 @@ def receive(self, command=None, prompts=None, answer=None, newline=True, prompt_
                     return self._command_response
             else:
                 data = self._ssh_shell.recv(256)
-
+                self._log_messages("response-%s: %s" % (window_count + 1, data))
             # when a channel stream is closed, received data will be empty
             if not data:
                 break
@@ -493,14 +511,18 @@ def _handle_prompt(self, resp, prompts, answer, newline, prompt_retry_check=Fals
         for index, regex in enumerate(prompts_regex):
             match = regex.search(resp)
             if match:
+                self._matched_cmd_prompt = match.group()
+                self._log_messages("matched command prompt: %s" % self._matched_cmd_prompt)
+
                 # if prompt_retry_check is enabled to check if same prompt is
                 # repeated don't send answer again.
                 if not prompt_retry_check:
                     prompt_answer = answer[index] if len(answer) > index else answer[0]
                     self._ssh_shell.sendall(b'%s' % prompt_answer)
                     if newline:
                         self._ssh_shell.sendall(b'\r')
-                self._matched_cmd_prompt = match.group()
+                        prompt_answer += '\r'
+                    self._log_messages("matched command prompt answer: %s" % self.prompt_answer)
                 if check_all and prompts and not single_prompt:
                     prompts.pop(0)
                     answer.pop(0)
@@ -536,6 +558,7 @@ def _find_prompt(self, response):
                         errored_response = response
                         self._matched_pattern = regex.pattern
                         self._matched_prompt = match.group()
+                        self._log_messages("matched error regex '%s' from response '%s'" % (self._matched_pattern, errored_response))
                         break
 
         if not is_error_message:
@@ -544,6 +567,7 @@ def _find_prompt(self, response):
                 if match:
                     self._matched_pattern = regex.pattern
                     self._matched_prompt = match.group()
+                    self._log_messages("matched cli prompt '%s' with regex '%s' from response '%s'" % (self._matched_prompt, self._matched_pattern, response))
                     if not errored_response:
                         return True