Need some Help Windows client wont reconnect

binderd

Hi,

i got a open VPN Client installation 2.4.8 on a Windows Server 2016 running as a Domain Controller. The Service is to connect to a Cloud PBX System for AD User Authentifikation. When i start the Client for the first time all is running fine it connect and get an IP Adress on the tap/tun interface. But if the client is loosing the connection and the open VPN client have to Reconnect it go in to an Error. in this case the client conntect link comes up but it never get an ip adress. the client stuck on sequence completed with Errors (see http://........dhcpclientserv) no i have to disable and enable the Tap adapter again, no the Client try to reconnect and it got connected and get a valid IP-Adress....

annyone got an Idea to solve this?

David

Pippin

it go in to an Error

I see no error...

Add

verb 4

to the client config and post the log here after replacing server IP.

binderd

Here are some Log outputs

Thu Nov 28 14:29:30 2019 OpenVPN 2.4.8 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Oct 31 2019
Thu Nov 28 14:29:30 2019 Windows version 6.2 (Windows 8 or greater) 64bit
Thu Nov 28 14:29:30 2019 library versions: OpenSSL 1.1.0l  10 Sep 2019, LZO 2.10
Enter Management Password:
Thu Nov 28 14:29:30 2019 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25340
Thu Nov 28 14:29:30 2019 Need hold release from management interface, waiting...
Thu Nov 28 14:29:30 2019 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25340
Thu Nov 28 14:29:30 2019 MANAGEMENT: CMD 'state on'
Thu Nov 28 14:29:30 2019 MANAGEMENT: CMD 'log all on'
Thu Nov 28 14:29:30 2019 MANAGEMENT: CMD 'echo all on'
Thu Nov 28 14:29:30 2019 MANAGEMENT: CMD 'bytecount 5'
Thu Nov 28 14:29:30 2019 MANAGEMENT: CMD 'hold off'
Thu Nov 28 14:29:30 2019 MANAGEMENT: CMD 'hold release'
Thu Nov 28 14:29:30 2019 WARNING: --ping should normally be used with --ping-restart or --ping-exit
Thu Nov 28 14:29:30 2019 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Thu Nov 28 14:29:30 2019 MANAGEMENT: >STATE:1574947770,RESOLVE,,,,,,
Thu Nov 28 14:29:30 2019 TCP/UDP: Preserving recently used remote address: [AF_INET]xx.xxx.xxx.xx:xxxx
Thu Nov 28 14:29:30 2019 Socket Buffers: R=[65536->65536] S=[65536->65536]
Thu Nov 28 14:29:30 2019 Attempting to establish TCP connection with [AF_INET]xx.xxx.xxx.xx:xxxx [nonblock]
Thu Nov 28 14:29:30 2019 MANAGEMENT: >STATE:1574947770,TCP_CONNECT,,,,,,
Thu Nov 28 14:29:31 2019 TCP connection established with [AF_INET]xx.xxx.xxx.xx:xxxx
Thu Nov 28 14:29:31 2019 Send to HTTP proxy: 'CONNECT xx.xxx.xxx.xx:xxxx HTTP/1.0'
Thu Nov 28 14:29:31 2019 Send to HTTP proxy: 'Host: xx.xxx.xxx.xx:xxxx'
Thu Nov 28 14:29:31 2019 HTTP proxy returned: 'HTTP/1.0 200 Connection Established'
Thu Nov 28 14:29:33 2019 TCP_CLIENT link local: (not bound)
Thu Nov 28 14:29:33 2019 TCP_CLIENT link remote: [AF_INET]xx.xxx.xxx.xx:xxxx
Thu Nov 28 14:29:33 2019 MANAGEMENT: >STATE:1574947773,WAIT,,,,,,
Thu Nov 28 14:29:33 2019 MANAGEMENT: >STATE:1574947773,AUTH,,,,,,
Thu Nov 28 14:29:33 2019 TLS: Initial packet from [AF_INET]xx.xxx.xxx.xx:xxxx, sid=04aebfb2 df096740
Thu Nov 28 14:29:33 2019 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Thu Nov 28 14:29:34 2019 VERIFY OK: depth=1, CN=ChangeMe
Thu Nov 28 14:29:34 2019 VERIFY OK: depth=0, CN=pbx
Thu Nov 28 14:29:34 2019 Control Channel: TLSv1.2, cipher TLSv1.2 DHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Thu Nov 28 14:29:34 2019 [pbx] Peer Connection Initiated with [AF_INET]xx.xxx.xxx.xx:xxxx
Thu Nov 28 14:29:35 2019 MANAGEMENT: >STATE:1574947775,GET_CONFIG,,,,,,
Thu Nov 28 14:29:35 2019 SENT CONTROL [pbx]: 'PUSH_REQUEST' (status=1)
Thu Nov 28 14:29:35 2019 PUSH: Received control message: 'PUSH_REPLY,route xx.xx.xx.x,topology net30,ping 10,ping-restart 60,ifconfig xx.xx.xx.x xx.xx.xx.x'
Thu Nov 28 14:29:35 2019 OPTIONS IMPORT: timers and/or timeouts modified
Thu Nov 28 14:29:35 2019 OPTIONS IMPORT: --ifconfig/up options modified
Thu Nov 28 14:29:35 2019 OPTIONS IMPORT: route options modified
Thu Nov 28 14:29:35 2019 Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Thu Nov 28 14:29:35 2019 Outgoing Data Channel: Using 256 bit message hash 'SHA256' for HMAC authentication
Thu Nov 28 14:29:35 2019 Incoming Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Thu Nov 28 14:29:35 2019 Incoming Data Channel: Using 256 bit message hash 'SHA256' for HMAC authentication
Thu Nov 28 14:29:35 2019 interactive service msg_channel=800
Thu Nov 28 14:29:35 2019 ROUTE_GATEWAY xx.xx.xx.x/xxx.xxx.xxx.xxx I=15 HWADDR=00:50:56:b1:16:a3
Thu Nov 28 14:29:35 2019 open_tun
Thu Nov 28 14:29:35 2019 TAP-WIN32 device [xxxx.xxxx] opened: \\.\Global\{CBD9E0C8-0C65-4D5A-9F8B-D89C13B97AA1}.tap
Thu Nov 28 14:29:35 2019 TAP-Windows Driver Version 9.24 
Thu Nov 28 14:29:35 2019 Notified TAP-Windows driver to set a DHCP IP/netmask of xx.xx.xx.x/xxx.xxx.xxx.xxx on interface {CBD9E0C8-0C65-4D5A-9F8B-D89C13B97AA1} [DHCP-serv: xx.xx.xx.x, lease-time: 31536000]
Thu Nov 28 14:29:35 2019 Successful ARP Flush on interface [13] {CBD9E0C8-0C65-4D5A-9F8B-D89C13B97AA1}
Thu Nov 28 14:29:35 2019 MANAGEMENT: >STATE:1574947775,ASSIGN_IP,,xx.xx.xx.x,,,,
Thu Nov 28 14:29:41 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:29:41 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:29:46 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:29:46 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:29:47 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:29:47 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:29:48 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:29:48 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:29:49 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:29:49 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:29:50 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:29:50 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:29:51 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:29:51 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:29:52 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:29:52 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:29:53 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:29:53 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:29:54 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:29:54 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:29:55 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:29:55 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:29:56 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:29:56 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:29:57 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:29:57 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:29:58 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:29:58 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:30:00 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:30:00 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:30:01 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:30:01 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:30:02 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:30:02 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:30:03 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:30:03 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:30:04 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:30:04 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:30:05 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:30:05 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:30:06 2019 TEST ROUTES: 0/0 succeeded len=-1 ret=0 a=0 u/d=down
Thu Nov 28 14:30:06 2019 Route: Waiting for TUN/TAP interface to come up...
Thu Nov 28 14:30:07 2019 TUN/TAP I/O operation aborted, restarting
Thu Nov 28 14:30:07 2019 Closing TUN/TAP interface
Thu Nov 28 14:30:07 2019 SIGHUP[soft,tun-abort] received, process restarting
Thu Nov 28 14:30:07 2019 MANAGEMENT: >STATE:1574947807,RECONNECTING,tun-abort,,,,,
Thu Nov 28 14:30:07 2019 OpenVPN 2.4.8 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Oct 31 2019
Thu Nov 28 14:30:07 2019 Windows version 6.2 (Windows 8 or greater) 64bit
Thu Nov 28 14:30:07 2019 library versions: OpenSSL 1.1.0l  10 Sep 2019, LZO 2.10
Thu Nov 28 14:30:07 2019 Restart pause, 10 second(s)
Thu Nov 28 14:30:17 2019 WARNING: --ping should normally be used with --ping-restart or --ping-exit
Thu Nov 28 14:30:17 2019 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Thu Nov 28 14:30:17 2019 MANAGEMENT: >STATE:1574947817,RESOLVE,,,,,,
Thu Nov 28 14:30:17 2019 TCP/UDP: Preserving recently used remote address: [AF_INET]xx.xxx.xxx.xx:xxxx
Thu Nov 28 14:30:17 2019 Socket Buffers: R=[65536->65536] S=[65536->65536]
Thu Nov 28 14:30:17 2019 Attempting to establish TCP connection with [AF_INET]xx.xxx.xxx.xx:xxxx [nonblock]
Thu Nov 28 14:30:17 2019 MANAGEMENT: >STATE:1574947817,TCP_CONNECT,,,,,,
Thu Nov 28 14:30:18 2019 TCP connection established with [AF_INET]xx.xxx.xxx.xx:xxxx
Thu Nov 28 14:30:18 2019 Send to HTTP proxy: 'CONNECT xx.xxx.xxx.xx:xxxx HTTP/1.0'
Thu Nov 28 14:30:18 2019 Send to HTTP proxy: 'Host: xx.xxx.xxx.xx:xxxx'
Thu Nov 28 14:30:18 2019 HTTP proxy returned: 'HTTP/1.0 200 Connection Established'
Thu Nov 28 14:30:20 2019 TCP_CLIENT link local: (not bound)
Thu Nov 28 14:30:20 2019 TCP_CLIENT link remote: [AF_INET]xx.xxx.xxx.xx:xxxx
Thu Nov 28 14:30:20 2019 MANAGEMENT: >STATE:1574947820,WAIT,,,,,,
Thu Nov 28 14:30:20 2019 MANAGEMENT: >STATE:1574947820,AUTH,,,,,,
Thu Nov 28 14:30:20 2019 TLS: Initial packet from [AF_INET]xx.xxx.xxx.xx:xxxx, sid=3e0305a2 020d90ec
Thu Nov 28 14:30:20 2019 VERIFY OK: depth=1, CN=ChangeMe
Thu Nov 28 14:30:20 2019 VERIFY OK: depth=0, CN=pbx
Thu Nov 28 14:30:20 2019 Control Channel: TLSv1.2, cipher TLSv1.2 DHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Thu Nov 28 14:30:20 2019 [pbx] Peer Connection Initiated with [AF_INET]xx.xxx.xxx.xx:xxxx
Thu Nov 28 14:30:22 2019 MANAGEMENT: >STATE:1574947822,GET_CONFIG,,,,,,
Thu Nov 28 14:30:22 2019 SENT CONTROL [pbx]: 'PUSH_REQUEST' (status=1)
Thu Nov 28 14:30:22 2019 PUSH: Received control message: 'PUSH_REPLY,route xx.xx.xx.x,topology net30,ping 10,ping-restart 60,ifconfig xx.xx.xx.x xx.xx.xx.x'
Thu Nov 28 14:30:22 2019 OPTIONS IMPORT: timers and/or timeouts modified
Thu Nov 28 14:30:22 2019 OPTIONS IMPORT: --ifconfig/up options modified
Thu Nov 28 14:30:22 2019 OPTIONS IMPORT: route options modified
Thu Nov 28 14:30:22 2019 Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Thu Nov 28 14:30:22 2019 Outgoing Data Channel: Using 256 bit message hash 'SHA256' for HMAC authentication
Thu Nov 28 14:30:22 2019 Incoming Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Thu Nov 28 14:30:22 2019 Incoming Data Channel: Using 256 bit message hash 'SHA256' for HMAC authentication
Thu Nov 28 14:30:22 2019 interactive service msg_channel=800
Thu Nov 28 14:30:22 2019 ROUTE_GATEWAY xx.xx.xx.x/xxx.xxx.xxx.xxx I=15 HWADDR=00:50:56:b1:16:a3
Thu Nov 28 14:30:22 2019 open_tun
Thu Nov 28 14:30:22 2019 TAP-WIN32 device [xxxx.xxxx] opened: \\.\Global\{CBD9E0C8-0C65-4D5A-9F8B-D89C13B97AA1}.tap
Thu Nov 28 14:30:22 2019 TAP-Windows Driver Version 9.24 
Thu Nov 28 14:30:22 2019 Notified TAP-Windows driver to set a DHCP IP/netmask of xx.xx.xx.x/xxx.xxx.xxx.xxx on interface {CBD9E0C8-0C65-4D5A-9F8B-D89C13B97AA1} [DHCP-serv: xx.xx.xx.x, lease-time: 31536000]
Thu Nov 28 14:30:22 2019 Successful ARP Flush on interface [13] {CBD9E0C8-0C65-4D5A-9F8B-D89C13B97AA1}
Thu Nov 28 14:30:22 2019 MANAGEMENT: >STATE:1574947822,ASSIGN_IP,,xx.xx.xx.x,,,,
Thu Nov 28 14:30:27 2019 TEST ROUTES: 1/1 succeeded len=1 ret=1 a=0 u/d=up
Thu Nov 28 14:30:27 2019 MANAGEMENT: >STATE:1574947827,ADD_ROUTES,,,,,,
Thu Nov 28 14:30:27 2019 C:\Windows\system32\route.exe ADD xx.xx.xx.x MASK 255.255.255.255 xx.xx.xx.x
Thu Nov 28 14:30:27 2019 Route addition via service succeeded
Thu Nov 28 14:30:27 2019 Initialization Sequence Completed
Thu Nov 28 14:30:27 2019 MANAGEMENT: >STATE:1574947827,CONNECTED,SUCCESS,xx.xx.xx.x,xx.xxx.xxx.xx,xxxx,xx.xxx.xxx.xxx,xxxxx

David

binderd

ok i test something more, the issue is only present if the server got the role of an Domain Controller....without this Role all is running fine. But i need it as an DC so anyone got an idea waths happening here?

TinCanTech

You could try --route-delay and/or --up-delay .. see the manual.

binderd wrote the issue is only present if the server got the role of an Domain Controller

Server log at verb 4 ..

All those xxx's make things a little more difficult ..