potentially flaky tests test_piped_exception1 and test_piped_exception2

[dvzrv]

Hi! During building the package of 1.14.0 for Arch Linux I ran the build on one of our build servers. When running the test suite using pytest (i.e. pytest -v test.py) every now and then the two tests would fail:

=================================== FAILURES ===================================
____________________ FunctionalTests.test_piped_exception1 _____________________

self = <test.FunctionalTests testMethod=test_piped_exception1>

        def test_piped_exception1(self):
            from sh import ErrorReturnCode_2

            py = create_tmp_test("""
    import sys
    sys.stdout.write("line1\\n")
    sys.stdout.write("line2\\n")
    exit(2)
    """)

            py2 = create_tmp_test("")

            def fn():
                list(python(python(py.name, _piped=True), "-u", py2.name, _iter=True))

>           self.assertRaises(ErrorReturnCode_2, fn)

/build/python-sh/src/sh-1.14.0/test.py:737:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
/build/python-sh/src/sh-1.14.0/test.py:735: in fn
    list(python(python(py.name, _piped=True), "-u", py2.name, _iter=True))
/build/python-sh/src/sh-1.14.0/sh.py:883: in __len__
    return len(str(self))
/build/python-sh/src/sh-1.14.0/sh.py:930: in __str__
    return self.__unicode__()
/build/python-sh/src/sh-1.14.0/sh.py:937: in __unicode__
    if self.process and self.stdout:
/build/python-sh/src/sh-1.14.0/sh.py:869: in stdout
    self.wait()
/build/python-sh/src/sh-1.14.0/sh.py:848: in wait
    self.process._stdin_process.command.wait()
/build/python-sh/src/sh-1.14.0/sh.py:841: in wait
    self.handle_command_exit_code(exit_code)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

    def handle_command_exit_code(self, code):
        """ here we determine if we had an exception, or an error code that we
        weren't expecting to see.  if we did, we create and raise an exception
        """
        ca = self.call_args
        exc_class = get_exc_exit_code_would_raise(code, ca["ok_code"], ca["piped"])
        if exc_class:
            exc = exc_class(self.ran, self.process.stdout, self.process.stderr, ca["truncate_exc"])
>           raise exc
E           sh.ErrorReturnCode_120:
E
E             RAN: /usr/bin/python /tmp/tmpao5nlisd
E
E             STDOUT:
E
E
E             STDERR:
E           Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
E           BrokenPipeError: [Errno 32] Broken pipe
                                                                                                                                                                                                                                                                                                                    [1320/8802]
/build/python-sh/src/sh-1.14.0/sh.py:865: ErrorReturnCode_120
----------------------------- Captured stderr call -----------------------------
Exception in thread background thread for pid 1510:
Traceback (most recent call last):
  File "/usr/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.8/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/build/python-sh/src/sh-1.14.0/sh.py", line 1637, in wrap
    fn(*rgs, **kwargs)
  File "/build/python-sh/src/sh-1.14.0/sh.py", line 2561, in background_thread
    handle_exit_code(exit_code)
  File "/build/python-sh/src/sh-1.14.0/sh.py", line 2265, in fn
    return self.command.handle_command_exit_code(exit_code)
  File "/build/python-sh/src/sh-1.14.0/sh.py", line 865, in handle_command_exit_code
    raise exc
sh.ErrorReturnCode_120:

  RAN: /usr/bin/python /tmp/tmpao5nlisd

  STDOUT:


  STDERR:
Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
BrokenPipeError: [Errno 32] Broken pipe

____________________ FunctionalTests.test_piped_exception2 _____________________

self = <test.FunctionalTests testMethod=test_piped_exception2>

        def test_piped_exception2(self):
            from sh import ErrorReturnCode_2

            py = create_tmp_test("""
    import sys
    sys.stdout.write("line1\\n")
    sys.stdout.write("line2\\n")
    exit(2)
    """)

            py2 = create_tmp_test("")

            def fn():
                python(python(py.name, _piped=True), "-u", py2.name)

>           self.assertRaises(ErrorReturnCode_2, fn)

/build/python-sh/src/sh-1.14.0/test.py:754:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
/build/python-sh/src/sh-1.14.0/test.py:752: in fn
    python(python(py.name, _piped=True), "-u", py2.name)
/build/python-sh/src/sh-1.14.0/sh.py:1520: in __call__
    return RunningCommand(cmd, call_args, stdin, stdout, stderr)
/build/python-sh/src/sh-1.14.0/sh.py:784: in __init__
    self.wait()
/build/python-sh/src/sh-1.14.0/sh.py:848: in wait
    self.process._stdin_process.command.wait()
/build/python-sh/src/sh-1.14.0/sh.py:841: in wait
    self.handle_command_exit_code(exit_code)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

    def handle_command_exit_code(self, code):
        """ here we determine if we had an exception, or an error code that we
        weren't expecting to see.  if we did, we create and raise an exception
        """
        ca = self.call_args
        exc_class = get_exc_exit_code_would_raise(code, ca["ok_code"], ca["piped"])
        if exc_class:
            exc = exc_class(self.ran, self.process.stdout, self.process.stderr, ca["truncate_exc"])
>           raise exc
E           sh.ErrorReturnCode_120:
E
E             RAN: /usr/bin/python /tmp/tmpk44k07uy
E
E             STDOUT:
E
E
E             STDERR:
E           Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
E           BrokenPipeError: [Errno 32] Broken pipe

/build/python-sh/src/sh-1.14.0/sh.py:865: ErrorReturnCode_120
----------------------------- Captured stderr call -----------------------------
Exception in thread background thread for pid 1519:
Traceback (most recent call last):
  File "/usr/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.8/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/build/python-sh/src/sh-1.14.0/sh.py", line 1637, in wrap
    fn(*rgs, **kwargs)
  File "/build/python-sh/src/sh-1.14.0/sh.py", line 2561, in background_thread
    handle_exit_code(exit_code)
  File "/build/python-sh/src/sh-1.14.0/sh.py", line 2265, in fn
    return self.command.handle_command_exit_code(exit_code)
  File "/build/python-sh/src/sh-1.14.0/sh.py", line 865, in handle_command_exit_code
    raise exc
sh.ErrorReturnCode_120:

  RAN: /usr/bin/python /tmp/tmpk44k07uy

  STDOUT:


  STDERR:
Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
BrokenPipeError: [Errno 32] Broken pipe

=========================== short test summary info ============================
FAILED test.py::FunctionalTests::test_piped_exception1 - sh.ErrorReturnCode_1...
FAILED test.py::FunctionalTests::test_piped_exception2 - sh.ErrorReturnCode_1...
=========== 2 failed, 164 passed, 1 skipped, 3 deselected in 48.84s ============

I am not entirely sure whether this is a problem with the tests themselves or with the environment they are being run in.
As we build all packages in pristine systemd-nspawn containers they should be the same.... but maybe this is not true under certain circumstances when using the /tmp directory.
I tried using pytest with the --basetemp parameter but test_piped_exception2 would still potentially fail.

I have disabled the two tests for now as they influence reproducibility of the build as well.

[amoffat]

@dvzrv Are you able to provide the image for the container that this fails in? It will assist with the debugging

[dvzrv]

Hm, this is a bit tricky. We do not build e.g. in docker containers but in a systemd-nspawn on a bare metal machine (usually).

I guess the closest/fastest thing you can get to this is by spinning up a vagrant machine:

vagrant init archlinux/archlinux
vagrant up

Then log in to the VM and install required things:

vagrant ssh
sudo pacman -Syu asp base-devel devtools

Check out the PKGBUILD for the package and build it (still on the VM):

asp checkout python-sh
cd python-sh/trunk/
extra-x86_64-build

Note, that the above will build the package without the disabled tests. To enable them modify the PKGBUILD to your needs (e.g. remove the -k parameter to pytest to run all tests).
Note: PKGBUILDs are really just bash scripts!

[amoffat]

Thanks for the detailed info @dvzrv. I'm unable to repro the issue unfortunately. I'm going to write my thoughts here, and they probably won't mean much to you, but they are mainly for future investigations into a similar issue. The TL;DR for you would be to continue ignoring those 2 tests in your package. Reopen this issue if you can find a way to repro it.

---

One of the failing tests in question:

    def test_piped_exception2(self):
        from sh import ErrorReturnCode_2

        py = create_tmp_test("""
import sys
sys.stdout.write("line1\\n")
sys.stdout.write("line2\\n")
exit(2)
""")

        py2 = create_tmp_test("")

        def fn():
            python(python(py.name, _piped=True), "-u", py2.name)

        self.assertRaises(ErrorReturnCode_2, fn)

Which is failing with an exit code 120, but also a message about a BrokenPipe. Normally sh will ignore a broken pipe error, but this error code isn't a broken pipe error, it's something else. According to this an exit code of 120 suggests that another exception happened after exit(2) was called.

One possible sequence of events, which doesn't make much sense honestly, is that "line1" and "line2" are output, then exit(2) is called, then the outer python exits, but for some reason the inner python tries to write something else (after its exit has been called). Since the outer python has exited though, anything it tries to write to stderr or stdout results in a broken pipe error, which doesn't get treated as such since it occurred after the exit(2), meaning that it bubbles up as a 120.