auth-pam leaves file descriptors open

[TheFang]

OS: Fedora 16
OpenVPN version (from Fedora repo):

OpenVPN 2.2.1 x86_64-redhat-linux-gnu [SSL] [LZO2] [EPOLL] [PKCS11] [eurephia] built on Sep  9 2011
Originally developed by James Yonan
Copyright (C) 2002-2010 OpenVPN Technologies, Inc. <sales@openvpn.net>

  $ ./configure --build=x86_64-redhat-linux-gnu --host=x86_64-redhat-linux-gnu --program-prefix= --disable-dependency-tracking --prefix=/usr --exec-prefix=/usr --bindir=/usr/bin --sbindir=/usr/sbin --sysconfdir=/etc --datadir=/usr/share --includedir=/usr/include --libdir=/usr/lib64 --libexecdir=/usr/libexec --localstatedir=/var --sharedstatedir=/var/lib --mandir=/usr/share/man --infodir=/usr/share/info --enable-pthread --enable-password-save --enable-iproute2 --with-ifconfig-path=/sbin/ifconfig --with-iproute-path=/sbin/ip --with-route-path=/sbin/route

Compile time defines:  ENABLE_CLIENT_SERVER ENABLE_DEBUG ENABLE_EUREPHIA ENABLE_FRAGMENT ENABLE_HTTP_PROXY ENABLE_MANAGEMENT ENABLE_MULTIHOME ENABLE_PASSWORD_SAVE ENABLE_PORT_SHARE ENABLE_SOCKS USE_CRYPTO USE_LIBDL USE_LZO USE_PKCS11 USE_SSL

My openvpn server has been running for some time and suddenly I couldn't log in anymore. I use:
plugin /usr/lib64/openvpn/plugin/lib/openvpn-auth-pam.so login
for logging in (together with client-cert-not-required)

My /var/log/secure shows the following:

Apr  5 10:22:54 localhost openvpn[14811]: PAM unable to dlopen(/lib64/security/pam_securetty.so): /lib64/security/pam_securetty.so: cannot open shared object file: Too many open files
Apr  5 10:22:54 localhost openvpn[14811]: PAM adding faulty module: /lib64/security/pam_securetty.so
Apr  5 10:22:54 localhost openvpn[14811]: PAM _pam_load_conf_file: unable to open /etc/pam.d/system-auth
Apr  5 10:22:54 localhost openvpn[14811]: PAM _pam_load_conf_file: unable to open /etc/pam.d/postlogin
Apr  5 10:22:54 localhost openvpn[14811]: PAM unable to dlopen(/lib64/security/pam_nologin.so): /lib64/security/pam_nologin.so: cannot open shared object file: Too many open files
Apr  5 10:22:54 localhost openvpn[14811]: PAM adding faulty module: /lib64/security/pam_nologin.so
Apr  5 10:22:54 localhost openvpn[14811]: PAM _pam_load_conf_file: unable to open /etc/pam.d/system-auth
Apr  5 10:22:54 localhost openvpn[14811]: PAM _pam_load_conf_file: unable to open /etc/pam.d/system-auth
Apr  5 10:22:54 localhost openvpn[14811]: PAM unable to dlopen(/lib64/security/pam_selinux.so): /lib64/security/pam_selinux.so: cannot open shared object file: Too many open files
Apr  5 10:22:54 localhost openvpn[14811]: PAM adding faulty module: /lib64/security/pam_selinux.so
Apr  5 10:22:54 localhost openvpn[14811]: PAM unable to dlopen(/lib64/security/pam_loginuid.so): /lib64/security/pam_loginuid.so: cannot open shared object file: Too many open files
Apr  5 10:22:54 localhost openvpn[14811]: PAM adding faulty module: /lib64/security/pam_loginuid.so
Apr  5 10:22:54 localhost openvpn[14811]: PAM unable to dlopen(/lib64/security/pam_console.so): /lib64/security/pam_console.so: cannot open shared object file: Too many open files
Apr  5 10:22:54 localhost openvpn[14811]: PAM adding faulty module: /lib64/security/pam_console.so
Apr  5 10:22:54 localhost openvpn[14811]: PAM unable to dlopen(/lib64/security/pam_namespace.so): /lib64/security/pam_namespace.so: cannot open shared object file: Too many open files
Apr  5 10:22:54 localhost openvpn[14811]: PAM adding faulty module: /lib64/security/pam_namespace.so
Apr  5 10:22:54 localhost openvpn[14811]: PAM unable to dlopen(/lib64/security/pam_keyinit.so): /lib64/security/pam_keyinit.so: cannot open shared object file: Too many open files
Apr  5 10:22:54 localhost openvpn[14811]: PAM adding faulty module: /lib64/security/pam_keyinit.so
Apr  5 10:22:54 localhost openvpn[14811]: PAM _pam_load_conf_file: unable to open /etc/pam.d/system-auth
Apr  5 10:22:54 localhost openvpn[14811]: PAM _pam_load_conf_file: unable to open /etc/pam.d/postlogin
Apr  5 10:22:54 localhost openvpn[14811]: PAM unable to dlopen(/lib64/security/pam_deny.so): /lib64/security/pam_deny.so: cannot open shared object file: Too many open files
Apr  5 10:22:54 localhost openvpn[14811]: PAM adding faulty module: /lib64/security/pam_deny.so

An 'lsof | grep openvpn' showed me openvpn used 1055 file descriptors, I think the max is 1024 on my current system settings.
Most of the file descriptors are:

openvpn   14811                root  113u     0000                0,9         0       5456 anon_inode

After a restart it started to work again.
I tested some more, and every time I make a new connection to openvpn, another anon_inode fd is opened. When I close the connection, the fd is not removed (kept open?).

I also run another openvpn server on the same machine, which uses a custom script for logging in. That server doesn't show an increasing number of open file descriptors.

Is there a bug in openvpn-auth-pam.so?
Looking at the Fedora srpms, it looks the 'DLOPEN_PAM' flag is 0, so the library isn't dlopened. I figure the dlopen errors in /var/log/secure are from the PAM library itself.
There is one bit of code I suspect in openvpn-2.2.1/plugin/auth-pam/auth-pam.c (line 433-438)

      /*
       * Background Process
       */

      /* close all parent fds except our socket back to parent */
      close_fds_except (fd[1]);

I'm not familiar with the plugin API, but isn't the plugin loaded for each new connection attempt? It should close all the files if it is.

[David Sommerseth]

A quick intro to how plug-ins work.

When openvpn is setting up configured plug-ins, it loads the plug-in and calls the openvpn_plugin_open_v3() or openvpn_plugin_open_v1() functions. This will initialise the plug-in and prepare it for later actions. It also tells OpenVPN which "hooks" this plug-in supports, like in the user/password authentication in auth-pam's case.

Then each time an even in OpenVPN which supports plug-ins to be called, OpenVPN loops through all loaded plug-ins which have the appropriate "type mask" set for the current event. If it finds a configured plug-in (say, OPENVPN_PLUGIN_AUTH_USER_PASS_VERIFY for user/password authentication) it will then call that plug-ins openvpn_plugin_func_v3(), openvpn_plugin_func_v2() or openvpn_plugin_v1() - depending on which plug-in API the plug-in supports. One of the parameters sent to this function is the "type mask", in addition to environment variables and an additional arguments. The API for all supported API versions is defined in include/openvpn-plugin.h

When OpenVPN is being shut down, it will call openvpn_plugin_close_v1() in each loaded plug-in, which should clean up and shutdown the plug-in.

So to summarize: Each plug-in are loaded and initialised once (via the 'open' function), and the 'func' function is called on each event. And then the 'close' function is called when OpenVPN is shut down.

In regards to auth-pam, it is a fairly advanced plug-in. As it requires root privileges to do some of the authentication, this plug-in fork()s out a child process when being initialised. OpenVPN calls the 'open' functions in the plug-ins before it drops privileges and/or chroots. Then this new child is being daemonised if OpenVPN is told being run as a daemon. This child then starts it's 'main' function, which is the pam_server() function. To communicate with this child, a socket pair is created.

When a OpenVPN clients connect and reaches the phase where it authenticates users with user/passwords, OpenVPN calls the plug-in's 'func' function with OPENVPN_PLUGIN_AUTH_USER_PASS_VERIFY as the type_mask. The 'func' function will then send the username/password over to the fork()ed child via the opened socket pairs and wait for a result. The fork()ed child will receive the username/password with the opened socket and pass it to the PAM infrastructure to do the authentication. When the authentication result is ready, it validates the result and sends a PASS/FAIL result back to the 'func' function via the socket pairs. When the 'func' functions receives the result, it returns either OPENVPN_PLUGIN_FUNC_SUCCESS or OPENVPN_PLUGIN_FUNC_ERROR back to OpenVPN.

I've only looked briefly at the socket handling in auth-pam now, but I don't see how OpenVPN or auth-pam could leak file descriptors. Also based on how this plug-in is written. However, it might be that there's is missing some PAM calls when the authentication has completed for each client which would could leak fds. Or that it's a PAM bug, where it is leaking fds internally.

I'll try to find some time to dig deeper into this, but we have quite a lot of users using auth-pam which have not had any issues like you describe. But by all means, it might just be that they don't have the amount of connections you have before they're restarting OpenVPN or the server itself. But having that said, I'm not fully convinced there is an OpenVPN or auth-pam bug. That needs to be investigated further.

[heisler]

I encountered this same problem on Fedora 17 with openvpn 2.2.2-7 After running for 3 months, openvpn server refused additional logins. I restarted openvpn to get it to run again and noticed this bug. A check of the 'lsof | grep openvpn' showed 'anon_inode' not being closed after a session (in 4 days I have 111 fd's for anon_inode). Any suggestions for what might be causing this?

[Gert Döring]

anon_inode sounds like a temp file that is created, deleted, but not closed.

David, does that ring any bell?

[Samuli Seppänen]

Can this be reproduced on 2.3.x or Git master?

[gitman@…]

Running 2.3.11 release on CentOS 5.11 and experience this about every 30 days. We typically have 3-4 users persistently connected.

Nov 30 22:16:48 noc openvpn[24482]: PAM unable to dlopen(/lib64/security/pam_securetty.so)
Nov 30 22:16:48 noc openvpn[24482]: PAM [error: /lib64/security/pam_securetty.so: cannot open shared object file: Too many open files]
Nov 30 22:16:48 noc openvpn[24482]: PAM adding faulty module: /lib64/security/pam_securetty.so
Nov 30 22:16:48 noc openvpn[24482]: PAM _pam_load_conf_file: unable to open /etc/pam.d/system-auth
Nov 30 22:16:48 noc openvpn[24482]: PAM unable to dlopen(<*unknown module path*>)
Nov 30 22:16:48 noc openvpn[24482]: PAM [error: <*unknown module path*>: cannot open shared object file: Too many open files]
Nov 30 22:16:48 noc openvpn[24482]: PAM adding faulty module: <*unknown module path*>
Nov 30 22:16:48 noc openvpn[24482]: PAM unable to dlopen(/lib64/security/pam_nologin.so)
Nov 30 22:16:48 noc openvpn[24482]: PAM [error: /lib64/security/pam_nologin.so: cannot open shared object file: Too many open files]
Nov 30 22:16:48 noc openvpn[24482]: PAM adding faulty module: /lib64/security/pam_nologin.so
Nov 30 22:16:48 noc openvpn[24482]: PAM _pam_load_conf_file: unable to open /etc/pam.d/system-auth
Nov 30 22:16:48 noc openvpn[24482]: PAM _pam_load_conf_file: unable to open /etc/pam.d/system-auth
Nov 30 22:16:48 noc openvpn[24482]: PAM unable to dlopen(/lib64/security/pam_selinux.so)
Nov 30 22:16:48 noc openvpn[24482]: PAM [error: /lib64/security/pam_selinux.so: cannot open shared object file: Too many open files]
Nov 30 22:16:48 noc openvpn[24482]: PAM adding faulty module: /lib64/security/pam_selinux.so
Nov 30 22:16:48 noc openvpn[24482]: PAM _pam_load_conf_file: unable to open /etc/pam.d/system-auth
Nov 30 22:16:48 noc openvpn[24482]: PAM unable to dlopen(/lib64/security/pam_loginuid.so)
Nov 30 22:16:48 noc openvpn[24482]: PAM [error: /lib64/security/pam_loginuid.so: cannot open shared object file: Too many open files]
Nov 30 22:16:48 noc openvpn[24482]: PAM adding faulty module: /lib64/security/pam_loginuid.so
Nov 30 22:16:48 noc openvpn[24482]: PAM unable to dlopen(/lib64/security/pam_console.so)
Nov 30 22:16:48 noc openvpn[24482]: PAM [error: /lib64/security/pam_console.so: cannot open shared object file: Too many open files]
Nov 30 22:16:48 noc openvpn[24482]: PAM adding faulty module: /lib64/security/pam_console.so
Nov 30 22:16:48 noc openvpn[24482]: PAM unable to dlopen(/lib64/security/pam_keyinit.so)
Nov 30 22:16:48 noc openvpn[24482]: PAM [error: /lib64/security/pam_keyinit.so: cannot open shared object file: Too many open files]
Nov 30 22:16:48 noc openvpn[24482]: PAM adding faulty module: /lib64/security/pam_keyinit.so
Nov 30 22:16:48 noc openvpn[24482]: PAM unable to dlopen(/lib64/security/pam_mkhomedir.so)
Nov 30 22:16:48 noc openvpn[24482]: PAM [error: /lib64/security/pam_mkhomedir.so: cannot open shared object file: Too many open files]
Nov 30 22:16:48 noc openvpn[24482]: PAM adding faulty module: /lib64/security/pam_mkhomedir.so
Nov 30 22:16:48 noc openvpn[24482]: PAM unable to dlopen(/lib64/security/pam_deny.so)
Nov 30 22:16:48 noc openvpn[24482]: PAM [error: /lib64/security/pam_deny.so: cannot open shared object file: Too many open files]
Nov 30 22:16:48 noc openvpn[24482]: PAM adding faulty module: /lib64/security/pam_deny.so

# lsof -n | grep openvpn | grep "can't identify protocol" | wc -l
1018

[Gert Döring]

I think this is a bug on the PAM side, outside OpenVPN's scope.

I have a fairly busy server on FreeBSD here, that is using plugin-auth-pam and FreeBSD's pam_radius to do our token handling. If I do an lsof on that process, I see 5 file descriptors in use, after running since May20 (3.5 months), handling a few thousand logins...

That said, using deferred authentication with the new plugin-auth-pam shipped in git master and 2.5.0 ("to be released in a few weeks") this problem can be circumvented, as it will do all the PAM handling in a per-client background process. So whatever PAM leaks will be of no consequence then.

To use, get a git master or 2.5_beta3 (or later) version, compile the plugin there - it's compatible with 2.4.x servers, so no need to upgrade the server - and put this into your openvpn config:

setenv deferred_auth_pam 1
setenv verb 9

(without the setenv, it will just do foreground request handling, in a single process, as before). Logging has also been improved, so you should see plugin log appear in the openvpn log now. Remove the setenv verb 9 if it is too much noise.

(The new plugin will not work with OpenVPN 2.3.x, as that is missing functions on the plugin API that we now use, most notably logging - but due to better crypto etc. you want to upgrade to 2.4.9 anyway)