Hanging on prompt setup

[ianmiell]

Hanging on prompt setup

[aidanhs]

So the last thing we see is what we've just sent, echoed back at us.
Interestingly, it says "SHUTIT_BACKUP_PS1_real_user_prompt=$PS1 && PS1='SHUTIT_REAL_USER#gEtgi>' && unset PROMPT_COMMAND" is the last 100 chars, but there aren't 100 chars there.

So since the last expect that was successfully met, we've sent characters and nothing is happening.
Looking at the code, I can't see a previous expect - we don't appear to check the prompt is ready for either the host child or container child so I guess we're rushing to try and do something on the host child before we're ready? Maybe? Though that can't be the whole story because in the timeout period we'd see more than the 96 characters we got after the prompt actually initialises.

I'm pretty sure we used to sync with the host/container prompt before we jump in - did it get removed for some reason?

[ianmiell]

Here's the code you can see the expect after the spawn, and then the send
and expects:

                container_child = pexpect.spawn(docker_command[0],
docker_command[1:])
                expect =
['assword',cfg['expect_prompts']['base_prompt'].strip(),'Waiting','ulling','endpoint','Download']
                res = container_child.expect(expect,9999)
                while True:
                        if res == 0:
                                res =
shutit.send_and_expect(cfg['host']['password'],child=container_child,expect=expect,timeout=9999,check_exit=False,fail_on_empty_before=False)
                        elif res == 1:
                                break
                        else:
                                print container_child.before +
container_child.after
                                res = container_child.expect(expect,9999)
                                continue

I tried reverting the previous code (I changed this recently to aid
downloads) and it had the same behaviour. I might have got that wrong
somehow though.

What I don't understand is why it's not consistent.

[ianmiell]

Bizzarrely, putting in print statements seems to fix it.

[ianmiell]

I spoke too soon:

Running: sudo docker --version


Command being run is:

sudo docker run --cidfile=/tmp/imiell_cidfile_lp01728_imiell_1402643370.61 --privileged=true -h=mycontainerhostname -v=/space/git/shutit/resources:/resources -t -i ubuntu:12.04 /bin/bash


This may download the image, please be patient


Prompt found, breaking out
Slept
Opening file
SHUTIT_BACKUP_PS1_real_user_prompt=$PS1 && PS1='SHUTIT_REAL_USER#9Y3vi>' && unset PROMPT_COMMAND
SHUTIT_BACKUP_PS1_real_user_prompt=$PS1 && PS1='SHUTIT_REAL_USER#9Y3vi>' && unset PROMPT_COMMAND
Traceback (most recent call last):
  File "/space/git/shutit/shutit", line 553, in <module>
    shutit_main()
  File "/space/git/shutit/shutit", line 507, in shutit_main
    conn_container(shutit)
  File "/space/git/shutit/shutit", line 184, in conn_container
    list(shutit.conn_modules)[0].build(shutit)
  File "/space/git/shutit/shutit_module.py", line 53, in wrapper
    ret = func(self, shutit)
  File "/space/git/shutit/setup.py", line 215, in build
    shutit.setup_prompt('real_user_prompt','REAL_USER')
  File "/space/git/shutit/shutit_global.py", line 555, in setup_prompt
    fail_on_empty_before=False,timeout=5)
  File "/space/git/shutit/shutit_global.py", line 215, in send_and_expect
    expect_res = child.expect(expect,timeout)
  File "/usr/lib/python2.7/dist-packages/pexpect.py", line 1311, in expect
    return self.expect_list(compiled_pattern_list, timeout, searchwindowsize)
  File "/usr/lib/python2.7/dist-packages/pexpect.py", line 1325, in expect_list
    return self.expect_loop(searcher_re(pattern_list), timeout, searchwindowsize)
  File "/usr/lib/python2.7/dist-packages/pexpect.py", line 1409, in expect_loop
    raise TIMEOUT (str(e) + '\n' + str(self))
pexpect.TIMEOUT: Timeout exceeded in read_nonblocking().
<pexpect.spawn object at 0x1921f10>
version: 2.3 ($Revision: 399 $)
command: /bin/bash
args: ['/bin/bash']
searcher: searcher_re:
    0: re.compile("
SHUTIT_REAL_USER#9Y3vi>")
buffer (last 100 chars): SHUTIT_BACKUP_PS1_real_user_prompt=$PS1 && PS1='SHUTIT_REAL_USER#9Y3vi>' && unset PROMPT_COMMAND

before (last 100 chars): SHUTIT_BACKUP_PS1_real_user_prompt=$PS1 && PS1='SHUTIT_REAL_USER#9Y3vi>' && unset PROMPT_COMMAND

after: <class 'pexpect.TIMEOUT'>
match: None
match_index: None
exitstatus: None
flag_eof: False
pid: 18567
child_fd: 4
closed: False
timeout: 30
delimiter: <class 'pexpect.EOF'>
logfile: <open file '<stdout>', mode 'w' at 0x7f3d48d141e0>
logfile_read: None
logfile_send: None
maxread: 2000
ignorecase: False
searchwindowsize: 1024
delaybeforesend: 0.05
delayafterclose: 0.1
delayafterterminate: 0.1

[ianmiell]

And with debug:

imiell@lp01728:/space/git/shutit/library/adduser$ /space/git/shutit/shutit build --debug
LOG: 2014-06-13 08:15:03 Loading source for: /space/git/shutit/setup.py
LOG: 2014-06-13 08:15:03 ShutIt module paths now: 
LOG: 2014-06-13 08:15:03 ['.']
LOG: 2014-06-13 08:15:04 Loading source for: /space/git/shutit/library/adduser/adduser.py
LOG: 2014-06-13 08:15:04 PHASE: base setup
{'container': {'name': '', 'locale': 'en_US.UTF-8', 'hostname': 'mycontainerhostname', 'force_repo_work': False, 'rm': False, 'password': 'mycontainerpassword', 'ports': '', 'docker_image': 'ubuntu:12.04'}, 'users': {}, 'repository': {'password': 'YOUR_INDEX_PASSWORD_OR_BLANK', 'name': 'my_repository_name', 'suffix_format': '%s', 'suffix_date': True, 'server': '', 'tag': True, 'export': False, 'user': '', 'push': False, 'save': False, 'email': 'YOUR_INDEX_EMAIL_OR_BLANK'}, 'shutit_home': '/home/imiell/.shutit', 'expect_prompts': {'base_prompt': '\r\n.*[@#$]'}, 'host': {'username': 'imiell', 'docker_executable': 'sudo docker', 'password': '^78yuihjk', 'shutit_module_paths': ['.'], 'logfile': '', 'dns': '', 'resources_dir': '/space/git/shutit/resources', 'real_user': 'imiell', 'real_user_id': '1043'}, 'build': {'build_id': 'lp01728_imiell_1402643703.62', 'action_on_ret_code': 'error', 'extra_configs': [], 'container_build_log': '/tmp/shutit_log_lp01728_imiell_1402643703.62', 'debug': True, 'build_log': False, 'lxc_conf': '', 'allowed_images': [u'any'], 'command_pause': 0.05, 'config_overrides': [], 'report': '', 'base_image': 'ubuntu:12.04', 'privileged': False, 'interactive': 0}, 'shutit.tk.adduser.adduser': {'build_ifneeded': False, 'remove': False, 'do_repository_work': False, 'build': True, 'password': 'apassword', 'user': 'ausername'}, 'action': {'build': True, 'show_depgraph': False, 'serve': False, 'skeleton': False, 'show_config': False}, 'config_parser': <util.LayerConfigParser instance at 0x2a50950>, 'shutit.tk.setup': {'do_update': True, 'build_ifneeded': False, 'remove': False, 'do_repository_work': False, 'build': True, 'packages': []}}
Running: sudo docker --version


Command being run is:

sudo docker run --cidfile=/tmp/imiell_cidfile_lp01728_imiell_1402643703.62 --privileged=true -h=mycontainerhostname -v=/space/git/shutit/resources:/resources -t -i ubuntu:12.04 /bin/bash


This may download the image, please be patient


Prompt found, breaking out
Slept
Opening file
cid: 7bd3b68f6ba8bfb742a2519c18aa7401971c6025bd0f6b903fb4752cce9078f0
LOG: 2014-06-13 08:15:06 Creating host child
Spawning host child
LOG: 2014-06-13 08:15:06 Setting up default prompt on host child
LOG: 2014-06-13 08:15:06 ================================================================================
LOG: 2014-06-13 08:15:06 Sending>>>SHUTIT_BACKUP_PS1_real_user_prompt=$PS1 && PS1='SHUTIT_REAL_USER#pa9TW>' && unset PROMPT_COMMAND<<<
LOG: 2014-06-13 08:15:06 Expecting>>>
SHUTIT_REAL_USER#pa9TW><<<
SHUTIT_BACKUP_PS1_real_user_prompt=$PS1 && PS1='SHUTIT_REAL_USER#pa9TW>' && unset PROMPT_COMMAND
SHUTIT_BACKUP_PS1_real_user_prompt=$PS1 && PS1='SHUTIT_REAL_USER#pa9TW>' && unset PROMPT_COMMAND
Traceback (most recent call last):
  File "/space/git/shutit/shutit", line 553, in <module>
    shutit_main()
  File "/space/git/shutit/shutit", line 507, in shutit_main
    conn_container(shutit)
  File "/space/git/shutit/shutit", line 184, in conn_container
    list(shutit.conn_modules)[0].build(shutit)
  File "/space/git/shutit/shutit_module.py", line 53, in wrapper
    ret = func(self, shutit)
  File "/space/git/shutit/setup.py", line 217, in build
    shutit.setup_prompt('real_user_prompt','REAL_USER')
  File "/space/git/shutit/shutit_global.py", line 555, in setup_prompt
    fail_on_empty_before=False,timeout=5)
  File "/space/git/shutit/shutit_global.py", line 215, in send_and_expect
    expect_res = child.expect(expect,timeout)
  File "/usr/lib/python2.7/dist-packages/pexpect.py", line 1311, in expect
    return self.expect_list(compiled_pattern_list, timeout, searchwindowsize)
  File "/usr/lib/python2.7/dist-packages/pexpect.py", line 1325, in expect_list
    return self.expect_loop(searcher_re(pattern_list), timeout, searchwindowsize)
  File "/usr/lib/python2.7/dist-packages/pexpect.py", line 1409, in expect_loop
    raise TIMEOUT (str(e) + '\n' + str(self))
pexpect.TIMEOUT: Timeout exceeded in read_nonblocking().
<pexpect.spawn object at 0x2a605d0>
version: 2.3 ($Revision: 399 $)
command: /bin/bash
args: ['/bin/bash']
searcher: searcher_re:
    0: re.compile("
SHUTIT_REAL_USER#pa9TW>")
buffer (last 100 chars): SHUTIT_BACKUP_PS1_real_user_prompt=$PS1 && PS1='SHUTIT_REAL_USER#pa9TW>' && unset PROMPT_COMMAND

before (last 100 chars): SHUTIT_BACKUP_PS1_real_user_prompt=$PS1 && PS1='SHUTIT_REAL_USER#pa9TW>' && unset PROMPT_COMMAND

after: <class 'pexpect.TIMEOUT'>
match: None
match_index: None
exitstatus: None
flag_eof: False
pid: 19293
child_fd: 4
closed: False
timeout: 30
delimiter: <class 'pexpect.EOF'>
logfile: <open file '<stdout>', mode 'w' at 0x7f14142251e0>
logfile_read: None
logfile_send: None
maxread: 2000
ignorecase: False
searchwindowsize: 1024
delaybeforesend: 0.05
delayafterclose: 0.1
delayafterterminate: 0.1

[ianmiell]

Seems to happen most on my machine.

[ianmiell]

Closing as a local issue.