When --disable is set for a client, the server never replies to the client.

[Eric Crist]

Using the shell script below as a client-connect script, when client1 attempts to connect, the server identifies the client as disabled, and registers such in the log, but never passes an AUTH_FAIL or other message back to the client. The end result is the client repeatedly sends the PUSH_REQUEST to the server, appearing to hang.

#!/bin/sh

if [ "$common_name" = "client1" ];
then
	echo "disable" >> $1
fi

exit 0

Server Log:

Mon Mar  2 20:02:33 2015 us=906686 client1/70.57.158.126:1194 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_e397d76e804e937b1f1d694381546058.tmp
Mon Mar  2 20:02:33 2015 us=907455 client1/70.57.158.126:1194 MULTI: client has been rejected due to 'disable' directive
Mon Mar  2 20:02:36 2015 us=103063 client1/70.57.158.126:1194 PUSH: Received control message: 'PUSH_REQUEST'
Mon Mar  2 20:02:41 2015 us=250097 client1/70.57.158.126:1194 PUSH: Received control message: 'PUSH_REQUEST'
Mon Mar  2 20:02:46 2015 us=397011 client1/70.57.158.126:1194 PUSH: Received control message: 'PUSH_REQUEST'
Mon Mar  2 20:02:51 2015 us=469295 client1/70.57.158.126:1194 PUSH: Received control message: 'PUSH_REQUEST'
Mon Mar  2 20:02:56 2015 us=536051 client1/70.57.158.126:1194 PUSH: Received control message: 'PUSH_REQUEST'
Mon Mar  2 20:03:01 2015 us=667854 client1/70.57.158.126:1194 PUSH: Received control message: 'PUSH_REQUEST'
Mon Mar  2 20:03:06 2015 us=821454 client1/70.57.158.126:1194 PUSH: Received control message: 'PUSH_REQUEST'
Mon Mar  2 20:03:11 2015 us=873038 client1/70.57.158.126:1194 PUSH: Received control message: 'PUSH_REQUEST'
Mon Mar  2 20:03:16 2015 us=921840 client1/70.57.158.126:1194 PUSH: Received control message: 'PUSH_REQUEST'
Mon Mar  2 20:03:22 2015 us=180347 client1/70.57.158.126:1194 PUSH: Received control message: 'PUSH_REQUEST'
Mon Mar  2 20:03:27 2015 us=439044 client1/70.57.158.126:1194 PUSH: Received control message: 'PUSH_REQUEST'
Mon Mar  2 20:03:32 2015 us=710428 client1/70.57.158.126:1194 PUSH: Received control message: 'PUSH_REQUEST'

Client Log:

2015-03-02 20:03:31 UDPv4 link remote: [AF_INET]199.102.77.83:1194
2015-03-02 20:03:32 [Mastering OpenVPN Server] Peer Connection Initiated with [AF_INET]199.102.77.83:1194
2015-03-02 20:04:11 *Tunnelblick: Disconnecting; VPN Details… window disconnect button pressed
2015-03-02 20:04:11 *Tunnelblick: Disconnecting using 'kill'

[Gert Döring]

Does it also not work if you put the "disable" into a ccd/ per-client config file?

(I do that, and seem to remember it worked for me, but client-connect "should" not make a difference here...)

[Gert Döring]

Ecrist, talk to me :)

[Eric Crist]

When I use a CCD file, I get the expected auth fail. When I use the client-connect script as entered above, I get the behavior precipitating this ticket.

[Gert Döring]

There is also #180, which is open quite a while, describing a different scenario ("it works fine if the plugin disallows a connection, but hangs forever if client-connect disallows [by returning 1]"). But that could be the same issue.

[David Sommerseth]

I have looked into #180. I believe this ticket is more a true bug, not sure #180 is a bug; even though the code paths are very much related.

The check for 'disabled' can be found in multi.c:1853-1862

      if (mi->context.options.disable)
	{
	  msg (D_MULTI_ERRORS, "MULTI: client has been rejected due to 'disable' directive");
	  cc_succeeded = false;
	}

In addition to set cc_succeeded to false, cc_succeeded_count should probably also be set to 0, which will make the client state become CAS_FAILED instead of CAS_PARTIAL. With CAS_FAILED, the OpenVPN server should return AUTH_FAILED to the client.

[David Sommerseth]

Can someone please test this patch and report back? (based on git master) If this resolves the issue, I'll submit a proper patch to the -devel ML.

diff --git a/src/openvpn/multi.c b/src/openvpn/multi.c
index 7c3aaac..e999450 100644
--- a/src/openvpn/multi.c
+++ b/src/openvpn/multi.c
@@ -1858,6 +1858,7 @@ multi_connection_established (struct multi_context *m, struct multi_instance *mi
        {
          msg (D_MULTI_ERRORS, "MULTI: client has been rejected due to 'disable' directive");
          cc_succeeded = false;
+         cc_succeeded_count = 0;
        }
 
       if (cc_succeeded)

[debbie10t]

@dazo: Just tested and it worked properly for me -- Will post full details soon.

[Eric Crist]

I've verified with the 201545 source snapshot thrown in to the FreeBSD port build that this functions. The 201545 snapshot produces the behavior described in this bug. Taking that same source and applying the one code addition listed in the patch corrects the behavior and OpenVPN correctly detects the auth failure.

Thanks for identifying this dazo! Feel free to list me in the signed-off-by.

[debbie10t]

multi.c

      /*
       * Check for "disable" directive in client-config-dir file
       * or config file generated by --client-connect script.
       */
      if (mi->context.options.disable)
        {
          msg (D_MULTI_ERRORS, "MULTI: client has been rejected due to 'disable' directive");
          cc_succeeded = false;
          cc_succeeded_count = 0;
        }

Server config - client connect script:

echo "disable" > $1

Server log (relevant):

OpenVPN 2.3_git [git:master/f107c62051ebbf4a+] x86_64-unknown-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH] [IPv6] built on Nov 10 2015
library versions: OpenSSL 1.0.1k 8 Jan 2015, LZO 2.08
<..>
Tue Nov 10 13:44:24 2015 us=490403 MULTI: multi_create_instance called
Tue Nov 10 13:44:25 2015 us=507815 client.name/client.ip:2088 OPTIONS IMPORT: reading client specific options from: server/temp/openvpn_cc_3733cdd2212f98ac733f689d0a7ebba9.tmp
<..>
Tue Nov 10 13:44:25 2015 us=508036 client.name/client.ip:2088 MULTI: client has been rejected due to 'disable' directive
Tue Nov 10 13:44:27 2015 us=680390 client.name/client.ip:2088 PUSH: Received control message: 'PUSH_REQUEST'
Tue Nov 10 13:44:27 2015 us=680451 client.name/client.ip:2088 Delayed exit in 5 seconds
Tue Nov 10 13:44:27 2015 us=680489 client.name/client.ip:2088 SENT CONTROL [client.name]: 'AUTH_FAILED' (status=1)
Tue Nov 10 13:44:30 2015 us=65731 MULTI: multi_create_instance called
<..>
Tue Nov 10 13:44:30 2015 us=758503 client.ip:4202 [client.name] Peer Connection Initiated with [AF_INET]client.ip:4202
Tue Nov 10 13:44:30 2015 us=758879 MULTI: new connection by client 'client.name' will cause previous active sessions by this client to be dropped.  Remember to use the --duplicate-cn option if you want multiple clients using the same certificate or username to concurrently connect.
<..>
Tue Nov 10 13:44:30 2015 us=866302 OPTIONS IMPORT: reading client specific options from: server/temp/openvpn_cc_c669d596bdcd612a0a16ed20c3519427.tmp
Tue Nov 10 13:44:30 2015 us=866541 MULTI: client has been rejected due to 'disable' directive
Tue Nov 10 13:44:33 2015 us=60309 client.name/client.ip:4202 PUSH: Received control message: 'PUSH_REQUEST'
Tue Nov 10 13:44:33 2015 us=60391 client.name/client.ip:4202 Delayed exit in 5 seconds
Tue Nov 10 13:44:33 2015 us=60430 client.name/client.ip:4202 SENT CONTROL [client.name]: 'AUTH_FAILED' (status=1)
Tue Nov 10 13:44:35 2015 us=478521 MULTI: multi_create_instance called
<..>
Tue Nov 10 13:44:36 2015 us=143872 client.ip:1068 [client.name] Peer Connection Initiated with [AF_INET]client.ip:1068
Tue Nov 10 13:44:36 2015 us=144230 MULTI: new connection by client 'client.name' will cause previous active sessions by this client to be dropped.  Remember to use the --duplicate-cn option if you want multiple clients using the same certificate or username to concurrently connect.
<..>
Tue Nov 10 13:44:36 2015 us=251237 OPTIONS IMPORT: reading client specific options from: server/temp/openvpn_cc_dbb331ccd10feb82d8fd2f6749ef5384.tmp
Tue Nov 10 13:44:36 2015 us=251476 MULTI: client has been rejected due to 'disable' directive
Tue Nov 10 13:44:38 2015 us=428522 client.name/client.ip:1068 PUSH: Received control message: 'PUSH_REQUEST'
Tue Nov 10 13:44:38 2015 us=428584 client.name/client.ip:1068 Delayed exit in 5 seconds
Tue Nov 10 13:44:38 2015 us=428622 client.name/client.ip:1068 SENT CONTROL [client.name]: 'AUTH_FAILED' (status=1)
Tue Nov 10 13:44:43 2015 us=598124 client.name/client.ip:1068 SIGTERM[soft,delayed-exit] received, client-instance exiting

Client log (relevant):

Tue Nov 10 13:44:37 2015 us=637841 OpenVPN 2.3.8 i686-w64-mingw32 [SSL (OpenSSL)] [LZO] [PKCS11] [IPv6] built on Aug  4 2015
Tue Nov 10 13:44:37 2015 us=637841 library versions: OpenSSL 1.0.1p 9 Jul 2015, LZO 2.08

Tue Nov 10 13:44:40 2015 us=782363 [server] Peer Connection Initiated with [AF_INET]server.ip:server.port
Tue Nov 10 13:44:41 2015 us=924004 MANAGEMENT: >STATE:1447163081,GET_CONFIG,,,
Tue Nov 10 13:44:43 2015 us=45617 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Tue Nov 10 13:44:43 2015 us=65646 AUTH: Received control message: AUTH_FAILED
Tue Nov 10 13:44:43 2015 us=95689 TCP/UDP: Closing socket
Tue Nov 10 13:44:43 2015 us=105703 SIGUSR1[soft,auth-failure] received, process restarting
Tue Nov 10 13:44:43 2015 us=125732 MANAGEMENT: >STATE:1447163083,RECONNECTING,auth-failure,,
Tue Nov 10 13:44:43 2015 us=145761 Restart pause, 2 second(s)

Tue Nov 10 13:44:46 2015 us=190139 [server] Peer Connection Initiated with [AF_INET]server.ip:server.port
Tue Nov 10 13:44:47 2015 us=311751 MANAGEMENT: >STATE:1447163087,GET_CONFIG,,,
Tue Nov 10 13:44:48 2015 us=433364 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Tue Nov 10 13:44:48 2015 us=463407 AUTH: Received control message: AUTH_FAILED
Tue Nov 10 13:44:48 2015 us=483436 TCP/UDP: Closing socket
Tue Nov 10 13:44:48 2015 us=493451 SIGUSR1[soft,auth-failure] received, process restarting
Tue Nov 10 13:44:48 2015 us=493451 MANAGEMENT: >STATE:1447163088,RECONNECTING,auth-failure,,
Tue Nov 10 13:44:48 2015 us=493451 Restart pause, 2 second(s)

Tue Nov 10 13:44:51 2015 us=527814 [server] Peer Connection Initiated with [AF_INET]server.ip:server.port
Tue Nov 10 13:44:52 2015 us=669455 MANAGEMENT: >STATE:1447163092,GET_CONFIG,,,
Tue Nov 10 13:44:53 2015 us=811097 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Tue Nov 10 13:44:53 2015 us=831126 AUTH: Received control message: AUTH_FAILED
Tue Nov 10 13:44:53 2015 us=851155 TCP/UDP: Closing socket
Tue Nov 10 13:44:53 2015 us=861169 SIGTERM[soft,auth-failure] received, process exiting
Tue Nov 10 13:44:53 2015 us=871183 MANAGEMENT: >STATE:1447163093,EXITING,auth-failure,,

[David Sommerseth]

Patch submitted to the -devel ML: ​http://thread.gmane.org/gmane.network.openvpn.devel/10486

[Gert Döring]

Thanks, dazo, for chasing this down - and yes, your patch totally fixes the issue (verified by staring at the code and understanding code paths, plus having the test report from ecrist and debbie10t, of course :-) ).

I do wonder whether we should do a bit deeper surgery and throw out CAS_PARTIAL and cc_succeeeded_count totally - it does not seem to have any useful purpose as all the rest of OpenVPN does not know what to do with CAS_PARTIAL - and I think it would fix #180 nicely with it.

Since I do not understand the history of this code, I have mailed James for advice.

[Gert Döring]

commit 6c2d790ad8f10029e95aecb0d39377ef06ea8b2a (master)
commit 4b0a6f808e20f1d6d6a0b60391f053bc8ab94772 (release/2.3)

Author: David Sommerseth
Date: Wed Nov 11 14:01:39 2015 +0100

Avoid partial authentication state when using --disabled in CCD configs

so... *this* can be closed now (ecrist: care to verify against current git master, and roll a new openvpn-devel port? there's two other freebsd-specific bug fixes in there :) ), and we'll do the CAS_PARTIAL dance in #180...

David, thanks again.