Repository: ansible/ansible
Pull request: Make the timeout decorator raise an exception out of the function's scope
##### SUMMARY
Make the timeout decorator properly raise an exception outside of the function's scope
    
signal handlers which raise exceptions will never work well because the
exception can be raised anywhere in the called code.  This leads to
exception race conditions where the exceptions could end up being
hanlded by unintended pieces of the called code.
    
The timeout decorator was using just that idiom.  It was especially bad
because the decorator syntactically occurs outside of the called code
but because of the signal handler, the exception was being raised inside
of the called code.
    
This change uses a thread instead of a signal to manage the timeout in
parallel to the execution of the decorated function.  Since raising of
the exception happens inside of the decorator, now, instead of inside of
a signal handler, the timeout exception is raised from outside of the
called code as expected which makes reasoning about where exceptions are
to be expected intuitive again.
    
Fixes #43884
Fixes #49824
Fixes #49817

##### ISSUE TYPE
<!--- Pick one below and delete the rest -->
- Bugfix Pull Request


##### COMPONENT NAME
lib/ansible/module_utils/facts/timeout.py


Problem statement:
Timer expired after 10 seconds when gather facts
##### SUMMARY
Timer expired after 10 seconds when gather facts on some hosts.

```
fatal: [kso-nlape1vp-rano-009]: FAILED! => {"changed": false, "cmd": "/usr/bin/udevadm info --query property --name /dev/sda1", "msg": "Timer expired after 10 seconds", "rc": 257}
```

##### ISSUE TYPE
 - Bug Report

##### COMPONENT NAME
gather facts on Rancher node running as CentOS.

##### ANSIBLE VERSION
<!--- Paste, BELOW THIS COMMENT, verbatim output from "ansible --version" between quotes below -->
```
ansible 2.6.2
  config file = /home/robin/dev/support-ansible/ansible.cfg
  configured module search path = [u'/home/robin/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python2.7/site-packages/ansible
  executable location = /usr/bin/ansible
  python version = 2.7.5 (default, Feb 20 2018, 09:19:12) [GCC 4.8.5 20150623 (Red Hat 4.8.5-28)]
```

##### CONFIGURATION
<!--- If using Ansible 2.4 or above, paste, BELOW THIS COMMENT, the results of "ansible-config dump --only-changed"
Otherwise, mention any settings you have changed/added/removed in ansible.cfg
(or using the ANSIBLE_* environment variables).-->

```
DEFAULT_ASK_VAULT_PASS(/home/robin/dev/support-ansible/ansible.cfg) = True
DIFF_ALWAYS(/home/robin/dev/support-ansible/ansible.cfg) = True
```

##### OS / ENVIRONMENT
<!--- Mention, BELOW THIS COMMENT, the OS you are running Ansible from, and the OS you are
managing, or say "N/A" for anything that is not platform-specific.
Also mention the specific version of what you are trying to control,
e.g. if this is a network bug the version of firmware on the network device.-->

Client: RHEL 7.5 (Maipo)
Remote: RancherOS v1.2.0

##### STEPS TO REPRODUCE
Run the playbook when it wants to gather facts it fails.

<!--- Paste example playbooks or commands between quotes below -->
```yaml
---
- name: Deploy CoreDNS
  hosts: dns
  roles:
    - coredns
```

<!--- You can also paste gist.github.com links for larger files -->

##### EXPECTED RESULTS
Finish the playbook

##### ACTUAL RESULTS
<!--- What actually happened? If possible run with extra verbosity (-vvvv) -->

<!--- Paste verbatim command output between quotes below -->
```
The full traceback is:
Traceback (most recent call last):
  File "/tmp/ansible_d9POp0/ansible_modlib.zip/ansible/module_utils/basic.py", line 2853, in run_command
    cmd = subprocess.Popen(args, **kwargs)
  File "/usr/lib64/python2.7/subprocess.py", line 711, in __init__
    errread, errwrite)
  File "/usr/lib64/python2.7/subprocess.py", line 1308, in _execute_child
    data = _eintr_retry_call(os.read, errpipe_read, 1048576)
  File "/usr/lib64/python2.7/subprocess.py", line 478, in _eintr_retry_call
    return func(*args)
  File "/tmp/ansible_d9POp0/ansible_modlib.zip/ansible/module_utils/facts/timeout.py", line 37, in _handle_timeout
    raise TimeoutError(msg)
TimeoutError: Timer expired after 10 seconds

fatal: [kso-nlape1vp-rano-009]: FAILED! => {
    "changed": false,
    "cmd": "/usr/bin/udevadm info --query property --name /dev/sda1",
    "invocation": {
        "module_args": {
            "fact_path": "/etc/ansible/facts.d",
            "filter": "*",
            "gather_subset": [
                "all"
            ],
            "gather_timeout": 10
        }
    },
    "msg": "Timer expired after 10 seconds",
    "rc": 257
}
```

Hints from issue discussion:
For the record, I don't have any issues with Ansible version 2.5.7.
I can confirm, I see this exact same issue sporadically. This only occurs on certain hosts, not the entire set.
Interesting traceback... Looks like the SIGALRM handler from facts.timeout is raising the TimeoutError when the `try/except TimeoutError` isn't in the stack, so the TimeoutError gets caught by module_utils.basic.AnsibleModule.run_command()'s `try/except` around the subprocess.Popen() call and that causes the fail_json() return before the `try/except` around get_mount_facts() ever sees it.

  The call to get_mount_facts() is wrapped in a try/except TimeoutError.
 (https://github.com/ansible/ansible/blob/devel/lib/ansible/module_utils/facts/hardware/linux.py#L90-L94)

``` python
        mount_facts = {}
        try:
            mount_facts = self.get_mount_facts()
        except timeout.TimeoutError:
            pass
```

The info in the fail_json return makes it look like it came from run_command()'s try/except around the subprocess.Popen() at https://github.com/ansible/ansible/blob/devel/lib/ansible/module_utils/basic.py#L2883-L2885

``` python
    try:
            if self._debug:
                self.log('Executing: ' + self._clean_args(args))
            cmd = subprocess.Popen(args, **kwargs)

         < ... snipped for brevity ... >

            while True:
                rfds, wfds, efds = select.select(rpipes, [], rpipes, 1)
                stdout += self._read_from_pipes(rpipes, rfds, cmd.stdout)
                stderr += self._read_from_pipes(rpipes, rfds, cmd.stderr)
              
               < ... snipped lots of code handling fd errors and a
                       cmd.wait() and other things that could raise Exception ...>

            cmd.stdout.close()
            cmd.stderr.close()

            rc = cmd.returncode
        except (OSError, IOError) as e:
            self.log("Error Executing CMD:%s Exception:%s" % (self._clean_args(args), to_native(e)))
            self.fail_json(rc=e.errno, msg=to_native(e), cmd=self._clean_args(args))
        except Exception as e:
            self.log("Error Executing CMD:%s Exception:%s" % (self._clean_args(args), to_native(traceback.format_exc())))
            self.fail_json(rc=257, msg=to_native(e), exception=traceback.format_exc(), cmd=self._clean_args(args))
```

Not sure how to fix that... 

One possibility might be to add a clause in run_command() to ignore and re-raise timeout.TimeoutError, so it doesn't get handled by the 'except Exception' clause.

Another way... maybe passing in the calling stack for the wrapped method in the timeout.Timeout() decorator? Or possibly just moving the _handle_timeout def inside the context of the wrapper() method instead of just inside the decorator() method. Other timeout implementations seem to match the existing code though, so unlikely.

Though, it kind of looks like the Timeout() decorator may not be resetting the original signal handler when it is done. Comparing the facts.timeout code to https://github.com/pnpnpn/timeout-decorator/blob/master/timeout_decorator/timeout_decorator.py#L65-L94 for example, resetting the signal handler seems to be the main thing missing in facts.timeout. Wondering if that in combo with subprocess's _eintr_retry_call() is causing problems. 
I am hitting this issue as well on Oracle Linux 7.5 with Ansible 2.6.2
Yep, seeing this also :(
Same here!

```
An exception occurred during task execution. To see the full traceback, use -vvv. The error was: TimeoutError: Timer expired after 10 seconds
fatal: [hostname]: FAILED! => {"changed": false, "cmd": "/bin/udevadm info --query property --name nas:/homes", "msg": "Timer expired after 10 seconds", "rc": 257}
```

The host is running Debian 9, mounted homedir with NFS (nfs (rw,noatime,vers=3,rsize=524288,wsize=524288,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=nas,mountvers=3,mountport=30000,mountproto=udp,local_lock=none,addr=nas,_netdev), and my ansible host is MacOS 10.13.6. Same with MacOS 10.14 beta.
same issue with ansible 2.6.3 on rhel 7.5

An exception occurred during task execution. To see the full traceback, use -vvv. The error was: TimeoutError: Timer expired after 10 seconds
fatal: [hostname]: FAILED! => {"changed": false, "cmd": "/sbin/udevadm info --query property --name /dev/mapper/rootvg-varlv", "msg": "Timer expired after 10 seconds", "rc": 257}

the command is executing without issues on the target host.
Same issue. Need a quick fix for this issue. 
Ansible-playbook executes properly on some nodes but on some nodes connection time out. Nothing has changed from configuration or playbook perspective.

The full traceback is:
```
Traceback (most recent call last):
  File "/tmp/ansible_Kh_sLm/ansible_modlib.zip/ansible/module_utils/basic.py", line 2853, in run_command
    cmd = subprocess.Popen(args, **kwargs)
  File "/usr/lib64/python2.7/subprocess.py", line 711, in __init__
    errread, errwrite)
  File "/usr/lib64/python2.7/subprocess.py", line 1308, in _execute_child
    data = _eintr_retry_call(os.read, errpipe_read, 1048576)
  File "/usr/lib64/python2.7/subprocess.py", line 478, in _eintr_retry_call
    return func(*args)
  File "/tmp/ansible_Kh_sLm/ansible_modlib.zip/ansible/module_utils/facts/timeout.py", line 37, in _handle_timeout
    raise TimeoutError(msg)
TimeoutError: Timer expired after 10 seconds

fatal: [a1uspod2.securonix.net]: FAILED! => {
    "changed": false, 
    "cmd": "/bin/findmnt --list --noheadings --notruncate", 
    "invocation": {
        "module_args": {
            "fact_path": "/etc/ansible/facts.d", 
            "filter": "*", 
            "gather_subset": [
                "all"
            ], 
            "gather_timeout": 10
        }
    }, 
    "msg": "Timer expired after 10 seconds", 
    "rc": 257
}

```

CentOS Linux release 7.5.1804 (Core) 

ansible 2.6.3
  config file = /etc/ansible/ansible.cfg
  configured module search path = [u'/root/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python2.7/site-packages/ansible
  executable location = /bin/ansible
  python version = 2.7.5 (default, Jul 13 2018, 13:06:57) [GCC 4.8.5 20150623 (Red Hat 4.8.5-28)]
This work-around helped me.
In  /etc/ansible/ansible.cfg I set **gather_subset = !all** which basically only gathers minimum facts. I think while gathering facts something is messed up. So based on your requirement set the value to only gather those facts which is required for you. 
You can see the failure here: https://travis-ci.org/Tecnativa/ansible-test-playground/builds/425233045#L601

Some problem with Debian 8? :thinking: 

---

Edit: it was a problem on my side: the docker image being used was too bloated, causing the CI machine to overflow.

Commit message: Make the timeout decorator properly raise an exception outside of the function's scope

signal handlers which raise exceptions will never work well because the
exception can be raised anywhere in the called code.  This leads to
exception race conditions where the exceptions could end up being
hanlded by unintended pieces of the called code.

The timeout decorator was using just that idiom.  It was especially bad
because the decorator syntactically occurs outside of the called code
but because of the signal handler, the exception was being raised inside
of the called code.

This change uses a thread instead of a signal to manage the timeout in
parallel to the execution of the decorated function.  Since raising of
the exception happens inside of the decorator, now, instead of inside of
a signal handler, the timeout exception is raised from outside of the
called code as expected which makes reasoning about where exceptions are
to be expected intuitive again.

Fixes #43884

Patch to review:
diff --git a/lib/ansible/module_utils/basic.py b/lib/ansible/module_utils/basic.py
index 01c90d54f632b8..c5f9a819bef7b3 100644
--- a/lib/ansible/module_utils/basic.py
+++ b/lib/ansible/module_utils/basic.py
@@ -2605,7 +2605,7 @@ def _restore_signal_handlers(self):
 
     def run_command(self, args, check_rc=False, close_fds=True, executable=None, data=None, binary_data=False, path_prefix=None, cwd=None,
                     use_unsafe_shell=False, prompt_regex=None, environ_update=None, umask=None, encoding='utf-8', errors='surrogate_or_strict',
-                    expand_user_and_vars=True, pass_fds=None, before_communicate_callback=None, raise_timeouts=False):
+                    expand_user_and_vars=True, pass_fds=None, before_communicate_callback=None):
         '''
         Execute a command, returns rc, stdout, and stderr.
 
@@ -2655,9 +2655,6 @@ def run_command(self, args, check_rc=False, close_fds=True, executable=None, dat
             after ``Popen`` object will be created
             but before communicating to the process.
             (``Popen`` object will be passed to callback as a first argument)
-        :kw raise_timeouts: This is a boolean, which when True, will allow the
-            caller to deal with timeout exceptions. When false we use the previous
-            behaviour of having run_command directly call fail_json when they occur.
         :returns: A 3-tuple of return code (integer), stdout (native string),
             and stderr (native string).  On python2, stdout and stderr are both
             byte strings.  On python3, stdout and stderr are text strings converted
@@ -2831,12 +2828,6 @@ def run_command(self, args, check_rc=False, close_fds=True, executable=None, dat
             cmd.stderr.close()
 
             rc = cmd.returncode
-        except TimeoutError as e:
-            self.log("Timeout Executing CMD:%s Timeout :%s" % (self._clean_args(args), to_native(e)))
-            if raise_timeouts:
-                raise e
-            else:
-                self.fail_json(rc=e.errno, msg=to_native(e), cmd=self._clean_args(args))
         except (OSError, IOError) as e:
             self.log("Error Executing CMD:%s Exception:%s" % (self._clean_args(args), to_native(e)))
             self.fail_json(rc=e.errno, msg=to_native(e), cmd=self._clean_args(args))
diff --git a/lib/ansible/module_utils/facts/timeout.py b/lib/ansible/module_utils/facts/timeout.py
index 2927b31c822429..1e2554f74d4b2e 100644
--- a/lib/ansible/module_utils/facts/timeout.py
+++ b/lib/ansible/module_utils/facts/timeout.py
@@ -16,7 +16,8 @@
 from __future__ import (absolute_import, division, print_function)
 __metaclass__ = type
 
-import signal
+import multiprocessing
+import multiprocessing.pool as mp
 
 # timeout function to make sure some fact gathering
 # steps do not exceed a time limit
@@ -25,29 +26,30 @@
 DEFAULT_GATHER_TIMEOUT = 10
 
 
-class TimeoutError(Exception):
-    pass
+try:
+    # On Python 3, reuse the TimeoutError
+    class TimeoutError(TimeoutError):
+        pass
+except NameError:
+    # On Python 2, there unfortunately isn't a better base class to inherit from
+    class TimeoutError(Exception):
+        pass
 
 
 def timeout(seconds=None, error_message="Timer expired"):
-
     def decorator(func):
-        def _handle_timeout(signum, frame):
-            msg = 'Timer expired after %s seconds' % globals().get('GATHER_TIMEOUT')
-            raise TimeoutError(msg)
-
         def wrapper(*args, **kwargs):
-            local_seconds = seconds
-            if local_seconds is None:
-                local_seconds = globals().get('GATHER_TIMEOUT') or DEFAULT_GATHER_TIMEOUT
-            signal.signal(signal.SIGALRM, _handle_timeout)
-            signal.alarm(local_seconds)
+            timeout_value = seconds
+            if timeout_value is None:
+                timeout_value = globals().get('GATHER_TIMEOUT') or DEFAULT_GATHER_TIMEOUT
 
+            pool = mp.ThreadPool(processes=1)
+            res = pool.apply_async(func, args, kwargs)
+            pool.close()
             try:
-                result = func(*args, **kwargs)
-            finally:
-                signal.alarm(0)
-            return result
+                return res.get(timeout_value)
+            except multiprocessing.TimeoutError:
+                raise TimeoutError('Timer expired after %s seconds' % timeout_value)
 
         return wrapper
 
diff --git a/test/units/module_utils/facts/test_timeout.py b/test/units/module_utils/facts/test_timeout.py
index 36adbfabd193a9..e2085b7e4f95f7 100644
--- a/test/units/module_utils/facts/test_timeout.py
+++ b/test/units/module_utils/facts/test_timeout.py
@@ -20,13 +20,11 @@
 from __future__ import (absolute_import, division)
 __metaclass__ = type
 
+import sys
 import time
 
 import pytest
 
-from units.compat import unittest
-from units.compat.mock import patch, MagicMock
-
 from ansible.module_utils.facts import timeout
 
 
@@ -67,6 +65,10 @@ def sleep_amount_explicit_lower(amount):
     return 'Succeeded after {0} sec'.format(amount)
 
 
+#
+# Tests for how the timeout decorator is specified
+#
+
 def test_defaults_still_within_bounds():
     # If the default changes outside of these bounds, some of the tests will
     # no longer test the right thing.  Need to review and update the timeouts
@@ -110,3 +112,84 @@ def test_explicit_timeout():
     sleep_time = 3
     with pytest.raises(timeout.TimeoutError):
         assert sleep_amount_explicit_lower(sleep_time) == '(Not expected to succeed)'
+
+
+#
+# Test that exception handling works
+#
+
+@timeout.timeout(1)
+def function_times_out():
+    time.sleep(2)
+
+
+@timeout.timeout(1)
+def function_other_timeout():
+    raise TimeoutError('Vanilla Timeout')
+
+
+@timeout.timeout(1)
+def function_raises():
+    1/0
+
+
+@timeout.timeout(1)
+def function_catches_all_exceptions():
+    try:
+        time.sleep(10)
+    except BaseException:
+        raise RuntimeError('We should not have gotten here')
+
+
+def test_timeout_raises_timeout():
+    with pytest.raises(timeout.TimeoutError):
+        assert function_times_out() == '(Not expected to succeed)'
+
+
+def test_timeout_raises_other_exception():
+    with pytest.raises(ZeroDivisionError):
+        assert function_raises() == '(Not expected to succeed)'
+
+
+def test_exception_not_caught_by_called_code():
+    with pytest.raises(timeout.TimeoutError):
+        assert function_catches_all_exceptions() =='(Not expected to succeed)'
+
+
+def test_timeout_can_catch_our_timeout_only():
+    passed = False
+    try:
+        function_times_out()
+    except timeout.TimeoutError:
+        passed = True
+    assert passed
+
+
+@pytest.mark.skipif(sys.version_info < (3, 0), reason="TimeoutError first appeared in Python3")
+def test_timeout_can_catch_other_timeout():
+    passed = False
+    try:
+        function_other_timeout()
+    except timeout.TimeoutError:
+        passed = False
+    except TimeoutError:
+        passed = True
+
+    assert passed
+
+
+@pytest.mark.skipif(sys.version_info < (3, 0), reason="TimeoutError first appeared in Python3")
+def test_timeout_can_catch_all_timeouts():
+    passed = False
+    try:
+        function_times_out()
+    except TimeoutError:
+        passed = True
+    assert passed
+
+    passed = False
+    try:
+        function_times_out()
+    except TimeoutError:
+        passed = True
+    assert passed


Code review comments:
diff_hunk: @@ -25,29 +26,30 @@
 DEFAULT_GATHER_TIMEOUT = 10
 
 
-class TimeoutError(Exception):
-    pass
+try:
+    # On Python 3, reuse the TimeoutError
+    class TimeoutError(TimeoutError):
+        pass
+except NameError:
+    # On Python 2, there unfortunately isn't a better base class to inherit from
+    class TimeoutError(Exception):
path: lib/ansible/module_utils/facts/timeout.py
text: @user1:
in py3 TimeoutError inherits from OSError, making this code subject to divergent paths in py2 vs py3, so if you really want to avoid that inherit from OSError, not Exception

@author:
Will do