Hi,

requesting some expert help because this thread could be useful to
the community if the problem can be properly diagnosed before fixing.

Ref:
https://forums.openvpn.net/viewtopic.php?f=6&t=23883

Essentially, the windows TAP driver appears to have suffered from
windows sleep problem which has caused a permanent problem.

The W10 client successfully connects but then --ping-timeout occurs
and subsequently the Linux server does not reply to PUSH_REQUEST

The most relevant log part is (client):
<q>
Tue Apr 11 20:44:02 2017 us=123252 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.14 10.8.0.13'
Tue Apr 11 20:44:02 2017 us=123252 OPTIONS IMPORT: timers and/or 
timeouts modified
Tue Apr 11 20:44:02 2017 us=123252 OPTIONS IMPORT: --ifconfig/up options 
modified
Tue Apr 11 20:44:02 2017 us=123252 OPTIONS IMPORT: route options modified
Tue Apr 11 20:44:02 2017 us=123252 Data Channel MTU parms [ L:1558 
D:1450 EF:58 EB:406 ET:0 EL:3 ]
Tue Apr 11 20:44:02 2017 us=123252 Data Channel Encrypt: Cipher 
'AES-256-CBC' initialized with 256 bit key
Tue Apr 11 20:44:02 2017 us=123252 Data Channel Encrypt: Using 160 bit 
message hash 'SHA1' for HMAC authentication
Tue Apr 11 20:44:02 2017 us=123252 Data Channel Decrypt: Cipher 
'AES-256-CBC' initialized with 256 bit key
Tue Apr 11 20:44:02 2017 us=123252 Data Channel Decrypt: Using 160 bit 
message hash 'SHA1' for HMAC authentication
Tue Apr 11 20:44:02 2017 us=123252 interactive service msg_channel=0
Tue Apr 11 20:44:02 2017 us=123252 ROUTE_GATEWAY 
192.168.86.1/255.255.255.0 I=16 HWADDR=94:de:80:b8:15:74
Tue Apr 11 20:44:02 2017 us=123252 open_tun
Tue Apr 11 20:44:02 2017 us=123252 TAP-WIN32 device [Ethernet 5] opened: 
\\.\Global\{4ABDC945-E734-415C-8B50-EE2FEAA2FA4C}.tap
Tue Apr 11 20:44:02 2017 us=123252 TAP-Windows Driver Version 9.21
Tue Apr 11 20:44:02 2017 us=123252 TAP-Windows MTU=1500
Tue Apr 11 20:44:02 2017 us=123252 Notified TAP-Windows driver to set a 
DHCP IP/netmask of 10.8.0.14/255.255.255.252 on interface 
{4ABDC945-E734-415C-8B50-EE2FEAA2FA4C} [DHCP-serv: 10.8.0.13, 
lease-time: 31536000]
Tue Apr 11 20:44:02 2017 us=123252 Successful ARP Flush on interface 
[13] {4ABDC945-E734-415C-8B50-EE2FEAA2FA4C}
Tue Apr 11 20:44:02 2017 us=123252 do_ifconfig, 
tt->did_ifconfig_ipv6_setup=0
Tue Apr 11 20:44:02 2017 us=123252 MANAGEMENT: 
 >STATE:1491957842,ASSIGN_IP,,10.8.0.14,,,,
Tue Apr 11 20:44:07 2017 us=806989 TEST ROUTES: 1/1 succeeded len=1 
ret=1 a=0 u/d=up
Tue Apr 11 20:44:07 2017 us=806989 MANAGEMENT: 
 >STATE:1491957847,ADD_ROUTES,,,,,,
Tue Apr 11 20:44:07 2017 us=806989 C:\WINDOWS\system32\route.exe ADD 
10.8.0.0 MASK 255.255.255.0 10.8.0.13
Tue Apr 11 20:44:07 2017 us=806989 ROUTE: CreateIpForwardEntry succeeded 
with dwForwardMetric1=35 and dwForwardType=4
Tue Apr 11 20:44:07 2017 us=806989 Route addition via IPAPI succeeded 
[adaptive]
Tue Apr 11 20:44:07 2017 us=806989 Initialization Sequence Completed
Tue Apr 11 20:44:07 2017 us=806989 MANAGEMENT: 
 >STATE:1491957847,CONNECTED,SUCCESS,10.8.0.14,x.x.x.x,1194,,
Tue Apr 11 20:46:57 2017 us=340199 [x.x.x] Inactivity timeout 
(--ping-restart), restarting
Tue Apr 11 20:46:57 2017 us=340199 TCP/UDP: Closing socket
Tue Apr 11 20:46:57 2017 us=340199 SIGUSR1[soft,ping-restart] received, 
process restarting
Tue Apr 11 20:46:57 2017 us=340199 MANAGEMENT: 
 >STATE:1491958017,RECONNECTING,ping-restart,,,,,
Tue Apr 11 20:46:57 2017 us=340199 Restart pause, 5 second(s)
Tue Apr 11 20:47:02 2017 us=371081 Re-using SSL/TLS context
Tue Apr 11 20:47:02 2017 us=371081 LZO compression initializing
Tue Apr 11 20:47:02 2017 us=371081 Control Channel MTU parms [ L:1622 
D:1184 EF:66 EB:0 ET:0 EL:3 ]
Tue Apr 11 20:47:02 2017 us=371081 Data Channel MTU parms [ L:1622 
D:1450 EF:122 EB:406 ET:0 EL:3 ]
Tue Apr 11 20:47:02 2017 us=371081 Local Options String (VER=V4): 
'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 
1,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-client'
Tue Apr 11 20:47:02 2017 us=371081 Expected Remote Options String 
(VER=V4): 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto 
UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA1,keysize 
256,tls-auth,key-method 2,tls-server'
Tue Apr 11 20:47:02 2017 us=371081 TCP/UDP: Preserving recently used 
remote address: [AF_INET]x.x.x.x:1194
Tue Apr 11 20:47:02 2017 us=371081 Socket Buffers: R=[65536->65536] 
S=[65536->65536]
Tue Apr 11 20:47:02 2017 us=371081 UDP link local: (not bound)
Tue Apr 11 20:47:02 2017 us=371081 UDP link remote: [AF_INET]x.x.x.x:1194
Tue Apr 11 20:47:02 2017 us=371081 MANAGEMENT: >STATE:1491958022,WAIT,,,,,,
Tue Apr 11 20:47:02 2017 us=386710 MANAGEMENT: >STATE:1491958022,AUTH,,,,,,
Tue Apr 11 20:47:02 2017 us=386710 TLS: Initial packet from 
[AF_INET]x.x.x.x:1194, sid=c18607a1 c87bd102
Tue Apr 11 20:47:02 2017 us=677110 VERIFY OK: depth=2, C=US, O=xxx, 
CN=Root CA
Tue Apr 11 20:47:02 2017 us=677110 VERIFY OK: depth=1, C=US, O=xxx, 
CN=Sub CA
Tue Apr 11 20:47:02 2017 us=677110 VERIFY KU OK
Tue Apr 11 20:47:02 2017 us=677110 Validating certificate extended key usage
Tue Apr 11 20:47:02 2017 us=677110 ++ Certificate has EKU (str) TLS Web 
Client Authentication, expects TLS Web Server Authentication
Tue Apr 11 20:47:02 2017 us=677110 ++ Certificate has EKU (oid) 
1.3.6.1.5.5.7.3.2, expects TLS Web Server Authentication
Tue Apr 11 20:47:02 2017 us=677110 ++ Certificate has EKU (str) TLS Web 
Server Authentication, expects TLS Web Server Authentication
Tue Apr 11 20:47:02 2017 us=677110 VERIFY EKU OK
Tue Apr 11 20:47:02 2017 us=677110 VERIFY OK: depth=0, C=US, ST=New 
York, O=xxx, OU=Water Street Brewing Co., CN=x.x.x, 
[email protected]
Tue Apr 11 20:47:02 2017 us=833356 Control Channel: TLSv1, cipher 
TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Tue Apr 11 20:47:02 2017 us=833356 [x.x.x] Peer Connection Initiated 
with [AF_INET]x.x.x.x:1194
Tue Apr 11 20:47:04 2017 us=13137 MANAGEMENT: 
 >STATE:1491958024,GET_CONFIG,,,,,,
Tue Apr 11 20:47:04 2017 us=13137 SENT CONTROL [x.x.x]: 'PUSH_REQUEST' 
(status=1)
Tue Apr 11 20:47:09 2017 us=367348 SENT CONTROL [x.x.x]: 'PUSH_REQUEST' 
(status=1)
Tue Apr 11 20:47:14 2017 us=915446 SENT CONTROL [x.x.x]: 'PUSH_REQUEST' 
(status=1)
Tue Apr 11 20:47:19 2017 us=332627 SENT CONTROL [x.x.x]: 'PUSH_REQUEST' 
(status=1)
Tue Apr 11 20:47:24 2017 us=748484 SENT CONTROL [x.x.x]: 'PUSH_REQUEST' 
(status=1)
Tue Apr 11 20:47:29 2017 us=541968 SENT CONTROL [x.x.x]: 'PUSH_REQUEST' 
(status=1)
Tue Apr 11 20:47:34 2017 us=799463 SENT CONTROL [x.x.x]: 'PUSH_REQUEST' 
(status=1)
Tue Apr 11 20:47:40 2017 us=123922 SENT CONTROL [x.x.x]: 'PUSH_REQUEST' 
(status=1)
Tue Apr 11 20:47:45 2017 us=294098 SENT CONTROL [x.x.x]: 'PUSH_REQUEST' 
(status=1)
Tue Apr 11 20:47:50 2017 us=318190 SENT CONTROL [x.x.x]: 'PUSH_REQUEST' 
(status=1)
Tue Apr 11 20:47:55 2017 us=477635 SENT CONTROL [x.x.x]: 'PUSH_REQUEST' 
(status=1)
Tue Apr 11 20:48:00 2017 us=612622 SENT CONTROL [x.x.x]: 'PUSH_REQUEST' 
(status=1)
Tue Apr 11 20:48:06 2017 us=19106 No reply from server after sending 12 
push requests
Tue Apr 11 20:48:06 2017 us=19106 TCP/UDP: Closing socket
Tue Apr 11 20:48:06 2017 us=19106 SIGUSR1[soft,no-push-reply] received, 
process restarting
</q>

More details can be found in the forum post and I have asked for the 
server log also.

Regards

------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
Openvpn-users mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/openvpn-users

Reply via email to