supervisorctl takes too long to execute command

[gilles]

[root@ip-10-245-174-225] ~ $ supervisorctl stop XXX
^CTraceback (most recent call last):
File "/usr/local/bin/supervisorctl", line 9, in
load_entry_point('supervisor==3.0a12', 'console_scripts', 'supervisorctl')()
File "/usr/local/lib/python2.6/dist-packages/supervisor/supervisorctl.py", line 1114, in main
c.onecmd(" ".join(options.args))
File "/usr/local/lib/python2.6/dist-packages/supervisor/supervisorctl.py", line 144, in onecmd
return do_func(arg)
File "/usr/local/lib/python2.6/dist-packages/supervisor/supervisorctl.py", line 732, in do_stop
result = supervisor.stopProcess(name)
File "/usr/lib/python2.6/xmlrpclib.py", line 1199, in call
return self.__send(self.__name, args)
File "/usr/lib/python2.6/xmlrpclib.py", line 1489, in __request
verbose=self.__verbose
File "/usr/local/lib/python2.6/dist-packages/supervisor/xmlrpc.py", line 463, in request
r = self.connection.getresponse()
File "/usr/lib/python2.6/httplib.py", line 990, in getresponse
response.begin()
File "/usr/lib/python2.6/httplib.py", line 391, in begin
version, status, reason = self._read_status()
File "/usr/lib/python2.6/httplib.py", line 349, in _read_status
line = self.fp.readline()
File "/usr/lib/python2.6/socket.py", line 427, in readline
data = recv(1)
KeyboardInterrupt

supervisorctl status show 'STOPPED' and the process does not exists.
The log file shows:
2012-06-19 14:31:08,722 INFO stopped: XXX (terminated by SIGTERM)

I can turn on more debugging if you need

[gilles]

It's happening on 3.0a12 and 3.0a8

[gilles]

Here are some strace. This is on a debian squeeze box. Note that we don't see the problem on a CentOS5

supervisord strace: strace -p 1467 2>&1 | grep SIG
kill(1494, SIGTERM) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
wait4(-1, [{WIFSIGNALED(s) && WTERMSIG(s) == SIGTERM}], WNOHANG, NULL) = 1494

=> Appears immediately after the stop command is issued, no other mention of process 1494

Chilld process strace: strace -p 1494
accept(296, {sa_family=AF_INET6, sin6_port=htons(49644), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 15
futex(0x21a01f0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x18d9680, FUTEX_WAKE_PRIVATE, 1) = 1
accept(296, {sa_family=AF_INET6, sin6_port=htons(49676), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 83
futex(0x1610370, FUTEX_WAKE_PRIVATE, 1) = 1
accept(296, {sa_family=AF_INET6, sin6_port=htons(49715), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 15
futex(0x1ea9a10, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x18d9680, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x21ad150, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x18d9680, FUTEX_WAKE_PRIVATE, 1) = 1
accept(296, 0x7fff2be93050, [28]) = ? ERESTARTSYS (To be restarted)
--- SIGTERM (Terminated) @ 0 (0) ---
Process 1494 detached

=> Appears immediately after the stop command is issued

=> The process is marked as 'STOPPED' and the process does not exists anymore almost immediately after the command is issued

The stop command supervisorctl stop service:service_X appears to hang but just takes a long time to complete:
date; supervisorctl stop service:service_X; date
Thu Jun 28 13:07:36 EDT 2012
service:service_X: stopped
Thu Jun 28 13:18:10 EDT 2012

Note: sometimes the start command takes a long time to complete too:
date; supervisorctl start service:service_X; date
Thu Jun 28 13:23:02 EDT 2012
service:service_X: started
Thu Jun 28 13:23:29 EDT 2012

Note: supervisord.log shows the process stopped almost immediately after the command is executed:
2012-06-28 13:07:36,390 INFO stopped: service_X (terminated by SIGTERM)

[beniwohli]

I'm seeing the same problem on one server (but not on others):

# date; supervisorctl stop project_main_gunicorn; date
Wed Jul 11 17:50:07 CEST 2012
project_main_gunicorn: stopped
Wed Jul 11 18:52:14 CEST 2012

Yes, more than one hour.

supervisor.log:

2012-07-11 17:50:08,468 INFO stopped: project_main_gunicorn (exit status 0)

This is a huge problem for us, since it basically makes an automated deployment impossible. If you need more information, just let me know.

[thieman]

I'm also experiencing this issue using 3.0a12 and Python 2.7.2 on Ubuntu 11.10.

[dcrosta]

Does anyone have a solution or work-around for this? We're seeing it with supervisor 3.0a12 on a variety of platforms (Centos 6.2, 6.3, and Amazon Linux 2012.03).

[beniwohli]

@dcrosta in my case I reported above, it turned out that one task was restarting all the time, and blocking supervisord. I'm not sure why supervisor didn't back off restarting the task, my guess is that it took slightly longer to start up and die than the "it's alive!"-threshold. But I didn't have the time to investigate it further.

[dcrosta]

@piquadrat Hmm, I don't think we have that issue on my end. In some cases, there's just one long-lived process managed by supervisord (though admittedly that process takes sometimes up to 10s to quit on its own after receiving SIGTERM).

If someone can point me in the right direction, I'd be happy to help gather more data about what's going on.

[caioariede]

+1 for this issue on CentOS 6

[RealJTG]

Same problem on CentOS 6 + gunicorn. Supervisorctl succesfully start/stop task and hangs

supervisorctl stop mysite
Zzzzzzz

^CTraceback (most recent call last):
  File "/usr/bin/supervisorctl", line 6, in <module>
    main()
  File "/usr/lib/python2.6/site-packages/supervisor/supervisorctl.py", line 598, in main
    c.onecmd(" ".join(options.args))
  File "/usr/lib/python2.6/site-packages/supervisor/supervisorctl.py", line 86, in onecmd
    return func(arg)
  File "/usr/lib/python2.6/site-packages/supervisor/supervisorctl.py", line 433, in do_stop
    result = supervisor.stopProcess(processname)
  File "/usr/lib64/python2.6/xmlrpclib.py", line 1199, in __call__
    return self.__send(self.__name, args)
  File "/usr/lib64/python2.6/xmlrpclib.py", line 1489, in __request
    verbose=self.__verbose
  File "/usr/lib/python2.6/site-packages/supervisor/options.py", line 1308, in request
    errcode, errmsg, headers = h.getreply()
  File "/usr/lib64/python2.6/httplib.py", line 1064, in getreply
    response = self._conn.getresponse()
  File "/usr/lib64/python2.6/httplib.py", line 990, in getresponse
    response.begin()
  File "/usr/lib64/python2.6/httplib.py", line 391, in begin
    version, status, reason = self._read_status()
  File "/usr/lib64/python2.6/httplib.py", line 349, in _read_status
    line = self.fp.readline()
  File "/usr/lib64/python2.6/socket.py", line 433, in readline
    data = recv(1)
KeyboardInterrupt

logs

2013-01-09 18:04:23,044 DEBG XML-RPC method called: supervisor.getVersion()
2013-01-09 18:04:23,044 DEBG XML-RPC method supervisor.getVersion() returned successfully
2013-01-09 18:04:23,044 INFO localhost:0 - - [09/Jan/2013:16:04:23 +0200] "POST /RPC2 HTTP/1.0" 200 254
2013-01-09 18:04:23,045 DEBG XML-RPC method called: supervisor.stopProcess()
2013-01-09 18:04:23,045 DEBG XML-RPC method supervisor.stopProcess() returned successfully
2013-01-09 18:04:23,045 DEBG killing mysite (pid 6320) with signal SIGTERM
2013-01-09 18:04:23,376 INFO stopped: mysite (exit status 0)
2013-01-09 18:04:23,377 INFO received SIGCLD indicating a child quit

[tsharju]

Has anyone found a solution to this problem? I'm facing similar issues with supervisor version 3.0a8 running on Ubuntu 12.04. Installed supervisor using apt. Problem is exactly same as described above. I run supervisorctl stop myapp and the application stops, but supervisorctl just hangs. Any help is greatly appreciated here.

[tobsch]

me to. any way out of this?

[tobsch]

okay, in my case it seems that one of the processes i am watching was constantly printing out messages.
this seems to keep supervisor too busy to return the rpc call!?

[philipcristiano]

Suffering from this as well on Ubuntu 12.04 with 3.0a8 and 3.0b1, sometimes up to 5 minutes to restart a process.

[amcmanus]

Any progress on this bug? We're seeing it on CentOS 5 and 6, supervisor 3.0a12.

[daenney]

Same here. We though we originally fixed it by fixing some bogus things with a child process but that just turned out to be a side-effect.

The quick fix to this issue is restart supervisord, after we do that it starts responding normally again and can take upto a month or two before it starts to exhibit this behaviour. I'm still convinced this is somehow triggered by a child process doing something weird but we haven't been able to pin point it yet.

We do have a strace to accompany the issue:

recvfrom(3, "<?xml version='1.0'?>\n<methodRes"..., 129, 0, NULL, NULL) = 129
stat("/usr/lib/pymodules/python2.6/supervisor/rpcinterface", 0x7fffec5d61a0) = -1 ENOENT (No such file or directory)
open("/usr/lib/pymodules/python2.6/supervisor/rpcinterface.so", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/pymodules/python2.6/supervisor/rpcinterfacemodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/pymodules/python2.6/supervisor/rpcinterface.py", O_RDONLY) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=30019, ...}) = 0
open("/usr/lib/pymodules/python2.6/supervisor/rpcinterface.pyc", O_RDONLY) = 5
fstat(5, {st_mode=S_IFREG|0644, st_size=27233, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7f05911000
read(5, "\321\362\r\n(\2135Pc\0\0\0\0\0\0\0\0\31\0\0\0@\0\0\0s\221\1\0\0d\0"..., 4096) = 4096
fstat(5, {st_mode=S_IFREG|0644, st_size=27233, ...}) = 0
read(5, "dules/python2.6/supervisor/rpcin"..., 20480) = 20480
read(5, "RB\0\0\0(\3\0\0\0R\24\0\0\0t\4\0\0\0typeR&\0\0\0(\0\0"..., 4096) = 2657
read(5, "", 4096)                       = 0
close(5)                                = 0
munmap(0x7f7f05911000, 4096)            = 0
stat("/usr/lib/pymodules/python2.6/supervisor/events", 0x7fffec5d2c00) = -1 ENOENT (No such file or directory)
open("/usr/lib/pymodules/python2.6/supervisor/events.so", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/pymodules/python2.6/supervisor/eventsmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/pymodules/python2.6/supervisor/events.py", O_RDONLY) = 5
fstat(5, {st_mode=S_IFREG|0644, st_size=6224, ...}) = 0
open("/usr/lib/pymodules/python2.6/supervisor/events.pyc", O_RDONLY) = 6
fstat(6, {st_mode=S_IFREG|0644, st_size=11881, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7f05911000
read(6, "\321\362\r\n(\2135Pc\0\0\0\0\0\0\0\0\4\0\0\0@\0\0\0s\237\2\0\0d\0"..., 4096) = 4096
fstat(6, {st_mode=S_IFREG|0644, st_size=11881, ...}) = 0
read(6, "or/events.pyR\23\0\0\0H\0\0\0s\4\0\0\0\0\1\t\1c\1"..., 4096) = 4096
read(6, "on2.6/supervisor/events.pyR-\0\0\0\217"..., 4096) = 3689
read(6, "", 4096)                       = 0
close(6)                                = 0
munmap(0x7f7f05911000, 4096)            = 0
close(5)                                = 0
close(4)                                = 0
close(3)                                = 0
socket(PF_FILE, SOCK_STREAM, 0)         = 3
connect(3, {sa_family=AF_FILE, path="/var/run/supervisor.sock"}, 26) = 0
sendto(3, "POST /RPC2 HTTP/1.1\r\nHost: local"..., 186, 0, NULL, 0) = 186
sendto(3, "<?xml version='1.0'?>\n<methodCal"..., 177, 0, NULL, 0) = 177
recvfrom(3, 

As you can see, which is also clear from @gilles backtrace we're just waiting, to infinity and beyond. This timeouts after approximately 15 minutes.

This all happens for us on superivsor 3.0b1 and odly enough is only happening on the machines that supervise nodejs processes, the ruby-only clusters are completely unaffected in our case (or the bug just hasn't shown up yet).