OpenVPN not adding routes on reconnect

whatthewhat

I am running OpenVPN 2.4.6 on both server and client with Ubuntu 16.04. My internet is not the most stable and goes down almost daily for about 20 minutes. I have a computer running at home 24/7 and is connected via OpenVPN to my own server running in the cloud. On the client computer I start openvpn at boot using systemd and it automatically connects to my vpn server with no problems.

The issue is when OpenVPN tries to reconnect to the server once the internet is restored, it is not adding back the routes. Running ifconfig shows the tun0 is still up, but running route does not show the additional vpn routes. The only way to get it to work is to shut down openvpn on the client, wait about 30 seconds and then restart it using systemctl.

I have tried removing the persist-tun and persist-key, but I am still getting the same issues.

server.conf

port 1194
proto udp
dev tun
sndbuf 0
rcvbuf 0
ca ca.crt
cert server.crt
key server.key
dh dh.pem
auth SHA512
tls-auth ta.key 0
topology subnet
server 10.8.0.0 255.255.255.0
ifconfig-pool-persist ipp.txt
push "redirect-gateway def1 bypass-dhcp"
push "dhcp-option DNS 8.8.8.8"
push "dhcp-option DNS 8.8.4.4"
keepalive 10 120
cipher AES-256-CBC
comp-lzo
user nobody
group nogroup
#persist-key    
#persist-tun  
status openvpn-status.log
verb 4
crl-verify crl.pem

client.conf

client
dev tun
proto udp
sndbuf 0
rcvbuf 0
remote 123.456.78.9 1194
resolv-retry infinite
nobind
#persist-key
#persist-tun
remote-cert-tls server
auth SHA512
cipher AES-256-CBC
comp-lzo
setenv opt block-outside-dns
key-direction 1
verb 3
log-append /var/log/openvpn.log
script-security 2
up /etc/openvpn/update-resolv-conf
down /etc/openvpn/update-resolv-conf

openvpn log on attempted reconnect

Sat Aug  4 06:53:21 2018 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Sat Aug  4 06:53:21 2018 Outgoing Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Sat Aug  4 06:53:21 2018 Incoming Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Sat Aug  4 06:53:21 2018 TCP/UDP: Preserving recently used remote address: [AF_INET]123.456.78.9:1194
Sat Aug  4 06:53:21 2018 Socket Buffers: R=[212992->212992] S=[212992->212992]
Sat Aug  4 06:53:21 2018 UDP link local: (not bound)
Sat Aug  4 06:53:21 2018 UDP link remote: [AF_INET]123.456.78.9:1194
Sat Aug  4 06:53:21 2018 TLS: Initial packet from [AF_INET]123.456.78.9:1194, sid=0f97b1b9 e7dr7548
Sat Aug  4 06:53:21 2018 VERIFY OK: depth=1, CN=ChangeMe
Sat Aug  4 06:53:21 2018 VERIFY KU OK
Sat Aug  4 06:53:21 2018 Validating certificate extended key usage
Sat Aug  4 06:53:21 2018 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sat Aug  4 06:53:21 2018 VERIFY EKU OK
Sat Aug  4 06:53:21 2018 VERIFY OK: depth=0, CN=server
Sat Aug  4 06:53:21 2018 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1550', remote='link-mtu 1602'
Sat Aug  4 06:53:21 2018 WARNING: 'cipher' is used inconsistently, local='cipher AES-256-GCM', remote='cipher AES-256-CBC'
Sat Aug  4 06:53:21 2018 WARNING: 'auth' is used inconsistently, local='auth [null-digest]', remote='auth SHA512'
Sat Aug  4 06:53:21 2018 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Aug  4 06:53:21 2018 [server] Peer Connection Initiated with [AF_INET]123.456.78.9:1194
Sat Aug  4 06:53:22 2018 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Sat Aug  4 06:53:22 2018 PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 8.8.8.8,dhcp-option DNS 8.8.4.4,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 120,ifconfig 10.8.0.2 255.255.255.0,peer-id 0,cipher AES-256-GCM'
Sat Aug  4 06:53:22 2018 OPTIONS IMPORT: timers and/or timeouts modified
Sat Aug  4 06:53:22 2018 OPTIONS IMPORT: --ifconfig/up options modified
Sat Aug  4 06:53:22 2018 OPTIONS IMPORT: route options modified
Sat Aug  4 06:53:22 2018 OPTIONS IMPORT: route-related options modified
Sat Aug  4 06:53:22 2018 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Sat Aug  4 06:53:22 2018 OPTIONS IMPORT: peer-id set
Sat Aug  4 06:53:22 2018 OPTIONS IMPORT: adjusting link_mtu to 1625
Sat Aug  4 06:53:22 2018 OPTIONS IMPORT: data channel crypto options modified
Sat Aug  4 06:53:22 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 06:53:22 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 06:53:22 2018 ROUTE_GATEWAY 192.168.1.1/255.255.255.0 IFACE=wlp6s0 HWADDR=7b:dd:76:2f:05:37
Sat Aug  4 06:53:22 2018 TUN/TAP device tun0 opened
Sat Aug  4 06:53:22 2018 TUN/TAP TX queue length set to 100
Sat Aug  4 06:53:22 2018 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Sat Aug  4 06:53:22 2018 /sbin/ip link set dev tun0 up mtu 1500
Sat Aug  4 06:53:22 2018 /sbin/ip addr add dev tun0 10.8.0.2/24 broadcast 10.8.0.255
Sat Aug  4 06:53:22 2018 /etc/openvpn/update-resolv-conf tun0 1500 1553 10.8.0.2 255.255.255.0 init
dhcp-option DNS 8.8.8.8
dhcp-option DNS 8.8.4.4

What should be there additionally in the logs

Sat Aug  4 12:58:55 2018 /sbin/ip route add 123.456.78.9/32 via 192.168.1.1
Sat Aug  4 12:58:55 2018 /sbin/ip route add 0.0.0.0/1 via 10.8.0.1
Sat Aug  4 12:58:55 2018 /sbin/ip route add 128.0.0.0/1 via 10.8.0.1
Sat Aug  4 12:58:55 2018 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Sat Aug  4 12:58:55 2018 Initialization Sequence Completed

TinCanTech

What does your route table show before and after dropping/reconnecting ?

Please also post your complete client log with both initial connection and reconnection.

whatthewhat

Route Successful connection:

Kernel IP routing table
Destination     Gateway         Genmask         Flags Metric Ref    Use Iface
0.0.0.0         10.8.0.1        128.0.0.0       UG    0      0        0 tun0
default         _gateway        0.0.0.0         UG    600    0        0 wlp6s0
10.8.0.0        0.0.0.0         255.255.255.0   U     0      0        0 tun0
128.0.0.0       10.8.0.1        128.0.0.0       UG    0      0        0 tun0
123.456.78.9    _gateway        255.255.255.255 UGH   0      0        0 wlp6s0
link-local      0.0.0.0         255.255.0.0     U     1000   0        0 wlp6s0
192.168.1.0    	0.0.0.0         255.255.255.0   U     600    0        0 wlp6s0

Route FAILED reconnect:

Kernel IP routing table
Destination     Gateway         Genmask         Flags Metric Ref    Use Iface
default         _gateway        0.0.0.0         UG    600    0        0 wlp6s0
10.8.0.0        0.0.0.0         255.255.255.0   U     0      0        0 tun0
link-local      0.0.0.0         255.255.0.0     U     1000   0        0 wlp6s0
192.168.1.0     0.0.0.0         255.255.255.0   U     600    0        0 wlp6s0

OpenVPN shutdown:

Kernel IP routing table
Destination     Gateway         Genmask         Flags Metric Ref    Use Iface
default         _gateway        0.0.0.0         UG    600    0        0 wlp6s0
link-local      0.0.0.0         255.255.0.0     U     1000   0        0 wlp6s0
192.168.1.0     0.0.0.0         255.255.255.0   U     600    0        0 wlp6s0

Full Client Logs:

Sat Aug  4 12:58:54 2018 OpenVPN 2.4.4 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Feb 10 2018
Sat Aug  4 12:58:54 2018 library versions: OpenSSL 1.1.0g  2 Nov 2017, LZO 2.08
Sat Aug  4 12:58:54 2018 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Sat Aug  4 12:58:54 2018 Outgoing Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Sat Aug  4 12:58:54 2018 Incoming Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Sat Aug  4 12:58:54 2018 TCP/UDP: Preserving recently used remote address: [AF_INET]123.456.78.9:1194
Sat Aug  4 12:58:54 2018 Socket Buffers: R=[212992->212992] S=[212992->212992]
Sat Aug  4 12:58:54 2018 UDP link local: (not bound)
Sat Aug  4 12:58:54 2018 UDP link remote: [AF_INET]123.456.78.9:1194
Sat Aug  4 12:58:54 2018 TLS: Initial packet from [AF_INET]123.456.78.9:1194, sid=61522998 8d215e9a
Sat Aug  4 12:58:54 2018 VERIFY OK: depth=1, CN=ChangeMe
Sat Aug  4 12:58:54 2018 VERIFY KU OK
Sat Aug  4 12:58:54 2018 Validating certificate extended key usage
Sat Aug  4 12:58:54 2018 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sat Aug  4 12:58:54 2018 VERIFY EKU OK
Sat Aug  4 12:58:54 2018 VERIFY OK: depth=0, CN=server
Sat Aug  4 12:58:54 2018 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Aug  4 12:58:54 2018 [server] Peer Connection Initiated with [AF_INET]123.456.78.9:1194
Sat Aug  4 12:58:55 2018 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Sat Aug  4 12:58:55 2018 PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 8.8.8.8,dhcp-option DNS 8.8.4.4,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 120,ifconfig 10.8.0.2 255.255.255.0,peer-id 0,cipher AES-256-GCM'
Sat Aug  4 12:58:55 2018 OPTIONS IMPORT: timers and/or timeouts modified
Sat Aug  4 12:58:55 2018 OPTIONS IMPORT: --ifconfig/up options modified
Sat Aug  4 12:58:55 2018 OPTIONS IMPORT: route options modified
Sat Aug  4 12:58:55 2018 OPTIONS IMPORT: route-related options modified
Sat Aug  4 12:58:55 2018 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Sat Aug  4 12:58:55 2018 OPTIONS IMPORT: peer-id set
Sat Aug  4 12:58:55 2018 OPTIONS IMPORT: adjusting link_mtu to 1625
Sat Aug  4 12:58:55 2018 OPTIONS IMPORT: data channel crypto options modified
Sat Aug  4 12:58:55 2018 Data Channel: using negotiated cipher 'AES-256-GCM'
Sat Aug  4 12:58:55 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 12:58:55 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 12:58:55 2018 ROUTE_GATEWAY 192.168.1.1/255.255.255.0 IFACE=wlp6s0 HWADDR=7b:dd:76:2f:05:37
Sat Aug  4 12:58:55 2018 TUN/TAP device tun0 opened
Sat Aug  4 12:58:55 2018 TUN/TAP TX queue length set to 100
Sat Aug  4 12:58:55 2018 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Sat Aug  4 12:58:55 2018 /sbin/ip link set dev tun0 up mtu 1500
Sat Aug  4 12:58:55 2018 /sbin/ip addr add dev tun0 10.8.0.2/24 broadcast 10.8.0.255
Sat Aug  4 12:58:55 2018 /etc/openvpn/update-resolv-conf tun0 1500 1553 10.8.0.2 255.255.255.0 init
dhcp-option DNS 8.8.8.8
dhcp-option DNS 8.8.4.4
Sat Aug  4 12:58:55 2018 /sbin/ip route add 123.456.78.9/32 via 192.168.1.1
Sat Aug  4 12:58:55 2018 /sbin/ip route add 0.0.0.0/1 via 10.8.0.1
Sat Aug  4 12:58:55 2018 /sbin/ip route add 128.0.0.0/1 via 10.8.0.1
Sat Aug  4 12:58:55 2018 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Sat Aug  4 12:58:55 2018 Initialization Sequence Completed
Sat Aug  4 13:58:54 2018 TLS: soft reset sec=0 bytes=225333641/-1 pkts=443585/0
Sat Aug  4 13:58:54 2018 VERIFY OK: depth=1, CN=ChangeMe
Sat Aug  4 13:58:54 2018 VERIFY KU OK
Sat Aug  4 13:58:54 2018 Validating certificate extended key usage
Sat Aug  4 13:58:54 2018 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sat Aug  4 13:58:54 2018 VERIFY EKU OK
Sat Aug  4 13:58:54 2018 VERIFY OK: depth=0, CN=server
Sat Aug  4 13:58:54 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 13:58:54 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 13:58:54 2018 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Aug  4 14:58:54 2018 TLS: soft reset sec=0 bytes=110410948/-1 pkts=406157/0
Sat Aug  4 14:58:54 2018 VERIFY OK: depth=1, CN=ChangeMe
Sat Aug  4 14:58:54 2018 VERIFY KU OK
Sat Aug  4 14:58:54 2018 Validating certificate extended key usage
Sat Aug  4 14:58:54 2018 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sat Aug  4 14:58:54 2018 VERIFY EKU OK
Sat Aug  4 14:58:54 2018 VERIFY OK: depth=0, CN=server
Sat Aug  4 14:58:54 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 14:58:54 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 14:58:54 2018 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Aug  4 15:58:54 2018 TLS: soft reset sec=0 bytes=85621832/-1 pkts=405380/0
Sat Aug  4 15:58:54 2018 VERIFY OK: depth=1, CN=ChangeMe
Sat Aug  4 15:58:54 2018 VERIFY KU OK
Sat Aug  4 15:58:54 2018 Validating certificate extended key usage
Sat Aug  4 15:58:54 2018 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sat Aug  4 15:58:54 2018 VERIFY EKU OK
Sat Aug  4 15:58:54 2018 VERIFY OK: depth=0, CN=server
Sat Aug  4 15:58:54 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 15:58:54 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 15:58:54 2018 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Aug  4 16:58:54 2018 VERIFY OK: depth=1, CN=ChangeMe
Sat Aug  4 16:58:54 2018 VERIFY KU OK
Sat Aug  4 16:58:54 2018 Validating certificate extended key usage
Sat Aug  4 16:58:54 2018 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sat Aug  4 16:58:54 2018 VERIFY EKU OK
Sat Aug  4 16:58:54 2018 VERIFY OK: depth=0, CN=server
Sat Aug  4 16:58:54 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 16:58:54 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 16:58:54 2018 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Aug  4 17:58:54 2018 TLS: soft reset sec=0 bytes=245778313/-1 pkts=693988/0
Sat Aug  4 17:58:54 2018 VERIFY OK: depth=1, CN=ChangeMe
Sat Aug  4 17:58:54 2018 VERIFY KU OK
Sat Aug  4 17:58:54 2018 Validating certificate extended key usage
Sat Aug  4 17:58:54 2018 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sat Aug  4 17:58:54 2018 VERIFY EKU OK
Sat Aug  4 17:58:54 2018 VERIFY OK: depth=0, CN=server
Sat Aug  4 17:58:54 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 17:58:54 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 17:58:54 2018 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Aug  4 18:58:54 2018 VERIFY OK: depth=1, CN=ChangeMe
Sat Aug  4 18:58:54 2018 VERIFY KU OK
Sat Aug  4 18:58:54 2018 Validating certificate extended key usage
Sat Aug  4 18:58:54 2018 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sat Aug  4 18:58:54 2018 VERIFY EKU OK
Sat Aug  4 18:58:54 2018 VERIFY OK: depth=0, CN=server
Sat Aug  4 18:58:54 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 18:58:54 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 18:58:54 2018 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Aug  4 19:58:54 2018 VERIFY OK: depth=1, CN=ChangeMe
Sat Aug  4 19:58:54 2018 VERIFY KU OK
Sat Aug  4 19:58:54 2018 Validating certificate extended key usage
Sat Aug  4 19:58:54 2018 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sat Aug  4 19:58:54 2018 VERIFY EKU OK
Sat Aug  4 19:58:54 2018 VERIFY OK: depth=0, CN=server
Sat Aug  4 19:58:54 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 19:58:54 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 19:58:54 2018 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Aug  4 20:58:54 2018 TLS: soft reset sec=0 bytes=268404963/-1 pkts=742069/0
Sat Aug  4 20:58:54 2018 VERIFY OK: depth=1, CN=ChangeMe
Sat Aug  4 20:58:54 2018 VERIFY KU OK
Sat Aug  4 20:58:54 2018 Validating certificate extended key usage
Sat Aug  4 20:58:54 2018 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sat Aug  4 20:58:54 2018 VERIFY EKU OK
Sat Aug  4 20:58:54 2018 VERIFY OK: depth=0, CN=server
Sat Aug  4 20:58:54 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 20:58:54 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 20:58:54 2018 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Aug  4 21:58:54 2018 VERIFY OK: depth=1, CN=ChangeMe
Sat Aug  4 21:58:54 2018 VERIFY KU OK
Sat Aug  4 21:58:54 2018 Validating certificate extended key usage
Sat Aug  4 21:58:54 2018 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sat Aug  4 21:58:54 2018 VERIFY EKU OK
Sat Aug  4 21:58:54 2018 VERIFY OK: depth=0, CN=server
Sat Aug  4 21:58:54 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 21:58:54 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 21:58:54 2018 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Aug  4 22:26:44 2018 [server] Inactivity timeout (--ping-restart), restarting
Sat Aug  4 22:26:44 2018 /sbin/ip route del 123.456.78.9/32
Sat Aug  4 22:26:44 2018 /sbin/ip route del 0.0.0.0/1
Sat Aug  4 22:26:44 2018 /sbin/ip route del 128.0.0.0/1
Sat Aug  4 22:26:44 2018 Closing TUN/TAP interface
Sat Aug  4 22:26:44 2018 /sbin/ip addr del dev tun0 10.8.0.2/24
Sat Aug  4 22:26:44 2018 /etc/openvpn/update-resolv-conf tun0 1500 1553 10.8.0.2 255.255.255.0 init
Sat Aug  4 22:26:45 2018 SIGUSR1[soft,ping-restart] received, process restarting
Sat Aug  4 22:26:45 2018 Restart pause, 5 second(s)
Sat Aug  4 22:26:50 2018 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Sat Aug  4 22:26:50 2018 Outgoing Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Sat Aug  4 22:26:50 2018 Incoming Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Sat Aug  4 22:26:50 2018 TCP/UDP: Preserving recently used remote address: [AF_INET]123.456.78.9:1194
Sat Aug  4 22:26:50 2018 Socket Buffers: R=[212992->212992] S=[212992->212992]
Sat Aug  4 22:26:50 2018 UDP link local: (not bound)
Sat Aug  4 22:26:50 2018 UDP link remote: [AF_INET]123.456.78.9:1194
Sat Aug  4 22:27:50 2018 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Sat Aug  4 22:27:50 2018 TLS Error: TLS handshake failed
Sat Aug  4 22:27:50 2018 SIGUSR1[soft,tls-error] received, process restarting
Sat Aug  4 22:27:50 2018 Restart pause, 5 second(s)
Sat Aug  4 22:27:55 2018 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Sat Aug  4 22:27:55 2018 Outgoing Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Sat Aug  4 22:27:55 2018 Incoming Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Sat Aug  4 22:27:55 2018 TCP/UDP: Preserving recently used remote address: [AF_INET]123.456.78.9:1194
Sat Aug  4 22:27:55 2018 Socket Buffers: R=[212992->212992] S=[212992->212992]
Sat Aug  4 22:27:55 2018 UDP link local: (not bound)
Sat Aug  4 22:27:55 2018 UDP link remote: [AF_INET]123.456.78.9:1194
Sat Aug  4 22:28:55 2018 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Sat Aug  4 22:28:55 2018 TLS Error: TLS handshake failed
Sat Aug  4 22:28:55 2018 SIGUSR1[soft,tls-error] received, process restarting
Sat Aug  4 22:28:55 2018 Restart pause, 5 second(s)
Sat Aug  4 22:29:00 2018 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Sat Aug  4 22:29:00 2018 Outgoing Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Sat Aug  4 22:29:00 2018 Incoming Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Sat Aug  4 22:29:00 2018 TCP/UDP: Preserving recently used remote address: [AF_INET]123.456.78.9:1194
Sat Aug  4 22:29:00 2018 Socket Buffers: R=[212992->212992] S=[212992->212992]
Sat Aug  4 22:29:00 2018 UDP link local: (not bound)
Sat Aug  4 22:29:00 2018 UDP link remote: [AF_INET]123.456.78.9:1194
Sat Aug  4 22:29:00 2018 TLS: Initial packet from [AF_INET]123.456.78.9:1194, sid=e2935425 1aa4fc51
Sat Aug  4 22:29:00 2018 VERIFY OK: depth=1, CN=ChangeMe
Sat Aug  4 22:29:00 2018 VERIFY KU OK
Sat Aug  4 22:29:00 2018 Validating certificate extended key usage
Sat Aug  4 22:29:00 2018 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sat Aug  4 22:29:00 2018 VERIFY EKU OK
Sat Aug  4 22:29:00 2018 VERIFY OK: depth=0, CN=server
Sat Aug  4 22:29:01 2018 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1550', remote='link-mtu 1602'
Sat Aug  4 22:29:01 2018 WARNING: 'cipher' is used inconsistently, local='cipher AES-256-GCM', remote='cipher AES-256-CBC'
Sat Aug  4 22:29:01 2018 WARNING: 'auth' is used inconsistently, local='auth [null-digest]', remote='auth SHA512'
Sat Aug  4 22:29:01 2018 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Aug  4 22:29:01 2018 [server] Peer Connection Initiated with [AF_INET]123.456.78.9:1194
Sat Aug  4 22:29:02 2018 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Sat Aug  4 22:29:02 2018 PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 8.8.8.8,dhcp-option DNS 8.8.4.4,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 120,ifconfig 10.8.0.2 255.255.255.0,peer-id 0,cipher AES-256-GCM'
Sat Aug  4 22:29:02 2018 OPTIONS IMPORT: timers and/or timeouts modified
Sat Aug  4 22:29:02 2018 OPTIONS IMPORT: --ifconfig/up options modified
Sat Aug  4 22:29:02 2018 OPTIONS IMPORT: route options modified
Sat Aug  4 22:29:02 2018 OPTIONS IMPORT: route-related options modified
Sat Aug  4 22:29:02 2018 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Sat Aug  4 22:29:02 2018 OPTIONS IMPORT: peer-id set
Sat Aug  4 22:29:02 2018 OPTIONS IMPORT: adjusting link_mtu to 1625
Sat Aug  4 22:29:02 2018 OPTIONS IMPORT: data channel crypto options modified
Sat Aug  4 22:29:02 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 22:29:02 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug  4 22:29:02 2018 ROUTE_GATEWAY 192.168.1.1/255.255.255.0 IFACE=wlp6s0 HWADDR=7b:dd:76:2f:05:37
Sat Aug  4 22:29:02 2018 TUN/TAP device tun0 opened
Sat Aug  4 22:29:02 2018 TUN/TAP TX queue length set to 100
Sat Aug  4 22:29:02 2018 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Sat Aug  4 22:29:02 2018 /sbin/ip link set dev tun0 up mtu 1500
Sat Aug  4 22:29:02 2018 /sbin/ip addr add dev tun0 10.8.0.2/24 broadcast 10.8.0.255
Sat Aug  4 22:29:02 2018 /etc/openvpn/update-resolv-conf tun0 1500 1553 10.8.0.2 255.255.255.0 init
dhcp-option DNS 8.8.8.8
dhcp-option DNS 8.8.4.4
Sun Aug  5 10:17:43 2018 OpenVPN 2.4.4 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Feb 10 2018
Sun Aug  5 10:17:43 2018 library versions: OpenSSL 1.1.0g  2 Nov 2017, LZO 2.08
Sun Aug  5 10:17:43 2018 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Sun Aug  5 10:17:43 2018 Outgoing Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Sun Aug  5 10:17:43 2018 Incoming Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Sun Aug  5 10:17:43 2018 TCP/UDP: Preserving recently used remote address: [AF_INET]123.456.78.9:1194
Sun Aug  5 10:17:43 2018 Socket Buffers: R=[212992->212992] S=[212992->212992]
Sun Aug  5 10:17:43 2018 UDP link local: (not bound)
Sun Aug  5 10:17:43 2018 UDP link remote: [AF_INET]123.456.78.9:1194
Sun Aug  5 10:17:43 2018 TLS: Initial packet from [AF_INET]123.456.78.9:1194, sid=f6a3f783 f8e4f7f9
Sun Aug  5 10:17:43 2018 VERIFY OK: depth=1, CN=ChangeMe
Sun Aug  5 10:17:43 2018 VERIFY KU OK
Sun Aug  5 10:17:43 2018 Validating certificate extended key usage
Sun Aug  5 10:17:43 2018 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sun Aug  5 10:17:43 2018 VERIFY EKU OK
Sun Aug  5 10:17:43 2018 VERIFY OK: depth=0, CN=server
Sun Aug  5 10:17:43 2018 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sun Aug  5 10:17:43 2018 [server] Peer Connection Initiated with [AF_INET]123.456.78.9:1194
Sun Aug  5 10:17:44 2018 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Sun Aug  5 10:17:44 2018 PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 8.8.8.8,dhcp-option DNS 8.8.4.4,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 120,ifconfig 10.8.0.2 255.255.255.0,peer-id 0,cipher AES-256-GCM'
Sun Aug  5 10:17:44 2018 OPTIONS IMPORT: timers and/or timeouts modified
Sun Aug  5 10:17:44 2018 OPTIONS IMPORT: --ifconfig/up options modified
Sun Aug  5 10:17:44 2018 OPTIONS IMPORT: route options modified
Sun Aug  5 10:17:44 2018 OPTIONS IMPORT: route-related options modified
Sun Aug  5 10:17:44 2018 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Sun Aug  5 10:17:44 2018 OPTIONS IMPORT: peer-id set
Sun Aug  5 10:17:44 2018 OPTIONS IMPORT: adjusting link_mtu to 1625
Sun Aug  5 10:17:44 2018 OPTIONS IMPORT: data channel crypto options modified
Sun Aug  5 10:17:44 2018 Data Channel: using negotiated cipher 'AES-256-GCM'
Sun Aug  5 10:17:44 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sun Aug  5 10:17:44 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sun Aug  5 10:17:44 2018 ROUTE_GATEWAY 192.168.1.1/255.255.255.0 IFACE=wlp6s0 HWADDR=7b:dd:76:2f:05:37
Sun Aug  5 10:17:44 2018 TUN/TAP device tun0 opened
Sun Aug  5 10:17:44 2018 TUN/TAP TX queue length set to 100
Sun Aug  5 10:17:44 2018 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Sun Aug  5 10:17:44 2018 /sbin/ip link set dev tun0 up mtu 1500
Sun Aug  5 10:17:44 2018 /sbin/ip addr add dev tun0 10.8.0.2/24 broadcast 10.8.0.255
Sun Aug  5 10:17:44 2018 /etc/openvpn/update-resolv-conf tun0 1500 1553 10.8.0.2 255.255.255.0 init
dhcp-option DNS 8.8.8.8
dhcp-option DNS 8.8.4.4
Sun Aug  5 10:17:44 2018 /sbin/ip route add 123.456.78.9/32 via 192.168.1.1
Sun Aug  5 10:17:44 2018 /sbin/ip route add 0.0.0.0/1 via 10.8.0.1
Sun Aug  5 10:17:44 2018 /sbin/ip route add 128.0.0.0/1 via 10.8.0.1
Sun Aug  5 10:17:44 2018 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Sun Aug  5 10:17:44 2018 Initialization Sequence Completed

TinCanTech

whatthewhat wrote The issue is when OpenVPN tries to reconnect to the server once the internet is restored, it is not adding back the routes

* sigh *

Look:

whatthewhat wrote Sat Aug 4 22:29:02 2018 PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 8.8.8.8,dhcp-option DNS 8.8.4.4,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 120,ifconfig 10.8.0.2 255.255.255.0,peer-id 0,cipher AES-256-GCM'
Sat Aug 4 22:29:02 2018 OPTIONS IMPORT: timers and/or timeouts modified
Sat Aug 4 22:29:02 2018 OPTIONS IMPORT: --ifconfig/up options modified
Sat Aug 4 22:29:02 2018 OPTIONS IMPORT: route options modified
Sat Aug 4 22:29:02 2018 OPTIONS IMPORT: route-related options modified
Sat Aug 4 22:29:02 2018 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Sat Aug 4 22:29:02 2018 OPTIONS IMPORT: peer-id set
Sat Aug 4 22:29:02 2018 OPTIONS IMPORT: adjusting link_mtu to 1625
Sat Aug 4 22:29:02 2018 OPTIONS IMPORT: data channel crypto options modified
Sat Aug 4 22:29:02 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug 4 22:29:02 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Aug 4 22:29:02 2018 ROUTE_GATEWAY 192.168.1.1/255.255.255.0 IFACE=wlp6s0 HWADDR=7b:dd:76:2f:05:37
Sat Aug 4 22:29:02 2018 TUN/TAP device tun0 opened
Sat Aug 4 22:29:02 2018 TUN/TAP TX queue length set to 100
Sat Aug 4 22:29:02 2018 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Sat Aug 4 22:29:02 2018 /sbin/ip link set dev tun0 up mtu 1500
Sat Aug 4 22:29:02 2018 /sbin/ip addr add dev tun0 10.8.0.2/24 broadcast 10.8.0.255
Sat Aug 4 22:29:02 2018 /etc/openvpn/update-resolv-conf tun0 1500 1553 10.8.0.2 255.255.255.0 init
dhcp-option DNS 8.8.8.8
dhcp-option DNS 8.8.4.4

Where is the rest of the log ?

Sun Aug 5 10:17:43 2018 OpenVPN 2.4.4 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Feb 10 2018
Sun Aug 5 10:17:43 2018 library versions: OpenSSL 1.1.0g 2 Nov 2017, LZO 2.08
Sun Aug 5 10:17:43 2018 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Sun Aug 5 10:17:43 2018 Outgoing Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Sun Aug 5 10:17:43 2018 Incoming Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Sun Aug 5 10:17:43 2018 TCP/UDP: Preserving recently used remote address: [AF_INET]123.456.78.9:1194
Sun Aug 5 10:17:43 2018 Socket Buffers: R=[212992->212992] S=[212992->212992]
Sun Aug 5 10:17:43 2018 UDP link local: (not bound)
Sun Aug 5 10:17:43 2018 UDP link remote: [AF_INET]123.456.78.9:1194
Sun Aug 5 10:17:43 2018 TLS: Initial packet from [AF_INET]123.456.78.9:1194, sid=f6a3f783 f8e4f7f9
Sun Aug 5 10:17:43 2018 VERIFY OK: depth=1, CN=ChangeMe
Sun Aug 5 10:17:43 2018 VERIFY KU OK
Sun Aug 5 10:17:43 2018 Validating certificate extended key usage
Sun Aug 5 10:17:43 2018 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sun Aug 5 10:17:43 2018 VERIFY EKU OK
Sun Aug 5 10:17:43 2018 VERIFY OK: depth=0, CN=server
Sun Aug 5 10:17:43 2018 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sun Aug 5 10:17:43 2018 [server] Peer Connection Initiated with [AF_INET]123.456.78.9:1194
Sun Aug 5 10:17:44 2018 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Sun Aug 5 10:17:44 2018 PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 8.8.8.8,dhcp-option DNS 8.8.4.4,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 120,ifconfig 10.8.0.2 255.255.255.0,peer-id 0,cipher AES-256-GCM'
Sun Aug 5 10:17:44 2018 OPTIONS IMPORT: timers and/or timeouts modified
Sun Aug 5 10:17:44 2018 OPTIONS IMPORT: --ifconfig/up options modified
Sun Aug 5 10:17:44 2018 OPTIONS IMPORT: route options modified
Sun Aug 5 10:17:44 2018 OPTIONS IMPORT: route-related options modified
Sun Aug 5 10:17:44 2018 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Sun Aug 5 10:17:44 2018 OPTIONS IMPORT: peer-id set
Sun Aug 5 10:17:44 2018 OPTIONS IMPORT: adjusting link_mtu to 1625
Sun Aug 5 10:17:44 2018 OPTIONS IMPORT: data channel crypto options modified
Sun Aug 5 10:17:44 2018 Data Channel: using negotiated cipher 'AES-256-GCM'
Sun Aug 5 10:17:44 2018 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sun Aug 5 10:17:44 2018 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sun Aug 5 10:17:44 2018 ROUTE_GATEWAY 192.168.1.1/255.255.255.0 IFACE=wlp6s0 HWADDR=7b:dd:76:2f:05:37
Sun Aug 5 10:17:44 2018 TUN/TAP device tun0 opened
Sun Aug 5 10:17:44 2018 TUN/TAP TX queue length set to 100
Sun Aug 5 10:17:44 2018 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Sun Aug 5 10:17:44 2018 /sbin/ip link set dev tun0 up mtu 1500
Sun Aug 5 10:17:44 2018 /sbin/ip addr add dev tun0 10.8.0.2/24 broadcast 10.8.0.255
Sun Aug 5 10:17:44 2018 /etc/openvpn/update-resolv-conf tun0 1500 1553 10.8.0.2 255.255.255.0 init
dhcp-option DNS 8.8.8.8
dhcp-option DNS 8.8.4.4
Sun Aug 5 10:17:44 2018 /sbin/ip route add 123.456.78.9/32 via 192.168.1.1
Sun Aug 5 10:17:44 2018 /sbin/ip route add 0.0.0.0/1 via 10.8.0.1
Sun Aug 5 10:17:44 2018 /sbin/ip route add 128.0.0.0/1 via 10.8.0.1
Sun Aug 5 10:17:44 2018 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Sun Aug 5 10:17:44 2018 Initialization Sequence Completed

I have tested this thoroughly and what you claim happens .. does not happen.

If openvpn were to behave as you claim we would have thousands of complaints about it.

There is a tiny chance that the version 2.4.4 which you are running has some unknown issue ..
Therefore, can you please test the exact same setup with the most recent release version 2.4.6
which you can probably download from here:
https://community.openvpn.net/openvpn/wiki/OpenvpnSoftwareRepos

whatthewhat

Where is the rest of the log? That is the entire log, and I will say again, that on a failed reconnect it does not add the additional routes. It was offline for 12 hours. The only way to get it to actually connect is to shutdown openvpn and restart it manually. The time of "Sun Aug 5 10:17:43 2018" is when I restarted it manually.

TinCanTech

You can try increasing the client --verb to 6 .. see if the log has anything new to offer.

You can try upgrading to the latest release (as above) -- this is what I would try ..

I presume you are not using NetworkManager ?

TinCanTech

FYI:

whatthewhat wrote I am running OpenVPN 2.4.6 on both server and client with Ubuntu 16.04

whatthewhat wrote Full Client Logs:

Code:

Sat Aug 4 12:58:54 2018 OpenVPN 2.4.4 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Feb 10 2018
Sat Aug 4 12:58:54 2018 library versions: OpenSSL 1.1.0g 2 Nov 2017, LZO 2.08

:geek:

whatthewhat

Just a little update. I tried 2.4.6 on both client and server and was still running into the same issue. I decided to switch to a different vpn protocol, which is working perfectly.

Thanks for trying to help me out regardless.

TinCanTech

whatthewhat wrote I decided to switch to a different vpn protocol, which is working perfectly.

I presume you mean you changed from UDP to TCP ?

This should not make any difference because the problem is occurring long after openvpn has selected protocol. Your log indicates that problem is occurring after, or during, calling the --up script .. at that point openvpn stops:

TinCanTech wrote Sat Aug 4 22:29:02 2018 /etc/openvpn/update-resolv-conf tun0 1500 1553 10.8.0.2 255.255.255.0 init
dhcp-option DNS 8.8.8.8
dhcp-option DNS 8.8.4.4

Where is the rest of the log ?

Sun Aug 5 10:17:43 2018 OpenVPN 2.4.4 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD]

whatthewhat wrote The only way to get it to actually connect is to shutdown openvpn and restart it manually

Has openvpn crashed .. is the process still running before you restart it ?

Does the version you are using have systemd support enabled ?
Use openvpn --version and look for enable_systemd=yes

I have ubuntu 16.04 and have tested a few possibilities but so far cannot make it fail.

It would be interesting to find out what the real cause is :geek:

whatthewhat

I'm not using OpenVPN anymore. I switched to Wireguard.