openvpn icon indicating copy to clipboard operation
openvpn copied to clipboard

Published 20 hours ago • verified publisher icon OpenVPN

Client disconnects with `DCO_NOT_INSTALLED` asserion failure

Open krzysdz opened this issue 7 months ago • 6 comments

Describe the bug Sometimes the Windows OpenVPN client disconnects after primary->dco_status != DCO_NOT_INSTALLED assertion fails.

Log from the day when the issue happened 
2023-10-27 13:31:22 us=625000 TLS: soft reset sec=29098/3600 bytes=0/-1 pkts=0/0
2023-10-27 13:31:22 us=625000 dco_del_key: peer-id 0, slot 1 called but ignored
2023-10-27 13:31:22 us=625000 UDP WRITE [54] to [AF_INET]SERVER_IP:1194: P_CONTROL_SOFT_RESET_V1 kid=3 pid=[ #29 ] [ ] pid=0 DATA len=0
2023-10-27 13:31:24 us=953000 UDP WRITE [54] to [AF_INET]SERVER_IP:1194: P_CONTROL_SOFT_RESET_V1 kid=3 pid=[ #30 ] [ ] pid=0 DATA len=0
2023-10-27 13:31:24 us=953000 write UDP: Operacja We/Wy nie powiodła się, ponieważ nośnik sieciowy jest odłączony lub punkt dostępu bezprzewodowego jest poza zasięgiem.   (fd=1a8,code=-2144075745)
2023-10-27 13:31:28 us=468000 UDP WRITE [54] to [AF_INET]SERVER_IP:1194: P_CONTROL_SOFT_RESET_V1 kid=3 pid=[ #31 ] [ ] pid=0 DATA len=0
2023-10-27 13:31:36 us=203000 UDP WRITE [54] to [AF_INET]SERVER_IP:1194: P_CONTROL_SOFT_RESET_V1 kid=3 pid=[ #32 ] [ ] pid=0 DATA len=0
2023-10-27 13:31:52 us=31000 UDP WRITE [54] to [AF_INET]SERVER_IP:1194: P_CONTROL_SOFT_RESET_V1 kid=3 pid=[ #33 ] [ ] pid=0 DATA len=0
2023-10-27 13:32:23 us=15000 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2023-10-27 13:32:23 us=15000 TLS Error: TLS handshake failed
2023-10-27 13:32:23 us=15000 TLS: move_session: dest=TM_LAME_DUCK src=TM_ACTIVE reinit_src=1
2023-10-27 13:32:23 us=15000 MANAGEMENT: >STATE:1698406343,WAIT,,,,,,
2023-10-27 13:32:23 us=15000 UDP WRITE [54] to [AF_INET]SERVER_IP:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 pid=[ #1 ] [ ] pid=0 DATA len=0
2023-10-27 13:32:23 us=15000 UDP READ [66] from [AF_INET]SERVER_IP:1194: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 pid=[ #1 ] [ 0 ] pid=0 DATA len=0
2023-10-27 13:32:23 us=15000 MANAGEMENT: >STATE:1698406343,AUTH,,,,,,
2023-10-27 13:32:23 us=15000 TLS: Initial packet from [AF_INET]SERVER_IP:1194, sid=476c28b1 0abe3e89
2023-10-27 13:32:23 us=15000 UDP WRITE [343] to [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=0 pid=[ #2 ] [ 0 ] pid=1 DATA len=277
2023-10-27 13:32:23 us=31000 UDP READ [62] from [AF_INET]SERVER_IP:1194: P_ACK_V1 kid=0 pid=[ #2 ] [ 1 ] DATA len=0
2023-10-27 13:32:23 us=31000 UDP READ [1148] from [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=0 pid=[ #3 ] [ ] pid=1 DATA len=1094
2023-10-27 13:32:23 us=31000 UDP WRITE [66] to [AF_INET]SERVER_IP:1194: P_ACK_V1 kid=0 pid=[ #3 ] [ 1 0 ] DATA len=0
2023-10-27 13:32:23 us=31000 UDP READ [1148] from [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=0 pid=[ #4 ] [ ] pid=2 DATA len=1094
2023-10-27 13:32:23 us=31000 VERIFY OK: depth=1, CN=CA certificate
2023-10-27 13:32:23 us=31000 VERIFY KU OK
2023-10-27 13:32:23 us=31000 Validating certificate extended key usage
2023-10-27 13:32:23 us=31000 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
2023-10-27 13:32:23 us=31000 VERIFY EKU OK
2023-10-27 13:32:23 us=31000 VERIFY OK: depth=0, CN=server certificate
2023-10-27 13:32:23 us=31000 UDP WRITE [70] to [AF_INET]SERVER_IP:1194: P_ACK_V1 kid=0 pid=[ #4 ] [ 2 1 0 ] DATA len=0
2023-10-27 13:32:23 us=31000 UDP READ [309] from [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=0 pid=[ #5 ] [ ] pid=3 DATA len=255
2023-10-27 13:32:23 us=31000 UDP WRITE [1222] to [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=0 pid=[ #5 ] [ 3 2 1 0 ] pid=2 DATA len=1144
2023-10-27 13:32:23 us=31000 UDP WRITE [1222] to [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=0 pid=[ #6 ] [ 3 2 1 0 ] pid=3 DATA len=1144
2023-10-27 13:32:23 us=31000 UDP WRITE [381] to [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=0 pid=[ #7 ] [ 3 2 1 0 ] pid=4 DATA len=303
2023-10-27 13:32:23 us=46000 UDP READ [62] from [AF_INET]SERVER_IP:1194: P_ACK_V1 kid=0 pid=[ #6 ] [ 2 ] DATA len=0
2023-10-27 13:32:23 us=62000 UDP READ [224] from [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=0 pid=[ #7 ] [ 3 ] pid=4 DATA len=158
2023-10-27 13:32:23 us=62000 UDP WRITE [78] to [AF_INET]SERVER_IP:1194: P_ACK_V1 kid=0 pid=[ #8 ] [ 4 3 2 1 0 ] DATA len=0
2023-10-27 13:32:23 us=62000 UDP READ [305] from [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=0 pid=[ #8 ] [ 4 ] pid=5 DATA len=239
2023-10-27 13:32:23 us=62000 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256
2023-10-27 13:32:23 us=62000 TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
2023-10-27 13:32:23 us=62000 TLS: tls_multi_process: initial untrusted session promoted to trusted
2023-10-27 13:32:23 us=62000 UDP WRITE [82] to [AF_INET]SERVER_IP:1194: P_ACK_V1 kid=0 pid=[ #9 ] [ 5 4 3 2 1 0 ] DATA len=0
2023-10-27 13:32:23 us=78000 UDP READ [214] from [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=0 pid=[ #9 ] [ ] pid=6 DATA len=160
2023-10-27 13:32:23 us=78000 PUSH: Received control message: 'PUSH_REPLY,route 10.8.0.0 255.255.255.0,topology net30,ping 10,ping-restart 120,ifconfig 10.8.0.22 10.8.0.21,peer-id 0,cipher AES-256-GCM'
2023-10-27 13:32:23 us=78000 dco_new_peer: peer-id 0, fd 424
2023-10-27 13:32:23 us=78000 Data Channel MTU parms [ mss_fix:1400 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
2023-10-27 13:32:23 us=78000 dco_install_key: peer_id=0 keyid=0, currently 1 keys installed
2023-10-27 13:32:23 us=78000 dco_new_key: slot 1, key-id 0, peer-id 0, cipher AES-256-GCM
2023-10-27 13:32:23 us=78000 dco_set_peer: peer-id 0, keepalive 10/120, mss 1400
2023-10-27 13:32:23 us=78000 Initialization Sequence Completed
2023-10-27 13:32:23 us=78000 MANAGEMENT: >STATE:1698406343,CONNECTED,SUCCESS,10.8.0.22,SERVER_IP,1194,,
2023-10-27 13:32:23 us=78000 Data Channel: cipher 'AES-256-GCM', peer-id: 0
2023-10-27 13:32:23 us=78000 Timers: ping 10, ping-restart 120
2023-10-27 13:32:23 us=78000 UDP WRITE [86] to [AF_INET]SERVER_IP:1194: P_ACK_V1 kid=0 pid=[ #10 ] [ 6 5 4 3 2 1 0 ] DATA len=0
2023-10-27 13:33:23 us=140000 Swapping primary and secondary keys to primary-id=0 secondary-id=2
2023-10-27 13:33:23 us=140000 dco_swap_keys: peer-id 0
2023-10-27 14:28:05 us=640000 UDP READ [54] from [AF_INET]SERVER_IP:1194: P_CONTROL_SOFT_RESET_V1 kid=1 pid=[ #10 ] [ ] pid=0 DATA len=0
2023-10-27 14:28:05 us=640000 UDP WRITE [66] to [AF_INET]SERVER_IP:1194: P_CONTROL_SOFT_RESET_V1 kid=1 pid=[ #11 ] [ 0 ] pid=0 DATA len=0
2023-10-27 14:28:05 us=656000 UDP READ [62] from [AF_INET]SERVER_IP:1194: P_ACK_V1 kid=1 pid=[ #11 ] [ 0 ] DATA len=0
2023-10-27 14:28:05 us=656000 UDP WRITE [343] to [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=1 pid=[ #12 ] [ 0 ] pid=1 DATA len=277
2023-10-27 14:28:05 us=671000 UDP READ [1160] from [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=1 pid=[ #12 ] [ 1 ] pid=1 DATA len=1094
2023-10-27 14:28:05 us=671000 UDP WRITE [66] to [AF_INET]SERVER_IP:1194: P_ACK_V1 kid=1 pid=[ #13 ] [ 1 0 ] DATA len=0
2023-10-27 14:28:05 us=671000 UDP READ [1148] from [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=1 pid=[ #13 ] [ ] pid=2 DATA len=1094
2023-10-27 14:28:05 us=671000 VERIFY OK: depth=1, CN=CA certificate
2023-10-27 14:28:05 us=671000 VERIFY KU OK
2023-10-27 14:28:05 us=671000 Validating certificate extended key usage
2023-10-27 14:28:05 us=671000 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
2023-10-27 14:28:05 us=671000 VERIFY EKU OK
2023-10-27 14:28:05 us=671000 VERIFY OK: depth=0, CN=server certificate
2023-10-27 14:28:05 us=671000 UDP WRITE [70] to [AF_INET]SERVER_IP:1194: P_ACK_V1 kid=1 pid=[ #14 ] [ 2 1 0 ] DATA len=0
2023-10-27 14:28:05 us=671000 UDP READ [309] from [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=1 pid=[ #14 ] [ ] pid=3 DATA len=255
2023-10-27 14:28:05 us=671000 UDP WRITE [1222] to [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=1 pid=[ #15 ] [ 3 2 1 0 ] pid=2 DATA len=1144
2023-10-27 14:28:05 us=671000 UDP WRITE [1222] to [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=1 pid=[ #16 ] [ 3 2 1 0 ] pid=3 DATA len=1144
2023-10-27 14:28:05 us=671000 UDP WRITE [381] to [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=1 pid=[ #17 ] [ 3 2 1 0 ] pid=4 DATA len=303
2023-10-27 14:28:05 us=687000 UDP READ [62] from [AF_INET]SERVER_IP:1194: P_ACK_V1 kid=1 pid=[ #15 ] [ 2 ] DATA len=0
2023-10-27 14:28:05 us=687000 UDP READ [224] from [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=1 pid=[ #16 ] [ 3 ] pid=4 DATA len=158
2023-10-27 14:28:05 us=687000 UDP WRITE [78] to [AF_INET]SERVER_IP:1194: P_ACK_V1 kid=1 pid=[ #18 ] [ 4 3 2 1 0 ] DATA len=0
2023-10-27 14:28:05 us=703000 UDP READ [305] from [AF_INET]SERVER_IP:1194: P_CONTROL_V1 kid=1 pid=[ #17 ] [ 4 ] pid=5 DATA len=239
2023-10-27 14:28:05 us=703000 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256
2023-10-27 14:28:05 us=703000 dco_install_key: peer_id=0 keyid=1, currently 2 keys installed
2023-10-27 14:28:05 us=703000 dco_new_key: slot 1, key-id 1, peer-id 0, cipher AES-256-GCM
2023-10-27 14:28:05 us=703000 UDP WRITE [82] to [AF_INET]SERVER_IP:1194: P_ACK_V1 kid=1 pid=[ #19 ] [ 5 4 3 2 1 0 ] DATA len=0
2023-10-27 14:29:05 us=656000 MANAGEMENT: Client disconnected
2023-10-27 14:29:05 us=656000 Assertion failed at C:\buildbot\msbuild\openvpn-build\src\openvpn\src\openvpn\dco.c:173 (primary->dco_status != DCO_NOT_INSTALLED)
2023-10-27 14:29:05 us=656000 Exiting due to fatal error
2023-10-27 14:29:05 us=656000 C:\Windows\system32\route.exe DELETE 10.8.0.0 MASK 255.255.255.0 10.8.0.21
2023-10-27 14:29:05 us=656000 Route deletion via service succeeded
2023-10-27 14:29:05 us=656000 Closing DCO interface
2023-10-27 14:29:05 us=656000 Deleting WINS servers on 'OpenVPN Data Channel Offload' (if_index = 19) using service
2023-10-27 14:29:05 us=750000 WINS servers deleted using service
2023-10-27 14:29:05 us=750000 Deleting IPv4 dns servers on 'OpenVPN Data Channel Offload' (if_index = 19) using service
2023-10-27 14:29:05 us=781000 IPv4 dns servers deleted using service
2023-10-27 14:29:05 us=781000 INET address service: remove 10.8.0.22/30

To Reproduce

  1. Connect to a VPN using a recent version of OpenVPN with DCO
  2. wait?

Client config:

client
dev tun
proto udp
remote SERVER_IP 1194
resolv-retry infinite
nobind
user nobody
group nogroup
persist-key
persist-tun
remote-cert-tls server
cipher AES-256-CBC
auth SHA256
key-direction 1
verb 6
# Keys and certificates
# ...

Expected behavior The client does not disconnect or reconnects to the server without user interaction.

Version information (please complete the following information):

  • OS: Windows 10 build 19045.3570
  • OpenVPN version: 2.6.6

Additional context This is probably a duplicate of #193, but the author did not provide the requested logs and was using Ubuntu.

The device often runs for a few days without reboot with occasional hibernations, but I did not observe a relation between uptime or time since last hibernation and the issue occurring.

krzysdz avatar Nov 03 '23 01:11 krzysdz