Opened 5 years ago

Closed 5 years ago

#651 closed Bug / Defect (fixed)

Wrong/Misleading error output

Reported by: hildeb Owned by:
Priority: minor Milestone: release 2.3.11
Component: Generic / unclassified Version: OpenVPN 2.3.10 (Community Ed)
Severity: Not set (select this one, unless your'e a OpenVPN developer) Keywords:
Cc: Heiko Hund, plaisthos

Description

Tue Jan 26 11:51:07 2016 OpenVPN 2.3.10 i686-w64-mingw32 [SSL (OpenSSL)] [LZO] [PKCS11]
[IPv6] built on Jan 4 2016
Tue Jan 26 11:51:07 2016 Windows version 6.1 (Windows 7)
Tue Jan 26 11:51:07 2016 library versions: OpenSSL 1.0.1q 3 Dec 2015, LZO 2.09
Tue Jan 26 11:51:07 2016 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25340
Tue Jan 26 11:51:07 2016 Need hold release from management interface, waiting...
Tue Jan 26 11:51:08 2016 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25340
Tue Jan 26 11:51:08 2016 MANAGEMENT: CMD 'state on'
Tue Jan 26 11:51:08 2016 MANAGEMENT: CMD 'log all on'
Tue Jan 26 11:51:08 2016 MANAGEMENT: CMD 'hold off'
Tue Jan 26 11:51:08 2016 MANAGEMENT: CMD 'hold release'
Tue Jan 26 11:51:18 2016 MANAGEMENT: CMD 'username "Auth" "username"'
Tue Jan 26 11:51:18 2016 MANAGEMENT: CMD 'password [...]'
Tue Jan 26 11:51:18 2016 Control Channel Authentication: tls-auth using INLINE static key
file
Tue Jan 26 11:51:18 2016 Outgoing Control Channel Authentication: Using 256 bit message
hash 'SHA256' for HMAC authentication
Tue Jan 26 11:51:18 2016 Incoming Control Channel Authentication: Using 256 bit message
hash 'SHA256' for HMAC authentication
Tue Jan 26 11:51:18 2016 Socket Buffers: R=[8192->8192] S=[64512->64512]
Tue Jan 26 11:51:18 2016 MANAGEMENT: >STATE:1453805478,RESOLVE,
Tue Jan 26 11:51:18 2016 UDPv4 link local: [undef]
Tue Jan 26 11:51:18 2016 UDPv4 link remote: [AF_INET]193.175.73.200:1194
Tue Jan 26 11:51:18 2016 MANAGEMENT: >STATE:1453805478,WAIT
,
Tue Jan 26 11:52:18 2016 TLS Error: TLS key negotiation failed to occur within 60 seconds
(check your network connectivity)
Tue Jan 26 11:52:18 2016 TLS Error: TLS handshake failed
Tue Jan 26 11:52:18 2016 SIGUSR1[soft,tls-error] received, process restarting
Tue Jan 26 11:52:18 2016 MANAGEMENT: >STATE:1453805538,RECONNECTING,tls-error
Tue Jan 26 11:52:18 2016 Restart pause, 2 second(s)
Tue Jan 26 11:52:20 2016 Socket Buffers: R=[8192->8192] S=[64512->64512]
Tue Jan 26 11:52:20 2016 UDPv4 link local: [undef]
Tue Jan 26 11:52:20 2016 UDPv4 link remote: [AF_INET]193.175.73.200:1194
Tue Jan 26 11:52:20 2016 MANAGEMENT: >STATE:1453805540,WAIT
,
Tue Jan 26 11:53:20 2016 TLS Error: TLS key negotiation failed to occur within 60 seconds
(check your network connectivity)
Tue Jan 26 11:53:20 2016 TLS Error: TLS handshake failed
Tue Jan 26 11:53:20 2016 SIGUSR1[soft,tls-error] received, process restarting
Tue Jan 26 11:53:20 2016 MANAGEMENT: >STATE:1453805600,RECONNECTING,tls-error
Tue Jan 26 11:53:20 2016 Restart pause, 2 second(s)
Tue Jan 26 11:53:22 2016 Socket Buffers: R=[8192->8192] S=[64512->64512]
Tue Jan 26 11:53:22 2016 MANAGEMENT: >STATE:1453805602,RESOLVE
,
Tue Jan 26 11:53:22 2016 Attempting to establish TCP connection with
[AF_INET]193.175.73.200:1194 [nonblock]
Tue Jan 26 11:53:22 2016 MANAGEMENT: >STATE:1453805602,TCP_CONNECT,
Tue Jan 26 11:53:32 2016 TCP: connect to [AF_INET]193.175.73.200:1194 failed, will try
again in 5 seconds: Das System hat versucht, einem Verzeichnis, das sich auf einem mit
JOIN zugeordneten Laufwerk befindet, ein Laufwerk mit SUBST zuzuordnen.
Tue Jan 26 11:53:32 2016 SIGUSR1[soft,init_instance] received, process restarting

Here you can see VPN failing to establish an UDP connect, and after that trying an TCP connection. Which also fails (since the user is behind a corporate firewall).

When the TCP connection fails (and just the TCP connection!!!), the system emits a misleading (?) error message:

"Das System hat versucht, einem Verzeichnis, das sich auf einem mit
JOIN zugeordneten Laufwerk befindet, ein Laufwerk mit SUBST zuzuordnen."

which is of course in German, since my users are German. Sorry.
I think it is "ERROR_IS_JOINED":

Error 134: ERROR_IS_JOINED: An attempt was made to use a JOIN or SUBST command on a drive that has already been joined.
or it's ERROR_IS_SUBSTED. It's really hard to tell for me, since I don't use windows.

Anyway: The error is misleading. The TCP connection could not be established. No mapping of drives is involved.

Change History (2)

comment:1 Changed 5 years ago by Gert Döring

Cc: Heiko Hund plaisthos added

funny coincidence. I was staring at *exactly* this error message myself today, and wondered what happened...

(In my case, it should have been "connection refused by foreign host", so my guess is that something mistranslates socket errors on windows - because on unix, the message is right)

Copying in socket and windows folks, in case one of them has a quick idea where to look at. Since you're seeing this in 2.3.10, it affects release/2.3 and git master (where I saw it).

comment:2 Changed 5 years ago by Gert Döring

Milestone: release 2.3.11
Resolution: fixed
Status: newclosed

commit 5f5229e41d134b659e502bb2597c711aedaf8096 (master)
commit 7107fef4adaf6d7b139270a6e33f54466fbb9b05 (release/2.3)

Author: Leonardo Basilio <leobasilio@…>
Date: Wed Feb 10 11:19:39 2016 +0100

Correctly report TCP connection timeout on windows.

Signed-off-by: Leonardo Basilio <leobasilio@…>

so, this should be fixed in the next windows snapshot the buildbot publishes, and in 2.3.11.

I'm closing this ticket for the time being - should not not work for you, please reopen.

Note: See TracTickets for help on using tickets.