Environment
Ubuntu Hardy on a Core2Duo
$ uname -a
Linux r2d2 2.6.24-25-server #1 SMP Tue Oct 20 07:20:02 UTC 2009 x86_64 GNU/Linux
flup 1.03-dev installed into clean virtualenv from pypi using easy_install. Also tried flup from hg repo to check if fixed there but not released to cheeseshop, with no difference.
Lighttp1.5(svn) forwarding FCGI requests to application service
WSGI app is multithreaded, but not multiprocess.
Problem
Once WSGI server has served a request, the process can no longer be terminated by SIGINT (or SIGTERM - same behaviour).
Once the application has dealt with one or more FCGI requests, and I send a SIG(TERM|INT, flup enters a futex brain-dead state. The FCGI worker threads keep serving FCGI requests, but the main thread no longer returns to the select() and thus also no longer call up to the _mainloopPeriodic method. The only way out is sending a SIGQUIT.
Before receiving FCGI requests
Normal termination of process following receipt of SIG(TERM|QUIT).
app logging
$ bin/locatord -D
03:12:48 locatord WARNING Process pid=31261, logging verbosity 10 (>=DEBUG)
03:12:48 locatord INFO Listening on fcgi://localhost:9000
03:12:49 locatord DEBUG in _mainloopPeriodic()...
03:12:50 locatord DEBUG in _mainloopPeriodic()...
03:12:51 locatord DEBUG in _mainloopPeriodic()...
03:12:52 locatord DEBUG in _mainloopPeriodic()...
03:12:53 locatord DEBUG in _mainloopPeriodic()...
03:12:54 locatord DEBUG in _mainloopPeriodic()...
03:12:55 locatord DEBUG in _mainloopPeriodic()...
03:12:56 locatord DEBUG in _mainloopPeriodic()...
03:12:57 locatord DEBUG in _mainloopPeriodic()...
03:12:58 locatord DEBUG in _mainloopPeriodic()...
03:12:59 locatord DEBUG in _mainloopPeriodic()...
03:13:00 locatord DEBUG in _mainloopPeriodic()...
03:13:01 locatord DEBUG in _mainloopPeriodic()...
03:13:02 locatord DEBUG in _mainloopPeriodic()...
03:13:03 locatord DEBUG in _mainloopPeriodic()...
03:13:04 locatord DEBUG in _mainloopPeriodic()...
03:13:05 locatord DEBUG in _mainloopPeriodic()...
03:13:06 locatord WARNING Process pid=31261 exiting
strace output
$ strace -p 31261
Process 31261 attached - interrupt to quit
select(4, [3], [], [], {0, 450000}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:12:58 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:12:59 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:13:00 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:13:01 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:13:02 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:13:03 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:13:04 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:13:05 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = ? ERESTARTNOHAND (To be restarted)
--- SIGINT (Interrupt) @ 0 (0) ---
rt_sigaction(SIGINT, {0x4b8450, [], SA_RESTORER, 0x7f62ab0127d0}, {0x4b8450, [], SA_RESTORER, 0x7f62ab0127d0}, 8) = 0
rt_sigreturn(0x2) = -1 EINTR (Interrupted system call)
rt_sigaction(SIGINT, {0x4b8450, [], SA_RESTORER, 0x7f62ab0127d0}, {0x4b8450, [], SA_RESTORER, 0x7f62ab0127d0}, 8) = 0
rt_sigaction(SIGTERM, {SIG_DFL}, {0x4b8450, [], SA_RESTORER, 0x7f62ab0127d0}, 8) = 0
rt_sigaction(SIGHUP, {SIG_DFL}, {0x4b8450, [], SA_RESTORER, 0x7f62ab0127d0}, 8) = 0
close(3) = 0
futex(0xa7fb80, 0x81 /* FUTEX_??? */, 1) = 1
futex(0x952410, 0x81 /* FUTEX_??? */, 1) = 1
futex(0x9dc350, 0x81 /* FUTEX_??? */, 1) = 1
futex(0xa10d80, 0x81 /* FUTEX_??? */, 1) = 1
futex(0x9e2660, 0x81 /* FUTEX_??? */, 1) = 1
futex(0xa647d0, 0x81 /* FUTEX_??? */, 1) = 1
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xa647d0, 0x81 /* FUTEX_??? */, 1) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:13:06 locatord WARNING Proce"..., 53) = 53
rt_sigaction(SIGINT, {SIG_DFL}, {0x4b8450, [], SA_RESTORER, 0x7f62ab0127d0}, 8) = 0
exit_group(0) = ?
Process 31261 detached
After a single FCGI request
app output
$ bin/locatord -D
03:08:22 locatord WARNING Process pid=30847, logging verbosity 10 (>=DEBUG)
03:08:22 locatord INFO Listening on fcgi://localhost:9000
03:08:23 locatord DEBUG in _mainloopPeriodic()...
03:08:24 locatord DEBUG in _mainloopPeriodic()...
03:08:25 locatord DEBUG in _mainloopPeriodic()...
03:08:26 locatord DEBUG in _mainloopPeriodic()...
03:08:27 locatord DEBUG in _mainloopPeriodic()...
03:08:28 locatord DEBUG in _mainloopPeriodic()...
03:08:29 locatord DEBUG in _mainloopPeriodic()...
03:08:30 locatord DEBUG in _mainloopPeriodic()...
03:08:31 locatord DEBUG in _mainloopPeriodic()...
03:08:32 locatord DEBUG in _mainloopPeriodic()...
03:08:33 locatord DEBUG in _mainloopPeriodic()...
03:08:34 locatord DEBUG in _mainloopPeriodic()...
03:08:35 locatord DEBUG in _mainloopPeriodic()...
03:08:36 locatord DEBUG in _mainloopPeriodic()...
03:08:37 locatord DEBUG in _mainloopPeriodic()...
03:08:38 locatord DEBUG in _mainloopPeriodic()...
03:08:39 locatord DEBUG in _mainloopPeriodic()...
03:08:40 locatord DEBUG in _mainloopPeriodic()...
03:08:41 locatord DEBUG in _mainloopPeriodic()...
03:08:42 locatord DEBUG in _mainloopPeriodic()...
03:08:43 locatord DEBUG in _mainloopPeriodic()...
03:08:44 locatord DEBUG in _mainloopPeriodic()...
03:08:45 locatord DEBUG in _mainloopPeriodic()...
03:08:46 locatord DEBUG in _mainloopPeriodic()...
03:08:47 locatord DEBUG in _mainloopPeriodic()...
03:08:48 locatord DEBUG in _mainloopPeriodic()...
03:08:49 locatord DEBUG in _mainloopPeriodic()...
03:08:50 locatord DEBUG in _mainloopPeriodic()...
03:08:51 locatord DEBUG in _mainloopPeriodic()...
03:08:52 locatord DEBUG in _mainloopPeriodic()...
03:08:53 locatord DEBUG in _mainloopPeriodic()...
03:08:54 locatord DEBUG in _mainloopPeriodic()...
03:08:55 locatord DEBUG in _mainloopPeriodic()...
03:08:56 locatord DEBUG in _mainloopPeriodic()...
03:08:57 locatord INFO GET /roam-dev
03:08:57 locatord DEBUG Site 'roam-dev', service None -> [] (text/html)
03:08:57 locatord DEBUG in _mainloopPeriodic()...
03:08:57 locatord INFO -> []
03:08:58 locatord DEBUG in _mainloopPeriodic()...
03:08:59 locatord DEBUG in _mainloopPeriodic()...
03:09:00 locatord DEBUG in _mainloopPeriodic()...
03:09:01 locatord DEBUG in _mainloopPeriodic()...
03:09:02 locatord DEBUG in _mainloopPeriodic()...
03:09:03 locatord DEBUG in _mainloopPeriodic()...
03:09:04 locatord DEBUG in _mainloopPeriodic()...
strace output
$ strace -p 30847
Process 30847 attached - interrupt to quit
select(4, [3], [], [], {0, 40000}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:39 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:40 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:41 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:42 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:43 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:44 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:45 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:46 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:47 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:48 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:49 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:50 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:51 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:52 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:53 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:54 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:55 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:56 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 1 (in [3], left {0, 590000})
accept(3, {sa_family=AF_INET, sin_port=htons(49523), sin_addr=inet_addr("192.168.11.2")}, [8340947993456803856]) = 4
fcntl(4, F_SETFD, FD_CLOEXEC) = 0
futex(0xa7fb80, 0x81 /* FUTEX_??? */, 1) = 1
futex(0xa647d0, 0x81 /* FUTEX_??? */, 1) = 1
futex(0xa647d0, 0x81 /* FUTEX_??? */, 1) = 1
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x81 /* FUTEX_??? */, 1) = 1
futex(0xa647d0, 0x81 /* FUTEX_??? */, 1) = 1
futex(0xa68e70, 0x80 /* FUTEX_??? */, 0) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:57 locatord DEBUG in _m"..., 53) = 53
futex(0xa68e70, 0x81 /* FUTEX_??? */, 1) = 1
futex(0xa647d0, 0x81 /* FUTEX_??? */, 1) = 1
futex(0xa647d0, 0x81 /* FUTEX_??? */, 1) = 0
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:58 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:08:59 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:09:00 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:09:01 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:09:02 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:09:03 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = 0 (Timeout)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(2, "03:09:04 locatord DEBUG in _m"..., 53) = 53
select(4, [3], [], [], {1, 0}) = ? ERESTARTNOHAND (To be restarted)
--- SIGINT (Interrupt) @ 0 (0) ---
rt_sigaction(SIGINT, {0x4b8450, [], SA_RESTORER, 0x7fa68334b7d0}, {0x4b8450, [], SA_RESTORER, 0x7fa68334b7d0}, 8) = 0
rt_sigreturn(0x2) = -1 EINTR (Interrupted system call)
rt_sigaction(SIGINT, {0x4b8450, [], SA_RESTORER, 0x7fa68334b7d0}, {0x4b8450, [], SA_RESTORER, 0x7fa68334b7d0}, 8) = 0
rt_sigaction(SIGTERM, {SIG_DFL}, {0x4b8450, [], SA_RESTORER, 0x7fa68334b7d0}, 8) = 0
rt_sigaction(SIGHUP, {SIG_DFL}, {0x4b8450, [], SA_RESTORER, 0x7fa68334b7d0}, 8) = 0
close(3) = 0
futex(0x952410, 0x81 /* FUTEX_??? */, 1) = 1
futex(0x9dc350, 0x81 /* FUTEX_??? */, 1) = 1
futex(0xa10d80, 0x81 /* FUTEX_??? */, 1) = 1
futex(0x9e2660, 0x81 /* FUTEX_??? */, 1) = 1
futex(0xa647d0, 0x81 /* FUTEX_??? */, 1) = 1
futex(0xa647d0, 0x80 /* FUTEX_??? */, 0) = 0
futex(0xa647d0, 0x81 /* FUTEX_??? */, 1) = 1
futex(0xa647d0, 0x81 /* FUTEX_??? */, 1) = 0
futex(0xa647d0, 0x81 /* FUTEX_??? */, 1) = 0
futex(0xa7f4a0, 0x80 /* FUTEX_??? */, 0
