OpenVPN exits when interface (or ip) is down

xtofh

Hi,

I've been using OpenVPN since long and pfsense for a little while (almost a year) and I just have 1 issue with OpenVPN. For some reason some of our pfsense boxes don't always get a new ip fast enough. (especially at night, so no big deal, these are 'cheap' internet connections)

The WAN interface use DHCP and OpenVPN is using this connection to establish a site-to-site connection. When the interface goes down, OpenVPN can't bind to the specified IP and exits.

No problem, but OpenVPN never retries because the process does not exist anymore and is not "restarted" until I do so manually. It makes the site-to-site go down until I manually restart the openvpn process. Using "save" on the webinterface or through the shell.

Any suggestions on how to fix or workaround this? Here's the log on OpenVPN: (as you can see I restarted it at 08:04)

Jun 28 01:03:38 	openvpn[42223]: LZO compression initialized
Jun 28 01:03:38 	openvpn[42223]: TCP/UDP: Socket bind failed on local address [AF_INET]81.82.XXX.XXX: Can't assign requested address
Jun 28 01:03:38 	openvpn[42223]: Exiting
Jun 28 01:03:38 	openvpn[42223]: /usr/local/sbin/ovpn-linkdown ovpnc1 1500 1545 192.168.250.18 192.168.250.17 init
Jun 28 08:04:24 	openvpn[62208]: OpenVPN testing-cee388313521 i386-portbld-freebsd8.1 [SSL] [LZO2] [eurephia] [MH] [PF_INET6] [IPv6 payload 20100307-1] built on Feb 21 2011
Jun 28 08:04:24 	openvpn[62208]: [DEPRECATED FEATURE ENABLED: random-resolv] Resolving hostnames will use randomisation if more than one IP address is found
Jun 28 08:04:24 	openvpn[62208]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Jun 28 08:04:24 	openvpn[62208]: LZO compression initialized
Jun 28 08:04:24 	openvpn[62208]: TUN/TAP device /dev/tun1 opened
Jun 28 08:04:24 	openvpn[62208]: do_ifconfig, tt->ipv6=0
Jun 28 08:04:24 	openvpn[62208]: /sbin/ifconfig ovpnc1 192.168.250.18 192.168.250.17 mtu 1500 netmask 255.255.255.255 up
Jun 28 08:04:24 	openvpn[62208]: /usr/local/sbin/ovpn-linkup ovpnc1 1500 1545 192.168.250.18 192.168.250.17 init
Jun 28 08:04:24 	openvpn[208]: UDPv4 link local (bound): [AF_INET]81.82.XXX.XXX
Jun 28 08:04:24 	openvpn[208]: UDPv4 link remote: [AF_INET]81.82.XX.XX:5002
Jun 28 08:04:28 	openvpn[208]: Peer Connection Initiated with [AF_INET]81.82.XX.XX:5002

Cheers,
Kristof

jimp

Can you show the system log from around the time when the IP changes? Something in the process that restarts on IP change may not be functioning properly.

I have seen this before on my cable modem when it loses sync and decides to switch to a 192.168.x.x IP and then switches back when the link comes back up.

I get around this usually be setting the OpenVPN instance to use 'any' interface rather than that interface specifically.

xtofh

Thanks for your reply, I have just changed the interface from WAN to any, to see how it goes. Thanks for the advice.

Here are the logs from last night (the vpn exited at 00:10). I also see some 192.168.x.y address in the log, a range that is not used on that network at all.. ???

openvpn log:

Jun 29 00:10:05 	openvpn[208]: write UDPv4: No route to host (code=65)
Jun 29 00:10:16 	openvpn[208]: write UDPv4: No route to host (code=65)
Jun 29 00:10:26 	openvpn[208]: write UDPv4: No route to host (code=65)
Jun 29 00:10:36 	openvpn[208]: write UDPv4: No route to host (code=65)
Jun 29 00:10:46 	openvpn[208]: Inactivity timeout (--ping-restart), restarting
Jun 29 00:10:46 	openvpn[208]: SIGUSR1[soft,ping-restart] received, process restarting
Jun 29 00:10:48 	openvpn[208]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Jun 29 00:10:48 	openvpn[208]: Re-using pre-shared static key
Jun 29 00:10:48 	openvpn[208]: LZO compression initialized
Jun 29 00:10:48 	openvpn[208]: TCP/UDP: Socket bind failed on local address [AF_INET]81.82.xxx.yyy: Can't assign requested address
Jun 29 00:10:48 	openvpn[208]: Exiting
Jun 29 00:10:48 	openvpn[208]: /usr/local/sbin/ovpn-linkdown ovpnc1 1500 1545 192.168.250.18 192.168.250.17 init

systemlog:

Jun 29 00:09:29 	apinger: ALARM: GW_WAN(81.82.192.1) *** down ***
Jun 29 00:09:39 	check_reload_status: reloading filter
Jun 29 00:09:53 	check_reload_status: Linkup starting rl0
Jun 29 00:09:53 	kernel: rl0: link state changed to DOWN
Jun 29 00:09:53 	php: : DEVD Ethernet detached event for wan
Jun 29 00:09:53 	dhclient[3496]: connection closed
Jun 29 00:09:53 	dhclient[3496]: connection closed
Jun 29 00:09:53 	dhclient[3496]: exiting.
Jun 29 00:09:53 	dhclient[3496]: exiting.
Jun 29 00:09:54 	check_reload_status: Linkup starting rl0
Jun 29 00:09:54 	kernel: rl0: link state changed to UP
Jun 29 00:09:54 	php: : DEVD Ethernet attached event for wan
Jun 29 00:09:54 	php: : HOTPLUG: Configuring interface wan
Jun 29 00:09:55 	kernel: arpresolve: can't allocate llinfo for 81.82.192.1
Jun 29 00:09:56 	dhclient: PREINIT
Jun 29 00:09:56 	dhclient[6440]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Jun 29 00:09:56 	kernel: arpresolve: can't allocate llinfo for 81.82.192.1
Jun 29 00:09:57 	dhclient[6440]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Jun 29 00:09:58 	dhclient[6440]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Jun 29 00:09:58 	kernel: rl0: link state changed to DOWN
Jun 29 00:09:58 	check_reload_status: Linkup starting rl0
Jun 29 00:09:58 	php: : DEVD Ethernet detached event for wan
Jun 29 00:09:58 	dhclient[6739]: connection closed
Jun 29 00:09:58 	dhclient[6739]: connection closed
Jun 29 00:09:58 	php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf rl0 > /tmp/rl0_output > /tmp/rl0_error_output' returned exit code '15', the output was ''
Jun 29 00:09:58 	dhclient[6739]: exiting.
Jun 29 00:09:58 	dhclient[6739]: exiting.
Jun 29 00:10:02 	kernel: arpresolve: can't allocate llinfo for 81.82.192.1
Jun 29 00:10:15 	check_reload_status: Linkup starting rl0
Jun 29 00:10:15 	kernel: rl0: link state changed to UP
Jun 29 00:10:15 	php: : DEVD Ethernet attached event for wan
Jun 29 00:10:15 	php: : HOTPLUG: Configuring interface wan
Jun 29 00:10:17 	dhclient: PREINIT
Jun 29 00:10:17 	dhclient[30286]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Jun 29 00:10:18 	dhclient[30286]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Jun 29 00:10:19 	dhclient[30286]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Jun 29 00:10:21 	dhclient[30286]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Jun 29 00:10:23 	dhclient[30286]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Jun 29 00:10:25 	check_reload_status: Linkup starting rl0
Jun 29 00:10:25 	kernel: rl0: link state changed to DOWN
Jun 29 00:10:25 	php: : DEVD Ethernet detached event for wan
Jun 29 00:10:25 	dhclient[30549]: connection closed
Jun 29 00:10:25 	dhclient[30549]: connection closed
Jun 29 00:10:25 	php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf rl0 > /tmp/rl0_output > /tmp/rl0_error_output' returned exit code '15', the output was ''
Jun 29 00:10:25 	dhclient[30549]: exiting.
Jun 29 00:10:25 	dhclient[30549]: exiting.
Jun 29 00:10:26 	check_reload_status: Linkup starting rl0
Jun 29 00:10:26 	kernel: rl0: link state changed to UP
Jun 29 00:10:27 	php: : DEVD Ethernet attached event for wan
Jun 29 00:10:27 	php: : HOTPLUG: Configuring interface wan
Jun 29 00:10:28 	dhclient: PREINIT
Jun 29 00:10:28 	dhclient[36307]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Jun 29 00:10:29 	kernel: arpresolve: can't allocate llinfo for 81.82.192.1
Jun 29 00:10:30 	dhclient[36307]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Jun 29 00:10:35 	dhclient[36307]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Jun 29 00:10:43 	dhclient[36307]: DHCPDISCOVER on rl0 to 255.255.255.255 port 67 interval 2
Jun 29 00:10:45 	dhclient[36307]: DHCPDISCOVER on rl0 to 255.255.255.255 port 67 interval 2
Jun 29 00:10:47 	dhclient[36307]: DHCPDISCOVER on rl0 to 255.255.255.255 port 67 interval 4
Jun 29 00:10:48 	kernel: ovpnc1: link state changed to DOWN
Jun 29 00:10:48 	check_reload_status: reloading filter
Jun 29 00:10:49 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:49 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:49 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:49 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:49 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:49 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:49 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:49 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:49 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:49 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:49 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:49 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:50 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:50 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:50 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:50 	php: : Could not find gateway for interface(wan).
Jun 29 00:10:51 	dhclient[36307]: DHCPDISCOVER on rl0 to 255.255.255.255 port 67 interval 9
Jun 29 00:11:00 	dhclient[36307]: DHCPDISCOVER on rl0 to 255.255.255.255 port 67 interval 13
Jun 29 00:11:13 	dhclient[36307]: DHCPDISCOVER on rl0 to 255.255.255.255 port 67 interval 16
Jun 29 00:11:29 	dhclient[36307]: DHCPDISCOVER on rl0 to 255.255.255.255 port 67 interval 15
Jun 29 00:11:29 	dhclient[36307]: DHCPOFFER from 81.82.192.1
Jun 29 00:11:29 	dhclient: ARPSEND
Jun 29 00:11:31 	dhclient: ARPCHECK
Jun 29 00:11:31 	dhclient[36307]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Jun 29 00:11:31 	dhclient[36307]: DHCPACK from 81.82.192.1
Jun 29 00:11:31 	dhclient: BOUND
Jun 29 00:11:31 	dhclient: Starting add_new_address()
Jun 29 00:11:31 	dhclient: ifconfig rl0 inet 81.82.xxx.yyy netmask 255.255.192.0 broadcast 255.255.255.255
Jun 29 00:11:31 	dhclient: New IP Address (rl0): 81.82.xxx.yyy
Jun 29 00:11:31 	dhclient: New Subnet Mask (rl0): 255.255.192.0
Jun 29 00:11:31 	dhclient: New Broadcast Address (rl0): 255.255.255.255
Jun 29 00:11:31 	dhclient: New Routers (rl0): 81.82.192.1
Jun 29 00:11:31 	dhclient: Adding new routes to interface: rl0
Jun 29 00:11:31 	dhclient: /sbin/route add default 81.82.192.1
Jun 29 00:11:31 	dhclient: Creating resolv.conf
Jun 29 00:11:31 	check_reload_status: rc.newwanip starting rl0
Jun 29 00:11:31 	dhclient[36307]: bound to 81.82.xxx.yyy -- renewal in 1851 seconds.
Jun 29 00:11:32 	php: : rc.newwanip: Informational is starting rl0.
Jun 29 00:11:32 	php: : rc.newwanip: on (IP address: 81.82.xxx.yyy) (interface: wan) (real interface: rl0).
Jun 29 00:11:32 	dnsmasq[23478]: reading /etc/resolv.conf
Jun 29 00:11:32 	dnsmasq[23478]: using nameserver 195.130.130.139#53
Jun 29 00:11:32 	dnsmasq[23478]: using nameserver 195.130.130.11#53
Jun 29 00:11:32 	php: : ROUTING: change default route to 192.168.0.1
Jun 29 00:11:32 	php: : The command '/sbin/route change -inet default '192.168.0.1'' returned exit code '1', the output was 'route: writing to routing socket: Network is unreachable change net default: gateway 192.168.0.1: Network is unreachable'
Jun 29 00:11:32 	apinger: Exiting on signal 15.
Jun 29 00:11:33 	check_reload_status: reloading filter
Jun 29 00:11:33 	apinger: Starting Alarm Pinger, apinger(12587)
Jun 29 00:42:22 	dhclient[9119]: DHCPREQUEST on rl0 to 195.130.132.102 port 67
Jun 29 00:42:22 	dhclient[9119]: DHCPACK from 195.130.132.102
Jun 29 00:42:22 	dhclient: RENEW
Jun 29 00:42:22 	dhclient: Creating resolv.conf
Jun 29 00:42:22 	dhclient[9119]: bound to 81.82.xxx.yyy -- renewal in 3600 seconds.
Jun 29 01:42:22 	dhclient[9119]: DHCPREQUEST on rl0 to 195.130.132.102 port 67
Jun 29 01:42:22 	dhclient[9119]: DHCPACK from 195.130.132.102
Jun 29 01:42:22 	dhclient: RENEW
Jun 29 01:42:22 	dhclient: Creating resolv.conf
Jun 29 01:42:22 	dhclient[9119]: bound to 81.82.xxx.yyy -- renewal in 3600 seconds.

jimp

It looks like sort of the same situation I have that I mentioned before, where when the modem loses its upstream link it decides to serve addresses from a private IP pool, and then reassigns the IP once the provider comes back online.

slu

Same problem here, because the ISP disconnect the PPPoE connection every 24h.
Works with any now thank you very much!

What happens when I have two WANs and want to use the vpn only on the second WAN?

xtofh

@slu:

Same problem here, because the ISP disconnect the PPPoE connection every 24h.
Works with any now thank you very much!

What happens when I have two WANs and want to use the vpn only on the second WAN?

If you want to use it on your second(ary) WAN, I think you must setup the interface as "wan2" instead of any.

If it's a site-to-site VPN and the remote host has a fixed ip you might be able to use fixed routing over wan2.

cheers

jimp

A static route would work if you want that to always go over the second WAN in that case.

Hopefully we can track down the cause of this error before the release though. It doesn't seem to happen to me quite as often these days for one reason or another.

slu

Work here now for 4 days with "any", hope it happen never again.
I have to drive 320 km (199 m) when the site-to-site VPN don't work :'(

xtofh

@slu:

Work here now for 4 days with "any", hope it happen never again.
I have to drive 320 km (199 m) when the site-to-site VPN don't work :'(

Good luck! (working here for a week now, so it seems okay)

Make sure you install a backdoor ( :) ) with ssh so you can always access it through ssh from your location..

cheers

pv2b

This exact same issue turned up for me with a customer. For some unknown reason, there was a few minutes long link-down event (approximately 2011-12-30 03.15) on the WAN interface, which caused OpenVPN to restart due to inactivity, and then not restart properly when the link came back up.

The WAN side is allocated using DHCP. Something to note when analysing the logs: the WAN network itself lies in private address space (192.168.0.0/24). The system in question is running pfSense 2.0-RELEASE (i386) built on Tue Sep 13 18:02:53 EDT 2011 - 512 MB NanoBSD on an OPNSense appliance.

Has there been any progress on this?

System logs:

Dec 30 02:16:59 dhclient: RENEW 
Dec 30 02:16:59 dhclient: Creating resolv.conf 
Dec 30 03:15:06 check_reload_status: Linkup starting vr1 
Dec 30 03:15:06 kernel: vr1: link state changed to DOWN 
Dec 30 03:15:09 apinger: ALARM: WAN(192.168.0.1) *** down *** 
Dec 30 03:15:12 php: : DEVD Ethernet detached event for wan 
Dec 30 03:15:12 dhclient[8429]: connection closed 
Dec 30 03:15:12 dhclient[8429]: connection closed 
Dec 30 03:15:12 dhclient[8429]: exiting. 
Dec 30 03:15:12 dhclient[8429]: exiting. 
Dec 30 03:15:14 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:19 check_reload_status: Reloading filter 
Dec 30 03:15:22 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:24 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:25 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:25 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:25 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:26 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:26 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:27 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:29 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:31 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:32 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:34 check_reload_status: Linkup starting vr1 
Dec 30 03:15:34 kernel: vr1: link state changed to UP 
Dec 30 03:15:35 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:40 php: : DEVD Ethernet attached event for wan 
Dec 30 03:15:40 php: : HOTPLUG: Configuring interface wan 
Dec 30 03:15:40 dhclient: PREINIT 
Dec 30 03:15:40 dhclient[48720]: DHCPREQUEST on vr1 to 255.255.255.255 port 67 
Dec 30 03:15:41 dhclient[48720]: DHCPREQUEST on vr1 to 255.255.255.255 port 67 
Dec 30 03:15:42 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:43 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:43 dhclient[48720]: DHCPREQUEST on vr1 to 255.255.255.255 port 67 
Dec 30 03:15:45 dhclient[48720]: DHCPREQUEST on vr1 to 255.255.255.255 port 67 
Dec 30 03:15:50 dhclient[48720]: DHCPREQUEST on vr1 to 255.255.255.255 port 67 
Dec 30 03:15:52 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 
Dec 30 03:15:53 kernel: ovpnc3: link state changed to DOWN 
Dec 30 03:15:53 check_reload_status: Reloading filter 
Dec 30 03:15:56 kernel: ovpnc1: link state changed to DOWN 
Dec 30 03:15:56 check_reload_status: Reloading filter 
Dec 30 03:16:02 dhclient[48720]: DHCPDISCOVER on vr1 to 255.255.255.255 port 67 interval 1 
Dec 30 03:16:02 dhclient[48720]: DHCPOFFER from 192.168.0.1 
Dec 30 03:16:02 dhclient: ARPSEND 
Dec 30 03:16:04 dhclient: ARPCHECK 
Dec 30 03:16:04 dhclient[48720]: DHCPREQUEST on vr1 to 255.255.255.255 port 67 
Dec 30 03:16:04 dhclient[48720]: DHCPACK from 192.168.0.1 
Dec 30 03:16:04 dhclient: BOUND 
Dec 30 03:16:04 dhclient: Starting add_new_address() 
Dec 30 03:16:04 dhclient: ifconfig vr1 inet 192.168.0.244 netmask 255.255.255.0 broadcast 192.168.0.255 
Dec 30 03:16:04 dhclient: New IP Address (vr1): 192.168.0.244 
Dec 30 03:16:04 dhclient: New Subnet Mask (vr1): 255.255.255.0 
Dec 30 03:16:04 dhclient: New Broadcast Address (vr1): 192.168.0.255 
Dec 30 03:16:04 dhclient: New Routers (vr1): 192.168.0.1 
Dec 30 03:16:04 dhclient: Adding new routes to interface: vr1 
Dec 30 03:16:04 dhclient: /sbin/route add default 192.168.0.1 
Dec 30 03:16:04 dhclient: Creating resolv.conf 
Dec 30 03:16:04 check_reload_status: rc.newwanip starting vr1 
Dec 30 03:16:04 dhclient[48720]: bound to 192.168.0.244 -- renewal in 21600 seconds. 
Dec 30 03:16:05 apinger: alarm canceled: WAN(192.168.0.1) *** down *** 
Dec 30 03:16:10 php: : rc.newwanip: Informational is starting vr1\. 
Dec 30 03:16:10 php: : rc.newwanip: on (IP address: 192.168.0.244) (interface: wan) (real interface: vr1). 
Dec 30 03:16:10 php: : ROUTING: setting default route to 192.168.0.1 
Dec 30 03:16:10 check_reload_status: Reloading filter 
Dec 30 03:16:10 apinger: Exiting on signal 15\. 
Dec 30 03:16:11 check_reload_status: Reloading filter 
Dec 30 03:16:11 apinger: Starting Alarm Pinger, apinger(27038) 
Dec 30 03:19:55 dnsmasq[47621]: reading /etc/resolv.conf 
Dec 30 03:19:55 dnsmasq[47621]: using nameserver 8.8.4.4#53 
Dec 30 03:19:55 dnsmasq[47621]: using nameserver 8.8.8.8#53 
Dec 30 03:19:55 dnsmasq[47621]: using nameserver 192.168.0.1#53 
Dec 30 03:19:55 dnsmasq[47621]: ignoring nameserver 127.0.0.1 - local interface 
Dec 30 03:19:55 dnsmasq[47621]: ignoring nameserver 127.0.0.1 - local interface 
Dec 30 09:16:08 dhclient[731]: DHCPREQUEST on vr1 to 192.168.0.1 port 67 
Dec 30 09:16:08 dhclient[731]: DHCPACK from 192.168.0.1 
Dec 30 09:16:08 dhclient: RENEW 
Dec 30 09:16:08 dhclient: Creating resolv.conf 
Dec 30 09:16:08 dhclient[731]: bound to 192.168.0.244 -- renewal in 19341 seconds.

OpenVPN logs:

Dec 28 11:27:54 openvpn[7652]: Initialization Sequence Completed 
Dec 30 03:15:51 openvpn[7652]: Inactivity timeout (--ping-restart), restarting 
Dec 30 03:15:51 openvpn[7652]: SIGUSR1[soft,ping-restart] received, process restarting 
Dec 30 03:15:53 openvpn[7652]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts 
Dec 30 03:15:53 openvpn[7652]: Re-using pre-shared static key 
Dec 30 03:15:53 openvpn[7652]: TCP/UDP: Socket bind failed on local address [AF_INET]192.168.0.244: Can't assign requested address 
Dec 30 03:15:53 openvpn[7652]: Exiting 
Dec 30 03:15:53 openvpn[7652]: /usr/local/sbin/ovpn-linkdown ovpnc3 1500 1560 10.22.255.6 10.22.255.5 init 
Dec 30 03:15:54 openvpn[5386]: Inactivity timeout (--ping-restart), restarting 
Dec 30 03:15:54 openvpn[5386]: SIGUSR1[soft,ping-restart] received, process restarting 
Dec 30 03:15:56 openvpn[5386]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts 
Dec 30 03:15:56 openvpn[5386]: Re-using pre-shared static key 
Dec 30 03:15:56 openvpn[5386]: TCP/UDP: Socket bind failed on local address [AF_INET]192.168.0.244: Can't assign requested address 
Dec 30 03:15:56 openvpn[5386]: Exiting 
Dec 30 03:15:56 openvpn[5386]: /usr/local/sbin/ovpn-linkdown ovpnc1 1500 1560 10.22.255.202 10.22.255.201 init

xtofh

@pv2b:

This exact same issue turned up for me with a customer. For some unknown reason, there was a few minutes long link-down event (approximately 2011-12-30 03.15) on the WAN interface, which caused OpenVPN to restart due to inactivity, and then not restart properly when the link came back up.

Is your openvpn tunnel configured to use the ANY interface? (and not WAN)

That fixed the issue for me.

fabsah

@pv2b:

This exact same issue turned up for me with a customer. For some unknown reason, there was a few minutes long link-down event (approximately 2011-12-30 03.15) on the WAN interface, which caused OpenVPN to restart due to inactivity, and then not restart properly when the link came back up.

The WAN side is allocated using DHCP. Something to note when analysing the logs: the WAN network itself lies in private address space (192.168.0.0/24). The system in question is running pfSense 2.0-RELEASE (i386) built on Tue Sep 13 18:02:53 EDT 2011 - 512 MB NanoBSD on an OPNSense appliance.

Has there been any progress on this?

Hello,

I have almost exactly the same problem.

I run pfSense 2.0.1 as my router/firewall at home. The WAN is allocated using DHCP and lives on 192.168.1.0/24.
The pfSense box is setup has an OpenVPN client to a VPN provider. I have firewall rules that forwards certain ports from certain LAN ip addresses to the OpenVPN client.

When the WAN connection is reset at night, no matter what I do, the OpenVPN daemon stops and the traffic that should be routed to the OpenVPN interface is routed to the WAN.

I have set a firewall rule on the WAN to block that traffic, but it doesn't do the trick.

I have tried what is suggested in this post (change the interface to "any") but it doesn't solve the problem either.

Any idea ?

Thanks !

xtofh

@fabsah:

I have set a firewall rule on the WAN to block that traffic, but it doesn't do the trick.

I have tried what is suggested in this post (change the interface to "any") but it doesn't solve the problem either.

Do you also have the option "Infinitely resolve server" checked? If not, make sure it's checked and see if that helps.

I also sometimes use a keep-alive option in the advanced configuration of the openvpn client, you can set that like this: keepalive 15 40

If your openvpn client quits for any reason, the openvpn/system logs should be able to tell you more..

Regards,
Kristof.

cmb

@fabsah:

I run pfSense 2.0.1 as my router/firewall at home. The WAN is allocated using DHCP and lives on 192.168.1.0/24.
The pfSense box is setup has an OpenVPN client to a VPN provider. I have firewall rules that forwards certain ports from certain LAN ip addresses to the OpenVPN client.

When the WAN connection is reset at night, no matter what I do, the OpenVPN daemon stops and the traffic that should be routed to the OpenVPN interface is routed to the WAN.

Sounds like that's a completely different problem. Your actual WAN IP on the firewall in that case (192.168.x) most likely is not changing, but it's changing on your modem or whatever device upstream has your public IP and is doing the NAT. This case sounds like a modem problem or a problem with whatever device is doing the NAT. With long-lived connections like that and IP changes, what can happen is the NAT state to the old public IP isn't removed, and until you close down that connection, let its state timeout, and re-open it (which will never happen as long as openvpn isn't manually stopped) to get that device to NAT it out to the new, correct IP.

fabsah

Hello,

Thanks for helping me trying to solve this problem.

I have experimented with the "Infinitely resolve server" option and I've added keepalive 15 40 to the configuration. It didn't solve the problem, unfortunatly. Here are the relevant logfile entries from last night :

Jan 6 05:06:38 openvpn[24199]: SIGTERM[soft,exit-with-notification] received, process exiting
Jan 6 05:06:38 openvpn[24199]: /usr/local/sbin/ovpn-linkdown ovpnc2 1500 1558 10.4.3.26 10.4.3.25 init
Jan 6 05:06:38 openvpn[24199]: Closing TUN/TAP interface
Jan 6 05:06:38 openvpn[24199]: /sbin/route delete -net 128.0.0.0 10.4.x.xx 128.0.0.0
Jan 6 05:06:38 openvpn[24199]: /sbin/route delete -net 0.0.0.0 10.4.x.xx 128.0.0.0
Jan 6 05:06:38 openvpn[24199]: /sbin/route delete -net 62.21x.xx.xx 192.168.1.1 255.255.255.255
Jan 6 05:06:38 openvpn[24199]: /sbin/route delete -net 10.4.0.1 10.4.x.xx 255.255.255.255
Jan 6 05:06:38 openvpn[24199]: TCP/UDP: Closing socket
Jan 6 05:06:38 openvpn[24199]: SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Jan 6 05:06:33 openvpn[24199]: SIGTERM received, sending exit notification to peer
Jan 6 05:06:33 openvpn[24199]: AUTH: Received AUTH_FAILED control message
Jan 6 05:06:33 openvpn[24199]: SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Jan 6 05:06:31 openvpn[24199]: [server] Peer Connection Initiated with [AF_INET]62.212.xx.xx:443
Jan 6 05:06:31 openvpn[24199]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Jan 6 05:06:31 openvpn[24199]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jan 6 05:06:31 openvpn[24199]: Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Jan 6 05:06:31 openvpn[24199]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jan 6 05:06:31 openvpn[24199]: Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Jan 6 05:06:31 openvpn[24199]: VERIFY OK: depth=0, /C=IT/ST=IT/L=Perugia/O=airvpn.org/CN=server/emailAddress=info@airvpn.org
Jan 6 05:06:31 openvpn[24199]: VERIFY OK: nsCertType=SERVER
Jan 6 05:06:31 openvpn[24199]: VERIFY OK: depth=1, /C=IT/ST=IT/L=Perugia/O=airvpn.org/CN=airvpn.org_CA/emailAddress=info@airvpn.org
Jan 6 05:06:31 openvpn[24199]: TLS: Initial packet from [AF_INET]62.212.xx.xx:443, sid=71ddc686 xxxxxx
Jan 6 05:06:31 openvpn[24199]: UDPv4 link remote: [AF_INET]62.212.xx.xx:443
Jan 6 05:06:31 openvpn[24199]: UDPv4 link local: [undef]
Jan 6 05:06:31 openvpn[24199]: Expected Remote Options hash (VER=V4): 'a8f55717'
Jan 6 05:06:31 openvpn[24199]: Local Options hash (VER=V4): '22188c5b'
Jan 6 05:06:31 openvpn[24199]: Expected Remote Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Jan 6 05:06:31 openvpn[24199]: Local Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Jan 6 05:06:31 openvpn[24199]: Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:135 ET:0 EL:0 AF:3/1 ]
Jan 6 05:06:31 openvpn[24199]: Socket Buffers: R=[42080->65536] S=[57344->65536]
Jan 6 05:06:31 openvpn[24199]: Control Channel MTU parms [ L:1558 D:138 EF:38 EB:0 ET:0 EL:0 ]
Jan 6 05:06:31 openvpn[24199]: LZO compression initialized
Jan 6 05:06:31 openvpn[24199]: Re-using SSL/TLS context
Jan 6 05:06:31 openvpn[24199]: NOTE: the current –script-security setting may allow this configuration to call user-defined scripts
Jan 6 05:06:29 openvpn[24199]: Restart pause, 2 second(s)
Jan 6 05:06:29 openvpn[24199]: SIGUSR1[soft,ping-restart] received, process restarting
Jan 6 05:06:29 openvpn[24199]: TCP/UDP: Closing socket
Jan 6 05:06:29 openvpn[24199]: [server] Inactivity timeout (–ping-restart), restarting

The problem might be I'm taking the wrong path here, trying to basically have a "proxy" living on my pfSense box and relay certain ports, from some LAN clients, to the OpenVPN client.

Here is how I do it :

I've set up a OpenVPN client on pfSense.
It acts as a Gateway.
I've set firewall rules on the LAN that direct the selected IP and ports (as aliases) to the OpenVPN gateway.

Is there a better way ?

I've quite new to pfSense (I've bought the book and installed the 2.0 release a few weeks ago).

Thanks for your time and your help.

xtofh

Hi,

What you're doing might work, I never tried it but I think it's possible. But maybe you might choose a different path. What are you trying to accomplish? You could create a site-to-site VPN from the pfsense to the remote openvpn server. (the remote openvpn server does not have to be a complete subnet, it can be just 1 host)

You could try disabling the rules for a short time to see if your OpenVPN connection stays stable.

As for the log files, what do you see in your "system" log at the same time? Something else that looks different?

Regards,
Kristof.