Opened 9 years ago

Last modified 4 years ago

#564 assigned Bug / Defect

openvpn connection stops when network interface is removed

Reported by: alexs_yb Owned by: Samuli Seppänen
Priority: major Milestone:
Component: Management Version: OpenVPN 2.3.6 (Community Ed)
Severity: Not set (select this one, unless your'e a OpenVPN developer) Keywords:
Cc: tct

Description

Hi

https://forums.openvpn.net/topic18973.html

I have openvpn 2.3.6 installed on a W8.1 laptop.
I use it via the service option, so always on.

The config is meant to continually try connecting back to the main office.
But when I unplug my usb ethernet oepnvpn crashes, but not the service just the current connection

You can see in the lots here

Thu Jun 11 07:17:02 2015 us=5212 NETSH: C:\Windows\system32\netsh.exe interface ipv6 delete address Ethernet 4 2002:ca4a:2000:2017:4000::1021 store=active
Thu Jun 11 07:17:02 2015 us=36460 ERROR: netsh command failed: returned error code 1
Thu Jun 11 08:57:28 2015 us=230295 NETSH: command failed
Thu Jun 11 08:57:28 2015 us=230295 Exiting due to fatal error

This is a bug/problem, as the service doesn't crash so windows can't restart it.
Openvpn stops trying to process the config as it crashes.

I think it should be restarting, just because it failds to remove the old routes from an old interface shouldn't be the reason it stops working.

Attachments (1)

yboffice.log (20.7 KB) - added by alexs_yb 9 years ago.
openvpn.log file

Download all attachments as: .zip

Change History (13)

comment:1 Changed 9 years ago by Gert Döring

Component: OpenVPN ConnectManagement
Owner: set to Samuli Seppänen
Status: newassigned

Why is openvpn trying to change "Ethernet 4"? Is this the USB Ethernet or the TAP driver? OpenVPN shouldn't try to fiddle with a network card that is not the tap driver, and the TAP driver really should not be affected by removing the USB Ethernet...

But anyway - you really want to use nssm to run OpenVPN as a service, because of this and other misbehaviour. Copying in mattock, he plans to build installers with nssm...

comment:2 Changed 9 years ago by Samuli Seppänen

I just finished preliminary tests with NSSM and it worked beautifully, at least on a virtual machine. Starting and stopping an OpenVPN an OpenVPN connection worked, as well as respawn after the process had been killed with Stop-Process. NSSM's behavior after resume from hibernation has not been tested, but is unlikely to be worse than with openvpnserv.exe.

I documented the basic OpenVPN + NSSM setup process on the "Integrating OpenVPN with NSSM"" wiki page.

comment:3 Changed 9 years ago by alexs_yb

Looking at it now shows eth4 as the TAP V9 device.

Will NSSM work. as the service (as far as windows is concerned is still running.

Changed 9 years ago by alexs_yb

Attachment: yboffice.log added

openvpn.log file

comment:4 Changed 9 years ago by alexs_yb

Hi

I ran some tests. Eth4 is the TAP device, Ethernet it the usb eth.

I had everything attached and restarted openvpn service
The openvpnserv started and the openvpn process was started.
It connected fine over the usb eth.

I then removed the usb eth and the laptop went to wireless and the openvpn service timedout and reconnected via the wifi. no problem

reconnected to the usb eth and disconnected from the wifi. openvpn process still running . no problem.

this time I hibernated with usb attached and openvpn service running (both the service exe and openvpn).

removed the laptop from the usb eth and waited 5 min

restarted the laptop and the openvpn process has died

this is the tail of the log

Tue Jun 23 11:28:56 2015 open_tun, tt->ipv6=1
Tue Jun 23 11:28:56 2015 TAP-WIN32 device [Ethernet 4] opened: \\.\Global\{05861746-0878-407F-A9B3-E442997FE712}.tap
Tue Jun 23 11:28:56 2015 TAP-Windows Driver Version 9.21
Tue Jun 23 11:28:56 2015 Set TAP-Windows TUN subnet mode network/local/netmask = 10.172.210.0/10.172.210.17/255.255.255.128 [SUCCEEDED]
Tue Jun 23 11:28:56 2015 Notified TAP-Windows driver to set a DHCP IP/netmask of 10.172.210.17/255.255.255.128 on interface {05861746-0878-407F-A9B3-E442997FE0.126, lease-time: 31536000]
Tue Jun 23 11:28:56 2015 Successful ARP Flush on interface [19] {05861746-0878-407F-A9B3-E442997FE712}
Tue Jun 23 11:29:01 2015 TEST ROUTES: 0/0 succeeded len=0 ret=1 a=0 u/d=up
Tue Jun 23 11:29:01 2015 Initialization Sequence Completed
Tue Jun 23 11:29:30 2015 TUN/TAP I/O operation aborted, exiting
Tue Jun 23 11:29:30 2015 Exiting due to fatal error
Tue Jun 23 11:29:30 2015 Closing TUN/TAP interface
Tue Jun 23 11:29:30 2015 delete_route_ipv6(2002:ca4a:2000:acd2:4000::/66)
Tue Jun 23 11:29:30 2015 C:\Windows\system32\netsh.exe interface ipv6 delete route 2002:ca4a:2000:acd2:4000::/66 Ethernet 4 fe80::8 store=active
Tue Jun 23 11:31:09 2015 ERROR: Windows route delete ipv6 command failed: returned error code 1
Tue Jun 23 11:31:10 2015 NETSH: C:\Windows\system32\netsh.exe interface ipv6 delete address Ethernet 4 2002:ca4a:2000                                         :acd2:4000::100f store=active
Tue Jun 23 11:31:11 2015 ERROR: netsh command failed: returned error code 1
Tue Jun 23 11:31:15 2015 NETSH: command failed
Tue Jun 23 11:31:15 2015 Exiting due to fatal error

But the openvpnserv.exe was still running, so I am not sure nssm would handle that ? or would it track openvpn.exe if it does the later then probably I will have to look into it .

I have uploaded the log file

comment:5 Changed 9 years ago by alexs_yb

Hi

Thought I understood this. More testing.

Laptop connected to usb eth.
I pulled the usb eth first and then hibernated.

Wed Jun 24 07:59:18 2015 SIGUSR1[soft,ping-restart] received, process restarting
Wed Jun 24 07:59:18 2015 Restart pause, 2 second(s)
Wed Jun 24 07:59:20 2015 Control Channel Authentication: using 'ta.key' as a OpenVPN static key file
Wed Jun 24 07:59:20 2015 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Jun 24 07:59:20 2015 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Jun 24 07:59:20 2015 Socket Buffers: R=[65536->393216] S=[65536->393216]
Wed Jun 24 07:59:20 2015 UDPv4 link local: [undef]
Wed Jun 24 07:59:20 2015 UDPv4 link remote: [AF_INET]202.74.32.200:2443
Wed Jun 24 07:59:20 2015 TLS: Initial packet from [AF_INET]202.74.32.200:2443, sid=427b61e2 338904d4
Wed Jun 24 07:59:20 2015 VERIFY OK: depth=2, C=US, O=thawte, Inc., OU=Certification Services Division, OU=(c) 2006 thawte, Inc. - For authorized use only, CN=thawte Primary Root CA
Wed Jun 24 07:59:20 2015 VERIFY OK: depth=1, C=US, O=Thawte, Inc., CN=Thawte SSL CA
Wed Jun 24 07:59:20 2015 Validating certificate key usage
Wed Jun 24 07:59:20 2015 ++ Certificate has key usage  00a0, expects 00a0
Wed Jun 24 07:59:20 2015 VERIFY KU OK
Wed Jun 24 07:59:20 2015 Validating certificate extended key usage
Wed Jun 24 07:59:20 2015 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Wed Jun 24 07:59:20 2015 VERIFY EKU OK
Wed Jun 24 07:59:20 2015 VERIFY X509NAME OK: C=AU, ST=New South Wales, L=Sydney, O=Yieldbroker Pty Ltd, OU=Yieldbroker Pty Ltd, CN=vpn.yieldbroker.com
Wed Jun 24 07:59:20 2015 VERIFY OK: depth=0, C=AU, ST=New South Wales, L=Sydney, O=Yieldbroker Pty Ltd, OU=Yieldbroker Pty Ltd, CN=vpn.yieldbroker.com
Wed Jun 24 07:59:20 2015 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Wed Jun 24 07:59:20 2015 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Jun 24 07:59:20 2015 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Wed Jun 24 07:59:20 2015 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Jun 24 07:59:20 2015 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Wed Jun 24 07:59:20 2015 [vpn.yieldbroker.com] Peer Connection Initiated with [AF_INET]202.74.32.200:2443
Wed Jun 24 07:59:23 2015 SENT CONTROL [vpn.yieldbroker.com]: 'PUSH_REQUEST' (status=1)
Wed Jun 24 07:59:23 2015 PUSH: Received control message: 'PUSH_REPLY,ifconfig-ipv6 2002:ca4a:2000:2017:4000::1021/66 2002:ca4a:2000:2017:4000::1,sndbuf 393216,rcvbuf 393216,route-ipv6 2001::/16,route-ipv6 2002::/16,route-ipv6 0::/1,route-ipv6 8000::/1,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 10.32.20.100,dhcp-option DNS 10.32.20.102,dhcp-option DNS 10.32.69.11,comp-lzo yes,tun-ipv6,route-gateway 10.32.23.1,topology subnet,ping 5,ping-restart 15,ifconfig 10.32.23.35 255.255.255.128'
Wed Jun 24 07:59:23 2015 OPTIONS IMPORT: timers and/or timeouts modified
Wed Jun 24 07:59:23 2015 OPTIONS IMPORT: LZO parms modified
Wed Jun 24 07:59:23 2015 OPTIONS IMPORT: --sndbuf/--rcvbuf options modified
Wed Jun 24 07:59:23 2015 Socket Buffers: R=[393216->393216] S=[393216->393216]
Wed Jun 24 07:59:23 2015 OPTIONS IMPORT: --ifconfig/up options modified
Wed Jun 24 07:59:23 2015 OPTIONS IMPORT: route options modified
Wed Jun 24 07:59:23 2015 OPTIONS IMPORT: route-related options modified
Wed Jun 24 07:59:23 2015 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Wed Jun 24 07:59:23 2015 do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=1
Wed Jun 24 07:59:24 2015 NETSH: C:\Windows\system32\netsh.exe interface ipv6 set address Ethernet 4 2002:ca4a:2000:2017:4000::1021 store=active
Wed Jun 24 07:59:24 2015 add_route_ipv6(2002:ca4a:2000:2017:4000::/66 -> 2002:ca4a:2000:2017:4000::1021 metric 0) dev Ethernet 4
Wed Jun 24 07:59:24 2015 C:\Windows\system32\netsh.exe interface ipv6 add route 2002:ca4a:2000:2017:4000::/66 Ethernet 4 fe80::8 store=active
Wed Jun 24 07:59:24 2015 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Wed Jun 24 07:59:24 2015 open_tun, tt->ipv6=1
Wed Jun 24 07:59:24 2015 TAP-WIN32 device [Ethernet 4] opened: \\.\Global\{05861746-0878-407F-A9B3-E442997FE712}.tap
Wed Jun 24 07:59:24 2015 TAP-Windows Driver Version 9.21
Wed Jun 24 07:59:24 2015 Set TAP-Windows TUN subnet mode network/local/netmask = 10.32.23.0/10.32.23.35/255.255.255.128 [SUCCEEDED]
Wed Jun 24 07:59:24 2015 Notified TAP-Windows driver to set a DHCP IP/netmask of 10.32.23.35/255.255.255.128 on interface {05861746-0878-407F-A9B3-E442997FE712} [DHCP-serv: 10.32.23.126, lease-time: 31536000]
Wed Jun 24 07:59:24 2015 Successful ARP Flush on interface [19] {05861746-0878-407F-A9B3-E442997FE712}
Wed Jun 24 07:59:29 2015 TEST ROUTES: 1/1 succeeded len=0 ret=1 a=0 u/d=up
Wed Jun 24 07:59:29 2015 C:\Windows\system32\route.exe ADD 202.74.32.200 MASK 255.255.255.255 192.168.11.1
Wed Jun 24 07:59:29 2015 ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Wed Jun 24 07:59:29 2015 Route addition via IPAPI succeeded [adaptive]
Wed Jun 24 07:59:29 2015 C:\Windows\system32\route.exe ADD 192.168.11.5 MASK 255.255.255.255 192.168.11.1 IF 24
Wed Jun 24 07:59:29 2015 ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Wed Jun 24 07:59:29 2015 Route addition via IPAPI succeeded [adaptive]
Wed Jun 24 07:59:29 2015 C:\Windows\system32\route.exe ADD 0.0.0.0 MASK 128.0.0.0 10.32.23.1
Wed Jun 24 07:59:29 2015 ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Wed Jun 24 07:59:29 2015 Route addition via IPAPI succeeded [adaptive]
Wed Jun 24 07:59:29 2015 C:\Windows\system32\route.exe ADD 128.0.0.0 MASK 128.0.0.0 10.32.23.1
Wed Jun 24 07:59:29 2015 ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Wed Jun 24 07:59:29 2015 Route addition via IPAPI succeeded [adaptive]
Wed Jun 24 07:59:29 2015 add_route_ipv6(2001::/16 -> 2002:ca4a:2000:2017:4000::1 metric -1) dev Ethernet 4
Wed Jun 24 07:59:29 2015 C:\Windows\system32\netsh.exe interface ipv6 add route 2001::/16 Ethernet 4 fe80::8 store=active
Wed Jun 24 07:59:29 2015 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Wed Jun 24 07:59:29 2015 add_route_ipv6(2002::/16 -> 2002:ca4a:2000:2017:4000::1 metric -1) dev Ethernet 4
Wed Jun 24 07:59:29 2015 C:\Windows\system32\netsh.exe interface ipv6 add route 2002::/16 Ethernet 4 fe80::8 store=active
Wed Jun 24 07:59:29 2015 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Wed Jun 24 07:59:29 2015 add_route_ipv6(::/1 -> 2002:ca4a:2000:2017:4000::1 metric -1) dev Ethernet 4
Wed Jun 24 07:59:29 2015 C:\Windows\system32\netsh.exe interface ipv6 add route ::/1 Ethernet 4 fe80::8 store=active
Wed Jun 24 07:59:29 2015 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Wed Jun 24 07:59:29 2015 add_route_ipv6(8000::/1 -> 2002:ca4a:2000:2017:4000::1 metric -1) dev Ethernet 4
Wed Jun 24 07:59:29 2015 C:\Windows\system32\netsh.exe interface ipv6 add route 8000::/1 Ethernet 4 fe80::8 store=active
Wed Jun 24 07:59:29 2015 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Wed Jun 24 07:59:29 2015 Initialization Sequence Completed
Wed Jun 24 07:59:29 2015 TUN/TAP I/O operation aborted, exiting
Wed Jun 24 07:59:29 2015 Exiting due to fatal error
Wed Jun 24 07:59:29 2015 C:\Windows\system32\route.exe DELETE 202.74.32.200 MASK 255.255.255.255 192.168.11.1
Wed Jun 24 07:59:30 2015 Route deletion via IPAPI succeeded [adaptive]
Wed Jun 24 07:59:30 2015 C:\Windows\system32\route.exe DELETE 192.168.11.5 MASK 255.255.255.255 192.168.11.1
Wed Jun 24 07:59:30 2015 Route deletion via IPAPI succeeded [adaptive]
Wed Jun 24 07:59:30 2015 C:\Windows\system32\route.exe DELETE 0.0.0.0 MASK 128.0.0.0 10.32.23.1
Wed Jun 24 07:59:30 2015 Warning: route gateway is not reachable on any active network adapters: 10.32.23.1
Wed Jun 24 07:59:30 2015 Route deletion via IPAPI failed [adaptive]
Wed Jun 24 07:59:30 2015 Route deletion fallback to route.exe
Wed Jun 24 07:59:30 2015 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Wed Jun 24 07:59:30 2015 C:\Windows\system32\route.exe DELETE 128.0.0.0 MASK 128.0.0.0 10.32.23.1
Wed Jun 24 07:59:30 2015 Warning: route gateway is not reachable on any active network adapters: 10.32.23.1
Wed Jun 24 07:59:30 2015 Route deletion via IPAPI failed [adaptive]
Wed Jun 24 07:59:30 2015 Route deletion fallback to route.exe
Wed Jun 24 07:59:30 2015 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Wed Jun 24 07:59:30 2015 delete_route_ipv6(8000::/1)
Wed Jun 24 07:59:30 2015 C:\Windows\system32\netsh.exe interface ipv6 delete route 8000::/1 Ethernet 4 fe80::8 store=active
Wed Jun 24 07:59:30 2015 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Wed Jun 24 09:42:27 2015 ERROR: Windows route delete ipv6 command failed: returned error code 1
Wed Jun 24 09:42:27 2015 delete_route_ipv6(::/1)
Wed Jun 24 09:42:27 2015 C:\Windows\system32\netsh.exe interface ipv6 delete route ::/1 Ethernet 4 fe80::8 store=active
Wed Jun 24 09:42:27 2015 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Wed Jun 24 09:42:27 2015 ERROR: Windows route delete ipv6 command failed: returned error code 1
Wed Jun 24 09:42:27 2015 delete_route_ipv6(2002::/16)
Wed Jun 24 09:42:27 2015 C:\Windows\system32\netsh.exe interface ipv6 delete route 2002::/16 Ethernet 4 fe80::8 store=active
Wed Jun 24 09:42:27 2015 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Wed Jun 24 09:42:28 2015 ERROR: Windows route delete ipv6 command failed: returned error code 1
Wed Jun 24 09:42:28 2015 delete_route_ipv6(2001::/16)
Wed Jun 24 09:42:28 2015 C:\Windows\system32\netsh.exe interface ipv6 delete route 2001::/16 Ethernet 4 fe80::8 store=active
Wed Jun 24 09:42:28 2015 env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Wed Jun 24 09:42:28 2015 ERROR: Windows route delete ipv6 command failed: returned error code 1
Wed Jun 24 09:42:28 2015 Closing TUN/TAP interface
Wed Jun 24 09:42:28 2015 delete_route_ipv6(2002:ca4a:2000:2017:4000::/66)
Wed Jun 24 09:42:28 2015 C:\Windows\system32\netsh.exe interface ipv6 delete route 2002:ca4a:2000:2017:4000::/66 Ethernet 4 fe80::8 store=active
Wed Jun 24 09:42:28 2015 ERROR: Windows route delete ipv6 command failed: returned error code 1
Wed Jun 24 09:42:29 2015 NETSH: C:\Windows\system32\netsh.exe interface ipv6 delete address Ethernet 4 2002:ca4a:2000:2017:4000::1021 store=active
Wed Jun 24 09:42:29 2015 ERROR: netsh command failed: returned error code 1
Wed Jun 24 09:42:33 2015 NETSH: command failed
Wed Jun 24 09:42:33 2015 Exiting due to fatal error

still crashed :(

comment:6 Changed 9 years ago by Gert Döring

From the logs, it seems as if "removing USB ethernet" will make the windows networking stack restart (or whatever it does), breaking access to the TAP adapter - that's the I/O error in the log, and the failure to remove the IPv6 routes.

So, I think we'll have to live with that, and focus on proper restarting of openvpn in case "something windowsy" happens. NSSM to the rescue :-)

(And yes, NSSM will work, as it will re-start the program run from it if so configured - Samuli, do you have sample documentation already?)

comment:7 Changed 9 years ago by Samuli Seppänen

Yes, there is Wiki article on NSSM and OpenVPN: "Integrating OpenVPN with NSSM".

comment:8 Changed 9 years ago by alexs_yb

Hi

Okay, so I have reread the nssm page and I think I miss read, I can actually install this as a service that runs on machine startup and not on user login. Thats good.

Wouldn't the best solution be for the openvpn.exe to not do a fatal error on netsh error and exit, maybe fatal error to try and reset itself.

NOTE - I think this is new for W8.1 (can't say about W8 didn't use it). We use this similarly for W7 users

Thanks

comment:9 in reply to:  8 Changed 9 years ago by Gert Döring

Replying to alexs_yb:

Wouldn't the best solution be for the openvpn.exe to not do a fatal error on netsh error and exit, maybe fatal error to try and reset itself.

There's only so much you can do inside openvpn - if your tap device is no longer accessible, and netsh fails in surprising ways, doing a "clean restart from scratch" is quite complicated - and "just die, and let the caller start openvpn.exe again" is actually more robust than trying to catch every potential weird error inside.

We do catch most of the normal stuff (timeouts to connect, --ping timeout), but some of the more weird stuff just needs to rely on external authority. (Like "a user just killing the process" - there's nothing we could do in that case either).

comment:10 Changed 8 years ago by Vanav

I can confirm this bug. openvpnserv.exe doesn't restart openvpn.exe on fatal error?

Log tail:

Sun Oct 04 22:57:20 2015 Closing TUN/TAP interface
Sun Oct 04 22:57:20 2015 delete_route_ipv6(2a02:6b8:0:81f::/64)
Sun Oct 04 22:57:20 2015 C:\windows\system32\netsh.exe interface ipv6 delete route 2a02:6b8:0:81f::/64 My TAP 2a02:6b8:0:81f::109 store=active
Sun Oct 04 22:57:20 2015 ERROR: Windows route delete ipv6 command failed: returned error code 1
Sun Oct 04 22:57:21 2015 NETSH: C:\windows\system32\netsh.exe interface ipv6 delete address My TAP 2a02:6b8:0:81f::109 store=active
Sun Oct 04 22:57:21 2015 ERROR: netsh command failed: returned error code 1
Sun Oct 04 22:58:08 2015 NETSH: command failed
Sun Oct 04 22:58:08 2015 Exiting due to fatal error

comment:11 Changed 8 years ago by Samuli Seppänen

Openvpnserv2, which is bundled with recent snapshot installers, should fix this issue. Can someone verify this?

There is also a patch on the mailing list which prevents OpenVPN from consuming 100% CPU in cases where the underlying interface goes away unexpectedly.

comment:12 Changed 4 years ago by tct

Cc: tct added

I'll try to find time to test this as well.

Note: See TracTickets for help on using tickets.