Browse code

Fix prompt mismatch issue for ios (#47004)

* Fix prompt mismatch issue for ios

Fixes #40884 #44463 #46082

* If the command prompt is matched check if data is
still pending to be read from buffer.
* This fix adds a new timer `buffer_read_timeout`
which will be trigerred after command prompt
is matched and data is attempted to be read from channel.
If not data is present of channel the timer will expire
and response we be returned to calling function.

* Update doc

* Fix review comments

* Update changelog

* Fix unit test CI failure

(cherry picked from commit 335a979f1d30d065504bf9222460f35356a2e0b6)

Ganesh Nalawade authored on 2018/10/23 00:35:15
Showing 4 changed files
1 1
new file mode 100644
... ...
@@ -0,0 +1,2 @@
0
+bugfixes:
1
+- Fix prompt mismatch issue for ios (https://github.com/ansible/ansible/issues/47004)
... ...
@@ -656,3 +656,38 @@ Example Ansible inventory file
656 656
    This is done to prevent secrets from leaking out, for example in ``ps`` output.
657 657
 
658 658
    We recommend using SSH Keys, and if needed an ssh-agent, rather than passwords, where ever possible.
659
+
660
+Miscellaneous Issues
661
+====================
662
+
663
+
664
+Intermittent failure while using ``network_cli`` connection type
665
+----------------------------------------------------------------
666
+
667
+If the command prompt received in response is not matched correctly within
668
+the ``network_cli`` connection plugin the task might fail intermittently with truncated
669
+response or with the error message ``operation requires privilege escalation``.
670
+Starting in 2.7.1 a new buffer read timer is added to ensure prompts are matched properly
671
+and a complete response is send in output. The timer default value is 0.1 seconds and
672
+can be adjusted on a per task basis or can be set globally in seconds.
673
+
674
+Example Per task timer setting
675
+
676
+.. code-block:: yaml
677
+
678
+  - name: gather ios facts
679
+    ios_facts:
680
+      gather_subset: all
681
+    register: result
682
+    vars:
683
+      ansible_buffer_read_timeout: 2
684
+
685
+
686
+To make this a global setting, add the following to your ``ansible.cfg`` file:
687
+
688
+.. code-block:: ini
689
+
690
+   [persistent_connection]
691
+   buffer_read_timeout = 2
692
+
693
+This timer delay per command executed on remote host can be disabled by setting the value to zero.
... ...
@@ -157,6 +157,21 @@ options:
157 157
       - name: ANSIBLE_PERSISTENT_COMMAND_TIMEOUT
158 158
     vars:
159 159
       - name: ansible_command_timeout
160
+  persistent_buffer_read_timeout:
161
+    type: float
162
+    description:
163
+      - Configures, in seconds, the amount of time to wait for the data to be read
164
+        from Paramiko channel after the command prompt is matched. This timeout
165
+        value ensures that command prompt matched is correct and there is no more data
166
+        left to be received from remote host.
167
+    default: 0.1
168
+    ini:
169
+      - section: persistent_connection
170
+        key: buffer_read_timeout
171
+    env:
172
+      - name: ANSIBLE_PERSISTENT_BUFFER_READ_TIMEOUT
173
+    vars:
174
+      - name: ansible_buffer_read_timeout
160 175
 """
161 176
 
162 177
 import getpass
... ...
@@ -164,6 +179,7 @@ import json
164 164
 import logging
165 165
 import re
166 166
 import os
167
+import signal
167 168
 import socket
168 169
 import traceback
169 170
 
... ...
@@ -183,6 +199,10 @@ except ImportError:
183 183
     display = Display()
184 184
 
185 185
 
186
+class AnsibleCmdRespRecv(Exception):
187
+    pass
188
+
189
+
186 190
 class Connection(NetworkConnectionBase):
187 191
     ''' CLI (shell) SSH connections on Paramiko '''
188 192
 
... ...
@@ -199,6 +219,7 @@ class Connection(NetworkConnectionBase):
199 199
         self._matched_pattern = None
200 200
         self._last_response = None
201 201
         self._history = list()
202
+        self._command_response = None
202 203
 
203 204
         self._terminal = None
204 205
         self.cliconf = None
... ...
@@ -342,15 +363,39 @@ class Connection(NetworkConnectionBase):
342 342
         '''
343 343
         Handles receiving of output from command
344 344
         '''
345
-        recv = BytesIO()
346
-        handled = False
347
-
348 345
         self._matched_prompt = None
349 346
         self._matched_cmd_prompt = None
347
+        recv = BytesIO()
348
+        handled = False
349
+        command_prompt_matched = False
350 350
         matched_prompt_window = window_count = 0
351 351
 
352
+        command_timeout = self.get_option('persistent_command_timeout')
353
+        self._validate_timeout_value(command_timeout, "persistent_command_timeout")
354
+
355
+        buffer_read_timeout = self.get_option('persistent_buffer_read_timeout')
356
+        self._validate_timeout_value(buffer_read_timeout, "persistent_buffer_read_timeout")
357
+
352 358
         while True:
353
-            data = self._ssh_shell.recv(256)
359
+            if command_prompt_matched:
360
+                try:
361
+                    signal.signal(signal.SIGALRM, self._handle_buffer_read_timeout)
362
+                    signal.setitimer(signal.ITIMER_REAL, buffer_read_timeout)
363
+                    data = self._ssh_shell.recv(256)
364
+                    signal.alarm(0)
365
+                    # if data is still received on channel it indicates the prompt string
366
+                    # is wrongly matched in between response chunks, continue to read
367
+                    # remaining response.
368
+                    command_prompt_matched = False
369
+
370
+                    # restart command_timeout timer
371
+                    signal.signal(signal.SIGALRM, self._handle_command_timeout)
372
+                    signal.alarm(command_timeout)
373
+
374
+                except AnsibleCmdRespRecv:
375
+                    return self._command_response
376
+            else:
377
+                data = self._ssh_shell.recv(256)
354 378
 
355 379
             # when a channel stream is closed, received data will be empty
356 380
             if not data:
... ...
@@ -376,7 +421,11 @@ class Connection(NetworkConnectionBase):
376 376
             if self._find_prompt(window):
377 377
                 self._last_response = recv.getvalue()
378 378
                 resp = self._strip(self._last_response)
379
-                return self._sanitize(resp, command)
379
+                self._command_response = self._sanitize(resp, command)
380
+                if buffer_read_timeout == 0.0:
381
+                    return self._command_response
382
+                else:
383
+                    command_prompt_matched = True
380 384
 
381 385
     def send(self, command, prompt=None, answer=None, newline=True, sendonly=False, prompt_retry_check=False, check_all=False):
382 386
         '''
... ...
@@ -398,6 +447,17 @@ class Connection(NetworkConnectionBase):
398 398
             display.vvvv(traceback.format_exc(), host=self._play_context.remote_addr)
399 399
             raise AnsibleConnectionFailure("timeout trying to send command: %s" % command.strip())
400 400
 
401
+    def _handle_buffer_read_timeout(self, signum, frame):
402
+        display.vvvv("Response received, triggered 'persistent_buffer_read_timeout' timer of %s seconds"
403
+                     % self.get_option('persistent_buffer_read_timeout'), host=self._play_context.remote_addr)
404
+        raise AnsibleCmdRespRecv()
405
+
406
+    def _handle_command_timeout(self, signum, frame):
407
+        msg = 'command timeout triggered, timeout value is %s secs.\nSee the timeout setting options in the Network Debug and Troubleshooting Guide.'\
408
+              % self.get_option('persistent_command_timeout')
409
+        display.display(msg, log_only=True)
410
+        raise AnsibleConnectionFailure(msg)
411
+
401 412
     def _strip(self, data):
402 413
         '''
403 414
         Removes ANSI codes from device response
... ...
@@ -488,3 +548,7 @@ class Connection(NetworkConnectionBase):
488 488
             raise AnsibleConnectionFailure(errored_response)
489 489
 
490 490
         return False
491
+
492
+    def _validate_timeout_value(self, timeout, timer_name):
493
+        if timeout < 0:
494
+            raise AnsibleConnectionFailure("'%s' timer value '%s' is invalid, value should be greater than or equal to zero." % (timer_name, timeout))
... ...
@@ -21,6 +21,7 @@ from __future__ import (absolute_import, division, print_function)
21 21
 __metaclass__ = type
22 22
 
23 23
 import re
24
+import time
24 25
 import json
25 26
 
26 27
 from io import StringIO
... ...
@@ -28,6 +29,7 @@ from io import StringIO
28 28
 from ansible.compat.tests import unittest
29 29
 from ansible.compat.tests.mock import patch, MagicMock
30 30
 
31
+from ansible.module_utils._text import to_text
31 32
 from ansible.errors import AnsibleConnectionFailure
32 33
 from ansible.playbook.play_context import PlayContext
33 34
 from ansible.plugins.connection import network_cli
... ...
@@ -140,15 +142,18 @@ class TestConnectionClass(unittest.TestCase):
140 140
         device#
141 141
         """
142 142
 
143
-        mock__shell.recv.return_value = response
143
+        mock__shell.recv.side_effect = [response, None]
144
+
145
+        conn.get_option = MagicMock()
146
+        conn.get_option.return_value = 1
144 147
 
145 148
         output = conn.send(b'command', None, None, None)
146 149
 
147 150
         mock__shell.sendall.assert_called_with(b'command\r')
148
-        self.assertEqual(output, 'command response')
151
+        self.assertEqual(to_text(conn._command_response), 'command response')
149 152
 
150 153
         mock__shell.reset_mock()
151
-        mock__shell.recv.return_value = b"ERROR: error message device#"
154
+        mock__shell.recv.side_effect = [b"ERROR: error message device#"]
152 155
 
153 156
         with self.assertRaises(AnsibleConnectionFailure) as exc:
154 157
             conn.send(b'command', None, None, None)