Context Navigation

← Previous Ticket
Next Ticket →

#1068 closed Bug / Defect (wontfix)

Route: Waiting for TUN/TAP interface to come up...

Reported by:	decibel83	Owned by:
Priority:	major	Milestone:
Component:	Generic / unclassified	Version:	OpenVPN 2.4.6 (Community Ed)
Severity:	Not set (select this one, unless your'e a OpenVPN developer)	Keywords:
Cc:

Description

Hi,
after updating Windows 10 to 1805 version I am not longer able to connect to my OpenVPN server using the OpenVPN client.
I am getting the Route: Waiting for TUN/TAP interface to come up... warning message, and after about 30 seconds the connection succeed but no traffic goes to the server.

What I tried to do to solve this problem:

uninstall the OpenVPN client and TAP drivers and reinstall the latest version
checked the DHCP client service
set the non-DHCP method (https://community.openvpn.net/openvpn/wiki/259-tap-win32-adapter-is-not-coming-up-initialization-sequence-completed-with-errors)
reset the network TCP/IP stack (https://community.openvpn.net/openvpn/wiki/reset-network-tcp-ip-stack)

Other clients are working good, so I don't think this is a server related problem.

Attached you can find:

My OpenVPN client configuration
My ipconfig/all output
My route print output

Attachments (4)

ipconfig.txt (3.9 KB) - added by decibel83 6 years ago.: "ipconfig /all" output
route.txt (3.0 KB) - added by decibel83 6 years ago.: "route print" output
VPN-client.ovpn (3.6 KB) - added by decibel83 6 years ago.: OpenVPN Client configuration file
openvpn-log.txt (14.9 KB) - added by decibel83 6 years ago.: OpenVPN Client log

Download all attachments as: .zip

Change History (20)

Changed 6 years ago by decibel83

Attachment:	ipconfig.txt added

"ipconfig /all" output

Changed 6 years ago by decibel83

Attachment:	route.txt added

"route print" output

Changed 6 years ago by decibel83

Attachment:	VPN-client.ovpn added

OpenVPN Client configuration file

Changed 6 years ago by decibel83

Attachment:	openvpn-log.txt added

OpenVPN Client log

comment:1 Changed 6 years ago by Selva Nair

Sounds similar to #665 and #807

As mentioned in #665, check whether dhcp media sense is off (globally or on the tap adapter): Eg., netsh interface ipv4 show global If its off enable it. Alternatively add --dhcp-renew to the client config and see if that helps.

Some other comments:
(i) Looks like you are using OpenVPN-GUI for Windows but either running with admin privileges or not running the interactive service. That is not the right way to run the GUI in 2.x releases. The interactive service is started by default by the installer (unless you stopped it), so just run the GUI without using "runas admin".

(ii) Is bridging absolutely necessary? If not use dev tun, not dev tap -- both on the server and clients

comment:2 Changed 6 years ago by decibel83

Hi.
dhcp media sense is enabled.

I tried to add dhcp-renew to the client configuration file, but it does not help: it taskes about 2 minutes to connect and after the connection I don't have the route to the server, so I cannot access to any remote resources.

Below you can find the status log of the connection.

Thu May 31 16:23:19 2018 OpenVPN 2.4.6 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Apr 26 2018
Thu May 31 16:23:19 2018 Windows version 6.2 (Windows 8 or greater) 64bit
Thu May 31 16:23:19 2018 library versions: OpenSSL 1.1.0h  27 Mar 2018, LZO 2.10
Thu May 31 16:23:19 2018 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25341
Thu May 31 16:23:19 2018 Need hold release from management interface, waiting...
Thu May 31 16:23:19 2018 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25341
Thu May 31 16:23:19 2018 MANAGEMENT: CMD 'state on'
Thu May 31 16:23:19 2018 MANAGEMENT: CMD 'log all on'
Thu May 31 16:23:19 2018 MANAGEMENT: CMD 'echo all on'
Thu May 31 16:23:19 2018 MANAGEMENT: CMD 'bytecount 5'
Thu May 31 16:23:19 2018 MANAGEMENT: CMD 'hold off'
Thu May 31 16:23:19 2018 MANAGEMENT: CMD 'hold release'
Thu May 31 16:23:19 2018 TCP/UDP: Preserving recently used remote address: [AF_INET]123.123.123.123:1194
Thu May 31 16:23:19 2018 Socket Buffers: R=[65536->65536] S=[65536->65536]
Thu May 31 16:23:19 2018 UDP link local: (not bound)
Thu May 31 16:23:19 2018 UDP link remote: [AF_INET]123.123.123.123:1194
Thu May 31 16:23:19 2018 MANAGEMENT: >STATE:1527776599,WAIT,,,,,,
Thu May 31 16:23:19 2018 MANAGEMENT: >STATE:1527776599,AUTH,,,,,,
Thu May 31 16:23:19 2018 TLS: Initial packet from [AF_INET]123.123.123.123:1194, sid=3e73470c 6313ca5b
Thu May 31 16:23:20 2018 VERIFY OK: depth=1, C=IT, ST=TN, L=City, O=Company, CN=Company Authority Certificate
Thu May 31 16:23:20 2018 VERIFY X509NAME OK: C=IT, ST=TN, L=City, O=Company, CN=vpn-VPN
Thu May 31 16:23:20 2018 VERIFY OK: depth=0, C=IT, ST=TN, L=City, O=Company, CN=vpn-VPN
Thu May 31 16:23:20 2018 Control Channel: TLSv1, cipher SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Thu May 31 16:23:20 2018 [vpn-VPN] Peer Connection Initiated with [AF_INET]123.123.123.123:1194
Thu May 31 16:23:21 2018 MANAGEMENT: >STATE:1527776601,GET_CONFIG,,,,,,
Thu May 31 16:23:21 2018 SENT CONTROL [vpn-VPN]: 'PUSH_REQUEST' (status=1)
Thu May 31 16:23:21 2018 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 192.168.181.254,dhcp-option DNS 8.8.8.8,dhcp-option WINS 192.168.181.200,dhcp-option DOMAIN aec.network,route 192.168.181.0 255.255.255.0,route-gateway 192.168.160.1,ping 10,ping-restart 120,ifconfig 192.168.160.4 255.255.255.0'
Thu May 31 16:23:21 2018 OPTIONS IMPORT: timers and/or timeouts modified
Thu May 31 16:23:21 2018 OPTIONS IMPORT: --ifconfig/up options modified
Thu May 31 16:23:21 2018 OPTIONS IMPORT: route options modified
Thu May 31 16:23:21 2018 OPTIONS IMPORT: route-related options modified
Thu May 31 16:23:21 2018 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Thu May 31 16:23:21 2018 Outgoing Data Channel: Cipher 'BF-CBC' initialized with 128 bit key
Thu May 31 16:23:21 2018 WARNING: INSECURE cipher with block size less than 128 bit (64 bit).  This allows attacks like SWEET32.  Mitigate by using a --cipher with a larger block size (e.g. AES-256-CBC).
Thu May 31 16:23:21 2018 Outgoing Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu May 31 16:23:21 2018 Incoming Data Channel: Cipher 'BF-CBC' initialized with 128 bit key
Thu May 31 16:23:21 2018 WARNING: INSECURE cipher with block size less than 128 bit (64 bit).  This allows attacks like SWEET32.  Mitigate by using a --cipher with a larger block size (e.g. AES-256-CBC).
Thu May 31 16:23:21 2018 Incoming Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu May 31 16:23:21 2018 WARNING: cipher with small block size in use, reducing reneg-bytes to 64MB to mitigate SWEET32 attacks.
Thu May 31 16:23:21 2018 interactive service msg_channel=0
Thu May 31 16:23:21 2018 ROUTE_GATEWAY 10.0.0.1/255.255.255.0 I=13 HWADDR=00:e0:4c:68:02:c6
Thu May 31 16:23:21 2018 open_tun
Thu May 31 16:23:21 2018 TAP-WIN32 device [Ethernet 5] opened: \\.\Global\{F3C4DF3F-3613-4D98-9A67-F070D8054D63}.tap
Thu May 31 16:23:21 2018 TAP-Windows Driver Version 9.21 
Thu May 31 16:23:21 2018 Notified TAP-Windows driver to set a DHCP IP/netmask of 192.168.160.4/255.255.255.0 on interface {F3C4DF3F-3613-4D98-9A67-F070D8054D63} [DHCP-serv: 192.168.160.0, lease-time: 31536000]
Thu May 31 16:23:21 2018 Successful ARP Flush on interface [33] {F3C4DF3F-3613-4D98-9A67-F070D8054D63}
Thu May 31 16:25:27 2018 WARNING: Failed to renew DHCP IP address lease on TAP-Windows adapter: Das Zeitlimit für die Semaphore wurde erreicht.   (code=121)
Thu May 31 16:25:27 2018 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Thu May 31 16:25:27 2018 MANAGEMENT: >STATE:1527776727,ASSIGN_IP,,192.168.160.4,,,,
Thu May 31 16:25:27 2018 [vpn-VPN] Inactivity timeout (--ping-restart), restarting
Thu May 31 16:25:27 2018 SIGUSR1[soft,ping-restart] received, process restarting
Thu May 31 16:25:27 2018 MANAGEMENT: >STATE:1527776727,RECONNECTING,ping-restart,,,,,
Thu May 31 16:25:27 2018 Restart pause, 5 second(s)
Thu May 31 16:25:32 2018 TCP/UDP: Preserving recently used remote address: [AF_INET]123.123.123.123:1194
Thu May 31 16:25:32 2018 Socket Buffers: R=[65536->65536] S=[65536->65536]
Thu May 31 16:25:32 2018 UDP link local: (not bound)
Thu May 31 16:25:32 2018 UDP link remote: [AF_INET]123.123.123.123:1194
Thu May 31 16:25:32 2018 MANAGEMENT: >STATE:1527776732,WAIT,,,,,,
Thu May 31 16:25:32 2018 MANAGEMENT: >STATE:1527776732,AUTH,,,,,,
Thu May 31 16:25:32 2018 TLS: Initial packet from [AF_INET]123.123.123.123:1194, sid=d18bbf31 381a60b0
Thu May 31 16:25:32 2018 VERIFY OK: depth=1, C=IT, ST=TN, L=City, O=Company, CN=Company Authority Certificate
Thu May 31 16:25:32 2018 VERIFY X509NAME OK: C=IT, ST=TN, L=City, O=Company, CN=vpn-VPN
Thu May 31 16:25:32 2018 VERIFY OK: depth=0, C=IT, ST=TN, L=City, O=Company, CN=vpn-VPN
Thu May 31 16:25:32 2018 Control Channel: TLSv1, cipher SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Thu May 31 16:25:32 2018 [vpn-VPN] Peer Connection Initiated with [AF_INET]123.123.123.123:1194
Thu May 31 16:25:34 2018 MANAGEMENT: >STATE:1527776734,GET_CONFIG,,,,,,
Thu May 31 16:25:34 2018 SENT CONTROL [vpn-VPN]: 'PUSH_REQUEST' (status=1)
Thu May 31 16:25:34 2018 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 192.168.181.254,dhcp-option DNS 8.8.8.8,dhcp-option WINS 192.168.181.200,dhcp-option DOMAIN aec.network,route 192.168.181.0 255.255.255.0,route-gateway 192.168.160.1,ping 10,ping-restart 120,ifconfig 192.168.160.4 255.255.255.0'
Thu May 31 16:25:34 2018 OPTIONS IMPORT: timers and/or timeouts modified
Thu May 31 16:25:34 2018 OPTIONS IMPORT: --ifconfig/up options modified
Thu May 31 16:25:34 2018 OPTIONS IMPORT: route options modified
Thu May 31 16:25:34 2018 OPTIONS IMPORT: route-related options modified
Thu May 31 16:25:34 2018 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Thu May 31 16:25:34 2018 Outgoing Data Channel: Cipher 'BF-CBC' initialized with 128 bit key
Thu May 31 16:25:34 2018 WARNING: INSECURE cipher with block size less than 128 bit (64 bit).  This allows attacks like SWEET32.  Mitigate by using a --cipher with a larger block size (e.g. AES-256-CBC).
Thu May 31 16:25:34 2018 Outgoing Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu May 31 16:25:34 2018 Incoming Data Channel: Cipher 'BF-CBC' initialized with 128 bit key
Thu May 31 16:25:34 2018 WARNING: INSECURE cipher with block size less than 128 bit (64 bit).  This allows attacks like SWEET32.  Mitigate by using a --cipher with a larger block size (e.g. AES-256-CBC).
Thu May 31 16:25:34 2018 Incoming Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu May 31 16:25:34 2018 WARNING: cipher with small block size in use, reducing reneg-bytes to 64MB to mitigate SWEET32 attacks.
Thu May 31 16:25:34 2018 Preserving previous TUN/TAP instance: Ethernet 5
Thu May 31 16:25:34 2018 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Thu May 31 16:25:34 2018 Initialization Sequence Completed
Thu May 31 16:25:34 2018 MANAGEMENT: >STATE:1527776734,CONNECTED,SUCCESS,192.168.160.4,123.123.123.13,1194,,

Last edited 6 years ago by decibel83 (previous) (diff)

comment:3 Changed 6 years ago by Selva Nair

Hi,

The new log is very sparse -- is this verb = 4? If not please set verb 4 in the config.

The logs show two attempts: in the first round there is this dhcp-renew error

Thu May 31 16:25:27 2018 WARNING: Failed to renew DHCP IP address lease on
TAP-Windows adapter: Das Zeitlimit für die Semaphore wurde erreicht.
(code=121)

That failure to lock the semaphore is unusual -- you probably had multiple instances of openvpn running all stuck in some ifconfig or netsh calls. Starting from a clean slate may help. In the second round, the connection completes with no errors, so its unexpected that routes are not created. Again, check whether another instance is interfering.

Anything changed in the client config other than the added dhcp-renew?

As I noted earlier it seems you are running the GUI but have stopped the interactive service or are starting the GUI as admin. Post a log with verb = 4 running the GUI as user and with interactive service started.

comment:4 Changed 6 years ago by decibel83

Thanks for your reply!

I checked and the Interactive Service is started, GUI not launched as admin, and no other OpenVPN instance running.

These are logs at verb=4:

Thu May 31 17:41:44 2018   pkcs11_protected_authentication = DISABLED
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_private_mode = 00000000
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_cert_private = DISABLED
Thu May 31 17:41:44 2018   pkcs11_pin_cache_period = -1
Thu May 31 17:41:44 2018   pkcs11_id = '[UNDEF]'
Thu May 31 17:41:44 2018   pkcs11_id_management = DISABLED
Thu May 31 17:41:44 2018   server_network = 0.0.0.0
Thu May 31 17:41:44 2018   server_netmask = 0.0.0.0
Thu May 31 17:41:44 2018   server_network_ipv6 = ::
Thu May 31 17:41:44 2018   server_netbits_ipv6 = 0
Thu May 31 17:41:44 2018   server_bridge_ip = 0.0.0.0
Thu May 31 17:41:44 2018   server_bridge_netmask = 0.0.0.0
Thu May 31 17:41:44 2018   server_bridge_pool_start = 0.0.0.0
Thu May 31 17:41:44 2018   server_bridge_pool_end = 0.0.0.0
Thu May 31 17:41:44 2018   ifconfig_pool_defined = DISABLED
Thu May 31 17:41:44 2018   ifconfig_pool_start = 0.0.0.0
Thu May 31 17:41:44 2018   ifconfig_pool_end = 0.0.0.0
Thu May 31 17:41:44 2018   ifconfig_pool_netmask = 0.0.0.0
Thu May 31 17:41:44 2018   ifconfig_pool_persist_filename = '[UNDEF]'
Thu May 31 17:41:44 2018   ifconfig_pool_persist_refresh_freq = 600
Thu May 31 17:41:44 2018   ifconfig_ipv6_pool_defined = DISABLED
Thu May 31 17:41:44 2018   ifconfig_ipv6_pool_base = ::
Thu May 31 17:41:44 2018   ifconfig_ipv6_pool_netbits = 0
Thu May 31 17:41:44 2018   n_bcast_buf = 256
Thu May 31 17:41:44 2018   tcp_queue_limit = 64
Thu May 31 17:41:44 2018   real_hash_size = 256
Thu May 31 17:41:44 2018   virtual_hash_size = 256
Thu May 31 17:41:44 2018   client_connect_script = '[UNDEF]'
Thu May 31 17:41:44 2018   learn_address_script = '[UNDEF]'
Thu May 31 17:41:44 2018   client_disconnect_script = '[UNDEF]'
Thu May 31 17:41:44 2018   client_config_dir = '[UNDEF]'
Thu May 31 17:41:44 2018   ccd_exclusive = DISABLED
Thu May 31 17:41:44 2018   tmp_dir = 'C:\Users\JOACHI~1\AppData\Local\Temp\'
Thu May 31 17:41:44 2018   push_ifconfig_defined = DISABLED
Thu May 31 17:41:44 2018   push_ifconfig_local = 0.0.0.0
Thu May 31 17:41:44 2018   push_ifconfig_remote_netmask = 0.0.0.0
Thu May 31 17:41:44 2018   push_ifconfig_ipv6_defined = DISABLED
Thu May 31 17:41:44 2018   push_ifconfig_ipv6_local = ::/0
Thu May 31 17:41:44 2018   push_ifconfig_ipv6_remote = ::
Thu May 31 17:41:44 2018   enable_c2c = DISABLED
Thu May 31 17:41:44 2018   duplicate_cn = DISABLED
Thu May 31 17:41:44 2018   cf_max = 0
Thu May 31 17:41:44 2018   cf_per = 0
Thu May 31 17:41:44 2018   max_clients = 1024
Thu May 31 17:41:44 2018   max_routes_per_client = 256
Thu May 31 17:41:44 2018   auth_user_pass_verify_script = '[UNDEF]'
Thu May 31 17:41:44 2018   auth_user_pass_verify_script_via_file = DISABLED
Thu May 31 17:41:44 2018   auth_token_generate = DISABLED
Thu May 31 17:41:44 2018   auth_token_lifetime = 0
Thu May 31 17:41:44 2018   client = ENABLED
Thu May 31 17:41:44 2018   pull = ENABLED
Thu May 31 17:41:44 2018   auth_user_pass_file = '[UNDEF]'
Thu May 31 17:41:44 2018   show_net_up = DISABLED
Thu May 31 17:41:44 2018   route_method = 3
Thu May 31 17:41:44 2018   block_outside_dns = DISABLED
Thu May 31 17:41:44 2018   ip_win32_defined = DISABLED
Thu May 31 17:41:44 2018   ip_win32_type = 3
Thu May 31 17:41:44 2018   dhcp_masq_offset = 0
Thu May 31 17:41:44 2018   dhcp_lease_time = 31536000
Thu May 31 17:41:44 2018   tap_sleep = 0
Thu May 31 17:41:44 2018   dhcp_options = DISABLED
Thu May 31 17:41:44 2018   dhcp_renew = ENABLED
Thu May 31 17:41:44 2018   dhcp_pre_release = DISABLED
Thu May 31 17:41:44 2018   domain = '[UNDEF]'
Thu May 31 17:41:44 2018   netbios_scope = '[UNDEF]'
Thu May 31 17:41:44 2018   netbios_node_type = 0
Thu May 31 17:41:44 2018   disable_nbt = DISABLED
Thu May 31 17:41:44 2018 OpenVPN 2.4.6 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Apr 26 2018
Thu May 31 17:41:44 2018 Windows version 6.2 (Windows 8 or greater) 64bit
Thu May 31 17:41:44 2018 library versions: OpenSSL 1.1.0h  27 Mar 2018, LZO 2.10
Thu May 31 17:41:44 2018 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25340
Thu May 31 17:41:44 2018 Need hold release from management interface, waiting...
Thu May 31 17:41:45 2018 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25340
Thu May 31 17:41:45 2018 MANAGEMENT: CMD 'state on'
Thu May 31 17:41:45 2018 MANAGEMENT: CMD 'log all on'
Thu May 31 17:41:45 2018 MANAGEMENT: CMD 'echo all on'
Thu May 31 17:41:45 2018 MANAGEMENT: CMD 'bytecount 5'
Thu May 31 17:41:45 2018 MANAGEMENT: CMD 'hold off'
Thu May 31 17:41:45 2018 MANAGEMENT: CMD 'hold release'
Thu May 31 17:41:45 2018 LZO compression initializing
Thu May 31 17:41:45 2018 Control Channel MTU parms [ L:1654 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Thu May 31 17:41:45 2018 Data Channel MTU parms [ L:1654 D:1450 EF:122 EB:411 ET:32 EL:3 ]
Thu May 31 17:41:45 2018 Local Options String (VER=V4): 'V4,dev-type tap,link-mtu 1574,tun-mtu 1532,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Thu May 31 17:41:45 2018 Expected Remote Options String (VER=V4): 'V4,dev-type tap,link-mtu 1574,tun-mtu 1532,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Thu May 31 17:41:45 2018 TCP/UDP: Preserving recently used remote address: [AF_INET]123.123.123.123:1194
Thu May 31 17:41:45 2018 Socket Buffers: R=[65536->65536] S=[65536->65536]
Thu May 31 17:41:45 2018 UDP link local: (not bound)
Thu May 31 17:41:45 2018 UDP link remote: [AF_INET]123.123.123.123:1194
Thu May 31 17:41:45 2018 MANAGEMENT: >STATE:1527781305,WAIT,,,,,,
Thu May 31 17:41:45 2018 MANAGEMENT: >STATE:1527781305,AUTH,,,,,,
Thu May 31 17:41:45 2018 TLS: Initial packet from [AF_INET]123.123.123.123:1194, sid=d1237245 f2ee094c
Thu May 31 17:41:45 2018 VERIFY OK: depth=1, C=IT, ST=TN, L=City, O=Company, CN=Company Authority Certificate
Thu May 31 17:41:45 2018 VERIFY X509NAME OK: C=IT, ST=TN, L=City, O=Company, CN=vpn-VPN
Thu May 31 17:41:45 2018 VERIFY OK: depth=0, C=IT, ST=TN, L=City, O=Company, CN=vpn-VPN
Thu May 31 17:41:45 2018 Control Channel: TLSv1, cipher SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Thu May 31 17:41:45 2018 [vpn-VPN] Peer Connection Initiated with [AF_INET]123.123.123.123:1194
Thu May 31 17:41:46 2018 MANAGEMENT: >STATE:1527781306,GET_CONFIG,,,,,,
Thu May 31 17:41:46 2018 SENT CONTROL [vpn-VPN]: 'PUSH_REQUEST' (status=1)
Thu May 31 17:41:46 2018 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 192.168.181.254,dhcp-option DNS 8.8.8.8,dhcp-option WINS 192.168.181.200,dhcp-option DOMAIN aec.network,route 192.168.181.0 255.255.255.0,route-gateway 192.168.160.1,ping 10,ping-restart 120,ifconfig 192.168.160.4 255.255.255.0'
Thu May 31 17:41:46 2018 OPTIONS IMPORT: timers and/or timeouts modified
Thu May 31 17:41:46 2018 OPTIONS IMPORT: --ifconfig/up options modified
Thu May 31 17:41:46 2018 OPTIONS IMPORT: route options modified
Thu May 31 17:41:46 2018 OPTIONS IMPORT: route-related options modified
Thu May 31 17:41:46 2018 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Thu May 31 17:41:46 2018 Data Channel MTU parms [ L:1574 D:1450 EF:42 EB:411 ET:32 EL:3 ]
Thu May 31 17:41:46 2018 Outgoing Data Channel: Cipher 'BF-CBC' initialized with 128 bit key
Thu May 31 17:41:46 2018 WARNING: INSECURE cipher with block size less than 128 bit (64 bit).  This allows attacks like SWEET32.  Mitigate by using a --cipher with a larger block size (e.g. AES-256-CBC).
Thu May 31 17:41:46 2018 Outgoing Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu May 31 17:41:46 2018 Incoming Data Channel: Cipher 'BF-CBC' initialized with 128 bit key
Thu May 31 17:41:46 2018 WARNING: INSECURE cipher with block size less than 128 bit (64 bit).  This allows attacks like SWEET32.  Mitigate by using a --cipher with a larger block size (e.g. AES-256-CBC).
Thu May 31 17:41:46 2018 Incoming Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu May 31 17:41:46 2018 WARNING: cipher with small block size in use, reducing reneg-bytes to 64MB to mitigate SWEET32 attacks.
Thu May 31 17:41:46 2018 interactive service msg_channel=624
Thu May 31 17:41:46 2018 ROUTE_GATEWAY 10.0.0.1/255.255.255.0 I=13 HWADDR=00:e0:4c:68:02:c6
Thu May 31 17:41:46 2018 open_tun
Thu May 31 17:41:46 2018 TAP-WIN32 device [Ethernet 5] opened: \\.\Global\{F3C4DF3F-3613-4D98-9A67-F070D8054D63}.tap
Thu May 31 17:41:46 2018 TAP-Windows Driver Version 9.21 
Thu May 31 17:41:46 2018 TAP-Windows MTU=1500
Thu May 31 17:41:46 2018 Notified TAP-Windows driver to set a DHCP IP/netmask of 192.168.160.4/255.255.255.0 on interface {F3C4DF3F-3613-4D98-9A67-F070D8054D63} [DHCP-serv: 192.168.160.0, lease-time: 31536000]
Thu May 31 17:41:46 2018 DHCP option string: 0f0b6165 632e6e65 74776f72 6b0608c0 a8b5fe08 0808082c 04c0a8b5 c8
Thu May 31 17:41:46 2018 Successful ARP Flush on interface [33] {F3C4DF3F-3613-4D98-9A67-F070D8054D63}
Thu May 31 17:43:51 2018 WARNING: Failed to renew DHCP IP address lease on TAP-Windows adapter: Das Zeitlimit für die Semaphore wurde erreicht.   (code=121)
Thu May 31 17:43:51 2018 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Thu May 31 17:43:51 2018 MANAGEMENT: >STATE:1527781431,ASSIGN_IP,,192.168.160.4,,,,
Thu May 31 17:43:51 2018 [vpn-VPN] Inactivity timeout (--ping-restart), restarting
Thu May 31 17:43:51 2018 TCP/UDP: Closing socket
Thu May 31 17:43:51 2018 SIGUSR1[soft,ping-restart] received, process restarting
Thu May 31 17:43:51 2018 MANAGEMENT: >STATE:1527781431,RECONNECTING,ping-restart,,,,,
Thu May 31 17:43:51 2018 Restart pause, 5 second(s)
Thu May 31 17:43:56 2018 Re-using SSL/TLS context
Thu May 31 17:43:56 2018 LZO compression initializing
Thu May 31 17:43:56 2018 Control Channel MTU parms [ L:1654 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Thu May 31 17:43:56 2018 Data Channel MTU parms [ L:1654 D:1450 EF:122 EB:411 ET:32 EL:3 ]
Thu May 31 17:43:56 2018 Local Options String (VER=V4): 'V4,dev-type tap,link-mtu 1574,tun-mtu 1532,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Thu May 31 17:43:56 2018 Expected Remote Options String (VER=V4): 'V4,dev-type tap,link-mtu 1574,tun-mtu 1532,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Thu May 31 17:43:56 2018 TCP/UDP: Preserving recently used remote address: [AF_INET]123.123.123.123:1194
Thu May 31 17:43:56 2018 Socket Buffers: R=[65536->65536] S=[65536->65536]
Thu May 31 17:43:56 2018 UDP link local: (not bound)
Thu May 31 17:43:56 2018 UDP link remote: [AF_INET]123.123.123.123:1194
Thu May 31 17:43:56 2018 MANAGEMENT: >STATE:1527781436,WAIT,,,,,,
Thu May 31 17:43:56 2018 MANAGEMENT: >STATE:1527781436,AUTH,,,,,,
Thu May 31 17:43:56 2018 TLS: Initial packet from [AF_INET]123.123.123.123:1194, sid=9e07fb41 aec16a83
Thu May 31 17:43:56 2018 VERIFY OK: depth=1, C=IT, ST=TN, L=City, O=Company, CN=Company Authority Certificate
Thu May 31 17:43:56 2018 VERIFY X509NAME OK: C=IT, ST=TN, L=City, O=Company, CN=vpn-VPN
Thu May 31 17:43:56 2018 VERIFY OK: depth=0, C=IT, ST=TN, L=City, O=Company, CN=vpn-VPN
Thu May 31 17:43:56 2018 Control Channel: TLSv1, cipher SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Thu May 31 17:43:56 2018 [vpn-VPN] Peer Connection Initiated with [AF_INET]123.123.123.123:1194
Thu May 31 17:43:57 2018 MANAGEMENT: >STATE:1527781437,GET_CONFIG,,,,,,
Thu May 31 17:43:57 2018 SENT CONTROL [vpn-VPN]: 'PUSH_REQUEST' (status=1)
Thu May 31 17:43:57 2018 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 192.168.181.254,dhcp-option DNS 8.8.8.8,dhcp-option WINS 192.168.181.200,dhcp-option DOMAIN aec.network,route 192.168.181.0 255.255.255.0,route-gateway 192.168.160.1,ping 10,ping-restart 120,ifconfig 192.168.160.4 255.255.255.0'
Thu May 31 17:43:57 2018 OPTIONS IMPORT: timers and/or timeouts modified
Thu May 31 17:43:57 2018 OPTIONS IMPORT: --ifconfig/up options modified
Thu May 31 17:43:57 2018 OPTIONS IMPORT: route options modified
Thu May 31 17:43:57 2018 OPTIONS IMPORT: route-related options modified
Thu May 31 17:43:57 2018 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Thu May 31 17:43:57 2018 Data Channel MTU parms [ L:1574 D:1450 EF:42 EB:411 ET:32 EL:3 ]
Thu May 31 17:43:57 2018 Outgoing Data Channel: Cipher 'BF-CBC' initialized with 128 bit key
Thu May 31 17:43:57 2018 WARNING: INSECURE cipher with block size less than 128 bit (64 bit).  This allows attacks like SWEET32.  Mitigate by using a --cipher with a larger block size (e.g. AES-256-CBC).
Thu May 31 17:43:57 2018 Outgoing Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu May 31 17:43:57 2018 Incoming Data Channel: Cipher 'BF-CBC' initialized with 128 bit key
Thu May 31 17:43:57 2018 WARNING: INSECURE cipher with block size less than 128 bit (64 bit).  This allows attacks like SWEET32.  Mitigate by using a --cipher with a larger block size (e.g. AES-256-CBC).
Thu May 31 17:43:57 2018 Incoming Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu May 31 17:43:57 2018 WARNING: cipher with small block size in use, reducing reneg-bytes to 64MB to mitigate SWEET32 attacks.
Thu May 31 17:43:57 2018 Preserving previous TUN/TAP instance: Ethernet 5
Thu May 31 17:43:57 2018 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Thu May 31 17:43:57 2018 Initialization Sequence Completed
Thu May 31 17:43:57 2018 MANAGEMENT: >STATE:1527781437,CONNECTED,SUCCESS,192.168.160.4,123.123.123.123,1194,,

The client is connected (after 2 minutes, which is very long time!) with IP 192.168.160.4, but no routes (192.168.160.0/24 and 192.168.181.0/24) are created.

Thanks!

comment:5 Changed 6 years ago by Selva Nair

As before the semaphore timeout (2 mins) causes dhcp-renew to fail. Looks like this is coming internally from Windows (not any semaphore openvpn is trying to lock). And, after a ping restart it shows no such error, nor does it show anything in the logs about ifconfig or route which is strange

Its posisble that there is a bug that shows up only when dhcp-renew times out like this. But that doesn't explain why the IP is not getting set in the first place -- should work even without dhcp renew. Also why dhcp-renew throws a semaphore timeout error.

Never seen anything like this but I never use "dev tap" so that's an unknown combination for me. Some random things to try: remove dhcp-renew and if the same error as in original post appears, do ipconfig /renew "Ethernet 5" (use the correct tap adapter name if its not Ethernet 5) from a command prompt to see whether the address does get set with that.

comment:6 Changed 6 years ago by decibel83

Thanks again!

I tried to run

ipconfig /renew "TAP-Windows Adapter V9"

and I received this message (translated from German to English):

The process failed because no adapter is in one for
this condition is permissible.

comment:7 Changed 6 years ago by decibel83

The exact error is

The operation failed as no adapter is in the state permissible for
this operation.

comment:8 Changed 6 years ago by Selva Nair

hmm.. Are you sure the adapter name is not "Ethernet 5" -- I thought the logs showed it with that name. Anyway, probably something isn't right with the TAP driver installation. Care to wipe it clean and re-install?

comment:9 Changed 6 years ago by decibel83

Yes, sorry.
I executed

ipconfig /renew "Ethernet 5"

during the connection from OpenVPN GUI and after about 2 minutes I got the error

C:\WINDOWS\system32>ipconfig /renew "Ethernet 5"

Windows-IP-Konfiguration

Beim Aktualisieren der Schnittstelle "Ethernet 5" ist folgender Fehler aufgetreten: es kann keinen Verbindung mit dem DHCP-Server hergestellt werden. Anforderung wurde wegen Zeitüberschreitung abgebrochen.

I tried to uninstall OpenVPN GUI (I verified that the adapter "Ethernet 5" was removed) and reinstalled it (then the adapter came back), tried to connect but nothing changed.

comment:10 Changed 6 years ago by Selva Nair

Not sure what uninstalling the GUI does. Make sure tap-windows is removed and re-installed.

Or at least recreate the adapter -- from an elevated command prompt navigate to the tap windows bin folder (may be C:\Program Files\Tap-Windows\bin) and do deltapall to delete all tap adapters and then addtap to create one afresh.

comment:11 follow-up: 14 Changed 6 years ago by Selva Nair

Possibly Windows 10 1805 doesn't like out tap driver at all? Anyone else seen this?

comment:12 Changed 6 years ago by decibel83

I think it's not a problem on Windows 10 1805 because I tried on another PC and it works.
But it could be a bug related to some particular configuration in the failed computer.

I don't have "TAP Driver" installed in the Windows 10 Apps because the TAP driver was installed during the OpenVPN GUI installation.

comment:13 Changed 6 years ago by decibel83

I also tried to download and install the TAP driver Installer (NDIS 6), but this did not solve the problem.

comment:14 in reply to: 11 Changed 6 years ago by tct

Replying to selvanair:

Possibly Windows 10 1805 doesn't like out tap driver at all? Anyone else seen this?

I have tested a similar --dev tap setup on Windows10 1803 client and have no issues.

Last edited 6 years ago by tct (previous) (diff)

comment:15 Changed 3 years ago by Gert Döring

Milestone:	release 2.4.6

Closing this.

Win10 1805 is old MS has brought us new and exciting new versions with new bugs. But even so, this really points at a local windows driver mishap, which should be fixable by full driver removal and re-installation. "Windows does this".

comment:16 Changed 3 years ago by Gert Döring

Resolution:	→ wontfix
Status:	new → closed

Note: See TracTickets for help on using tickets.

Download in other formats: