openvpn icon indicating copy to clipboard operation
openvpn copied to clipboard
verified publisher icon OpenVPN

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

Open thyxNY opened this issue 2 years ago • 15 comments

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

thyxNY avatar Aug 12 '23 21:08 thyxNY

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?

schwabe avatar Aug 13 '23 02:08 schwabe

@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.

cron2 avatar Aug 13 '23 06:08 cron2

@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

thyxNY avatar Aug 13 '23 10:08 thyxNY

@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");

schwabe avatar Aug 13 '23 12:08 schwabe

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

thyxNY avatar Aug 13 '23 14:08 thyxNY

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.

selvanair avatar Aug 13 '23 17:08 selvanair

@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");

?

cron2 avatar Aug 13 '23 18:08 cron2

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.

thyxNY avatar Aug 14 '23 05:08 thyxNY

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

schwabe avatar Aug 14 '23 10:08 schwabe 

    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 6e68d8c5d5304d56de588f4584e2dc6266d2f129 Author: Gert Doering [email protected] 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.

cron2 avatar Aug 14 '23 13:08 cron2

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

thyxNY avatar Aug 14 '23 16:08 thyxNY

@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.

schwabe avatar Aug 14 '23 16:08 schwabe

@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.

selvanair avatar Aug 14 '23 16:08 selvanair

@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 :-(

thyxNY avatar Aug 14 '23 16:08 thyxNY

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

ocafebabe avatar Feb 28 '24 00:02 ocafebabe