[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,

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] Unexplainable "bad source address from client" after reconnect (bug?)

Robust and flexible VPN network tunnelling

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