[Openvpn-users] Windows 10 sleep and TAP driver problem

[debbie10t]

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

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

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

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

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,
emailAddress=***@gmail.com
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

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

[Gert Doering]

Hi,

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

This part of the communication is totally outside the tap driver.

gert