OpenVPN 2.6.5 disconnects if connected to RDP with Windows 2012 Server (every 10 minutes)

[thyxNY]

I have a strange problem connecting with OpenVPN.
I connect to the company using OpenVPN client 2.6.5.

If I run RDP connection to the Windows 2016 Datacenter server - everything is OK.
However, if you connect to a server with Windows 2012 Datacenter R2 (build 9600), the OpenVPN client disconnects exactly every 10 minutes, then reconnects 2-3 seconds and .... the situation repeats every 10 minutes.

I made a config with verb=11 and I have this record from the log:

2023-07-24 15:21:43 us=390000 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=000001BDB164C3B0, ptr=0000000000000000, ad=000001BDB164C440, idx=1, argl=0, argp=00007FFFBAD13D38
2023-07-24 15:21:43 us=390000 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=000001BDB164BD20, ptr=0000000000000000, ad=000001BDB164BDB0, idx=1, argl=0, argp=00007FFFBAD13D38
2023-07-24 15:21:43 us=390000 TCP/UDP: Closing socket
2023-07-24 15:21:43 us=390000 SIGUSR1[soft,remote-exit] received, process restarting
2023-07-24 15:21:43 us=390000 MANAGEMENT: >STATE:1690204903,RECONNECTING,remote-exit,,,,,
2023-07-24 15:21:43 us=390000 Restart pause, 1 second(s)
2023-07-24 15:21:44 us=406000 Re-using SSL/TLS context
2023-07-24 15:21:44 us=406000 MTU: adding 426 buffer tailroom for compression for 1768 bytes of payload
2023-07-24 15:21:44 us=406000 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 ]
2023-07-24 15:21:44 us=406000 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 ]
2023-07-24 15:21:44 us=406000 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
2023-07-24 15:21:44 us=406000 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
2023-07-24 15:21:44 us=406000 TCP/UDP: Preserving recently used remote address: [AF_INET]91.207.xx.xx:1194
2023-07-24 15:21:44 us=406000 Socket Buffers: R=[65536->65536] S=[65536->65536]
2023-07-24 15:21:44 us=406000 UDPv4 link local: (not bound)
2023-07-24 15:21:44 us=406000 UDPv4 link remote: [AF_INET]91.207.xx.xx:1194
2023-07-24 15:21:44 us=406000 MANAGEMENT: >STATE:1690204904,WAIT,,,,,,
2023-07-24 15:21:44 us=406000 write_control_auth(): P_CONTROL_HARD_RESET_CLIENT_V2
…
2023-07-24 15:32:25 us=593000 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=000001BDB164B870, ptr=0000000000000000, ad=000001BDB164B900, idx=1, argl=0, argp=00007FFFBAD13D38
2023-07-24 15:32:25 us=593000 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=000001BDB164AA60, ptr=0000000000000000, ad=000001BDB164AAF0, idx=1, argl=0, argp=00007FFFBAD13D38
2023-07-24 15:32:25 us=593000 TCP/UDP: Closing socket
2023-07-24 15:32:25 us=593000 SIGUSR1[soft,remote-exit] received, process restarting
2023-07-24 15:32:25 us=593000 MANAGEMENT: >STATE:1690205545,RECONNECTING,remote-exit,,,,,
2023-07-24 15:32:25 us=593000 Restart pause, 1 second(s)
2023-07-24 15:32:26 us=609000 Re-using SSL/TLS context
2023-07-24 15:32:26 us=609000 MTU: adding 426 buffer tailroom for compression for 1768 bytes of payload
2023-07-24 15:32:26 us=609000 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 ]
2023-07-24 15:32:26 us=609000 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 ]
2023-07-24 15:32:26 us=609000 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
2023-07-24 15:32:26 us=609000 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
2023-07-24 15:32:26 us=609000 TCP/UDP: Preserving recently used remote address: [AF_INET]91.207.xx.xx:1194
2023-07-24 15:32:26 us=609000 Socket Buffers: R=[65536->65536] S=[65536->65536]
2023-07-24 15:32:26 us=609000 UDPv4 link local: (not bound)
2023-07-24 15:32:26 us=609000 UDPv4 link remote: [AF_INET]91.207.xx.xx:1194
2023-07-24 15:32:26 us=609000 MANAGEMENT: >STATE:1690205546,WAIT,,,,,,
2023-07-24 15:32:26 us=609000 write_control_auth(): P_CONTROL_HARD_RESET_CLIENT_V2

Version information (please complete the following information):

• OS: Windows 10
• OpenVPN version: 2.6.5

[schwabe]

2023-07-24 15:21:43 us=390000 SIGUSR1[soft,remote-exit] received, process restarting

The peer tells your client to reconnect. The client is behaving exactly like it should. What kind of server do you use and what the server log say?

[cron2]

@thxny not sure I agree with @schwabe on the "it's coming from the server", but it's hard to see because your log is incomplete in that regard. Can you please re-run with verb 4 and include everything(!) between two Initialization Sequence Completed lines?

The pkcs#11 stuff in your log irritates me, but that might be perfectly normal, just caused by verb 11 - it could hint at "if RDP is running, it grabs the smartcard interface and confuses OpenVPN at TLS renegotiation", but this is a very wild guess.

Of course, seeing the server log (verb 3 or 4) at the time of disconnect (30seconds before that, to actual disconnect) would also be helpful.

[thyxNY]

@schwabe @cron2

Hi,
I changed verb to 4:

11:38:27 first connecting
11:39:00 I run RDP connection to WindowsServer 2012R2, OpenVPN disconnecting and connecting again, RDP working fine (and 10 minutes will be worked fine)
11:49:16 OpenVPN disconnecting and connecting again
11:59:17 OpenVPN disconnecting and connecting again
and 10 minutes ..
and 10 minutes ..

Full log:
Sun Aug 13 11:38:27 2023 pkcs11_private_mode = 00000000
Sun Aug 13 11:38:27 2023 pkcs11_private_mode = 00000000
Sun Aug 13 11:38:27 2023 pkcs11_private_mode = 00000000
Sun Aug 13 11:38:27 2023 pkcs11_private_mode = 00000000
Sun Aug 13 11:38:27 2023 pkcs11_private_mode = 00000000
Sun Aug 13 11:38:27 2023 pkcs11_private_mode = 00000000
Sun Aug 13 11:38:27 2023 pkcs11_private_mode = 00000000
Sun Aug 13 11:38:27 2023 pkcs11_private_mode = 00000000
Sun Aug 13 11:38:27 2023 pkcs11_private_mode = 00000000
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_cert_private = DISABLED
Sun Aug 13 11:38:27 2023 pkcs11_pin_cache_period = -1
Sun Aug 13 11:38:27 2023 pkcs11_id = '[UNDEF]'
Sun Aug 13 11:38:27 2023 pkcs11_id_management = DISABLED
Sun Aug 13 11:38:27 2023 server_network = 0.0.0.0
Sun Aug 13 11:38:27 2023 server_netmask = 0.0.0.0
Sun Aug 13 11:38:27 2023 server_network_ipv6 = ::
Sun Aug 13 11:38:27 2023 server_netbits_ipv6 = 0
Sun Aug 13 11:38:27 2023 server_bridge_ip = 0.0.0.0
Sun Aug 13 11:38:27 2023 server_bridge_netmask = 0.0.0.0
Sun Aug 13 11:38:27 2023 server_bridge_pool_start = 0.0.0.0
Sun Aug 13 11:38:27 2023 server_bridge_pool_end = 0.0.0.0
Sun Aug 13 11:38:27 2023 ifconfig_pool_defined = DISABLED
Sun Aug 13 11:38:27 2023 ifconfig_pool_start = 0.0.0.0
Sun Aug 13 11:38:27 2023 ifconfig_pool_end = 0.0.0.0
Sun Aug 13 11:38:27 2023 ifconfig_pool_netmask = 0.0.0.0
Sun Aug 13 11:38:27 2023 ifconfig_pool_persist_filename = '[UNDEF]'
Sun Aug 13 11:38:27 2023 ifconfig_pool_persist_refresh_freq = 600
Sun Aug 13 11:38:27 2023 ifconfig_ipv6_pool_defined = DISABLED
Sun Aug 13 11:38:27 2023 ifconfig_ipv6_pool_base = ::
Sun Aug 13 11:38:27 2023 ifconfig_ipv6_pool_netbits = 0
Sun Aug 13 11:38:27 2023 n_bcast_buf = 256
Sun Aug 13 11:38:27 2023 tcp_queue_limit = 64
Sun Aug 13 11:38:27 2023 real_hash_size = 256
Sun Aug 13 11:38:27 2023 virtual_hash_size = 256
Sun Aug 13 11:38:27 2023 client_connect_script = '[UNDEF]'
Sun Aug 13 11:38:27 2023 learn_address_script = '[UNDEF]'
Sun Aug 13 11:38:27 2023 client_disconnect_script = '[UNDEF]'
Sun Aug 13 11:38:27 2023 client_crresponse_script = '[UNDEF]'
Sun Aug 13 11:38:27 2023 client_config_dir = '[UNDEF]'
Sun Aug 13 11:38:27 2023 ccd_exclusive = DISABLED
Sun Aug 13 11:38:27 2023 tmp_dir = 'C:\Users\Irek\AppData\Local\Temp'
Sun Aug 13 11:38:27 2023 push_ifconfig_defined = DISABLED
Sun Aug 13 11:38:27 2023 push_ifconfig_local = 0.0.0.0
Sun Aug 13 11:38:27 2023 push_ifconfig_remote_netmask = 0.0.0.0
Sun Aug 13 11:38:27 2023 push_ifconfig_ipv6_defined = DISABLED
Sun Aug 13 11:38:27 2023 push_ifconfig_ipv6_local = ::/0
Sun Aug 13 11:38:27 2023 push_ifconfig_ipv6_remote = ::
Sun Aug 13 11:38:27 2023 enable_c2c = DISABLED
Sun Aug 13 11:38:27 2023 duplicate_cn = DISABLED
Sun Aug 13 11:38:27 2023 cf_max = 0
Sun Aug 13 11:38:27 2023 cf_per = 0
Sun Aug 13 11:38:27 2023 cf_initial_max = 100
Sun Aug 13 11:38:27 2023 cf_initial_per = 10
Sun Aug 13 11:38:27 2023 max_clients = 1024
Sun Aug 13 11:38:27 2023 max_routes_per_client = 256
Sun Aug 13 11:38:27 2023 auth_user_pass_verify_script = '[UNDEF]'
Sun Aug 13 11:38:27 2023 auth_user_pass_verify_script_via_file = DISABLED
Sun Aug 13 11:38:27 2023 auth_token_generate = DISABLED
Sun Aug 13 11:38:27 2023 auth_token_lifetime = 0
Sun Aug 13 11:38:27 2023 auth_token_secret_file = '[UNDEF]'
Sun Aug 13 11:38:27 2023 vlan_tagging = DISABLED
Sun Aug 13 11:38:27 2023 vlan_accept = all
Sun Aug 13 11:38:27 2023 vlan_pvid = 1
Sun Aug 13 11:38:27 2023 client = ENABLED
Sun Aug 13 11:38:27 2023 pull = ENABLED
Sun Aug 13 11:38:27 2023 auth_user_pass_file = 'login.conf'
Sun Aug 13 11:38:27 2023 show_net_up = DISABLED
Sun Aug 13 11:38:27 2023 route_method = 3
Sun Aug 13 11:38:27 2023 block_outside_dns = DISABLED
Sun Aug 13 11:38:27 2023 ip_win32_defined = DISABLED
Sun Aug 13 11:38:27 2023 ip_win32_type = 3
Sun Aug 13 11:38:27 2023 dhcp_masq_offset = 0
Sun Aug 13 11:38:27 2023 dhcp_lease_time = 31536000
Sun Aug 13 11:38:27 2023 tap_sleep = 0
Sun Aug 13 11:38:27 2023 dhcp_options = 0x00000000
Sun Aug 13 11:38:27 2023 dhcp_renew = DISABLED
Sun Aug 13 11:38:27 2023 dhcp_pre_release = DISABLED
Sun Aug 13 11:38:27 2023 domain = '[UNDEF]'
Sun Aug 13 11:38:27 2023 netbios_scope = '[UNDEF]'
Sun Aug 13 11:38:27 2023 netbios_node_type = 0
Sun Aug 13 11:38:27 2023 disable_nbt = DISABLED
Sun Aug 13 11:38:27 2023 OpenVPN 2.6.5 [git:v2.6.5/cbc9e0ce412e7b42] Windows-MSVC [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] [DCO] built on Jun 13 2023
Sun Aug 13 11:38:27 2023 Windows version 10.0 (Windows 10 or greater), amd64 executable
Sun Aug 13 11:38:27 2023 library versions: OpenSSL 3.1.1 30 May 2023, LZO 2.10
Sun Aug 13 11:38:27 2023 DCO version: v0
Sun Aug 13 11:38:27 2023 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25342
Sun Aug 13 11:38:27 2023 Need hold release from management interface, waiting...
Sun Aug 13 11:38:27 2023 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:1942
Sun Aug 13 11:38:27 2023 MANAGEMENT: CMD 'state on'
Sun Aug 13 11:38:27 2023 MANAGEMENT: CMD 'log on all'
Sun Aug 13 11:38:27 2023 MANAGEMENT: CMD 'echo on all'
Sun Aug 13 11:38:27 2023 MANAGEMENT: CMD 'bytecount 5'
Sun Aug 13 11:38:27 2023 MANAGEMENT: CMD 'state'
Sun Aug 13 11:38:27 2023 MANAGEMENT: CMD 'hold off'
Sun Aug 13 11:38:27 2023 MANAGEMENT: CMD 'hold release'
Sun Aug 13 11:38:27 2023 MANAGEMENT: CMD 'password [...]'
Sun Aug 13 11:38:27 2023 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 ]
Sun Aug 13 11:38:27 2023 MANAGEMENT: >STATE:1691919507,RESOLVE,,,,,,
Sun Aug 13 11:38:28 2023 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 ]
Sun Aug 13 11:38:28 2023 TCP/UDP: Preserving recently used remote address: [AF_INET]yy.yy.yy.yy:1194
Sun Aug 13 11:38:28 2023 Socket Buffers: R=[65536->65536] S=[65536->65536]
Sun Aug 13 11:38:28 2023 UDPv4 link local: (not bound)
Sun Aug 13 11:38:28 2023 UDPv4 link remote: [AF_INET]yy.yy.yy.yy:1194
Sun Aug 13 11:38:28 2023 MANAGEMENT: >STATE:1691919508,WAIT,,,,,,
Sun Aug 13 11:38:28 2023 MANAGEMENT: >STATE:1691919508,AUTH,,,,,,
Sun Aug 13 11:38:28 2023 TLS: Initial packet from [AF_INET]yy.yy.yy.yy:1194, sid=8327c1fb bbf601a3
Sun Aug 13 11:38:29 2023 VERIFY OK: depth=1, C=PL, O=DST Sp. z O.O., CN=xxx.xxx.xxx.xxx
Sun Aug 13 11:38:29 2023 VERIFY KU OK
Sun Aug 13 11:38:29 2023 Validating certificate extended key usage
Sun Aug 13 11:38:29 2023 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sun Aug 13 11:38:29 2023 VERIFY EKU OK
Sun Aug 13 11:38:29 2023 VERIFY OK: depth=0, C=PL, O=DST Sp. z O.O., CN=.xxx.xxx.xxx.xxx
Sun Aug 13 11:38:30 2023 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, peer certificate: 4096 bit RSA, signature: RSA-SHA256
Sun Aug 13 11:38:30 2023 [.xxx.xxx.xxx.xxx] Peer Connection Initiated with [AF_INET]yy.yy.yy.yy:1194
Sun Aug 13 11:38:30 2023 TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
Sun Aug 13 11:38:30 2023 TLS: tls_multi_process: initial untrusted session promoted to trusted
Sun Aug 13 11:38:31 2023 MANAGEMENT: >STATE:1691919511,GET_CONFIG,,,,,,
Sun Aug 13 11:38:31 2023 SENT CONTROL [.xxx.xxx.xxx.xxx]: 'PUSH_REQUEST' (status=1)
Sun Aug 13 11:38:31 2023 PUSH: Received control message: 'PUSH_REPLY,inactive 7200,ping 20,ping-restart 60,topology subnet,route-gateway 172.18.0.1,ifconfig 172.18.0.5 255.255.255.0,peer-id 11'
Sun Aug 13 11:38:31 2023 OPTIONS IMPORT: --ifconfig/up options modified
Sun Aug 13 11:38:31 2023 OPTIONS IMPORT: route-related options modified
Sun Aug 13 11:38:31 2023 Using peer cipher 'AES-256-CBC'
Sun Aug 13 11:38:31 2023 interactive service msg_channel=592
Sun Aug 13 11:38:31 2023 open_tun
Sun Aug 13 11:38:31 2023 tap-windows6 device [OpenVPN TAP-Windows6] opened
Sun Aug 13 11:38:31 2023 TAP-Windows Driver Version 9.24
Sun Aug 13 11:38:31 2023 TAP-Windows MTU=1500
Sun Aug 13 11:38:31 2023 Set TAP-Windows TUN subnet mode network/local/netmask = 172.18.0.0/172.18.0.5/255.255.255.0 [SUCCEEDED]
Sun Aug 13 11:38:31 2023 Notified TAP-Windows driver to set a DHCP IP/netmask of 172.18.0.5/255.255.255.0 on interface {AAA704B5-0AFB-4B0B-9F21-EE79D431A795} [DHCP-serv: 172.18.0.0, lease-time: 31536000]
Sun Aug 13 11:38:31 2023 Successful ARP Flush on interface [27] {AAA704B5-0AFB-4B0B-9F21-EE79D431A795}
Sun Aug 13 11:38:31 2023 do_ifconfig, ipv4=1, ipv6=0
Sun Aug 13 11:38:31 2023 MANAGEMENT: >STATE:1691919511,ASSIGN_IP,,172.18.0.5,,,,
Sun Aug 13 11:38:31 2023 IPv4 MTU set to 1500 on interface 27 using service
Sun Aug 13 11:38:31 2023 Data Channel MTU parms [ mss_fix:1379 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
Sun Aug 13 11:38:31 2023 Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Sun Aug 13 11:38:31 2023 Outgoing Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Sun Aug 13 11:38:31 2023 Incoming Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Sun Aug 13 11:38:31 2023 Incoming Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Sun Aug 13 11:38:31 2023 Data Channel: cipher 'AES-256-CBC', auth 'SHA1', peer-id: 11
Sun Aug 13 11:38:31 2023 Timers: ping 20, ping-restart 60, inactive 7200
Sun Aug 13 11:38:36 2023 TEST ROUTES: 1/1 succeeded len=1 ret=1 a=0 u/d=up
Sun Aug 13 11:38:36 2023 MANAGEMENT: >STATE:1691919516,ADD_ROUTES,,,,,,
Sun Aug 13 11:38:36 2023 C:\WINDOWS\system32\route.exe ADD 10.1.1.0 MASK 255.255.255.0 172.18.0.1
Sun Aug 13 11:38:36 2023 Route addition via service succeeded
Sun Aug 13 11:38:36 2023 Initialization Sequence Completed
Sun Aug 13 11:38:36 2023 MANAGEMENT: >STATE:1691919516,CONNECTED,SUCCESS,172.18.0.5,yy.yy.yy.yy,1194,,
Sun Aug 13 11:39:04 2023 TCP/UDP: Closing socket
Sun Aug 13 11:39:04 2023 SIGUSR1[soft,remote-exit] received, process restarting
Sun Aug 13 11:39:04 2023 MANAGEMENT: >STATE:1691919544,RECONNECTING,remote-exit,,,,,
Sun Aug 13 11:39:04 2023 Restart pause, 1 second(s)
Sun Aug 13 11:39:05 2023 Re-using SSL/TLS context
Sun Aug 13 11:39:05 2023 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 ]
Sun Aug 13 11:39:05 2023 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 ]
Sun Aug 13 11:39:05 2023 TCP/UDP: Preserving recently used remote address: [AF_INET]yy.yy.yy.yy:1194
Sun Aug 13 11:39:05 2023 Socket Buffers: R=[65536->65536] S=[65536->65536]
Sun Aug 13 11:39:05 2023 UDPv4 link local: (not bound)
Sun Aug 13 11:39:05 2023 UDPv4 link remote: [AF_INET]yy.yy.yy.yy:1194
Sun Aug 13 11:39:05 2023 MANAGEMENT: >STATE:1691919545,WAIT,,,,,,
Sun Aug 13 11:39:05 2023 MANAGEMENT: >STATE:1691919545,AUTH,,,,,,
Sun Aug 13 11:39:05 2023 TLS: Initial packet from [AF_INET]yy.yy.yy.yy:1194, sid=df365a06 1f006f3b
Sun Aug 13 11:39:07 2023 VERIFY OK: depth=1, C=PL, O=DST Sp. z O.O., CN=xxx.xxx.xxx.xxx
Sun Aug 13 11:39:07 2023 VERIFY KU OK
Sun Aug 13 11:39:07 2023 Validating certificate extended key usage
Sun Aug 13 11:39:07 2023 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sun Aug 13 11:39:07 2023 VERIFY EKU OK
Sun Aug 13 11:39:07 2023 VERIFY OK: depth=0, C=PL, O=DST Sp. z O.O., CN=.xxx.xxx.xxx.xxx
Sun Aug 13 11:39:07 2023 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, peer certificate: 4096 bit RSA, signature: RSA-SHA256
Sun Aug 13 11:39:07 2023 [.xxx.xxx.xxx.xxx] Peer Connection Initiated with [AF_INET]yy.yy.yy.yy:1194
Sun Aug 13 11:39:07 2023 TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
Sun Aug 13 11:39:07 2023 TLS: tls_multi_process: initial untrusted session promoted to trusted
Sun Aug 13 11:39:08 2023 Key [AF_INET]yy.yy.yy.yy:1194 [0] not initialized (yet), dropping packet.
Sun Aug 13 11:39:08 2023 MANAGEMENT: >STATE:1691919548,GET_CONFIG,,,,,,
Sun Aug 13 11:39:08 2023 SENT CONTROL [.xxx.xxx.xxx.xxx]: 'PUSH_REQUEST' (status=1)
Sun Aug 13 11:39:08 2023 PUSH: Received control message: 'PUSH_REPLY,inactive 7200,ping 20,ping-restart 60,topology subnet,route-gateway 172.18.0.1,ifconfig 172.18.0.5 255.255.255.0,peer-id 11'
Sun Aug 13 11:39:08 2023 OPTIONS IMPORT: --ifconfig/up options modified
Sun Aug 13 11:39:08 2023 OPTIONS IMPORT: route-related options modified
Sun Aug 13 11:39:08 2023 Using peer cipher 'AES-256-CBC'
Sun Aug 13 11:39:08 2023 Preserving previous TUN/TAP instance: OpenVPN TAP-Windows6
Sun Aug 13 11:39:08 2023 Data Channel MTU parms [ mss_fix:1379 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
Sun Aug 13 11:39:08 2023 Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Sun Aug 13 11:39:08 2023 Outgoing Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Sun Aug 13 11:39:08 2023 Incoming Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Sun Aug 13 11:39:08 2023 Incoming Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Sun Aug 13 11:39:08 2023 Initialization Sequence Completed
Sun Aug 13 11:39:08 2023 MANAGEMENT: >STATE:1691919548,CONNECTED,SUCCESS,172.18.0.5,yy.yy.yy.yy,1194,,
Sun Aug 13 11:39:08 2023 Data Channel: cipher 'AES-256-CBC', auth 'SHA1', peer-id: 11
Sun Aug 13 11:39:08 2023 Timers: ping 20, ping-restart 60, inactive 7200
Sun Aug 13 11:49:16 2023 TCP/UDP: Closing socket
Sun Aug 13 11:49:16 2023 SIGUSR1[soft,remote-exit] received, process restarting
Sun Aug 13 11:49:16 2023 MANAGEMENT: >STATE:1691920156,RECONNECTING,remote-exit,,,,,
Sun Aug 13 11:49:16 2023 Restart pause, 1 second(s)
Sun Aug 13 11:49:17 2023 Re-using SSL/TLS context
Sun Aug 13 11:49:17 2023 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 ]
Sun Aug 13 11:49:17 2023 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 ]
Sun Aug 13 11:49:17 2023 TCP/UDP: Preserving recently used remote address: [AF_INET]yy.yy.yy.yy:1194
Sun Aug 13 11:49:17 2023 Socket Buffers: R=[65536->65536] S=[65536->65536]
Sun Aug 13 11:49:17 2023 UDPv4 link local: (not bound)
Sun Aug 13 11:49:17 2023 UDPv4 link remote: [AF_INET]yy.yy.yy.yy:1194
Sun Aug 13 11:49:17 2023 MANAGEMENT: >STATE:1691920157,WAIT,,,,,,
Sun Aug 13 11:49:18 2023 MANAGEMENT: >STATE:1691920158,AUTH,,,,,,
Sun Aug 13 11:49:18 2023 TLS: Initial packet from [AF_INET]yy.yy.yy.yy:1194, sid=c6f686c3 593aff7f
Sun Aug 13 11:49:19 2023 VERIFY OK: depth=1, C=PL, O=DST Sp. z O.O., CN=xxx.xxx.xxx.xxx
Sun Aug 13 11:49:19 2023 VERIFY KU OK
Sun Aug 13 11:49:19 2023 Validating certificate extended key usage
Sun Aug 13 11:49:19 2023 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sun Aug 13 11:49:19 2023 VERIFY EKU OK
Sun Aug 13 11:49:19 2023 VERIFY OK: depth=0, C=PL, O=DST Sp. z O.O., CN=.xxx.xxx.xxx.xxx
Sun Aug 13 11:49:19 2023 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, peer certificate: 4096 bit RSA, signature: RSA-SHA256
Sun Aug 13 11:49:19 2023 [.xxx.xxx.xxx.xxx] Peer Connection Initiated with [AF_INET]yy.yy.yy.yy:1194
Sun Aug 13 11:49:19 2023 TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
Sun Aug 13 11:49:19 2023 TLS: tls_multi_process: initial untrusted session promoted to trusted
Sun Aug 13 11:49:21 2023 MANAGEMENT: >STATE:1691920161,GET_CONFIG,,,,,,
Sun Aug 13 11:49:21 2023 SENT CONTROL [.xxx.xxx.xxx.xxx]: 'PUSH_REQUEST' (status=1)
Sun Aug 13 11:49:21 2023 PUSH: Received control message: 'PUSH_REPLY,inactive 7200,ping 20,ping-restart 60,topology subnet,route-gateway 172.18.0.1,ifconfig 172.18.0.5 255.255.255.0,peer-id 11'
Sun Aug 13 11:49:21 2023 OPTIONS IMPORT: --ifconfig/up options modified
Sun Aug 13 11:49:21 2023 OPTIONS IMPORT: route-related options modified
Sun Aug 13 11:49:21 2023 Using peer cipher 'AES-256-CBC'
Sun Aug 13 11:49:21 2023 Preserving previous TUN/TAP instance: OpenVPN TAP-Windows6
Sun Aug 13 11:49:21 2023 Data Channel MTU parms [ mss_fix:1379 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
Sun Aug 13 11:49:21 2023 Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Sun Aug 13 11:49:21 2023 Outgoing Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Sun Aug 13 11:49:21 2023 Incoming Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Sun Aug 13 11:49:21 2023 Incoming Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Sun Aug 13 11:49:21 2023 Initialization Sequence Completed
Sun Aug 13 11:49:21 2023 MANAGEMENT: >STATE:1691920161,CONNECTED,SUCCESS,172.18.0.5,yy.yy.yy.yy,1194,,
Sun Aug 13 11:49:21 2023 Data Channel: cipher 'AES-256-CBC', auth 'SHA1', peer-id: 11
Sun Aug 13 11:49:21 2023 Timers: ping 20, ping-restart 60, inactive 7200
Sun Aug 13 11:59:17 2023 TCP/UDP: Closing socket
Sun Aug 13 11:59:17 2023 SIGUSR1[soft,remote-exit] received, process restarting
Sun Aug 13 11:59:17 2023 MANAGEMENT: >STATE:1691920757,RECONNECTING,remote-exit,,,,,
Sun Aug 13 11:59:17 2023 Restart pause, 1 second(s)
Sun Aug 13 11:59:18 2023 Re-using SSL/TLS context
Sun Aug 13 11:59:18 2023 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 ]
Sun Aug 13 11:59:18 2023 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 ]
Sun Aug 13 11:59:18 2023 TCP/UDP: Preserving recently used remote address: [AF_INET]yy.yy.yy.yy:1194
Sun Aug 13 11:59:18 2023 Socket Buffers: R=[65536->65536] S=[65536->65536]
Sun Aug 13 11:59:18 2023 UDPv4 link local: (not bound)
Sun Aug 13 11:59:18 2023 UDPv4 link remote: [AF_INET]yy.yy.yy.yy:1194
Sun Aug 13 11:59:18 2023 MANAGEMENT: >STATE:1691920758,WAIT,,,,,,
Sun Aug 13 11:59:18 2023 MANAGEMENT: >STATE:1691920758,AUTH,,,,,,
Sun Aug 13 11:59:18 2023 TLS: Initial packet from [AF_INET]yy.yy.yy.yy:1194, sid=e4eea035 2b056d46
Sun Aug 13 11:59:20 2023 VERIFY OK: depth=1, C=PL, O=DST Sp. z O.O., CN=xxx.xxx.xxx.xxx
Sun Aug 13 11:59:20 2023 VERIFY KU OK
Sun Aug 13 11:59:20 2023 Validating certificate extended key usage
Sun Aug 13 11:59:20 2023 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sun Aug 13 11:59:20 2023 VERIFY EKU OK
Sun Aug 13 11:59:20 2023 VERIFY OK: depth=0, C=PL, O=DST Sp. z O.O., CN=.xxx.xxx.xxx.xxx
Sun Aug 13 11:59:20 2023 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, peer certificate: 4096 bit RSA, signature: RSA-SHA256
Sun Aug 13 11:59:20 2023 [.xxx.xxx.xxx.xxx] Peer Connection Initiated with [AF_INET]yy.yy.yy.yy:1194
Sun Aug 13 11:59:20 2023 TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
Sun Aug 13 11:59:20 2023 TLS: tls_multi_process: initial untrusted session promoted to trusted
Sun Aug 13 11:59:21 2023 MANAGEMENT: >STATE:1691920761,GET_CONFIG,,,,,,
Sun Aug 13 11:59:21 2023 SENT CONTROL [.xxx.xxx.xxx.xxx]: 'PUSH_REQUEST' (status=1)
Sun Aug 13 11:59:22 2023 PUSH: Received control message: 'PUSH_REPLY,inactive 7200,ping 20,ping-restart 60,topology subnet,route-gateway 172.18.0.1,ifconfig 172.18.0.5 255.255.255.0,peer-id 11'
Sun Aug 13 11:59:22 2023 OPTIONS IMPORT: --ifconfig/up options modified
Sun Aug 13 11:59:22 2023 OPTIONS IMPORT: route-related options modified
Sun Aug 13 11:59:22 2023 Using peer cipher 'AES-256-CBC'
Sun Aug 13 11:59:22 2023 Preserving previous TUN/TAP instance: OpenVPN TAP-Windows6
Sun Aug 13 11:59:22 2023 Data Channel MTU parms [ mss_fix:1379 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
Sun Aug 13 11:59:22 2023 Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Sun Aug 13 11:59:22 2023 Outgoing Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Sun Aug 13 11:59:22 2023 Incoming Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Sun Aug 13 11:59:22 2023 Incoming Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Sun Aug 13 11:59:22 2023 Initialization Sequence Completed
Sun Aug 13 11:59:22 2023 MANAGEMENT: >STATE:1691920762,CONNECTED,SUCCESS,172.18.0.5,yy.yy.yy.yy,1194,,
Sun Aug 13 11:59:22 2023 Data Channel: cipher 'AES-256-CBC', auth 'SHA1', peer-id: 11
Sun Aug 13 11:59:22 2023 Timers: ping 20, ping-restart 60, inactive 7200

[schwabe]

@cron2 we only log remote-exit when we receive a OCC_EXIT or the control channel EXIT message. So that we log this, is for a me a pretty strong indication that the server is sending that. Maybe some server that gets a SIGHUP every ten minutes or something via cron job?

https://github.com/search?q=repo%3AOpenVPN%2Fopenvpn%20remote-exit&type=code

With verb 7 the log event should be visible:

    dmsg(D_STREAM_ERRORS, "Exit message received by peer");

[thyxNY]

With verb=7

15:45:43 first connecting OpenVPN
15:47:00 I run RDP connection to WindowsServer 2012R2, OpenVPN disconnecting and connecting again, RDP working fine (and 10 minutes will be worked fine)
15:57:00 OpenVPN disconnecting and connecting again
...

mylog.zip

[selvanair]

dmsg() requires ENABLE_DEBUG but we probably do not have it on by default in MSVC builds (unlike cross-compile)?. So, verb=7 is not super useful here except that it shows data is flowing right until the restart.

Strangely, the first restart happens soon after connection is established and user starts RDP. And then repeated at 10 minute intervals. As its i "remote-exit" in all cases, some script on the server may be doing this, the first of which somehow triggers at "zero" minutes. I think you need to look at the server setup and logs.

[cron2]

@schwabe, @selvanair I see what you mean - the OCC_EXIT in occ.c logs with

src/openvpn/occ.c-        case OCC_EXIT:
src/openvpn/occ.c-            dmsg(D_PACKET_CONTENT, "RECEIVED OCC_EXIT");
src/openvpn/occ.c:            register_signal(c->sig, SIGUSR1, "remote-exit");
src/openvpn/occ.c-            break;

which might not end up somewhere useful. Shall we change this to "about the same" as for the CC-EEN, maybe pointing out that this was OCC

    dmsg(D_STREAM_ERRORS, "OCC exit message received by peer");

?

[thyxNY]

Strangely, the first restart happens soon after connection is established and user starts RDP. And then repeated at 10 minute intervals. As its i "remote-exit" in all cases, some script on the server may be doing this, the first of which somehow triggers at "zero" minutes. I think you need to look at the server setup and logs.

@selvanair @schwabe
I do not have access to the logs from the server. I sent a request to the admin...

The important thing is that only some employees have a problem accessing this RDP server. For some it works perfectly fine.

[schwabe]

@thyxNY yes. But the logs show no problems on the client side. The disconnecct is triggered by the server side.

[cron2]

    dmsg(D_STREAM_ERRORS, "OCC exit message received by peer");

This has been implemented today and will be part of the upcoming 2.6.6 release (tomorrow-ish). It will not fix the actual problem here, but helps diagnostics.

commit 6e68d8c
Author: Gert Doering gert@greenie.muc.de
Date: Mon Aug 14 08:04:09 2023 +0200

Make received OCC exit messages more visible in log.

Currently, OCC exit messages are only logged at some high debug level
(and if OpenVPN compiled with DEBUG), while control-channel EEN messages
are logged on verb 1.  Make this consistent, both in wording and in
log level.

[thyxNY]

@cron2 I can install the beta software, set the verb variable and give you the current infolog...

[schwabe]

@thyxNY that will just make the issue more obvious but will not give us any better/new information. You need the server side to diagnose what is going on here.

[selvanair]

@thyxNY Is the VPN server same as the RDP server or are you always connected to the same VPN and different RDP servers, one of which causes this issue? I guess the latter as you mention "company" VPN and "data centre" RDP servers. Is RDP tunneled through the VPN connection or in clear? If no RDP session is active, I suppose the VPN stays up for long with no such periodic disconnects, does it?

Although the disconnection does appear to be initiated by the server, its bizarre that RDP to an independent server could have anything to do with it.

[thyxNY]

@selvanair Yes, connecting to only one server causes this problem. We have no problems with connecting to other servers (neither me nor other employees, 10 minutes/hours/... and all is OK). OpenVPN client disconnection only occurs when trying to connect to terminal server on Windows2012R2.

Is the VPN server same as the RDP server or are you always connected to the same VPN and different RDP servers, one of which causes this issue? I guess the latter as you mention "company" VPN and "data centre" RDP servers.

One VPN Server, then connecting to different servers (or different remote desktop services).

Is RDP tunneled through the VPN connection or in clear?

Yes, RDP connection goes through the VPN connection.

If no RDP session is active, I suppose the VPN stays up for long with no such periodic disconnects, does it?

Yes.

Although the disconnection does appear to be initiated by the server, its bizarre that RDP to an independent server could have anything to do with it.

Yes :-(

[ocafebabe]

@thyxNY Have you ever found a solution to this issue?