Fix prompt mismatch issue for ios

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

@@ -656,3 +656,38 @@ Example Ansible inventory file
    This is done to prevent secrets from leaking out, for example in ``ps`` output.
 
    We recommend using SSH Keys, and if needed an ssh-agent, rather than passwords, where ever possible.
+
+Miscellaneous Issues
+====================
+
+
+Intermittent failure while using ``network_cli`` connection type
+----------------------------------------------------------------
+
+If the command prompt received in response is not matched correctly within
+the ``network_cli`` connection plugin the task might fail intermittently with truncated
+response or with the error message ``operation requires privilege escalation``.
+Starting in 2.7.1 a new buffer read timer is added to ensure prompts are matched properly
+and a complete response is send in output. The timer default value is 0.2 seconds and
+can be adjusted on a per task basis or can be set globally in seconds.
+
+Example Per task timer setting
+
+.. code-block:: yaml
+
+  - name: gather ios facts
+    ios_facts:
+      gather_subset: all
+    register: result
+    vars:
+      ansible_buffer_read_timeout: 2
+
+
+To make this a global setting, add the following to your ``ansible.cfg`` file:
+
+.. code-block:: ini
+
+   [persistent_connection]
+   buffer_read_timeout = 2
+
+This timer delay per command executed on remote host can be disabled by setting the value to zero.

lib/ansible/plugins/connection/network_cli.py

@@ -157,13 +157,29 @@
       - name: ANSIBLE_PERSISTENT_COMMAND_TIMEOUT
     vars:
       - name: ansible_command_timeout
+  persistent_buffer_read_timeout:
+    type: float
+    description:
+      - Configures, in seconds, the amount of time to wait for the data to be read
+        from Paramiko channel after the command prompt is matched. This timeout
+        value ensures that command prompt matched is correct and there is no more data
+        left to be received from remote host.
+    default: 0.1
+    ini:
+      - section: persistent_connection
+        key: buffer_read_timeout
+    env:
+      - name: ANSIBLE_PERSISTENT_BUFFER_READ_TIMEOUT
+    vars:
+      - name: ansible_buffer_read_timeout
 """
 
 import getpass
 import json
 import logging
 import re
 import os
+import signal
 import socket
 import traceback
 from io import BytesIO
@@ -184,6 +200,10 @@
     display = Display()
 
 
+class AnsibleCmdRespRecv(Exception):
+    pass
+
+
 class Connection(NetworkConnectionBase):
     ''' CLI (shell) SSH connections on Paramiko '''
 
@@ -200,6 +220,7 @@ def __init__(self, play_context, new_stdin, *args, **kwargs):
         self._matched_pattern = None
         self._last_response = None
         self._history = list()
+        self._command_response = None
 
         self._terminal = None
         self.cliconf = None
@@ -342,15 +363,39 @@ def receive(self, command=None, prompts=None, answer=None, newline=True, prompt_
         '''
         Handles receiving of output from command
         '''
-        recv = BytesIO()
-        handled = False
-
         self._matched_prompt = None
         self._matched_cmd_prompt = None
+        recv = BytesIO()
+        handled = False
+        command_prompt_matched = False
         matched_prompt_window = window_count = 0
 
+        command_timeout = self.get_option('persistent_command_timeout')
+        self._validate_timeout_value(command_timeout, "persistent_command_timeout")
+
+        buffer_read_timeout = self.get_option('persistent_buffer_read_timeout')
+        self._validate_timeout_value(buffer_read_timeout, "persistent_buffer_read_timeout")
+
         while True:
-            data = self._ssh_shell.recv(256)
+            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)
+                    # if data is still received on channel it indicates the prompt string
+                    # is wrongly matched in between response chunks, continue to read
+                    # remaining response.
+                    command_prompt_matched = False
+
+                    # restart command_timeout timer
+                    signal.signal(signal.SIGALRM, self._handle_command_timeout)
+                    signal.alarm(command_timeout)
+
+                except AnsibleCmdRespRecv:
+                    return self._command_response
+            else:
+                data = self._ssh_shell.recv(256)
 
             # when a channel stream is closed, received data will be empty
             if not data:
@@ -376,7 +421,11 @@ def receive(self, command=None, prompts=None, answer=None, newline=True, prompt_
             if self._find_prompt(window):
                 self._last_response = recv.getvalue()
                 resp = self._strip(self._last_response)
-                return self._sanitize(resp, command)
+                self._command_response = self._sanitize(resp, command)
+                if buffer_read_timeout == 0.0:
+                    return self._command_response
+                else:
+                    command_prompt_matched = True
 
     def send(self, command, prompt=None, answer=None, newline=True, sendonly=False, prompt_retry_check=False, check_all=False):
         '''
@@ -398,6 +447,17 @@ def send(self, command, prompt=None, answer=None, newline=True, sendonly=False,
             display.vvvv(traceback.format_exc(), host=self._play_context.remote_addr)
             raise AnsibleConnectionFailure("timeout trying to send command: %s" % command.strip())
 
+    def _handle_buffer_read_timeout(self, signum, frame):
+        display.vvvv("Response received, triggered 'persistent_buffer_read_timeout' timer of %s seconds"
+                     % self.get_option('persistent_buffer_read_timeout'), host=self._play_context.remote_addr)
+        raise AnsibleCmdRespRecv()
+
+    def _handle_command_timeout(self, signum, frame):
+        msg = 'command timeout triggered, timeout value is %s secs.\nSee the timeout setting options in the Network Debug and Troubleshooting Guide.'\
+              % self.get_option('persistent_command_timeout')
+        display.display(msg, log_only=True)
+        raise AnsibleConnectionFailure(msg)
+
     def _strip(self, data):
         '''
         Removes ANSI codes from device response
@@ -488,3 +548,7 @@ def _find_prompt(self, response):
             raise AnsibleConnectionFailure(errored_response)
 
         return False
+
+    def _validate_timeout_value(self, timeout, timer_name):
+        if timeout < 0:
+            raise AnsibleConnectionFailure("'%s' timer value '%s' is invalid, value should be greater than or equal to zero." % (timer_name, timeout))

test/units/plugins/connection/test_network_cli.py

@@ -21,13 +21,15 @@
 __metaclass__ = type
 
 import re
+import time
 import json
 
 from io import StringIO
 
 from units.compat import unittest
 from units.compat.mock import patch, MagicMock
 
+from ansible.module_utils._text import to_text
 from ansible.errors import AnsibleConnectionFailure
 from ansible.playbook.play_context import PlayContext
 from ansible.plugins.loader import connection_loader
@@ -131,15 +133,14 @@ def test_network_cli_send(self):
         device#
         """
 
-        mock__shell.recv.return_value = response
-
+        mock__shell.recv.side_effect = [response, None]
         output = conn.send(b'command', None, None, None)
 
         mock__shell.sendall.assert_called_with(b'command\r')
-        self.assertEqual(output, 'command response')
+        self.assertEqual(to_text(conn._command_response), 'command response')
 
         mock__shell.reset_mock()
-        mock__shell.recv.return_value = b"ERROR: error message device#"
+        mock__shell.recv.side_effect = [b"ERROR: error message device#"]
 
         with self.assertRaises(AnsibleConnectionFailure) as exc:
             conn.send(b'command', None, None, None)