webauthldap(SUNetID): cannot get ticket: Too many open files (24)

Wed Feb 18 16:54:16 EST 2009

Russ Allbery <rra <at> stanford.edu> writes:

> 
> Fletcher Cocquyt <fcocquyt <at> stanford.edu> writes:
> 
> > Hi, I am following the code now on this one - after posting to the
> > webauth list a couple weeks ago we are still experiencing several
> > hundred of these errors per day - we have maxed out our file descriptors
> > hard and soft limits at 64k and verified with running plimit.
> >
> > webauthldap(SUNetID): cannot get ticket: Too many open files (24)
> >
> > Env: Solaris 9, apache 2.0.52, webauth 3.5.4, MIT kerberos krb5-1.4.1
> >
> > Our apache threads are now approaching 250-300 open files (as reported
> > by lsof).
> 
> What does lsof say that these open files are?  Are they all legitimate
> open files that you expect?

yes, they are libraries and many fifofs PIPEs (we use cronolog)
httpd     10260      www    6u  FIFO 0xdb0d3e60        0t0  16070378 (fifofs)
PIPE->0xdb0d3ef4
httpd     10260      www    8u  FIFO 0xd093a340      0t287  16070380 (fifofs)
PIPE->0xd093a3d4
httpd     10260      www    9u  FIFO 0xd0b0e6d4      0t100  16070379 (fifofs)
PIPE->0xd0b0e640
httpd     10260      www   10u  FIFO 0xd093a3d4      0t287  16070380 (fifofs)
PIPE->0xd093a340
httpd     10260      www   11u  FIFO 0xd093a080      0t148  16070382 (fifofs)
PIPE->0xd093a114

> 
> > Hypothesis: This version of webauth & kerberos is somehow not using the
> > 64k file descriptor limit, but is using a 256 file limit and throwing
> > the error on the ticket operations when the apache thread has more than
> > 256 files open.
> 
> Oh, good call.  I should have thought of that.
> 
> Solaris 9 uses a char to store the file descriptor number in the FILE
> struct used in stdio and hence has an artificial limit on the number of
> open file descriptors that can be addressed by stdio.
> 
> If this is the case and Kerberos is using stdio, then there aren't a lot
> of good solutions that I'm aware of.  64-bit builds will also not have
> this problem.  It might be fixed in Solaris 10, but part of the problem is
> that it's hard to fix without changing the binary ABI.  I think there are
> build-time hacks you can use to change the FILE struct, but you have to
> rebuild everything with those hacks and I don't remember the details.
> 

So I recompiled webauth3.5.4 with the latest krb5-1.6.3 and still get the 
error:

[Wed Feb 18 13:32:43 2009] [info] webauthldap: invoked for user SUNetID
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): filter template is 
uid=USER
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): filter is uid=SUNetID
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): initialized sucessfully
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): begins ldap bind
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): set ticket to 
KRB5CCNAME=FILE:/opt/httpd/conf/webauth/krb5cc_ldap
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): search returned 2
 messages
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): retrieved entry DN = 
suRegID=,cn=people,dc=stanford,dc=edu
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): got attrib: 
displayName
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): got attrib: mail
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): got attrib:
 suAffiliation
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): got attrib: 
suDisplayNameLF
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): got attrib: suRegID
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): got attrib: 
suRegisteredName
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): got attrib: 
suRegisteredNameLF
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): got attrib: 
suSunetID
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): got attrib: uid
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): got attrib: 
suPrivilegeGroup
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): search returned 1 
entries
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): found: require 
privgroup

med-irt:dcswiki
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): SUCCEEDED comparing

suPrivilegeGroup=med-irt:dcswiki in suRegID=0a82322c45f946b3bf6e2a996694a2d6,

cn=people,dc=stanford,dc=edu
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): cached this conn - 
cache

size 1
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): returning OK
[Wed Feb 18 13:32:43 2009] [info] webauthldap: finished for user SUNetID
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): getting new ticket
[Wed Feb 18 13:32:43 2009] [error] webauthldap(SUNetID): cannot get ticket: 
Too many open files (24)
[Wed Feb 18 13:32:43 2009] [debug] mod_webauth.c(2363): mod_webauth: in 
check_user_id hook(/errordocs/500err.html)
[Wed Feb 18 13:32:43 2009] [debug] mod_webauth.c(2405): mod_webauth: found 
note, user(SUNetID)
[Wed Feb 18 13:32:43 2009] [debug] mod_webauth.c(2420): mod_webauth: 
check_user_id_hook setting user(SUNetID)
[Wed Feb 18 13:32:43 2009] [warn] mod_webauth: mwa_setenv: (WEBAUTH_USER) 
(SUNetID)
[Wed Feb 18 13:32:43 2009] [debug] mod_webauth.c(2473): mod_webauth:
check_user_id_hook: no_cache(0) dont_cache(0) dont_cache_ex(0)
[Wed Feb 18 13:32:43 2009] [info] webauthldap: invoked for user SUNetID
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): filter template is 
uid=USER
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): filter is uid=SUNetID
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): initialized sucessfully
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): begins ldap bind
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): set ticket to
 KRB5CCNAME=FILE:/opt/httpd/conf/webauth/krb5cc_ldap
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): getting new ticket
[Wed Feb 18 13:32:43 2009] [error] webauthldap(SUNetID): 
cannot get ticket: Too many open files (24)
[Wed Feb 18 13:32:43 2009] [debug] mod_deflate.c(467): [client 171.65.1.170]
Zlib: Compressed 922 to 536 : URL /bb/gifs/bkg-red.gif, referer: http://irt
-bb.stanford.edu/bb/bb2.html
[Wed Feb 18 13:32:43 2009] [debug] mod_webauth.c(2363): mod_webauth: in
check_user_id hook(/bb/gifs/bbnav2.gif)
[Wed Feb 18 13:32:43 2009] [debug] mod_webauth.c(1342): mod_webauth:
parse_app_token_cookie: found valid webauth_at cookie for (SUNetID)
[Wed Feb 18 13:32:43 2009] [debug] mod_webauth.c(2397): mod_webauth: stash note,
user(SUNetID)
[Wed Feb 18 13:32:43 2009] [debug] mod_webauth.c(2420): mod_webauth:
check_user_id_hook setting user(SUNetID)
[Wed Feb 18 13:32:43 2009] [warn] mod_webauth: mwa_setenv: (WEBAUTH_USER) 
(SUNetID)
[Wed Feb 18 13:32:43 2009] [warn] mod_webauth: mwa_setenv: 
(WEBAUTH_TOKEN_EXPIRATION) (1235034932)
[Wed Feb 18 13:32:43 2009] [warn] mod_webauth: mwa_setenv: 
(WEBAUTH_TOKEN_CREATION) (1234991732)
[Wed Feb 18 13:32:43 2009] [debug] mod_webauth.c(2473): mod_webauth:
check_user_id_hook: no_cache(0) dont_cache(0) dont_cache_ex(0)
[Wed Feb 18 13:32:43 2009] [info] webauthldap: invoked for user SUNetID
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): filter template is 
uid=USER
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): filter is uid=SUNetID
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): initialized sucessfully

[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): got cached conn - cache 
size 0
[Wed Feb 18 13:32:43 2009] [info] webauthldap(SUNetID): search returned 2 
messages

thanks