Add option to disable streaming to stdout file #937

AlanCoding · 2021-12-07T21:03:00Z

This addresses #926

My current intention is to make use of the setting (set it to True) in AWX, unconditionally. We don't want the additional disk writes this incurs. If the executor team is okay with the looks of this, I may ask @amolgautam25 to make that PR.

This use case is only concerned with the pexpect runner mode. I only messed with subprocess here for completeness. The subprocess mode also appears to somehow be connected with the introduction of this behavior. Maybe @ganeshrn has more history to share about this.

john-westcott-iv · 2021-12-08T15:20:55Z

docs/intro.rst

@@ -139,7 +139,8 @@ The **settings** file is a little different than the other files provided in thi
 * ``pexpect_timeout``: ``10`` Number of seconds for the internal pexpect command to wait to block on input before continuing
 * ``pexpect_use_poll``: ``True`` Use ``poll()`` function for communication with child processes instead of ``select()``. ``select()`` is used when the value is set to ``False``. ``select()`` has a known limitation of using only up to 1024 file descriptors.

-* ``suppress_ansible_output``: ``False`` Allow output from ansible to not be printed to the screen
+* ``suppress_output_file``: ``False`` Allow output from ansible to not be streamed to the ``stdout`` or ``stderr`` files inside of the artifacts directory.
+* ``suppress_ansible_output``: ``False`` Allow output from ansible to not be printed to the screen.


Should there be a check to make these mutually exclusive? If they are both set ansible would "just run" with no output, maybe we don't care?

AWX will set them both to False by design. The output is processed by the callback receiver. If someone really wanted the standard out file (which is normally deleted at the end of the run anyway) then we can introduce a setting for them to get it back.

There's a feature in AWX to download the standard out file from a job run. It is illustrative that this works by a completely unrelated method. In the request-response cycle, it is written to disk from the database data and then delivered to the client. Then deleted.

AlanCoding · 2021-12-09T15:13:49Z

test/unit/test_runner.py

-    # about being nice
-    m = mocker.patch('time.sleep')
-    m.start()
-    request.addfinalizer(m.stop)


I checked the timing, and the whole module takes about 3.6 seconds. Maybe this was reducing it to 3.5 or 3.4, but the difference also could have been indistinguishable. I'm using time.sleep to make the assertion reliable, so that's why I did this.

Shrews

Looks pretty good to me, other than the comment on the tests to re-use the iterate_timeout() function.

Shrews · 2021-12-10T18:36:35Z

test/unit/test_runner.py

+    stdout_path = Path(rc.artifact_dir) / 'stdout'
+    # this can be subject to a race condition so we will be patient with the check
+    start_time = time.time()
+    while time.time() - start_time < 2.0:


Use iterate_timeout() here from test/utils/common.py. You can find examples in the test code.

Shrews · 2021-12-10T21:27:51Z

test/unit/test_runner.py

@@ -154,13 +155,9 @@ def test_stdout_file_write(rc, runner_mode):
    assert status == 'successful'
    stdout_path = Path(rc.artifact_dir) / 'stdout'
    # this can be subject to a race condition so we will be patient with the check
-    start_time = time.time()
-    while time.time() - start_time < 2.0:
+    for _ in iterate_timeout(2.0, 'stdout file to be written', interval=0.2):


We can get some pretty slow test VMs, so 2 seconds can be cutting it pretty darn close, which is likely why you see the test failure. I see no reason not to just bump this to, say, 30 seconds.

Thanks. The first time I checked results I saw 2 configurations failing and after adding the 2 second poll 1 was failing. So this would fit the picture that it's slow, dependent on the hardware.

ansible-zuul

LGTM!

AlanCoding · 2021-12-14T20:47:16Z

Interesting... I'm wondering if this was a pre-existing failure of the same type

=================================== FAILURES ===================================
�[31m�[1m_____________________________ test_password_prompt _____________________________�[0m
[gw3] linux -- Python 3.8.12 /home/zuul/src/github.com/ansible/ansible-runner/.tox/py38/bin/python

rc = <ansible_runner.config.runner.RunnerConfig object at 0x7ff864f2e520>

    def test_password_prompt(rc):
        rc.command = [sys.executable, '-c' 'import time; print(input("Password: "))']
        rc.expect_passwords[re.compile(r'Password:\s*?$', re.M)] = '1234'
        status, exitcode = Runner(config=rc).run()
        assert status == 'successful'
        assert exitcode == 0
        with open(os.path.join(rc.artifact_dir, 'stdout')) as f:
>           assert '1234' in f.read()
�[1m�[31mE           AssertionError: assert '1234' in ''�[0m
�[1m�[31mE            +  where '' = <built-in method read of _io.TextIOWrapper object at 0x7ff864d44ee0>()�[0m
�[1m�[31mE            +    where <built-in method read of _io.TextIOWrapper object at 0x7ff864d44ee0> = <_io.TextIOWrapper name='/tmp/pytest-of-zuul/pytest-0/popen-gw3/test_password_prompt0/artifacts/21213e93-55b2-4899-8dc7-edeebb7c59ec/stdout' mode='r' encoding='UTF-8'>.read�[0m

exitcode   = 0
f          = <_io.TextIOWrapper name='/tmp/pytest-of-zuul/pytest-0/popen-gw3/test_password_prompt0/artifacts/21213e93-55b2-4899-8dc7-edeebb7c59ec/stdout' mode='r' encoding='UTF-8'>
rc         = <ansible_runner.config.runner.RunnerConfig object at 0x7ff864f2e520>
status     = 'successful'

�[1m�[31mtest/integration/test_runner.py�[0m:22: AssertionError

I can apply the same methods to that assertion. That looks like it may be the proper thing to do.

Shrews · 2021-12-15T14:04:29Z

The disk space issue aside (no idea why we're seeing that on occasion), each time the new test_stdout_file_write has failed has been with the pexpect path (not the subprocess path). That may be worth looking into.

Shrews · 2021-12-15T15:03:48Z

The disk space issue aside (no idea why we're seeing that on occasion), each time the new test_stdout_file_write has failed has been with the pexpect path (not the subprocess path). That may be worth looking into.

FYI, the failure using pexpect is reproducible on Linux. It can take several runs, but definitely reproducible.

Shrews

Removing approval until the test failure under pexpect is figured out.

AlanCoding · 2021-12-15T15:13:46Z

Would it be a problem for me to do a pytest.skip for the pexpect case? It looks like it's just buggy from some problem with the library maybe.

Do a quick poll until assertion is satisfied Use iterate_timeout test util from review comment reuse poll for the stdout file because of race condition Skip test for pexpect because it does not work

AlanCoding · 2021-12-15T16:56:54Z

@Shrews I added the skip, which looks like it's working to stabilize tests. I can make an issue to cover the stdout log file not working with pexpect

Shrews

It makes me a sad panda that we have to skip the test case we explicitly want this feature for, but this change obviously didn't create the error, only exposed it. So I guess skipping it is ok for now.

Fix suppress_output_file bug where event_callback was not called Sorry, I had a major flaw with #937 and I should have tested that better before it was merged. The handle was not passed to pexpect, and that was wrong. The handle is the way that it dispatches events to the event_callback. Even if you do not intend to write to the stdout file, this is necessary. Design-wise, if suppress_output_file is given, we do want to use the stdout handle wrapper, but we do not want to use the stdout handle itself. I think this code structure articulates that about as best as possible. Alternatively, we could create a null handler and pass that to OutputEventFilter, instead of handling the None case. Separately, I may have discovered a bug related to the test failures on the prior PR. ansible-runner/ansible_runner/utils/__init__.py Line 373 in d013044 event_data['stdout'] = stdout_chunk[:-2] if len(stdout_chunk) > 2 else "" This is assuming the .splitlines(True) leaves \r\n at the end of the line. This is... not universal. Because of that, the final character in the echo command gets truncated, because it has a \n without the \r. This looks completely fixable, but I wish to keep that separate. Reviewed-by: David Shrewsbury <None> Reviewed-by: None <None> Reviewed-by: Alexander Sowitzki <dev@eqrx.net>

Add option to disable streaming to stdout file

1cb7d7f

AlanCoding requested a review from a team as a code owner December 7, 2021 21:03

github-actions bot added the needs_triage New item that needs to be triaged label Dec 7, 2021

Add a quick line to document new setting

28c996b

github-actions bot added the docs Changes to documentation label Dec 7, 2021

john-westcott-iv reviewed Dec 8, 2021

View reviewed changes

AlanCoding commented Dec 9, 2021

View reviewed changes

Shrews requested changes Dec 10, 2021

View reviewed changes

Shrews reviewed Dec 10, 2021

View reviewed changes

Shrews approved these changes Dec 13, 2021

View reviewed changes

Shrews added gate and removed needs_triage New item that needs to be triaged labels Dec 13, 2021

ansible-zuul bot approved these changes Dec 13, 2021

View reviewed changes

ansible-zuul bot removed the gate label Dec 14, 2021

Shrews requested changes Dec 15, 2021

View reviewed changes

Test refinement for feature to skip writing stdout

dbbe02f

Do a quick poll until assertion is satisfied Use iterate_timeout test util from review comment reuse poll for the stdout file because of race condition Skip test for pexpect because it does not work

AlanCoding force-pushed the no_stdout branch from aca2bb5 to dbbe02f Compare December 15, 2021 15:21

Shrews approved these changes Dec 15, 2021

View reviewed changes

Shrews added the gate label Dec 15, 2021

ansible-zuul bot merged commit cb7a971 into ansible:devel Dec 15, 2021

This was referenced Dec 15, 2021

Pass new ansible-runner parameters to reduce number of artifacts we don't need on file system ansible/awx#11472

Merged

Fix suppress_output_file bug where event_callback was not called #943

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add option to disable streaming to stdout file #937

Add option to disable streaming to stdout file #937

AlanCoding commented Dec 7, 2021

john-westcott-iv Dec 8, 2021

AlanCoding Dec 8, 2021

AlanCoding Dec 9, 2021

Shrews left a comment

Shrews Dec 10, 2021

Shrews Dec 10, 2021

AlanCoding Dec 10, 2021

ansible-zuul bot left a comment

AlanCoding commented Dec 14, 2021

Shrews commented Dec 15, 2021

Shrews commented Dec 15, 2021

Shrews left a comment

AlanCoding commented Dec 15, 2021

AlanCoding commented Dec 15, 2021

Shrews left a comment

Add option to disable streaming to stdout file #937

Add option to disable streaming to stdout file #937

Conversation

AlanCoding commented Dec 7, 2021

john-westcott-iv Dec 8, 2021

Choose a reason for hiding this comment

AlanCoding Dec 8, 2021

Choose a reason for hiding this comment

AlanCoding Dec 9, 2021

Choose a reason for hiding this comment

Shrews left a comment

Choose a reason for hiding this comment

Shrews Dec 10, 2021

Choose a reason for hiding this comment

Shrews Dec 10, 2021

Choose a reason for hiding this comment

AlanCoding Dec 10, 2021

Choose a reason for hiding this comment

ansible-zuul bot left a comment

Choose a reason for hiding this comment

AlanCoding commented Dec 14, 2021

Shrews commented Dec 15, 2021

Shrews commented Dec 15, 2021

Shrews left a comment

Choose a reason for hiding this comment

AlanCoding commented Dec 15, 2021

AlanCoding commented Dec 15, 2021

Shrews left a comment

Choose a reason for hiding this comment