#160 closed Bug / Defect (duplicate)
openvpn sometimes doesn't provide 'common_name' env. var during client-disconnect execution.
| Reported by: | Daniel | Owned by: | JJK |
|---|---|---|---|
| Priority: | major | Milestone: | release 2.4.11 |
| Component: | plug-ins / plug-in API | Version: | OpenVPN 2.2.0 (Community Ed) |
| Severity: | Not set (select this one, unless your'e a OpenVPN developer) | Keywords: | |
| Cc: | Gert Döring |
Description
Hi!
I have a client-disconnect script which gets executed when users disconnect. Although I'm push'ing "explicit-exit-notify" to clients, sometimes it happens that they disconnect abruptly (because of flaky internet connections). For a long time the client-disconnect script has never failed me, and it cleaned up after the user, but to be able to do this, it needs the 'common_name' environment variable, which provides me the username (I'm using username/password auth, not key files).
Unfortunately, every now and then, there is a user, who loses her/his internet connection, and I'm starting to get these in the server logs:
read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Then after ten or so messages, the client-disconnect script's log entries:
client-disconnect: undefined username!
The code is simple which provides this: it simply checks for the 'common_name' env. var existence.
I've gathered additional information from the time when this has happened. These informations are produced by the same client-disconnect script, which couldn't find the 'common_name' env. variable:
- ENVIRONMENT VARIABLES:
time_ascii=Sat Sep 10 15:35:02 2011 daemon_start_time=1315566047 ifconfig_local=10.x.x.x trusted_ip=7x.x.x.x remote_port_1=1194 daemon_pid=1129 daemon_log_redirect=0 untrusted_port=1024 verb=3 time_duration=416 bytes_sent=17018 daemon=1 local_1=9x.x.x.x trusted_port=1024 ifconfig_broadcast=10.x.x.x dev=tap0 ifconfig_pool_remote_ip=10.x.x.49 untrusted_ip=7x.x.x.x bytes_received=10460 tun_mtu=1500 ifconfig_netmask=255.255.240.0 ifconfig_pool_netmask=255.255.240.0 time_unix=1315661702 proto_1=udp link_mtu=1574 local_port_1=1194 config=/etc/openvpn/openvpn-fw.conf script_type=client-disconnect script_context=init
You can see that the 'common_name' is missing from it. Every other information is present and correct.
- ARP TABLE:
Address HWtype HWaddress Flags Mask Iface [...] 10.x.x.49 ether 00:ff:x:x:x:x C tap0 [...]
The "offending" user's information is available in the arp table.
- OPENVPN STATUS FILE:
OpenVPN CLIENT LIST Updated,Sat Sep 10 15:41:58 2011 Common Name,Real Address,Bytes Received,Bytes Sent,Connected Since [...] UNDEF,7x.x.x.x:1024,10460,17018,Sat Sep 10 15:35:02 2011 [...] ROUTING TABLE Virtual Address,Common Name,Real Address,Last Ref [...] 00:ff:x:x:x:x,UNDEF,7x.x.x.x:1024,Sat Sep 10 15:41:21 2011 [...] GLOBAL STATS Max bcast/mcast queue length,49 END
As you can see, the username is UNDEF, probably that is why the client-disconnect script won't get the env. var. The other informations (ip, mac) are present and correct.
OpenVPN server version is 2.2.1, and has been configured and compiled like this:
./configure --enable-password-save --enable-iproute2 --disable-selinux --prefix=/usr/local && make
The server config:
daemon openvpn-fw mode server tls-server dh /etc/openvpn/dh1024.pem ca /etc/ssl/certs/ca.crt cert /etc/ssl/certs/cert.crt key /etc/ssl/private/key.key user openvpn group openvpn local 9x.x.x.x port 1194 proto udp dev-type tap dev tap0 ifconfig 10.x.x.1 255.255.240.0 ifconfig-pool 10.x.x.10 10.x.x.255 255.255.240.0 push "route-gateway 10.x.x.1" persist-key persist-tun replay-persist /var/run/openvpn/openvpn-replay comp-lzo adaptive push "comp-lzo adaptive" max-clients 150 keepalive 3 30 push "explicit-exit-notify 3" status /var/run/openvpn/openvpn-fw_status 1 status-version 1 syslog openvpn verb 3 management /var/run/openvpn/openvpn-fw_management unix /etc/openvpn/management_passwd management-client-user root management-client-group root client-cert-not-required username-as-common-name script-security 2 client-connect /usr/local/libexec/openvpn/client-connect.pl client-disconnect /usr/local/libexec/openvpn/client-disconnect.pl tmp-dir /dev/shm auth-user-pass-verify /usr/local/libexec/openvpn/auth-user-pass-verify.pl via-file
Attachments (1)
Change History (33)
comment:1 Changed 11 years ago by
| Component: | Generic / unclassified → Configuration |
|---|---|
| Owner: | set to JJK |
| Status: | new → accepted |
comment:2 Changed 11 years ago by
Thank you, I'm starting to test the patch now.
Just for the record, a copy-paste'able version of it:
--- multi.c.orig 2011-06-24 08:13:39.000000000 +0200
+++ multi.c 2011-09-13 08:43:56.732903222 +0200
@@ -447,6 +447,9 @@
multi_client_disconnect_setenv (struct multi_context *m,
struct multi_instance *mi)
{
+ /* setenv incoming cert common name for script */
+ setenv_str (mi->context.c2.es, "common_name", tls_common_name (mi->context.c2.tls_multi, true));
+
/* setenv client real IP address */
setenv_trusted (mi->context.c2.es, get_link_socket_info (&mi->context));
comment:4 Changed 11 years ago by
Unfortunatelly, I've again got a disconnection when the common_name variable was not present. What can I do to further aid the solving of this problem?
comment:5 Changed 10 years ago by
| Component: | Configuration → plug-ins / plug-in API |
|---|
The best way to help sorting out this is to try to find a reliable way how to reproduce this at will.
Otherwise, you'll need to have a debugger attached to the openvpn process with a trigger to dump a backtrace when multi_client_disconnect_setenv() is called and tls_common(mi->context.c2.tls_multi, true)) returns nothing (or NULL).
It would also be interesting to see if a plugin written in C would also have an empty common_name in this case as well.
comment:6 Changed 9 years ago by
I do also have this issue, version: 2.3.2-2.el6.
I use username-as-common-name, client-connect and client-disconnect options.
common-name environment variable is indeed the username, as intended for the client-connect script, but this is not always true for the client-disconnect script: sometimes, the common_name environ variable become the common_name of the client's certificate instead of the actual username. Note: this happens only on connections that lasted for more then an hour or two.
The patch above thats adds common_name setup in multi_client_disconnect_setenv fixed the problem for me.
comment:7 Changed 8 years ago by
| Cc: | Gert Döring added |
|---|---|
| Milestone: | → release 2.4 |
We have at least three reports of the same issue, and in all cases the provided patch fixes the issue. If the patch is likely to be harmless, perhaps we should just apply it to Git "master" and let it go to 2.4. Thoughts?
comment:8 Changed 8 years ago by
as far as I know (and can see) the patch is harmless, and I don't see how it could negatively affect an existing setup. Let's apply it to Git "master".
comment:9 Changed 8 years ago by
I'm not convinced. From my reading of the ticket, OpenVPN seems to clear the common_name internally before calling the script (which is why it has "UNDEF" in the status.log), so there's at least two bugs here
- why is it UNDEF on "client disappears without saying goodbye" (and: cann this be reproduced?)
- why is it sometimes not passing the username but the common_name on disconnect? The time dependency hints at "during rekey, the variable in question is overwritten" (comment 6)
I feel that we're not fully understand what is happening here.
@samuli: daniell reports that it does not fix the problem for him...
comment:10 Changed 8 years ago by
which message is daniell seeing? same as before? any way to reproduce his setup? the big problem with this bug report is that it does not address the underlying bug (the reproducability issue) but it *did* fix the issue for several people: classical case of "bad solution to a bad problem"
comment:11 follow-up: 12 Changed 8 years ago by
Guys, I reported this four years ago. The fact that the patch was/wasn't working for me then is irrelevant... I don't even live in the same city, and I sure don't know the details or the environment of this setup anymore. I don't know how to reproduce this, that script has long gone, in fact, the whole setup has been long gone.
This reminds me of a few KDE bugs I had reported when I was still in high school, and got the flash-back when after 7 years they replied with an inquiry if it is still reproducible :-)
Daniel
comment:12 Changed 8 years ago by
Replying to daniell:
Guys, I reported this four years ago.
well... sorry for that. We do our best, but some of the bugs are harder than others - like this one. And, like most open source projects, we lack developer resources...
comment:13 Changed 8 years ago by
Oh, hey man, don't get me wrong, I wasn't trying to hold anyone accountable. This was simply a "fun fact", and I was just trying to state that since a very long time, I'm unable to test or reproduce this in the original environment -- it (along with me from there) has been long gone.
Daniel
comment:14 Changed 8 years ago by
still playing around with this, and actually managed to reproduce it with 2.3.6 !
my test config is a basic tun setup with auth-user-pass-verify + client-disconnect + reneg-sec 40
After several key renegotiations and a termination of the client the disconnect script prints the common_name instead of the username. The "reneg-sec XX" is crucial here.
Now all we have to do is figure out what is causing this to happen.
comment:15 Changed 8 years ago by
follow-up: here's what happens:
- client connects, auth-user-pass-verify script is called with common_name=cert, username=user
- client auth succeeeds, client-connect script is called. During this, an explict common_name=user is done
- renegotion: auth-user-pass-verify script is called again, which sets common_name=cert !
- client-connect is NOT called again, hence common_name is not altered
- at disconnect, common_name is still set to certificate name
My original patch now makes more sense, although one could argue that the common_name should be set to <user> straight after calling the auth-user-pass-verify script. However, how does the server keep track of which env vars are used for which client?
comment:16 Changed 7 years ago by
I am having the same problem and created a new ticket (#691) for it. Sorry for that, I didn't see this one.
Anyway, I will just post my experiences about this problem:
I had a problem with my disconnect script and discovered this bug. I am using the $common_name variable in the disconnect script to receive the "username" while having "username-as-common-name" activated. My expected behaviour would be that the $common_name variable always includes the username submitted by the authentication script. But this is not the case. Somewhen this variable is overwritten and the common name from the certificate is written to it. Sadly I can't tell you exactly when this overwriting happens but my assumption is during a TLS renegotiation or ping timeout. It would be nice if you could fix this as I assume further problems if duplicate-cn is not activated. Then multiple people could have the same common name and would then be disconnected because of that.
comment:17 Changed 22 months ago by
This might have been fixed in 2.5 (because all the environment handling for all that script stuff was rewritten as part of the async-cc patch set).
Can one of you test?
(And sorry for the insane delay...)
comment:18 Changed 22 months ago by
| Milestone: | release 2.4 → release 2.4.11 |
|---|
comment:19 Changed 17 months ago by
Using:
2021-09-12 13:49:44 us=721327 OpenVPN 2.6_git [git:master/42f6063f611b75a0] x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Aug 30 2021
2021-09-12 13:49:44 us=721350 library versions: OpenSSL 1.1.1f 31 Mar 2020, LZO 2.10
I can confirm that this problem still exists.
comment:20 Changed 17 months ago by
Complete server log verb 4:
2021-09-12 14:58:51 us=864139 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2021-09-12 14:58:51 us=864222 Current Parameter Settings:
2021-09-12 14:58:51 us=864239 config = 'wiscii-v31a-ca.conf'
2021-09-12 14:58:51 us=864254 mode = 1
2021-09-12 14:58:51 us=864266 persist_config = DISABLED
2021-09-12 14:58:51 us=864278 persist_mode = 1
2021-09-12 14:58:51 us=864291 show_ciphers = DISABLED
2021-09-12 14:58:51 us=864303 show_digests = DISABLED
2021-09-12 14:58:51 us=864316 show_engines = DISABLED
2021-09-12 14:58:51 us=864328 genkey = DISABLED
2021-09-12 14:58:51 us=864340 genkey_filename = '[UNDEF]'
2021-09-12 14:58:51 us=864353 key_pass_file = '[UNDEF]'
2021-09-12 14:58:51 us=864365 show_tls_ciphers = DISABLED
2021-09-12 14:58:51 us=864378 connect_retry_max = 0
2021-09-12 14:58:51 us=864390 Connection profiles [0]:
2021-09-12 14:58:51 us=864403 proto = udp6
2021-09-12 14:58:51 us=864416 local = '[UNDEF]'
2021-09-12 14:58:51 us=864428 local_port = '17122'
2021-09-12 14:58:51 us=864440 remote = '[UNDEF]'
2021-09-12 14:58:51 us=864452 remote_port = '17122'
2021-09-12 14:58:51 us=864463 remote_float = DISABLED
2021-09-12 14:58:51 us=864476 bind_defined = DISABLED
2021-09-12 14:58:51 us=864487 bind_local = ENABLED
2021-09-12 14:58:51 us=864499 bind_ipv6_only = DISABLED
2021-09-12 14:58:51 us=864511 connect_retry_seconds = 5
2021-09-12 14:58:51 us=864523 connect_timeout = 120
2021-09-12 14:58:51 us=864535 socks_proxy_server = '[UNDEF]'
2021-09-12 14:58:51 us=864548 socks_proxy_port = '[UNDEF]'
2021-09-12 14:58:51 us=864561 tun_mtu = 1500
2021-09-12 14:58:51 us=864573 tun_mtu_defined = ENABLED
2021-09-12 14:58:51 us=864585 link_mtu = 1500
2021-09-12 14:58:51 us=864597 link_mtu_defined = DISABLED
2021-09-12 14:58:51 us=864609 tun_mtu_extra = 0
2021-09-12 14:58:51 us=864621 tun_mtu_extra_defined = DISABLED
2021-09-12 14:58:51 us=864633 mtu_discover_type = -1
2021-09-12 14:58:51 us=864646 fragment = 0
2021-09-12 14:58:51 us=864658 mssfix = 1450
2021-09-12 14:58:51 us=864671 explicit_exit_notification = 1
2021-09-12 14:58:51 us=864681 tls_auth_file = '[INLINE]'
2021-09-12 14:58:51 us=864693 key_direction = not set
2021-09-12 14:58:51 us=864704 tls_crypt_file = '[UNDEF]'
2021-09-12 14:58:51 us=864716 tls_crypt_v2_file = '[INLINE]'
2021-09-12 14:58:51 us=864729 Connection profiles END
2021-09-12 14:58:51 us=864741 remote_random = DISABLED
2021-09-12 14:58:51 us=864753 ipchange = '[UNDEF]'
2021-09-12 14:58:51 us=864765 dev = 'tun17122'
2021-09-12 14:58:51 us=864775 dev_type = '[UNDEF]'
2021-09-12 14:58:51 us=864787 dev_node = '[UNDEF]'
2021-09-12 14:58:51 us=864799 lladdr = '[UNDEF]'
2021-09-12 14:58:51 us=864812 topology = 3
2021-09-12 14:58:51 us=864824 ifconfig_local = '10.171.22.1'
2021-09-12 14:58:51 us=864836 ifconfig_remote_netmask = '255.255.255.252'
2021-09-12 14:58:51 us=864848 ifconfig_noexec = DISABLED
2021-09-12 14:58:51 us=864860 ifconfig_nowarn = DISABLED
2021-09-12 14:58:51 us=864872 ifconfig_ipv6_local = '[UNDEF]'
2021-09-12 14:58:51 us=864885 ifconfig_ipv6_netbits = 0
2021-09-12 14:58:51 us=864897 ifconfig_ipv6_remote = '[UNDEF]'
2021-09-12 14:58:51 us=864910 shaper = 0
2021-09-12 14:58:51 us=864922 mtu_test = 0
2021-09-12 14:58:51 us=864935 mlock = DISABLED
2021-09-12 14:58:51 us=864947 keepalive_ping = 20
2021-09-12 14:58:51 us=864959 keepalive_timeout = 60
2021-09-12 14:58:51 us=864972 inactivity_timeout = 0
2021-09-12 14:58:51 us=864985 ping_send_timeout = 20
2021-09-12 14:58:51 us=864997 ping_rec_timeout = 120
2021-09-12 14:58:51 us=865010 ping_rec_timeout_action = 2
2021-09-12 14:58:51 us=865022 ping_timer_remote = DISABLED
2021-09-12 14:58:51 us=865034 remap_sigusr1 = 0
2021-09-12 14:58:51 us=865047 persist_tun = ENABLED
2021-09-12 14:58:51 us=865059 persist_local_ip = DISABLED
2021-09-12 14:58:51 us=865071 persist_remote_ip = DISABLED
2021-09-12 14:58:51 us=865084 persist_key = ENABLED
2021-09-12 14:58:51 us=865097 passtos = DISABLED
2021-09-12 14:58:51 us=865110 resolve_retry_seconds = 1000000000
2021-09-12 14:58:51 us=865121 resolve_in_advance = DISABLED
2021-09-12 14:58:51 us=865133 username = '[UNDEF]'
2021-09-12 14:58:51 us=865144 groupname = '[UNDEF]'
2021-09-12 14:58:51 us=865156 chroot_dir = '/var/easytls'
2021-09-12 14:58:51 us=865167 cd_dir = '[UNDEF]'
2021-09-12 14:58:51 us=865873 writepid = '[UNDEF]'
2021-09-12 14:58:51 us=865903 up_script = '[UNDEF]'
2021-09-12 14:58:51 us=865923 down_script = '[UNDEF]'
2021-09-12 14:58:51 us=865943 down_pre = DISABLED
2021-09-12 14:58:51 us=865961 up_restart = DISABLED
2021-09-12 14:58:51 us=865980 up_delay = DISABLED
2021-09-12 14:58:51 us=865999 daemon = DISABLED
2021-09-12 14:58:51 us=866019 log = DISABLED
2021-09-12 14:58:51 us=866039 suppress_timestamps = DISABLED
2021-09-12 14:58:51 us=866057 machine_readable_output = DISABLED
2021-09-12 14:58:51 us=866077 nice = 0
2021-09-12 14:58:51 us=866098 verbosity = 4
2021-09-12 14:58:51 us=866117 mute = 0
2021-09-12 14:58:51 us=866136 gremlin = 0
2021-09-12 14:58:51 us=866155 status_file = '[UNDEF]'
2021-09-12 14:58:51 us=866182 status_file_version = 1
2021-09-12 14:58:51 us=866207 status_file_update_freq = 60
2021-09-12 14:58:51 us=866229 occ = ENABLED
2021-09-12 14:58:51 us=866253 rcvbuf = 0
2021-09-12 14:58:51 us=866275 sndbuf = 0
2021-09-12 14:58:51 us=866296 mark = 0
2021-09-12 14:58:51 us=866318 sockflags = 0
2021-09-12 14:58:51 us=866339 fast_io = DISABLED
2021-09-12 14:58:51 us=866361 comp.alg = 1
2021-09-12 14:58:51 us=866383 comp.flags = 0
2021-09-12 14:58:51 us=866405 route_script = '[UNDEF]'
2021-09-12 14:58:51 us=866427 route_default_gateway = '10.171.22.2'
2021-09-12 14:58:51 us=866448 route_default_metric = 0
2021-09-12 14:58:51 us=866469 route_noexec = DISABLED
2021-09-12 14:58:51 us=866491 route_delay = 0
2021-09-12 14:58:51 us=866512 route_delay_window = 30
2021-09-12 14:58:51 us=866534 route_delay_defined = DISABLED
2021-09-12 14:58:51 us=866555 route_nopull = DISABLED
2021-09-12 14:58:51 us=866577 route_gateway_via_dhcp = DISABLED
2021-09-12 14:58:51 us=866599 allow_pull_fqdn = DISABLED
2021-09-12 14:58:51 us=866621 route 192.168.1.0/255.255.255.252/net_gateway/default (not set)
2021-09-12 14:58:51 us=866642 route 192.168.0.0/255.255.0.0/default (not set)/default (not set)
2021-09-12 14:58:51 us=866666 route 172.16.0.0/255.240.0.0/default (not set)/default (not set)
2021-09-12 14:58:51 us=866687 route 10.0.0.0/255.0.0.0/default (not set)/default (not set)
2021-09-12 14:58:51 us=866712 route 10.10.201.0/255.255.255.0/net_gateway/default (not set)
2021-09-12 14:58:51 us=866734 management_addr = '127.0.0.1'
2021-09-12 14:58:51 us=866756 management_port = '17122'
2021-09-12 14:58:51 us=866777 management_user_pass = '[UNDEF]'
2021-09-12 14:58:51 us=866801 management_log_history_cache = 250
2021-09-12 14:58:51 us=866816 management_echo_buffer_size = 100
2021-09-12 14:58:51 us=866830 management_write_peer_info_file = '[UNDEF]'
2021-09-12 14:58:51 us=866846 management_client_user = '[UNDEF]'
2021-09-12 14:58:51 us=866860 management_client_group = '[UNDEF]'
2021-09-12 14:58:51 us=866874 management_flags = 0
2021-09-12 14:58:51 us=866888 shared_secret_file = '[UNDEF]'
2021-09-12 14:58:51 us=866902 key_direction = not set
2021-09-12 14:58:51 us=866916 ciphername = 'BF-CBC'
2021-09-12 14:58:51 us=866930 ncp_ciphers = 'CHACHA20-POLY1305:AES-256-GCM:AES-128-GCM'
2021-09-12 14:58:51 us=866944 authname = 'SHA1'
2021-09-12 14:58:51 us=866958 prng_hash = 'SHA1'
2021-09-12 14:58:51 us=866971 prng_nonce_secret_len = 16
2021-09-12 14:58:51 us=866985 engine = DISABLED
2021-09-12 14:58:51 us=866998 replay = ENABLED
2021-09-12 14:58:51 us=867011 mute_replay_warnings = DISABLED
2021-09-12 14:58:51 us=867025 replay_window = 64
2021-09-12 14:58:51 us=867040 replay_time = 15
2021-09-12 14:58:51 us=867053 packet_id_file = '[UNDEF]'
2021-09-12 14:58:51 us=867068 test_crypto = DISABLED
2021-09-12 14:58:51 us=867082 tls_server = ENABLED
2021-09-12 14:58:51 us=867095 tls_client = DISABLED
2021-09-12 14:58:51 us=867107 ca_file = '[INLINE]'
2021-09-12 14:58:51 us=867120 ca_path = '[UNDEF]'
2021-09-12 14:58:51 us=867133 dh_file = '[UNDEF]'
2021-09-12 14:58:51 us=867146 cert_file = '[INLINE]'
2021-09-12 14:58:51 us=867158 extra_certs_file = '[UNDEF]'
2021-09-12 14:58:51 us=867173 priv_key_file = '[INLINE]'
2021-09-12 14:58:51 us=867186 pkcs12_file = '[UNDEF]'
2021-09-12 14:58:51 us=867199 cipher_list = '[UNDEF]'
2021-09-12 14:58:51 us=867211 cipher_list_tls13 = '[UNDEF]'
2021-09-12 14:58:51 us=867223 tls_cert_profile = '[UNDEF]'
2021-09-12 14:58:51 us=867236 tls_verify = '[UNDEF]'
2021-09-12 14:58:51 us=867249 tls_export_cert = '/tmp'
2021-09-12 14:58:51 us=867262 verify_x509_type = 0
2021-09-12 14:58:51 us=867274 verify_x509_name = '[UNDEF]'
2021-09-12 14:58:51 us=867287 crl_file = '[UNDEF]'
2021-09-12 14:58:51 us=867301 ns_cert_type = 0
2021-09-12 14:58:51 us=867313 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867326 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867339 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867353 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867366 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867378 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867391 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867404 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867417 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867429 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867442 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867455 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867468 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867482 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867494 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867507 remote_cert_ku[i] = 0
2021-09-12 14:58:51 us=867520 remote_cert_eku = '[UNDEF]'
2021-09-12 14:58:51 us=867533 ssl_flags = 4
2021-09-12 14:58:51 us=867546 tls_timeout = 2
2021-09-12 14:58:51 us=867559 renegotiate_bytes = -1
2021-09-12 14:58:51 us=867572 renegotiate_packets = 0
2021-09-12 14:58:51 us=867585 renegotiate_seconds = 342
2021-09-12 14:58:51 us=867598 handshake_window = 60
2021-09-12 14:58:51 us=867611 transition_window = 3600
2021-09-12 14:58:51 us=867623 single_session = DISABLED
2021-09-12 14:58:51 us=867637 push_peer_info = DISABLED
2021-09-12 14:58:51 us=867650 tls_exit = DISABLED
2021-09-12 14:58:51 us=867663 tls_crypt_v2_metadata = '[UNDEF]'
2021-09-12 14:58:51 us=867678 server_network = 0.0.0.0
2021-09-12 14:58:51 us=867692 server_netmask = 0.0.0.0
2021-09-12 14:58:51 us=867715 server_network_ipv6 = ::
2021-09-12 14:58:51 us=867729 server_netbits_ipv6 = 0
2021-09-12 14:58:51 us=867743 server_bridge_ip = 0.0.0.0
2021-09-12 14:58:51 us=867757 server_bridge_netmask = 0.0.0.0
2021-09-12 14:58:51 us=867771 server_bridge_pool_start = 0.0.0.0
2021-09-12 14:58:51 us=867785 server_bridge_pool_end = 0.0.0.0
2021-09-12 14:58:51 us=867798 push_entry = 'topology subnet'
2021-09-12 14:58:51 us=867814 push_entry = 'route 10.10.101.0 255.255.255.0 net_gateway'
2021-09-12 14:58:51 us=867825 push_entry = 'route 10.0.0.0 255.0.0.0'
2021-09-12 14:58:51 us=867834 push_entry = 'route 172.16.0.0 255.240.0.0'
2021-09-12 14:58:51 us=867843 push_entry = 'route 192.168.0.0 255.255.0.0'
2021-09-12 14:58:51 us=867852 push_entry = 'route 192.168.1.0 255.255.255.252 net_gateway'
2021-09-12 14:58:51 us=867861 push_entry = 'explicit-exit-notify 1'
2021-09-12 14:58:51 us=867868 push_entry = 'comp-lzo no'
2021-09-12 14:58:51 us=867873 push_entry = 'ping 20'
2021-09-12 14:58:51 us=867879 push_entry = 'ping-restart 60'
2021-09-12 14:58:51 us=867885 ifconfig_pool_defined = DISABLED
2021-09-12 14:58:51 us=867891 ifconfig_pool_start = 0.0.0.0
2021-09-12 14:58:51 us=867897 ifconfig_pool_end = 0.0.0.0
2021-09-12 14:58:51 us=867904 ifconfig_pool_netmask = 0.0.0.0
2021-09-12 14:58:51 us=867910 ifconfig_pool_persist_filename = '[UNDEF]'
2021-09-12 14:58:51 us=867916 ifconfig_pool_persist_refresh_freq = 600
2021-09-12 14:58:51 us=867922 ifconfig_ipv6_pool_defined = DISABLED
2021-09-12 14:58:51 us=867928 ifconfig_ipv6_pool_base = ::
2021-09-12 14:58:51 us=867934 ifconfig_ipv6_pool_netbits = 0
2021-09-12 14:58:51 us=867939 n_bcast_buf = 256
2021-09-12 14:58:51 us=867945 tcp_queue_limit = 64
2021-09-12 14:58:51 us=867951 real_hash_size = 256
2021-09-12 14:58:51 us=867956 virtual_hash_size = 256
2021-09-12 14:58:51 us=867962 client_connect_script = '/etc/openvpn/server/v31a/easytls-client-connect.sh -v -l=/etc/openvpn/server/v31a/easytls-client-connect.vars'
2021-09-12 14:58:51 us=867969 learn_address_script = '[UNDEF]'
2021-09-12 14:58:51 us=867975 client_disconnect_script = '/etc/openvpn/server/v31a/easytls-client-disconnect.sh -v -l=/etc/openvpn/server/v31a/easytls-client-disconnect.vars'
2021-09-12 14:58:51 us=867981 client_config_dir = '/etc/openvpn/server/v31a/ccd'
2021-09-12 14:58:51 us=867987 ccd_exclusive = ENABLED
2021-09-12 14:58:51 us=867993 tmp_dir = '/tmp'
2021-09-12 14:58:51 us=867998 push_ifconfig_defined = DISABLED
2021-09-12 14:58:51 us=868004 push_ifconfig_local = 0.0.0.0
2021-09-12 14:58:51 us=868011 push_ifconfig_remote_netmask = 0.0.0.0
2021-09-12 14:58:51 us=868016 push_ifconfig_ipv6_defined = DISABLED
2021-09-12 14:58:51 us=868022 push_ifconfig_ipv6_local = ::/0
2021-09-12 14:58:51 us=868028 push_ifconfig_ipv6_remote = ::
2021-09-12 14:58:51 us=868034 enable_c2c = DISABLED
2021-09-12 14:58:51 us=868040 duplicate_cn = DISABLED
2021-09-12 14:58:51 us=868053 cf_max = 0
2021-09-12 14:58:51 us=868064 cf_per = 0
2021-09-12 14:58:51 us=868077 max_clients = 1024
2021-09-12 14:58:51 us=868088 max_routes_per_client = 256
2021-09-12 14:58:51 us=868100 auth_user_pass_verify_script = '/etc/openvpn/server/v31a/easytls-defer-userpass-verify.sh'
2021-09-12 14:58:51 us=868114 auth_user_pass_verify_script_via_file = DISABLED
2021-09-12 14:58:51 us=868129 auth_token_generate = DISABLED
2021-09-12 14:58:51 us=868143 auth_token_lifetime = 0
2021-09-12 14:58:51 us=868156 auth_token_secret_file = '[UNDEF]'
2021-09-12 14:58:51 us=868169 port_share_host = '[UNDEF]'
2021-09-12 14:58:51 us=868182 port_share_port = '[UNDEF]'
2021-09-12 14:58:51 us=868195 vlan_tagging = DISABLED
2021-09-12 14:58:51 us=868208 vlan_accept = all
2021-09-12 14:58:51 us=868234 vlan_pvid = 1
2021-09-12 14:58:51 us=868254 client = DISABLED
2021-09-12 14:58:51 us=868266 pull = DISABLED
2021-09-12 14:58:51 us=868278 auth_user_pass_file = '[UNDEF]'
2021-09-12 14:58:51 us=868304 OpenVPN 2.6_git [git:master/42f6063f611b75a0] x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Aug 30 2021
2021-09-12 14:58:51 us=868326 library versions: OpenSSL 1.1.1f 31 Mar 2020, LZO 2.10
2021-09-12 14:58:51 us=868441 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:17122
2021-09-12 14:58:51 us=868508 WARNING: you are using chroot without specifying user and group -- this may cause the chroot jail to be insecure
2021-09-12 14:58:51 us=868668 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
2021-09-12 14:58:51 us=869763 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-09-12 14:58:51 us=869803 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-09-12 14:58:51 us=869836 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-09-12 14:58:51 us=869863 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-09-12 14:58:51 us=869892 TLS-Auth MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-09-12 14:58:51 us=870056 ROUTE_GATEWAY 10.10.101.1/255.255.255.0 IFACE=enp5s0 HWADDR=24:b6:fd:31:bc:ca
2021-09-12 14:58:51 us=875014 TUN/TAP device tun17122 opened
2021-09-12 14:58:51 us=876070 do_ifconfig, ipv4=1, ipv6=0
2021-09-12 14:58:51 us=876194 /sbin/ip link set dev tun17122 up mtu 1500
2021-09-12 14:58:51 us=881587 /sbin/ip link set dev tun17122 up
2021-09-12 14:58:51 us=883486 /sbin/ip addr add dev tun17122 10.171.22.1/30
2021-09-12 14:58:51 us=886007 /sbin/ip route add 10.10.201.0/24 via 10.10.101.1
2021-09-12 14:58:51 us=893893 /sbin/ip route add 10.0.0.0/8 via 10.171.22.2
2021-09-12 14:58:51 us=906071 /sbin/ip route add 172.16.0.0/12 via 10.171.22.2
2021-09-12 14:58:51 us=908695 /sbin/ip route add 192.168.0.0/16 via 10.171.22.2
2021-09-12 14:58:51 us=913147 /sbin/ip route add 192.168.1.0/30 via 10.10.101.1
2021-09-12 14:58:51 us=916943 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-09-12 14:58:51 us=917005 Socket Buffers: R=[212992->212992] S=[212992->212992]
2021-09-12 14:58:51 us=917022 setsockopt(IPV6_V6ONLY=0)
2021-09-12 14:58:51 us=917051 UDPv6 link local (bound): [AF_INET6][undef]:17122
2021-09-12 14:58:51 us=917067 UDPv6 link remote: [AF_UNSPEC]
2021-09-12 13:58:51 us=917087 chroot to '/var/easytls' and cd to '/' succeeded
2021-09-12 13:58:51 us=917126 MULTI: multi_init called, r=256 v=256
2021-09-12 13:58:51 us=917203 Initialization Sequence Completed
2021-09-12 13:58:58 us=836478 Control Channel: using tls-crypt-v2 key
2021-09-12 13:58:58 us=836560 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-09-12 13:58:58 us=836584 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-09-12 13:58:58 us=836602 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-09-12 13:58:58 us=836622 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-09-12 13:58:58 us=836653 MULTI: multi_create_instance called
2021-09-12 13:58:58 us=836713 192.168.1.2:1864 Re-using SSL/TLS context
2021-09-12 13:58:58 us=836790 192.168.1.2:1864 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-09-12 13:58:58 us=836806 192.168.1.2:1864 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-09-12 13:58:58 us=836844 192.168.1.2:1864 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-09-12 13:58:58 us=836864 192.168.1.2:1864 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-09-12 13:58:58 us=836985 192.168.1.2:1864 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-09-12 13:58:58 us=837009 192.168.1.2:1864 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-09-12 13:58:58 us=837055 192.168.1.2:1864 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
2021-09-12 13:58:58 us=837073 192.168.1.2:1864 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
2021-09-12 13:58:58 us=837118 192.168.1.2:1864 TLS: Initial packet from [AF_INET6]::ffff:192.168.1.2:1864, sid=c7cc4c6e fc43d2da
2021-09-12 13:58:58 us=837134 192.168.1.2:1864 Control Channel: using tls-crypt-v2 key
2021-09-12 13:58:58 us=837165 192.168.1.2:1864 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-09-12 13:58:58 us=837184 192.168.1.2:1864 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-09-12 13:58:58 us=837195 192.168.1.2:1864 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-09-12 13:58:58 us=837206 192.168.1.2:1864 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => >< acquire_lock >< => CN:arch-v30a => easytls OK => custom_group EasyTLS-v30a OK => tlskey-serial verified OK => Key age 10 days OK => Enabled OK => client passed TLS tests => connection allowed => Created client_md_file => << release_lock >>
2021-09-12 13:58:58 us=857188 192.168.1.2:1864 TLS CRYPT V2 VERIFY SCRIPT OK
2021-09-12 13:58:58 us=903206 192.168.1.2:1864 VERIFY OK: depth=1, C=00, ST=home, L=tct, O=easy-tls, OU=Easy-TLS test v30a, CN=Easy-TLS v30a CA, emailAddress=tct@…
2021-09-12 13:58:58 us=905484 192.168.1.2:1864 VERIFY OK: depth=0, C=00, ST=home, L=tct, O=easy-tls, OU=Easy-TLS test v30a, CN=arch-v30a, emailAddress=tct@…
2021-09-12 13:58:58 us=907787 192.168.1.2:1864 peer info: IV_VER=2.6_git
2021-09-12 13:58:58 us=907825 192.168.1.2:1864 peer info: IV_PLAT=linux
2021-09-12 13:58:58 us=907841 192.168.1.2:1864 peer info: IV_NCP=2
2021-09-12 13:58:58 us=907855 192.168.1.2:1864 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM
2021-09-12 13:58:58 us=907870 192.168.1.2:1864 peer info: IV_PROTO=30
2021-09-12 13:58:58 us=907885 192.168.1.2:1864 peer info: IV_LZ4=1
2021-09-12 13:58:58 us=907899 192.168.1.2:1864 peer info: IV_LZ4v2=1
2021-09-12 13:58:58 us=907913 192.168.1.2:1864 peer info: IV_LZO=1
2021-09-12 13:58:58 us=907927 192.168.1.2:1864 peer info: IV_COMP_STUB=1
2021-09-12 13:58:58 us=907939 192.168.1.2:1864 peer info: IV_COMP_STUBv2=1
2021-09-12 13:58:58 us=907952 192.168.1.2:1864 peer info: IV_TCPNL=1
2021-09-12 13:58:58 us=907964 192.168.1.2:1864 peer info: IV_HWADDR=00:15:5d:c9:6e:01
2021-09-12 13:58:58 us=907981 192.168.1.2:1864 peer info: IV_SSL=OpenSSL_1.1.1k__25_Mar_2021
2021-09-12 13:58:58 us=907996 192.168.1.2:1864 peer info: UV_TLSKEY_SERIAL=1189d5ff0d0c1f08b0ed3b1528464c16209c20b30d64bfdad257ac48844260f8
2021-09-12 13:58:58 us=909993 192.168.1.2:1864 TLS: Username/Password? authentication deferred for username 'arch' [CN SET]
2021-09-12 13:58:58 us=910068 192.168.1.2:1864 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1558', remote='link-mtu 1557'
2021-09-12 13:58:58 us=910088 192.168.1.2:1864 WARNING: 'comp-lzo' is present in local config but missing in remote config, local='comp-lzo'
* delay for 7 seconds -- arch-v30a arch *
2021-09-12 13:58:58 us=915437 192.168.1.2:1864 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 384 bit EC, curve secp384r1, signature: ecdsa-with-SHA256
2021-09-12 13:58:58 us=915549 192.168.1.2:1864 [arch] Peer Connection Initiated with [AF_INET6]::ffff:192.168.1.2:1864
2021-09-12 13:59:00 us=26910 192.168.1.2:1864 PUSH: Received control message: 'PUSH_REQUEST'
2021-09-12 13:59:05 us=142020 192.168.1.2:1864 PUSH: Received control message: 'PUSH_REQUEST'
* delay for 7 seconds -- arch-v30a arch DONE *
2021-09-12 13:59:06 us=559519 arch/192.168.1.2:1864 OPTIONS IMPORT: reading client specific options from: /etc/openvpn/server/v31a/ccd/arch
2021-09-12 13:59:06 us=559630 arch/192.168.1.2:1864 PUSH_REMOVE 'route-gateway'
Initial connection:
<EXOK> * EasyTLS-client-connect => vars loaded => CN:arch => conn-trac: registered => 1189d5ff0d0c1f08b0ed3b1528464c16209c20b30d64bfdad257ac48844260f8=6C039A9F3CA4A4B1AA9FDB9A185AF68C=arch => tls key serial: 1189d5ff0d0c1f08b0ed3b1528464c16209c20b30d64bfdad257ac48844260f8 => fixed_md_file loaded => metadata -> x509 serial match => hwaddr 00155DC96E01 pushed and matched => connection allowed => temp-files deleted
2021-09-12 13:59:06 us=588457 arch/192.168.1.2:1864 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_5d3f765afe0ab03a5e7d906413a3a0df.tmp
2021-09-12 13:59:06 us=588655 arch/192.168.1.2:1864 MULTI: Learn: 172.16.55.10 -> arch/192.168.1.2:1864
2021-09-12 13:59:06 us=588683 arch/192.168.1.2:1864 MULTI: primary virtual IP for arch/192.168.1.2:1864: 172.16.55.10
2021-09-12 13:59:06 us=588710 arch/192.168.1.2:1864 Data Channel: using negotiated cipher 'AES-256-GCM'
2021-09-12 13:59:06 us=588751 arch/192.168.1.2:1864 Data Channel MTU parms [ L:1550 D:1450 EF:50 EB:406 ET:0 EL:3 AF:14/122 ]
2021-09-12 13:59:06 us=588855 arch/192.168.1.2:1864 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2021-09-12 13:59:06 us=588887 arch/192.168.1.2:1864 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2021-09-12 13:59:06 us=588969 arch/192.168.1.2:1864 SENT CONTROL [arch]: 'PUSH_REPLY,topology subnet,route 10.10.101.0 255.255.255.0 net_gateway,route 10.0.0.0 255.0.0.0,route 172.16.0.0 255.240.0.0,route 192.168.0.0 255.255.0.0,route 192.168.1.0 255.255.255.252 net_gateway,explicit-exit-notify 1,comp-lzo no,ping 20,ping-restart 60,route-gateway 172.16.55.9,ifconfig 172.16.55.10 255.255.255.252,peer-id 0,cipher AES-256-GCM,key-derivation tls-ekm' (status=1)
Client initiated Renegotiate:
2021-09-12 14:00:29 us=53995 arch/192.168.1.2:1864 VERIFY OK: depth=1, C=00, ST=home, L=tct, O=easy-tls, OU=Easy-TLS test v30a, CN=Easy-TLS v30a CA, emailAddress=tct@…
2021-09-12 14:00:29 us=56403 arch/192.168.1.2:1864 VERIFY OK: depth=0, C=00, ST=home, L=tct, O=easy-tls, OU=Easy-TLS test v30a, CN=arch-v30a, emailAddress=tct@…
2021-09-12 14:00:29 us=58728 arch/192.168.1.2:1864 peer info: IV_VER=2.6_git
2021-09-12 14:00:29 us=58777 arch/192.168.1.2:1864 peer info: IV_PLAT=linux
2021-09-12 14:00:29 us=58792 arch/192.168.1.2:1864 peer info: IV_NCP=2
2021-09-12 14:00:29 us=58806 arch/192.168.1.2:1864 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM
2021-09-12 14:00:29 us=58831 arch/192.168.1.2:1864 peer info: IV_PROTO=30
2021-09-12 14:00:29 us=58845 arch/192.168.1.2:1864 peer info: IV_LZ4=1
2021-09-12 14:00:29 us=58858 arch/192.168.1.2:1864 peer info: IV_LZ4v2=1
2021-09-12 14:00:29 us=58874 arch/192.168.1.2:1864 peer info: IV_LZO=1
2021-09-12 14:00:29 us=58887 arch/192.168.1.2:1864 peer info: IV_COMP_STUB=1
2021-09-12 14:00:29 us=58901 arch/192.168.1.2:1864 peer info: IV_COMP_STUBv2=1
2021-09-12 14:00:29 us=58916 arch/192.168.1.2:1864 peer info: IV_TCPNL=1
2021-09-12 14:00:29 us=58930 arch/192.168.1.2:1864 peer info: IV_HWADDR=00:15:5d:c9:6e:01
2021-09-12 14:00:29 us=58943 arch/192.168.1.2:1864 peer info: IV_SSL=OpenSSL_1.1.1k__25_Mar_2021
2021-09-12 14:00:29 us=58957 arch/192.168.1.2:1864 peer info: UV_TLSKEY_SERIAL=1189d5ff0d0c1f08b0ed3b1528464c16209c20b30d64bfdad257ac48844260f8
2021-09-12 14:00:29 us=60584 arch/192.168.1.2:1864 TLS: Username/Password? authentication deferred for username 'arch' [CN SET]
2021-09-12 14:00:29 us=60641 arch/192.168.1.2:1864 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1558', remote='link-mtu 1557'
2021-09-12 14:00:29 us=60662 arch/192.168.1.2:1864 WARNING: 'comp-lzo' is present in local config but missing in remote config, local='comp-lzo'
This is from my script showing -- CN username *
* delay for 7 seconds -- arch-v30a arch *
This shows that Openvpn is using username as CN in the log:
2021-09-12 14:00:29 us=64117 arch/192.168.1.2:1864 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 384 bit EC, curve secp384r1, signature: ecdsa-with-SHA256
* delay for 7 seconds -- arch-v30a arch DONE *
2021-09-12 14:00:44 us=263483 arch/192.168.1.2:1864 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2021-09-12 14:00:44 us=263580 arch/192.168.1.2:1864 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2021-09-12 14:00:50 us=294254 arch/192.168.1.2:1864 SIGTERM[soft,remote-exit] received, client-instance exiting
<ERROR> * EasyTLS-client-disconnect => vars loaded => CN:arch-v30a => disconnection success => conntrac: record not found => 1189d5ff0d0c1f08b0ed3b1528464c16209c20b30d64bfdad257ac48844260f8=6C039A9F3CA4A4B1AA9FDB9A185AF68C=arch-v30a => conn_trac_disconnect FAIL
ERROR: CONNTRAC_DISCONNECT_FAIL
XXXXX CD - Kill Server XXXXX
<EXOK> * EasyTLS-client-disconnect => vars loaded => CN:arch-v30a => disconnection success => conntrac: record not found => 1189d5ff0d0c1f08b0ed3b1528464c16209c20b30d64bfdad257ac48844260f8=6C039A9F3CA4A4B1AA9FDB9A185AF68C=arch-v30a => conn_trac_disconnect FAIL => temp-files deleted
2021-09-12 14:00:52 us=309568 TCP/UDP: Closing socket
2021-09-12 14:00:52 us=309659 /sbin/ip route del 10.10.201.0/24
2021-09-12 14:00:52 us=312882 /sbin/ip route del 10.0.0.0/8
2021-09-12 14:00:52 us=316689 /sbin/ip route del 172.16.0.0/12
2021-09-12 14:00:52 us=319040 /sbin/ip route del 192.168.0.0/16
2021-09-12 14:00:52 us=322115 /sbin/ip route del 192.168.1.0/30
2021-09-12 14:00:52 us=327233 Closing TUN/TAP interface
2021-09-12 14:00:52 us=327302 /sbin/ip addr del dev tun17122 10.171.22.1/30
2021-09-12 14:00:52 us=367382 SIGTERM[hard,] received, process exiting
comment:21 Changed 17 months ago by
Applied this patch and the problem is resolved:
tct@home:~/openvpn/master$ git diff
diff --git a/src/openvpn/multi.c b/src/openvpn/multi.c
index 22357cfb..bccb82a7 100644
--- a/src/openvpn/multi.c
+++ b/src/openvpn/multi.c
@@ -557,6 +557,9 @@ setenv_stats(struct context *c)
static void
multi_client_disconnect_setenv(struct multi_instance *mi)
{
+ /* setenv incoming cert common name for script */
+ setenv_str (mi->context.c2.es, "common_name", tls_common_name (mi->context.c2.tls_multi, true));
+
/* setenv client real IP address */
setenv_trusted(mi->context.c2.es, get_link_socket_info(&mi->context));
tct@home:~/openvpn/master$
comment:22 Changed 17 months ago by
After 8 days (192 hours) testing, Openvpn failed to provide a common_name at all.
2021-09-20 00:57:09 us=30112 core_02/192.168.1.2:4382 [UNDEF] Inactivity timeout (--ping-restart), restarting
2021-09-20 00:57:09 us=30155 core_02/192.168.1.2:4382 SIGUSR1[soft,ping-restart] received, client-instance restarting
<ERROR> * EasyTLS-client-disconnect => vars loaded => CN: => disconnection success => conntrac: record not found => 362c82b845f8ba8e4d2ba2c5f49c90107c0d0cfbf01cc687ff049087000e13f6=CF426D2E987F17B856AAD3530BD8A7AB={CN/username should be here}=10.171.22.14 => conn_trac_disconnect FAIL
ERROR: CONNTRAC_DISCONNECT_FAIL
XXXXX CD - Kill Server XXXXX
I have a 46mb log (~84 hours) which shows 47 --ping-restart events but only the last caused the script to kill the server. I attach the last ~3hours prior to failure.
Changed 17 months ago by
| Attachment: | easytls-disconnect-no-cn-3hrs.log.tar.gz added |
|---|
comment:23 Changed 17 months ago by
The snippet above shows something curious which may help diagnose the source of the problem:
2021-09-20 00:57:09 us=30155 core_02/192.168.1.2:4382 SIGUSR1
core_02 is the username not X509-CN, which means Openvpn still has this data.
But when explicitly setting common_name as:
tls_common_name (mi->context.c2.tls_multi, true)
this data is no longer available.
comment:24 Changed 17 months ago by
More info - --client-disconnect environment:
Note:
UNAME_AS_CN1=COMMON_NAMEmissing.
UV_REAL_NAME=wcore02 daemon_log_redirect=0 X509_1_emailAddress=tct@easytls.net EASYTLS_tmp_dir=/tmp script_type=client-disconnect bytes_sent=19237 ifconfig_pool_netmask=255.255.255.252 proto_1=udp6 UNAME_AS_CN1= IV_COMP_STUBv2=1 daemon=0 username=wcore_02 auth_control_file=/tmp/openvpn_acf_3da63a8803e116bb029a76947b458e.tmp X509_0_CN=core02 remote_port_1=17122 X509_1_CN=Easy-TLS v30a CA X509_1_C=00 bytes_received=15895 IV_PLAT=linux IV_TCPNL=1 IV_LZO_STUB=1 ifconfig_netmask=255.255.255.252 tls_digest_sha256_0=1a:93:44:35:b0:5b:ad:6a:71:ae:93:64:67:82:d9:93:d4:de:6f:1c:3b:8a:e2:5f:c5:e6:59:d4:24:3a:75:ea daemon_start_time=1632403994 time_duration=907 tls_digest_sha256_1=f4:4d:df:d0:84:8f:9c:37:9c:72:58:2b:09:16:33:39:7e:13:09:0c:a7:32:6b:82:a3:f0:b1:38:04:fb:24:13 ifconfig_local=10.171.22.1 time_ascii=2021-09-23 14:44:55 auth_pending_file=/tmp/openvpn_apf_778ce85ec010af05e5ab6ae5b32b1a.tmp ifconfig_pool_remote_ip=10.171.22.30 local_port_1=17122 verb=4 X509_1_L=tct IV_VER=2.6_git trusted_ip=192.168.1.2 tls_serial_hex_0=cf:42:6d:2e:98:7f:17:b8:56:aa:d3:53:0b:d8:a7:ab X509_1_O=easy-tls tls_serial_hex_1=70:bf:f9:a7:df:21:1f:d5:92:d1:fd:79:99:1a:f5:f7:19:2b:b1:fa trusted_port=4336 tls_id_0=CN=core02 IV_SSL=OpenSSL_1.1.1f__31_Mar_2020 tls_id_1=C=00, ST=home, L=tct, O=easy-tls, OU=Easy-TLS test v30a, CN=Easy-TLS v30a CA, emailAddress=tct@easytls.net time_unix=1632408295 daemon_pid=333611 X509_1_OU=Easy-TLS test v30a config=wiscii-v31a-ca.conf untrusted_ip=192.168.1.2 IV_HWADDR=00:00:00:aa:00:08 tls_serial_0=275495101194478525089617373891860670379 tls_digest_0=a1:aa:7f:ad:4e:44:4d:ff:32:20:1f:c8:07:ac:14:68:fc:ab:74:28 UV_TLSKEY_SERIAL=362c82b845f8ba8e4d2ba2c5f49c90107c0d0cfbf01cc687ff049087000e13f6 IV_COMP_STUB=1 IV_PROTO=30 tls_serial_1=643688156748131494364386735879387197645559411194 tls_digest_1=24:a3:72:48:c2:3f:02:10:9c:ef:07:c7:6c:0d:c4:d4:6a:48:a3:8d X509_1_ST=home untrusted_port=4336 PWD=/ IV_CIPHERS=CHACHA20-POLY1305
comment:25 Changed 16 months ago by
UNAME_AS_CN1 was added by my server config, why is it named but not set ?
I had setenv UNAME_AS_CN=1 but did not get an error.
comment:26 follow-up: 27 Changed 16 months ago by
I believe there are two separate issues here:
- The original issue:
Openvpn "sometimes" reverts
common_nameback to X509-CN instead of correctly usingusernameas instructed.
The patch included here appears to fix this completely.
- Problem with
--tls-crypt-v2-verifyscript.
When using TLS-Crypt-V2 keys then Openvpn "often" fails to set
common_nameat all.
Cause: Unknown.
comment:27 Changed 16 months ago by
Replying to tct:
- Problem with
--tls-crypt-v2-verifyscript.When using TLS-Crypt-V2 keys then Openvpn "often" fails to set
common_nameat all.
Cause: Unknown.
I can now reliably reproduce this problem:
- Connect to server with UDP (TCP not tested)
- Attempt to float but fail due to bad routing. (return routes to the client are not complete)
- Wait for the connection to time out on the server.
- When the server runs
--client-disconnectthencommon_nameis not present inenv.
This dos not require TLS-Crypt-V2 keys, it will happen with TLS-Auth keys also.
After hours of testing I found that, to cause this issue, TLS-Crypt-V2 is required.
After hours more testing I found that, even this test is not enough to consistently trigger the issue.
comment:28 Changed 16 months ago by
I ran a 12 hour test and caught the Number-2 problem above 15 times.
10/06/21 03:45:21 NF DIS: TLSAC=0FB933C7BEB929C71DC0BA1842D58CFF==10.171.22.202==10.20.1.2:49341 10/06/21 03:46:04 NF DIS: ff24f52a74a8338c667638824f8d2f0f8b68d3567fc584ca9258e635e8326384=91C8F9DE11E334ED41DF50407F43AE9A==10.171.22.201==10.20.1.2:60464 10/06/21 03:47:09 NF DIS: 362c82b845f8ba8e4d2ba2c5f49c90107c0d0cfbf01cc687ff049087000e13f6=CF426D2E987F17B856AAD3530BD8A7AB==10.171.22.203==10.20.1.2:33789 10/06/21 04:46:52 NF DIS: ff24f52a74a8338c667638824f8d2f0f8b68d3567fc584ca9258e635e8326384=91C8F9DE11E334ED41DF50407F43AE9A==10.171.22.201==10.20.1.2:50761 10/06/21 04:47:31 NF DIS: 362c82b845f8ba8e4d2ba2c5f49c90107c0d0cfbf01cc687ff049087000e13f6=CF426D2E987F17B856AAD3530BD8A7AB==10.171.22.203==10.20.1.2:41922 10/06/21 05:47:29 NF DIS: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5=817D664B73EF39A1A788E84E685DC5EB==10.171.22.204==10.20.1.2:54250 10/06/21 06:45:11 NF DIS: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5=817D664B73EF39A1A788E84E685DC5EB==10.171.22.203==10.20.1.2:60200 10/06/21 07:47:15 NF DIS: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5=817D664B73EF39A1A788E84E685DC5EB==10.171.22.203==10.20.1.2:53191 10/06/21 10:45:02 NF DIS: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5=817D664B73EF39A1A788E84E685DC5EB==10.171.22.203==10.20.1.2:36749 10/06/21 10:45:30 NF DIS: TLSAC=0FB933C7BEB929C71DC0BA1842D58CFF==10.171.22.202==10.20.1.2:45151 10/06/21 11:45:26 NF DIS: TLSAC=0FB933C7BEB929C71DC0BA1842D58CFF==10.171.22.202==10.20.1.2:56604 10/06/21 11:47:09 NF DIS: ff24f52a74a8338c667638824f8d2f0f8b68d3567fc584ca9258e635e8326384=91C8F9DE11E334ED41DF50407F43AE9A==10.171.22.201==10.20.1.2:56170 10/06/21 11:47:12 NF DIS: 362c82b845f8ba8e4d2ba2c5f49c90107c0d0cfbf01cc687ff049087000e13f6=CF426D2E987F17B856AAD3530BD8A7AB==10.171.22.204==10.20.1.2:34613 10/06/21 12:47:17 NF DIS: 362c82b845f8ba8e4d2ba2c5f49c90107c0d0cfbf01cc687ff049087000e13f6=CF426D2E987F17B856AAD3530BD8A7AB==10.171.22.204==10.20.1.2:37164 10/06/21 12:47:35 NF DIS: TLSAC=0FB933C7BEB929C71DC0BA1842D58CFF==10.171.22.202==10.20.1.2:34115 10/06/21 14:46:50 NF DIS: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5=817D664B73EF39A1A788E84E685DC5EB==10.171.22.204==10.20.1.2:43591 10/06/21 15:46:58 NF DIS: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5=817D664B73EF39A1A788E84E685DC5EB==10.171.22.204==10.20.1.2:52712
Each record above is missing the common_name (username) between the first double equal == (The second is a typo)
The records above show that this happens for TLS-Auth and TLS-Crypt-V2.
The test is exactly as described above.
comment:29 Changed 16 months ago by
comment:30 Changed 16 months ago by
comment:31 Changed 16 months ago by
| Resolution: | → duplicate |
|---|---|
| Status: | accepted → closed |
Closed - Follow up #1434
comment:32 Changed 16 months ago by
Sooo. Due to the long and hard testing done by @tct, we seem to have found ways this could be triggered in 2.5 and master (client-as-username, wait for a renegotiation, then disconnect without explicit-exit-notify).
A patch has been proposed & merged in the context of #1434, so this should now be fixed in 2.4 (if ever released, 2.4.12), 2.5.5 and 2.6.0.
this has been reported before in the openvpn-users mailing list but nobody was able to reproduce this bug. A patch was presented, which fixes the issue, but this patch was not applied due to the reproducability issues. The patch is:
--- multi.c 2009-10-24 21:17:29.000000000 -0200
+++ multi.c.patched 2010-03-02 14:57:12.000000000 -0300
@@ -447,6 +447,9 @@
+ /* setenv incoming cert common name for script */
+ setenv_str (mi->context.c2.es, "common_name", tls_common_name
(mi->context.c2.tls_multi, true));
+
(this was for 2.1)