Phantom OpenVPN client session

ssheikh · Sep 2, 2013, 6:00 AM

I am trying to track down this phantom OpenVPN client session that gets started soon after the firewall is booted up and somehow is not tracked by its pid so its never killed.

I am running 8/31 snapshot with my own fixes for #3172 and #3174 incorporated. There is only one OpenVPN client configured on this firewall. It is bound to a gateway group which in turn has CARP VIPs for the primary and backup WAN links. There is a backup firewall in this CARP cluster as well but the OpenVPN client never starts on it.

In the logs I have made the following substitutions:

<fqdn_of_far_end_server>= DNS name of the far side OpenVPN server this client needs to connect to.
<vip_tier1>= CARP VIP of primary WAN
<vip_tier2>= CARP VIP of backup WAN
<ip_of_far_end_server>= IP address of <fqdn_of_far_end_server>Log is from the moment the firewall boots up.


001 | Sep 1 23:03:52 openvpn[24435]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Jul 24 2013
002 | Sep 1 23:03:52 openvpn[24435]: WARNING: using --pull/--client and --ifconfig together is probably not what you want
003 | Sep 1 23:03:52 openvpn[24435]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
004 | Sep 1 23:03:52 openvpn[24435]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
005 | Sep 1 23:03:52 openvpn[24435]: Control Channel Authentication: using '/var/etc/openvpn/client2.tls-auth' as a OpenVPN static key file
006 | Sep 1 23:04:12 openvpn[16778]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Jul 24 2013
007 | Sep 1 23:04:12 openvpn[16778]: WARNING: using --pull/--client and --ifconfig together is probably not what you want
008 | Sep 1 23:04:12 openvpn[16778]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
009 | Sep 1 23:04:12 openvpn[16778]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
010 | Sep 1 23:04:12 openvpn[16778]: Control Channel Authentication: using '/var/etc/openvpn/client2.tls-auth' as a OpenVPN static key file
011 | Sep 1 23:04:29 openvpn[16778]: RESOLVE: Cannot resolve host address: <fqdn_of_far_end_server>: hostname nor servname provided, or not known
012 | Sep 1 23:04:29 openvpn[22772]: UDPv4 link local (bound): [AF_INET] <vip_tier2>013 | Sep 1 23:04:29 openvpn[22772]: UDPv4 link remote: [AF_INET]<ip_of_far_end_server>:16001
014 | Sep 1 23:04:30 openvpn[22772]: WARNING: 'tun-ipv6' is present in remote config but missing in local config, remote='tun-ipv6'
015 | Sep 1 23:04:30 openvpn[22772]: WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 192.168.240.38 192.168.240.37'
016 | Sep 1 23:04:30 openvpn[22772]: [<cn_of_far_end_server's_cert>] Peer Connection Initiated with [AF_INET]<ip_of_far_end_server>:16001
017 | Sep 1 23:04:33 openvpn[22772]: TUN/TAP device ovpnc2 exists previously, keep at program end
018 | Sep 1 23:04:33 openvpn[22772]: TUN/TAP device /dev/tun2 opened
019 | Sep 1 23:04:33 openvpn[22772]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
020 | Sep 1 23:04:33 openvpn[22772]: /sbin/ifconfig ovpnc2 192.168.240.38 192.168.240.37 mtu 1500 netmask 255.255.255.255 up
021 | Sep 1 23:04:33 openvpn[22772]: /usr/local/sbin/ovpn-linkup ovpnc2 1500 1557 192.168.240.38 192.168.240.37 init
022 | Sep 1 23:04:33 openvpn[22772]: Initialization Sequence Completed
023 | Sep 1 23:04:33 openvpn[24435]: RESOLVE: Cannot resolve host address: <fqdn_of_far_end_server>: hostname nor servname provided, or not known
024 | Sep 1 23:04:33 openvpn[26127]: UDPv4 link local (bound): [AF_INET] <vip_tier1>025 | Sep 1 23:04:33 openvpn[26127]: UDPv4 link remote: [AF_INET]<ip_of_far_end_server>:16001
026 | Sep 1 23:04:34 openvpn[26127]: WARNING: 'tun-ipv6' is present in remote config but missing in local config, remote='tun-ipv6'
027 | Sep 1 23:04:34 openvpn[26127]: WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 192.168.240.38 192.168.240.37'
028 | Sep 1 23:04:34 openvpn[26127]: [<cn_of_far_end_server's_cert>] Peer Connection Initiated with [AF_INET]<ip_of_far_end_server>:16001
029 | Sep 1 23:04:36 openvpn[26127]: event_wait : Interrupted system call (code=4)
030 | Sep 1 23:04:36 openvpn[26127]: SIGTERM[hard,] received, process exiting
031 | Sep 1 23:04:36 openvpn[46582]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Jul 24 2013
032 | Sep 1 23:04:36 openvpn[46582]: WARNING: using --pull/--client and --ifconfig together is probably not what you want
033 | Sep 1 23:04:36 openvpn[46582]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
034 | Sep 1 23:04:36 openvpn[46582]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
035 | Sep 1 23:04:36 openvpn[46582]: Control Channel Authentication: using '/var/etc/openvpn/client2.tls-auth' as a OpenVPN static key file
036 | Sep 1 23:04:36 openvpn[46591]: UDPv4 link local (bound): [AF_INET] <vip_tier1>037 | Sep 1 23:04:36 openvpn[46591]: UDPv4 link remote: [AF_INET]<ip_of_far_end_server>:16001
038 | Sep 1 23:04:37 openvpn[46591]: WARNING: 'tun-ipv6' is present in remote config but missing in local config, remote='tun-ipv6'
039 | Sep 1 23:04:37 openvpn[46591]: WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 192.168.240.38 192.168.240.37'
040 | Sep 1 23:04:37 openvpn[46591]: [<cn_of_far_end_server's_cert>] Peer Connection Initiated with [AF_INET]<ip_of_far_end_server>:16001
041 | Sep 1 23:04:40 openvpn[22772]: [<cn_of_far_end_server's_cert>] Inactivity timeout (--ping-restart), restarting
042 | Sep 1 23:04:40 openvpn[22772]: SIGUSR1[soft,ping-restart] received, process restarting
043 | Sep 1 23:04:42 openvpn[22772]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
044 | Sep 1 23:04:42 openvpn[22772]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
045 | Sep 1 23:04:42 openvpn[22772]: UDPv4 link local (bound): [AF_INET] <vip_tier2>046 | Sep 1 23:04:42 openvpn[22772]: UDPv4 link remote: [AF_INET]<ip_of_far_end_server>:16001
047 | Sep 1 23:04:43 openvpn[22772]: WARNING: 'tun-ipv6' is present in remote config but missing in local config, remote='tun-ipv6'
048 | Sep 1 23:04:43 openvpn[22772]: WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 192.168.240.38 192.168.240.37'
049 | Sep 1 23:04:43 openvpn[22772]: [<cn_of_far_end_server's_cert>] Peer Connection Initiated with [AF_INET]<ip_of_far_end_server>:16001
050 | Sep 1 23:04:49 openvpn[46591]: [<cn_of_far_end_server's_cert>] Inactivity timeout (--ping-restart), restarting
051 | Sep 1 23:04:49 openvpn[46591]: SIGUSR1[soft,ping-restart] received, process restarting
052 | Sep 1 23:04:51 openvpn[46591]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
053 | Sep 1 23:04:51 openvpn[46591]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
054 | Sep 1 23:04:51 openvpn[46591]: UDPv4 link local (bound): [AF_INET] <vip_tier1>055 | Sep 1 23:04:51 openvpn[46591]: UDPv4 link remote: [AF_INET]<ip_of_far_end_server>:16001
056 | Sep 1 23:04:52 openvpn[46591]: WARNING: 'tun-ipv6' is present in remote config but missing in local config, remote='tun-ipv6'
057 | Sep 1 23:04:52 openvpn[46591]: WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 192.168.240.38 192.168.240.37'
058 | Sep 1 23:04:52 openvpn[46591]: [<cn_of_far_end_server's_cert>] Peer Connection Initiated with [AF_INET]<ip_of_far_end_server>:16001
059 | Sep 1 23:04:57 openvpn[22772]: [<cn_of_far_end_server's_cert>] Inactivity timeout (--ping-restart), restarting
060 | Sep 1 23:04:57 openvpn[22772]: SIGUSR1[soft,ping-restart] received, process restarting
061 | Sep 1 23:04:59 openvpn[22772]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
062 | Sep 1 23:04:59 openvpn[22772]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
063 | Sep 1 23:04:59 openvpn[22772]: UDPv4 link local (bound): [AF_INET] <vip_tier2>064 | Sep 1 23:04:59 openvpn[22772]: UDPv4 link remote: [AF_INET]<ip_of_far_end_server>:16001
065 | Sep 1 23:05:00 openvpn[22772]: WARNING: 'tun-ipv6' is present in remote config but missing in local config, remote='tun-ipv6'
066 | Sep 1 23:05:00 openvpn[22772]: WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 192.168.240.38 192.168.240.37'
067 | Sep 1 23:05:00 openvpn[22772]: [<cn_of_far_end_server's_cert>] Peer Connection Initiated with [AF_INET]<ip_of_far_end_server>:16001
068 | Sep 1 23:05:06 openvpn[46591]: [<cn_of_far_end_server's_cert>] Inactivity timeout (--ping-restart), restarting
069 | Sep 1 23:05:06 openvpn[46591]: SIGUSR1[soft,ping-restart] received, process restarting
070 | Sep 1 23:05:07 openvpn[22772]: Preserving previous TUN/TAP instance: ovpnc2
071 | Sep 1 23:05:07 openvpn[22772]: NOTE: Pulled options changed on restart, will need to close and reopen TUN/TAP device.
072 | Sep 1 23:05:07 openvpn[22772]: /usr/local/sbin/ovpn-linkdown ovpnc2 1500 1557 192.168.240.38 192.168.240.37 init
073 | Sep 1 23:05:08 openvpn[46591]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
074 | Sep 1 23:05:08 openvpn[46591]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
075 | Sep 1 23:05:08 openvpn[46591]: UDPv4 link local (bound): [AF_INET] <vip_tier1>076 | Sep 1 23:05:08 openvpn[46591]: UDPv4 link remote: [AF_INET]<ip_of_far_end_server>:16001
077 | Sep 1 23:05:08 openvpn[22772]: TUN/TAP device ovpnc2 exists previously, keep at program end
078 | Sep 1 23:05:08 openvpn[22772]: TUN/TAP device /dev/tun2 opened
079 | Sep 1 23:05:08 openvpn[22772]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
080 | Sep 1 23:05:08 openvpn[22772]: /sbin/ifconfig ovpnc2 192.168.240.38 192.168.240.37 mtu 1500 netmask 255.255.255.255 up
081 | Sep 1 23:05:08 openvpn[22772]: /usr/local/sbin/ovpn-linkup ovpnc2 1500 1557 192.168.240.38 192.168.240.37 init
082 | Sep 1 23:05:08 openvpn[22772]: Initialization Sequence Completed
083 | Sep 1 23:05:09 openvpn[46591]: WARNING: 'tun-ipv6' is present in remote config but missing in local config, remote='tun-ipv6'
084 | Sep 1 23:05:09 openvpn[46591]: WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 192.168.240.38 192.168.240.37'
085 | Sep 1 23:05:09 openvpn[46591]: [<cn_of_far_end_server's_cert>] Peer Connection Initiated with [AF_INET]<ip_of_far_end_server>:16001
086 | Sep 1 23:05:15 openvpn[22772]: [<cn_of_far_end_server's_cert>] Inactivity timeout (--ping-restart), restarting
087 | Sep 1 23:05:15 openvpn[22772]: SIGUSR1[soft,ping-restart] received, process restarting
088 | Sep 1 23:05:17 openvpn[22772]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
089 | Sep 1 23:05:17 openvpn[22772]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
090 | Sep 1 23:05:17 openvpn[22772]: UDPv4 link local (bound): [AF_INET] <vip_tier2>091 | Sep 1 23:05:17 openvpn[22772]: UDPv4 link remote: [AF_INET]<ip_of_far_end_server>:16001
092 | Sep 1 23:05:18 openvpn[22772]: WARNING: 'tun-ipv6' is present in remote config but missing in local config, remote='tun-ipv6'
093 | Sep 1 23:05:18 openvpn[22772]: WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 192.168.240.38 192.168.240.37'
094 | Sep 1 23:05:18 openvpn[22772]: [<cn_of_far_end_server's_cert>] Peer Connection Initiated with [AF_INET]<ip_of_far_end_server>:16001
095 | Sep 1 23:05:24 openvpn[46591]: [<cn_of_far_end_server's_cert>] Inactivity timeout (--ping-restart), restarting
096 | Sep 1 23:05:24 openvpn[46591]: SIGUSR1[soft,ping-restart] received, process restarting
097 | Sep 1 23:05:27 openvpn[46591]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
098 | Sep 1 23:05:27 openvpn[46591]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
099 | Sep 1 23:05:27 openvpn[46591]: UDPv4 link local (bound): [AF_INET] <vip_tier1>100 | Sep 1 23:05:27 openvpn[46591]: UDPv4 link remote: [AF_INET]<ip_of_far_end_server>:16001
101 | Sep 1 23:05:28 openvpn[46591]: WARNING: 'tun-ipv6' is present in remote config but missing in local config, remote='tun-ipv6'
102 | Sep 1 23:05:28 openvpn[46591]: WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 192.168.240.38 192.168.240.37'
103 | Sep 1 23:05:28 openvpn[46591]: [<cn_of_far_end_server's_cert>] Peer Connection Initiated with [AF_INET]<ip_of_far_end_server>:16001
104 | Sep 1 23:05:34 openvpn[22772]: [<cn_of_far_end_server's_cert>] Inactivity timeout (--ping-restart), restarting
105 | Sep 1 23:05:34 openvpn[22772]: SIGUSR1[soft,ping-restart] received, process restarting
106 | Sep 1 23:05:36 openvpn[22772]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
107 | Sep 1 23:05:36 openvpn[22772]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
108 | Sep 1 23:05:36 openvpn[22772]: UDPv4 link local (bound): [AF_INET] <vip_tier2>109 | Sep 1 23:05:36 openvpn[22772]: UDPv4 link remote: [AF_INET]<ip_of_far_end_server>:16001
110 | Sep 1 23:05:37 openvpn[22772]: WARNING: 'tun-ipv6' is present in remote config but missing in local config, remote='tun-ipv6'
111 | Sep 1 23:05:37 openvpn[22772]: WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 192.168.240.38 192.168.240.37'
112 | Sep 1 23:05:37 openvpn[22772]: [<cn_of_far_end_server's_cert>] Peer Connection Initiated with [AF_INET]<ip_of_far_end_server>:16001
113 | Sep 1 23:05:39 openvpn[22772]: Preserving previous TUN/TAP instance: ovpnc2
114 | Sep 1 23:05:39 openvpn[22772]: NOTE: Pulled options changed on restart, will need to close and reopen TUN/TAP device.
115 | Sep 1 23:05:39 openvpn[22772]: /usr/local/sbin/ovpn-linkdown ovpnc2 1500 1557 192.168.240.38 192.168.240.37 init
116 | Sep 1 23:05:40 openvpn[22772]: TUN/TAP device ovpnc2 exists previously, keep at program end
117 | Sep 1 23:05:40 openvpn[22772]: TUN/TAP device /dev/tun2 opened
118 | Sep 1 23:05:40 openvpn[22772]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
119 | Sep 1 23:05:40 openvpn[22772]: /sbin/ifconfig ovpnc2 192.168.240.38 192.168.240.37 mtu 1500 netmask 255.255.255.255 up
120 | Sep 1 23:05:40 openvpn[22772]: /usr/local/sbin/ovpn-linkup ovpnc2 1500 1557 192.168.240.38 192.168.240.37 init
121 | Sep 1 23:05:40 openvpn[22772]: Initialization Sequence Completed
122 | Sep 1 23:05:43 openvpn[46591]: [<cn_of_far_end_server's_cert>] Inactivity timeout (--ping-restart), restarting
123 | Sep 1 23:05:43 openvpn[46591]: SIGUSR1[soft,ping-restart] received, process restarting
124 | Sep 1 23:05:45 openvpn[46591]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
125 | Sep 1 23:05:45 openvpn[46591]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
126 | Sep 1 23:05:45 openvpn[46591]: UDPv4 link local (bound): [AF_INET] <vip_tier1>127 | Sep 1 23:05:45 openvpn[46591]: UDPv4 link remote: [AF_INET]<ip_of_far_end_server>:16001
128 | Sep 1 23:05:46 openvpn[46591]: WARNING: 'tun-ipv6' is present in remote config but missing in local config, remote='tun-ipv6'
129 | Sep 1 23:05:46 openvpn[46591]: WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 192.168.240.38 192.168.240.37'
130 | Sep 1 23:05:46 openvpn[46591]: [<cn_of_far_end_server's_cert>] Peer Connection Initiated with [AF_INET]<ip_of_far_end_server>:16001
131 | Sep 1 23:05:52 openvpn[22772]: [<cn_of_far_end_server's_cert>] Inactivity timeout (--ping-restart), restarting
132 | Sep 1 23:05:52 openvpn[22772]: SIGUSR1[soft,ping-restart] received, process restarting
133 | Sep 1 23:05:54 openvpn[22772]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
134 | Sep 1 23:05:54 openvpn[22772]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
135 | Sep 1 23:05:54 openvpn[22772]: UDPv4 link local (bound): [AF_INET] <vip_tier2>136 | Sep 1 23:05:54 openvpn[22772]: UDPv4 link remote: [AF_INET]<ip_of_far_end_server>:16001
137 | Sep 1 23:05:55 openvpn[22772]: WARNING: 'tun-ipv6' is present in remote config but missing in local config, remote='tun-ipv6'
138 | Sep 1 23:05:55 openvpn[22772]: WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 192.168.240.38 192.168.240.37'
139 | Sep 1 23:05:55 openvpn[22772]: [<cn_of_far_end_server's_cert>] Peer Connection Initiated with [AF_INET]<ip_of_far_end_server>:16001
140 | Sep 1 23:06:00 openvpn[46591]: [<cn_of_far_end_server's_cert>] Inactivity timeout (--ping-restart), restarting
141 | Sep 1 23:06:00 openvpn[46591]: SIGUSR1[soft,ping-restart] received, process restarting
142 | Sep 1 23:06:02 openvpn[46591]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
143 | Sep 1 23:06:02 openvpn[46591]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
144 | Sep 1 23:06:02 openvpn[46591]: UDPv4 link local (bound): [AF_INET] <vip_tier1>145 | Sep 1 23:06:02 openvpn[46591]: UDPv4 link remote: [AF_INET]<ip_of_far_end_server>:16001
146 | Sep 1 23:06:03 openvpn[46591]: WARNING: 'tun-ipv6' is present in remote config but missing in local config, remote='tun-ipv6'
147 | Sep 1 23:06:03 openvpn[46591]: WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 192.168.240.38 192.168.240.37'
148 | Sep 1 23:06:03 openvpn[46591]: [<cn_of_far_end_server's_cert>] Peer Connection Initiated with [AF_INET]<ip_of_far_end_server>:16001
149 | Sep 1 23:06:08 openvpn[22772]: [<cn_of_far_end_server's_cert>] Inactivity timeout (--ping-restart), restarting
150 | Sep 1 23:06:08 openvpn[22772]: SIGUSR1[soft,ping-restart] received, process restarting
151 | Sep 1 23:06:10 openvpn[22772]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
152 | Sep 1 23:06:10 openvpn[22772]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
153 | Sep 1 23:06:10 openvpn[22772]: UDPv4 link local (bound): [AF_INET] <vip_tier2>154 | Sep 1 23:06:10 openvpn[22772]: UDPv4 link remote: [AF_INET]<ip_of_far_end_server>:16001
155 | Sep 1 23:06:10 openvpn[46591]: TUN/TAP device ovpnc2 exists previously, keep at program end
156 | Sep 1 23:06:10 openvpn[46591]: Cannot open TUN/TAP dev /dev/tun2: Device busy (errno=16)
157 | Sep 1 23:06:10 openvpn[46591]: Exiting due to fatal error
158 | Sep 1 23:06:11 openvpn[22772]: WARNING: 'tun-ipv6' is present in remote config but missing in local config, remote='tun-ipv6'
159 | Sep 1 23:06:11 openvpn[22772]: WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 192.168.240.38 192.168.240.37'
160 | Sep 1 23:06:11 openvpn[22772]: [<cn_of_far_end_server's_cert>] Peer Connection Initiated with [AF_INET]<ip_of_far_end_server>:16001
161 | Sep 1 23:06:44 openvpn[22772]: Preserving previous TUN/TAP instance: ovpnc2
162 | Sep 1 23:06:44 openvpn[22772]: NOTE: Pulled options changed on restart, will need to close and reopen TUN/TAP device.
163 | Sep 1 23:06:44 openvpn[22772]: /usr/local/sbin/ovpn-linkdown ovpnc2 1500 1557 192.168.240.38 192.168.240.37 init
164 | Sep 1 23:06:45 openvpn[22772]: TUN/TAP device ovpnc2 exists previously, keep at program end
165 | Sep 1 23:06:45 openvpn[22772]: TUN/TAP device /dev/tun2 opened
166 | Sep 1 23:06:45 openvpn[22772]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
167 | Sep 1 23:06:45 openvpn[22772]: /sbin/ifconfig ovpnc2 192.168.240.38 192.168.240.37 mtu 1500 netmask 255.255.255.255 up
168 | Sep 1 23:06:45 openvpn[22772]: /usr/local/sbin/ovpn-linkup ovpnc2 1500 1557 192.168.240.38 192.168.240.37 init
169 | Sep 1 23:06:45 openvpn[22772]: Initialization Sequence Completed</ip_of_far_end_server></cn_of_far_end_server's_cert></ip_of_far_end_server></vip_tier2></cn_of_far_end_server's_cert></ip_of_far_end_server></cn_of_far_end_server's_cert></ip_of_far_end_server></vip_tier1></cn_of_far_end_server's_cert></ip_of_far_end_server></cn_of_far_end_server's_cert></ip_of_far_end_server></vip_tier2></cn_of_far_end_server's_cert></ip_of_far_end_server></cn_of_far_end_server's_cert></ip_of_far_end_server></vip_tier1></cn_of_far_end_server's_cert></ip_of_far_end_server></cn_of_far_end_server's_cert></ip_of_far_end_server></vip_tier2></cn_of_far_end_server's_cert></ip_of_far_end_server></cn_of_far_end_server's_cert></ip_of_far_end_server></vip_tier1></cn_of_far_end_server's_cert></ip_of_far_end_server></cn_of_far_end_server's_cert></ip_of_far_end_server></vip_tier2></cn_of_far_end_server's_cert></ip_of_far_end_server></cn_of_far_end_server's_cert></ip_of_far_end_server></vip_tier1></cn_of_far_end_server's_cert></ip_of_far_end_server></cn_of_far_end_server's_cert></ip_of_far_end_server></vip_tier2></cn_of_far_end_server's_cert></ip_of_far_end_server></cn_of_far_end_server's_cert></ip_of_far_end_server></vip_tier1></cn_of_far_end_server's_cert></ip_of_far_end_server></cn_of_far_end_server's_cert></ip_of_far_end_server></vip_tier2></cn_of_far_end_server's_cert></ip_of_far_end_server></cn_of_far_end_server's_cert></ip_of_far_end_server></vip_tier1></ip_of_far_end_server></cn_of_far_end_server's_cert></ip_of_far_end_server></vip_tier1></fqdn_of_far_end_server></ip_of_far_end_server></cn_of_far_end_server's_cert></ip_of_far_end_server></vip_tier2></fqdn_of_far_end_server>

Line 006: How come a second instance of OpenVPN is spawning when the first one is still running? Do we have two different sources starting the OpenVPN client?

Line 011: Name resolution comes from DNSMasq. I guess it is not up yet. At this point pid 16778 either dies or morphs into 22772. Probably should select Infinitely resolve server.

Line 012: pid 22772 is the phantom session. How it got started is unknown. Why did it bind with the VIP of the backup tier when the primary gateway is up? When all is said and done, this sessions is still up and running.

Line 013: Magically now it was able to resolve the server name.

Line 022: pid 22772 VPN connected. How it got connected with the backup (tier2) VIP?

Line 023: This was the very first OpenVPN session that was started. Pid 24435 is no where to be found in the logs after this.

Line 024: Second instance of the same VPN trying to come up.

Line 030: Kaboom!

Line 031: What started this instance now?

Line 041: the phantom session times out. I guess because there is no way for traffic to get routed because default gateway is tier 1. Phantom session is still bound to tier 2 VIP.

After this pid 46591 and 22772 keep connecting and the timing out.

The event "Initialization Sequence Completed" is only logged by the phantom OpenVPN session. Never by 46591

Line: 157: 46591 eventually crashes.

And this is how the system sits from here on. /var/run/openvpn_client2.pid has 46591 in it. Any attempt to restart the client from the Web GUI just fails. And the phantom session is still running:

[2.1-RC1][root@fw04]/var/run(9): ps -aux | grep openvpn
root   22772  0.0  0.1 15536  5936  ??  SNs  11:04PM   0:00.64 /usr/local/sbin/openvpn --config /var/etc/openvpn/client2.conf
root   11458  0.0  0.0  9068  1464   0  S+    1:28AM   0:00.00 grep openvpn

/var/etc/openvpn/client2.conf has the correct VIP ip in there in the local statement. But I guess at some point early on in the bootup process when 22772 was spooling up it did not have the correct IP (instead had the IP of the backup tier VIP).

So I suspect the problem is that during the boot process the OpenVPN client gets spawned twice. Possibly by two separate processes. One process is able to get the correct VIP and the other is not. The one that doesn't get the correct VIP (first one to start) survives. The one that is tracked in the /var/run/openvpn_client2.pid dies.

Not sure where to look for the cause of the problem. Can anyone give me a brief lowdown of the startup process.

Thanks,

Shahid</fqdn_of_far_end_server></ip_of_far_end_server></vip_tier2></vip_tier1></fqdn_of_far_end_server>

ssheikh · Sep 2, 2013, 7:19 AM

Think I found the problem. The system log told the whole story.

I have so many interfaces and vips that it takes it a while for the kernel to bring them all up. But monitoring kicks in before interfaces are up. Causing the default gateway to flap a couple of times and trigger repetitive restarts for various components.

I made two changes to bootup.rc.

1. Moved OpenVPN to start after IPsec.

2. Added a 15 second sleep before $g['booting'] is unset.

Seems to have fixed the problem. There is probably a more elegant solution than sleeping for 15 seconds.

phil.davis · Sep 2, 2013, 1:13 PM

We (a friend at my workplace and myself) are working on some rc.bootup changes to handle low-memory systems better - giving the option to slow down the boot process, checking free memory after each significant process is started and waiting until it stabilises before moving on. We are also thinking about moving the OpenVPN startup until later, as OpenVPN process startups are memory hogs, and it might be best to have all the other essential things up and running before OpenVPN.
Hopefully there will be a proposed code solution later in the week.
If you have any ideas to share to improve the boot process, let us all know.

ssheikh · Sep 4, 2013, 7:58 AM

We probably should start another thread on optimizing rc.bootup. –> http://forum.pfsense.org/index.php/topic,66188.0.html

Shahid

eri-- · Sep 4, 2013, 9:42 AM

@phil.davis:

We (a friend at my workplace and myself) are working on some rc.bootup changes to handle low-memory systems better - giving the option to slow down the boot process, checking free memory after each significant process is started and waiting until it stabilises before moving on. We are also thinking about moving the OpenVPN startup until later, as OpenVPN process startups are memory hogs, and it might be best to have all the other essential things up and running before OpenVPN.
Hopefully there will be a proposed code solution later in the week.
If you have any ideas to share to improve the boot process, let us all know.

As i said in the other thread its not openvpn the issue its the php.

If you want to be smart enough you should optimize check_reload_status to check memory conditions or even not fire an similar even if its running.
The simple hack to make all things work on lowmem systems would be to tell check_reload_status to serialize the events and wait for one to finish before starting another.

That will give you predictable behviour on lowmem systems.