Debian – saslauthd and PAM: “Too many open files” error – saslauthd restart fixes this – what is wrong

debianpamsaslsaslauthdwinbind

I have a Postfix mail server running Debian Squeeze. SASL authentication for secure SMTP is supported by saslauthd which relies on pam, which relies on winbind.

This pattern seems to be reoccuring every couple of weeks:

  1. Initially, there are no errors in /var/log/auth.log – postfix SMTP is working well
  2. Errors appear in the log after a week or more:

    Dec 5 15:45:22 myhostname saslauthd[32586]: PAM unable to dlopen(/lib/security/pam_winbind.so): /lib/security/pam_winbind.so: cannot open shared object file: Too many open files
    Dec 5 15:45:22 myhostname saslauthd[32586]: PAM adding faulty module: /lib/security/pam_winbind.so
    Dec 5 15:45:22 myhostname saslauthd[32586]: PAM unable to dlopen(/lib/security/pam_deny.so): /lib/security/pam_deny.so: cannot open shared object file: Too many open files
    Dec 5 15:45:22 myhostname saslauthd[32586]: PAM adding faulty module: /lib/security/pam_deny.so
    Dec 5 15:45:22 myhostname saslauthd[32586]: PAM _pam_load_conf_file: unable to open /etc/pam.d/common-auth
    Dec 5 15:45:22 myhostname saslauthd[32586]: PAM error loading (null)
    Dec 5 15:45:22 myhostname saslauthd[32586]: PAM _pam_init_handlers: error reading /etc/pam.d/other
    Dec 5 15:45:22 myhostname saslauthd[32586]: PAM _pam_init_handlers: [Critical error – immediate abort]
    Dec 5 15:45:22 myhostname saslauthd[32586]: PAM error reading PAM configuration file
    Dec 5 15:45:22 myhostname saslauthd[32586]: PAM pam_start: failed to initialize handlers
    Dec 5 15:45:22 myhostname saslauthd[32586]: DEBUG: auth_pam: pam_start failed: Critical error – immediate abort
    Dec 5 15:45:22 myhostname saslauthd[32586]: do_auth : auth failure: [user=dteed] [service=smtp] [realm=] [mech=pam] [reason=PAM start error]
    Dec 5 15:45:32 myhostname saslauthd[32586]: server_exit : master exited: 32586
    Dec 5 15:45:32 myhostname saslauthd[1696]: detach_tty : master pid is: 1696
    Dec 5 15:45:32 myhostname saslauthd[1696]: ipc_init : listening on socket: /var/run/saslauthd/mux

At this time authentication will always fail. It can be verified in testsaslauthd.
Simply restarting saslauthd corrects the problem for another week or two.

I've searched for the error on too many open files and there is nothing solid on what this indicates. Some of the pam modules it complains cannot be opened have nothing to do with the job saslauthd is handling of simply SASL authentication over winbind.

Here is the /etc/pam.d/smtp :

account     required    pam_permit.so
auth        sufficient    pam_winbind.so debug
auth        required      pam_deny.so

I don't want to run saslauthd in the debug (foreground) method. I don't think I need more saslauthd processes – I'm running 5 and this was sufficient on a previous lower powered server. The secure SMTP is an option which is not widely used by our users, but there is probably one connection every couple of minutes using it.

Best Answer

This seems to be a reported bug in samba's winbind, although it was saslauthd which complained. Here is the bug report:

https://bugzilla.samba.org/show_bug.cgi?id=7265

A workaround, until this is released, is to restart winbind and saslauthd every few days (in a cron).