Current setup:
- Users on Mac OSX(10.12+ Sierra or High Sierra) using tunnelblick with ovpn file
- Used Nyr openvpn installer
- Using AWS EC2 instance using m4.large
---------------------------------------------------------------------------
I am trying to get help with a weird issue that seems to plague most/all users where the client times out and says it is because of a ping-restart directive or session timeout- i could be totally off.
Here are snippets of the logs ->
####
# Server
#####
Fri Feb 16 21:17:03 2018 us=314419 event_wait : Interrupted system call (code=4)
Fri Feb 16 21:17:03 2018 us=314811 TCP/UDP: Closing socket
Fri Feb 16 21:17:03 2018 us=314853 Closing TUN/TAP interface
Fri Feb 16 21:17:03 2018 us=314876 /sbin/ip addr del dev tun0 10.8.0.1/24
RTNETLINK answers: Operation not permitted
Fri Feb 16 21:17:03 2018 us=315777 Linux ip addr del failed: external program exited with error status: 2
Fri Feb 16 21:17:03 2018 us=337611 SIGTERM[hard,] received, process exiting
####
# CLIENT LOG
####
2018 -02-16 16:19:03 us=183489 [server] Inactivity timeout (--ping-restart), restarting
…
2018-02-16 16:19:06 us=920138 NOTE: Tried to delete pre-existing tun/tap instance -- – No Problem if failure
--------------------------------------------------------------------
Here is another log from tunnelblick this morning:
####
# SERVER LOG
####
Fri Feb 23 15:25:02 2018 us=438029 MULTI: multi_create_instance called
Fri Feb 23 15:25:02 2018 us=438088 originating.ip.xx.xx:15772 Re-using SSL/TLS context
Fri Feb 23 15:25:02 2018 us=438121 originating.ip.xx.xx:15772 LZO compression initialized
Fri Feb 23 15:25:02 2018 us=438195 originating.ip.xx.xx:15772 Control Channel MTU parms [ L:1602 D:1140 EF:110 EB:0 ET:0 EL:3 ]
Fri Feb 23 15:25:02 2018 us=438205 originating.ip.xx.xx:15772 Data Channel MTU parms [ L:1602 D:1450 EF:102 EB:143 ET:0 EL:3 AF:3/1 ]
Fri Feb 23 15:25:02 2018 us=438225 originating.ip.xx.xx:15772 Local Options String: 'V4,dev-type tun,link-mtu 1602,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA512,keysize 256,tls-auth,key-method 2,tls-server'
Fri Feb 23 15:25:02 2018 us=438232 originating.ip.xx.xx:15772 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1602,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA512,keysize 256,tls-auth,key-method 2,tls-client'
Fri Feb 23 15:25:02 2018 us=438245 originating.ip.xx.xx:15772 Local Options hash (VER=V4): '14d315e7'
Fri Feb 23 15:25:02 2018 us=438254 originating.ip.xx.xx:15772 Expected Remote Options hash (VER=V4): 'a5d50645'
Fri Feb 23 15:25:02 2018 us=438276 originating.ip.xx.xx:15772 UDPv4 READ [86] from [AF_INET]originating.ip.xx.xx:15772: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 pid=[ #1 ] [ ] pid=0 DATA len=0
Fri Feb 23 15:25:02 2018 us=438286 originating.ip.xx.xx:15772 TLS: Initial packet from [AF_INET]originating.ip.xx.xx:15772, sid=42051be5 43caca41
Fri Feb 23 15:25:02 2018 us=438308 originating.ip.xx.xx:15772 UDPv4 WRITE [98] to [AF_INET]originating.ip.xx.xx:15772: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 pid=[ #1 ] [ 0 ] pid=0 DATA len=0
Fri Feb 23 15:25:02 2018 us=446839 originating.ip.xx.xx:15772 UDPv4 READ [94] from [AF_INET]originating.ip.xx.xx:15772: P_ACK_V1 kid=0 pid=[ #2 ] [ 0 ]
Fri Feb 23 15:25:02 2018 us=447181 originating.ip.xx.xx:15772 UDPv4 READ [331] from [AF_INET]originating.ip.xx.xx:15772: P_CONTROL_V1 kid=0 pid=[ #3 ] [ ] pid=1 DATA len=245
Fri Feb 23 15:25:02 2018 us=452137 originating.ip.xx.xx:15772 UDPv4 WRITE [1128] to [AF_INET]originating.ip.xx.xx:15772: P_CONTROL_V1 kid=0 pid=[ #2 ] [ 1 ] pid=1 DATA len=1030
Fri Feb 23 15:25:02 2018 us=452191 originating.ip.xx.xx:15772 UDPv4 WRITE [1116] to [AF_INET]originating.ip.xx.xx:15772: P_CONTROL_V1 kid=0 pid=[ #3 ] [ ] pid=2 DATA len=1030
Fri Feb 23 15:25:02 2018 us=452228 originating.ip.xx.xx:15772 UDPv4 WRITE [606] to [AF_INET]originating.ip.xx.xx:15772: P_CONTROL_V1 kid=0 pid=[ #4 ] [ ] pid=3 DATA len=520
Fri Feb 23 15:25:02 2018 us=460877 originating.ip.xx.xx:15772 UDPv4 READ [94] from [AF_INET]originating.ip.xx.xx:15772: P_ACK_V1 kid=0 pid=[ #4 ] [ 1 ]
Fri Feb 23 15:25:02 2018 us=462350 originating.ip.xx.xx:15772 UDPv4 READ [94] from [AF_INET]originating.ip.xx.xx:15772: P_ACK_V1 kid=0 pid=[ #5 ] [ 2 ]
Fri Feb 23 15:25:02 2018 us=491917 originating.ip.xx.xx:15772 UDPv4 READ [1128] from [AF_INET]originating.ip.xx.xx:15772: P_CONTROL_V1 kid=0 pid=[ #6 ] [ 3 ] pid=2 DATA len=1030
Fri Feb 23 15:25:02 2018 us=491953 originating.ip.xx.xx:15772 UDPv4 WRITE [94] to [AF_INET]originating.ip.xx.xx:15772: P_ACK_V1 kid=0 pid=[ #5 ] [ 2 ]
Fri Feb 23 15:25:02 2018 us=492205 originating.ip.xx.xx:15772 UDPv4 READ [1116] from [AF_INET]originating.ip.xx.xx:15772: P_CONTROL_V1 kid=0 pid=[ #7 ] [ ] pid=3 DATA len=1030
Fri Feb 23 15:25:02 2018 us=492416 originating.ip.xx.xx:15772 CRL CHECK OK: CN=ChangeMe
Fri Feb 23 15:25:02 2018 us=492437 originating.ip.xx.xx:15772 VERIFY OK: depth=1, CN=ChangeMe
Fri Feb 23 15:25:02 2018 us=492557 originating.ip.xx.xx:15772 CRL CHECK OK: CN=clientuser1
Fri Feb 23 15:25:02 2018 us=492572 originating.ip.xx.xx:15772 VERIFY OK: depth=0, CN=clientuser1
Fri Feb 23 15:25:02 2018 us=496564 originating.ip.xx.xx:15772 UDPv4 WRITE [94] to [AF_INET]originating.ip.xx.xx:15772: P_ACK_V1 kid=0 pid=[ #6 ] [ 3 ]
Fri Feb 23 15:25:02 2018 us=496611 originating.ip.xx.xx:15772 UDPv4 READ [277] from [AF_INET]originating.ip.xx.xx:15772: P_CONTROL_V1 kid=0 pid=[ #8 ] [ ] pid=4 DATA len=191
Fri Feb 23 15:25:02 2018 us=496772 originating.ip.xx.xx:15772 UDPv4 WRITE [149] to [AF_INET]originating.ip.xx.xx:15772: P_CONTROL_V1 kid=0 pid=[ #7 ] [ 4 ] pid=4 DATA len=51
Fri Feb 23 15:25:02 2018 us=504901 originating.ip.xx.xx:15772 UDPv4 READ [505] from [AF_INET]originating.ip.xx.xx:15772: P_CONTROL_V1 kid=0 pid=[ #9 ] [ 4 ] pid=5 DATA len=407
Fri Feb 23 15:25:02 2018 us=504987 originating.ip.xx.xx:15772 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Fri Feb 23 15:25:02 2018 us=505000 originating.ip.xx.xx:15772 Data Channel Encrypt: Using 512 bit message hash 'SHA512' for HMAC authentication
Fri Feb 23 15:25:02 2018 us=505007 originating.ip.xx.xx:15772 Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Fri Feb 23 15:25:02 2018 us=505015 originating.ip.xx.xx:15772 Data Channel Decrypt: Using 512 bit message hash 'SHA512' for HMAC authentication
Fri Feb 23 15:25:02 2018 us=505032 originating.ip.xx.xx:15772 UDPv4 WRITE [353] to [AF_INET]originating.ip.xx.xx:15772: P_CONTROL_V1 kid=0 pid=[ #8 ] [ 5 ] pid=5 DATA len=255
Fri Feb 23 15:25:02 2018 us=515170 originating.ip.xx.xx:15772 UDPv4 READ [94] from [AF_INET]originating.ip.xx.xx:15772: P_ACK_V1 kid=0 pid=[ #10 ] [ 5 ]
Fri Feb 23 15:25:02 2018 us=515196 originating.ip.xx.xx:15772 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES128-GCM-SHA256, 2048 bit RSA
Fri Feb 23 15:25:02 2018 us=515211 originating.ip.xx.xx:15772 [clientuser1] Peer Connection Initiated with [AF_INET]originating.ip.xx.xx:15772
Fri Feb 23 15:25:02 2018 us=515229 clientuser1/originating.ip.xx.xx:15772 MULTI_sva: pool returned IPv4=ec2.private.ip.xx, IPv6=(Not enabled)
Fri Feb 23 15:25:02 2018 us=515255 clientuser1/originating.ip.xx.xx:15772 MULTI: Learn: ec2.private.ip.xx -> clientuser1/originating.ip.xx.xx:15772
Fri Feb 23 15:25:02 2018 us=515263 clientuser1/originating.ip.xx.xx:15772 MULTI: primary virtual IP for clientuser1/originating.ip.xx.xx:15772: ec2.private.ip.xx
Fri Feb 23 15:25:02 2018 us=734286 clientuser1/originating.ip.xx.xx:15772 UDPv4 READ [161] from [AF_INET]originating.ip.xx.xx:15772: P_DATA_V1 kid=0 DATA len=160
Fri Feb 23 15:25:02 2018 us=734339 clientuser1/originating.ip.xx.xx:15772 TUN WRITE [62]
####
# CLIENT LOG
####
2018-02-23 09:46:36 *Tunnelblick: This computer's apparent public IP address changed from originating.ip.xx.xx before connection to stat.ip.xx.xx after connection
2018-02-23 10:24:58 us=157239 [server] Inactivity timeout (--ping-restart), restarting
2018-02-23 10:24:58 us=157714 TCP/UDP: Closing socket
2018-02-23 10:24:58 us=158236 SIGUSR1[soft,ping-restart] received, process restarting
2018-02-23 10:24:58 us=158312 MANAGEMENT: >STATE:1519399498,RECONNECTING,ping-restart,,
2018-02-23 10:24:58 *Tunnelblick: No 'reconnecting.sh' script to execute
2018-02-23 10:24:58 us=487675 MANAGEMENT: CMD 'hold release'
2018-02-23 10:24:58 us=487798 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
2018-02-23 10:24:58 us=488010 Re-using SSL/TLS context
2018-02-23 10:24:58 us=488419 LZO compression initialized
2018-02-23 10:24:58 us=488543 Control Channel MTU parms [ L:1602 D:1140 EF:110 EB:0 ET:0 EL:3 ]
2018-02-23 10:24:58 us=488630 Socket Buffers: R=[196724->393216] S=[9216->393216]
2018-02-23 10:24:58 us=488688 MANAGEMENT: >STATE:1519399498,RESOLVE,,,
2018-02-23 10:24:58 us=491973 Data Channel MTU parms [ L:1602 D:1450 EF:102 EB:143 ET:0 EL:3 AF:3/1 ]
2018-02-23 10:24:58 us=492092 Local Options String: 'V4,dev-type tun,link-mtu 1602,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA512,keysize 256,tls-auth,key-method 2,tls-client'
2018-02-23 10:24:58 us=492143 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1602,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA512,keysize 256,tls-auth,key-method 2,tls-server'
2018-02-23 10:24:58 us=492196 Local Options hash (VER=V4): 'a5d50645'
2018-02-23 10:24:58 us=492246 Expected Remote Options hash (VER=V4): '14d315e7'
2018-02-23 10:24:58 us=492304 UDPv4 link local: [undef]
2018-02-23 10:24:58 us=492366 UDPv4 link remote: [AF_INET]stat.ip.xx.xx:1194
2018-02-23 10:24:58 us=492420 MANAGEMENT: >STATE:1519399498,WAIT,,,
RFri Feb 23 10:24:58 2018 us=503196 MANAGEMENT: >STATE:1519399498,AUTH,,,
2018-02-23 10:24:58 us=503288 TLS: Initial packet from [AF_INET]stat.ip.xx.xx:1194, sid=0369f740 52138451
WWRWRFri Feb 23 10:24:58 2018 us=517979 VERIFY OK: depth=1, CN=ChangeMe
2018-02-23 10:24:58 us=518271 Validating certificate key usage
2018-02-23 10:24:58 us=518337 ++ Certificate has key usage 00a0, expects 00a0
2018-02-23 10:24:58 us=518503 VERIFY KU OK
2018-02-23 10:24:58 us=518704 Validating certificate extended key usage
2018-02-23 10:24:58 us=518880 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
2018-02-23 10:24:58 us=519028 VERIFY EKU OK
2018-02-23 10:24:58 us=519091 VERIFY OK: depth=0, CN=server
WRWWWRRRWRFri Feb 23 10:24:58 2018 us=570653 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
2018-02-23 10:24:58 us=571339 Data Channel Encrypt: Using 512 bit message hash 'SHA512' for HMAC authentication
2018-02-23 10:24:58 us=571508 Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
2018-02-23 10:24:58 us=571843 Data Channel Decrypt: Using 512 bit message hash 'SHA512' for HMAC authentication
WFri Feb 23 10:24:58 2018 us=572000 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES128-GCM-SHA256, 2048 bit RSA
2018-02-23 10:24:58 us=572120 [server] Peer Connection Initiated with [AF_INET]stat.ip.xx.xx:1194
rWrWRwRwrWrWRwrWrWRwRwRwRwRwRwrWrWrWrWRwRwrWrWrFri Feb 23 10:24:59 2018 us=69645 MANAGEMENT: >STATE:1519399499,GET_CONFIG,,,
rWRwrWRwrWrWRwRwrWrWrWrWRwrWRwrWrWRwRwrWRwRwrWrWRwRwrWRwrWrWRwRwRwrWrWrWrWRwRwrWRwRwrWrWRwRwrWrWRFri Feb 23 10:25:00 2018 us=1883 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
WwrWRRFri Feb 23 10:25:00 2018 us=11102 PUSH: Received control message: 'PUSH_REPLY,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 480,ifconfig ec2.private.ip.xx 255.255.255.0'
2018-02-23 10:25:00 us=11276 OPTIONS IMPORT: timers and/or timeouts modified
2018-02-23 10:25:00 us=11344 OPTIONS IMPORT: --ifconfig/up options modified
2018-02-23 10:25:00 us=11401 OPTIONS IMPORT: route-related options modified
2018-02-23 10:25:00 us=11459 Preserving previous TUN/TAP instance: utun1
2018-02-23 10:25:00 us=11534 Initialization Sequence Completed
2018-02-23 10:25:00 us=11598 MANAGEMENT: >STATE:1519399500,CONNECTED,SUCCESS,ec2.private.ip.xx,stat.ip.xx.xx
2018-02-23 10:25:00 *Tunnelblick: No 'connected.sh' script to execute
2018-02-23 10:25:05 *Tunnelblick: This computer's apparent public IP address changed from originating.ip.xx.xx before connection to stat.ip.xx.xx after connection
I have also attached my server.conf and client.ovpn file ->
server.conf and client.ovpn
