[SOLVED] Client disconnecting - but why?

gilgongo

I'm using the OpenVPN client in the DD-WRT router software to connect a wireless router (which I've configured to be a wireless access point) to my VPN server running Debian Squeeze. The client on the router connects, but then disconnects immediately. Since I can't see any errors in the server logs, I'm assuming the client is deciding to disconnect.

I've tried running a client with the same configuration on a machine on the LAN that's connected to another router, and that works fine. So I suspect the problem may be due to the fact that I have the wireless router configured as an access point which (should!) be routing out to the Internet via the main router/gateway on the LAN. Does anyone have any further clues on the problem though?

Thanks for any help...

Jun 18 22:04:38 edith ovpn-server_443[12912]: MULTI: multi_create_instance called
Jun 18 22:04:38 edith ovpn-server_443[12912]: Re-using SSL/TLS context
Jun 18 22:04:38 edith ovpn-server_443[12912]: LZO compression initialized
Jun 18 22:04:38 edith ovpn-server_443[12912]: Control Channel MTU parms [ L:1544 D:140 EF:40 EB:0 ET:0 EL:0 ]
Jun 18 22:04:38 edith ovpn-server_443[12912]: Data Channel MTU parms [ L:1544 D:1450 EF:44 EB:135 ET:0 EL:0 AF:3/1 ]
Jun 18 22:04:38 edith ovpn-server_443[12912]: Local Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Jun 18 22:04:38 edith ovpn-server_443[12912]: Expected Remote Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Jun 18 22:04:38 edith ovpn-server_443[12912]: Local Options hash (VER=V4): 'c0103fa8'
Jun 18 22:04:38 edith ovpn-server_443[12912]: Expected Remote Options hash (VER=V4): '69109d17'
Jun 18 22:04:38 edith ovpn-server_443[12912]: TCP connection established with [AF_INET]93.96.x.x:2189
Jun 18 22:04:38 edith ovpn-server_443[12912]: TCPv4_SERVER link local: [undef]
Jun 18 22:04:38 edith ovpn-server_443[12912]: TCPv4_SERVER link remote: [AF_INET]93.96.x.x:2189
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [14] from [AF_INET]93.96.x.x:2189: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TLS: Initial packet from [AF_INET]93.96.x.x:2189, sid=93b6741a 2035f3dc
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [26] to [AF_INET]93.96.x.x:2189: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 0 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [106] from [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=1 DATA len=92
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [126] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ 1 ] pid=1 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=2 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=3 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=4 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 1 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=5 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 2 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=6 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [26] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 3 4 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=7 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=8 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 5 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=9 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 6 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=10 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 7 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=11 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 8 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=12 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 9 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=13 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 10 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=14 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 11 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=15 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 12 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=16 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 13 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=17 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 14 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=18 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 15 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=19 DATA len=100
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 16 ]
Jun 18 22:04:39 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=20 DATA len=100
Jun 18 22:04:40 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 17 ]
Jun 18 22:04:40 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=21 DATA len=100
Jun 18 22:04:40 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER READ [22] from [AF_INET]93.96.x.x:2189: P_ACK_V1 kid=0 [ 18 ]
Jun 18 22:04:40 edith ovpn-server_443[12912]: 93.96.x.x:2189 TCPv4_SERVER WRITE [114] to [AF_INET]93.96.x.x:2189: P_CONTROL_V1 kid=0 [ ] pid=22 DATA len=100
Jun 18 22:04:40 edith ovpn-server_443[12912]: 93.96.x.x:2189 Connection reset, restarting [0]
Jun 18 22:04:40 edith ovpn-server_443[12912]: 93.96.x.x:2189 SIGUSR1[soft,connection-reset] received, client-instance restarting
Jun 18 22:04:40 edith ovpn-server_443[12912]: TCP/UDP: Closing socket

My server config is:

port 443
proto tcp
dev tun1
ca ca.crt
cert edith-vpn.crt
key edith-vpn.key
dh dh1024.pem
server 10.8.1.0 255.255.255.0
ifconfig-pool-persist ipp_443.txt
client-config-dir ccd
route 192.168.1.0 255.255.255.0
push "redirect-gateway def1 bypass-dhcp"
push "dhcp-option DNS 208.67.222.222"
push "dhcp-option DNS 208.67.220.220"
keepalive 10 120
comp-lzo
persist-key
persist-tun
status openvpn-status_443.log
verb 5

My client config is:

client
dev tun
proto tcp
remote 80.68.x.x 443
resolv-retry infinite
nobind
persist-key
persist-tun
tun-mtu 1500
tun-mtu-extra 32
mssfix 1450
ca /tmp/openvpncl/ca.crt
cert /tmp/openvpncl/client.crt
key /tmp/openvpncl/client.key
comp-lzo

janjust

comment out the lines

tun-mtu 1500
tun-mtu-extra 32

on the client config, reconnect and post the *client* connection log this time.

gilgongo

Ah, thanks. OK those lines commented out. This is what the client log looks like (sorry - dunno why I didn't think to look at that before!) Looks like a cert problem, but I'm still confused...

Looking at http://openvpn.net/index.php/open-source/documentation/howto.html#mitm - which indicates that I might have to build the key using build-key-server, but I don't understand why my other client is able to connect OK in that case. Can't seem to find the client config on the Ubuntu machine I'm using to test that though (network-manager is weird).

Tue Jun 19 20:10:27 2012 OpenVPN 2.1.1 mipsel-unknown-linux-gnu [SSL] [LZO2] [EPOLL] built on Aug  7 2010
Tue Jun 19 20:10:27 2012 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Tue Jun 19 20:10:27 2012 WARNING: file '/tmp/openvpncl/client.key' is group or others accessible
Tue Jun 19 20:10:27 2012 LZO compression initialized
Tue Jun 19 20:10:27 2012 Attempting to establish TCP connection with 80.68.x.x:443 [nonblock]
Tue Jun 19 20:10:28 2012 TCP connection established with 80.68.x.x:443
Tue Jun 19 20:10:28 2012 TCPv4_CLIENT link local: [undef]
Tue Jun 19 20:10:28 2012 TCPv4_CLIENT link remote: 80.68.x.x:443
Tue Jun 19 20:10:29 2012 VERIFY ERROR: depth=1, error=self signed certificate in certificate chain: /C=GB/ST=England/L=London/O=x/CN=y/emailAddress=sysadmin@x.org.uk
Tue Jun 19 20:10:29 2012 TLS_ERROR: BIO read tls_read_plaintext error: error:14090086:lib(20):func(144):reason(134)
Tue Jun 19 20:10:29 2012 TLS Error: TLS object -> incoming plaintext read error
Tue Jun 19 20:10:29 2012 TLS Error: TLS handshake failed
Tue Jun 19 20:10:29 2012 Fatal TLS error (check_tls_errors_co), restarting
Tue Jun 19 20:10:29 2012 SIGUSR1[soft,tls-error] received, process restarting

janjust

which certificate is this:

Tue Jun 19 20:10:29 2012 VERIFY ERROR: depth=1, error=self signed certificate in certificate chain: /C=GB/ST=England/L=London/O=x/CN=y/emailAddress=sysadmin@x.org.uk

the CA cert or the server cert ? if it's the CA cert then make sure you have the same CA cert on your client. If it's the server cert then generate a new one : this one is broken.

gilgongo

Ah - bingo! For some reason I didn't have the same CA cert on the client as the server (or maybe it was otherwise mashed up). Hm.

Well. Works now!

Thanks so much for your time on this. Very much appreciated!

janjust

Glad to hear it's now working. Closing topic.