Connected but can't ping server VPN IP until --ping-restart

fulaftrbrnr

Set up a tun with a win7 client and win7 server, but noticed there was a ~6 minute delay between the connection being established and the client being able to ping 10.8.0.1 and access public IPs over the internet. When I looked at the logs, I realized that the connection started working as soon as I received an inactivity timeout and the server pushed --ping-restart. Any idea why this could be happening and how I can resolve it or at least work around it for the time being?

Thanks much. Configs, logs, and client routing table below:

Server config:

port 1194
proto udp
dev tun

ca "C:\\Program Files\\OpenVPN\\config\\ca.crt"
cert "C:\\Program Files\\OpenVPN\\config\\server.crt"
key "C:\\Program Files\\OpenVPN\\config\\server.key"
dh "C:\\Program Files\\OpenVPN\\config\\dh2048.pem"

server 10.8.0.0 255.255.255.0

ifconfig-pool-persist ipp.txt

push "redirect-gateway def1"

push "dhcp-option DNS 8.8.8.8"

keepalive 10 120

comp-lzo

persist-key
persist-tun

status openvpn-status.log

verb 3

Client config:

client
dev tun
proto udp

remote ##SERVER PUBLIC IP##

resolv-retry infinite

nobind

persist-key
persist-tun

ca "C:\\Program Files\\OpenVPN\\config\\ca.crt"
cert "C:\\Program Files\\OpenVPN\\config\\server.crt"
key "C:\\Program Files\\OpenVPN\\config\\server.key"

remote-cert-tls server

comp-lzo

verb 4

Server logs (partial, some info redacted):

Wed Jul 15 10:20:25 2015 68.190.238.178:64316 [js_sa_laptop] Peer Connection Initiated with [AF_INET]68.190.238.178:64316
Wed Jul 15 10:20:25 2015 js_sa_laptop/68.190.238.178:64316 MULTI_sva: pool returned IPv4=10.8.0.6, IPv6=(Not enabled)
Wed Jul 15 10:20:25 2015 js_sa_laptop/68.190.238.178:64316 MULTI: Learn: 10.8.0.6 -> js_sa_laptop/## IP ##
Wed Jul 15 10:20:25 2015 js_sa_laptop/68.190.238.178:64316 MULTI: primary virtual IP for js_sa_laptop/## IP ##: 10.8.0.6
Wed Jul 15 10:20:27 2015 js_sa_laptop/68.190.238.178:64316 PUSH: Received control message: 'PUSH_REQUEST'
Wed Jul 15 10:20:27 2015 js_sa_laptop/68.190.238.178:64316 send_push_reply(): safe_cap=940
Wed Jul 15 10:20:27 2015 js_sa_laptop/68.190.238.178:64316 SENT CONTROL [js_sa_laptop]: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS 8.8.8.8,route 10.8.0.1,topology net30,ping 10,ping-restart 120,ifconfig 10.8.0.6 10.8.0.5' (status=1)
Wed Jul 15 10:24:27 2015 js_sa_laptop/68.190.238.178:64316 [js_sa_laptop] Inactivity timeout (--ping-restart), restarting
Wed Jul 15 10:24:27 2015 js_sa_laptop/68.190.238.178:64316 SIGUSR1[soft,ping-restart] received, client-instance restarting
Wed Jul 15 10:26:20 2015 ## IP ## TLS: Initial packet from [AF_INET]## IP ##, sid=40875943 6e584f27

Client routing table:

===========================================================================
Interface List
 20...00 ff 93 ab b3 28 ......TAP-Windows Adapter V9
 19...a2 a8 cd 72 c0 7d ......Microsoft Virtual WiFi Miniport Adapter #2
 18...a2 a8 cd 72 c0 7c ......Microsoft Virtual WiFi Miniport Adapter
 17...a0 a8 cd 72 c0 7c ......Intel(R) Dual Band Wireless-AC 7260
 11...ec f4 bb 44 dd 7d ......Intel(R) Ethernet Connection I217-LM
  1...........................Software Loopback Interface 1
===========================================================================

IPv4 Route Table
===========================================================================
Active Routes:
Network Destination        Netmask          Gateway       Interface  Metric
          0.0.0.0          0.0.0.0         10.0.1.2        10.0.3.15     38
          0.0.0.0          0.0.0.0         10.0.1.2        10.0.3.16     25
          0.0.0.0        128.0.0.0         10.8.0.5         10.8.0.6     20
         10.0.0.0    255.255.252.0         On-link         10.0.3.15    275
         10.0.0.0    255.255.252.0         On-link         10.0.3.16    281
        10.0.3.15  255.255.255.255         On-link         10.0.3.15    275
        10.0.3.16  255.255.255.255         On-link         10.0.3.16    281
       10.0.3.255  255.255.255.255         On-link         10.0.3.15    275
       10.0.3.255  255.255.255.255         On-link         10.0.3.16    281
         10.8.0.1  255.255.255.255         10.8.0.5         10.8.0.6     20
         10.8.0.4  255.255.255.252         On-link          10.8.0.6    276
         10.8.0.6  255.255.255.255         On-link          10.8.0.6    276
         10.8.0.7  255.255.255.255         On-link          10.8.0.6    276
   ##SVR PUB IP##  255.255.255.255         10.0.1.2        10.0.3.15     20
        127.0.0.0        255.0.0.0         On-link         127.0.0.1    306
        127.0.0.1  255.255.255.255         On-link         127.0.0.1    306
  127.255.255.255  255.255.255.255         On-link         127.0.0.1    306
        128.0.0.0        128.0.0.0         10.8.0.5         10.8.0.6     20
        224.0.0.0        240.0.0.0         On-link         127.0.0.1    306
        224.0.0.0        240.0.0.0         On-link         10.0.3.16    281
        224.0.0.0        240.0.0.0         On-link         10.0.3.15    275
        224.0.0.0        240.0.0.0         On-link          10.8.0.6    276
  255.255.255.255  255.255.255.255         On-link         127.0.0.1    306
  255.255.255.255  255.255.255.255         On-link         10.0.3.16    281
  255.255.255.255  255.255.255.255         On-link         10.0.3.15    275
  255.255.255.255  255.255.255.255         On-link          10.8.0.6    276
===========================================================================

Traffic

Please post your client log.

fulaftrbrnr

Realized that if I run from cmd that I can force a soft restart immediately after establishing connection by pressing F1. This has the same effect as waiting for the timeout.

Obviously this isn't ideal. Here are the client logs (changed to verb 5 to hide all the read/write operations):

Fri Jul 17 09:23:53 2015 us=477419 Current Parameter Settings:
Fri Jul 17 09:23:53 2015 us=478419   config = 'client.ovpn'
Fri Jul 17 09:23:53 2015 us=478419   mode = 0
Fri Jul 17 09:23:53 2015 us=478419   show_ciphers = DISABLED
Fri Jul 17 09:23:53 2015 us=478419   show_digests = DISABLED
Fri Jul 17 09:23:53 2015 us=478419   show_engines = DISABLED
Fri Jul 17 09:23:53 2015 us=478419   genkey = DISABLED
Fri Jul 17 09:23:53 2015 us=479419   key_pass_file = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=479419   show_tls_ciphers = DISABLED
Fri Jul 17 09:23:53 2015 us=479419 Connection profiles [default]:
Fri Jul 17 09:23:53 2015 us=479419   proto = udp
Fri Jul 17 09:23:53 2015 us=479419   local = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=479419   local_port = 0
Fri Jul 17 09:23:53 2015 us=479419   remote = '######.ddns.net'
Fri Jul 17 09:23:53 2015 us=479419   remote_port = 1194
Fri Jul 17 09:23:53 2015 us=479419   remote_float = DISABLED
Fri Jul 17 09:23:53 2015 us=479419   bind_defined = DISABLED
Fri Jul 17 09:23:53 2015 us=479419   bind_local = DISABLED
Fri Jul 17 09:23:53 2015 us=479419   connect_retry_seconds = 5
Fri Jul 17 09:23:53 2015 us=479419   connect_timeout = 10
Fri Jul 17 09:23:53 2015 us=479419   connect_retry_max = 0
Fri Jul 17 09:23:53 2015 us=479419   socks_proxy_server = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=479419   socks_proxy_port = 0
Fri Jul 17 09:23:53 2015 us=479419   socks_proxy_retry = DISABLED
Fri Jul 17 09:23:53 2015 us=479419   tun_mtu = 1500
Fri Jul 17 09:23:53 2015 us=479419   tun_mtu_defined = ENABLED
Fri Jul 17 09:23:53 2015 us=479419   link_mtu = 1500
Fri Jul 17 09:23:53 2015 us=479419   link_mtu_defined = DISABLED
Fri Jul 17 09:23:53 2015 us=479419   tun_mtu_extra = 0
Fri Jul 17 09:23:53 2015 us=479419   tun_mtu_extra_defined = DISABLED
Fri Jul 17 09:23:53 2015 us=479419   mtu_discover_type = -1
Fri Jul 17 09:23:53 2015 us=479419   fragment = 0
Fri Jul 17 09:23:53 2015 us=479419   mssfix = 1450
Fri Jul 17 09:23:53 2015 us=479419   explicit_exit_notification = 2
Fri Jul 17 09:23:53 2015 us=479419 Connection profiles END
Fri Jul 17 09:23:53 2015 us=479419   remote_random = DISABLED
Fri Jul 17 09:23:53 2015 us=479419   ipchange = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=479419   dev = 'tun'
Fri Jul 17 09:23:53 2015 us=479419   dev_type = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=479419   dev_node = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=479419   lladdr = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=479419   topology = 1
Fri Jul 17 09:23:53 2015 us=479419   tun_ipv6 = DISABLED
Fri Jul 17 09:23:53 2015 us=479419   ifconfig_local = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=479419   ifconfig_remote_netmask = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=479419   ifconfig_noexec = DISABLED
Fri Jul 17 09:23:53 2015 us=480419   ifconfig_nowarn = DISABLED
Fri Jul 17 09:23:53 2015 us=480419   ifconfig_ipv6_local = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=480419   ifconfig_ipv6_netbits = 0
Fri Jul 17 09:23:53 2015 us=480419   ifconfig_ipv6_remote = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=480419   shaper = 0
Fri Jul 17 09:23:53 2015 us=480419   mtu_test = 0
Fri Jul 17 09:23:53 2015 us=480419   mlock = DISABLED
Fri Jul 17 09:23:53 2015 us=480419   keepalive_ping = 0
Fri Jul 17 09:23:53 2015 us=480419   keepalive_timeout = 0
Fri Jul 17 09:23:53 2015 us=480419   inactivity_timeout = 0
Fri Jul 17 09:23:53 2015 us=480419   ping_send_timeout = 10
Fri Jul 17 09:23:53 2015 us=480419   ping_rec_timeout = 60
Fri Jul 17 09:23:53 2015 us=480419   ping_rec_timeout_action = 2
Fri Jul 17 09:23:53 2015 us=480419   ping_timer_remote = DISABLED
Fri Jul 17 09:23:53 2015 us=480419   remap_sigusr1 = 0
Fri Jul 17 09:23:53 2015 us=480419   persist_tun = ENABLED
Fri Jul 17 09:23:53 2015 us=480419   persist_local_ip = DISABLED
Fri Jul 17 09:23:53 2015 us=480419   persist_remote_ip = DISABLED
Fri Jul 17 09:23:53 2015 us=480419   persist_key = ENABLED
Fri Jul 17 09:23:53 2015 us=480419   passtos = DISABLED
Fri Jul 17 09:23:53 2015 us=480419   resolve_retry_seconds = 1000000000
Fri Jul 17 09:23:53 2015 us=480419   username = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=480419   groupname = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=480419   chroot_dir = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=480419   cd_dir = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=480419   writepid = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=480419   up_script = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=480419   down_script = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=480419   down_pre = DISABLED
Fri Jul 17 09:23:53 2015 us=480419   up_restart = DISABLED
Fri Jul 17 09:23:53 2015 us=480419   up_delay = DISABLED
Fri Jul 17 09:23:53 2015 us=480419   daemon = DISABLED
Fri Jul 17 09:23:53 2015 us=480419   inetd = 0
Fri Jul 17 09:23:53 2015 us=480419   log = ENABLED
Fri Jul 17 09:23:53 2015 us=480419   suppress_timestamps = DISABLED
Fri Jul 17 09:23:53 2015 us=480419   nice = 0
Fri Jul 17 09:23:53 2015 us=480419   verbosity = 5
Fri Jul 17 09:23:53 2015 us=480419   mute = 0
Fri Jul 17 09:23:53 2015 us=481419   status_file = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=481419   status_file_version = 1
Fri Jul 17 09:23:53 2015 us=481419   status_file_update_freq = 60
Fri Jul 17 09:23:53 2015 us=481419   occ = ENABLED
Fri Jul 17 09:23:53 2015 us=481419   rcvbuf = 0
Fri Jul 17 09:23:53 2015 us=481419   sndbuf = 0
Fri Jul 17 09:23:53 2015 us=481419   sockflags = 0
Fri Jul 17 09:23:53 2015 us=481419   fast_io = DISABLED
Fri Jul 17 09:23:53 2015 us=481419   lzo = 7
Fri Jul 17 09:23:53 2015 us=481419   route_script = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=481419   route_default_gateway = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=481419   route_default_metric = 0
Fri Jul 17 09:23:53 2015 us=481419   route_noexec = DISABLED
Fri Jul 17 09:23:53 2015 us=481419   route_delay = 2
Fri Jul 17 09:23:53 2015 us=481419   route_delay_window = 30
Fri Jul 17 09:23:53 2015 us=481419   route_delay_defined = ENABLED
Fri Jul 17 09:23:53 2015 us=481419   route_nopull = DISABLED
Fri Jul 17 09:23:53 2015 us=481419   route_gateway_via_dhcp = DISABLED
Fri Jul 17 09:23:53 2015 us=481419   max_routes = 100
Fri Jul 17 09:23:53 2015 us=481419   allow_pull_fqdn = DISABLED
Fri Jul 17 09:23:53 2015 us=481419   management_addr = '127.0.0.1'
Fri Jul 17 09:23:53 2015 us=481419   management_port = 25340
Fri Jul 17 09:23:53 2015 us=481419   management_user_pass = 'stdin'
Fri Jul 17 09:23:53 2015 us=481419   management_log_history_cache = 250
Fri Jul 17 09:23:53 2015 us=481419   management_echo_buffer_size = 100
Fri Jul 17 09:23:53 2015 us=481419   management_write_peer_info_file = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=481419   management_client_user = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=481419   management_client_group = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=481419   management_flags = 6
Fri Jul 17 09:23:53 2015 us=481419   shared_secret_file = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=481419   key_direction = 0
Fri Jul 17 09:23:53 2015 us=481419   ciphername_defined = ENABLED
Fri Jul 17 09:23:53 2015 us=481419   ciphername = 'BF-CBC'
Fri Jul 17 09:23:53 2015 us=481419   authname_defined = ENABLED
Fri Jul 17 09:23:53 2015 us=481419   authname = 'SHA1'
Fri Jul 17 09:23:53 2015 us=481419   prng_hash = 'SHA1'
Fri Jul 17 09:23:53 2015 us=481419   prng_nonce_secret_len = 16
Fri Jul 17 09:23:53 2015 us=481419   keysize = 0
Fri Jul 17 09:23:53 2015 us=481419   engine = DISABLED
Fri Jul 17 09:23:53 2015 us=481419   replay = ENABLED
Fri Jul 17 09:23:53 2015 us=482419   mute_replay_warnings = DISABLED
Fri Jul 17 09:23:53 2015 us=482419   replay_window = 64
Fri Jul 17 09:23:53 2015 us=482419   replay_time = 15
Fri Jul 17 09:23:53 2015 us=482419   packet_id_file = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=482419   use_iv = ENABLED
Fri Jul 17 09:23:53 2015 us=482419   test_crypto = DISABLED
Fri Jul 17 09:23:53 2015 us=482419   tls_server = DISABLED
Fri Jul 17 09:23:53 2015 us=482419   tls_client = ENABLED
Fri Jul 17 09:23:53 2015 us=482419   key_method = 2
Fri Jul 17 09:23:53 2015 us=482419   ca_file = 'C:\Program Files\OpenVPN\config\ca.crt'
Fri Jul 17 09:23:53 2015 us=482419   ca_path = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=482419   dh_file = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=482419   cert_file = 'C:\Program Files\OpenVPN\config\js_sa.crt'
Fri Jul 17 09:23:53 2015 us=482419   priv_key_file = 'C:\Program Files\OpenVPN\config\js_sa.key'
Fri Jul 17 09:23:53 2015 us=482419   pkcs12_file = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=482419   cryptoapi_cert = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=482419   cipher_list = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=482419   tls_verify = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=482419   tls_export_cert = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=482419   verify_x509_type = 0
Fri Jul 17 09:23:53 2015 us=482419   verify_x509_name = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=482419   crl_file = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=482419   ns_cert_type = 0
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 160
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 136
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 0
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 0
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 0
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 0
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 0
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 0
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 0
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 0
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 0
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 0
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 0
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 0
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 0
Fri Jul 17 09:23:53 2015 us=482419   remote_cert_ku[i] = 0
Fri Jul 17 09:23:53 2015 us=483419   remote_cert_eku = 'TLS Web Server Authentication'
Fri Jul 17 09:23:53 2015 us=483419   ssl_flags = 0
Fri Jul 17 09:23:53 2015 us=483419   tls_timeout = 2
Fri Jul 17 09:23:53 2015 us=483419   renegotiate_bytes = 0
Fri Jul 17 09:23:53 2015 us=483419   renegotiate_packets = 0
Fri Jul 17 09:23:53 2015 us=483419   renegotiate_seconds = 3600
Fri Jul 17 09:23:53 2015 us=483419   handshake_window = 60
Fri Jul 17 09:23:53 2015 us=483419   transition_window = 3600
Fri Jul 17 09:23:53 2015 us=483419   single_session = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   push_peer_info = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   tls_exit = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   tls_auth_file = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_protected_authentication = DISABLED
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=483419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_private_mode = 00000000
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_cert_private = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_pin_cache_period = -1
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_id = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=484419   pkcs11_id_management = DISABLED
Fri Jul 17 09:23:53 2015 us=484419   server_network = 0.0.0.0
Fri Jul 17 09:23:53 2015 us=484419   server_netmask = 0.0.0.0
Fri Jul 17 09:23:53 2015 us=488418   server_network_ipv6 = ::
Fri Jul 17 09:23:53 2015 us=488418   server_netbits_ipv6 = 0
Fri Jul 17 09:23:53 2015 us=488418   server_bridge_ip = 0.0.0.0
Fri Jul 17 09:23:53 2015 us=488418   server_bridge_netmask = 0.0.0.0
Fri Jul 17 09:23:53 2015 us=488418   server_bridge_pool_start = 0.0.0.0
Fri Jul 17 09:23:53 2015 us=488418   server_bridge_pool_end = 0.0.0.0
Fri Jul 17 09:23:53 2015 us=488418   ifconfig_pool_defined = DISABLED
Fri Jul 17 09:23:53 2015 us=488418   ifconfig_pool_start = 0.0.0.0
Fri Jul 17 09:23:53 2015 us=488418   ifconfig_pool_end = 0.0.0.0
Fri Jul 17 09:23:53 2015 us=488418   ifconfig_pool_netmask = 0.0.0.0
Fri Jul 17 09:23:53 2015 us=488418   ifconfig_pool_persist_filename = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=488418   ifconfig_pool_persist_refresh_freq = 600
Fri Jul 17 09:23:53 2015 us=488418   ifconfig_ipv6_pool_defined = DISABLED
Fri Jul 17 09:23:53 2015 us=489418   ifconfig_ipv6_pool_base = ::
Fri Jul 17 09:23:53 2015 us=489418   ifconfig_ipv6_pool_netbits = 0
Fri Jul 17 09:23:53 2015 us=489418   n_bcast_buf = 256
Fri Jul 17 09:23:53 2015 us=489418   tcp_queue_limit = 64
Fri Jul 17 09:23:53 2015 us=489418   real_hash_size = 256
Fri Jul 17 09:23:53 2015 us=489418   virtual_hash_size = 256
Fri Jul 17 09:23:53 2015 us=489418   client_connect_script = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=489418   learn_address_script = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=489418   client_disconnect_script = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=489418   client_config_dir = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=489418   ccd_exclusive = DISABLED
Fri Jul 17 09:23:53 2015 us=489418   tmp_dir = 'C:\Users\e04627\AppData\Local\Temp\'
Fri Jul 17 09:23:53 2015 us=489418   push_ifconfig_defined = DISABLED
Fri Jul 17 09:23:53 2015 us=489418   push_ifconfig_local = 0.0.0.0
Fri Jul 17 09:23:53 2015 us=489418   push_ifconfig_remote_netmask = 0.0.0.0
Fri Jul 17 09:23:53 2015 us=489418   push_ifconfig_ipv6_defined = DISABLED
Fri Jul 17 09:23:53 2015 us=489418   push_ifconfig_ipv6_local = ::/0
Fri Jul 17 09:23:53 2015 us=489418   push_ifconfig_ipv6_remote = ::
Fri Jul 17 09:23:53 2015 us=489418   enable_c2c = DISABLED
Fri Jul 17 09:23:53 2015 us=489418   duplicate_cn = DISABLED
Fri Jul 17 09:23:53 2015 us=489418   cf_max = 0
Fri Jul 17 09:23:53 2015 us=489418   cf_per = 0
Fri Jul 17 09:23:53 2015 us=489418   max_clients = 1024
Fri Jul 17 09:23:53 2015 us=489418   max_routes_per_client = 256
Fri Jul 17 09:23:53 2015 us=489418   auth_user_pass_verify_script = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=489418   auth_user_pass_verify_script_via_file = DISABLED
Fri Jul 17 09:23:53 2015 us=489418   client = ENABLED
Fri Jul 17 09:23:53 2015 us=489418   pull = ENABLED
Fri Jul 17 09:23:53 2015 us=489418   auth_user_pass_file = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=489418   show_net_up = DISABLED
Fri Jul 17 09:23:53 2015 us=489418   route_method = 2
Fri Jul 17 09:23:53 2015 us=489418   ip_win32_defined = DISABLED
Fri Jul 17 09:23:53 2015 us=490418   ip_win32_type = 3
Fri Jul 17 09:23:53 2015 us=490418   dhcp_masq_offset = 0
Fri Jul 17 09:23:53 2015 us=490418   dhcp_lease_time = 31536000
Fri Jul 17 09:23:53 2015 us=490418   tap_sleep = 0
Fri Jul 17 09:23:53 2015 us=490418   dhcp_options = DISABLED
Fri Jul 17 09:23:53 2015 us=490418   dhcp_renew = DISABLED
Fri Jul 17 09:23:53 2015 us=490418   dhcp_pre_release = DISABLED
Fri Jul 17 09:23:53 2015 us=490418   dhcp_release = DISABLED
Fri Jul 17 09:23:53 2015 us=490418   domain = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=490418   netbios_scope = '[UNDEF]'
Fri Jul 17 09:23:53 2015 us=490418   netbios_node_type = 0
Fri Jul 17 09:23:53 2015 us=490418   disable_nbt = DISABLED
Fri Jul 17 09:23:53 2015 us=490418 OpenVPN 2.3.7 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [PKCS11] [IPv6] built on Jul  9 2015
Fri Jul 17 09:23:53 2015 us=490418 library versions: OpenSSL 1.0.1p 9 Jul 2015, LZO 2.08
Enter Management Password:
Fri Jul 17 09:23:53 2015 us=492418 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25340
Fri Jul 17 09:23:53 2015 us=492418 Need hold release from management interface, waiting...
Fri Jul 17 09:23:53 2015 us=801387 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25340
Fri Jul 17 09:23:53 2015 us=902377 MANAGEMENT: CMD 'state on'
Fri Jul 17 09:23:53 2015 us=903377 MANAGEMENT: CMD 'log all on'
Fri Jul 17 09:23:54 2015 us=214346 MANAGEMENT: CMD 'hold off'
Fri Jul 17 09:23:54 2015 us=218345 MANAGEMENT: CMD 'hold release'
Fri Jul 17 09:23:54 2015 us=662301 LZO compression initialized
Fri Jul 17 09:23:54 2015 us=662301 Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:3 ]
Fri Jul 17 09:23:54 2015 us=663301 Socket Buffers: R=[8192->8192] S=[8192->8192]
Fri Jul 17 09:23:54 2015 us=663301 MANAGEMENT: >STATE:1437150234,RESOLVE,,,
Fri Jul 17 09:23:54 2015 us=699297 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:143 ET:0 EL:3 AF:3/1 ]
Fri Jul 17 09:23:54 2015 us=699297 Local Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Fri Jul 17 09:23:54 2015 us=700297 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Fri Jul 17 09:23:54 2015 us=700297 Local Options hash (VER=V4): '41690919'
Fri Jul 17 09:23:54 2015 us=700297 Expected Remote Options hash (VER=V4): '530fdded'
Fri Jul 17 09:23:54 2015 us=700297 UDPv4 link local: [undef]
Fri Jul 17 09:23:54 2015 us=700297 UDPv4 link remote: [AF_INET]76.94.240.236:1194
Fri Jul 17 09:23:54 2015 us=700297 MANAGEMENT: >STATE:1437150234,WAIT,,,
Fri Jul 17 09:23:54 2015 us=727294 MANAGEMENT: >STATE:1437150234,AUTH,,,
Fri Jul 17 09:23:54 2015 us=727294 TLS: Initial packet from [AF_INET]76.94.240.236:1194, sid=e62c7b50 2cc51380
Fri Jul 17 09:23:54 2015 us=995267 VERIFY OK: depth=1, C=US, ST=##, L=##, O=##, OU=##, CN=js_pc, name=##, emailAddress=##
Fri Jul 17 09:23:54 2015 us=996267 Validating certificate key usage
Fri Jul 17 09:23:54 2015 us=996267 ++ Certificate has key usage  00a0, expects 00a0
Fri Jul 17 09:23:54 2015 us=996267 VERIFY KU OK
Fri Jul 17 09:23:54 2015 us=996267 Validating certificate extended key usage
Fri Jul 17 09:23:54 2015 us=996267 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Fri Jul 17 09:23:54 2015 us=996267 VERIFY EKU OK
Fri Jul 17 09:23:54 2015 us=996267 VERIFY OK: depth=0, C=US, ST=##, L=##, O=##, OU=##, CN=js_svr, name=##, emailAddress=##
Fri Jul 17 09:23:55 2015 us=471220 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Fri Jul 17 09:23:55 2015 us=471220 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Fri Jul 17 09:23:55 2015 us=471220 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Fri Jul 17 09:23:55 2015 us=471220 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Fri Jul 17 09:23:55 2015 us=471220 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Fri Jul 17 09:23:55 2015 us=471220 [js_svr] Peer Connection Initiated with [AF_INET]76.94.240.236:1194
Fri Jul 17 09:23:56 2015 us=501117 MANAGEMENT: >STATE:1437150236,GET_CONFIG,,,
Fri Jul 17 09:23:57 2015 us=530014 SENT CONTROL [js_svr]: 'PUSH_REQUEST' (status=1)
Fri Jul 17 09:23:57 2015 us=619005 PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS 8.8.8.8,ping 10,ping-restart 60,route 10.8.0.1,topology net30,ping 10,ping-restart 120,ifconfig 10.8.0.6 10.8.0.5'
Fri Jul 17 09:23:57 2015 us=620005 OPTIONS IMPORT: timers and/or timeouts modified
Fri Jul 17 09:23:57 2015 us=620005 OPTIONS IMPORT: --ifconfig/up options modified
Fri Jul 17 09:23:57 2015 us=620005 OPTIONS IMPORT: route options modified
Fri Jul 17 09:23:57 2015 us=620005 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Fri Jul 17 09:23:57 2015 us=675999 do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0
Fri Jul 17 09:23:57 2015 us=675999 MANAGEMENT: >STATE:1437150237,ASSIGN_IP,,10.8.0.6,
Fri Jul 17 09:23:57 2015 us=675999 open_tun, tt->ipv6=0
Fri Jul 17 09:23:57 2015 us=678999 TAP-WIN32 device [Local Area Connection 4] opened: \\.\Global\{93ABB328-82C0-47C6-848F-2EA1E7919DEA}.tap
Fri Jul 17 09:23:57 2015 us=678999 TAP-Windows Driver Version 9.21 
Fri Jul 17 09:23:57 2015 us=679999 TAP-Windows MTU=1500
Fri Jul 17 09:23:57 2015 us=685998 Notified TAP-Windows driver to set a DHCP IP/netmask of 10.8.0.6/255.255.255.252 on interface {93ABB328-82C0-47C6-848F-2EA1E7919DEA} [DHCP-serv: 10.8.0.5, lease-time: 31536000]
Fri Jul 17 09:23:57 2015 us=685998 DHCP option string: 06040808 0808
Fri Jul 17 09:23:57 2015 us=685998 Successful ARP Flush on interface [20] {93ABB328-82C0-47C6-848F-2EA1E7919DEA}
Fri Jul 17 09:23:59 2015 us=745792 TEST ROUTES: 2/2 succeeded len=1 ret=1 a=0 u/d=up
Fri Jul 17 09:23:59 2015 us=746792 C:\Windows\system32\route.exe ADD 76.94.240.236 MASK 255.255.255.255 10.0.1.2
Fri Jul 17 09:23:59 2015 us=746792 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Fri Jul 17 09:23:59 2015 us=959771 C:\Windows\system32\route.exe ADD 0.0.0.0 MASK 128.0.0.0 10.8.0.5
Fri Jul 17 09:23:59 2015 us=959771 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Fri Jul 17 09:24:00 2015 us=160751 C:\Windows\system32\route.exe ADD 128.0.0.0 MASK 128.0.0.0 10.8.0.5
Fri Jul 17 09:24:00 2015 us=160751 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Fri Jul 17 09:24:00 2015 us=325734 MANAGEMENT: >STATE:1437150240,ADD_ROUTES,,,
Fri Jul 17 09:24:00 2015 us=326734 C:\Windows\system32\route.exe ADD 10.8.0.1 MASK 255.255.255.255 10.8.0.5
Fri Jul 17 09:24:00 2015 us=326734 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Fri Jul 17 09:24:00 2015 us=496717 Initialization Sequence Completed
Fri Jul 17 09:24:00 2015 us=497717 MANAGEMENT: >STATE:1437150240,CONNECTED,SUCCESS,10.8.0.6,76.94.240.236
Fri Jul 17 09:29:50 2015 us=391732 [js_svr] Inactivity timeout (--ping-restart), restarting
Fri Jul 17 09:29:50 2015 us=392732 TCP/UDP: Closing socket
Fri Jul 17 09:29:50 2015 us=393732 SIGUSR1[soft,ping-restart] received, process restarting
Fri Jul 17 09:29:50 2015 us=393732 MANAGEMENT: >STATE:1437150590,RECONNECTING,ping-restart,,
Fri Jul 17 09:29:50 2015 us=393732 Restart pause, 2 second(s)
Fri Jul 17 09:29:52 2015 us=396732 Re-using SSL/TLS context
Fri Jul 17 09:29:52 2015 us=397732 LZO compression initialized
Fri Jul 17 09:29:52 2015 us=397732 Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:3 ]
Fri Jul 17 09:29:52 2015 us=397732 Socket Buffers: R=[8192->8192] S=[8192->8192]
Fri Jul 17 09:29:52 2015 us=398732 MANAGEMENT: >STATE:1437150592,RESOLVE,,,
Fri Jul 17 09:29:53 2015 us=426732 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:143 ET:0 EL:3 AF:3/1 ]
Fri Jul 17 09:29:53 2015 us=427732 Local Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Fri Jul 17 09:29:53 2015 us=427732 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Fri Jul 17 09:29:53 2015 us=428732 Local Options hash (VER=V4): '41690919'
Fri Jul 17 09:29:53 2015 us=428732 Expected Remote Options hash (VER=V4): '530fdded'
Fri Jul 17 09:29:53 2015 us=428732 UDPv4 link local: [undef]
Fri Jul 17 09:29:53 2015 us=429732 UDPv4 link remote: [AF_INET]76.94.240.236:1194
Fri Jul 17 09:29:53 2015 us=429732 MANAGEMENT: >STATE:1437150593,WAIT,,,
Fri Jul 17 09:29:53 2015 us=451732 MANAGEMENT: >STATE:1437150593,AUTH,,,
Fri Jul 17 09:29:53 2015 us=452732 TLS: Initial packet from [AF_INET]76.94.240.236:1194, sid=a93ea11b f1b5d358
Fri Jul 17 09:29:53 2015 us=603732 VERIFY OK: depth=1, C=US, ST=##, L=##, O=##, OU=##, CN=js_pc, name=##, emailAddress=##
Fri Jul 17 09:29:53 2015 us=604732 Validating certificate key usage
Fri Jul 17 09:29:53 2015 us=604732 ++ Certificate has key usage  00a0, expects 00a0
Fri Jul 17 09:29:53 2015 us=604732 VERIFY KU OK
Fri Jul 17 09:29:53 2015 us=605732 Validating certificate extended key usage
Fri Jul 17 09:29:53 2015 us=605732 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Fri Jul 17 09:29:53 2015 us=605732 VERIFY EKU OK
Fri Jul 17 09:29:53 2015 us=605732 VERIFY OK: depth=0, C=US, ST=##, L=##, O=##, OU=##, CN=js_svr, name=##, emailAddress=##
Fri Jul 17 09:29:53 2015 us=875732 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Fri Jul 17 09:29:53 2015 us=875732 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Fri Jul 17 09:29:53 2015 us=876732 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Fri Jul 17 09:29:53 2015 us=876732 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Fri Jul 17 09:29:53 2015 us=876732 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Fri Jul 17 09:29:53 2015 us=876732 [js_svr] Peer Connection Initiated with [AF_INET]76.94.240.236:1194
Fri Jul 17 09:29:54 2015 us=198732 MANAGEMENT: >STATE:1437150594,GET_CONFIG,,,
Fri Jul 17 09:29:55 2015 us=41732 SENT CONTROL [js_svr]: 'PUSH_REQUEST' (status=1)
Fri Jul 17 09:29:55 2015 us=62732 PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS 8.8.8.8,ping 10,ping-restart 60,route 10.8.0.1,topology net30,ping 10,ping-restart 120,ifconfig 10.8.0.6 10.8.0.5'
Fri Jul 17 09:29:55 2015 us=62732 OPTIONS IMPORT: timers and/or timeouts modified
Fri Jul 17 09:29:55 2015 us=63732 OPTIONS IMPORT: --ifconfig/up options modified
Fri Jul 17 09:29:55 2015 us=63732 OPTIONS IMPORT: route options modified
Fri Jul 17 09:29:55 2015 us=63732 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Fri Jul 17 09:29:55 2015 us=63732 Preserving previous TUN/TAP instance: Local Area Connection 4
Fri Jul 17 09:29:55 2015 us=64732 Initialization Sequence Completed
Fri Jul 17 09:29:55 2015 us=64732 MANAGEMENT: >STATE:1437150595,CONNECTED,SUCCESS,10.8.0.6,76.94.240.236
##A bunch of R/W/r/w operations##

fulaftrbrnr

Tried to post my client logs but my posts aren't getting approved at all. It's been several days now. Lovely. Wish it was easier to get support.

Traffic

fulaftrbrnr wrote

IPv4 Route Table
===========================================================================
Active Routes:
Network Destination        Netmask          Gateway       Interface  Metric
          0.0.0.0          0.0.0.0         10.0.1.2        10.0.3.15     38
          0.0.0.0          0.0.0.0         10.0.1.2        10.0.3.16     25

Your client has two network interfaces 10.0.3.15 and .16 is this ethernet and wireless ?

fulaftrbrnr

Yes, .16 is wireless, and .15 is wired in this case.

Traffic

Have you tried disabling the network interface that you are not using and then start openvpn ?

fulaftrbrnr

No, I'll give that a shot. Also, I recently lost all ability to access the internet on VPN for some reason. Same behavior on initial "connection", but now even when I restart (F1) it won't connect and it shows the standard UDPv4 link remote line with my server's public IP and port, but it looks like it never connects properly or something and then there's a strange series of WrrrrrrrrrrrrrrrrrrrrrrrrWrrrrrrrrrrrrrrrrrrrrrrrrrrrrrWrrrrrrrrrrrrrrrrrrrrrrrrr, or sometimes a line of alternating Wr and then a huge rapid block of read operations. I deleted the default route to 10.8.0.5 (mask 128.0.0.0) and recreated it using a mask of 0.0.0.0 and it immediately started working. Any thoughts? Could this be related to my original issue?

fulaftrbrnr

It appears that if I disable my wireless adapter it works flawlessly. Any way to work around that? Would be nice to be able to have my wireless adapter active, but not in use for any traffic.