Hi, We operate an OpenVPN network with about 2000 clients in the whole world, sometimes with bad connections (packet loss and high RTT).
Since a long time, we notice the following sporadic behavior: 1. The OpenVPN connection is lost by a client, who then tries another server 2. The connection comes up, but pings don't work 3. The openvpn server is discarding incoming packets from the tunnel We had this behavior already with OpenVPN 2.1.1, and now use OpenVPN 2.3.4. I did increase the verbosity on all severs to 4, and got a pretty interesting log, which clearly shows the problem (see below). Question: as far as I know, this message "bad source address from client" happens when the server sees an incoming packet on the tunnel for which he has no "iroute" entry. Why is this happening in this case? It wrote just a few minute before: Learn: 192.0.2.12 -> h55268/203.0.113.12:3144 And then, after 5 minutes: h55268/203.0.113.12:3144 MULTI: bad source address from client [192.0.2.12], packet dropped That shouldn't happen, right? That's the correct tunnel IP of the host... Thanks David Here are the full logs with some comments: --------------------------------------------------------------------------------- OpenVPN version: 2.3.4 * Used IPs (changed from real ones for privacy): 203.0.113.12: Client Public IP (name: h55268) 192.0.2.1: Server Tunnel IP 192.0.2.12: Client Tunnel IP * 08:53:00: first try Oct 29 08:53:00 v-gate openvpn[29681]: 203.0.113.12:3133 Re-using SSL/TLS context Oct 29 08:53:00 v-gate openvpn[29681]: 203.0.113.12:3133 LZO compression initialized Oct 29 08:53:00 v-gate openvpn[29681]: 203.0.113.12:3133 Control Channel MTU parms [ L:1558 D:166 EF:66 EB:0 ET:0 EL:0 ] Oct 29 08:53:00 v-gate openvpn[29681]: 203.0.113.12:3133 Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:135 ET:0 EL:0 AF:3/1 ] Oct 29 08:53:00 v-gate openvpn[29681]: 203.0.113.12:3133 Local Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-128-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server' Oct 29 08:53:00 v-gate openvpn[29681]: 203.0.113.12:3133 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-128-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client' Oct 29 08:53:00 v-gate openvpn[29681]: 203.0.113.12:3133 Local Options hash (VER=V4): '2f29e19c' Oct 29 08:53:00 v-gate openvpn[29681]: 203.0.113.12:3133 Expected Remote Options hash (VER=V4): '9fde0044' Oct 29 08:53:00 v-gate openvpn[29681]: 203.0.113.12:3133 TLS: Initial packet from [AF_INET]203.0.113.12:3133, sid=ec179990 11c3ed56 Oct 29 08:53:08 v-gate openvpn[29681]: 203.0.113.12:3133 VERIFY SCRIPT OK: depth=1, C=CH, [...] Oct 29 08:53:08 v-gate openvpn[29681]: 203.0.113.12:3133 VERIFY OK: depth=1, C=CH, [...] Oct 29 08:53:08 v-gate openvpn[29681]: 203.0.113.12:3133 VERIFY SCRIPT OK: depth=0, C=CH, [...] Oct 29 08:53:08 v-gate openvpn[29681]: 203.0.113.12:3133 VERIFY OK: depth=0, C=CH, [...] * 08:54:00: timeout for TLS handshake Oct 29 08:54:00 v-gate openvpn[29681]: 203.0.113.12:3133 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity) Oct 29 08:54:00 v-gate openvpn[29681]: 203.0.113.12:3133 TLS Error: TLS handshake failed Oct 29 08:54:00 v-gate openvpn[29681]: 203.0.113.12:3133 SIGUSR1[soft,tls-error] received, client-instance restarting * 08:55:25: second try Oct 29 08:55:25 v-gate openvpn[29681]: 203.0.113.12:3128 Re-using SSL/TLS context Oct 29 08:55:25 v-gate openvpn[29681]: 203.0.113.12:3128 LZO compression initialized Oct 29 08:55:25 v-gate openvpn[29681]: 203.0.113.12:3128 Control Channel MTU parms [ L:1558 D:166 EF:66 EB:0 ET:0 EL:0 ] Oct 29 08:55:25 v-gate openvpn[29681]: 203.0.113.12:3128 Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:135 ET:0 EL:0 AF:3/1 ] Oct 29 08:55:25 v-gate openvpn[29681]: 203.0.113.12:3128 Local Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-128-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server' Oct 29 08:55:25 v-gate openvpn[29681]: 203.0.113.12:3128 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-128-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client' Oct 29 08:55:25 v-gate openvpn[29681]: 203.0.113.12:3128 Local Options hash (VER=V4): '2f29e19c' Oct 29 08:55:25 v-gate openvpn[29681]: 203.0.113.12:3128 Expected Remote Options hash (VER=V4): '9fde0044' Oct 29 08:55:25 v-gate openvpn[29681]: 203.0.113.12:3128 TLS: Initial packet from [AF_INET]203.0.113.12:3128, sid=61f0e44c fe37d197 Oct 29 08:55:32 v-gate openvpn[29681]: 203.0.113.12:3128 VERIFY SCRIPT OK: depth=1, C=CH, [...] Oct 29 08:55:32 v-gate openvpn[29681]: 203.0.113.12:3128 VERIFY OK: depth=1, C=CH, [...] Oct 29 08:55:32 v-gate openvpn[29681]: 203.0.113.12:3128 VERIFY SCRIPT OK: depth=0, C=CH, [...] Oct 29 08:55:32 v-gate openvpn[29681]: 203.0.113.12:3128 VERIFY OK: depth=0, C=CH, [...] Oct 29 08:55:41 v-gate openvpn[29681]: 203.0.113.12:3128 Data Channel Encrypt: Cipher 'AES-128-CBC' initialized with 128 bit key Oct 29 08:55:41 v-gate openvpn[29681]: 203.0.113.12:3128 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication Oct 29 08:55:41 v-gate openvpn[29681]: 203.0.113.12:3128 Data Channel Decrypt: Cipher 'AES-128-CBC' initialized with 128 bit key Oct 29 08:55:41 v-gate openvpn[29681]: 203.0.113.12:3128 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication * 08:56:25: timeout for TLS handshake Oct 29 08:56:25 v-gate openvpn[29681]: 203.0.113.12:3128 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity) Oct 29 08:56:25 v-gate openvpn[29681]: 203.0.113.12:3128 TLS Error: TLS handshake failed Oct 29 08:56:25 v-gate openvpn[29681]: 203.0.113.12:3128 SIGUSR1[soft,tls-error] received, client-instance restarting * 09:03:50: third try, succesful this time Oct 29 09:03:50 v-gate openvpn[29681]: 203.0.113.12:3144 Re-using SSL/TLS context Oct 29 09:03:50 v-gate openvpn[29681]: 203.0.113.12:3144 LZO compression initialized Oct 29 09:03:50 v-gate openvpn[29681]: 203.0.113.12:3144 Control Channel MTU parms [ L:1558 D:166 EF:66 EB:0 ET:0 EL:0 ] Oct 29 09:03:50 v-gate openvpn[29681]: 203.0.113.12:3144 Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:135 ET:0 EL:0 AF:3/1 ] Oct 29 09:03:50 v-gate openvpn[29681]: 203.0.113.12:3144 Local Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-128-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server' Oct 29 09:03:50 v-gate openvpn[29681]: 203.0.113.12:3144 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-128-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client' Oct 29 09:03:50 v-gate openvpn[29681]: 203.0.113.12:3144 Local Options hash (VER=V4): '2f29e19c' Oct 29 09:03:50 v-gate openvpn[29681]: 203.0.113.12:3144 Expected Remote Options hash (VER=V4): '9fde0044' Oct 29 09:03:50 v-gate openvpn[29681]: 203.0.113.12:3144 TLS: Initial packet from [AF_INET]203.0.113.12:3144, sid=72f54961 bee9340a Oct 29 09:03:52 v-gate openvpn[29681]: 203.0.113.12:3144 VERIFY SCRIPT OK: depth=1, C=CH, [...] Oct 29 09:03:52 v-gate openvpn[29681]: 203.0.113.12:3144 VERIFY OK: depth=1, C=CH, [...] Oct 29 09:03:52 v-gate openvpn[29681]: 203.0.113.12:3144 VERIFY SCRIPT OK: depth=0, C=CH, [...] Oct 29 09:03:52 v-gate openvpn[29681]: 203.0.113.12:3144 VERIFY OK: depth=0, C=CH, [...] Oct 29 09:03:52 v-gate openvpn[29681]: 203.0.113.12:3144 Data Channel Encrypt: Cipher 'AES-128-CBC' initialized with 128 bit key Oct 29 09:03:52 v-gate openvpn[29681]: 203.0.113.12:3144 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication Oct 29 09:03:52 v-gate openvpn[29681]: 203.0.113.12:3144 Data Channel Decrypt: Cipher 'AES-128-CBC' initialized with 128 bit key Oct 29 09:03:52 v-gate openvpn[29681]: 203.0.113.12:3144 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication Oct 29 09:03:52 v-gate openvpn[29681]: 203.0.113.12:3144 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA Oct 29 09:03:52 v-gate openvpn[29681]: 203.0.113.12:3144 [h55268] Peer Connection Initiated with [AF_INET]203.0.113.12:3144 Oct 29 09:03:52 v-gate openvpn[29681]: h55268/203.0.113.12:3144 MULTI_sva: pool returned IPv4=192.0.2.12, IPv6=(Not enabled) Oct 29 09:03:52 v-gate openvpn[29681]: OPENVPN:CLIENT:CONNECT h55268 203.0.113.12 BY 192.0.2.12 Oct 29 09:03:52 v-gate openvpn[29681]: h55268/203.0.113.12:3144 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_aeca221ba15dfff275feaca96fd6e33b.tmp Oct 29 09:03:52 v-gate openvpn[29681]: h55268/203.0.113.12:3144 MULTI: Learn: 192.0.2.12 -> h55268/203.0.113.12:3144 Oct 29 09:03:52 v-gate openvpn[29681]: h55268/203.0.113.12:3144 MULTI: primary virtual IP for h55268/203.0.113.12:3144: 192.0.2.12 Oct 29 09:03:55 v-gate openvpn[29681]: h55268/203.0.113.12:3144 PUSH: Received control message: 'PUSH_REQUEST' Oct 29 09:03:55 v-gate openvpn[29681]: h55268/203.0.113.12:3144 send_push_reply(): safe_cap=940 Oct 29 09:03:55 v-gate openvpn[29681]: h55268/203.0.113.12:3144 SENT CONTROL [h55268]: 'PUSH_REPLY,route 192.0.2.0 255.255.255.0 vpn_gateway,topology p2p,ping 10,ping-restart 60,ifconfig 192.0.2.12 192.0.2.1' (status=1) * 09:08:57: incoming packets get dropped because of missing iroute (?) Oct 29 09:08:57 v-gate openvpn[29681]: h55268/203.0.113.12:3144 MULTI: bad source address from client [192.0.2.12], packet dropped Oct 29 09:10:57 v-gate openvpn[29681]: h55268/203.0.113.12:3144 MULTI: bad source address from client [192.0.2.12], packet dropped Oct 29 09:12:57 v-gate openvpn[29681]: h55268/203.0.113.12:3144 MULTI: bad source address from client [192.0.2.12], packet dropped Oct 29 09:14:57 v-gate openvpn[29681]: h55268/203.0.113.12:3144 MULTI: bad source address from client [192.0.2.12], packet dropped Oct 29 09:16:57 v-gate openvpn[29681]: h55268/203.0.113.12:3144 MULTI: bad source address from client [192.0.2.12], packet dropped Oct 29 09:18:57 v-gate openvpn[29681]: h55268/203.0.113.12:3144 MULTI: bad source address from client [192.0.2.12], packet dropped Oct 29 09:20:57 v-gate openvpn[29681]: h55268/203.0.113.12:3144 MULTI: bad source address from client [192.0.2.12], packet dropped Oct 29 09:22:36 v-gate openvpn[29681]: h55268/203.0.113.12:3144 MULTI: bad source address from client [192.0.2.12], packet dropped Oct 29 09:22:57 v-gate openvpn[29681]: h55268/203.0.113.12:3144 MULTI: bad source address from client [192.0.2.12], packet dropped ------------------------------------------------------------------------------ _______________________________________________ Openvpn-users mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/openvpn-users
