client-connect/disconnect scripts execution order

antmarot

Hi

I have encountered a particular issue and would like to know if it is the expected behavior or not.

We noticed that clients on mobile data connection have their internet connection reset once a day by the mobile carrier.
This is annoying but not that much since the process is quite fast.

What it means with respect to OpenVPN is that our clients reconnect automatically once a day.
We did not set the duplicate-cn option so when a client reconnects, OpenVPN disconnects the previous entry for that common name.

My question is about the order in which things are done. We have client-connect and client-disconnect scripts configured, and most of the time the disconnect one is correctly executed before the connect script. Unfortunately the inverse execution order (connect then disconnect) happens from time to time and this messes with the logic implemented in our scripts. Note that I can confirm that even though the disconnect script is the last one to be executed, the client is still connected. Also clients have static ips assigned to make sure it's not related (eg. a disconnection from a virtual ip different than the ip given at connection).

Are we wrong to assume the client-disconnect script should always be executed before the client-connect script?
If so, is there any information our scripts could get to pair a disconnect event to its previous connect event (like a session id)?

Antoine

TinCanTech

antmarot wrote Are we wrong to assume the client-disconnect script should always be executed before the client-connect script?

Indeed so .. --client-disconnect is only executed when the server knows the client has disconnected.

UDP is a connectionless protocol so detecting client disconnect must happen through either --explicit-exit-notify (which works great if the client exits gracefully) or time outs (which do mess with script execution order if a client reconnects before the time out elapses).

My solution is some fairly funky scripting which attempts to maintain connection status independent of openvpn.

Or, if the connection status is vital to your VPN functionality, you may have to switch to using TCP.

antmarot

Thank you for your help.

Given the fact that my config specifies only one active connection per common name, I thought that OpenVPN would disconnect (at least logically) any existing connection when another connection is created. That would ensure --client-disconnect is always executed first.

TinCanTech

antmarot wrote I thought that OpenVPN would disconnect (at least logically) any existing connection when another connection is created

It does .. but it does not run the --client-disconnect until the new connection is fully authenticated and connected. (Or fails)

TinCanTech

TinCanTech wrote it does not run the --client-disconnect until the new connection is fully authenticated and connected.

This appears to be incorrect .. it is under investigation :geek:

antmarot

TinCanTech wrote it is under investigation :geek:

Ok great. I look forward to learning more about this.

TinCanTech

antmarot wrote Are we wrong to assume the client-disconnect script should always be executed before the client-connect script?

According to further testing .. you should see the --client-disconnect script executed before the current client connection is dropped.

Client-A first connects:

--client-connect Client-A[1] -- Loop here ..
Time passes ..
New connection initialized from Client-A[2]
--tls-verify Client-A[2]
--user-pass-verify Client-A[2]
--client-disconnect Client-A[1]
Server drops Client-A[1]
goto 1

antmarot

Thank you for these clarifications.

Here is a log snippet illustrating the issue (--client-disconnect executed after --client-connect for the "client-pc" common name):

Fri Jul 27 16:24:51 2018 BB.BBB.BBB.BBB:3457 WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1342)
Fri Jul 27 16:24:51 2018 BB.BBB.BBB.BBB:3457 TLS: Initial packet from [AF_INET]BB.BBB.BBB.BBB:3457, sid=0cc5a1a3 f42b2218
Fri Jul 27 16:24:54 2018 BB.BBB.BBB.BBB:3457 VERIFY OK: depth=1, C=BE, ST=**, L=********, O=*******, OU=IT, CN=******* CA, name=server, emailAddress=*****@gmail.com
Fri Jul 27 16:24:54 2018 BB.BBB.BBB.BBB:3457 VERIFY OK: depth=0, C=BE, ST=**, L=********, O=*******, OU=IT, CN=router-4g, name=server, emailAddress=*****@gmail.com
Fri Jul 27 16:24:54 2018 BB.BBB.BBB.BBB:3457 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1384', remote='link-mtu 1542'
Fri Jul 27 16:24:54 2018 BB.BBB.BBB.BBB:3457 WARNING: 'tun-mtu' is used inconsistently, local='tun-mtu 1342', remote='tun-mtu 1500'
Fri Jul 27 16:24:54 2018 BB.BBB.BBB.BBB:3457 WARNING: 'ifconfig' is present in remote config but missing in local config, remote='ifconfig 10.8.0.181 10.8.0.182'
Fri Jul 27 16:24:54 2018 BB.BBB.BBB.BBB:3457 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Fri Jul 27 16:24:54 2018 BB.BBB.BBB.BBB:3457 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Fri Jul 27 16:24:54 2018 BB.BBB.BBB.BBB:3457 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Fri Jul 27 16:24:54 2018 BB.BBB.BBB.BBB:3457 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Fri Jul 27 16:24:54 2018 BB.BBB.BBB.BBB:3457 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Fri Jul 27 16:24:54 2018 BB.BBB.BBB.BBB:3457 [router-4g] Peer Connection Initiated with [AF_INET]BB.BBB.BBB.BBB:3457

## --client-disconnect [router-4g]

Fri Jul 27 16:24:55 2018 MULTI: new connection by client 'router-4g' 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.
Fri Jul 27 16:24:55 2018 MULTI_sva: pool returned IPv4=10.8.0.182, IPv6=(Not enabled)

## --client-connect [router-4g]

Fri Jul 27 16:24:56 2018 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_d55181add5b443984c0d5e06c01db076.tmp
Fri Jul 27 16:24:56 2018 MULTI: Learn: 10.8.0.182 -> router-4g/BB.BBB.BBB.BBB:3457
Fri Jul 27 16:24:56 2018 MULTI: primary virtual IP for router-4g/BB.BBB.BBB.BBB:3457: 10.8.0.182
Fri Jul 27 16:25:01 2018 client-pc/AA.AAA.AAA.AAA:3260 TLS: tls_process: killed expiring key
Fri Jul 27 16:25:03 2018 client-pc/AA.AAA.AAA.AAA:3260 TLS: soft reset sec=0 bytes=244207/0 pkts=2121/0
Fri Jul 27 16:26:03 2018 client-pc/AA.AAA.AAA.AAA:3260 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Fri Jul 27 16:26:03 2018 client-pc/AA.AAA.AAA.AAA:3260 TLS Error: TLS handshake failed
Fri Jul 27 16:26:03 2018 client-pc/AA.AAA.AAA.AAA:3260 TLS: move_session: dest=TM_LAME_DUCK src=TM_ACTIVE reinit_src=1
Fri Jul 27 16:26:07 2018 BB.BBB.BBB.BBB:3894 WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1342)
Fri Jul 27 16:26:07 2018 BB.BBB.BBB.BBB:3894 TLS: Initial packet from [AF_INET]BB.BBB.BBB.BBB:3894, sid=fc0f57f6 d5898308
Fri Jul 27 16:26:08 2018 BB.BBB.BBB.BBB:3894 VERIFY OK: depth=1, C=BE, ST=**, L=********, O=*******, OU=IT, CN=******* CA, name=server, emailAddress=*****@gmail.com
Fri Jul 27 16:26:08 2018 BB.BBB.BBB.BBB:3894 VERIFY OK: depth=0, C=BE, ST=**, L=********, O=*******, OU=IT, CN=client-pc, name=server, emailAddress=*****@gmail.com
Fri Jul 27 16:26:08 2018 BB.BBB.BBB.BBB:3894 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Fri Jul 27 16:26:08 2018 BB.BBB.BBB.BBB:3894 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Fri Jul 27 16:26:08 2018 BB.BBB.BBB.BBB:3894 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Fri Jul 27 16:26:08 2018 BB.BBB.BBB.BBB:3894 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Fri Jul 27 16:26:08 2018 BB.BBB.BBB.BBB:3894 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Fri Jul 27 16:26:08 2018 BB.BBB.BBB.BBB:3894 [client-pc] Peer Connection Initiated with [AF_INET]BB.BBB.BBB.BBB:3894
Fri Jul 27 16:26:08 2018 client-pc/BB.BBB.BBB.BBB:3894 OPTIONS IMPORT: reading client specific options from: ccd/client-pc

## --client-connect [client-pc]

Fri Jul 27 16:26:09 2018 client-pc/BB.BBB.BBB.BBB:3894 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_9f674f3af26fff65f0d2f9795e5d749e.tmp
Fri Jul 27 16:26:09 2018 client-pc/BB.BBB.BBB.BBB:3894 MULTI: Learn: 10.8.0.154 -> client-pc/BB.BBB.BBB.BBB:3894
Fri Jul 27 16:26:09 2018 client-pc/BB.BBB.BBB.BBB:3894 MULTI: primary virtual IP for client-pc/BB.BBB.BBB.BBB:3894: 10.8.0.154
Fri Jul 27 16:26:11 2018 client-pc/BB.BBB.BBB.BBB:3894 PUSH: Received control message: 'PUSH_REQUEST'
Fri Jul 27 16:26:11 2018 client-pc/BB.BBB.BBB.BBB:3894 send_push_reply(): safe_cap=940
Fri Jul 27 16:26:11 2018 client-pc/BB.BBB.BBB.BBB:3894 SENT CONTROL [client-pc]: 'PUSH_REPLY,route 10.8.0.0 255.255.255.0,topology net30,ping 10,ping-restart 120,ifconfig 10.8.0.154 10.8.0.153' (status=1)
Fri Jul 27 16:27:18 2018 client-pc/AA.AAA.AAA.AAA:3260 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Fri Jul 27 16:27:18 2018 client-pc/AA.AAA.AAA.AAA:3260 TLS Error: TLS handshake failed
Fri Jul 27 16:28:05 2018 client-pc/AA.AAA.AAA.AAA:3260 [UNDEF] Inactivity timeout (--ping-restart), restarting
Fri Jul 27 16:28:05 2018 client-pc/AA.AAA.AAA.AAA:3260 SIGUSR1[soft,ping-restart] received, client-instance restarting

## --client-disconnect [client-pc]

BB.BBB.BBB.BBB

is the new remote ip, while

AA.AAA.AAA.AAA

is the ip it was previously connected on.

Do you see a reason why the script order is not respected?

TinCanTech

I don't have a specific reason for you but that is the nature of UDP ..

I have had the same problem and have tried to build some crude error correction into my scripts.

antmarot

Ok, I think I'll just try to pair connect and disconnect events using remote ips (with $trusted_ip).
Thanks again.

rgaufman

I have the same issue here, where:

1) Client A connects (--client-connect)
2) Client A connects again for some reason, maybe it crashed, maybe something else unexpected happened, who knows (--client-connect)
3) Client A original connection times out (--client-disconnect)

I am not quite sure how to handle this because my scripts think oh, the client disconnected. But in fact, it is the original connection that disconnected, not the second one.

Is there any kind of environment variable or something to identify which session disconnected? - this way I can say ah, it's the first session that's disconnected, the second session is still fine. Any other solution for this to correctly tracking which sessions connection/disconnect?

rgaufman

I was tearing my hair out over this but found a solution, documented it here: https://serverfault.com/questions/1105221/openvpn-session-id-for-client-connect-and-client-disconnect-unpredictable-e/1105274#1105274

TinCanTech

That answer is a poor quality hack at best.

Easy-TLS manages full client connect/disconnect with ease and is fully tested.