OpenVPN continues to work even after it's terminated due to fatal error

brick41 · Apr 23, 2014, 5:10 AM

I rebooted a few days ago but it happened again.

nwebber · Apr 23, 2014, 4:17 PM

I'm trying to chase down something similar and was planning to do more homework before posting, but seeing this makes me wonder. I have the same symptom - dashboard Services Status reports openvpn down, but it isn't. And my logs contain fatal error messages from openvpn, pertaining to EADDRINUSE (1194) and it looks to my untrained (as far as pfSense goes) eyes that the system tried to start multiple openvpn instances.

Everything is "working" except for the status reporting.

I have two different pfSense installations (different networks) and as far as I can tell both are configured "similarly" but obviously something is different. Was settling in for a debug/archeology session but thought maybe I'd get some pointers/clues here.

Here's what my log looks like after booting:


Apr 17 11:02:43 pfsense openvpn[32177]: OpenVPN 2.3.2 i386-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014
Apr 17 11:02:43 pfsense openvpn[59735]: OpenVPN 2.3.2 i386-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014
Apr 17 11:02:43 pfsense openvpn[50028]: OpenVPN 2.3.2 i386-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014
Apr 17 11:02:43 pfsense openvpn[59735]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Apr 17 11:02:43 pfsense openvpn[32177]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Apr 17 11:02:43 pfsense openvpn[50028]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Apr 17 11:02:44 pfsense openvpn[32177]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file
Apr 17 11:02:44 pfsense openvpn[59735]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file
Apr 17 11:02:44 pfsense openvpn[32177]: TCP/UDP: Socket bind failed on local address [AF_INET]66.68.35.6:1194: Address already in use
Apr 17 11:02:44 pfsense openvpn[32177]: Exiting due to fatal error
Apr 17 11:02:45 pfsense openvpn[59735]: TUN/TAP device ovpns1 exists previously, keep at program end
Apr 17 11:02:45 pfsense openvpn[59735]: TUN/TAP device /dev/tun1 opened
Apr 17 11:02:45 pfsense openvpn[59735]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
Apr 17 11:02:45 pfsense openvpn[59735]: /sbin/ifconfig ovpns1 192.168.80.129 192.168.80.130 mtu 1500 netmask 255.255.255.255 up
Apr 17 11:02:45 pfsense openvpn[50028]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file
Apr 17 11:02:45 pfsense openvpn[50028]: TCP/UDP: Socket bind failed on local address [AF_INET]66.68.35.6:1194: Address already in use
Apr 17 11:02:45 pfsense openvpn[50028]: Exiting due to fatal error
Apr 17 11:02:45 pfsense openvpn[59735]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.80.129 192.168.80.130 init
Apr 17 11:02:45 pfsense openvpn[80689]: UDPv4 link local (bound): [AF_INET]66.68.35.6:1194
Apr 17 11:02:45 pfsense openvpn[80689]: UDPv4 link remote: [undef]
Apr 17 11:02:45 pfsense openvpn[80689]: Initialization Sequence Completed

phil.davis · Apr 23, 2014, 4:29 PM

I have not noticed this recently, but it certainly happened in the past. Somehow the OpenVPN instance tried to be started again, and I think the PID file got updated. Then the process dies because it can't listen on the specified port (the other process has it already). The PID file now has the new (gone) process id. Now the system can't find the old process any more - it thinks the PID file is a reliable indicator to use to find the process. But, as you say, the VPN is happily running and working.
Eventually you "ps aux | grep openvpn" and find the lost process, kill it (interrupting service) and then you can restart from the webGUI and the Dashboard will be happy again.
I guess there will be a timing thing somewhere with particular real-time interface events. If you can work out a
sequence to make it happen, then it should be easy to analyse and fix ;)

Edit: Fixed wrong command text.

nwebber · Apr 23, 2014, 5:27 PM

Ok, that at least helped me correct the situation - thanks!

If it's a race condition my only clue I can provide is I'm on a soekris 6501-50 (both instances). My configuration that works is pretty vanilla (one WAN one LAN). The configuration exhibiting the problem has an extra lan card (8 ports in the machine) and 6 networks configured (one WAN, 5 LAN, 4 of which are actually connected and one is dangling/down). The problem manifests at boot (the log I posted is from bootup). Not entirely sure if it manifests every boot or just sometimes. I don't reboot on a regular basis :)

Not much help, I know. Willing to provide more data if given some pointers/tips things to try/instrument/whatever.

brick41 · Apr 23, 2014, 7:18 PM

@phil.davis:

Eventually you "ps aux | grep ovpn" and find the lost process, kill it (interrupting service) and then you can restart from the webGUI and the Dashboard will be happy again.

I just tried that and it doesn't find any process ovpn. I tried the restart button in the GUI but that doesn't do anything either so I'm rebooting again. Thanks anyway

nwebber · Apr 23, 2014, 9:43 PM

ps auxww | grep openvpn

I half-jokingly thought the "not quite right" instruction was a safety hurdle - before being qualified to kill random PIDs maybe Phil wanted to make sure we could get over that hump. :) In reality I imagine it was just a typo / brain-hiccup.

MrKoen · Sep 15, 2014, 6:27 PM

Thanks for sharing guys. I ran into the same issue here. Killing the process through SSH and then restarting OpenVPN through the web interface made it work again for me.

For the sake of completeness for the less Linux skilled people, like myself, the complete sequence of actions would be:

SSH into your pfSense server, i.e. using Putty
Log in as user root
Use option 8 in the menu to go to the shell
Type: ps auxww | grep openvpn
It should give a list of openvpn processes. The first number shown is the process id (pid). You'll need that to kill the process.
Type: kill
Now through the pfSense Web interface, go to Status -> Services and click on the Play icon in the line with openvpn to start it. It should now start again.

Attached a screen capture of the commands I used to do this trick. Worked like a charm!

duntuk · Oct 27, 2014, 5:32 AM

Thank you for the SSH instruction, but what if this happens on a regular basis; is there a way to prevent this from happening?

MrKoen · Oct 27, 2014, 12:23 PM

@duntuk:

Thank you for the SSH instruction, but what if this happens on a regular basis; is there a way to prevent this from happening?

Can't answer that question for you. What I can say that once I went through the steps outlined above, it has never occurred anymore on my pfSense system, so it might be a one time thing that can occur.

cmb · Oct 31, 2014, 1:15 AM

Pretty sure that's this scenario.
https://redmine.pfsense.org/issues/3894