New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

'Inappropriate ioctl for device' when using run() in a headless process #425

Closed
txomon opened this Issue Feb 2, 2017 · 17 comments

Comments

Projects
None yet
4 participants
@txomon

txomon commented Feb 2, 2017

Hello, I have no idea what happened in the last release, but invoke 0.14.0 is breaking a setup for me when I run invoke remove_reference from a git commit-msg hook. I don't know if this gives any clue.

I will post back whenever I come up with a way to properly reproduce.

@task                                                                                                                                                                                                                
def remove_reference(ctx):                                                                                                                                                                                                    
    """Remove references"""                                                                                                                                                                
    ctx.run('rm -rf docs/reference/')                                                                                                                                                                                
  File "/home/javier/projects/test/bin/invoke", line 11, in <module>
    sys.exit(program.run())
  File "/home/javier/projects/test/lib/python3.6/site-packages/invoke/program.py", line 274, in run
    self.execute()
  File "/home/javier/projects/test/lib/python3.6/site-packages/invoke/program.py", line 389, in execute
    executor.execute(*self.tasks)
  File "/home/javier/projects/test/lib/python3.6/site-packages/invoke/executor.py", line 113, in execute
    result = call.task(*args, **call.kwargs)
  File "/home/javier/projects/test/lib/python3.6/site-packages/invoke/tasks.py", line 111, in __call__
    result = self.body(*args, **kwargs)
  File "/home/javier/projects/ridee/jinn-api/tasks.py", line 16, in remove_reference
    ctx.run('rm -rf docs/reference/')
  File "/home/javier/projects/test/lib/python3.6/site-packages/invoke/context.py", line 60, in run
    return runner_class(context=self).run(command, **kwargs)
  File "/home/javier/projects/test/lib/python3.6/site-packages/invoke/runners.py", line 256, in run
    return self._run_body(command, **kwargs)
  File "/home/javier/projects/test/lib/python3.6/site-packages/invoke/runners.py", line 358, in _run_body
    raise ThreadException(thread_exceptions)
invoke.exceptions.ThreadException:
Saw 1 exceptions within threads (OSError):


Thread args: {'kwargs': {'echo': None,
            'input_': <_io.TextIOWrapper name='<stdin>' mode='r' encoding='UTF-8'>,
            'output': <_io.TextIOWrapper name='<stdout>' mode='w' encoding='UTF-8'>},
 'target': <bound method Runner.handle_stdin of <invoke.runners.Local object at 0x7ff17286cc88>>}

Traceback (most recent call last):

  File "/home/javier/projects/test/lib/python3.6/site-packages/invoke/util.py", line 125, in run
    super(ExceptionHandlingThread, self).run()

  File "/usr/lib64/python3.6/threading.py", line 864, in run
    self._target(*self._args, **self._kwargs)

  File "/home/javier/projects/test/lib/python3.6/site-packages/invoke/runners.py", line 621, in handle_stdin
    data = self.read_our_stdin(input_)

  File "/home/javier/projects/test/lib/python3.6/site-packages/invoke/runners.py", line 583, in read_our_stdin
    bytes_ = input_.read(bytes_to_read(input_))

  File "/home/javier/projects/test/lib/python3.6/site-packages/invoke/platform.py", line 162, in bytes_to_read
    return struct.unpack('h', fcntl.ioctl(input_, termios.FIONREAD, "  "))[0]

OSError: [Errno 25] Inappropriate ioctl for device
@txomon

This comment has been minimized.

txomon commented Feb 2, 2017

Ok, the minimal setup for this not to work, tested with python3.6.

In a folder for this test:

virtualenv3 ve
source ve/bin/activate
pip install invoke==0.14.0
mkdir test; cd test
git init
echo '#!/bin/bash
invoke git_pre_commit_hook
exit $?' > .git/hooks/pre-commit
chmod +x .git/hooks/pre-commit
echo 'from invoke import task

@task
def git_pre_commit_hook(ctx):
    """Hook to be run by git, not called directly"""
    ctx.run("echo asdfaasdf asdfasdf")' > tasks.py
git add tasks.py
git commit -am 'ASDF'

However, the same setup with invoke 0.13.0 works

virtualenv3 ve
source ve/bin/activate
pip install invoke==0.13.0
mkdir test; cd test
git init
echo '#!/bin/bash
invoke git_pre_commit_hook
exit $?' > .git/hooks/pre-commit
chmod +x .git/hooks/pre-commit
echo 'from invoke import task

@task
def git_pre_commit_hook(ctx):
    """Hook to be run by git, not called directly"""
    ctx.run("echo asdfaasdf asdfasdf")' > tasks.py
git add tasks.py
git commit -am 'ASDF'
@bitprophet

This comment has been minimized.

Member

bitprophet commented Feb 3, 2017

Almost definitely covered under this FAQ: http://www.pyinvoke.org/faq.html#i-m-getting-ioerror-inappropriate-ioctl-for-device-when-i-run-commands

Given you started having the issue in 0.14 IIRC that means your issue is on stdin specifically?

Do comment again if that doesn't get you pointed in the right direction!

@bitprophet bitprophet closed this Feb 3, 2017

@txomon

This comment has been minimized.

txomon commented Feb 3, 2017

@paiv

This comment has been minimized.

paiv commented Feb 4, 2017

I can confirm @txomon sample has described issue running on macOS.

I myself faced this on AWS CodeBuild just after upgrading to 0.14. Not sure that Git hook is involved on CodeBuild, but it might be.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Feb 10, 2017

The core problem here is still going to be related to stdin not being a "real enough" pipe, but if it's coming up this often we should try to figure out if there's a graceful method of handling that situation. Invoke definitely gets run headless a lot. Reopening.

@bitprophet bitprophet modified the milestone: 0.12.3 Feb 10, 2017

@tuukkamustonen

This comment has been minimized.

tuukkamustonen commented Apr 21, 2017

I seeing this on 0.16.3 (after upgrade from 0.11.1), with something like:

@task
def foo(ctx):
    ctx.run('git describe')

In general, it works, even when I run it in background:

inv foo &

However, running in background only works when I run it in interactive login shell. When I run it through Jenkins, it fails to similar stacktrace as in original report.

My jenkins slave is a docker container, but slaves connect to them over SSH as usual. No idea if docker here makes any difference.

It used to work in 0.11.1.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Apr 21, 2017

@tuukkamustonen Are you able to get extra info about the value of sys.stdin in that situation? (I don't have a handy Jenkins lying around right now, though I do actually have plans to do some CI work in the near-ish future...)

As in my last comment, the core issue should be that it's evading our attempt to detect whether sys.stdin is attached to a TTY, meaning it's somehow returning True when asked if it has/passes isatty or has a fileno that os.isatty says is a TTY.

I'd assume in a truly headless situation that sys.stdin would be None or at least that it would have isatty() returning False, or that it would lack a fileno, all of which ought to result in us going "ok, is not real, will not try to manipulate".

@tuukkamustonen

This comment has been minimized.

tuukkamustonen commented Apr 22, 2017

I investigated it a bit more. Unfortunately, my initial pointers were a bit off. Sorry for that.

Running task in background actually works just ok, both in login shell and in Jenkins. The problem comes when you try to run in the background in a (bash) sub shell:

(inv foo)& wait

Again, it works in login shell, but fails in Jenkins. Also, running in sub shell works, but running in sub shell combined with running in the background, doesn't.

(Why would I do something like this? Yeah I know it's a bit hacky, but I've been using that for convenience - I run some (deployment) tasks in parallel with something like:

{
    (inv deploy_component1)&
    (inv deploy_component2)&
    wait;
}

This allows not having to have separate Jenkins job for each component... I'm just lazy.)

I'm not sure what debug information to provide about sys.stdin, but in Jenkins repr is:

<_io.TextIOWrapper name='<stdin>' mode='r' encoding='UTF-8'>

For sys.stdin.isatty(), sys.stdout.isatty(), sys.stderr.isatty(), all return False in Jenkins (and True in login shell).

I tried running the commands in parallel using GNU parallel like:

parallel ::: "inv deploy_component1" "inv deploy_component2"

That works also with latest invoke, no issues. I assume GNU parallel works in quite a bit different ways...


This may or may not be related to this ticket, please advice if I should open a separate ticket about this.

Consider a task of:

@task
def foo():
    import time
    print("sleeping...")
    time.sleep(2)
    print("running command...")
    run('whoami')
    print("sleeping again...")
    time.sleep(2)
    print("DONE")

When running this in background:

inv foo &

With 0.11.1:

12:35 $ inv foo &
[1] 12364
12:35 $ sleeping...
running command...
whoami
musttu
sleeping again...
DONE

[1]+  Done                    inv foo
12:35 $

With 0.12.0+:

12:36 $ inv foo &
[1] 12515
12:36 $ sleeping...
running command...
whoami

[1]+  Stopped                 inv foo
12:36 $ # task gets halted, like it's waiting for stdout or something
12:38 $ fg  # let's resume it
inv foo
musttu
sleeping again...
DONE
12:38 $

So, in other words, 0.12.0+ halts in the background does not proceed until you bring it to foreground. In 0.11.1, it completes without delay in the background.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Apr 26, 2017

Thanks for the details, that is funny.

I seem to be able to trivially reproduce this even in a regular interactive shell, as long as I do something using invoke.run here < /dev/null, i.e. replacing normal stdin; that should AFAIK be roughly analogous to running under any headless situation like a CI system.

Not sure why I didn't think to try that in the past, but there it is. So time to dig in a bit, because sys.stdin.isatty() is definitely False here and I assumed that would trigger "we have no PTY" behavior. Will report back.


Re: the other case where the task drops out of background, that's very interesting. IIRC in 0.12 or thereabouts we changed a lot of how stdin is processed, probably including tweaks to the terminal device to make it submit stdin data bytewise instead of linewise. I'm wondering if some of those syscalls are the cause of this.

It's possible the root cause is the same "I'm under a PTY or not" logic, but I don't think so, so unless the issue goes away after I fix the other one, we should probably split that into its own ticket.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Apr 26, 2017

I was going to troubleshoot this soon anyways but literally found it popping up in my dayjob's own headless workers, after I injected some invoke to replace an unhelpful subprocess call. So, I have a handy local test case outside of the /dev/null trick.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Apr 26, 2017

Seems to be two possibly conflated things going on:

  • At a higher level: reading from stdin, which I suspect shouldn't be happening at all in this case, given stdin is effectively null/none/not a file.
    • This would possibly be a failure of the isatty test, as called in Runner.should_echo_stdin
    • Alternately, the logic around that call in that method might be funky itself?
  • At a lower level, because we are apparently reading from stdin anyways: the actual traceback is due to calling ioctl against the bum stdin (within bytes_to_read()), which does not support it, being not a real terminal device.
    • This would be a failure of the has_fileno test, which is presumably passing. Not clear to me why these bad stdins have a fileno but perhaps it's because it is a real channel/pipe at the OS level and it's just that the other end of it is not a terminal.
      • I.e. this might also be problematic when piping as well as the already-verified redirect scenario
@bitprophet

This comment has been minimized.

Member

bitprophet commented Apr 26, 2017

  • When redirected, yes, fileno() still runs OK and yields 0, same as in regular operation, so that's why bytes_to_read is attempting to ioctl.
  • Piping (i.e. echo "something" | python calling invoke) works fine, which IIRC was the test case when we last overhauled and/or generated all of this behavior / these tests.
    • isatty is False in that case, and fileno is still returning 0, but the ioctl call is able to function as intended
  • The 'high level' test in Runner.should_echo_stdin is actually...not helping here, because it's called after the read. So if isatty is a useful test here we need to be calling it earlier, either separately or by moving this check around.
  • Generally, I think we should be just dropping the stdin-reading/mirroring thread entirely in this kind of situation, as it's that much less opportunity for bugs and other issues, as well as just being cleaner and more efficient.
    • I actually have a TODO for making that functionality explicitly opt-out-able; that is an "easy" solution here, though I'd much prefer to find a way of detecting it automatically, even if it's something like altering Runner internal state when exceptions occur like the one here. (e.g. EAFP style).
@bitprophet

This comment has been minimized.

Member

bitprophet commented Apr 26, 2017

Right - so part of the issue is that we were not calling this ioctl stuff (for FIONREAD) prior to solving #58, so that's one reason why it "works better" on older versions in some cases. Prior to that point, the other ioctl calls (around setting stdin to be byte-oriented) were already being skipped when util.isatty() was False.

I doublechecked quickly and that function has the same behavior under pipe as it does under redirect, so I think it's safe to use in this case as well; meaning that one solution may be as simple as changing the if not has_fileno test inside bytes_to_read, to if not isatty; then it will not attempt to discern FIONREAD number of bytes but just returns 1.


Whether we can instead (or also) make the larger change of "don't even run a stdin mirroring thread when not isatty(in_stream), I'm less sure, I'm worried there are edge cases I am not thinking of. Especially the case of "supply a FLO to in_stream so it gets fed into the subprocess' stdin" - I think the thread is the only way that could possibly happen.

So for now I am going to hope the lower level fix is sufficient.

bitprophet added a commit that referenced this issue Apr 26, 2017

bitprophet added a commit that referenced this issue Apr 26, 2017

@bitprophet

This comment has been minimized.

Member

bitprophet commented Apr 26, 2017

@tuukkamustonen if you have time/ability to run off a branch, please battle-test https://github.com/pyinvoke/invoke/tree/avoid-FIONREAD-on-non-tty-fds-425 ? It works for me with my local shell redirect case, I won't be able to test it under a CI like environment (besides the integration test I added...which might be sufficient...?) for a bit though.

EDIT: if https://travis-ci.org/pyinvoke/invoke/builds/226182418 passes that may be another useful data point re: headless operation; I forget offhand exactly how things look to Invoke when running under Travis in that regard, been a while since I had to poke that angle.

@tuukkamustonen

This comment has been minimized.

tuukkamustonen commented Apr 28, 2017

Can't say I understand your analysis, nor do I have time (or brain) to go deeper now. But I gave the branch a spin.

First of all, I can't see Inappropriate ioctl for device errors anymore. Hooray!

About background tasks, on interactive shell:

inv foo &

...behavior remains unaltered, ie. it still halts in the background when it hits run() command (or rather, it halts after running that, I assume it's waiting for stdin or something), and only after running fg, the execution continues (from "sleeping again...").

However, in Jenkins, this doesn't happen. I ran:

inv foo &
inv foo &
sleep 10

Output:

15:09:24 sleeping...
15:09:24 sleeping...
15:09:26 running command...
15:09:26 running command...
15:09:26 jenkins
15:09:26 sleeping again...
15:09:26 jenkins
15:09:26 sleeping again...
15:09:28 DONE
15:09:28 DONE

So, only problem I still find is that in interactive shell, the process halts on run() when running a task in the background. On Jenkins, this doesn't happen.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Apr 28, 2017

@tuukkamustonen -

  • re: core issue working for you too, thanks for testing!
    • I'm close to getting my own headless runner operating in a test environment, so I'll close this once I've triple checked the problem via that avenue.
  • Re: analysis commentary: don't worry, those were all notes to my future self :) never feel obligated to read big blocks of bitprophet comments that don't reference your username! ;)
  • Re: background behavior: as noted earlier I'm suspecting that is a distinct (if probably related) issue. See #439. I'll post some questions for you in there too.

@bitprophet bitprophet changed the title from Invoke 0.14.0 is failing on execution to 'Inappropriate ioctl for device' when using run() in a headless process Apr 28, 2017

@bitprophet

This comment has been minimized.

Member

bitprophet commented May 4, 2017

Finally got my headless runner stuff replicating this and confirm issue present in 0.15 (local pin) and fixed in the branch

Will merge shortly.

@bitprophet bitprophet closed this in d7f19b2 May 4, 2017

bitprophet added a commit that referenced this issue May 4, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment