Re: [Openvpn-users] Unexplainable "bad source address from client" after reconnect (bug?)

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

Hi David,

David Schweikert wrote:
> 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...
>
>
>   
you are right, this normally should not happen ; however, I did notice 
that you are using 'mode p2p' - I thought that was no longer used 
nowadays. Do you have any particular reason for using this mode? A 
better approach would be to use
  topology subnet

HTH,

JJK

> 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
> Ope...@li...
> https://lists.sourceforge.net/lists/listinfo/openvpn-users
>   

Re: [Openvpn-users] Unexplainable "bad source address from client" after reconnect (bug?)

Robust and flexible VPN network tunnelling

Re: [Openvpn-users] Unexplainable "bad source address from client" after reconnect (bug?)