VPN Failure (Is this an OpenVPN bug / remote server failure / config error or Hack?
-
I hope one of the gurus here can assist me in understanding what is happening here and give some advice.
I have an OpenVPN running 2.4.4-RELEASE-p3 and server in question has 2 OpenVPN clients (with 1 disabled), that connect to a public VPN, and 2 remote access servers (idle awaiting a valid connection). The OpenVPN client keeps going down (about once every 1-1.5 days-not sure, but it maybe a deliberate action by the service provider--or it maybe an attack on the connection --or some type of bug). Stopping and restarting the OpenVPN client service is the only way to restore the connection.
From looking at the log, the problem appears to start here:
Mar 2 19:02:45 guardian openvpn[70385]: [782c96f7267ba0608d83f93647035eb1] Inactivity timeout (--ping-restart), restarting Mar 2 19:02:45 guardian openvpn[70385]: SIGUSR1[soft,ping-restart] received, process restarting Mar 2 19:02:45 guardian openvpn[70385]: Restart pause, 10 second(s) Mar 2 19:02:55 guardian openvpn[70385]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts Mar 2 19:02:55 guardian openvpn[70385]: TCP/UDP: Preserving recently used remote address: [AF_INET]yyy.yyy.yyy.yyy:1197 Mar 2 19:02:55 guardian openvpn[70385]: Socket Buffers: R=[42080->42080] S=[57344->57344] Mar 2 19:02:55 guardian openvpn[70385]: UDPv4 link local (bound): [AF_INET]xxx.xxx.xxx.xxx:0 Mar 2 19:02:55 guardian openvpn[70385]: UDPv4 link remote: [AF_INET]yyy.yyy.yyy.yyy:1197 Mar 2 19:03:06 guardian openvpn[27905]: MANAGEMENT: Client connected from /var/etc/openvpn/server3.sock Mar 2 19:03:07 guardian openvpn[27905]: MANAGEMENT: CMD 'status 2' Mar 2 19:03:07 guardian openvpn[27905]: MANAGEMENT: CMD 'quit' Mar 2 19:03:07 guardian openvpn[27905]: MANAGEMENT: Client disconnected Mar 2 19:03:07 guardian openvpn[53698]: MANAGEMENT: Client connected from /var/etc/openvpn/server4.sock Mar 2 19:03:07 guardian openvpn[53698]: MANAGEMENT: CMD 'status 2' Mar 2 19:03:07 guardian openvpn[53698]: MANAGEMENT: CMD 'quit' Mar 2 19:03:07 guardian openvpn[53698]: MANAGEMENT: Client disconnected Mar 2 19:03:09 guardian openvpn[70385]: TLS: Initial packet from [AF_INET]yyy.yyy.yyy.yyy:1197, sid=3a0aceaf c2dd3e64 Mar 2 19:03:09 guardian openvpn[70385]: VERIFY OK: depth=1, C=US, ST=CA, L=LosAngeles, O=--------, OU=--------, CN=--------, name=--------, emailAddress=secure@-------- Mar 2 19:03:09 guardian openvpn[70385]: VERIFY KU OK Mar 2 19:03:09 guardian openvpn[70385]: Validating certificate extended key usage Mar 2 19:03:09 guardian openvpn[70385]: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication Mar 2 19:03:09 guardian openvpn[70385]: VERIFY EKU OK Mar 2 19:03:09 guardian openvpn[70385]: VERIFY OK: depth=0, C=US, ST=CA, L=LosAngeles, O=--------, OU=--------, CN=782c96f7267ba0608d83f93647035eb1, name=782c96f7267ba0608d83f93647035eb1 Mar 2 19:03:09 guardian openvpn[70385]: WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1550', remote='link-mtu 1542' Mar 2 19:03:09 guardian openvpn[70385]: WARNING: 'cipher' is used inconsistently, local='cipher AES-256-GCM', remote='cipher BF-CBC' Mar 2 19:03:09 guardian openvpn[70385]: WARNING: 'auth' is used inconsistently, local='auth [null-digest]', remote='auth SHA1' Mar 2 19:03:09 guardian openvpn[70385]: WARNING: 'keysize' is used inconsistently, local='keysize 256', remote='keysize 128' Mar 2 19:03:09 guardian openvpn[70385]: Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 4096 bit RSA Mar 2 19:03:09 guardian openvpn[70385]: [782c96f7267ba0608d83f93647035eb1] Peer Connection Initiated with [AF_INET]yyy.yyy.yyy.yyy:1197 Mar 2 19:03:10 guardian openvpn[70385]: SENT CONTROL [782c96f7267ba0608d83f93647035eb1]: 'PUSH_REQUEST' (status=1) Mar 2 19:03:15 guardian openvpn[70385]: SENT CONTROL [782c96f7267ba0608d83f93647035eb1]: 'PUSH_REQUEST' (status=1) Mar 2 19:03:15 guardian openvpn[70385]: AUTH: Received control message: AUTH_FAILED Mar 2 19:03:15 guardian openvpn[70385]: SIGUSR1[soft,auth-failure] received, process restarting Mar 2 19:03:15 guardian openvpn[70385]: Restart pause, 10 second(s) Mar 2 19:03:25 guardian openvpn[70385]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts Mar 2 19:03:25 guardian openvpn[70385]: TCP/UDP: Preserving recently used remote address: [AF_INET]yyy.yyy.yyy.yyy:1197 Mar 2 19:03:25 guardian openvpn[70385]: Socket Buffers: R=[42080->42080] S=[57344->57344] Mar 2 19:03:25 guardian openvpn[70385]: UDPv4 link local (bound): [AF_INET]xxx.xxx.xxx.xxx:0 Mar 2 19:03:25 guardian openvpn[70385]: UDPv4 link remote: [AF_INET]yyy.yyy.yyy.yyy:1197 Mar 2 19:03:25 guardian openvpn[70385]: TLS: Initial packet from [AF_INET]yyy.yyy.yyy.yyy:1197, sid=fff13b2b 37254595 Mar 2 19:03:25 guardian openvpn[70385]: VERIFY OK: depth=1, C=US, ST=CA, L=LosAngeles, O=--------, OU=--------, CN=--------, name=--------, emailAddress=secure@-------- Mar 2 19:03:25 guardian openvpn[70385]: VERIFY KU OK Mar 2 19:03:25 guardian openvpn[70385]: Validating certificate extended key usage Mar 2 19:03:25 guardian openvpn[70385]: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication Mar 2 19:03:25 guardian openvpn[70385]: VERIFY EKU OK Mar 2 19:03:25 guardian openvpn[70385]: VERIFY OK: depth=0, C=US, ST=CA, L=LosAngeles, O=--------, OU=--------, CN=782c96f7267ba0608d83f93647035eb1, name=782c96f7267ba0608d83f93647035eb1 Mar 2 19:03:26 guardian openvpn[70385]: WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1550', remote='link-mtu 1542' Mar 2 19:03:26 guardian openvpn[70385]: WARNING: 'cipher' is used inconsistently, local='cipher AES-256-GCM', remote='cipher BF-CBC' Mar 2 19:03:26 guardian openvpn[70385]: WARNING: 'auth' is used inconsistently, local='auth [null-digest]', remote='auth SHA1' Mar 2 19:03:26 guardian openvpn[70385]: WARNING: 'keysize' is used inconsistently, local='keysize 256', remote='keysize 128' Mar 2 19:03:26 guardian openvpn[70385]: Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 4096 bit RSA Mar 2 19:03:26 guardian openvpn[70385]: [782c96f7267ba0608d83f93647035eb1] Peer Connection Initiated with [AF_INET]yyy.yyy.yyy.yyy:1197 Mar 2 19:03:27 guardian openvpn[70385]: SENT CONTROL [782c96f7267ba0608d83f93647035eb1]: 'PUSH_REQUEST' (status=1) Mar 2 19:03:32 guardian openvpn[70385]: SENT CONTROL [782c96f7267ba0608d83f93647035eb1]: 'PUSH_REQUEST' (status=1) Mar 2 19:03:32 guardian openvpn[70385]: AUTH: Received control message: AUTH_FAILED Mar 2 19:03:32 guardian openvpn[70385]: SIGUSR1[soft,auth-failure] received, process restarting Mar 2 19:03:32 guardian openvpn[70385]: Restart pause, 10 second(s)
These messages keep repeating until I restart the OpenVPN client. After the reset, I get the following log:
Mar 2 19:32:07 guardian openvpn[70385]: event_wait : Interrupted system call (code=4) Mar 2 19:32:07 guardian openvpn[70385]: Closing TUN/TAP interface Mar 2 19:32:07 guardian openvpn[70385]: /usr/local/sbin/ovpn-linkdown ovpnc1 1500 1622 10.26.11.6 10.26.11.5 init Mar 2 19:32:07 guardian openvpn[70385]: SIGTERM[hard,] received, process exiting Mar 2 19:32:08 guardian openvpn[96916]: WARNING: file '/var/etc/openvpn/client1.up' is group or others accessible Mar 2 19:32:08 guardian openvpn[96916]: OpenVPN 2.4.6 amd64-portbld-freebsd11.2 [SSL (OpenSSL)] [LZO] [LZ4] [MH/RECVDA] [AEAD] built on Oct 3 2018 Mar 2 19:32:08 guardian openvpn[96916]: library versions: OpenSSL 1.0.2o-freebsd 27 Mar 2018, LZO 2.10 Mar 2 19:32:08 guardian openvpn[96995]: MANAGEMENT: unix domain socket listening on /var/etc/openvpn/client1.sock Mar 2 19:32:08 guardian openvpn[96995]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts Mar 2 19:32:08 guardian openvpn[96995]: TCP/UDP: Preserving recently used remote address: [AF_INET]172.98.67.82:1197 Mar 2 19:32:08 guardian openvpn[96995]: Socket Buffers: R=[42080->42080] S=[57344->57344] Mar 2 19:32:08 guardian openvpn[96995]: UDPv4 link local (bound): [AF_INET]xxx.xxx.xxx.xxx:0 Mar 2 19:32:08 guardian openvpn[96995]: UDPv4 link remote: [AF_INET]172.98.67.82:1197 Mar 2 19:32:08 guardian openvpn[96995]: TLS: Initial packet from [AF_INET]172.98.67.82:1197, sid=3b93c078 78a09cde Mar 2 19:32:08 guardian openvpn[96995]: WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this Mar 2 19:32:08 guardian openvpn[96995]: VERIFY OK: depth=1, C=US, ST=CA, L=LosAngeles, O=--------, OU=--------, CN=--------, name=--------, emailAddress=secure@-------- Mar 2 19:32:08 guardian openvpn[96995]: VERIFY KU OK Mar 2 19:32:08 guardian openvpn[96995]: Validating certificate extended key usage Mar 2 19:32:08 guardian openvpn[96995]: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication Mar 2 19:32:08 guardian openvpn[96995]: VERIFY EKU OK Mar 2 19:32:08 guardian openvpn[96995]: VERIFY OK: depth=0, C=US, ST=CA, L=LosAngeles, O=--------, OU=--------, CN=ed94a476f5d85a786733b30232a72030, name=ed94a476f5d85a786733b30232a72030 Mar 2 19:32:08 guardian openvpn[96995]: WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1550', remote='link-mtu 1542' Mar 2 19:32:08 guardian openvpn[96995]: WARNING: 'cipher' is used inconsistently, local='cipher AES-256-GCM', remote='cipher BF-CBC' Mar 2 19:32:08 guardian openvpn[96995]: WARNING: 'auth' is used inconsistently, local='auth [null-digest]', remote='auth SHA1' Mar 2 19:32:08 guardian openvpn[96995]: WARNING: 'keysize' is used inconsistently, local='keysize 256', remote='keysize 128' Mar 2 19:32:08 guardian openvpn[96995]: Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 4096 bit RSA Mar 2 19:32:08 guardian openvpn[96995]: [ed94a476f5d85a786733b30232a72030] Peer Connection Initiated with [AF_INET]172.98.67.82:1197 Mar 2 19:32:09 guardian openvpn[27905]: MANAGEMENT: Client connected from /var/etc/openvpn/server3.sock Mar 2 19:32:09 guardian openvpn[27905]: MANAGEMENT: CMD 'status 2' Mar 2 19:32:09 guardian openvpn[27905]: MANAGEMENT: Client disconnected Mar 2 19:32:09 guardian openvpn[53698]: MANAGEMENT: Client connected from /var/etc/openvpn/server4.sock Mar 2 19:32:09 guardian openvpn[53698]: MANAGEMENT: CMD 'status 2' Mar 2 19:32:09 guardian openvpn[53698]: MANAGEMENT: Client disconnected Mar 2 19:32:09 guardian openvpn[96995]: MANAGEMENT: Client connected from /var/etc/openvpn/client1.sock Mar 2 19:32:09 guardian openvpn[96995]: SENT CONTROL [ed94a476f5d85a786733b30232a72030]: 'PUSH_REQUEST' (status=1) Mar 2 19:32:09 guardian openvpn[96995]: MANAGEMENT: CMD 'state 1' Mar 2 19:32:09 guardian openvpn[96995]: MANAGEMENT: Client disconnected Mar 2 19:32:09 guardian openvpn[27905]: MANAGEMENT: Client connected from /var/etc/openvpn/server3.sock Mar 2 19:32:09 guardian openvpn[27905]: MANAGEMENT: CMD 'status 2' Mar 2 19:32:09 guardian openvpn[27905]: MANAGEMENT: Client disconnected Mar 2 19:32:09 guardian openvpn[53698]: MANAGEMENT: Client connected from /var/etc/openvpn/server4.sock Mar 2 19:32:09 guardian openvpn[53698]: MANAGEMENT: CMD 'status 2' Mar 2 19:32:09 guardian openvpn[53698]: MANAGEMENT: Client disconnected Mar 2 19:32:09 guardian openvpn[96995]: MANAGEMENT: Client connected from /var/etc/openvpn/client1.sock Mar 2 19:32:09 guardian openvpn[96995]: MANAGEMENT: CMD 'state 1' Mar 2 19:32:09 guardian openvpn[96995]: MANAGEMENT: Client disconnected Mar 2 19:32:09 guardian openvpn[96995]: PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS 209.222.18.222,dhcp-option DNS 209.222.18.218,ping 10,comp-lzo no,route 10.62.10.1,topology net30,ifconfig 10.62.10.6 10.62.10.5,auth-token' Mar 2 19:32:09 guardian openvpn[96995]: Options error: option 'redirect-gateway' cannot be used in this context ([PUSH-OPTIONS]) Mar 2 19:32:09 guardian openvpn[96995]: Options error: option 'dhcp-option' cannot be used in this context ([PUSH-OPTIONS]) Mar 2 19:32:09 guardian openvpn[96995]: Options error: option 'dhcp-option' cannot be used in this context ([PUSH-OPTIONS]) Mar 2 19:32:09 guardian openvpn[96995]: Options error: option 'route' cannot be used in this context ([PUSH-OPTIONS]) Mar 2 19:32:09 guardian openvpn[96995]: OPTIONS IMPORT: timers and/or timeouts modified Mar 2 19:32:09 guardian openvpn[96995]: OPTIONS IMPORT: compression parms modified Mar 2 19:32:09 guardian openvpn[96995]: OPTIONS IMPORT: --ifconfig/up options modified Mar 2 19:32:09 guardian openvpn[96995]: Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key Mar 2 19:32:09 guardian openvpn[96995]: Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key Mar 2 19:32:09 guardian openvpn[96995]: TUN/TAP device ovpnc1 exists previously, keep at program end Mar 2 19:32:09 guardian openvpn[96995]: TUN/TAP device /dev/tun1 opened Mar 2 19:32:09 guardian openvpn[96995]: do_ifconfig, tt->did_ifconfig_ipv6_setup=0 Mar 2 19:32:09 guardian openvpn[96995]: /sbin/ifconfig ovpnc1 10.62.10.6 10.62.10.5 mtu 1500 netmask 255.255.255.255 up Mar 2 19:32:09 guardian openvpn[96995]: /usr/local/sbin/ovpn-linkup ovpnc1 1500 1550 10.62.10.6 10.62.10.5 init Mar 2 19:32:09 guardian openvpn[96995]: Initialization Sequence Completed Mar 2 19:32:18 guardian openvpn[27905]: MANAGEMENT: Client connected from /var/etc/openvpn/server3.sock Mar 2 19:32:18 guardian openvpn[27905]: MANAGEMENT: CMD 'status 2' Mar 2 19:32:18 guardian openvpn[27905]: MANAGEMENT: Client disconnected Mar 2 19:32:18 guardian openvpn[53698]: MANAGEMENT: Client connected from /var/etc/openvpn/server4.sock Mar 2 19:32:18 guardian openvpn[53698]: MANAGEMENT: CMD 'status 2' Mar 2 19:32:18 guardian openvpn[53698]: MANAGEMENT: Client disconnected Mar 2 19:32:18 guardian openvpn[96995]: MANAGEMENT: Client connected from /var/etc/openvpn/client1.sock Mar 2 19:32:18 guardian openvpn[96995]: MANAGEMENT: CMD 'state 1' Mar 2 19:32:18 guardian openvpn[96995]: MANAGEMENT: CMD 'status 2' Mar 2 19:32:18 guardian openvpn[96995]: MANAGEMENT: Client disconnected
The the connection remains up and stable, but I get a constant flow of "Client connected from" entries for server3.sock, server4.sock, and client1.sock (last entries above) that repeat every 15-45 seconds.
Are those messages normal, or do I have a bug or configuration error?
Is this likely the provider dropping the connection, some kind of attack or bug?