vpn connection works... until tls soft-reset...

[nasaiya]

Hello.

I'm connecting to an openvpn server that I have no control over. It works perfectly for one hour, then the tls reset happens and after that - despite still appearing to be connected - there is no successful traffic through the vpn. If I restart openvpn (client) it works again until the next tls reset.

I'm having trouble figuring out exactly where the problem is...

My machine (the client) is set up like this:
eth0 - wan
eth1 and eth2 - local subnets (not involved with vpn)
tap0 - openvpn

I have a routing policy set up so that only desired traffic goes through the vpn, and everything else goes through the normal wan connection.

I do not have access to the server config, but my client config is:

Code: Select all

client
dev tap
proto tcp
port 5555
remote my_vpn_server.xxx
resolv-retry infinite
nobind
persist-key
persist-tun
ca tp.ca.crt
ns-cert-type server
comp-lzo
verb 3
auth-user-pass /etc/openvpn/pwf
status openvpn-status.log
log        /var/log/openvpn.log
log-append /var/log/openvpn.log 
# this is here because I don't want all traffic going through the vpn
# my "up" script takes care of routing
route-noexec
pull

I use gentoo, which has it's own up/down scripts, essentially the gentoo default scripts just take care of /etc/resolv.conf, and then call your custom scripts if applicable.

My custom up script (sets up routing, iptables rules, etc.)

Code: Select all

ip route add $trusted_ip/32 via $route_net_gateway
real_default_route=`ip route show table main | grep default`
ip route del table main $real_default_route
ip route add table real_default $real_default_route
ip route add table vpn default via $route_vpn_gateway

# I put this bogus route here because I was getting "network
# unreachable" on the initial routeing decision because
# until the mark is matched by ip rule and (re)routed correctly,
# there was no default so the packet would apparently get dropped.
ip route add table bogus default via 192.168.0.252 dev eth1

/sbin/iptables -t nat -A POSTROUTING -o tap0 -j MASQUERADE
/sbin/iptables -t mangle -A OUTPUT -p tcp --dport 80 -j MARK --set-mark 4
/sbin/iptables -t mangle -A OUTPUT -p tcp --dport 443 -j MARK --set-mark 4
/sbin/iptables -t mangle -A OUTPUT -p udp --dport 53 -j MARK --set-mark 4
# added this so vpn traffic (with invalid route at this stage) wouldn't get
# zapped by my other rules...
/sbin/iptables -I OUTPUT -m mark --mark 4 -j ACCEPT

# vpn, real_default, and bogus are in my /etc/iproute2/rt_tables
ip rule flush
ip rule add prio 32766 from all lookup main 
ip rule add prio 32767 from all lookup default 
ip rule add prio 40000 from all fwmark 0x4 lookup vpn 
ip rule add prio 40001 not from all fwmark 0x4 lookup real_default 
ip rule add prio 40002 from all lookup bogus 

ip route flush cache

My down script reverses everything that the up script does.

This all works flawlessly, until the tls-reset occurs. Here is the log: (IPs and private info changed/replaced with xxx):

Code: Select all

Mon Dec 26 17:05:57 2011 OpenVPN 2.1.4 x86_64-pc-linux-gnu [SSL] [LZO2] [EPOLL] built on Dec  4 2011
Mon Dec 26 17:05:57 2011 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Mon Dec 26 17:05:57 2011 LZO compression initialized
Mon Dec 26 17:05:57 2011 Control Channel MTU parms [ L:1576 D:140 EF:40 EB:0 ET:0 EL:0 ]
Mon Dec 26 17:05:57 2011 Socket Buffers: R=[87380->131072] S=[16384->131072]
Mon Dec 26 17:05:57 2011 Data Channel MTU parms [ L:1576 D:1450 EF:44 EB:135 ET:32 EL:0 AF:3/1 ]
Mon Dec 26 17:05:57 2011 Local Options hash (VER=V4): '31fdf004'
Mon Dec 26 17:05:57 2011 Expected Remote Options hash (VER=V4): '3e6d1056'
Mon Dec 26 17:05:57 2011 Attempting to establish TCP connection with xxx.xxx.54.12:5555 [nonblock]
Mon Dec 26 17:05:58 2011 TCP connection established with xxx.xxx.54.12:5555
Mon Dec 26 17:05:58 2011 TCPv4_CLIENT link local: [undef]
Mon Dec 26 17:05:58 2011 TCPv4_CLIENT link remote: xxx.xxx.54.12:5555
Mon Dec 26 17:05:58 2011 TLS: Initial packet from xxx.xxx.54.12:5555, sid=135bda35 9e260870
Mon Dec 26 17:05:58 2011 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Mon Dec 26 17:06:01 2011 VERIFY OK: depth=1, /C=US/ST=CA/L=xxxxxxxxxxx/O=xxxxxxxxxxxx/CN=xxxxxxxxxxxCA/emailAddress=admin@xxxxxxxxxxxxx.xxx
Mon Dec 26 17:06:01 2011 VERIFY OK: nsCertType=SERVER
Mon Dec 26 17:06:01 2011 VERIFY OK: depth=0, /C=US/ST=CA/L=xxxxxxxxxxxxx/O=xxxxxxxxxxxxx/CN=server/emailAddress=admin@xxxxxxxxxxxxx.xxx
Mon Dec 26 17:06:02 2011 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mon Dec 26 17:06:02 2011 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Dec 26 17:06:02 2011 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mon Dec 26 17:06:02 2011 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Dec 26 17:06:02 2011 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
Mon Dec 26 17:06:02 2011 [server] Peer Connection Initiated with xxx.xxx.54.12:5555
Mon Dec 26 17:06:05 2011 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Mon Dec 26 17:06:05 2011 PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1,route-gateway 10.10.0.1,dhcp-option DNS 10.10.0.1,ifconfig 10.10.0.52 255.255.255.0'
Mon Dec 26 17:06:05 2011 OPTIONS IMPORT: --ifconfig/up options modified
Mon Dec 26 17:06:05 2011 OPTIONS IMPORT: route options modified
Mon Dec 26 17:06:05 2011 OPTIONS IMPORT: route-related options modified
Mon Dec 26 17:06:05 2011 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Mon Dec 26 17:06:05 2011 ROUTE default_gateway=xxx.xxx.23.1
Mon Dec 26 17:06:05 2011 TUN/TAP device tap0 opened
Mon Dec 26 17:06:05 2011 TUN/TAP TX queue length set to 100
Mon Dec 26 17:06:05 2011 /sbin/ip link set dev tap0 up mtu 1500
Mon Dec 26 17:06:05 2011 /sbin/ip addr add dev tap0 10.10.0.52/24 broadcast 10.10.0.255
Mon Dec 26 17:06:05 2011 /etc/openvpn/up.sh tap0 1500 1576 10.10.0.52 255.255.255.0 init
 * status: inactive
Mon Dec 26 17:06:05 2011 Initialization Sequence Completed
Mon Dec 26 18:06:02 2011 TLS: soft reset sec=0 bytes=5559329/0 pkts=14618/0
Mon Dec 26 18:06:02 2011 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Mon Dec 26 18:06:05 2011 VERIFY OK: depth=1, /C=US/ST=CA/L=xxxxxxxxxxx/O=xxxxxxxxxxx/CN=xxxxxxxxxxxCA/emailAddress=admin@xxxxxxxxxxx.xxx
Mon Dec 26 18:06:05 2011 VERIFY OK: nsCertType=SERVER
Mon Dec 26 18:06:05 2011 VERIFY OK: depth=0, /C=US/ST=CA/L=xxxxxxxxxxx/O=xxxxxxxxxxx/CN=server/emailAddress=admin@xxxxxxxxxxx.xxx
Mon Dec 26 18:06:09 2011 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mon Dec 26 18:06:09 2011 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Dec 26 18:06:09 2011 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mon Dec 26 18:06:09 2011 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Dec 26 18:06:09 2011 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA

I have verified that there are no changes to the routing tables, rules, or iptables rules after the tls-reset so I'm guessing the problem is elsewhere. After the reset tcpdump -i tap0 shows nothing (except a bunch of outgoing ARPs). After a few minutes, some outgoing packets start to appear in the tcpdump but never any replies. I can't figure out where or why all these outgoing packets are disappearing. I also don't understand why they suddenly start showing up again in tcpdump, but never get replied to. The vpn connection has to be completely restarted to make it work again.

Any ideas? Thanks in advance!!

[maikcat]

you can use

reneg-sec 0

to disable tls renegotiation..

Michael.

[nasaiya]

Thanks.

I gave that a try but the renegotiation still seems to be triggered (maybe by the server?).

The log line like:

Code: Select all

Mon Dec 26 18:06:02 2011 TLS: soft reset sec=0 bytes=5559329/0 pkts=14618/0

is no longer showing up, but the rest looks the same and it still stops working.

I know others are using this same vpn with the default settings without any problem. The only difference between mine and the default settings that I'm aware of is that I added the route-noexec option and added my custom up/down scripts so my default route doesn't get replaced automatically.

That leads me to believe there is something on my end causing the problem, probably something I did

It seems strange to me that the renegotiation would cause the connection to stop working.

Any ideas why that might happen?

[krzee]

Your client log seems to be cut short... from what i see it looks like the renegotiation was going fine.
Please also post your server config, and server log (from start until after a reneg with the client)

I know others are using this same vpn with the default settings without any problem. The only difference between mine and the default settings that I'm aware of is that I added the route-noexec option and added my custom up/down scripts so my default route doesn't get replaced automatically.

ok... so lets isolate the problem.
remove reneg-sec 0 from the config

• try starting openvpn without the gentoo script, and call your scripts from the config, Do it for over an hour and see if packets keep passing when the renegotiation happens.
  try commenting route-noexec and disabling those scripts. Do it for over an hour and see if packets keep passing when the renegotiation happens.
  try adding reneg-sec 0 to both the server and client config files, this would disable forward security per session, but we can use this to be sure the problem is renegotiations

-krzee

[nasaiya]

Your client log seems to be cut short... from what i see it looks like the renegotiation was going fine.
Please also post your server config, and server log (from start until after a reneg with the client)

I thought it looked fine too, but that was the entire log. Even at log level 6 the only additional info is about ARP packets being sent repeatedly

ok... so lets isolate the problem.

Okay, here's what I've done so far:
I started with a fresh config (provided by the vpn provider):

Code: Select all

client
dev tap
proto tcp
port 5555
remote myvpnserver.xxx
resolv-retry infinite
nobind
persist-key
persist-tun
ca cert.ca.crt
comp-lzo
verb 6
log-append /var/log/openvpn.log.clean
auth-user-pass
auth-nocache
pull

The only change I made was to add the logging. I started openvpn directly using that config (to bypass all the gentoo stuff). After an hour it stopped working as usual.

I got tired of waiting for hours so out of curiosity I tried setting reneg-sec to 120 (still using the clean conf and no scripts) and watched it go... The first renegotiation happened, and the traffic stopped flowing as usual (without any errors or indications of a problem in the log). Then 2 minutes later it renegotiated again, and everything mysteriously started working again...

I let it run a few more times and more often than not it would continue to work properly after the tls-reset, but still occasionally the traffic would stop until the next one. The first reset almost always breaks it.

I also saw a "connection reset" message in the log, once or twice followed by openvpn restarting (and then working properly afterwards). Not sure if that was related or not.

I then ran it again with the gentoo scripts and my scripts back in place and with reneg-sec still set to 120 and got the same (erratic) behaviour.

Unfortunately I don't have access to the server log or configs so I can't try setting reneg-sec 0 but I can at least say I have not yet had the connection drop on it's own without the tls-reset... although that may not mean anything.

For now I've got reneg-sec commented out again (so it'll go every hour) and I'm just going to let it run for a few hours (working or not) and see what happens...

This is starting to seem more and more like an intermittent connection problem to me rather than an actual configuration problem.