AnsibleModule.run_command() scheduling race

[dw]

SUMMARY

• run_command() has a select loop with a 1 second timeout.
• If the timeout expires, select returns empty lists.
• If the lists are empty, _read_from_pipes will not attempt to read from the associated descriptor
• If process is then put to sleep before the proc.poll() test,
• and the child being executed wakes, and that child writes to its pipes and exits,
• and parent is then rescheduled
  • proc.poll() test will succeed and input loop will exit
  • child's final stdout/stderr will never be read

ISSUE TYPE

• Bug Report

COMPONENT NAME

lib/ansible/module_utils/basic.py

ANSIBLE VERSION

devel

OS / ENVIRONMENT

Ubuntu 18.10

STEPS TO REPRODUCE

Modify run_command():

• Change select timeout from 1 to 0.5
• Insert time.sleep(2) immediately following the select to simulate scheduler uncertainty

Run playbook:

- hosts: localhost
   tasks:
   - shell: sleep 1; echo hi

Observe stdout is absent in output:

changed: [localhost] => {
  changed: True
  cmd: sleep 1; echo hi
  delta: 0:00:02.507000
  end: 2019-01-28 16:49:49.808403
  invocation: {
    module_args: {
      _raw_params: sleep 1; echo hi
      _uses_shell: True
      argv: None
      chdir: None
      creates: None
      executable: None
      removes: None
      stdin: None
      warn: True
    }
  }
  rc: 0
  start: 2019-01-28 16:49:47.301403
}

EXPECTED RESULTS

"stdout" key contains "hi"

ACTUAL RESULTS

"stdout" key is empty due to race

[ansibot]

Files identified in the description:
None

If these files are inaccurate, please update the component name section of the description or use the !component bot command.

click here for bot help

[ansibot]

Files identified in the description:

• lib/ansible/module_utils/basic.py

If these files are inaccurate, please update the component name section of the description or use the !component bot command.

click here for bot help

[dw]

The existing behavior appears to be due to coping with the possibility a child process starts a long-lived child of its own that keeps the pipes open, so testing for pipe disconnect is not a reliable way to exit the loop by itself.

[dw]

Rough patch in https://github.com/dw/ansible/tree/issue51393

[bcoca]

similar first attempt to fix

index 007cb32a33..4406c80482 100644
--- a/lib/ansible/module_utils/basic.py
+++ b/lib/ansible/module_utils/basic.py
@@ -2833,8 +2833,14 @@ class AnsibleModule(object):
                 cmd.stdin.write(data)
                 cmd.stdin.close()

+            read_once = False
             while True:
                 rfds, wfds, efds = select.select(rpipes, [], rpipes, 1)
+                if not read_once:
+                    if rfds:
+                        read_once = True
+                    else:
+                        continue
                 stdout += self._read_from_pipes(rpipes, rfds, cmd.stdout)
                 stderr += self._read_from_pipes(rpipes, rfds, cmd.stderr)
                 # if we're checking for prompts, do it now```

[dw]

I'm not sure it's possible to avoid a timeout-second delay when the pipes are held open, kindof annoying.

[dw]

Actually a single loop iteration like in yours could do it -- if _read_pipes() buffer size was adjusted to match Linux pipe buffer size (up to 64KiB by default)

read() is not guaranteed to empty the buffer in one call even given a suitably sized buffer

[dw]

If process is trying to write more than pipe buffer size data, it won't be able to exit. The problem only manifests when written output can fit entirely in buffer, we need to be sure the buffer is fully drained (9KiB read in 1 iteration isn't enough if the buffer could be up to 64KB)

[dw]

Pushed another patch, but still not happy with it.

• In case of silent grandchild holding pipes open, set timeout to 0 so that iterations complete immediately
• In case of noisy grandchild (cat /dev/urandom), just give up draining pipes after 10 iterations.
• Exit after first iteration with empty reads if process has exitted
• Bump os.read() buffer size to match Linux pipe, so it /should/ only take one loop iteration to empty

I don't like the '10 iterations' bit, but there is no guarantee read() will return entire buffer in one call. On Linux I think it's true that read() on a pipe will return full buffer given a large enough userspace buffer, that may not be true on other OSes, and it's not guaranteed by specification.

The os.read() should also be wrapped in an EINTR try/except for Python 2 (for example, I believe SIGWINCH could be delivered during connection:local) but I haven't done that yet. [edit: the select.select needs an EINTR wrapper too]

[bcoca]

don't assume linux buffer size, 1/2 of my test targets are using 4k buffers

[dw]

Should I just keep reads size 9000? That looks like a made up number, tweaking it is fairly orthogonal to the rest of the patch, except that if the pipe buffer is legitimately full, 7 loop iterations will be required to empty it if the buffer is 64KiB, so bumping exit_loops to 20 or 30 might be wise in that case.

A better solution would not require that exit_loops variable at all, but I'm out of ideas :)

[bcoca]

i was looking at dynamically querying the size via fcntl.fcntl(<fd>, F_GETPIPE_SZ) but unsure if its not POSIX (or at least fails on BSDs)

[dw]

PIPE_BUF constant (maybe available via sysconf) is what you're after, but per above it's inaccurate on Linux, since Linux does not pick a constant

Sorry, someone talking in my ear :) "per above" doesn't actually appear above. Linux pipe buf size varies according to admin sysctl configurables, memory pressure, whether or not the process has CAP_SYS_ADMIN, and varies dynamically across process lifetime, though I think it's at least fixed per pipe lifetime

[bcoca]

So this seems to work across most systems

+++ b/lib/ansible/module_utils/basic.py
@@ -65,6 +65,7 @@ PASS_BOOLS = ('no_log', 'debug', 'diff')
 import __main__
 import atexit
 import locale
+import fcntl
 import os
 import re
 import shlex
@@ -751,6 +752,7 @@ class AnsibleModule(object):
         and :ref:`developing_program_flow_modules` for more detailed explanation.
         '''

+        self._buffer_size = None
         self._name = os.path.basename(__file__)  # initialize name until we can parse from options
         self.argument_spec = argument_spec
         self.supports_check_mode = supports_check_mode
@@ -862,6 +864,17 @@ class AnsibleModule(object):
                            ' Update the code for this module  In the future, AnsibleModule will'
                            ' always check for invalid arguments.', version='2.9')

+    @property
+    def buffer_size(self, fd):
+        if not self._buffer_size:
+            try:
+                # 1032 is F_GETPIPE_SZ
+                self._buffer_size = fcntl.fcntl(fd, 1032)
+            except:
+                self._buffer_size = select.PIPE_BUF
+
+    return self._buffer_size
+
     @property
     def tmpdir(self):
         # if _ansible_tmpdir was not set and we have a remote_tmp,
@@ -2592,7 +2605,7 @@ class AnsibleModule(object):
     def _read_from_pipes(self, rpipes, rfds, file_descriptor):
         data = b('')
         if file_descriptor in rfds:
-            data = os.read(file_descriptor.fileno(), 9000)
+            data = os.read(file_descriptor.fileno(), self.buffer_size(file_descriptor))
             if data == b(''):
                 rpipes.remove(file_descriptor)```

[dw]

I've pushed another copy that includes the EINTR handling. It's easy to hit this while running Ansible under a profiler, and I've witnessed it in the past. The script below demonstrates read() on Linux catching EINTR despite a populated buffer

import time
import os
import subprocess
import signal

signal.signal(signal.SIGALRM, (lambda *_: None))
signal.setitimer(signal.ITIMER_REAL, 100/1e6, 100/1e6)

proc = subprocess.Popen(['cat', '/dev/zero'], stdout=subprocess.PIPE)
while True:
    os.read(proc.stdout.fileno(), 1)

[dw]

I'm happy to add tests and turn this into a PR, but there should be clarity on what the desired behavior is.. fixing one data loss with another, or breaking something elsewhere would suck :)

It boils down to having no way to know whether the child or its noisy grandchild is responsible for continued output. I like bcoca's idea, if the pipe buffer size can be portably determined, stop reading after we know for sure at least a full buffer's worth has been emptied, or a select timeout occurs. That is more principled than the heuristic in my patch, but if the size cannot be determined everywhere, a heuristic might be necessary.

If you are happy for me to continue working on a patch, is it okay to fix the EINTR stuff in the same change? At some stage I was re-starting Ansible constantly as a run would fail under profiling due to it, though I can't remember which profiler caused this. (I guess it hardly matters, as profilers aren't the only source of signals)

This has been present for >4 years.. 5d0bb33, I looked for related issues but couldn't find any with obvious searches. It's fairly likely this is responsible for quite a few random failures

[bcoca]

I don't think EINTR is an issue here since we are running one off scripts and they should really avoid using signals, this is not affecting the ansible runtime itself.

As for the race condition, I doubt many have hit this, since it would require very particular loads on a system when ansible executes the module. It is still a bug and I think we can fix it, either your code or mine seems to address the issue, I do prefer a simpler approach but I would bring more people in to discuss it.

As for the buffer size, I've tested on several platforms and it seems pretty consistent, I don't have access to 'everything' but I consider we cover 95^%j of what users should encounter and can