Closed selvanair closed 1 year ago
I also observed this problem.
Even 2.5.0 appears to behave the same way. Looks like SIGHUP restart never worked with wintun?
Possibly, closing ring buffers require to use the service? None of the CloseHandle() calls in ~close_tun_sevice()~ close_tun_handle() do error out though. Edit: on further look, attempt is made to close duplicated handles and unmap the file in the service, but its buggy. See https://patchwork.openvpn.net/project/openvpn2/patch/20221229040717.1471276-1-selva.nair@gmail.com/
Confirmed.
Re-installed 2.5.8 and followed the simple instructions.
Connection failed, all adapters in use or disabled.
Thanks, I'll look into it
Ah looks like @selvanair has already fixed it.
Interesting, while the fix indeed makes sense, I cannot reproduce this bug:
Thu Dec 29 12:31:27 2022 OpenVPN 2.6_rc1 [git:v2.6_rc1/84e70c479e81eebe] Windows-MSVC [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] [DCO] built on Dec 28 2022
Thu Dec 29 12:31:27 2022 Windows version 10.0 (Windows 10 or greater), amd64 executable
Thu Dec 29 12:31:27 2022 library versions: OpenSSL 3.0.7 1 Nov 2022, LZO 2.10
Thu Dec 29 12:31:27 2022 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25355
Thu Dec 29 12:31:27 2022 Need hold release from management interface, waiting...
Thu Dec 29 12:31:27 2022 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:61554
Thu Dec 29 12:31:27 2022 MANAGEMENT: CMD 'state on'
Thu Dec 29 12:31:27 2022 MANAGEMENT: CMD 'log on all'
Thu Dec 29 12:31:27 2022 MANAGEMENT: CMD 'echo on all'
Thu Dec 29 12:31:27 2022 MANAGEMENT: CMD 'bytecount 5'
Thu Dec 29 12:31:27 2022 MANAGEMENT: CMD 'state'
Thu Dec 29 12:31:27 2022 MANAGEMENT: CMD 'hold off'
Thu Dec 29 12:31:27 2022 MANAGEMENT: CMD 'hold release'
Thu Dec 29 12:31:27 2022 MANAGEMENT: CMD 'proxy NONE '
Thu Dec 29 12:31:28 2022 WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
Thu Dec 29 12:31:28 2022 Control Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1250 tun_max_mtu:0 headroom:126 payload:1600 tailroom:126 ET:0 ]
Thu Dec 29 12:31:28 2022 MANAGEMENT: >STATE:1672309888,RESOLVE,,,,,,
Thu Dec 29 12:31:28 2022 Data Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
Thu Dec 29 12:31:28 2022 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1543,tun-mtu 1500,proto TCPv4_CLIENT,auth SHA1,keysize 128,key-method 2,tls-client'
Thu Dec 29 12:31:28 2022 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1543,tun-mtu 1500,proto TCPv4_SERVER,auth SHA1,keysize 128,key-method 2,tls-server'
Thu Dec 29 12:31:28 2022 TCP/UDP: Preserving recently used remote address: [AF_INET]a.b.c.d:1194
Thu Dec 29 12:31:28 2022 Socket Buffers: R=[65536->65536] S=[65536->65536]
Thu Dec 29 12:31:28 2022 Attempting to establish TCP connection with [AF_INET]a.b.c.d:1194
Thu Dec 29 12:31:28 2022 MANAGEMENT: >STATE:1672309888,TCP_CONNECT,,,,,,
Thu Dec 29 12:31:28 2022 TCP connection established with [AF_INET]a.b.c.d:1194
Thu Dec 29 12:31:28 2022 TCPv4_CLIENT link local: (not bound)
Thu Dec 29 12:31:28 2022 TCPv4_CLIENT link remote: [AF_INET]a.b.c.d:1194
Thu Dec 29 12:31:28 2022 MANAGEMENT: >STATE:1672309888,WAIT,,,,,,
Thu Dec 29 12:31:28 2022 MANAGEMENT: >STATE:1672309888,AUTH,,,,,,
Thu Dec 29 12:31:28 2022 TLS: Initial packet from [AF_INET]a.b.c.d:1194, sid=944d8412 cac1e5de
Thu Dec 29 12:31:29 2022 VERIFY OK: depth=1, CN=LeeviCA5
Thu Dec 29 12:31:29 2022 VERIFY OK: depth=0, CN=foo.fi
Thu Dec 29 12:31:29 2022 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256
Thu Dec 29 12:31:29 2022 [foo.fi] Peer Connection Initiated with [AF_INET]a.b.c.d:1194
Thu Dec 29 12:31:29 2022 TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
Thu Dec 29 12:31:29 2022 TLS: tls_multi_process: initial untrusted session promoted to trusted
Thu Dec 29 12:31:29 2022 PUSH: Received control message: 'PUSH_REPLY,tun-ipv6,route-gateway 10.58.0.1,topology subnet,ping 30,ping-restart 180,ifconfig-ipv6 2001:db8:0:456::1000/64 2001:db8:0:456::1,ifconfig 10.58.0.2 255.255.255.0,peer-id 0,cipher AES-256-GCM,protocol-flags cc-exit tls-ekm,tun-mtu 1500'
Thu Dec 29 12:31:29 2022 OPTIONS IMPORT: timers and/or timeouts modified
Thu Dec 29 12:31:29 2022 OPTIONS IMPORT: --ifconfig/up options modified
Thu Dec 29 12:31:29 2022 OPTIONS IMPORT: route-related options modified
Thu Dec 29 12:31:29 2022 OPTIONS IMPORT: peer-id set
Thu Dec 29 12:31:29 2022 OPTIONS IMPORT: data channel crypto options modified
Thu Dec 29 12:31:29 2022 OPTIONS IMPORT: tun-mtu set to 1500
Thu Dec 29 12:31:29 2022 interactive service msg_channel=656
Thu Dec 29 12:31:29 2022 open_tun
Thu Dec 29 12:31:29 2022 Ring buffers registered via service
Thu Dec 29 12:31:29 2022 wintun device [Local Area Connection 2] opened
Thu Dec 29 12:31:29 2022 do_ifconfig, ipv4=1, ipv6=1
Thu Dec 29 12:31:29 2022 MANAGEMENT: >STATE:1672309889,ASSIGN_IP,,10.58.0.2,,,,,2001:db8:0:456::1000
Thu Dec 29 12:31:29 2022 INET address service: add 10.58.0.2/24
Thu Dec 29 12:31:29 2022 IPv4 MTU set to 1500 on interface 18 using service
Thu Dec 29 12:31:29 2022 INET6 address service: add 2001:db8:0:456::1000/128
Thu Dec 29 12:31:29 2022 add_route_ipv6(2001:db8:0:456::/64 -> 2001:db8:0:456::1000 metric 0) dev Local Area Connection 2
Thu Dec 29 12:31:29 2022 IPv6 route addition via service succeeded
Thu Dec 29 12:31:29 2022 IPv6 MTU set to 1500 on interface 18 using service
Thu Dec 29 12:31:29 2022 Data Channel: using negotiated cipher 'AES-256-GCM'
Thu Dec 29 12:31:29 2022 Data Channel MTU parms [ mss_fix:1386 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
Thu Dec 29 12:31:29 2022 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Thu Dec 29 12:31:29 2022 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Thu Dec 29 12:31:29 2022 Initialization Sequence Completed
Thu Dec 29 12:31:29 2022 MANAGEMENT: >STATE:1672309889,CONNECTED,SUCCESS,10.58.0.2,a.b.c.d,1194,100.77.196.74,61557,2001:db8:0:456::1000
Thu Dec 29 12:31:36 2022 MANAGEMENT: CMD 'signal SIGHUP'
Thu Dec 29 12:31:36 2022 TCP/UDP: Closing socket
Thu Dec 29 12:31:36 2022 Closing TUN/TAP interface
Thu Dec 29 12:31:36 2022 delete_route_ipv6(2001:db8:0:456::/64)
Thu Dec 29 12:31:36 2022 IPv6 route deletion via service succeeded
Thu Dec 29 12:31:36 2022 INET6 address service: remove 2001:db8:0:456::1000/128
Thu Dec 29 12:31:36 2022 Deleting IPv4 dns servers on 'Local Area Connection 2' (if_index = 18) using service
Thu Dec 29 12:31:37 2022 IPv4 dns servers deleted using service
Thu Dec 29 12:31:37 2022 INET address service: remove 10.58.0.2/24
Thu Dec 29 12:31:37 2022 SIGHUP[hard,] received, process restarting
Thu Dec 29 12:31:37 2022 MANAGEMENT: >STATE:1672309897,RECONNECTING,SIGHUP,,,,,
Thu Dec 29 12:31:37 2022 Note: --cipher is not set. OpenVPN versions before 2.5 defaulted to BF-CBC as fallback when cipher negotiation failed in this case. If you need this fallback please add '--data-ciphers-fallback BF-CBC' to your configuration and/or add BF-CBC to --data-ciphers.
Thu Dec 29 12:31:37 2022 --windows-driver is set to 'wintun'. Disabling Data Channel Offload
<snip>
Thu Dec 29 12:31:37 2022 OpenVPN 2.6_rc1 [git:v2.6_rc1/84e70c479e81eebe] Windows-MSVC [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] [DCO] built on Dec 28 2022
Thu Dec 29 12:31:37 2022 Windows version 10.0 (Windows 10 or greater), amd64 executable
Thu Dec 29 12:31:37 2022 library versions: OpenSSL 3.0.7 1 Nov 2022, LZO 2.10
Thu Dec 29 12:31:37 2022 Restart pause, 2 second(s)
Thu Dec 29 12:31:40 2022 MANAGEMENT: CMD 'proxy NONE '
Thu Dec 29 12:31:40 2022 WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
Thu Dec 29 12:31:40 2022 Control Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1250 tun_max_mtu:0 headroom:126 payload:1600 tailroom:126 ET:0 ]
Thu Dec 29 12:31:40 2022 MANAGEMENT: >STATE:1672309900,RESOLVE,,,,,,
Thu Dec 29 12:31:40 2022 Data Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
Thu Dec 29 12:31:40 2022 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1543,tun-mtu 1500,proto TCPv4_CLIENT,auth SHA1,keysize 128,key-method 2,tls-client'
Thu Dec 29 12:31:40 2022 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1543,tun-mtu 1500,proto TCPv4_SERVER,auth SHA1,keysize 128,key-method 2,tls-server'
Thu Dec 29 12:31:40 2022 TCP/UDP: Preserving recently used remote address: [AF_INET]a.b.c.d:1194
Thu Dec 29 12:31:40 2022 Socket Buffers: R=[65536->65536] S=[65536->65536]
Thu Dec 29 12:31:40 2022 Attempting to establish TCP connection with [AF_INET]a.b.c.d:1194
Thu Dec 29 12:31:40 2022 MANAGEMENT: >STATE:1672309900,TCP_CONNECT,,,,,,
Thu Dec 29 12:31:40 2022 TCP connection established with [AF_INET]a.b.c.d:1194
Thu Dec 29 12:31:40 2022 TCPv4_CLIENT link local: (not bound)
Thu Dec 29 12:31:40 2022 TCPv4_CLIENT link remote: [AF_INET]a.b.c.d:1194
Thu Dec 29 12:31:40 2022 MANAGEMENT: >STATE:1672309900,WAIT,,,,,,
Thu Dec 29 12:31:40 2022 MANAGEMENT: >STATE:1672309900,AUTH,,,,,,
Thu Dec 29 12:31:40 2022 TLS: Initial packet from [AF_INET]a.b.c.d:1194, sid=d1ecf9a8 841641bb
Thu Dec 29 12:31:40 2022 VERIFY OK: depth=1, CN=LeeviCA5
Thu Dec 29 12:31:40 2022 VERIFY OK: depth=0, CN=foo.fi
Thu Dec 29 12:31:40 2022 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256
Thu Dec 29 12:31:40 2022 [foo.fi] Peer Connection Initiated with [AF_INET]a.b.c.d:1194
Thu Dec 29 12:31:40 2022 TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
Thu Dec 29 12:31:40 2022 TLS: tls_multi_process: initial untrusted session promoted to trusted
Thu Dec 29 12:31:40 2022 PUSH: Received control message: 'PUSH_REPLY,tun-ipv6,route-gateway 10.58.0.1,topology subnet,ping 30,ping-restart 180,ifconfig-ipv6 2001:db8:0:456::1000/64 2001:db8:0:456::1,ifconfig 10.58.0.2 255.255.255.0,peer-id 1,cipher AES-256-GCM,protocol-flags cc-exit tls-ekm,tun-mtu 1500'
Thu Dec 29 12:31:40 2022 OPTIONS IMPORT: timers and/or timeouts modified
Thu Dec 29 12:31:40 2022 OPTIONS IMPORT: --ifconfig/up options modified
Thu Dec 29 12:31:40 2022 OPTIONS IMPORT: route-related options modified
Thu Dec 29 12:31:40 2022 OPTIONS IMPORT: peer-id set
Thu Dec 29 12:31:40 2022 OPTIONS IMPORT: data channel crypto options modified
Thu Dec 29 12:31:40 2022 OPTIONS IMPORT: tun-mtu set to 1500
Thu Dec 29 12:31:40 2022 interactive service msg_channel=656
Thu Dec 29 12:31:40 2022 open_tun
Thu Dec 29 12:31:40 2022 Ring buffers registered via service
Thu Dec 29 12:31:40 2022 wintun device [Local Area Connection 2] opened
Thu Dec 29 12:31:40 2022 do_ifconfig, ipv4=1, ipv6=1
Thu Dec 29 12:31:40 2022 MANAGEMENT: >STATE:1672309900,ASSIGN_IP,,10.58.0.2,,,,,2001:db8:0:456::1000
Thu Dec 29 12:31:40 2022 INET address service: add 10.58.0.2/24
Thu Dec 29 12:31:40 2022 IPv4 MTU set to 1500 on interface 18 using service
Thu Dec 29 12:31:40 2022 INET6 address service: add 2001:db8:0:456::1000/128
Thu Dec 29 12:31:40 2022 add_route_ipv6(2001:db8:0:456::/64 -> 2001:db8:0:456::1000 metric 0) dev Local Area Connection 2
Thu Dec 29 12:31:40 2022 IPv6 route addition via service succeeded
Thu Dec 29 12:31:40 2022 IPv6 MTU set to 1500 on interface 18 using service
Thu Dec 29 12:31:40 2022 Data Channel: using negotiated cipher 'AES-256-GCM'
Thu Dec 29 12:31:40 2022 Data Channel MTU parms [ mss_fix:1386 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
Thu Dec 29 12:31:40 2022 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Thu Dec 29 12:31:40 2022 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Thu Dec 29 12:31:40 2022 Initialization Sequence Completed
Thu Dec 29 12:31:40 2022 MANAGEMENT: >STATE:1672309900,CONNECTED,SUCCESS,10.58.0.2,a.b.c.d,1194,100.77.196.74,61664,2001:db8:0:456::1000
Edit: on further look, attempt is made to close duplicated handles and unmap the file in the service, but its buggy. See https://patchwork.openvpn.net/project/openvpn2/patch/20221229040717.1471276-1-selva.nair@gmail.com/
We really should do _beta and _rc releases much more often... this brings so many nice findings :-)
Describe the bug After a successful connection using OpenVPN-GUI, reconnecting fails with "All wintun adapters on this system are currently in use or disabled." The actual error appears to be with registering ring buffers (see logs below).
To Reproduce Start a connection on Windows with
--windows-driver wintun
using OpenVPN-GUI. Once connected, press reconnect which sends SIGHUP. After receiving PUSH_REPLY, the connection will fail with the above error. Tested only using OpenVPN-GUI as wintun needs SYSTEM privileges, but the error doesn't appear to be related to the GUI.Expected behavior SIGHUP restart should work
Version information (please complete the following information):
Additional context Logs after first successful connection (excuse the hacked-up highlighting of errors)