Expect fails to spawn more than two commands

Question

I have three interactive console applications: controller, node, client.

I am unable to handle more than two!

The following script produces correct output.

spawn controller
expect "controller>"
spawn node
expect "node>"

While this script does not.

spawn controller
expect "controller>"
spawn node
expect "node>"
spawn client
expect "client>"

And from the output of client one can conclude that controller is not running anymore.

Why? Why did it stop? How can I keep it running?

I tried the same with Python bindings. It didn't work either.

Python 2.7, Pexpect 3.0

UPDATE: python code and output

Python code:

import pexpect

def pp(t, s):
    t.expect(s)
    print t.before + t.after

r = pexpect.spawn('bash ./registry.sh')
c = pexpect.spawn ('bash ./controller.sh')
pp(c, '>')
n = pexpect.spawn ('bash ./node.sh')
pp(n, '>')
cl = pexpect.spawn ('bash ./client.sh')
pp(cl, '>')

cl.sendintr()
n.sendintr()
c.sendintr()
r.sendintr()

Output:

INFO  ds.controller.Main  - Starting Controller
Nov 22, 2013 11:28:34 AM sun.rmi.server.UnicastServerRef logCall
FINER: RMI TCP Connection(1)-127.0.0.1: [127.0.0.1: sun.rmi.transport.DGCImpl[0:0:0, 2]: java.rmi.dgc.Lease dirty(java.rmi.server.ObjID[], long, java.rmi.dgc.Lease)]
INFO  ds.controller.Main  - Registered remote object

controller>
INFO  ds.node.Main  - Starting Node
INFO  ds.node.Main  - Base folder folders/node
INFO  ds.node.Main  - ServerSocket created
Nov 22, 2013 11:28:34 AM sun.rmi.server.UnicastServerRef logCall
FINER: RMI TCP Connection(1)-192.168.1.5: [192.168.1.5: sun.rmi.transport.DGCImpl[0:0:0, 2]: java.rmi.dgc.Lease dirty(java.rmi.server.ObjID[], long, java.rmi.dgc.Lease)]
INFO  ds.node.Main  - Registered remote object as NodeServer-1385116114787
INFO  ds.node.Main  - Created folder folders/node/NodeServer-1385116114787
DEBUG ds.node.Commands  - Connected to controller
Nov 22, 2013 11:28:34 AM sun.rmi.server.UnicastServerRef logCall
FINER: RMI TCP Connection(2)-192.168.1.5: [192.168.1.5: sun.rmi.transport.DGCImpl[0:0:0, 2]: java.rmi.dgc.Lease dirty(java.rmi.server.ObjID[], long, java.rmi.dgc.Lease)]
Nov 22, 2013 11:28:34 AM sun.rmi.server.UnicastServerRef logCall
FINER: RMI TCP Connection(2)-192.168.1.5: [192.168.1.5: ds.node.rmi.NodeFileServerImpl[11d2b4e2:1427f5a9f6b:-7fff, -3656571857937916756]: public abstract java.lang.Integer ds.node.rmi.NodeFileServerInterface.getServerSocketPort() throws java.rmi.RemoteException]
INFO  ds.node.rmi.NodeFileServerImpl  - Start listening on ServerSocketPort
INFO  ds.node.rmi.NodeFileServerImpl  - Returning ServerSocketPort
DEBUG ds.shared.socket.ServerSocketHandler  - Waiting for incomming connections
DEBUG ds.shared.socket.ServerSocketHandler  - Accepted connection
DEBUG ds.shared.socket.ClientSocketHandler  - Connection ID 0
DEBUG ds.shared.socket.ServerSocketHandler  - Set clientHandler: ds.shared.socket.ClientSocketHandler@f31a3e3

node>
Traceback (most recent call last):
  File "../expect/py.py", line 13, in <module>
    pp(cl, '>')
  File "../expect/py.py", line 4, in pp
    t.expect(s)
  File "build/bdist.macosx-10.9-intel/egg/pexpect/__init__.py", line 1410, in expect
  File "build/bdist.macosx-10.9-intel/egg/pexpect/__init__.py", line 1425, in expect_list
  File "build/bdist.macosx-10.9-intel/egg/pexpect/__init__.py", line 1527, in expect_loop
pexpect.TIMEOUT: Timeout exceeded.
<pexpect.spawn object at 0x10cd773d0>
version: 3.0
command: /bin/bash
args: ['/bin/bash', './client.sh']
searcher: <pexpect.searcher_re object at 0x10cd77390>
buffer (last 100 chars): 'ng, java.rmi.dgc.Lease)]\r\nINFO  ds.client.Main  - Registered remote object as Client-1385116115111\r\n'
before (last 100 chars): 'ng, java.rmi.dgc.Lease)]\r\nINFO  ds.client.Main  - Registered remote object as Client-1385116115111\r\n'
after: <class 'pexpect.TIMEOUT'>
match: None
match_index: None
exitstatus: None
flag_eof: False
pid: 2036
child_fd: 6
closed: False
timeout: 30
delimiter: <class 'pexpect.EOF'>
logfile: None
logfile_read: None
logfile_send: None
maxread: 2000
ignorecase: False
searchwindowsize: None
delaybeforesend: 0.05
delayafterclose: 0.1
delayafterterminate: 0.1

I suppose it happens because child processes are not interleaved. Should I use something non-blocking?

Answer 1

Why? Because the processes were filling up their std buffers and were blocked writing to stdout.

Working code. With enough comments to get at the cause of the problem.

#!/usr/bin/python

import pexpect
import threading
import time

# Consumes output of some subprocess in a background thread
class OutletThread(threading.Thread):
    # obj:   pexpect.spawn object
    # delay: time (in seconds) to wait between two reads
    def __init__(self, obj, delay = 1):
        threading.Thread.__init__(self)
        self.obj = obj
        self.on = True
        self.delay = delay
    # main
    def run(self):
        while self.on:
            try:
                self.obj.read_nonblocking(size=2048, timeout=0)
            except pexpect.TIMEOUT:
                pass
            time.sleep(self.delay)

# Brief
#    Print expected output
# Arguments
#    obj:   pexpect.spawn object
#      s:   expected string
# Exceptions
#    pexpect.TIMEOUT if default timeout is not met
def pp(obj, s):
    obj.expect(s)
    print obj.before + obj.after

print("Setting up the environment...")

print("Registry...")
r = pexpect.spawn('./registry.sh')
# Hold a moment for Java RMI Registry to start.
# So that controller can connect properly.
time.sleep(1)

print("Controller...")
c = pexpect.spawn ('./controller.sh')
pp(c, '>')
c_rlt = OutletThread(c)
c_rlt.start()

print("Node...")
n = pexpect.spawn ('./node.sh')
pp(n, '>')
n_rlt = OutletThread(n)
n_rlt.start()

print("Client...")
cl = pexpect.spawn ('./client.sh')
pp(cl, '>')
cl_rlt = OutletThread(cl)
cl_rlt.start()

raw_input("Press Enter to run 'info' at the controller...")

# Disable controller outlet
c_rlt.on = False
# Run command
c.sendline('info')
# Expect output
pp(c, '>')
# Enable controller outlet
c_rlt.on = True

raw_input("Press Enter to exit...")

# Disable and join all outlet threads
c_rlt.on = False
c_rlt.join()
n_rlt.on = False
n_rlt.join()
cl_rlt.on = False
cl_rlt.join()

# Terminate all spawned processes
cl.sendintr()
n.sendintr()
c.sendintr()
r.sendintr()

Output.

Setting up the environment...
Registry...
Controller...
INFO  ds.controller.Main  - Starting Controller
INFO  ds.controller.Main  - Registered remote object

controller>
Node...
INFO  ds.node.Main  - Starting Node
INFO  ds.node.Main  - Base folder folders/node
INFO  ds.node.Main  - ServerSocket created
INFO  ds.node.Main  - Registered remote object as NodeServer-1385415881716
INFO  ds.node.Main  - Created folder folders/node/NodeServer-1385415881716
DEBUG ds.node.Commands  - Connected to controller
INFO  ds.node.rmi.NodeFileServerImpl  - Start listening on ServerSocketPort
INFO  ds.node.rmi.NodeFileServerImpl  - Returning ServerSocketPort
DEBUG ds.shared.socket.ServerSocketHandler  - Waiting for incomming connections
DEBUG ds.shared.socket.ServerSocketHandler  - Accepted connection
DEBUG ds.shared.socket.ClientSocketHandler  - Connection ID 0
DEBUG ds.shared.socket.ServerSocketHandler  - Set clientHandler: ds.shared.socket.ClientSocketHandler@a9c8620

node>
Client...
INFO  ds.client.Main  - Starting Client
INFO  ds.client.Main  - Base folder folders/client
INFO  ds.client.Main  - Registered remote object as Client-1385415882026
DEBUG ds.client.Commands  - Connected to controller.
DEBUG ds.client.Commands  - Connecting to 192.168.1.8:50690
DEBUG ds.client.Commands  - Opened socket connection.

client>
Press Enter to run 'info' at the controller...
 info
DS Controller, version 0.1 (Beta)

Connected nodes:

 * NodeServer-1385415881716
controller>
Press Enter to exit...
Fedors-MacBook-Pro:distributed ted$ ../expect/nv.py 
Setting up the environment...
Registry...
Controller...
INFO  ds.controller.Main  - Starting Controller
INFO  ds.controller.Main  - Registered remote object

controller>
Node...
INFO  ds.node.Main  - Starting Node
INFO  ds.node.Main  - Base folder folders/node
INFO  ds.node.Main  - ServerSocket created
INFO  ds.node.Main  - Registered remote object as NodeServer-1385417858283
INFO  ds.node.Main  - Created folder folders/node/NodeServer-1385417858283
DEBUG ds.node.Commands  - Connected to controller
INFO  ds.node.rmi.NodeFileServerImpl  - Start listening on ServerSocketPort
INFO  ds.node.rmi.NodeFileServerImpl  - Returning ServerSocketPort
DEBUG ds.shared.socket.ServerSocketHandler  - Waiting for incomming connections
DEBUG ds.shared.socket.ServerSocketHandler  - Accepted connection
DEBUG ds.shared.socket.ClientSocketHandler  - Connection ID 0
DEBUG ds.shared.socket.ServerSocketHandler  - Set clientHandler: ds.shared.socket.ClientSocketHandler@1d672476

node>
Client...
INFO  ds.client.Main  - Starting Client
INFO  ds.client.Main  - Base folder folders/client
INFO  ds.client.Main  - Registered remote object as Client-1385417858595
DEBUG ds.client.Commands  - Connected to controller.
DEBUG ds.client.Commands  - Connecting to 192.168.1.8:50883
DEBUG ds.client.Commands  - Opened socket connection.

client>
Press Enter to run 'info' at the controller...
 info
DS Controller, version 0.1 (Beta)

Connected nodes:

 * NodeServer-1385417858283
controller>
Press Enter to exit...

Assets.

• Python 2.7.5
• Pexpect 3.0
• threading and time libraries

Links.

• Pexpect 3.0 documentation
• Python Multithreaded Programming
• 16.2. threading — Higher-level threading interface — Python v2.7.6 documentation

Big thanks to Thomas Kluyver, other pexpect enthusiasts and stackoverflow team.