ctx.run fails due to bad command exit code

[flazzarini]

Scenario

I stumbled upon this issue when using fabric2 where I had a task which would execute alembic to upgrade/downgrade multiple local databases. When executing the task it would sometimes (completely randomly) fail with the following exception.

Please note the following is only happening when pty is set to False.

Version of invoke used 1.3.0.

Encountered a bad command exit code!

Command: './env/bin/alembic upgrade head'

Exit code: None

Stdout: already printed

Stderr: already printed

Reproduction of the bug

I replicated the fabric task to a pure invoke task like shown here. When executing the following code I get randomly the error mentioned above. I will execute the task multiple times to see that the error occurs in different runs every time.

Code

from invoke import task


@task
def upgrade(ctx):
    for index in range(1, 5):
        try:
            print("Run upgrade")
            ctx.run("./env/bin/alembic upgrade head")
        except Exception as exc:
            print(exc)

First run

$ ./env/bin/invoke upgrade
Run upgrade 1
Run upgrade 2
Run upgrade 3
Run upgrade 4
Run upgrade 5
Encountered a bad command exit code!

Command: './env/bin/alembic upgrade head'

Exit code: None

Stdout: already printed

Stderr: already printed


Run upgrade 6
Encountered a bad command exit code!

Command: './env/bin/alembic upgrade head'

Exit code: None

Stdout: already printed

Stderr: already printed


Run upgrade 7
Encountered a bad command exit code!

Command: './env/bin/alembic upgrade head'

Exit code: None

Stdout: already printed

Stderr: already printed


Run upgrade 8
Run upgrade 9

Second run

$ ./env/bin/invoke upgrade
Run upgrade 1
Encountered a bad command exit code!

Command: './env/bin/alembic upgrade head'

Exit code: None

Stdout: already printed

Stderr: already printed


Run upgrade 2
Run upgrade 3
Encountered a bad command exit code!

Command: './env/bin/alembic upgrade head'

Exit code: None

Stdout: already printed

Stderr: already printed


Run upgrade 4
Run upgrade 5
Encountered a bad command exit code!

Command: './env/bin/alembic upgrade head'

Exit code: None

Stdout: already printed

Stderr: already printed


Run upgrade 6
Encountered a bad command exit code!

Command: './env/bin/alembic upgrade head'

Exit code: None

Stdout: already printed

Stderr: already printed


Run upgrade 7
Run upgrade 8
Run upgrade 9

Investigation

After investigating the issue with one of my colleagues we might have identified the issue. However this is merely an assumption rather than a certainty. It seems that the threads that are being spawned for the Runners are trying to access Local.returncode function before the process has had a chance to finish without waiting on the process to finish.

I've tried changing the code of returncode by adding Popen wait call which seems to fix the issue I had.

    def returncode(self):
        if self.using_pty:
            # No subprocess.returncode available; use WIFEXITED/WIFSIGNALED to
            # determine whch of WEXITSTATUS / WTERMSIG to use.
            # TODO: is it safe to just say "call all WEXITSTATUS/WTERMSIG and
            # return whichever one of them is nondefault"? Probably not?
            # NOTE: doing this in an arbitrary order should be safe since only
            # one of the WIF* methods ought to ever return True.
            code = None
            if os.WIFEXITED(self.status):
                code = os.WEXITSTATUS(self.status)
            elif os.WIFSIGNALED(self.status):
                code = os.WTERMSIG(self.status)
                # Match subprocess.returncode by turning signals into negative
                # 'exit code' integers.
                code = -1 * code
            return code
            # TODO: do we care about WIFSTOPPED? Maybe someday?
        else:
            self.process.wait(timeout=3)
            return self.process.returncode

$ ./env/bin/invoke upgrade
Run upgrade 1
Run upgrade 2
Run upgrade 3
Run upgrade 4
Run upgrade 5
Run upgrade 6
Run upgrade 7
Run upgrade 8
Run upgrade 9

Please consider the following pull request #661

[florisla]

Thanks, #661 works for me (Python 3.6, Windows 10).

Invoke 1.3.0 is unusable for some of my tasks which happen do a lot of sub-process calls -- it's hit and miss whether the task completes at all.

Invoke 1.2.0 and the #661 branch don't stumble on those same tasks.

[rsora]

Thanks @flazzarini, #661 solves also the same issue that we had in our Github Actions CI workflows (arduino/arduino-cli#416), both on win and linux environments.

I hope that this PR will be merged ASAP 😸

[beornling]

Good work @flazzarini. I'm running into the same basic issue but directly using pyinvoke c.run(). My use case has a failure rate of ~10%. To test some changes to runners.py, I simplified your test to just use Windows "dir" command.

tasks.py

from invoke import task

@task
def test(ctx):
    print('Begging test...')
    failures = 0
    count = 0
    for _ in range(0, 1000):
        count += 1
        try:
            resp = ctx.run('dir', hide='both')
            if not resp.ok:
                failures += 1
                #print(resp)
        except Exception as exc:
            failures += 1
            #print(exc)

    print(f'Finished: ran {count} times with {failures} failures')

Here's the baseline running pyinvoke 1.3.0.

Begging test...
Finished: ran 1000 times with 83 failures

Running pyinvoke 1.3.0 + change from #661.

Begging test...
Finished: ran 1000 times with 0 failures

Since your change in #661 might wait a bit long, I tested a few alternatives. First, instead of waiting for a static timeout, I first tried just returning self.process.poll() as that updates the process returncode as well.

Running pyinvoke 1.3.0 + 'return self.process.poll()'

Begging test...
Finished: ran 1000 times with 6 failures

Lastly, I tested with just setting the wait timeout to the currently set self.input_sleep which defaults to 0.01

Running pyinvoke 1.3.0 + 'self.process.wait(timeout=self.input_sleep)'

Begging test...
Finished: ran 1000 times with 0 failures

As you can see, even a tiny wait is enough to fix this issue. Hopefully this change makes it in soon or we'll have to find an alternative to pyinvoke since this sort of instability is causing all sorts of random errors.

[SwampFalc]

I'd like to report I'm also running into this issue. A quick fix to this would be very much appreciated.

[cod3monk3y]

I think this is the same issue:
#683

My analysis and (hack-ish) workaround might also be helpful to the discussion:
cod3monk3y@1123485

[krupan]

I think I might be seeing the same bug. I explained what I'm seeing here: #683 (comment)

[bitprophet]

I'm seeing this myself now, mostly via Travis-CI on other projects using Invoke to run eg pytest. Thanks to @flazzarini for the post & investigation, thread race conditions are the obvious culprit so that's unsurprising (and wearying, the whole thread shutdown thing has already gone through a few mutations).

I'll look at the PR my next block of OSS time.