How to see when pool releases an IP?

[deleted]

Hello,

I'm trying to make sense of auditing the openvpn logs. I also have ulogd installed, so I can see at what time of the day the openvpn IP 10.8.0.x is assigned to a client. Please keep in mind I have `duplicate-cn` in server config.

Looking at the openvpn logs I seem to see when the pool has allocated the internal IP 10.8.0.10 to a client. But I fail to see when the pool has released an IP address.
1) For example at line 33 it seems the pool has returned 10.8.0.10, does that mean at this point it was not in use but now it will be assigned to somebody?
2) At line 34 `Learn 10.8.0.10 -> clientDeFsn4` means it's allocating the 10.8.0.10 to the client?

But when I look otherwise into the file, I don't seem to see where the IP 10.8.0.10 is actually released so that I know when the client has disconnected.

2021-05-02 13:19:21 Control Channel: using tls-crypt-v2 key
2021-05-02 13:19:21 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-05-02 13:19:21 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-05-02 13:19:21 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-05-02 13:19:21 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-05-02 13:19:21 xx.xx.66.62:40385 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-05-02 13:19:21 xx.xx.66.62:40385 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-05-02 13:19:21 xx.xx.66.62:40385 TLS: Initial packet from [AF_INET]xx.xx.66.62:40385, sid=6ad034e2 943f1397
2021-05-02 13:19:21 xx.xx.66.62:40385 Control Channel: using tls-crypt-v2 key
2021-05-02 13:19:21 xx.xx.66.62:40385 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-05-02 13:19:21 xx.xx.66.62:40385 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-05-02 13:19:21 xx.xx.66.62:40385 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-05-02 13:19:21 xx.xx.66.62:40385 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-05-02 13:19:21 xx.xx.66.62:40385 VERIFY OK: depth=1, CN=cn_QxbnuONDYMX207zb
2021-05-02 13:19:21 xx.xx.66.62:40385 VERIFY OK: depth=0, CN=clientDeFsn4
2021-05-02 13:19:21 xx.xx.66.62:40385 peer info: IV_VER=2.5_master
2021-05-02 13:19:21 xx.xx.66.62:40385 peer info: IV_PLAT=android
2021-05-02 13:19:21 xx.xx.66.62:40385 peer info: IV_NCP=2
2021-05-02 13:19:21 xx.xx.66.62:40385 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM
2021-05-02 13:19:21 xx.xx.66.62:40385 peer info: IV_PROTO=22
2021-05-02 13:19:21 xx.xx.66.62:40385 peer info: IV_LZ4=1
2021-05-02 13:19:21 xx.xx.66.62:40385 peer info: IV_LZ4v2=1
2021-05-02 13:19:21 xx.xx.66.62:40385 peer info: IV_LZO=1
2021-05-02 13:19:21 xx.xx.66.62:40385 peer info: IV_COMP_STUB=1
2021-05-02 13:19:21 xx.xx.66.62:40385 peer info: IV_COMP_STUBv2=1
2021-05-02 13:19:21 xx.xx.66.62:40385 peer info: IV_TCPNL=1
2021-05-02 13:19:21 xx.xx.66.62:40385 peer info: IV_GUI_VER=com.vc.tg.vpn.android_7.0.4
2021-05-02 13:19:21 xx.xx.66.62:40385 peer info: IV_SSO=openurl,crtext
2021-05-02 13:19:21 xx.xx.66.62:40385 PLUGIN_CALL: POST /usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so/PLUGIN_AUTH_USER_PASS_VERIFY status=0
2021-05-02 13:19:21 xx.xx.66.62:40385 TLS: Username/Password authentication succeeded for username 'ffffffff-f31d-7842-ffff-fffff31d7842'
2021-05-02 13:19:21 xx.xx.66.62:40385 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 256 bit EC, curve: prime256v1
2021-05-02 13:19:21 xx.xx.66.62:40385 [clientDeFsn4] Peer Connection Initiated with [AF_INET]xx.xx.66.62:40385
2021-05-02 13:19:21 clientDeFsn4/xx.xx.66.62:40385 MULTI_sva: pool returned IPv4=10.8.0.10, IPv6=(Not enabled)
2021-05-02 13:19:21 clientDeFsn4/xx.xx.66.62:40385 MULTI: Learn: 10.8.0.10 -> clientDeFsn4/xx.xx.66.62:40385
2021-05-02 13:19:21 clientDeFsn4/xx.xx.66.62:40385 MULTI: primary virtual IP for clientDeFsn4/xx.xx.66.62:40385: 10.8.0.10
2021-05-02 13:19:21 clientDeFsn4/xx.xx.66.62:40385 Outgoing Data Channel: Cipher 'AES-128-GCM' initialized with 128 bit key
2021-05-02 13:19:21 clientDeFsn4/xx.xx.66.62:40385 Incoming Data Channel: Cipher 'AES-128-GCM' initialized with 128 bit key
2021-05-02 13:19:21 clientDeFsn4/xx.xx.66.62:40385 SENT CONTROL [clientDeFsn4]: 'PUSH_REPLY,dhcp-option DNS 1.0.0.1,dhcp-option DNS 1.1.1.1,redirect-gateway def1 bypass-dhcp,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 120,ifconfig 10.8.0.10 255.255.255.0,peer-id 9,cipher AES-128-GCM' (status=1)
2021-05-02 13:19:58 clientDeFsn4/xx.xx.76.162:53109 SIGTERM[soft,remote-exit] received, client-instance exiting
2021-05-02 13:20:17 xx.xx.152.59:45984 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-05-02 13:20:17 xx.xx.152.59:45984 TLS Error: TLS handshake failed
2021-05-02 13:20:17 xx.xx.152.59:45984 SIGUSR1[soft,tls-error] received, client-instance restarting
2021-05-02 13:20:31 Control Channel: using tls-crypt-v2 key

TinCanTech

The server does not do DHCP, it simply hands out unused IPs.

IPs are returned to the pool when clients disconnect but don't count on that ..
Especially when using --duplicate-cn ..

[deleted]

Hey buddy,

TinCanTech wrote IPs are returned to the pool when clients disconnect but don't count on that ..

Ok, but does that get written into the logs? How would it look like if this happens? I haven't been able to find any entry that corresponds to returning an IP to the pool. 🙂

TinCanTech

I don't know, perhaps it is not logged or may be you need to increase --verb