OpenVpn 2.5 wintun closing connection intermittently right after connect

stvitaly

Hi experts,
I am using openvpn community 2.5 GA on client side (windows) and want to work with wintun as a virtual interface.
openvpn being run from command line with system elevation.
In part of the cases openvpn closing the connection at the second the connection is established with ping-restart
If connection is not closed at the second it is open, or in case of tap driver/interface is used there are no such disconnects.
It happens a lot on my laptop, but still haven't seen it even once on my stationary machine connected to the same ISP (although wired).

ping-restart defined as 10 seconds, ping as 3, so the first ping-restart disconnect is expected to be 10 seconds after connecting.
In any case tried to redefine to 60 and 10, it didn't resolve the issue too.

Log below is with verb 6
Client Debug

2020-12-23 14:39:52 us=143977 [x.x.x.x] Peer Connection Initiated with [AF_INET]x.x.x.x:1194
2020-12-23 14:39:53 us=191192 SENT CONTROL [x.x.x.x]: 'PUSH_REQUEST' (status=1)
2020-12-23 14:39:53 us=191192 UDP WRITE [128] to [AF_INET]x.x.x.x:1194: P_CONTROL_V1 kid=0 pid=[ #11 ] [ ] pid=6 DATA len=42
2020-12-23 14:39:53 us=198174 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:9999
2020-12-23 14:39:55 us=70203 UDP READ [94] from [AF_INET]x.x.x.x:1194: P_ACK_V1 kid=0 pid=[ #9 ] [ 6 ]
2020-12-23 14:39:55 us=72190 UDP READ [358] from [AF_INET]x.x.x.x:1194: P_CONTROL_V1 kid=0 pid=[ #10 ] [ ] pid=6 DATA len=272
2020-12-23 14:39:55 us=72190 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,sndbuf 2097152,rcvbuf 2097152,route 100.124.4.1,topology net30,ping 3,ping-restart 10,ifconfig 100.124.4.42 100.124.4.41,peer-id 1,cipher AES-256-GCM'
2020-12-23 14:39:55 us=72190 OPTIONS IMPORT: timers and/or timeouts modified
2020-12-23 14:39:55 us=72190 OPTIONS IMPORT: --sndbuf/--rcvbuf options modified
2020-12-23 14:39:55 us=72190 Socket Buffers: R=[65536->2097152] S=[64512->2097152]
2020-12-23 14:39:55 us=72190 OPTIONS IMPORT: --ifconfig/up options modified
2020-12-23 14:39:55 us=72190 OPTIONS IMPORT: route options modified
2020-12-23 14:39:55 us=72190 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
2020-12-23 14:39:55 us=72190 OPTIONS IMPORT: peer-id set
2020-12-23 14:39:55 us=72190 OPTIONS IMPORT: adjusting link_mtu to 1625
2020-12-23 14:39:55 us=72190 OPTIONS IMPORT: data channel crypto options modified
2020-12-23 14:39:55 us=72190 Data Channel: using negotiated cipher 'AES-256-GCM'
2020-12-23 14:39:55 us=72190 Data Channel MTU parms [ L:1553 D:1350 EF:53 EB:406 ET:0 EL:3 ]
2020-12-23 14:39:55 us=72190 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2020-12-23 14:39:55 us=72190 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2020-12-23 14:39:55 us=72190 interactive service msg_channel=0
2020-12-23 14:39:55 us=105104 ROUTE_GATEWAY 192.168.1.1/255.255.255.0 I=19 HWADDR=e4:a4:71:01:dd:67
2020-12-23 14:39:55 us=155967 open_tun
2020-12-23 14:39:55 us=171925 wintun device [Local Area Connection] opened
2020-12-23 14:39:55 us=172921 do_ifconfig, ipv4=1, ipv6=0
2020-12-23 14:39:56 us=175258 NETSH: C:\WINDOWS\system32\netsh.exe interface ip set address 16 static 100.124.4.42 255.255.255.252
2020-12-23 14:39:58 us=491100 NETSH: C:\WINDOWS\system32\netsh.exe interface ip delete dns 16 all
2020-12-23 14:40:00 us=720172 NETSH: C:\WINDOWS\system32\netsh.exe interface ip set dns 16 static 8.8.8.8 validate=no
2020-12-23 14:40:03 us=268392 NETSH: C:\WINDOWS\system32\netsh.exe interface ip add dns 16 8.8.4.4 validate=no
2020-12-23 14:40:05 us=501451 NETSH: C:\WINDOWS\system32\netsh.exe interface ip delete wins 16 all
2020-12-23 14:40:06 us=376123 IPv4 MTU set to 1500 on interface 16 using SetIpInterfaceEntry()
2020-12-23 14:40:06 us=376123 C:\WINDOWS\system32\route.exe ADD x.x.x.x MASK 255.255.255.255 192.168.1.1
2020-12-23 14:40:06 us=393079 ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=19]
2020-12-23 14:40:06 us=393079 Route addition via IPAPI failed [adaptive]
2020-12-23 14:40:06 us=393079 Route addition fallback to route.exe
2020-12-23 14:40:06 us=394075 env_block: add PATH=C:\WINDOWS\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
2020-12-23 14:40:07 us=359508 C:\WINDOWS\system32\route.exe ADD 0.0.0.0 MASK 128.0.0.0 100.124.4.41
2020-12-23 14:40:07 us=377460 ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=5 and dwForwardType=4
2020-12-23 14:40:07 us=377460 Route addition via IPAPI succeeded [adaptive]
2020-12-23 14:40:07 us=377460 C:\WINDOWS\system32\route.exe ADD 128.0.0.0 MASK 128.0.0.0 100.124.4.41
2020-12-23 14:40:07 us=409374 ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=5 and dwForwardType=4
2020-12-23 14:40:07 us=409374 Route addition via IPAPI succeeded [adaptive]
2020-12-23 14:40:07 us=409374 C:\WINDOWS\system32\route.exe ADD 0.0.0.0 MASK 0.0.0.0 100.124.4.41
2020-12-23 14:40:07 us=438298 ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=5 and dwForwardType=4
2020-12-23 14:40:07 us=438298 Route addition via IPAPI succeeded [adaptive]
2020-12-23 14:40:07 us=438298 C:\WINDOWS\system32\route.exe ADD 100.124.4.1 MASK 255.255.255.255 100.124.4.41
2020-12-23 14:40:07 us=445280 ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=5 and dwForwardType=4
2020-12-23 14:40:07 us=445280 Route addition via IPAPI succeeded [adaptive]
2020-12-23 14:40:07 us=445280 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
2020-12-23 14:40:07 us=445280 Initialization Sequence Completed
2020-12-23 14:40:07 us=446276 UDP WRITE [94] to [AF_INET]x.x.x.x:1194: P_ACK_V1 kid=0 pid=[ #12 ] [ 6 ]
2020-12-23 14:40:07 us=446276 [x.x.x.x] Inactivity timeout (--ping-restart), restarting
2020-12-23 14:40:07 us=446276 TCP/UDP: Closing socket
2020-12-23 14:40:07 us=446276 C:\WINDOWS\system32\route.exe DELETE 0.0.0.0 MASK 0.0.0.0 100.124.4.41
2020-12-23 14:40:07 us=453258 Route deletion via IPAPI succeeded [adaptive]
2020-12-23 14:40:07 us=453258 C:\WINDOWS\system32\route.exe DELETE 100.124.4.1 MASK 255.255.255.255 100.124.4.41
2020-12-23 14:40:07 us=523073 Route deletion via IPAPI succeeded [adaptive]
2020-12-23 14:40:07 us=523073 C:\WINDOWS\system32\route.exe DELETE x.x.x.x MASK 255.255.255.255 192.168.1.1
2020-12-23 14:40:07 us=531051 Route deletion via IPAPI succeeded [adaptive]
2020-12-23 14:40:07 us=531051 C:\WINDOWS\system32\route.exe DELETE 0.0.0.0 MASK 128.0.0.0 100.124.4.41

client
dev tun

key "private_key.pem"
tls-version-min 1.2
tls-cipher TLS-ECDHE-RSA-WITH-AES-128-GCM-SHA256:TLS-ECDHE-ECDSA-WITH-AES-128-GCM-SHA256:TLS-ECDHE-RSA-WITH-AES-256-GCM-SHA384:TLS-DHE-RSA-WITH-AES-256-CBC-SHA256
auth SHA512
cipher AES-256-CBC
resolv-retry infinite
auth-retry none
nobind
persist-key
ns-cert-type server
comp-lzo
verb 4
windows-driver wintun
tls-client
up-delay
management 127.0.0.1 9999
connect-retry-max 3
mssfix 1350
route 0.0.0.0 0.0.0.0

Any ideas what can be wrong?

stvitaly

by the way here is a successful log with the same wintun and same configuration and even same failed route addition:
Client log:

2020-12-24 15:46:19 us=541190 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,sndbuf 2097152,rcvbuf 2097152,route 100.124.4.1,topology net30,ping 3,ping-restart 10,ifconfig 100.124.4.42 100.124.4.41,peer-id 0,cipher AES-256-GCM'
2020-12-24 15:46:19 us=542187 OPTIONS IMPORT: timers and/or timeouts modified
2020-12-24 15:46:19 us=542187 OPTIONS IMPORT: --sndbuf/--rcvbuf options modified
2020-12-24 15:46:19 us=542187 Socket Buffers: R=[65536->2097152] S=[64512->2097152]
2020-12-24 15:46:19 us=542187 OPTIONS IMPORT: --ifconfig/up options modified
2020-12-24 15:46:19 us=542187 OPTIONS IMPORT: route options modified
2020-12-24 15:46:19 us=542187 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
2020-12-24 15:46:19 us=542187 OPTIONS IMPORT: peer-id set
2020-12-24 15:46:19 us=542187 OPTIONS IMPORT: adjusting link_mtu to 1625
2020-12-24 15:46:19 us=542187 OPTIONS IMPORT: data channel crypto options modified
2020-12-24 15:46:19 us=542187 Data Channel: using negotiated cipher 'AES-256-GCM'
2020-12-24 15:46:19 us=542187 Data Channel MTU parms [ L:1553 D:1350 EF:53 EB:406 ET:0 EL:3 ]
2020-12-24 15:46:19 us=542187 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2020-12-24 15:46:19 us=542187 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2020-12-24 15:46:19 us=542187 interactive service msg_channel=0
2020-12-24 15:46:19 us=547173 ROUTE_GATEWAY 192.168.1.1/255.255.255.0 I=19 HWADDR=e4:a4:71:01:dd:67
2020-12-24 15:46:19 us=612000 open_tun
2020-12-24 15:46:19 us=627957 wintun device [Local Area Connection] opened
2020-12-24 15:46:19 us=628955 do_ifconfig, ipv4=1, ipv6=0
2020-12-24 15:46:20 us=631274 NETSH: C:\WINDOWS\system32\netsh.exe interface ip set address 15 static 100.124.4.42 255.255.255.252
2020-12-24 15:46:23 us=126601 NETSH: C:\WINDOWS\system32\netsh.exe interface ip delete dns 15 all
2020-12-24 15:46:24 us=731310 NETSH: C:\WINDOWS\system32\netsh.exe interface ip set dns 15 static 8.8.8.8 validate=no
2020-12-24 15:46:26 us=573380 NETSH: C:\WINDOWS\system32\netsh.exe interface ip add dns 15 8.8.4.4 validate=no
2020-12-24 15:46:28 us=7547 NETSH: C:\WINDOWS\system32\netsh.exe interface ip delete wins 15 all
2020-12-24 15:46:28 us=438394 IPv4 MTU set to 1500 on interface 15 using SetIpInterfaceEntry()
2020-12-24 15:46:28 us=440388 C:\WINDOWS\system32\route.exe ADD x.x.x.x MASK 255.255.255.255 192.168.1.1
2020-12-24 15:46:28 us=446371 ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=19]
2020-12-24 15:46:28 us=446371 Route addition via IPAPI failed [adaptive]
2020-12-24 15:46:28 us=446371 Route addition fallback to route.exe
2020-12-24 15:46:28 us=446371 env_block: add PATH=C:\WINDOWS\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
2020-12-24 15:46:28 us=884201 C:\WINDOWS\system32\route.exe ADD 0.0.0.0 MASK 128.0.0.0 100.124.4.41
2020-12-24 15:46:28 us=888191 ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=2 and dwForwardType=4
2020-12-24 15:46:28 us=888191 Route addition via IPAPI succeeded [adaptive]
2020-12-24 15:46:28 us=888191 C:\WINDOWS\system32\route.exe ADD 128.0.0.0 MASK 128.0.0.0 100.124.4.41
2020-12-24 15:46:28 us=892180 ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=2 and dwForwardType=4
2020-12-24 15:46:28 us=892180 Route addition via IPAPI succeeded [adaptive]
2020-12-24 15:46:28 us=894175 C:\WINDOWS\system32\route.exe ADD 0.0.0.0 MASK 0.0.0.0 100.124.4.41
2020-12-24 15:46:28 us=898164 ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=2 and dwForwardType=4
2020-12-24 15:46:28 us=898164 Route addition via IPAPI succeeded [adaptive]
2020-12-24 15:46:28 us=898164 C:\WINDOWS\system32\route.exe ADD 100.124.4.1 MASK 255.255.255.255 100.124.4.41
2020-12-24 15:46:28 us=925091 ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=2 and dwForwardType=4
2020-12-24 15:46:28 us=925091 Route addition via IPAPI succeeded [adaptive]
2020-12-24 15:46:28 us=925091 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
2020-12-24 15:46:28 us=925091 Initialization Sequence Completed
2020-12-24 15:46:28 us=925091 UDP WRITE [94] to [AF_INET]x.x.x.x:1194: P_ACK_V1 kid=0 pid=[ #12 ] [ 6 ]
2020-12-24 15:46:28 us=926089 TUN READ [96]
2020-12-24 15:46:28 us=926089 UDP WRITE [121] to [AF_INET]x.x.x.x:1194: P_DATA_V2 kid=0 DATA len=120
2020-12-24 15:46:28 us=926089 TUN READ [96]
2020-12-24 15:46:28 us=926089 UDP WRITE [121] to [AF_INET]x.x.x.x:1194: P_DATA_V2 kid=0 DATA len=120
2020-12-24 15:46:28 us=926089 TUN READ [96]

TinCanTech

Your log is at --verb 6 but your config is --verb 4 .. are you using the right config ?

Please don't use "route 0.0.0.0 0.0.0.0"

stvitaly

TinCanTech wrote Your log is at --verb 6 but your config is --verb 4 .. are you using the right config ?

Please don't use "route 0.0.0.0 0.0.0.0"

Regarding verb, I have changed it to get higher resolution debug, but the config is the same.

For 'route 0.0.0.0 0.0.0.0' can you explain a little bit, why is it not recommended?
Also do you mean that it can be a reason (as also wintun is able to connect with such configuration, just not always), or it is a bad practice in general?
What should be used instead?

TinCanTech

route 0.0.0.0 0.0.0.0 causes recursive routing .. which breaks the VPN.

Use --redirect-gateway def1

stvitaly

TinCanTech wrote route 0.0.0.0 0.0.0.0 causes recursive routing .. which breaks the VPN.

Use --redirect-gateway def1

So, it is a general bad practice. Thanks, I'll implement!
In any case it doesn't explain the specific issue as it is working most of the time and there are no recursive routing drops which would appear if this was an issue here.

Any ideas specifically regarding the ping-restart?

TinCanTech

stvitaly wrote Any ideas specifically regarding the ping-restart?

stvitaly wrote ping-restart defined as 10 seconds, ping as 3, so the first ping-restart disconnect is expected to be 10 seconds after connecting.
In any case tried to redefine to 60 and 10, it didn't resolve the issue too.

Just use the default ..

stvitaly

TinCanTech wrote
stvitaly wrote Any ideas specifically regarding the ping-restart?
stvitaly wrote ping-restart defined as 10 seconds, ping as 3, so the first ping-restart disconnect is expected to be 10 seconds after connecting.
In any case tried to redefine to 60 and 10, it didn't resolve the issue too.
Just use the default ..

I meant the issue of disconnecting because of ping-restart at the second of connecting.

2020-12-23 14:40:07 us=445280 Initialization Sequence Completed
2020-12-23 14:40:07 us=446276 UDP WRITE [94] to [AF_INET]x.x.x.x:1194: P_ACK_V1 kid=0 pid=[ #12 ] [ 6 ]
2020-12-23 14:40:07 us=446276 [x.x.x.x] Inactivity timeout (--ping-restart), restarting
2020-12-23 14:40:07 us=446276 TCP/UDP: Closing socket

It is not related to the actual values of ping-restart as it happens on the same second when the client is connected.
Also it does not happen always and it also doesn't happen with tap.

TinCanTech

According to what you have posted your --keepalive values are now broken because the timeout is lower than the ping.

If you want further help please post full details as per:
https://forums.openvpn.net/viewtopic.php?f=30&t=22603#p68963

stvitaly

Just to help other people who can come across the same issue, the problem was relevant to really long connection time for wintun.
The reason for long connection time is a default way used by OpenVPN to configure wintun interface.
The default method for wintun is using netsh which can take a very long time on user machines, specifically I have seen cases where a single command taken 30 seconds and it needs to run 5 of them, so at the moment it connects it already reaches ping-restart (or possibly negotiation) timeout, so it disconnects right away.

The way I have found to resolve the issue was to use --ip-win32 ipapi which decreased connection times greatly and allowed to stay within ping-restart timeouts.

Additional possibility could be to use –up-delay, but I haven't tried it as connection time of minutes does not provide good enough user experience in any case.

TinCanTech

Maybe you should not be using --up-delay ..

stvitaly

TinCanTech wrote Maybe you should not be using --up-delay ..

I didn't use it, but as I wrote above it could be a possibility.
Still, 5 commands of 30 seconds runtime - user will be freaking out.

TinCanTech

stvitaly wrote
TinCanTech wrote Maybe you should not be using --up-delay ..
I didn't use it

Yes you are -- See your config above.

stvitaly

TinCanTech wrote
stvitaly wrote
TinCanTech wrote Maybe you should not be using --up-delay ..
I didn't use it
Yes you are -- See your config above.

Oops, you are right.
Then it is totally looks like a bug of ping-restart, I would expect it to only be started after the interface considered to be connected.
Will try to remove it, although I think it should only make the situation worse or same as traffic will not be able to pass until the interface is configured.

In any case I had to move to ipapi due to terrible performance of netsh on a lot of user machines (windows), which resolves the whole situation with or without up-delay.

TinCanTech

That is not the only thing wrong with your VPN:

stvitaly wrote 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,sndbuf 2097152,rcvbuf 2097152,route 100.124.4.1,topology net30,ping 3,ping-restart 10,ifconfig 100.124.4.42 100.124.4.41,peer-id 0,cipher AES-256-GCM'

I suggest you learn how --keepalive works.

stvitaly

Current keepalive is defined on the server side as:
keepalive 3 15
Not sure what is wrong with it (at some point it was changed from 3 10 to 3 15).
Or you mean that this will be defined as well on the server side and client will be disconnected by the server without relevance to up-delay?

TinCanTech

Why did you change the default --keepalive ?

stvitaly

TinCanTech wrote Why did you change the default --keepalive ?

For faster recovery in case of failures.

TinCanTech

Well, your change is the root cause of the problem.

stvitaly

TinCanTech wrote Well, your change is the root cause of the problem.

As I already said netsh taken a LOT of time on client machines. In a part of the cases more than a minute, so this issue with would happen with 60 second keepalive as well.
I think it is important for community to know that default way of wintun ip assignment can take a lot of time and create issues due to it.
Do not understand why you are trying to present it as something normal.