Client - Server connection no longer working

hpoonis · Post by **hpoonis** » Wed Jul 18, 2018 8:48 am

Setup is thus:-

All systems are on internal work lan.
Server Ubuntu 18.04 (updated) - 10.8.0.1
Clients connect and ccd files deliver static IP addresses to each client.

2 Clients - gns3vm appliances (Ubuntu 14).

- One installed on Ubuntu 18.04 (updated) as a KVM/QEMU virtual machine - gns3vm3 (supposed to be 10.8.0.13)
- One installed on ESXi6.5 - gns3vm1 (10.8.0.11)

All was working with no problems. Yesterday I moved all to adjacent desk (2.5m to the left). Disconnected and reconnected both Ubuntu systems (server and gns3vm3).

Server and gns3vm1 (ESXi) are still working fine and happily connected but gns3vm3 no longer connects and I see TLS-AUTH errors.

No software configuration changes have been made between the 40 minutes or so it took me to disconnect and reconnect all systems, wires, net ports, etc. Each clients config is exactly the same with the only difference being the local .crt/key filenames in the client.conf file. Each client uses server name in the hosts file and not IP address so if IP does change I just edit hosts file. However...

SERVER AND CLIENTS STILL HAVE SAME DHCP IP LEASES and NO MAC ADDRESS CHANGES HAVE OCCURRED.

I am mystified as to why this may be so.

***********************************************
***********************************************

Here is the startup portion of the server log:

Wed Jul 18 10:36:21 2018 us=433862 Current Parameter Settings:
Wed Jul 18 10:36:21 2018 us=433897 config = '/etc/openvpn/server.conf'
Wed Jul 18 10:36:21 2018 us=433904 mode = 1
Wed Jul 18 10:36:21 2018 us=433909 persist_config = DISABLED
Wed Jul 18 10:36:21 2018 us=433914 persist_mode = 1
Wed Jul 18 10:36:21 2018 us=433918 show_ciphers = DISABLED
Wed Jul 18 10:36:21 2018 us=433923 show_digests = DISABLED
Wed Jul 18 10:36:21 2018 us=433927 show_engines = DISABLED
Wed Jul 18 10:36:21 2018 us=433931 genkey = DISABLED
Wed Jul 18 10:36:21 2018 us=433936 key_pass_file = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=433940 show_tls_ciphers = DISABLED
Wed Jul 18 10:36:21 2018 us=433944 connect_retry_max = 0
Wed Jul 18 10:36:21 2018 us=433949 Connection profiles [0]:
Wed Jul 18 10:36:21 2018 us=433954 proto = udp
Wed Jul 18 10:36:21 2018 us=433959 local = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=433963 local_port = '1194'
Wed Jul 18 10:36:21 2018 us=433967 remote = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=433971 remote_port = '1194'
Wed Jul 18 10:36:21 2018 us=433976 remote_float = DISABLED
Wed Jul 18 10:36:21 2018 us=433980 bind_defined = DISABLED
Wed Jul 18 10:36:21 2018 us=433984 bind_local = ENABLED
Wed Jul 18 10:36:21 2018 us=433988 bind_ipv6_only = DISABLED
Wed Jul 18 10:36:21 2018 us=433992 connect_retry_seconds = 5
Wed Jul 18 10:36:21 2018 us=433997 connect_timeout = 120
Wed Jul 18 10:36:21 2018 us=434001 socks_proxy_server = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434005 socks_proxy_port = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434011 tun_mtu = 1500
Wed Jul 18 10:36:21 2018 us=434015 tun_mtu_defined = ENABLED
Wed Jul 18 10:36:21 2018 us=434020 link_mtu = 1500
Wed Jul 18 10:36:21 2018 us=434024 link_mtu_defined = DISABLED
Wed Jul 18 10:36:21 2018 us=434028 tun_mtu_extra = 0
Wed Jul 18 10:36:21 2018 us=434032 tun_mtu_extra_defined = DISABLED
Wed Jul 18 10:36:21 2018 us=434036 mtu_discover_type = -1
Wed Jul 18 10:36:21 2018 us=434040 fragment = 0
Wed Jul 18 10:36:21 2018 us=434045 mssfix = 1450
Wed Jul 18 10:36:21 2018 us=434049 explicit_exit_notification = 1
Wed Jul 18 10:36:21 2018 us=434053 Connection profiles END
Wed Jul 18 10:36:21 2018 us=434057 remote_random = DISABLED
Wed Jul 18 10:36:21 2018 us=434062 ipchange = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434066 dev = 'tun'
Wed Jul 18 10:36:21 2018 us=434070 dev_type = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434074 dev_node = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434078 lladdr = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434082 topology = 1
Wed Jul 18 10:36:21 2018 us=434087 ifconfig_local = '10.8.0.1'
Wed Jul 18 10:36:21 2018 us=434091 ifconfig_remote_netmask = '10.8.0.2'
Wed Jul 18 10:36:21 2018 us=434095 ifconfig_noexec = DISABLED
Wed Jul 18 10:36:21 2018 us=434099 ifconfig_nowarn = DISABLED
Wed Jul 18 10:36:21 2018 us=434103 ifconfig_ipv6_local = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434107 ifconfig_ipv6_netbits = 0
Wed Jul 18 10:36:21 2018 us=434112 ifconfig_ipv6_remote = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434116 shaper = 0
Wed Jul 18 10:36:21 2018 us=434120 mtu_test = 0
Wed Jul 18 10:36:21 2018 us=434124 mlock = DISABLED
Wed Jul 18 10:36:21 2018 us=434129 keepalive_ping = 10
Wed Jul 18 10:36:21 2018 us=434133 keepalive_timeout = 120
Wed Jul 18 10:36:21 2018 us=434137 inactivity_timeout = 0
Wed Jul 18 10:36:21 2018 us=434141 ping_send_timeout = 10
Wed Jul 18 10:36:21 2018 us=434145 ping_rec_timeout = 240
Wed Jul 18 10:36:21 2018 us=434150 ping_rec_timeout_action = 2
Wed Jul 18 10:36:21 2018 us=434154 ping_timer_remote = DISABLED
Wed Jul 18 10:36:21 2018 us=434158 remap_sigusr1 = 0
Wed Jul 18 10:36:21 2018 us=434162 persist_tun = ENABLED
Wed Jul 18 10:36:21 2018 us=434166 persist_local_ip = DISABLED
Wed Jul 18 10:36:21 2018 us=434170 persist_remote_ip = DISABLED
Wed Jul 18 10:36:21 2018 us=434175 persist_key = ENABLED
Wed Jul 18 10:36:21 2018 us=434179 passtos = DISABLED
Wed Jul 18 10:36:21 2018 us=434183 resolve_retry_seconds = 1000000000
Wed Jul 18 10:36:21 2018 us=434187 resolve_in_advance = DISABLED
Wed Jul 18 10:36:21 2018 us=434205 username = 'nobody'
Wed Jul 18 10:36:21 2018 us=434210 groupname = 'nogroup'
Wed Jul 18 10:36:21 2018 us=434214 chroot_dir = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434218 cd_dir = '/etc/openvpn'
Wed Jul 18 10:36:21 2018 us=434222 writepid = '/run/openvpn/server.pid'
Wed Jul 18 10:36:21 2018 us=434227 up_script = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434231 down_script = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434235 down_pre = DISABLED
Wed Jul 18 10:36:21 2018 us=434239 up_restart = DISABLED
Wed Jul 18 10:36:21 2018 us=434243 up_delay = DISABLED
Wed Jul 18 10:36:21 2018 us=434248 daemon = ENABLED
Wed Jul 18 10:36:21 2018 us=434252 inetd = 0
Wed Jul 18 10:36:21 2018 us=434256 log = ENABLED
Wed Jul 18 10:36:21 2018 us=434260 suppress_timestamps = DISABLED
Wed Jul 18 10:36:21 2018 us=434264 machine_readable_output = DISABLED
Wed Jul 18 10:36:21 2018 us=434269 nice = 0
Wed Jul 18 10:36:21 2018 us=434273 verbosity = 5
Wed Jul 18 10:36:21 2018 us=434277 mute = 0
Wed Jul 18 10:36:21 2018 us=434281 gremlin = 0
Wed Jul 18 10:36:21 2018 us=434285 status_file = '/var/log/openvpn/openvpn-status.log'
Wed Jul 18 10:36:21 2018 us=434290 status_file_version = 1
Wed Jul 18 10:36:21 2018 us=434294 status_file_update_freq = 10
Wed Jul 18 10:36:21 2018 us=434298 occ = ENABLED
Wed Jul 18 10:36:21 2018 us=434302 rcvbuf = 0
Wed Jul 18 10:36:21 2018 us=434306 sndbuf = 0
Wed Jul 18 10:36:21 2018 us=434311 mark = 0
Wed Jul 18 10:36:21 2018 us=434315 sockflags = 0
Wed Jul 18 10:36:21 2018 us=434319 fast_io = DISABLED
Wed Jul 18 10:36:21 2018 us=434323 comp.alg = 2
Wed Jul 18 10:36:21 2018 us=434327 comp.flags = 1
Wed Jul 18 10:36:21 2018 us=434331 route_script = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434336 route_default_gateway = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434340 route_default_metric = 0
Wed Jul 18 10:36:21 2018 us=434344 route_noexec = DISABLED
Wed Jul 18 10:36:21 2018 us=434348 route_delay = 0
Wed Jul 18 10:36:21 2018 us=434353 route_delay_window = 30
Wed Jul 18 10:36:21 2018 us=434357 route_delay_defined = DISABLED
Wed Jul 18 10:36:21 2018 us=434361 route_nopull = DISABLED
Wed Jul 18 10:36:21 2018 us=434365 route_gateway_via_dhcp = DISABLED
Wed Jul 18 10:36:21 2018 us=434369 allow_pull_fqdn = DISABLED
Wed Jul 18 10:36:21 2018 us=434374 route 10.8.0.0/255.255.255.0/default (not set)/default (not set)
Wed Jul 18 10:36:21 2018 us=434379 route 10.8.0.0/255.255.255.0/default (not set)/default (not set)
Wed Jul 18 10:36:21 2018 us=434383 management_addr = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434387 management_port = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434392 management_user_pass = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434396 management_log_history_cache = 250
Wed Jul 18 10:36:21 2018 us=434400 management_echo_buffer_size = 100
Wed Jul 18 10:36:21 2018 us=434404 management_write_peer_info_file = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434409 management_client_user = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434413 management_client_group = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434417 management_flags = 0
Wed Jul 18 10:36:21 2018 us=434421 shared_secret_file = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434426 key_direction = 1
Wed Jul 18 10:36:21 2018 us=434430 ciphername = 'AES-256-CBC'
Wed Jul 18 10:36:21 2018 us=434434 ncp_enabled = ENABLED
Wed Jul 18 10:36:21 2018 us=434439 ncp_ciphers = 'AES-256-GCM:AES-128-GCM'
Wed Jul 18 10:36:21 2018 us=434443 authname = 'SHA256'
Wed Jul 18 10:36:21 2018 us=434447 prng_hash = 'SHA1'
Wed Jul 18 10:36:21 2018 us=434451 prng_nonce_secret_len = 16
Wed Jul 18 10:36:21 2018 us=434456 keysize = 0
Wed Jul 18 10:36:21 2018 us=434460 engine = DISABLED
Wed Jul 18 10:36:21 2018 us=434464 replay = ENABLED
Wed Jul 18 10:36:21 2018 us=434468 mute_replay_warnings = DISABLED
Wed Jul 18 10:36:21 2018 us=434473 replay_window = 64
Wed Jul 18 10:36:21 2018 us=434477 replay_time = 15
Wed Jul 18 10:36:21 2018 us=434481 packet_id_file = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434489 use_iv = ENABLED
Wed Jul 18 10:36:21 2018 us=434493 test_crypto = DISABLED
Wed Jul 18 10:36:21 2018 us=434497 tls_server = ENABLED
Wed Jul 18 10:36:21 2018 us=434502 tls_client = DISABLED
Wed Jul 18 10:36:21 2018 us=434506 key_method = 2
Wed Jul 18 10:36:21 2018 us=434510 ca_file = 'ca.crt'
Wed Jul 18 10:36:21 2018 us=434514 ca_path = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434519 dh_file = 'dh2048.pem'
Wed Jul 18 10:36:21 2018 us=434523 cert_file = 'amd-tr.crt'
Wed Jul 18 10:36:21 2018 us=434527 extra_certs_file = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434531 priv_key_file = 'amd-tr.key'
Wed Jul 18 10:36:21 2018 us=434536 pkcs12_file = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434540 cipher_list = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434544 tls_verify = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434548 tls_export_cert = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434552 verify_x509_type = 0
Wed Jul 18 10:36:21 2018 us=434556 verify_x509_name = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434561 crl_file = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434565 ns_cert_type = 0
Wed Jul 18 10:36:21 2018 us=434569 remote_cert_ku = 0
...
...
Wed Jul 18 10:36:21 2018 us=434632 remote_cert_ku = 0
Wed Jul 18 10:36:21 2018 us=434636 remote_cert_eku = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434641 ssl_flags = 0
Wed Jul 18 10:36:21 2018 us=434645 tls_timeout = 2
Wed Jul 18 10:36:21 2018 us=434649 renegotiate_bytes = -1
Wed Jul 18 10:36:21 2018 us=434654 renegotiate_packets = 0
Wed Jul 18 10:36:21 2018 us=434658 renegotiate_seconds = 3600
Wed Jul 18 10:36:21 2018 us=434662 handshake_window = 60
Wed Jul 18 10:36:21 2018 us=434667 transition_window = 3600
Wed Jul 18 10:36:21 2018 us=434671 single_session = DISABLED
Wed Jul 18 10:36:21 2018 us=434675 push_peer_info = DISABLED
Wed Jul 18 10:36:21 2018 us=434679 tls_exit = DISABLED
Wed Jul 18 10:36:21 2018 us=434684 tls_auth_file = 'ta.key'
Wed Jul 18 10:36:21 2018 us=434688 tls_crypt_file = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434692 pkcs11_protected_authentication = DISABLED
...
...
Wed Jul 18 10:36:21 2018 us=434757 pkcs11_protected_authentication = DISABLED
Wed Jul 18 10:36:21 2018 us=434764 pkcs11_private_mode = 00000000
...
...
Wed Jul 18 10:36:21 2018 us=434826 pkcs11_private_mode = 00000000
Wed Jul 18 10:36:21 2018 us=434831 pkcs11_cert_private = DISABLED
...
...
Wed Jul 18 10:36:21 2018 us=434893 pkcs11_cert_private = DISABLED
Wed Jul 18 10:36:21 2018 us=434897 pkcs11_pin_cache_period = -1
Wed Jul 18 10:36:21 2018 us=434901 pkcs11_id = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=434905 pkcs11_id_management = DISABLED
Wed Jul 18 10:36:21 2018 us=434910 server_network = 10.8.0.0
Wed Jul 18 10:36:21 2018 us=434915 server_netmask = 255.255.255.0
Wed Jul 18 10:36:21 2018 us=434920 server_network_ipv6 = ::
Wed Jul 18 10:36:21 2018 us=434924 server_netbits_ipv6 = 0
Wed Jul 18 10:36:21 2018 us=434929 server_bridge_ip = 0.0.0.0
Wed Jul 18 10:36:21 2018 us=434934 server_bridge_netmask = 0.0.0.0
Wed Jul 18 10:36:21 2018 us=434939 server_bridge_pool_start = 0.0.0.0
Wed Jul 18 10:36:21 2018 us=434944 server_bridge_pool_end = 0.0.0.0
Wed Jul 18 10:36:21 2018 us=434948 push_entry = 'route 10.8.0.0 255.255.255.0'
Wed Jul 18 10:36:21 2018 us=434952 push_entry = 'topology net30'
Wed Jul 18 10:36:21 2018 us=434956 push_entry = 'ping 10'
Wed Jul 18 10:36:21 2018 us=434961 push_entry = 'ping-restart 120'
Wed Jul 18 10:36:21 2018 us=434965 ifconfig_pool_defined = ENABLED
Wed Jul 18 10:36:21 2018 us=434970 ifconfig_pool_start = 10.8.0.4
Wed Jul 18 10:36:21 2018 us=434974 ifconfig_pool_end = 10.8.0.251
Wed Jul 18 10:36:21 2018 us=434979 ifconfig_pool_netmask = 0.0.0.0
Wed Jul 18 10:36:21 2018 us=434983 ifconfig_pool_persist_filename = '/var/log/openvpn/ipp.txt'
Wed Jul 18 10:36:21 2018 us=434988 ifconfig_pool_persist_refresh_freq = 600
Wed Jul 18 10:36:21 2018 us=434992 ifconfig_ipv6_pool_defined = DISABLED
Wed Jul 18 10:36:21 2018 us=434997 ifconfig_ipv6_pool_base = ::
Wed Jul 18 10:36:21 2018 us=435001 ifconfig_ipv6_pool_netbits = 0
Wed Jul 18 10:36:21 2018 us=435005 n_bcast_buf = 256
Wed Jul 18 10:36:21 2018 us=435010 tcp_queue_limit = 64
Wed Jul 18 10:36:21 2018 us=435014 real_hash_size = 256
Wed Jul 18 10:36:21 2018 us=435019 virtual_hash_size = 256
Wed Jul 18 10:36:21 2018 us=435025 client_connect_script = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=435030 learn_address_script = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=435034 client_disconnect_script = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=435038 client_config_dir = 'ccd'
Wed Jul 18 10:36:21 2018 us=435042 ccd_exclusive = DISABLED
Wed Jul 18 10:36:21 2018 us=435047 tmp_dir = '/tmp'
Wed Jul 18 10:36:21 2018 us=435051 push_ifconfig_defined = DISABLED
Wed Jul 18 10:36:21 2018 us=435056 push_ifconfig_local = 0.0.0.0
Wed Jul 18 10:36:21 2018 us=435061 push_ifconfig_remote_netmask = 0.0.0.0
Wed Jul 18 10:36:21 2018 us=435065 push_ifconfig_ipv6_defined = DISABLED
Wed Jul 18 10:36:21 2018 us=435070 push_ifconfig_ipv6_local = ::/0
Wed Jul 18 10:36:21 2018 us=435074 push_ifconfig_ipv6_remote = ::
Wed Jul 18 10:36:21 2018 us=435078 enable_c2c = ENABLED
Wed Jul 18 10:36:21 2018 us=435083 duplicate_cn = DISABLED
Wed Jul 18 10:36:21 2018 us=435087 cf_max = 0
Wed Jul 18 10:36:21 2018 us=435091 cf_per = 0
Wed Jul 18 10:36:21 2018 us=435096 max_clients = 1024
Wed Jul 18 10:36:21 2018 us=435100 max_routes_per_client = 256
Wed Jul 18 10:36:21 2018 us=435104 auth_user_pass_verify_script = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=435108 auth_user_pass_verify_script_via_file = DISABLED
Wed Jul 18 10:36:21 2018 us=435113 auth_token_generate = DISABLED
Wed Jul 18 10:36:21 2018 us=435117 auth_token_lifetime = 0
Wed Jul 18 10:36:21 2018 us=435121 port_share_host = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=435125 port_share_port = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=435129 client = DISABLED
Wed Jul 18 10:36:21 2018 us=435133 pull = DISABLED
Wed Jul 18 10:36:21 2018 us=435138 auth_user_pass_file = '[UNDEF]'
Wed Jul 18 10:36:21 2018 us=435143 OpenVPN 2.4.4 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Feb 10 2018
Wed Jul 18 10:36:21 2018 us=435153 library versions: OpenSSL 1.1.0g 2 Nov 2017, LZO 2.08
Wed Jul 18 10:36:21 2018 us=435624 Diffie-Hellman initialized with 2048 bit key
Wed Jul 18 10:36:21 2018 us=436049 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Jul 18 10:36:21 2018 us=436062 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Jul 18 10:36:21 2018 us=436070 TLS-Auth MTU parms [ L:1622 D:1172 EF:78 EB:0 ET:0 EL:3 ]
Wed Jul 18 10:36:21 2018 us=436218 ROUTE_GATEWAY 10.1.201.1/255.255.255.0 IFACE=enp4s0 HWADDR=70:85:c2:62:b4:a5
Wed Jul 18 10:36:21 2018 us=436531 TUN/TAP device tun0 opened
Wed Jul 18 10:36:21 2018 us=436568 TUN/TAP TX queue length set to 100
Wed Jul 18 10:36:21 2018 us=436578 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Wed Jul 18 10:36:21 2018 us=436588 /sbin/ip link set dev tun0 up mtu 1500
Wed Jul 18 10:36:21 2018 us=438497 /sbin/ip addr add dev tun0 local 10.8.0.1 peer 10.8.0.2
Wed Jul 18 10:36:21 2018 us=440100 /sbin/ip route add 10.8.0.0/24 via 10.8.0.2
Wed Jul 18 10:36:21 2018 us=441664 /sbin/ip route add 10.8.0.0/24 via 10.8.0.2
RTNETLINK answers: File exists
Wed Jul 18 10:36:21 2018 us=442844 ERROR: Linux route add command failed: external program exited with error status: 2
Wed Jul 18 10:36:21 2018 us=442889 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Wed Jul 18 10:36:21 2018 us=443308 Could not determine IPv4/IPv6 protocol. Using AF_INET
Wed Jul 18 10:36:21 2018 us=443331 Socket Buffers: R=[212992->212992] S=[212992->212992]
Wed Jul 18 10:36:21 2018 us=443346 UDPv4 link local (bound): [AF_INET][undef]:1194
Wed Jul 18 10:36:21 2018 us=443354 UDPv4 link remote: [AF_UNSPEC]
Wed Jul 18 10:36:21 2018 us=443365 GID set to nogroup
Wed Jul 18 10:36:21 2018 us=443379 UID set to nobody
Wed Jul 18 10:36:21 2018 us=443392 MULTI: multi_init called, r=256 v=256
Wed Jul 18 10:36:21 2018 us=443418 IFCONFIG POOL: base=10.8.0.4 size=62, ipv6=0
Wed Jul 18 10:36:21 2018 us=443435 IFCONFIG POOL LIST
Wed Jul 18 10:36:21 2018 us=443495 Initialization Sequence Completed
Wed Jul 18 10:36:22 2018 us=719400 MULTI: multi_create_instance called
Wed Jul 18 10:36:22 2018 us=719494 10.1.116.24:34908 Re-using SSL/TLS context
Wed Jul 18 10:36:22 2018 us=719509 10.1.116.24:34908 LZO compression initializing
Wed Jul 18 10:36:22 2018 us=719632 10.1.116.24:34908 Control Channel MTU parms [ L:1622 D:1172 EF:78 EB:0 ET:0 EL:3 ]
Wed Jul 18 10:36:22 2018 us=719643 10.1.116.24:34908 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Wed Jul 18 10:36:22 2018 us=719671 10.1.116.24:34908 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
Wed Jul 18 10:36:22 2018 us=719678 10.1.116.24:34908 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
RWed Jul 18 10:36:22 2018 us=719705 10.1.116.24:34908 TLS: Initial packet from [AF_INET]10.1.116.24:34908, sid=6de279dc 10f99e81
WRRWRWRWWWRRRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWed Jul 18 10:36:22 2018 us=731734 10.1.116.24:34908 VERIFY OK: depth=1, C=SK, ST=BA, L=Bratislava, O=TGH, OU=TGHcom, CN=amd-tr, name=gns3vpn, emailAddress=marc.hoppins@eset.sk
Wed Jul 18 10:36:22 2018 us=731882 10.1.116.24:34908 VERIFY OK: depth=0, C=SK, ST=BA, L=Bratislava, O=TGH, OU=TGHcom, CN=gns3vm1, name=gns3vpn, emailAddress=marc.hoppins@eset.sk
WRWRWRWRWRWRWRWRWed Jul 18 10:36:22 2018 us=732964 10.1.116.24:34908 peer info: IV_VER=2.3.2
Wed Jul 18 10:36:22 2018 us=732974 10.1.116.24:34908 peer info: IV_PLAT=linux
Wed Jul 18 10:36:22 2018 us=733037 10.1.116.24:34908 Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Wed Jul 18 10:36:22 2018 us=733046 10.1.116.24:34908 Outgoing Data Channel: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Jul 18 10:36:22 2018 us=733051 10.1.116.24:34908 Incoming Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Wed Jul 18 10:36:22 2018 us=733057 10.1.116.24:34908 Incoming Data Channel: Using 256 bit message hash 'SHA256' for HMAC authentication
WRWed Jul 18 10:36:22 2018 us=733555 10.1.116.24:34908 Control Channel: TLSv1, cipher TLSv1.0 ECDHE-RSA-AES256-SHA, 2048 bit RSA
Wed Jul 18 10:36:22 2018 us=733568 10.1.116.24:34908 [gns3vm1] Peer Connection Initiated with [AF_INET]10.1.116.24:34908
Wed Jul 18 10:36:22 2018 us=733595 gns3vm1/10.1.116.24:34908 OPTIONS IMPORT: reading client specific options from: ccd/gns3vm1
Wed Jul 18 10:36:22 2018 us=733638 gns3vm1/10.1.116.24:34908 MULTI: Learn: 10.8.0.11 -> gns3vm1/10.1.116.24:34908
Wed Jul 18 10:36:22 2018 us=733645 gns3vm1/10.1.116.24:34908 MULTI: primary virtual IP for gns3vm1/10.1.116.24:34908: 10.8.0.11
RWed Jul 18 10:36:25 2018 us=48638 gns3vm1/10.1.116.24:34908 PUSH: Received control message: 'PUSH_REQUEST'
Wed Jul 18 10:36:25 2018 us=48684 gns3vm1/10.1.116.24:34908 SENT CONTROL [gns3vm1]: 'PUSH_REPLY,route 10.8.0.0 255.255.255.0,topology net30,ping 10,ping-restart 120,ifconfig 10.8.0.11 10.8.0.1' (status=1)
WWRWWRWRWRWRWRWRWWed Jul 18 10:37:32 2018 us=788301 MULTI: multi_create_instance called
Wed Jul 18 10:37:32 2018 us=788392 10.1.201.31:42195 Re-using SSL/TLS context
Wed Jul 18 10:37:32 2018 us=788405 10.1.201.31:42195 LZO compression initializing
Wed Jul 18 10:37:32 2018 us=788501 10.1.201.31:42195 Control Channel MTU parms [ L:1622 D:1172 EF:78 EB:0 ET:0 EL:3 ]
Wed Jul 18 10:37:32 2018 us=788513 10.1.201.31:42195 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Wed Jul 18 10:37:32 2018 us=788544 10.1.201.31:42195 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
Wed Jul 18 10:37:32 2018 us=788552 10.1.201.31:42195 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
RWed Jul 18 10:37:32 2018 us=788578 10.1.201.31:42195 TLS: Initial packet from [AF_INET]10.1.201.31:42195, sid=58031038 788fe682
WRWRWRWWRRWWWed Jul 18 10:37:56 2018 us=169434 event_wait : Interrupted system call (code=4)
Wed Jul 18 10:37:56 2018 us=169512 SENT CONTROL [UNDEF]: 'RESTART' (status=1)
Wed Jul 18 10:37:56 2018 us=169550 SENT CONTROL [gns3vm1]: 'RESTART' (status=1)
WWed Jul 18 10:37:58 2018 us=172504 MULTI: multi_create_instance called
Wed Jul 18 10:37:58 2018 us=172576 10.1.116.24:39374 Re-using SSL/TLS context
Wed Jul 18 10:37:58 2018 us=172590 10.1.116.24:39374 LZO compression initializing
Wed Jul 18 10:37:58 2018 us=172679 10.1.116.24:39374 Control Channel MTU parms [ L:1622 D:1172 EF:78 EB:0 ET:0 EL:3 ]
Wed Jul 18 10:37:58 2018 us=172690 10.1.116.24:39374 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Wed Jul 18 10:37:58 2018 us=172721 10.1.116.24:39374 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
Wed Jul 18 10:37:58 2018 us=172728 10.1.116.24:39374 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
RWed Jul 18 10:37:58 2018 us=172756 10.1.116.24:39374 TLS: Initial packet from [AF_INET]10.1.116.24:39374, sid=720324af 06a46553
WWed Jul 18 10:37:58 2018 us=173115 TCP/UDP: Closing socket
Wed Jul 18 10:37:58 2018 us=173155 /sbin/ip route del 10.8.0.0/24
RTNETLINK answers: Operation not permitted
Wed Jul 18 10:37:58 2018 us=174512 ERROR: Linux route delete command failed: external program exited with error status: 2
Wed Jul 18 10:37:58 2018 us=174543 Closing TUN/TAP interface
Wed Jul 18 10:37:58 2018 us=174561 /sbin/ip addr del dev tun0 local 10.8.0.1 peer 10.8.0.2
RTNETLINK answers: Operation not permitted
Wed Jul 18 10:37:58 2018 us=176026 Linux ip addr del failed: external program exited with error status: 2
Wed Jul 18 10:37:58 2018 us=205702 SIGTERM[hard,] received, process exiting

***********************************************
***********************************************

I stopped the service to collect the server log.

Here is a truncated server log containing the failed client attempting to connect:-

Wed Jul 18 06:43:39 2018 us=301499 10.1.201.31:40431 TLS Error: TLS handshake failed
Wed Jul 18 06:43:39 2018 us=301564 10.1.201.31:40431 SIGUSR1[soft,tls-error] received, client-instance restarting
Wed Jul 18 06:43:41 2018 us=483028 MULTI: multi_create_instance called
Wed Jul 18 06:43:41 2018 us=483084 10.1.201.31:38889 Re-using SSL/TLS context
Wed Jul 18 06:43:41 2018 us=483095 10.1.201.31:38889 LZO compression initializing
Wed Jul 18 06:43:41 2018 us=483148 10.1.201.31:38889 Control Channel MTU parms [ L:1622 D:1172 EF:78 EB:0 ET:0 EL:3 ]
Wed Jul 18 06:43:41 2018 us=483158 10.1.201.31:38889 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Wed Jul 18 06:43:41 2018 us=483189 10.1.201.31:38889 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
Wed Jul 18 06:43:41 2018 us=483197 10.1.201.31:38889 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
RWed Jul 18 06:43:41 2018 us=483231 10.1.201.31:38889 TLS: Initial packet from [AF_INET]10.1.201.31:38889, sid=7dc4e6f3 8406ca4f
WRWRWWRWWRRWWRRWWRRWRWWed Jul 18 06:44:41 2018 us=972364 10.1.201.31:38889 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Wed Jul 18 06:44:41 2018 us=972404 10.1.201.31:38889 TLS Error: TLS handshake failed
Wed Jul 18 06:44:41 2018 us=972474 10.1.201.31:38889 SIGUSR1[soft,tls-error] received, client-instance restarting
Wed Jul 18 06:44:43 2018 us=683011 MULTI: multi_create_instance called
Wed Jul 18 06:44:43 2018 us=683057 10.1.201.31:58520 Re-using SSL/TLS context
Wed Jul 18 06:44:43 2018 us=683068 10.1.201.31:58520 LZO compression initializing
Wed Jul 18 06:44:43 2018 us=683111 10.1.201.31:58520 Control Channel MTU parms [ L:1622 D:1172 EF:78 EB:0 ET:0 EL:3 ]
Wed Jul 18 06:44:43 2018 us=683121 10.1.201.31:58520 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Wed Jul 18 06:44:43 2018 us=683151 10.1.201.31:58520 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
Wed Jul 18 06:44:43 2018 us=683159 10.1.201.31:58520 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
RWed Jul 18 06:44:43 2018 us=683182 10.1.201.31:58520 TLS: Initial packet from [AF_INET]10.1.201.31:58520, sid=e6b15b6d d4f87d22
WWRWRWWRWWRWRWRWWRWWRWRRWWed Jul 18 06:45:43 2018 us=178106 10.1.201.31:58520 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Wed Jul 18 06:45:43 2018 us=178141 10.1.201.31:58520 TLS Error: TLS handshake failed
Wed Jul 18 06:45:43 2018 us=178220 10.1.201.31:58520 SIGUSR1[soft,tls-error] received, client-instance restarting
WRWed Jul 18 06:45:45 2018 us=399139 MULTI: multi_create_instance called
Wed Jul 18 06:45:45 2018 us=399184 10.1.201.31:43725 Re-using SSL/TLS context
Wed Jul 18 06:45:45 2018 us=399198 10.1.201.31:43725 LZO compression initializing
Wed Jul 18 06:45:45 2018 us=399239 10.1.201.31:43725 Control Channel MTU parms [ L:1622 D:1172 EF:78 EB:0 ET:0 EL:3 ]
Wed Jul 18 06:45:45 2018 us=399248 10.1.201.31:43725 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Wed Jul 18 06:45:45 2018 us=399278 10.1.201.31:43725 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
Wed Jul 18 06:45:45 2018 us=399285 10.1.201.31:43725 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
RWed Jul 18 06:45:45 2018 us=399305 10.1.201.31:43725 TLS: Initial packet from [AF_INET]10.1.201.31:43725, sid=74ceb6c3 abdd99af
WWRWRWRWWRWRWRWWRRWWRWRWed Jul 18 06:46:45 2018 us=439235 10.1.201.31:43725 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

***********************************************
***********************************************

I restarted the openvpn client on the gns3vm3 appliance and waited until the above messages had been generated on the server before shutting down the client. Client log below:-

Wed Jul 18 10:13:25 2018 us=969864 Current Parameter Settings:
Wed Jul 18 10:13:25 2018 us=969921 config = '/etc/openvpn/client.conf'
Wed Jul 18 10:13:25 2018 us=969930 mode = 0
Wed Jul 18 10:13:25 2018 us=969937 persist_config = DISABLED
Wed Jul 18 10:13:25 2018 us=969944 persist_mode = 1
Wed Jul 18 10:13:25 2018 us=969950 show_ciphers = DISABLED
Wed Jul 18 10:13:25 2018 us=969956 show_digests = DISABLED
Wed Jul 18 10:13:25 2018 us=969962 show_engines = DISABLED
Wed Jul 18 10:13:25 2018 us=969968 genkey = DISABLED
Wed Jul 18 10:13:25 2018 us=969975 key_pass_file = '[UNDEF]'
Wed Jul 18 10:13:25 2018 us=969981 show_tls_ciphers = DISABLED
Wed Jul 18 10:13:25 2018 us=969987 Connection profiles [default]:
Wed Jul 18 10:13:25 2018 us=969993 proto = udp
Wed Jul 18 10:13:25 2018 us=969999 local = '[UNDEF]'
Wed Jul 18 10:13:25 2018 us=970005 local_port = 0
Wed Jul 18 10:13:25 2018 us=970011 remote = 'amd-tr'
Wed Jul 18 10:13:25 2018 us=970017 remote_port = 1194
Wed Jul 18 10:13:25 2018 us=970023 remote_float = ENABLED
Wed Jul 18 10:13:25 2018 us=970029 bind_defined = DISABLED
Wed Jul 18 10:13:25 2018 us=970035 bind_local = DISABLED
Wed Jul 18 10:13:25 2018 us=970041 NOTE: --mute triggered...
Wed Jul 18 10:13:25 2018 us=970056 255 variation(s) on previous 20 message(s) suppressed by --mute
Wed Jul 18 10:13:25 2018 us=970063 OpenVPN 2.3.2 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [eurephia] [MH] [IPv6] built on Jun 22 2017
Wed Jul 18 10:13:25 2018 us=970124 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Wed Jul 18 10:13:25 2018 us=970689 Control Channel Authentication: using 'ta.key' as a OpenVPN static key file
Wed Jul 18 10:13:25 2018 us=970708 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Jul 18 10:13:25 2018 us=970717 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Jul 18 10:13:25 2018 us=970736 LZO compression initialized
Wed Jul 18 10:13:25 2018 us=970784 Control Channel MTU parms [ L:1570 D:178 EF:78 EB:0 ET:0 EL:0 ]
Wed Jul 18 10:13:25 2018 us=970810 Socket Buffers: R=[212992->131072] S=[212992->131072]
Wed Jul 18 10:13:25 2018 us=971006 Data Channel MTU parms [ L:1570 D:1450 EF:70 EB:135 ET:0 EL:0 AF:3/1 ]
Wed Jul 18 10:13:25 2018 us=971025 Local Options String: 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
Wed Jul 18 10:13:25 2018 us=971032 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
Wed Jul 18 10:13:25 2018 us=971045 Local Options hash (VER=V4): '73e43c96'
Wed Jul 18 10:13:25 2018 us=971055 Expected Remote Options hash (VER=V4): '8a3b3cca'
Wed Jul 18 10:13:25 2018 us=971613 NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay
Wed Jul 18 10:13:25 2018 us=971663 UDPv4 link local: [undef]
Wed Jul 18 10:13:25 2018 us=971695 UDPv4 link remote: [AF_INET]10.1.201.40:1194
WWWWWWed Jul 18 10:14:26 2018 us=41783 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Wed Jul 18 10:14:26 2018 us=41836 TLS Error: TLS handshake failed
Wed Jul 18 10:14:26 2018 us=42115 TCP/UDP: Closing socket
Wed Jul 18 10:14:26 2018 us=42157 SIGUSR1[soft,tls-error] received, process restarting
Wed Jul 18 10:14:26 2018 us=42190 Restart pause, 2 second(s)
Wed Jul 18 10:14:28 2018 us=42337 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Wed Jul 18 10:14:28 2018 us=42397 Re-using SSL/TLS context
Wed Jul 18 10:14:28 2018 us=42459 LZO compression initialized
Wed Jul 18 10:14:28 2018 us=42525 Control Channel MTU parms [ L:1570 D:178 EF:78 EB:0 ET:0 EL:0 ]
Wed Jul 18 10:14:28 2018 us=42565 Socket Buffers: R=[212992->131072] S=[212992->131072]
Wed Jul 18 10:14:28 2018 us=42711 Data Channel MTU parms [ L:1570 D:1450 EF:70 EB:135 ET:0 EL:0 AF:3/1 ]
Wed Jul 18 10:14:28 2018 us=42770 Local Options String: 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
Wed Jul 18 10:14:28 2018 us=42784 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1570,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
Wed Jul 18 10:14:28 2018 us=42808 Local Options hash (VER=V4): '73e43c96'
Wed Jul 18 10:14:28 2018 us=42825 Expected Remote Options hash (VER=V4): '8a3b3cca'
Wed Jul 18 10:14:28 2018 us=42839 UDPv4 link local: [undef]
Wed Jul 18 10:14:28 2018 us=42854 UDPv4 link remote: [AF_INET]10.1.201.40:1194
WWWed Jul 18 10:14:33 2018 us=867829 event_wait : Interrupted system call (code=4)
Wed Jul 18 10:14:33 2018 us=868015 TCP/UDP: Closing socket
Wed Jul 18 10:14:33 2018 us=868055 SIGTERM[hard,] received, process exiting