Server authentication "hangs"

dsulli99

Hi,

I have kind of a weird problem with OpenVPN that I am hoping somebody can help me diagnose. My configuration is pretty simple and the symptom is obvious, however I am unable to reliably reproduce the problem.

I am using the standard OpenVPN package on Ubuntu 10.04.2 LTS with a bridging/tap interface (br0). I am also using "plugin /usr/lib/openvpn/openvpn-auth-pam.so login" to have OpenVPN authenticate against the local /etc/shadow file (in conjunction with RSA certificates for authentication). I am using easy-rsa as my CA. I'm basically doing the setup that is specified in this document: https://help.ubuntu.com/community/OpenVPN (with the auth-pam.so module added). My OpenVPN package version is 2.1.0-1ubuntu1.1 as reported by "dpkg -s openvpn".

I've actually got everything working fine. Users can authenticate using their credentials in combination with their RSA certificate fine from both Window XP and OS X workstations. They can use the VPN and talk unrestricted to the host through the tunnel without issue. The problem is that after running for a day or two, and for no explainable reason, OpenVPN authentication just "hangs". The server is still listening on the port, but users are unable to authenticate. To fix the problem, all I have to do is restart the OpenVPN service and the problem is fixed. Since I am using easy-rsa and local authentication, I am confused as to what could possibly be breaking in the authentication phase. What I'm seeing in the client side logs is this:

Wed Jun 22 14:34:12 2011 Expected Remote Options hash (VER=V4): '360696c5'
Wed Jun 22 14:34:12 2011 UDPv4 link local: [undef]
Wed Jun 22 14:34:12 2011 UDPv4 link remote: 68.169.149.182:13370
Wed Jun 22 14:34:12 2011 TLS: Initial packet from 68.169.149.182:13370, sid=515b6a80 84a52bbd
Wed Jun 22 14:34:13 2011 VERIFY OK: depth=1, /C=US/ST=TN/L=Chattanooga/O=New_Age_Communications/CN=New_Age_Communications_CA/emailAddress=jctut1@gmail.com
Wed Jun 22 14:34:13 2011 VERIFY OK: depth=0, /C=US/ST=TN/L=Chattanooga/O=New_Age_Communications/CN=server/emailAddress=jctut1@gmail.com
Wed Jun 22 14:34:13 2011 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Wed Jun 22 14:34:13 2011 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Jun 22 14:34:13 2011 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Wed Jun 22 14:34:13 2011 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Jun 22 14:34:13 2011 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
Wed Jun 22 14:34:13 2011 [server] Peer Connection Initiated with 68.169.149.182:13370
Wed Jun 22 14:34:15 2011 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Wed Jun 22 14:34:16 2011 AUTH: Received AUTH_FAILED control message
Wed Jun 22 14:34:16 2011 TCP/UDP: Closing socket
Wed Jun 22 14:34:16 2011 SIGTERM[soft,auth-failure] received, process exiting
Wed Jun 22 14:34:16 2011 OpenVPN 2.2.0 Win32-MSVC++ [SSL] [LZO2] built on Apr 26 2011

Now, I am 100% sure that the password being specified when this occurs is valid. And from what I can tell from the debug logs the certificate is valid as well. Basically I am seeing "SIGTERM[soft,auth-failure] received, process exiting", although I am certain that the password being specified is valid. And as I said earlier, the *only* thing I have to do to fix this problem is restart the OpenVPN service. This is a reliable fix.

I enabled logging on the server side with "log /var/log/openvpn.log", and I don't see anything blaring in the logs that even suggest an authentication failure is actually taking place. So I guess I have two questions;

1) Giving that restarting the OpenVPN service is the only thing required to make the problem go away, can anybody provide insight as to what may be causing this issue?

2) Is there a way to turn up the verbosity on the server side logging to get more visibility into how the daemon is operating?

maikcat

hi there,

you can use verb 5 or higher to increase verbocity

also ,can you post server config as well?

Michael.

ps:is there any chance that the time on ubuntu changes automatically?

dsulli99

Thank-you for the verb. I have updated my server config (I will have to wait to restart the daemon).

I do see a bunch of these in my daemon.log:

daemon.log:Jun 17 16:47:31 fortuneServer ntpd[1561]: kernel time sync status change 6001
daemon.log:Jun 17 17:21:39 fortuneServer ntpd[1561]: kernel time sync status change 2001
daemon.log:Jun 17 19:21:09 fortuneServer ntpd[1561]: kernel time sync status change 6001
daemon.log:Jun 17 19:38:15 fortuneServer ntpd[1561]: kernel time sync status change 2001
daemon.log:Jun 17 20:12:24 fortuneServer ntpd[1561]: kernel time sync status change 6001
daemon.log:Jun 17 20:29:29 fortuneServer ntpd[1561]: kernel time sync status change 2001

Should I try disabling NTP to troubleshoot this problem?

My server configuration is here:

mode server
tls-server

local 10.0.3.3 ## ip/hostname of server
port 13370 ## default openvpn port
proto udp

#bridging directive
dev tap0 ## If you need multiple tap devices, add them here
up "/etc/openvpn/up.sh br0 tap0 1500"
down "/etc/openvpn/down.sh br0 tap0"

persist-key
persist-tun

#certificates and encryption
ca ca.crt
cert server.crt
key server.key # This file should be kept secret
dh dh1024.pem
tls-auth ta.key 0 # This file is secret

cipher BF-CBC # Blowfish (default)
comp-lzo

#DHCP Information
ifconfig-pool-persist ipp.txt
server-bridge 10.0.3.3 255.255.255.0 10.0.3.241 10.0.3.250
max-clients 10 ## set this to the max number of clients that should be connected at a time

#log and security
user nobody
group nogroup
keepalive 10 120
status openvpn-status.log
log /var/log/openvpn.log
verb 5

#plugin for user credential authentication
plugin /usr/lib/openvpn/openvpn-auth-pam.so login

maikcat

hi there,

i have a few questions/suggestions for start

>max-clients 10

do you have only less than 10 clients?

can you try to disable (for testing) ntp client?

when you set verb 5 and above ,does it logs anything when your clients
fail to connect?

cant think of anything else right now... :cry:

Michael.

dsulli99

Michael,

Yes, I have less than 10 clients. I'll see if I can disable NTP and see if that fixes the problem. Also updated logging verbosity to 5. Thank-you for your suggestions.

Dan

janjust

the NTP warnings are not related , I'd guess with 99.99% certaincy. Please post the openvpn log file, which can be found in

log /var/log/openvpn.log

according to your server config.

dsulli99

Ok, I've replicated the problem with the increased verbosity. Looks like a file handle problem. Has anybody seen this or know how to fix it?

CN=New_Age_Communications_CA/emailAddress=jctut1@gmail.com
Mon Jun 27 11:52:08 2011 us=5834 dbartley/75.27.58.4:2680 VERIFY OK: depth=0, /C=US/ST=TN/L=Chattanooga/O=New_Age_Communications/CN=dbartley/emailAddress=planxty@yahoo.com
WRWRWRWWWWRWRWRWRWRWRWRWRWRwRWRRRRWRWRWRAUTH-PAM: BACKGROUND: received command code: 0
AUTH-PAM: BACKGROUND: USER: justyn
AUTH-PAM: BACKGROUND: my_conv[0] query='Password: ' style=1
ltdb: tdb((null)): tdb_open_ex: could not open file /var/lib/samba/group_mapping.ldb: Too many open files
Unable to open tdb '/var/lib/samba/group_mapping.ldb'
Failed to connect to '/var/lib/samba/group_mapping.ldb'
ltdb: tdb((null)): tdb_open_ex: could not open file /var/lib/samba/group_mapping.ldb: Too many open files
Unable to open tdb '/var/lib/samba/group_mapping.ldb'
Failed to connect to '/var/lib/samba/group_mapping.ldb'
ltdb: tdb((null)): tdb_open_ex: could not open file /var/lib/samba/group_mapping.ldb: Too many open files
Unable to open tdb '/var/lib/samba/group_mapping.ldb'
Failed to connect to '/var/lib/samba/group_mapping.ldb'
AUTH-PAM: BACKGROUND: user 'justyn' failed to authenticate: Authentication failure
Mon Jun 27 11:52:08 2011 us=280785 dbartley/75.27.58.4:2680 PLUGIN_CALL: POST /usr/lib/openvpn/openvpn-auth-pam.so/PLUGIN_AUTH_USER_PASS_VERIFY status=1
Mon Jun 27 11:52:08 2011 us=280816 dbartley/75.27.58.4:2680 PLUGIN_CALL: plugin function PLUGIN_AUTH_USER_PASS_VERIFY failed with status 1: /usr/lib/openvpn/openvpn-auth-pam.s

billatverity

I have the same problem. I'm running a OpenVPN Access Server Virtual Appliance on VMware Server. While I don't know how to fix the problem, I do have a crude but effective hack to work around it:

Enter a cron job to reboot the guest operating system once per day. To do this, log in to the guest operating system (Ubuntu) via either the VMware console or telnet.

Edit the crontab by typing:

bill@localhost:~#sudo crontab -e

Then add the following line:

00 08 * * * /user/bin/sudo /sbin/reboot

(Save and exit by typing control-o control-x.)

This will reboot your guest OS each day at 08:00. Since my timezone on my guest o/s is set to UTC, this works out to midnight local time. Of course this disconnects every active OpenVPN connection each day at midnight, but it clears the problem.

Hope this helps.

Bill

janjust

there's some sloppy coding if you run out of file handles; can you try increasing the number of files prior to starting OpenVPN:

ulimit -n 10000
openvpn .....