I have this situation where a httpd process will try to use 100% of my
cpu after a fastcgi or normal cgi script has finished doing its thing
-- POST will modified server state and GET will give me the page but
the browser keeps loading and the controlling httpd's cpu usage goes
right up.
This is repeated on either the next request or with a few successful
requests in between and then I have two httpds sitting on around 50%
and a another browser request still active. Once I get to about 4 or
so httpds fighting away the site gets sluggish...
I'm not sure what the pattern is, it can take a while to trigger the
first run away process but then it seems likely that the next one will
go soon.
The problem appears to be with mod_auth_bsd (see backtrace below)
I didn't notice this problem on 4.0-release.
I'm running 4.1-release i386 in VMware Server 1.0.2 under Debian 4.0 amd64
httpd with "-u -DSSL"
Packages:
mod_auth_bsd-0.8.2
mod_fastcgi-2.4.2
python-2.4.4p1
Non ports:
flup 0.5 + patch (fcgi_base.py to r2348)
web.py 0.21
This is the backtrace from one of the run away processes, it is trying
to read from the auth_socket variable in auth_child_userokay() in
/usr/ports/www/mod_auth_bsd/w-mod_auth_bsd-0.8.2/bsdauth-0.8.2/authd.c
(gdb) bt
#0 0x00a85a49 in read () from /usr/lib/libc.so.40.3
#1 0x0822d6ae in auth_child_userokay ()
from /usr/lib/apache/modules/mod_auth_bsd.so
#2 0x0822fa72 in authenticate () from /usr/lib/apache/modules/mod_auth_bsd.so
#3 0x1c0358a9 in ap_cleanup_method_ptrs ()
#4 0x1c035996 in ap_check_user_id ()
#5 0x1c04637f in ap_some_auth_required ()
#6 0x1c0464bf in ap_process_request ()
#7 0x00000000 in ?? ()
This my httpd error_log since the last restart (lots of lines sorry):
[Fri Jul 13 15:41:49 2007] [error] (2)No such file or directory:
FastCGI: access for server (uid 32767, gid 32766) failed: read not
allowed
[Fri Jul 13 15:41:49 2007] [error] (2)No such file or directory:
FastCGI: can't create dynamic directory
"/var/www/logs/fastcgi/dynamic": access for server (uid 32767, gid
32766) failed: read not allowed
[Fri Jul 13 15:41:49 2007] [notice] [AuthBSD] Preparing auth daemon
[Fri Jul 13 15:41:49 2007] [notice] [AuthBSD] Forking auth daemon
[Fri Jul 13 15:41:49 2007] [error] (2)No such file or directory:
FastCGI: access for server (uid 32767, gid 32766) failed: read not
allowed
[Fri Jul 13 15:41:49 2007] [error] (2)No such file or directory:
FastCGI: can't create dynamic directory
"/var/www/logs/fastcgi/dynamic": access for server (uid 32767, gid
32766) failed: read not allowed
[Fri Jul 13 15:41:49 2007] [notice] [AuthBSD] Auth daemon running with pid 2692
[Fri Jul 13 15:41:49 2007] [notice] [AuthBSD] Auth daemon changed
user/group to www/auth
[Fri Jul 13 15:41:49 2007] [notice] FastCGI: process manager
initialized (pid 10504)
[Fri Jul 13 15:41:49 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 10775)
[Fri Jul 13 15:41:50 2007] [notice] Initializing etag from
/var/www/logs/etag-state
[Fri Jul 13 15:41:50 2007] [notice] Apache/1.3.29 (Unix)
mod_fastcgi/2.4.2 mod_ssl/2.8.16 OpenSSL/0.9.7j configured -- resuming
normal operations
[Fri Jul 13 15:41:50 2007] [notice] suEXEC mechanism enabled (wrapper:
/usr/sbin/suexec)
[Fri Jul 13 15:41:50 2007] [notice] Accept mutex: sysvsem (Default: sysvsem)
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:50 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 25035)
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:41:50 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:41:51 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 8986)
[Fri Jul 13 15:41:52 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 25566)
[Fri Jul 13 15:41:53 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 25127)
[Fri Jul 13 15:41:54 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 20578)
[Fri Jul 13 15:41:55 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 12862)
[Fri Jul 13 15:41:56 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 31194)
[Fri Jul 13 15:41:57 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 10954)
[Fri Jul 13 15:41:58 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 8800)
[Fri Jul 13 15:41:59 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 11802)
[Fri Jul 13 15:42:00 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 10701)
[Fri Jul 13 15:42:01 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 13336)
[Fri Jul 13 15:42:02 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 31513)
[Fri Jul 13 15:42:03 2007] [warn] FastCGI: server
"/var/www/cgi-bin/pharmac.py" started (pid 2472)
[Fri Jul 13 15:42:08 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer writing request
[Fri Jul 13 15:42:08 2007] [debug] authd.c(0): [AuthBSD] Auth cache
miss for user ericson
[Fri Jul 13 15:42:08 2007] [debug] authd.c(0): [AuthBSD] Caching
success user ericson
[Fri Jul 13 15:42:08 2007] [debug] authd.c(0): [AuthBSD] Inserting
user into okay cache (0 existing)
[Fri Jul 13 15:42:08 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer wrote request
[Fri Jul 13 15:42:08 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer read answer
[Fri Jul 13 15:42:08 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group ericson?
[Fri Jul 13 15:42:08 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group wheel?
[Fri Jul 13 15:42:08 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group
svn-pharmac?
[Fri Jul 13 15:42:08 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group ericson?
[Fri Jul 13 15:42:08 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group wheel?
[Fri Jul 13 15:42:08 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group
svn-pharmac?
[Fri Jul 13 15:42:09 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:42:09 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:42:11 2007] [debug] authd.c(0): [AuthBSD] Peer read 64
bytes from auth daemon
[Fri Jul 13 15:42:11 2007] [debug] authd.c(0): [AuthBSD] Peer received
auth socket and shared secret
[Fri Jul 13 15:42:23 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer writing request
[Fri Jul 13 15:42:23 2007] [debug] authd.c(0): [AuthBSD] Auth cache
hit for user ericson
[Fri Jul 13 15:42:23 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer wrote request
[Fri Jul 13 15:42:23 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer read answer
[Fri Jul 13 15:42:23 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group ericson?
[Fri Jul 13 15:42:23 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group wheel?
[Fri Jul 13 15:42:23 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group
svn-pharmac?
[Fri Jul 13 15:42:23 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group ericson?
[Fri Jul 13 15:42:23 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group wheel?
[Fri Jul 13 15:42:23 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group
svn-pharmac?
[Fri Jul 13 15:42:50 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer writing request
[Fri Jul 13 15:42:50 2007] [debug] authd.c(0): [AuthBSD] Auth cache
hit for user ericson
[Fri Jul 13 15:42:50 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer wrote request
[Fri Jul 13 15:42:50 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer read answer
[Fri Jul 13 15:42:50 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group ericson?
[Fri Jul 13 15:42:50 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group wheel?
[Fri Jul 13 15:42:50 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group
svn-pharmac?
[Fri Jul 13 15:42:50 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group ericson?
[Fri Jul 13 15:42:50 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group wheel?
[Fri Jul 13 15:42:50 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group
svn-pharmac?
[Fri Jul 13 15:43:06 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer writing request
[Fri Jul 13 15:43:06 2007] [debug] authd.c(0): [AuthBSD] Auth cache
hit for user ericson
[Fri Jul 13 15:43:06 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer wrote request
[Fri Jul 13 15:43:06 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer read answer
[Fri Jul 13 15:43:09 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer writing request
[Fri Jul 13 15:43:09 2007] [debug] authd.c(0): [AuthBSD] Auth cache
hit for user ericson
[Fri Jul 13 15:43:09 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer wrote request
[Fri Jul 13 15:43:09 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer read answer
[Fri Jul 13 15:43:09 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group ericson?
[Fri Jul 13 15:43:09 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group wheel?
[Fri Jul 13 15:43:09 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group
svn-pharmac?
[Fri Jul 13 15:43:09 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group ericson?
[Fri Jul 13 15:43:09 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group wheel?
[Fri Jul 13 15:43:09 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group
svn-pharmac?
[Fri Jul 13 15:43:19 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer writing request
[Fri Jul 13 15:43:19 2007] [debug] authd.c(0): [AuthBSD] Auth cache
hit for user ericson
[Fri Jul 13 15:43:19 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer wrote request
[Fri Jul 13 15:43:19 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer read answer
[Fri Jul 13 15:43:19 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group ericson?
[Fri Jul 13 15:43:19 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group wheel?
[Fri Jul 13 15:43:19 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group
svn-pharmac?
[Fri Jul 13 15:43:19 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group ericson?
[Fri Jul 13 15:43:19 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group wheel?
[Fri Jul 13 15:43:19 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group
svn-pharmac?
[Fri Jul 13 15:43:35 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer writing request
[Fri Jul 13 15:43:35 2007] [debug] authd.c(0): [AuthBSD] Auth cache
hit for user ericson
[Fri Jul 13 15:43:35 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer wrote request
[Fri Jul 13 15:43:35 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer read answer
[Fri Jul 13 15:43:35 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group ericson?
[Fri Jul 13 15:43:35 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group wheel?
[Fri Jul 13 15:43:35 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group
svn-pharmac?
[Fri Jul 13 15:43:35 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group ericson?
[Fri Jul 13 15:43:35 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group wheel?
[Fri Jul 13 15:43:35 2007] [debug] mod_auth_bsd.c(0): [client
172.16.4.59] [AuthBSD] Required group svn-pharmac == group
svn-pharmac?
[Fri Jul 13 15:43:45 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer writing request
[Fri Jul 13 15:43:45 2007] [debug] authd.c(0): [AuthBSD] Auth cache
hit for user ericson
[Fri Jul 13 15:43:45 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer wrote request
[Fri Jul 13 15:43:45 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer read answer
[Fri Jul 13 15:43:49 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer writing request
[Fri Jul 13 15:43:49 2007] [debug] authd.c(0): [AuthBSD] Auth cache
hit for user ericson
[Fri Jul 13 15:43:49 2007] [debug] authd.c(0): [client 172.16.4.59]
[AuthBSD] Peer wrote request
and here are the relevant parts of my httpd.conf:
...
MinSpareServers 15
MaxSpareServers 30
...
StartServers 15
...
MaxClients 150
...
LoadModule proxy_module /usr/lib/apache/modules/libproxy.so
LoadModule fastcgi_module /usr/lib/apache/modules/mod_fastcgi.so
LoadModule bsd_auth_module /usr/lib/apache/modules/mod_auth_bsd.so
...
AuthBSDGroup auth
<Location ~ ".*/props">
SSLRequireSSL
AuthType Basic
AuthName "PHARMAC"
AuthBSD On
Require group svn-pharmac
</Location>
FastCgiServer cgi-bin/pharmac.py -processes 15 -listen-queue-depth 150
-idle-timeout 300 -flush
RewriteEngine On
RewriteCond %{HTTPS} !=on
RewriteRule ^/(props|.*/props) https://%{HTTP_HOST}/$1 [R,L]
RewriteCond %{HTTPS} !=on
RewriteRule ^/(~.*) https://%{HTTP_HOST}/$1 [R,L]
RewriteRule ^/~.* - [L]
RewriteRule ^/(icons|cgi-bin)/.* - [L]
RewriteRule ^/(.*) /cgi-bin/pharmac.py/$1 [PT]
...
UserDir /home/*/public_html
...
<Directory /home/*/public_html>
SSLRequireSSL
AuthType Basic
AuthName "PHARMAC"
AuthBSD On
Require group svn-pharmac
...
</Directory>
...
<VirtualHost _default_:443>
RewriteEngine On
RewriteRule ^/~.* - [L]
RewriteRule ^/(icons|cgi-bin)/.* - [L]
RewriteRule ^/(.*) /cgi-bin/pharmac.py/$1 [PT]
...
I have also upped my openfiles-cur to 1024 for daemon class in
/etc/login.conf (because I was getting "Too many open files" errors
from mod_auth_bsd during load testing)
This is my first post on misc@ so I hope I have included enough detail.
Thanks very much
--
Peter Ericson
