OpenVPN / OpenVPN/openvpn

Client disconnects with `DCO_NOT_INSTALLED` asserion failure

Open
#445 7 comments 0 reactions 1 assignee View on GitHub

@lstipakov is already working on this.

Since Nov 3, 2023.

DCO dco-win
Dominant language
C
Stars
14.6k
Forks
3.4k
No merged PRs in 30d

Description

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.

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.