Clients are able to connect OK - but only it seems on the second attempt.
In order to try to debug this I did a tcpdump on the server on 1194 eth0 - I can see the incoming traffic when I first initiate the connection, but nothing is showing on the openvpn log to register the attempt to connect. After the timeout and retry it connects just fine.
I am running the openvpn server on Lubuntu on virtual Hyper-V machine. Windows 10 is the host.
server.conf
Server conf
mode server
tls-server
port 1194
proto udp
dev tun
script-security 2
server 10.8.0.0 255.255.255.0
push "route 192.168.1.0 255.255.255.0"
push "dhcp-option DNS 192.168.1.1"
client-to-client
ca ca.crt
cert server.crt
key server.key # This file should be kept secret
dh dh2048.pem
tls-auth ta.key 0
I did a tcpdump on the server on 1194 eth0 - I can see the incoming traffic
What did it look like?
Encrypted ..
Re: Client connects only on second try
Posted: Sun Nov 22, 2020 7:33 am
by bigAlNZ
verb6 is a good idea.
Log still doesnt seem to show much relevant. I disconnect and reconnect - nothing immediately comes up indicating that OVPN is trying to accept the connection:
Sun Nov 22 20:27:36 2020 us=947951 client1/121.74.193.xx:58074 UDPv4 WRITE [38] to [AF_INET]121.74.193.xx:58074: P_DATA_V1 kid=0 DATA len=37
Sun Nov 22 20:27:46 2020 us=139347 client1/121.74.193.xx:58074 UDPv4 WRITE [38] to [AF_INET]121.74.193.xx:58074: P_DATA_V1 kid=0 DATA len=37
Sun Nov 22 20:27:56 2020 us=209043 client1/121.74.193.xx:58074 UDPv4 WRITE [38] to [AF_INET]121.74.193.xx:58074: P_DATA_V1 kid=0 DATA len=37
Sun Nov 22 20:28:06 2020 us=275272 client1/121.74.193.xx:58074 UDPv4 WRITE [38] to [AF_INET]121.74.193.xx:58074: P_DATA_V1 kid=0 DATA len=37
Sun Nov 22 20:28:16 2020 us=338019 client1/121.74.193.xx:58074 UDPv4 WRITE [38] to [AF_INET]121.74.193.xx:58074: P_DATA_V1 kid=0 DATA len=37
Sun Nov 22 20:28:26 2020 us=516828 client1/121.74.193.xx:58074 UDPv4 WRITE [38] to [AF_INET]121.74.193.xx:58074: P_DATA_V1 kid=0 DATA len=37
Sun Nov 22 20:28:36 2020 us=587280 client1/121.74.193.xx:58074 UDPv4 WRITE [38] to [AF_INET]121.74.193.xx:58074: P_DATA_V1 kid=0 DATA len=37
I wonder if it is anything to do with Lubuntu (normally I use Ubuntu)
Re: Client connects only on second try
Posted: Tue Nov 24, 2020 6:30 am
by bigAlNZ
A bit more information. This is the connection log
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_private_mode = 00000000
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_cert_private = DISABLED
Tue Nov 24 19:28:12 2020 pkcs11_pin_cache_period = -1
Tue Nov 24 19:28:12 2020 pkcs11_id = '[UNDEF]'
Tue Nov 24 19:28:12 2020 pkcs11_id_management = DISABLED
Tue Nov 24 19:28:12 2020 server_network = 0.0.0.0
Tue Nov 24 19:28:12 2020 server_netmask = 0.0.0.0
Tue Nov 24 19:28:12 2020 server_network_ipv6 = ::
Tue Nov 24 19:28:12 2020 server_netbits_ipv6 = 0
Tue Nov 24 19:28:12 2020 server_bridge_ip = 0.0.0.0
Tue Nov 24 19:28:12 2020 server_bridge_netmask = 0.0.0.0
Tue Nov 24 19:28:12 2020 server_bridge_pool_start = 0.0.0.0
Tue Nov 24 19:28:12 2020 server_bridge_pool_end = 0.0.0.0
Tue Nov 24 19:28:12 2020 ifconfig_pool_defined = DISABLED
Tue Nov 24 19:28:12 2020 ifconfig_pool_start = 0.0.0.0
Tue Nov 24 19:28:12 2020 ifconfig_pool_end = 0.0.0.0
Tue Nov 24 19:28:12 2020 ifconfig_pool_netmask = 0.0.0.0
Tue Nov 24 19:28:12 2020 ifconfig_pool_persist_filename = '[UNDEF]'
Tue Nov 24 19:28:12 2020 ifconfig_pool_persist_refresh_freq = 600
Tue Nov 24 19:28:12 2020 ifconfig_ipv6_pool_defined = DISABLED
Tue Nov 24 19:28:12 2020 ifconfig_ipv6_pool_base = ::
Tue Nov 24 19:28:12 2020 ifconfig_ipv6_pool_netbits = 0
Tue Nov 24 19:28:12 2020 n_bcast_buf = 256
Tue Nov 24 19:28:12 2020 tcp_queue_limit = 64
Tue Nov 24 19:28:12 2020 real_hash_size = 256
Tue Nov 24 19:28:12 2020 virtual_hash_size = 256
Tue Nov 24 19:28:12 2020 client_connect_script = '[UNDEF]'
Tue Nov 24 19:28:12 2020 learn_address_script = '[UNDEF]'
Tue Nov 24 19:28:12 2020 client_disconnect_script = '[UNDEF]'
Tue Nov 24 19:28:12 2020 client_config_dir = '[UNDEF]'
Tue Nov 24 19:28:12 2020 ccd_exclusive = DISABLED
Tue Nov 24 19:28:12 2020 tmp_dir = 'C:\Users\ALGRAN~1\AppData\Local\Temp\'
Tue Nov 24 19:28:12 2020 push_ifconfig_defined = DISABLED
Tue Nov 24 19:28:12 2020 push_ifconfig_local = 0.0.0.0
Tue Nov 24 19:28:12 2020 push_ifconfig_remote_netmask = 0.0.0.0
Tue Nov 24 19:28:12 2020 push_ifconfig_ipv6_defined = DISABLED
Tue Nov 24 19:28:12 2020 push_ifconfig_ipv6_local = ::/0
Tue Nov 24 19:28:12 2020 push_ifconfig_ipv6_remote = ::
Tue Nov 24 19:28:12 2020 enable_c2c = DISABLED
Tue Nov 24 19:28:12 2020 duplicate_cn = DISABLED
Tue Nov 24 19:28:12 2020 cf_max = 0
Tue Nov 24 19:28:12 2020 cf_per = 0
Tue Nov 24 19:28:12 2020 max_clients = 1024
Tue Nov 24 19:28:12 2020 max_routes_per_client = 256
Tue Nov 24 19:28:12 2020 auth_user_pass_verify_script = '[UNDEF]'
Tue Nov 24 19:28:12 2020 auth_user_pass_verify_script_via_file = DISABLED
Tue Nov 24 19:28:12 2020 auth_token_generate = DISABLED
Tue Nov 24 19:28:12 2020 auth_token_lifetime = 0
Tue Nov 24 19:28:12 2020 client = ENABLED
Tue Nov 24 19:28:12 2020 pull = ENABLED
Tue Nov 24 19:28:12 2020 auth_user_pass_file = '[UNDEF]'
Tue Nov 24 19:28:12 2020 show_net_up = DISABLED
Tue Nov 24 19:28:12 2020 route_method = 3
Tue Nov 24 19:28:12 2020 block_outside_dns = DISABLED
Tue Nov 24 19:28:12 2020 ip_win32_defined = DISABLED
Tue Nov 24 19:28:12 2020 ip_win32_type = 3
Tue Nov 24 19:28:12 2020 dhcp_masq_offset = 0
Tue Nov 24 19:28:12 2020 dhcp_lease_time = 31536000
Tue Nov 24 19:28:12 2020 tap_sleep = 0
Tue Nov 24 19:28:12 2020 dhcp_options = ENABLED
Tue Nov 24 19:28:12 2020 dhcp_renew = DISABLED
Tue Nov 24 19:28:12 2020 dhcp_pre_release = DISABLED
Tue Nov 24 19:28:12 2020 domain = '[UNDEF]'
Tue Nov 24 19:28:12 2020 netbios_scope = '[UNDEF]'
Tue Nov 24 19:28:12 2020 netbios_node_type = 0
Tue Nov 24 19:28:12 2020 disable_nbt = DISABLED
Tue Nov 24 19:28:12 2020 DNS[0] = 192.168.1.1
Tue Nov 24 19:28:12 2020 OpenVPN 2.4.5 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Mar 1 2018
Tue Nov 24 19:28:12 2020 Windows version 6.2 (Windows 8 or greater) 64bit
Tue Nov 24 19:28:12 2020 library versions: OpenSSL 1.1.0f 25 May 2017, LZO 2.10
Tue Nov 24 19:28:12 2020 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25343
Tue Nov 24 19:28:12 2020 Need hold release from management interface, waiting...
Tue Nov 24 19:28:13 2020 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25343
Tue Nov 24 19:28:13 2020 MANAGEMENT: CMD 'state on'
Tue Nov 24 19:28:13 2020 MANAGEMENT: CMD 'log all on'
Tue Nov 24 19:28:13 2020 MANAGEMENT: CMD 'echo all on'
Tue Nov 24 19:28:13 2020 MANAGEMENT: CMD 'bytecount 5'
Tue Nov 24 19:28:13 2020 MANAGEMENT: CMD 'hold off'
Tue Nov 24 19:28:13 2020 MANAGEMENT: CMD 'hold release'
Tue Nov 24 19:28:13 2020 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Tue Nov 24 19:28:13 2020 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Tue Nov 24 19:28:13 2020 LZO compression initializing
Tue Nov 24 19:28:13 2020 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Tue Nov 24 19:28:13 2020 MANAGEMENT: >STATE:1606199293,RESOLVE,,,,,,
Tue Nov 24 19:28:14 2020 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Tue Nov 24 19:28:14 2020 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Tue Nov 24 19:28:14 2020 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Tue Nov 24 19:28:14 2020 TCP/UDP: Preserving recently used remote address: [AF_INET6]2407:7000:8cb8:6967:d8c8:6f0b:de14:6a49:1194
Tue Nov 24 19:28:14 2020 Socket Buffers: R=[65536->65536] S=[65536->65536]
Tue Nov 24 19:28:14 2020 UDP link local: (not bound)
Tue Nov 24 19:28:14 2020 UDP link remote: [AF_INET6]2407:7000:8cb8:6967:d8c8:6f0b:de14:6a49:1194
Tue Nov 24 19:28:14 2020 MANAGEMENT: >STATE:1606199294,WAIT,,,,,,
Tue Nov 24 19:28:14 2020 UDP WRITE [42] to [AF_INET6]2407:7000:8cb8:6967:d8c8:6f0b:de14:6a49:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 pid=[ #1 ] [ ] pid=0 DATA len=0
Tue Nov 24 19:28:14 2020 UDP READ [0] from [AF_UNSPEC]: DATA UNDEF len=-1
Tue Nov 24 19:28:16 2020 UDP WRITE [42] to [AF_INET6]2407:7000:8cb8:6967:d8c8:6f0b:de14:6a49:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 pid=[ #2 ] [ ] pid=0 DATA len=0
Tue Nov 24 19:28:20 2020 UDP WRITE [42] to [AF_INET6]2407:7000:8cb8:6967:d8c8:6f0b:de14:6a49:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 pid=[ #3 ] [ ] pid=0 DATA len=0
The successful connection is actually nothing to do with the second attempt (I can force a retry right away) it seems that you need to wait 1 minute before a successful attempt.
After logging in I notice a lot of these entries on the client log:
ue Nov 24 19:30:09 2020 UDP WRITE [101] to [AF_INET]27.252.83.xxx:1194: P_DATA_V2 kid=0 DATA len=100
Tue Nov 24 19:30:09 2020 TUN READ [70]
Tue Nov 24 19:30:09 2020 UDP WRITE [95] to [AF_INET]27.252.83.xxx:1194: P_DATA_V2 kid=0 DATA len=94
Tue Nov 24 19:30:09 2020 TUN READ [70]
Tue Nov 24 19:30:09 2020 UDP WRITE [95] to [AF_INET]27.252.83.xxx:1194: P_DATA_V2 kid=0 DATA len=94
Tue Nov 24 19:30:09 2020 TUN READ [76]
Tue Nov 24 19:30:09 2020 UDP WRITE [101] to [AF_INET]27.252.83.xxx:1194: P_DATA_V2 kid=0 DATA len=100
Tue Nov 24 19:30:09 2020 TUN READ [76]
Tue Nov 24 19:30:09 2020 UDP WRITE [101] to [AF_INET]27.252.83.xxx:1194: P_DATA_V2 kid=0 DATA len=100
Tue Nov 24 19:30:09 2020 TUN READ [70]
Tue Nov 24 19:30:09 2020 UDP WRITE [95] to [AF_INET]27.252.83.xxx:1194: P_DATA_V2 kid=0 DATA len=94
Tue Nov 24 19:30:09 2020 TUN READ [70]
Tue Nov 24 19:30:09 2020 UDP WRITE [95] to [AF_INET]27.252.83.xxx:1194: P_DATA_V2 kid=0 DATA len=94
Tue Nov 24 19:30:10 2020 TUN READ [76]
Tue Nov 24 19:30:10 2020 UDP WRITE [101] to [AF_INET]27.252.83.xxx:1194: P_DATA_V2 kid=0 DATA len=100
Tue Nov 24 19:30:10 2020 TUN READ [76]
Tue Nov 24 19:30:10 2020 UDP WRITE [101] to [AF_INET]27.252.83.xxx:1194: P_DATA_V2 kid=0 DATA len=100
Does this give any more clues?
Re: Client connects only on second try
Posted: Tue Nov 24, 2020 6:48 am
by bigAlNZ
I found the issue. secret.freeddns.org was registering a IPV6 address - but it would only connect on the second attempt when it used IPV4.