twisted threading with subprocess.Popen?

Question

I'm trying to implement a service with Twisted that's fairly close to the "finger" tutorial found here: http://twistedmatrix.com/documents/current/core/howto/tutorial/intro.html

I've got a basic.LineListener waiting for a command and then executing it, then I have a client connecting and issuing commands. Trouble is that the command sometimes needs to execute something else and I'm using python's subprocess module for that. It's not just that calls to communicate() are hanging, that's a normal subprocess issue and I know how to get past it. It's that subprocess.Popen calls are hanging.

Here's the twisted server code:

from twisted.application import internet, service
from twisted.internet import protocol, reactor, defer, threads
from twisted.protocols import basic
import sys
import time
import subprocess

class MyProtocol(basic.LineReceiver):
    def lineReceived(self, line):
        self.go()
    def go(self):
        def writeResponse(message):
            self.transport.write(message + '\r\n')
            self.transport.loseConnection()
        threads.deferToThread(self.factory.action).addCallback(writeResponse)
    def connectionMade(self):
        self.lines = []

class ActionService(service.Service):
    def __init__(self, **kwargs):
        pass
        #self.users = kwargs

def action(self):
    print "launching subprocess"
    sys.stdout.flush()
    p = subprocess.Popen(["ls"], stderr=subprocess.PIPE, stdout=subprocess.PIPE, stdin=subprocess.PIPE)
    print "launched subprocess, trying to communicate..."
    sys.stdout.flush()
    p.communicate()
    print "returning"
    sys.stdout.flush()
    return "%032d" % (0)

    def getActionFactory(self):
        f = protocol.ServerFactory()
        f.protocol = MyProtocol
        f.action = self.action
        return f

reactor.suggestThreadPoolSize(300)
application = service.Application('Action', uid=0, gid=0)
f = ActionService()
serviceCollection = service.IServiceCollection(application)
internet.TCPServer(31337,f.getActionFactory()
                   ).setServiceParent(serviceCollection)

...and here's some client code:

#!/usr/bin/python
import time
import threading
import socket

def connectAction(host):
    s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
    s.connect((host, 31337))
    s.send("asdf\r\n")
    resp = s.recv(32)
    s.close()
    return resp

class sscceThread(threading.Thread):
    def __init__(self, host):
        self.host = host
        threading.Thread.__init__(self)
    def run(self):
        connectAction(self.host)

def main():
    threads = []
    for i in range(0, 1000):
        for j in range(0,5):
            t = sscceThread("localhost")
            t.start()
            threads.append(t)
        for t in threads:
            t.join()
        print i
        time.sleep(1)
    #    print i

if __name__ == "__main__":
    main()

Start the service by running:

twistd -y sscce_twisted_service.py -l twistdLog; tail -f twistdLog

And run the client by running:

./sscce_twisted_client.py

You should see the client go for a couple of iterations (I've seen it go as many as 10) and then hang. The client code contains a 1-second sleep so that you can tell the difference between twisted log entries from each iteration and on the one that hangs you'll see something like this in the twisted log:

2009-12-22 11:18:47-0800 [MyProtocol,55,127.0.0.1] launching subprocess
2009-12-22 11:18:47-0800 [MyProtocol,56,127.0.0.1] launching subprocess
2009-12-22 11:18:47-0800 [MyProtocol,55,127.0.0.1] launched subprocess, trying to communicate...
2009-12-22 11:18:47-0800 [MyProtocol,57,127.0.0.1]  launching subprocess
2009-12-22 11:18:47-0800 [MyProtocol,58,127.0.0.1] launching subprocess
2009-12-22 11:18:47-0800 [MyProtocol,56,127.0.0.1] launched subprocess, trying to communicate...
2009-12-22 11:18:47-0800 [MyProtocol,55,127.0.0.1] returning
2009-12-22 11:18:47-0800 [MyProtocol,57,127.0.0.1]  launching subprocess 
2009-12-22 11:18:47-0800 [MyProtocol,56,127.0.0.1]  launching subprocess returning
2009-12-22 11:18:47-0800 [MyProtocol,59,127.0.0.1]  launching subprocess
2009-12-22 11:18:47-0800 [MyProtocol,58,127.0.0.1]  launched subprocess, trying to communicate...
2009-12-22 11:18:47-0800 [MyProtocol,58,127.0.0.1] returning
2009-12-22 11:18:47-0800 [MyProtocol,59,127.0.0.1] launched subprocess, trying to communicate...
2009-12-22 11:18:47-0800 [MyProtocol,59,127.0.0.1] returning

Of particular note is MyProtocol,57. It says it was about to try launching the subprocess but it never printed the "launched subprocess, trying to communicate" line. I think it must have hung there.

Answer 1

As mg said in his comment, don't use the subprocess module. On POSIX platforms, it's necessary (more or less) to handle the SIGCHLD signal to deal with child processes that exit. Since there can only be one SIGCHLD handler, multiple libraries generally won't cooperate. Twisted's child process support and the subprocess module's support conflict. Either use Twisted's support (see http://twistedmatrix.com/documents/current/core/howto/process.html) or disable Twisted's support by passing installSignalHandlers=False to reactor.run (I recommend the former, as subprocess presents blocking interfaces which don't integrate well into Twisted-based applications).