Mac OS X Lion: Ping restart every few minutes

[Jerry Jacobs]

Dear all,

Since (i think) a OS X Lion update my good working openvpn configuration is broken on Mac OS X Lion, this functions for a friend of mine which runs 10.6 and another friend which runs linux and windows (same configuration). My connection is dropped between 3-4 minutes after the link is established. I already tried the latest Tunnelblick 3.2beta32 (build 2817). I also did set the extra keepalive option to 10 minutes and 10 seconds interval. Which doesn't solve the problem.

Here are some details (important is in bold):

Kernel:

Darwin Jerrys-MacBook.local 11.2.0 Darwin Kernel Version 11.2.0: Tue Aug  9 20:54:00 PDT 2011; root:xnu-1699.24.8~1/RELEASE_X86_64 x86_64

OpenVPN:

client
dev tun
proto udp
remote myserver 1194
keepalive 10 600
resolv-retry infinite
nobind
ca ca.crt
cert client.crt
key client.key
persist-tun
persist-key
comp-lzo
verb 3
pull
mute 20

Log:

2011-10-30 13:25:40 *Tunnelblick: OS X 10.7.2; Tunnelblick 3.2beta24 (build 2625); OpenVPN 2.2.1
2011-10-30 13:25:40 *Tunnelblick: Attempting connection with myserver (VPN); Set nameserver = 1; monitoring connection
2011-10-30 13:25:40 *Tunnelblick: /Applications/Tunnelblick.app/Contents/Resources/openvpnstart start myserver.tblk 1337 1 0 0 0 49 
2011-10-30 13:25:40 OpenVPN 2.2.1 i386-apple-darwin10.8.0 [SSL] [LZO2] [PKCS11] [eurephia] built on Jul 10 2011
2011-10-30 13:25:40 MANAGEMENT: TCP Socket listening on 127.0.0.1:1337
2011-10-30 13:25:40 Need hold release from management interface, waiting...
2011-10-30 13:25:40 *Tunnelblick: openvpnstart: /Applications/Tunnelblick.app/Contents/Resources/openvpn --cd /Users/jerry/Library/Application Support/Tunnelblick/Configurations/myserver.tblk/Contents/Resources --daemon --management 127.0.0.1 1337 --config /Users/jerry/Library/Application Support/Tunnelblick/Configurations/myserver.tblk/Contents/Resources/config.ovpn --log /Library/Application Support/Tunnelblick/Logs/-SUsers-Sjerry-SLibrary-SApplication Support-STunnelblick-SConfigurations-Smyserver.tblk-SContents-SResources-Sconfig.ovpn.1_0_0_0_49.1337.openvpn.log --management-query-passwords --management-hold --script-security 2 --up /Applications/Tunnelblick.app/Contents/Resources/client.up.tunnelblick.sh -m -w -d --down /Applications/Tunnelblick.app/Contents/Resources/client.down.tunnelblick.sh -m -w -d --up-restart
2011-10-30 13:25:41 *Tunnelblick: Established communication with OpenVPN
2011-10-30 13:25:41 MANAGEMENT: Client connected from 127.0.0.1:1337
2011-10-30 13:25:41 MANAGEMENT: CMD 'pid'
2011-10-30 13:25:41 MANAGEMENT: CMD 'state on'
2011-10-30 13:25:41 MANAGEMENT: CMD 'state'
2011-10-30 13:25:41 MANAGEMENT: CMD 'hold release'
2011-10-30 13:25:41 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
2011-10-30 13:25:41 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
2011-10-30 13:25:41 LZO compression initialized
2011-10-30 13:25:41 Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
2011-10-30 13:25:41 Socket Buffers: R=[42080->65536] S=[9216->65536]
2011-10-30 13:25:41 MANAGEMENT: >STATE:1319977541,RESOLVE,,,
2011-10-30 13:25:41 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
2011-10-30 13:25:41 Local Options hash (VER=V4): '41690919'
2011-10-30 13:25:41 Expected Remote Options hash (VER=V4): '530fdded'
2011-10-30 13:25:41 UDPv4 link local: [undef]
2011-10-30 13:25:41 UDPv4 link remote: 178.63.246.226:1194
2011-10-30 13:25:41 MANAGEMENT: >STATE:1319977541,WAIT,,,
2011-10-30 13:25:41 MANAGEMENT: >STATE:1319977541,AUTH,,,
2011-10-30 13:25:41 TLS: Initial packet from 178.63.246.226:1194, sid=277bc2d8 21ad50f3
2011-10-30 13:25:41 VERIFY OK: depth=1, /C=NL/ST=NH/L=Haarlem/O=myserver/CN=myserver/emailAddress=root@myserver
2011-10-30 13:25:41 VERIFY OK: depth=0, /C=NL/ST=NH/O=myserver/CN=myserver/emailAddress=root@myserver
2011-10-30 13:25:42 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
2011-10-30 13:25:42 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
2011-10-30 13:25:42 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
2011-10-30 13:25:42 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
2011-10-30 13:25:42 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
2011-10-30 13:25:42 [myserver] Peer Connection Initiated with 178.63.246.226:1194
2011-10-30 13:25:43 MANAGEMENT: >STATE:1319977543,GET_CONFIG,,,
2011-10-30 13:25:44 SENT CONTROL [myserver]: 'PUSH_REQUEST' (status=1)
2011-10-30 13:25:44 PUSH: Received control message: 'PUSH_REPLY,route 10.8.0.0 255.255.255.0,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 120,ifconfig 10.8.0.2 255.255.255.0'
2011-10-30 13:25:44 OPTIONS IMPORT: timers and/or timeouts modified
2011-10-30 13:25:44 OPTIONS IMPORT: --ifconfig/up options modified
2011-10-30 13:25:44 OPTIONS IMPORT: route options modified
2011-10-30 13:25:44 OPTIONS IMPORT: route-related options modified
2011-10-30 13:25:44 ROUTE default_gateway=192.168.1.1
2011-10-30 13:25:44 TUN/TAP device /dev/tun0 opened
2011-10-30 13:25:44 MANAGEMENT: >STATE:1319977544,ASSIGN_IP,,10.8.0.2,
2011-10-30 13:25:44 /sbin/ifconfig tun0 delete
                                        ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address
2011-10-30 13:25:44 NOTE: Tried to delete pre-existing tun/tap instance -- No Problem if failure
2011-10-30 13:25:44 /sbin/ifconfig tun0 10.8.0.2 10.8.0.2 netmask 255.255.255.0 mtu 1500 up
2011-10-30 13:25:44 /sbin/route add -net 10.8.0.0 10.8.0.2 255.255.255.0
                                        add net 10.8.0.0: gateway 10.8.0.2
2011-10-30 13:25:44 /Applications/Tunnelblick.app/Contents/Resources/client.up.tunnelblick.sh -m -w -d tun0 1500 1542 10.8.0.2 255.255.255.0 init
2011-10-30 13:25:46 *Tunnelblick: Flushed the DNS cache
2011-10-30 13:25:46 MANAGEMENT: >STATE:1319977546,ADD_ROUTES,,,
2011-10-30 13:25:46 /sbin/route add -net 10.8.0.0 10.8.0.1 255.255.255.0
                                        route: writing to routing socket: File exists
                                        add net 10.8.0.0: gateway 10.8.0.1: File exists
2011-10-30 13:25:46 Initialization Sequence Completed
2011-10-30 13:25:46 MANAGEMENT: >STATE:1319977546,CONNECTED,SUCCESS,10.8.0.2,178.63.246.226
2011-10-30 13:25:46 *Tunnelblick client.up.tunnelblick.sh: No network configuration changes need to be made.
2011-10-30 13:25:46 *Tunnelblick client.up.tunnelblick.sh: Will NOT monitor for other network configuration changes.
2011-10-30 13:29:37 [myserver] Inactivity timeout (--ping-restart), restarting
2011-10-30 13:29:37 TCP/UDP: Closing socket
2011-10-30 13:29:37 /Applications/Tunnelblick.app/Contents/Resources/client.down.tunnelblick.sh -m -w -d tun0 1500 1542 10.8.0.2 255.255.255.0 restart
2011-10-30 13:29:38 *Tunnelblick client.down.tunnelblick.sh: WARNING: No existing OpenVPN DNS configuration found; not tearing down anything; exiting.
2011-10-30 13:29:38 SIGUSR1[soft,ping-restart] received, process restarting
2011-10-30 13:29:38 MANAGEMENT: >STATE:1319977778,RECONNECTING,ping-restart,,
2011-10-30 13:29:38 MANAGEMENT: CMD 'hold release'
2011-10-30 13:29:38 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
2011-10-30 13:29:38 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
2011-10-30 13:29:38 Re-using SSL/TLS context
2011-10-30 13:29:38 LZO compression initialized
2011-10-30 13:29:38 Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
2011-10-30 13:29:38 Socket Buffers: R=[42080->65536] S=[9216->65536]
2011-10-30 13:29:38 MANAGEMENT: >STATE:1319977778,RESOLVE,,,
2011-10-30 13:29:38 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
2011-10-30 13:29:38 Local Options hash (VER=V4): '41690919'
2011-10-30 13:29:38 Expected Remote Options hash (VER=V4): '530fdded'
2011-10-30 13:29:38 UDPv4 link local: [undef]
2011-10-30 13:29:38 UDPv4 link remote: 178.63.246.226:1194
2011-10-30 13:29:38 MANAGEMENT: >STATE:1319977778,WAIT,,,
2011-10-30 13:29:38 MANAGEMENT: >STATE:1319977778,AUTH,,,
2011-10-30 13:29:38 TLS: Initial packet from 178.63.246.226:1194, sid=352f226d c8e928d3
2011-10-30 13:29:39 VERIFY OK: depth=1, /C=NL/ST=NH/L=myserver/O=myserver/CN=myserver/emailAddress=root@myserver
2011-10-30 13:29:39 VERIFY OK: depth=0, /C=NL/ST=NH/O=myserver/CN=myserver/emailAddress=root@myserver
2011-10-30 13:29:40 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
2011-10-30 13:29:40 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
2011-10-30 13:29:40 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
2011-10-30 13:29:40 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
2011-10-30 13:29:40 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
2011-10-30 13:29:40 [myserver] Peer Connection Initiated with 178.63.246.226:1194
2011-10-30 13:29:41 MANAGEMENT: >STATE:1319977781,GET_CONFIG,,,
2011-10-30 13:29:42 SENT CONTROL [myserver]: 'PUSH_REQUEST' (status=1)
2011-10-30 13:29:42 PUSH: Received control message: 'PUSH_REPLY,route 10.8.0.0 255.255.255.0,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 120,ifconfig 10.8.0.2 255.255.255.0'
2011-10-30 13:29:42 OPTIONS IMPORT: timers and/or timeouts modified
2011-10-30 13:29:42 OPTIONS IMPORT: --ifconfig/up options modified
2011-10-30 13:29:42 OPTIONS IMPORT: route options modified
2011-10-30 13:29:42 OPTIONS IMPORT: route-related options modified
2011-10-30 13:29:42 Preserving previous TUN/TAP instance: tun0
2011-10-30 13:29:42 /Applications/Tunnelblick.app/Contents/Resources/client.up.tunnelblick.sh -m -w -d tun0 1500 1542 10.8.0.2 255.255.255.0 restart
2011-10-30 13:29:44 *Tunnelblick: Flushed the DNS cache
2011-10-30 13:29:44 Initialization Sequence Completed
2011-10-30 13:29:44 MANAGEMENT: >STATE:1319977784,CONNECTED,SUCCESS,10.8.0.2,178.63.246.226
2011-10-30 13:29:44 *Tunnelblick client.up.tunnelblick.sh: No network configuration changes need to be made.
2011-10-30 13:29:44 *Tunnelblick client.up.tunnelblick.sh: Will NOT monitor for other network configuration changes.

[jkbull...gmail.com]

Thanks for supplying your config and log.

Note the entry

2011-10-30 13:29:37 [myserver] Inactivity timeout (--ping-restart), restarting

which says that the client has tried to ping the server and not received a response within 120 seconds, so it is restarting the connection.

It did that because 'ping 10; ping-restart-120' was pushed to the client by the server. That tells the client to ping the server every 10 seconds and restart the connection if no response is received within 120 seconds.

I think that the 'ping 10; ping-restart-120' being pushed from the server overrides your "keepalive" in the client configuration, which is why the "keepalive" in your client configuration is being ignored.

So the reason for the restarts is that client is pinging the server and not getting a response. The most likely cause of that would be a firewall between you and the server. Or perhaps it is a routing problem.