Opened 3 years ago

Closed 2 years ago

#1434 closed Bug / Defect (fixed)

Client-disconnect script env does not have common_name

Reported by: tct Owned by:
Priority: major Milestone: release 2.5.5
Component: Generic / unclassified Version: OpenVPN git master branch (Community Ed)
Severity: Not set (select this one, unless your'e a OpenVPN developer) Keywords:
Cc:

Description (last modified by tct)

Under certain circumstances, --client-disconnect has the wrong value for common_name in the env.

In this case --username-as-common-name is in use and username is not the same as common_name.

Follow-up to #160 #1370

Possibly Related to: #167

What actually takes place is as follows:

  1. Client connects normally - UDP - username is assigned to common_name
  2. Client renegotiates normally.
  3. Client disconnects normally.

This leads the server supplying common_name not username to --client-disconnect, every time.

I ran a single standard server and a single standard client.
I used a simple script to monotonically dis/enable routing to the server, over a period of 10mins.
The client uses --reneg-sec 270, so the client has always done a renegotiate when the routing becomes disabled. Then the server does --ping-timeout for the client.
Then the server runs --client-disconnect with the wrong value for common_name, every time.

The server ran for ~20 hours and generated this error 130 times.

Change History (16)

comment:1 Changed 3 years ago by tct

If JJK's patch is applied then the behaviour becomes slightly different but the problem is not resolved.

In this case, the client does the following:

  1. Connect normally - UDP - username is assigned to common_name
  2. Renegotiate normally.
  3. Float normally. Not required
  4. Disconnect normally by time-out only.

This leads to the server not supplying any value to common_name for --client-disconnect.

Last edited 3 years ago by tct (previous) (diff)

comment:2 Changed 3 years ago by tct

FTR

This log shows how JJK's patch still fails:

2021-10-18 20:49:40 us=215762 Note: --cipher is not set. OpenVPN versions before 2.6 defaulted to BF-CBC as fallback when cipher negotiation failed in this case. If you need this fallback please add '--data-ciphers-fallback 'BF-CBC' to your configuration and/or add BF-CBC to --data-ciphers.
2021-10-18 20:49:40 us=216009 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2021-10-18 20:49:40 us=216049 Current Parameter Settings:
2021-10-18 20:49:40 us=216081   config = 'wiscii-v31a-ca.conf'
2021-10-18 20:49:40 us=216103   mode = 1
2021-10-18 20:49:40 us=216121   persist_config = DISABLED
2021-10-18 20:49:40 us=216140   persist_mode = 1
2021-10-18 20:49:40 us=216157   show_ciphers = DISABLED
2021-10-18 20:49:40 us=216176   show_digests = DISABLED
2021-10-18 20:49:40 us=216200   show_engines = DISABLED
2021-10-18 20:49:40 us=216219   genkey = DISABLED
2021-10-18 20:49:40 us=216237   genkey_filename = '[UNDEF]'
2021-10-18 20:49:40 us=216256   key_pass_file = '[UNDEF]'
2021-10-18 20:49:40 us=216275   show_tls_ciphers = DISABLED
2021-10-18 20:49:40 us=216293   connect_retry_max = 0
2021-10-18 20:49:40 us=216311 Connection profiles [0]:
2021-10-18 20:49:40 us=216438   proto = udp6
2021-10-18 20:49:40 us=216523   local = '[UNDEF]'
2021-10-18 20:49:40 us=216617   local_port = '17122'
2021-10-18 20:49:40 us=216699   remote = '[UNDEF]'
2021-10-18 20:49:40 us=216803   remote_port = '17122'
2021-10-18 20:49:40 us=216890   remote_float = DISABLED
2021-10-18 20:49:40 us=216983   bind_defined = DISABLED
2021-10-18 20:49:40 us=217058   bind_local = ENABLED
2021-10-18 20:49:40 us=217140   bind_ipv6_only = DISABLED
2021-10-18 20:49:40 us=217223   connect_retry_seconds = 5
2021-10-18 20:49:40 us=217336   connect_timeout = 120
2021-10-18 20:49:40 us=217677   socks_proxy_server = '[UNDEF]'
2021-10-18 20:49:40 us=217762   socks_proxy_port = '[UNDEF]'
2021-10-18 20:49:40 us=217850   tun_mtu = 1500
2021-10-18 20:49:40 us=217936   tun_mtu_defined = ENABLED
2021-10-18 20:49:40 us=217955   link_mtu = 1500
2021-10-18 20:49:40 us=217969   link_mtu_defined = DISABLED
2021-10-18 20:49:40 us=217982   tun_mtu_extra = 0
2021-10-18 20:49:40 us=217995   tun_mtu_extra_defined = DISABLED
2021-10-18 20:49:40 us=218007   mtu_discover_type = -1
2021-10-18 20:49:40 us=218019   fragment = 0
2021-10-18 20:49:40 us=218031   mssfix = 1450
2021-10-18 20:49:40 us=218043   explicit_exit_notification = 1
2021-10-18 20:49:40 us=218055   tls_auth_file = '[INLINE]'
2021-10-18 20:49:40 us=218068   key_direction = not set
2021-10-18 20:49:40 us=218079   tls_crypt_file = '[UNDEF]'
2021-10-18 20:49:40 us=218091   tls_crypt_v2_file = '[INLINE]'
2021-10-18 20:49:40 us=218104 Connection profiles END
2021-10-18 20:49:40 us=218116   remote_random = DISABLED
2021-10-18 20:49:40 us=218126   ipchange = '[UNDEF]'
2021-10-18 20:49:40 us=218139   dev = 'tun17122'
2021-10-18 20:49:40 us=218151   dev_type = '[UNDEF]'
2021-10-18 20:49:40 us=218164   dev_node = '[UNDEF]'
2021-10-18 20:49:40 us=218177   lladdr = '[UNDEF]'
2021-10-18 20:49:40 us=218189   topology = 3
2021-10-18 20:49:40 us=218202   ifconfig_local = '10.171.22.1'
2021-10-18 20:49:40 us=218216   ifconfig_remote_netmask = '255.255.255.0'
2021-10-18 20:49:40 us=218229   ifconfig_noexec = DISABLED
2021-10-18 20:49:40 us=218241   ifconfig_nowarn = DISABLED
2021-10-18 20:49:40 us=218252   ifconfig_ipv6_local = '[UNDEF]'
2021-10-18 20:49:40 us=218264   ifconfig_ipv6_netbits = 0
2021-10-18 20:49:40 us=218278   ifconfig_ipv6_remote = '[UNDEF]'
2021-10-18 20:49:40 us=218293   shaper = 0
2021-10-18 20:49:40 us=218316   mtu_test = 0
2021-10-18 20:49:40 us=218336   mlock = DISABLED
2021-10-18 20:49:40 us=218354   keepalive_ping = 0
2021-10-18 20:49:40 us=218372   keepalive_timeout = 0
2021-10-18 20:49:40 us=218391   inactivity_timeout = 0
2021-10-18 20:49:40 us=218409   ping_send_timeout = 90
2021-10-18 20:49:40 us=218426   ping_rec_timeout = 180
2021-10-18 20:49:40 us=218444   ping_rec_timeout_action = 2
2021-10-18 20:49:40 us=218461   ping_timer_remote = DISABLED
2021-10-18 20:49:40 us=218479   remap_sigusr1 = 0
2021-10-18 20:49:40 us=218496   persist_tun = ENABLED
2021-10-18 20:49:40 us=218515   persist_local_ip = DISABLED
2021-10-18 20:49:40 us=218534   persist_remote_ip = DISABLED
2021-10-18 20:49:40 us=218554   persist_key = ENABLED
2021-10-18 20:49:40 us=218573   passtos = DISABLED
2021-10-18 20:49:40 us=218601   resolve_retry_seconds = 1000000000
2021-10-18 20:49:40 us=218648   resolve_in_advance = DISABLED
2021-10-18 20:49:40 us=218674   username = '[UNDEF]'
2021-10-18 20:49:40 us=218696   groupname = '[UNDEF]'
2021-10-18 20:49:40 us=218716   chroot_dir = '/var/easytls'
2021-10-18 20:49:40 us=218741   cd_dir = '[UNDEF]'
2021-10-18 20:49:40 us=218761   writepid = '[UNDEF]'
2021-10-18 20:49:40 us=218779   up_script = '[UNDEF]'
2021-10-18 20:49:40 us=218799   down_script = '[UNDEF]'
2021-10-18 20:49:40 us=218821   down_pre = DISABLED
2021-10-18 20:49:40 us=218841   up_restart = DISABLED
2021-10-18 20:49:40 us=218863   up_delay = DISABLED
2021-10-18 20:49:40 us=218957   daemon = DISABLED
2021-10-18 20:49:40 us=219039   log = DISABLED
2021-10-18 20:49:40 us=219124   suppress_timestamps = DISABLED
2021-10-18 20:49:40 us=219170   machine_readable_output = DISABLED
2021-10-18 20:49:40 us=219187   nice = 0
2021-10-18 20:49:40 us=219200   verbosity = 4
2021-10-18 20:49:40 us=219213   mute = 0
2021-10-18 20:49:40 us=219227   gremlin = 0
2021-10-18 20:49:40 us=219241   status_file = '[UNDEF]'
2021-10-18 20:49:40 us=219255   status_file_version = 1
2021-10-18 20:49:40 us=219269   status_file_update_freq = 60
2021-10-18 20:49:40 us=219281   occ = ENABLED
2021-10-18 20:49:40 us=219295   rcvbuf = 0
2021-10-18 20:49:40 us=219308   sndbuf = 0
2021-10-18 20:49:40 us=219322   mark = 0
2021-10-18 20:49:40 us=219335   sockflags = 0
2021-10-18 20:49:40 us=219349   fast_io = DISABLED
2021-10-18 20:49:40 us=219362   comp.alg = 1
2021-10-18 20:49:40 us=219375   comp.flags = 24
2021-10-18 20:49:40 us=219389   route_script = '[UNDEF]'
2021-10-18 20:49:40 us=219402   route_default_gateway = '10.171.22.2'
2021-10-18 20:49:40 us=219415   route_default_metric = 0
2021-10-18 20:49:40 us=219428   route_noexec = DISABLED
2021-10-18 20:49:40 us=219443   route_delay = 0
2021-10-18 20:49:40 us=219456   route_delay_window = 30
2021-10-18 20:49:40 us=219469   route_delay_defined = DISABLED
2021-10-18 20:49:40 us=219482   route_nopull = DISABLED
2021-10-18 20:49:40 us=219496   route_gateway_via_dhcp = DISABLED
2021-10-18 20:49:40 us=219509   allow_pull_fqdn = DISABLED
2021-10-18 20:49:40 us=219523   management_addr = '127.0.0.1'
2021-10-18 20:49:40 us=219536   management_port = '17101'
2021-10-18 20:49:40 us=219550   management_user_pass = '[UNDEF]'
2021-10-18 20:49:40 us=219564   management_log_history_cache = 250
2021-10-18 20:49:40 us=219578   management_echo_buffer_size = 100
2021-10-18 20:49:40 us=219591   management_write_peer_info_file = '[UNDEF]'
2021-10-18 20:49:40 us=219605   management_client_user = '[UNDEF]'
2021-10-18 20:49:40 us=219618   management_client_group = '[UNDEF]'
2021-10-18 20:49:40 us=219632   management_flags = 0
2021-10-18 20:49:40 us=219645   shared_secret_file = '[UNDEF]'
2021-10-18 20:49:40 us=219659   key_direction = not set
2021-10-18 20:49:40 us=219672   ciphername = 'BF-CBC'
2021-10-18 20:49:40 us=219686   ncp_ciphers = 'CHACHA20-POLY1305:AES-256-GCM:AES-128-GCM'
2021-10-18 20:49:40 us=219700   authname = 'SHA1'
2021-10-18 20:49:40 us=219714   prng_hash = 'SHA1'
2021-10-18 20:49:40 us=219728   prng_nonce_secret_len = 16
2021-10-18 20:49:40 us=219741   engine = DISABLED
2021-10-18 20:49:40 us=219754   replay = ENABLED
2021-10-18 20:49:40 us=219768   mute_replay_warnings = DISABLED
2021-10-18 20:49:40 us=219782   replay_window = 64
2021-10-18 20:49:40 us=219795   replay_time = 15
2021-10-18 20:49:40 us=219809   packet_id_file = '[UNDEF]'
2021-10-18 20:49:40 us=219822   test_crypto = DISABLED
2021-10-18 20:49:40 us=219835   tls_server = ENABLED
2021-10-18 20:49:40 us=219849   tls_client = DISABLED
2021-10-18 20:49:40 us=219862   ca_file = '[INLINE]'
2021-10-18 20:49:40 us=219875   ca_path = '[UNDEF]'
2021-10-18 20:49:40 us=219889   dh_file = '[UNDEF]'
2021-10-18 20:49:40 us=219902   cert_file = '[INLINE]'
2021-10-18 20:49:40 us=219915   extra_certs_file = '[UNDEF]'
2021-10-18 20:49:40 us=219929   priv_key_file = '[INLINE]'
2021-10-18 20:49:40 us=219943   pkcs12_file = '[UNDEF]'
2021-10-18 20:49:40 us=219956   cipher_list = '[UNDEF]'
2021-10-18 20:49:40 us=219971   cipher_list_tls13 = 'TLS_CHACHA20_POLY1305_SHA256:TLS_AES_256_GCM_SHA384'
2021-10-18 20:49:40 us=219985   tls_cert_profile = '[UNDEF]'
2021-10-18 20:49:40 us=219998   tls_verify = '[UNDEF]'
2021-10-18 20:49:40 us=220012   tls_export_cert = '/tmp'
2021-10-18 20:49:40 us=220026   verify_x509_type = 0
2021-10-18 20:49:40 us=220039   verify_x509_name = '[UNDEF]'
2021-10-18 20:49:40 us=220053   crl_file = '[UNDEF]'
2021-10-18 20:49:40 us=220067   ns_cert_type = 0
2021-10-18 20:49:40 us=220081   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220095   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220108   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220122   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220135   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220149   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220163   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220177   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220190   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220204   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220217   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220232   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220245   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220258   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220272   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220286   remote_cert_ku[i] = 0
2021-10-18 20:49:40 us=220299   remote_cert_eku = '[UNDEF]'
2021-10-18 20:49:40 us=220313   ssl_flags = 260
2021-10-18 20:49:40 us=220326   tls_timeout = 2
2021-10-18 20:49:40 us=220339   renegotiate_bytes = -1
2021-10-18 20:49:40 us=220352   renegotiate_packets = 0
2021-10-18 20:49:40 us=220366   renegotiate_seconds = 600
2021-10-18 20:49:40 us=220379   handshake_window = 60
2021-10-18 20:49:40 us=220392   transition_window = 3600
2021-10-18 20:49:40 us=220406   single_session = DISABLED
2021-10-18 20:49:40 us=220419   push_peer_info = DISABLED
2021-10-18 20:49:40 us=220432   tls_exit = DISABLED
2021-10-18 20:49:40 us=220446   tls_crypt_v2_metadata = '[UNDEF]'
2021-10-18 20:49:40 us=220462   server_network = 0.0.0.0
2021-10-18 20:49:40 us=220477   server_netmask = 0.0.0.0
2021-10-18 20:49:40 us=220493   server_network_ipv6 = ::
2021-10-18 20:49:40 us=220507   server_netbits_ipv6 = 0
2021-10-18 20:49:40 us=220522   server_bridge_ip = 0.0.0.0
2021-10-18 20:49:40 us=220537   server_bridge_netmask = 0.0.0.0
2021-10-18 20:49:40 us=220551   server_bridge_pool_start = 0.0.0.0
2021-10-18 20:49:40 us=220566   server_bridge_pool_end = 0.0.0.0
2021-10-18 20:49:40 us=220620   push_entry = 'topology subnet'
2021-10-18 20:49:40 us=220634   push_entry = 'route-gateway 10.171.22.1'
2021-10-18 20:49:40 us=220648   push_entry = 'route 10.171.22.1'
2021-10-18 20:49:40 us=220662   push_entry = 'route 10.66.67.101'
2021-10-18 20:49:40 us=220675   push_entry = 'comp-lzo no'
2021-10-18 20:49:40 us=220687   ifconfig_pool_defined = ENABLED
2021-10-18 20:49:40 us=220701   ifconfig_pool_start = 10.171.22.201
2021-10-18 20:49:40 us=220714   ifconfig_pool_end = 10.171.22.209
2021-10-18 20:49:40 us=220728   ifconfig_pool_netmask = 0.0.0.0
2021-10-18 20:49:40 us=220742   ifconfig_pool_persist_filename = '[UNDEF]'
2021-10-18 20:49:40 us=220756   ifconfig_pool_persist_refresh_freq = 600
2021-10-18 20:49:40 us=220770   ifconfig_ipv6_pool_defined = DISABLED
2021-10-18 20:49:40 us=220785   ifconfig_ipv6_pool_base = ::
2021-10-18 20:49:40 us=220799   ifconfig_ipv6_pool_netbits = 0
2021-10-18 20:49:40 us=220813   n_bcast_buf = 256
2021-10-18 20:49:40 us=220827   tcp_queue_limit = 64
2021-10-18 20:49:40 us=220841   real_hash_size = 256
2021-10-18 20:49:40 us=220854   virtual_hash_size = 256
2021-10-18 20:49:40 us=220867   client_connect_script = '/etc/openvpn/server/v31a/easytls-client-connect.sh -v -l=/etc/openvpn/server/v31a/easytls-client-connect.vars'
2021-10-18 20:49:40 us=220881   learn_address_script = '[UNDEF]'
2021-10-18 20:49:40 us=220894   client_disconnect_script = '/etc/openvpn/server/v31a/easytls-client-disconnect.sh -v -l=/etc/openvpn/server/v31a/easytls-client-disconnect.vars'
2021-10-18 20:49:40 us=220909   client_config_dir = '/etc/openvpn/server/v31a/ccd'
2021-10-18 20:49:40 us=220922   ccd_exclusive = ENABLED
2021-10-18 20:49:40 us=220935   tmp_dir = '/tmp'
2021-10-18 20:49:40 us=220948   push_ifconfig_defined = DISABLED
2021-10-18 20:49:40 us=220962   push_ifconfig_local = 0.0.0.0
2021-10-18 20:49:40 us=220988   push_ifconfig_remote_netmask = 0.0.0.0
2021-10-18 20:49:40 us=221002   push_ifconfig_ipv6_defined = DISABLED
2021-10-18 20:49:40 us=221017   push_ifconfig_ipv6_local = ::/0
2021-10-18 20:49:40 us=221032   push_ifconfig_ipv6_remote = ::
2021-10-18 20:49:40 us=221045   enable_c2c = DISABLED
2021-10-18 20:49:40 us=221059   duplicate_cn = DISABLED
2021-10-18 20:49:40 us=221072   cf_max = 0
2021-10-18 20:49:40 us=221086   cf_per = 0
2021-10-18 20:49:40 us=221099   max_clients = 1024
2021-10-18 20:49:40 us=221113   max_routes_per_client = 256
2021-10-18 20:49:40 us=221126   auth_user_pass_verify_script = '/etc/openvpn/server/v31a/easytls-defer-userpass-verify.sh'
2021-10-18 20:49:40 us=221140   auth_user_pass_verify_script_via_file = DISABLED
2021-10-18 20:49:40 us=221153   auth_token_generate = DISABLED
2021-10-18 20:49:40 us=221167   auth_token_lifetime = 0
2021-10-18 20:49:40 us=221177   auth_token_secret_file = '[UNDEF]'
2021-10-18 20:49:40 us=221208   port_share_host = '[UNDEF]'
2021-10-18 20:49:40 us=221232   port_share_port = '[UNDEF]'
2021-10-18 20:49:40 us=221254   vlan_tagging = DISABLED
2021-10-18 20:49:40 us=221275   vlan_accept = all
2021-10-18 20:49:40 us=221299   vlan_pvid = 1
2021-10-18 20:49:40 us=221321   client = DISABLED
2021-10-18 20:49:40 us=221342   pull = DISABLED
2021-10-18 20:49:40 us=221364   auth_user_pass_file = '[UNDEF]'
2021-10-18 20:49:40 us=221389 OpenVPN 2.6_git [git:master/01ce6ca39d1f4bf4] x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Oct 18 2021
2021-10-18 20:49:40 us=221425 library versions: OpenSSL 1.1.1f  31 Mar 2020, LZO 2.10
2021-10-18 20:49:40 us=221527 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:17101
2021-10-18 20:49:40 us=221593 WARNING: you are using chroot without specifying user and group -- this may cause the chroot jail to be insecure
2021-10-18 20:49:40 us=221605 WARNING: --keepalive option is missing from server config
2021-10-18 20:49:40 us=221719 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
2021-10-18 20:49:40 us=222601 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 20:49:40 us=222623 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 20:49:40 us=222646 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:49:40 us=222662 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:49:40 us=222680 TLS-Auth MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-10-18 20:49:40 us=224650 TUN/TAP device tun17122 opened
2021-10-18 20:49:40 us=224709 do_ifconfig, ipv4=1, ipv6=0
2021-10-18 20:49:40 us=224734 /sbin/ip link set dev tun17122 up mtu 1500
2021-10-18 20:49:40 us=230218 /sbin/ip link set dev tun17122 up
2021-10-18 20:49:40 us=232202 /sbin/ip addr add dev tun17122 10.171.22.1/24
2021-10-18 20:49:40 us=235151 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 20:49:40 us=235209 Socket Buffers: R=[212992->212992] S=[212992->212992]
2021-10-18 20:49:40 us=235222 setsockopt(IPV6_V6ONLY=0)
2021-10-18 20:49:40 us=235247 UDPv6 link local (bound): [AF_INET6][undef]:17122
2021-10-18 20:49:40 us=235258 UDPv6 link remote: [AF_UNSPEC]
2021-10-18 19:49:40 us=235274 chroot to '/var/easytls' and cd to '/' succeeded
2021-10-18 19:49:40 us=235305 MULTI: multi_init called, r=256 v=256
2021-10-18 19:49:40 us=235331 IFCONFIG POOL IPv4: base=10.171.22.201 size=9
2021-10-18 19:49:40 us=235429 Initialization Sequence Completed
reneg_sec: 600
restart_sec: 43200
2021-10-18 19:50:33 us=114348 Control Channel: using tls-crypt-v2 key
2021-10-18 19:50:33 us=114430 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:50:33 us=114462 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:50:33 us=114480 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:50:33 us=114502 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:50:33 us=114525 MULTI: multi_create_instance called
2021-10-18 19:50:33 us=114565 10.20.2.2:47660 Re-using SSL/TLS context
2021-10-18 19:50:33 us=114648 10.20.2.2:47660 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 19:50:33 us=114667 10.20.2.2:47660 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 19:50:33 us=114699 10.20.2.2:47660 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:50:33 us=114719 10.20.2.2:47660 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:50:33 us=114844 10.20.2.2:47660 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-10-18 19:50:33 us=114864 10.20.2.2:47660 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 19:50:33 us=114903 10.20.2.2:47660 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-10-18 19:50:33 us=114918 10.20.2.2:47660 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-10-18 19:50:33 us=114952 10.20.2.2:47660 TLS: Initial packet from [AF_INET6]::ffff:10.20.2.2:47660, sid=8d720700 9bb3f2e3
2021-10-18 19:50:33 us=114968 10.20.2.2:47660 Control Channel: using tls-crypt-v2 key
2021-10-18 19:50:33 us=114994 10.20.2.2:47660 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:50:33 us=115013 10.20.2.2:47660 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:50:33 us=115033 10.20.2.2:47660 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:50:33 us=115052 10.20.2.2:47660 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 19:50:33 us=128163 10.20.2.2:47660 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 19:50:53 us=490563 Control Channel: using tls-crypt-v2 key
2021-10-18 19:50:53 us=490676 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:50:53 us=490720 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:50:53 us=490750 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:50:53 us=490784 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:50:53 us=490828 MULTI: multi_create_instance called
2021-10-18 19:50:53 us=490880 10.20.1.2:47660 Re-using SSL/TLS context
2021-10-18 19:50:53 us=491017 10.20.1.2:47660 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 19:50:53 us=491048 10.20.1.2:47660 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 19:50:53 us=491112 10.20.1.2:47660 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:50:53 us=491155 10.20.1.2:47660 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:50:53 us=491346 10.20.1.2:47660 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-10-18 19:50:53 us=491379 10.20.1.2:47660 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 19:50:53 us=491465 10.20.1.2:47660 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-10-18 19:50:53 us=491499 10.20.1.2:47660 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-10-18 19:50:53 us=491587 10.20.1.2:47660 TLS: Initial packet from [AF_INET6]::ffff:10.20.1.2:47660, sid=8d720700 9bb3f2e3
2021-10-18 19:50:53 us=491637 10.20.1.2:47660 Control Channel: using tls-crypt-v2 key
2021-10-18 19:50:53 us=491681 10.20.1.2:47660 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:50:53 us=491710 10.20.1.2:47660 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:50:53 us=491741 10.20.1.2:47660 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:50:53 us=491765 10.20.1.2:47660 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 19:50:53 us=513041 10.20.1.2:47660 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 19:51:33 us=832911 10.20.2.2:47660 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 19:51:33 us=833013 10.20.2.2:47660 TLS Error: TLS handshake failed
2021-10-18 19:51:33 us=833310 10.20.2.2:47660 SIGUSR1[soft,tls-error] received, client-instance restarting
2021-10-18 19:51:38 us=326321 Control Channel: using tls-crypt-v2 key
2021-10-18 19:51:38 us=326477 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:51:38 us=326537 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:51:38 us=326607 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:51:38 us=326661 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:51:38 us=326720 MULTI: multi_create_instance called
2021-10-18 19:51:38 us=326815 10.20.1.2:34723 Re-using SSL/TLS context
2021-10-18 19:51:38 us=327074 10.20.1.2:34723 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 19:51:38 us=327123 10.20.1.2:34723 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 19:51:38 us=327212 10.20.1.2:34723 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:51:38 us=327265 10.20.1.2:34723 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:51:38 us=327378 10.20.1.2:34723 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-10-18 19:51:38 us=327409 10.20.1.2:34723 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 19:51:38 us=327477 10.20.1.2:34723 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-10-18 19:51:38 us=327502 10.20.1.2:34723 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-10-18 19:51:38 us=327585 10.20.1.2:34723 TLS: Initial packet from [AF_INET6]::ffff:10.20.1.2:34723, sid=2fbdb65b 5fc6aa89
2021-10-18 19:51:38 us=327615 10.20.1.2:34723 Control Channel: using tls-crypt-v2 key
2021-10-18 19:51:38 us=327679 10.20.1.2:34723 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:51:38 us=327722 10.20.1.2:34723 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:51:38 us=327756 10.20.1.2:34723 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:51:38 us=327795 10.20.1.2:34723 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 19:51:38 us=347384 10.20.1.2:34723 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 19:51:38 us=367255 10.20.1.2:34723 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@easytls.net
2021-10-18 19:51:38 us=369148 10.20.1.2:34723 VERIFY OK: depth=0, CN=core01
2021-10-18 19:51:38 us=369519 10.20.1.2:34723 peer info: IV_VER=2.6_git
2021-10-18 19:51:38 us=369551 10.20.1.2:34723 peer info: IV_PLAT=linux
2021-10-18 19:51:38 us=369576 10.20.1.2:34723 peer info: IV_CIPHERS=CHACHA20-POLY1305
2021-10-18 19:51:38 us=369589 10.20.1.2:34723 peer info: IV_PROTO=30
2021-10-18 19:51:38 us=369605 10.20.1.2:34723 peer info: IV_LZO_STUB=1
2021-10-18 19:51:38 us=369619 10.20.1.2:34723 peer info: IV_COMP_STUB=1
2021-10-18 19:51:38 us=369634 10.20.1.2:34723 peer info: IV_COMP_STUBv2=1
2021-10-18 19:51:38 us=369650 10.20.1.2:34723 peer info: IV_TCPNL=1
2021-10-18 19:51:38 us=369665 10.20.1.2:34723 peer info: IV_HWADDR=00:00:00:aa:00:03
2021-10-18 19:51:38 us=369683 10.20.1.2:34723 peer info: IV_SSL=OpenSSL_1.1.1f__31_Mar_2020
2021-10-18 19:51:38 us=369700 10.20.1.2:34723 peer info: UV_TLSKEY_SERIAL=638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5
2021-10-18 19:51:38 us=369716 10.20.1.2:34723 peer info: UV_REAL_NAME=core01
2021-10-18 19:51:38 us=371490 10.20.1.2:34723 TLS: Username/Password authentication deferred for username 'core_01_b' [CN SET]
2021-10-18 19:51:38 us=371544 10.20.1.2:34723 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1558', remote='link-mtu 1557'
2021-10-18 19:51:38 us=371584 10.20.1.2:34723 WARNING: 'comp-lzo' is present in local config but missing in remote config, local='comp-lzo'

***** delay for 7 seconds -- core01 core_01_b *****

2021-10-18 19:51:38 us=373612 10.20.1.2:34723 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_CHACHA20_POLY1305_SHA256, peer certificate: 2048 bit RSA, signature: ecdsa-with-SHA256
2021-10-18 19:51:38 us=373696 10.20.1.2:34723 [core_01_b] Peer Connection Initiated with [AF_INET6]::ffff:10.20.1.2:34723
2021-10-18 19:51:39 us=422678 10.20.1.2:34723 PUSH: Received control message: 'PUSH_REQUEST'
2021-10-18 19:51:44 us=476448 10.20.1.2:34723 PUSH: Received control message: 'PUSH_REQUEST'

***** delay for 7 seconds -- core01 core_01_b DONE *****

2021-10-18 19:51:45 us=611038 core_01_b/10.20.1.2:34723 MULTI_sva: pool returned IPv4=10.171.22.201, IPv6=(Not enabled)
2021-10-18 19:51:45 us=611179 core_01_b/10.20.1.2:34723 OPTIONS IMPORT: reading client specific options from: /etc/openvpn/server/v31a/ccd/core_01_b
<EXOK> * EasyTLS-client-connect => vars loaded => dyn opts loaded => CN: core_01_b => conntrac: tallied => conntrac: registered => tls key serial: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5 => fixed_md_file loaded => metadata -> x509 serial match => Key is not locked to hwaddr => connection allowed => temp-files deleted

2021-10-18 19:51:45 us=635510 core_01_b/10.20.1.2:34723 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_6577ee89169eeb5c17d9c64f71586892.tmp
2021-10-18 19:51:45 us=635763 core_01_b/10.20.1.2:34723 OPTIONS IMPORT: timers and/or timeouts modified
2021-10-18 19:51:45 us=635805 core_01_b/10.20.1.2:34723 MULTI: Learn: 10.171.22.201 -> core_01_b/10.20.1.2:34723
2021-10-18 19:51:45 us=635823 core_01_b/10.20.1.2:34723 MULTI: primary virtual IP for core_01_b/10.20.1.2:34723: 10.171.22.201
2021-10-18 19:51:45 us=635857 core_01_b/10.20.1.2:34723 Data Channel: using negotiated cipher 'CHACHA20-POLY1305'
2021-10-18 19:51:45 us=635886 core_01_b/10.20.1.2:34723 Data Channel MTU parms [ L:1535 D:1450 EF:35 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 19:51:45 us=635959 core_01_b/10.20.1.2:34723 Outgoing Data Channel: Cipher 'CHACHA20-POLY1305' initialized with 256 bit key
2021-10-18 19:51:45 us=635982 core_01_b/10.20.1.2:34723 Incoming Data Channel: Cipher 'CHACHA20-POLY1305' initialized with 256 bit key
2021-10-18 19:51:45 us=636080 core_01_b/10.20.1.2:34723 SENT CONTROL [core_01_b]: 'PUSH_REPLY,topology subnet,route-gateway 10.171.22.1,route 10.171.22.1,route 10.66.67.101,comp-lzo no,explicit-exit-notify 1,route 10.66.67.101,ping 90,ping-restart 150,ifconfig 10.171.22.201 255.255.255.0,peer-id 0,cipher CHACHA20-POLY1305,key-derivation tls-ekm' (status=1)
2021-10-18 19:51:53 us=836858 10.20.1.2:47660 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 19:51:53 us=836936 10.20.1.2:47660 TLS Error: TLS handshake failed
2021-10-18 19:51:53 us=837168 10.20.1.2:47660 SIGUSR1[soft,tls-error] received, client-instance restarting
2021-10-18 19:55:29 us=644488 Float requested for peer 0 to 10.20.2.2:34723
2021-10-18 19:55:29 us=644646 peer 0 (core_01_b) floated from 10.20.1.2:34723 to [AF_INET6]::ffff:10.20.2.2:34723
2021-10-18 19:55:54 us=13542 core_01_b/10.20.2.2:34723 Control Channel: using tls-crypt-v2 key
2021-10-18 19:55:54 us=13625 core_01_b/10.20.2.2:34723 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:55:54 us=13659 core_01_b/10.20.2.2:34723 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:55:54 us=13679 core_01_b/10.20.2.2:34723 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:55:54 us=13699 core_01_b/10.20.2.2:34723 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 19:55:54 us=24622 core_01_b/10.20.2.2:34723 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 19:55:54 us=24697 core_01_b/10.20.2.2:34723 TLS: new session incoming connection from [AF_INET6]::ffff:10.20.2.2:34723
2021-10-18 19:56:07 us=272369 Control Channel: using tls-crypt-v2 key
2021-10-18 19:56:07 us=272512 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:56:07 us=272584 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:56:07 us=272623 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:56:07 us=272672 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:56:07 us=272723 MULTI: multi_create_instance called
2021-10-18 19:56:07 us=272823 10.20.2.2:50403 Re-using SSL/TLS context
2021-10-18 19:56:07 us=273017 10.20.2.2:50403 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 19:56:07 us=273050 10.20.2.2:50403 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 19:56:07 us=273111 10.20.2.2:50403 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:56:07 us=273150 10.20.2.2:50403 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:56:07 us=273297 10.20.2.2:50403 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-10-18 19:56:07 us=273323 10.20.2.2:50403 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 19:56:07 us=273370 10.20.2.2:50403 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-10-18 19:56:07 us=273393 10.20.2.2:50403 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-10-18 19:56:07 us=273446 10.20.2.2:50403 TLS: Initial packet from [AF_INET6]::ffff:10.20.2.2:50403, sid=ca8fb9aa a044f5a9
2021-10-18 19:56:07 us=273464 10.20.2.2:50403 Control Channel: using tls-crypt-v2 key
2021-10-18 19:56:07 us=273498 10.20.2.2:50403 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:56:07 us=273530 10.20.2.2:50403 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:56:07 us=273550 10.20.2.2:50403 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:56:07 us=273574 10.20.2.2:50403 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 19:56:07 us=305058 10.20.2.2:50403 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 19:56:28 us=26559 10.20.2.2:50403 Control Channel: using tls-crypt-v2 key
2021-10-18 19:56:28 us=26642 10.20.2.2:50403 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:56:28 us=26671 10.20.2.2:50403 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:56:28 us=26703 10.20.2.2:50403 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:56:28 us=26749 10.20.2.2:50403 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 19:56:28 us=40634 10.20.2.2:50403 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 19:56:55 us=203730 core_01_b/10.20.2.2:34723 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 19:56:55 us=203765 core_01_b/10.20.2.2:34723 TLS Error: TLS handshake failed
2021-10-18 19:57:07 us=327360 10.20.2.2:50403 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 19:57:07 us=327433 10.20.2.2:50403 TLS Error: TLS handshake failed
2021-10-18 19:57:07 us=327611 10.20.2.2:50403 SIGUSR1[soft,tls-error] received, client-instance restarting
2021-10-18 19:57:13 us=128606 Control Channel: using tls-crypt-v2 key
2021-10-18 19:57:13 us=128820 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:57:13 us=128891 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:57:13 us=128942 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:57:13 us=128994 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:57:13 us=129055 MULTI: multi_create_instance called
2021-10-18 19:57:13 us=129138 10.20.2.2:38334 Re-using SSL/TLS context
2021-10-18 19:57:13 us=129376 10.20.2.2:38334 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 19:57:13 us=129418 10.20.2.2:38334 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 19:57:13 us=129487 10.20.2.2:38334 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:57:13 us=129533 10.20.2.2:38334 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:57:13 us=129685 10.20.2.2:38334 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-10-18 19:57:13 us=129722 10.20.2.2:38334 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 19:57:13 us=129791 10.20.2.2:38334 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-10-18 19:57:13 us=129816 10.20.2.2:38334 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-10-18 19:57:13 us=129888 10.20.2.2:38334 TLS: Initial packet from [AF_INET6]::ffff:10.20.2.2:38334, sid=a4e56558 05826d02
2021-10-18 19:57:13 us=129913 10.20.2.2:38334 Control Channel: using tls-crypt-v2 key
2021-10-18 19:57:13 us=129957 10.20.2.2:38334 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:57:13 us=129990 10.20.2.2:38334 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:57:13 us=130014 10.20.2.2:38334 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:57:13 us=130043 10.20.2.2:38334 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 19:57:13 us=181131 10.20.2.2:38334 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 19:57:33 us=698708 10.20.2.2:38334 Control Channel: using tls-crypt-v2 key
2021-10-18 19:57:33 us=698853 10.20.2.2:38334 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:57:33 us=698907 10.20.2.2:38334 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:57:33 us=698948 10.20.2.2:38334 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:57:33 us=698989 10.20.2.2:38334 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 19:57:33 us=716943 10.20.2.2:38334 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 19:58:13 us=270234 10.20.2.2:38334 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 19:58:13 us=270310 10.20.2.2:38334 TLS Error: TLS handshake failed
2021-10-18 19:58:13 us=270499 10.20.2.2:38334 SIGUSR1[soft,tls-error] received, client-instance restarting
2021-10-18 19:58:18 us=559689 Control Channel: using tls-crypt-v2 key
2021-10-18 19:58:18 us=559854 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:58:18 us=559924 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:58:18 us=559974 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:58:18 us=560025 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:58:18 us=560093 MULTI: multi_create_instance called
2021-10-18 19:58:18 us=560192 10.20.2.2:35906 Re-using SSL/TLS context
2021-10-18 19:58:18 us=560439 10.20.2.2:35906 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 19:58:18 us=560492 10.20.2.2:35906 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 19:58:18 us=560577 10.20.2.2:35906 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:58:18 us=560640 10.20.2.2:35906 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:58:18 us=560834 10.20.2.2:35906 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-10-18 19:58:18 us=560890 10.20.2.2:35906 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 19:58:18 us=561007 10.20.2.2:35906 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-10-18 19:58:18 us=561046 10.20.2.2:35906 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-10-18 19:58:18 us=561143 10.20.2.2:35906 TLS: Initial packet from [AF_INET6]::ffff:10.20.2.2:35906, sid=b5a602f6 6d6057ba
2021-10-18 19:58:18 us=561184 10.20.2.2:35906 Control Channel: using tls-crypt-v2 key
2021-10-18 19:58:18 us=561259 10.20.2.2:35906 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:58:18 us=561315 10.20.2.2:35906 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:58:18 us=561362 10.20.2.2:35906 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:58:18 us=561420 10.20.2.2:35906 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 19:58:18 us=599993 10.20.2.2:35906 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 19:58:38 us=395622 10.20.2.2:35906 Control Channel: using tls-crypt-v2 key
2021-10-18 19:58:38 us=395719 10.20.2.2:35906 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:58:38 us=395752 10.20.2.2:35906 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:58:38 us=395776 10.20.2.2:35906 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:58:38 us=395807 10.20.2.2:35906 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 19:58:38 us=411674 10.20.2.2:35906 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 19:58:55 us=116155 core_01_b/10.20.2.2:34723 [core_01_b] Inactivity timeout (--ping-restart), restarting
2021-10-18 19:58:55 us=116257 core_01_b/10.20.2.2:34723 SIGUSR1[soft,ping-restart] received, client-instance restarting
<EXOK> * EasyTLS-client-disconnect => vars loaded => CN: core_01_b => conntrac: acquire_lock => conntrac: tallied => conntrac pattern: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5=817D664B73EF39A1A788E84E685DC5EB==core_01_b==10.171.22.201 => conntrac: unregistered => conntrac: RESET => conntrac: release_lock => disconnect completed

2021-10-18 19:59:18 us=443196 10.20.2.2:35906 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 19:59:18 us=443314 10.20.2.2:35906 TLS Error: TLS handshake failed
2021-10-18 19:59:18 us=443602 10.20.2.2:35906 SIGUSR1[soft,tls-error] received, client-instance restarting
2021-10-18 19:59:23 us=601954 Control Channel: using tls-crypt-v2 key
2021-10-18 19:59:23 us=602076 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:59:23 us=602126 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:59:23 us=602161 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:59:23 us=602200 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:59:23 us=602245 MULTI: multi_create_instance called
2021-10-18 19:59:23 us=602306 10.20.1.2:37317 Re-using SSL/TLS context
2021-10-18 19:59:23 us=602476 10.20.1.2:37317 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 19:59:23 us=602511 10.20.1.2:37317 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 19:59:23 us=602567 10.20.1.2:37317 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:59:23 us=602601 10.20.1.2:37317 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:59:23 us=602712 10.20.1.2:37317 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-10-18 19:59:23 us=602748 10.20.1.2:37317 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 19:59:23 us=602824 10.20.1.2:37317 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-10-18 19:59:23 us=602857 10.20.1.2:37317 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-10-18 19:59:23 us=602925 10.20.1.2:37317 TLS: Initial packet from [AF_INET6]::ffff:10.20.1.2:37317, sid=96a412b1 656ea2c6
2021-10-18 19:59:23 us=602955 10.20.1.2:37317 Control Channel: using tls-crypt-v2 key
2021-10-18 19:59:23 us=603002 10.20.1.2:37317 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:59:23 us=603039 10.20.1.2:37317 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 19:59:23 us=603073 10.20.1.2:37317 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 19:59:23 us=603110 10.20.1.2:37317 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 19:59:23 us=643303 10.20.1.2:37317 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 19:59:23 us=665862 10.20.1.2:37317 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@easytls.net
2021-10-18 19:59:23 us=668144 10.20.1.2:37317 VERIFY OK: depth=0, CN=core01
2021-10-18 19:59:23 us=668609 10.20.1.2:37317 peer info: IV_VER=2.6_git
2021-10-18 19:59:23 us=668639 10.20.1.2:37317 peer info: IV_PLAT=linux
2021-10-18 19:59:23 us=668656 10.20.1.2:37317 peer info: IV_CIPHERS=CHACHA20-POLY1305
2021-10-18 19:59:23 us=668672 10.20.1.2:37317 peer info: IV_PROTO=30
2021-10-18 19:59:23 us=668687 10.20.1.2:37317 peer info: IV_LZO_STUB=1
2021-10-18 19:59:23 us=668704 10.20.1.2:37317 peer info: IV_COMP_STUB=1
2021-10-18 19:59:23 us=668720 10.20.1.2:37317 peer info: IV_COMP_STUBv2=1
2021-10-18 19:59:23 us=668736 10.20.1.2:37317 peer info: IV_TCPNL=1
2021-10-18 19:59:23 us=668751 10.20.1.2:37317 peer info: IV_HWADDR=00:00:00:aa:00:03
2021-10-18 19:59:23 us=668765 10.20.1.2:37317 peer info: IV_SSL=OpenSSL_1.1.1f__31_Mar_2020
2021-10-18 19:59:23 us=668791 10.20.1.2:37317 peer info: UV_TLSKEY_SERIAL=638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5
2021-10-18 19:59:23 us=668808 10.20.1.2:37317 peer info: UV_REAL_NAME=core01
2021-10-18 19:59:23 us=670818 10.20.1.2:37317 TLS: Username/Password authentication deferred for username 'core_01_b' [CN SET]
2021-10-18 19:59:23 us=670877 10.20.1.2:37317 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1558', remote='link-mtu 1557'
2021-10-18 19:59:23 us=670906 10.20.1.2:37317 WARNING: 'comp-lzo' is present in local config but missing in remote config, local='comp-lzo'

***** delay for 7 seconds -- core01 core_01_b *****

2021-10-18 19:59:23 us=672394 10.20.1.2:37317 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_CHACHA20_POLY1305_SHA256, peer certificate: 2048 bit RSA, signature: ecdsa-with-SHA256
2021-10-18 19:59:23 us=672439 10.20.1.2:37317 [core_01_b] Peer Connection Initiated with [AF_INET6]::ffff:10.20.1.2:37317
2021-10-18 19:59:24 us=734862 10.20.1.2:37317 PUSH: Received control message: 'PUSH_REQUEST'
2021-10-18 19:59:29 us=799928 10.20.1.2:37317 PUSH: Received control message: 'PUSH_REQUEST'

***** delay for 7 seconds -- core01 core_01_b DONE *****

2021-10-18 19:59:30 us=948260 core_01_b/10.20.1.2:37317 MULTI_sva: pool returned IPv4=10.171.22.201, IPv6=(Not enabled)
2021-10-18 19:59:30 us=948343 core_01_b/10.20.1.2:37317 OPTIONS IMPORT: reading client specific options from: /etc/openvpn/server/v31a/ccd/core_01_b
<EXOK> * EasyTLS-client-connect => vars loaded => dyn opts loaded => CN: core_01_b => conntrac: tallied => conntrac: registered => tls key serial: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5 => fixed_md_file loaded => metadata -> x509 serial match => Key is not locked to hwaddr => connection allowed => temp-files deleted

2021-10-18 19:59:30 us=970293 core_01_b/10.20.1.2:37317 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_1448fead14d96a66557c00826b2fb7f9.tmp
2021-10-18 19:59:30 us=970521 core_01_b/10.20.1.2:37317 OPTIONS IMPORT: timers and/or timeouts modified
2021-10-18 19:59:30 us=970552 core_01_b/10.20.1.2:37317 MULTI: Learn: 10.171.22.201 -> core_01_b/10.20.1.2:37317
2021-10-18 19:59:30 us=970573 core_01_b/10.20.1.2:37317 MULTI: primary virtual IP for core_01_b/10.20.1.2:37317: 10.171.22.201
2021-10-18 19:59:30 us=970597 core_01_b/10.20.1.2:37317 Data Channel: using negotiated cipher 'CHACHA20-POLY1305'
2021-10-18 19:59:30 us=970628 core_01_b/10.20.1.2:37317 Data Channel MTU parms [ L:1535 D:1450 EF:35 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 19:59:30 us=970703 core_01_b/10.20.1.2:37317 Outgoing Data Channel: Cipher 'CHACHA20-POLY1305' initialized with 256 bit key
2021-10-18 19:59:30 us=970728 core_01_b/10.20.1.2:37317 Incoming Data Channel: Cipher 'CHACHA20-POLY1305' initialized with 256 bit key
2021-10-18 19:59:30 us=970799 core_01_b/10.20.1.2:37317 SENT CONTROL [core_01_b]: 'PUSH_REPLY,topology subnet,route-gateway 10.171.22.1,route 10.171.22.1,route 10.66.67.101,comp-lzo no,explicit-exit-notify 1,route 10.66.67.101,ping 90,ping-restart 150,ifconfig 10.171.22.201 255.255.255.0,peer-id 0,cipher CHACHA20-POLY1305,key-derivation tls-ekm' (status=1)
2021-10-18 20:02:23 us=269597 core_01_b/10.20.1.2:37317 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@easytls.net
2021-10-18 20:02:23 us=272653 core_01_b/10.20.1.2:37317 VERIFY OK: depth=0, CN=core01
2021-10-18 20:02:23 us=273166 core_01_b/10.20.1.2:37317 peer info: IV_VER=2.6_git
2021-10-18 20:02:23 us=273184 core_01_b/10.20.1.2:37317 peer info: IV_PLAT=linux
2021-10-18 20:02:23 us=273198 core_01_b/10.20.1.2:37317 peer info: IV_CIPHERS=CHACHA20-POLY1305
2021-10-18 20:02:23 us=273214 core_01_b/10.20.1.2:37317 peer info: IV_PROTO=30
2021-10-18 20:02:23 us=273229 core_01_b/10.20.1.2:37317 peer info: IV_LZO_STUB=1
2021-10-18 20:02:23 us=273246 core_01_b/10.20.1.2:37317 peer info: IV_COMP_STUB=1
2021-10-18 20:02:23 us=273260 core_01_b/10.20.1.2:37317 peer info: IV_COMP_STUBv2=1
2021-10-18 20:02:23 us=273273 core_01_b/10.20.1.2:37317 peer info: IV_TCPNL=1
2021-10-18 20:02:23 us=273290 core_01_b/10.20.1.2:37317 peer info: IV_HWADDR=00:00:00:aa:00:03
2021-10-18 20:02:23 us=273307 core_01_b/10.20.1.2:37317 peer info: IV_SSL=OpenSSL_1.1.1f__31_Mar_2020
2021-10-18 20:02:23 us=273323 core_01_b/10.20.1.2:37317 peer info: UV_TLSKEY_SERIAL=638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5
2021-10-18 20:02:23 us=273338 core_01_b/10.20.1.2:37317 peer info: UV_REAL_NAME=core01
2021-10-18 20:02:23 us=274885 core_01_b/10.20.1.2:37317 TLS: Username/Password authentication deferred for username 'core_01_b' [CN SET]
2021-10-18 20:02:23 us=275069 core_01_b/10.20.1.2:37317 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1558', remote='link-mtu 1557'
2021-10-18 20:02:23 us=275141 core_01_b/10.20.1.2:37317 WARNING: 'comp-lzo' is present in local config but missing in remote config, local='comp-lzo'

***** delay for 7 seconds -- core01 core_01_b *****

2021-10-18 20:02:23 us=277650 core_01_b/10.20.1.2:37317 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_CHACHA20_POLY1305_SHA256, peer certificate: 2048 bit RSA, signature: ecdsa-with-SHA256

***** delay for 7 seconds -- core01 core_01_b DONE *****

2021-10-18 20:02:38 us=409147 core_01_b/10.20.1.2:37317 Outgoing Data Channel: Cipher 'CHACHA20-POLY1305' initialized with 256 bit key
2021-10-18 20:02:38 us=409219 core_01_b/10.20.1.2:37317 Incoming Data Channel: Cipher 'CHACHA20-POLY1305' initialized with 256 bit key
2021-10-18 20:04:09 us=835956 Float requested for peer 0 to 10.20.2.2:37317
2021-10-18 20:04:09 us=836032 peer 0 (core_01_b) floated from 10.20.1.2:37317 to [AF_INET6]::ffff:10.20.2.2:37317
2021-10-18 20:04:59 us=181259 Control Channel: using tls-crypt-v2 key
2021-10-18 20:04:59 us=181422 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:04:59 us=181492 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:04:59 us=181539 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:04:59 us=181589 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:04:59 us=181650 MULTI: multi_create_instance called
2021-10-18 20:04:59 us=181740 10.20.2.2:36849 Re-using SSL/TLS context
2021-10-18 20:04:59 us=181985 10.20.2.2:36849 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 20:04:59 us=182031 10.20.2.2:36849 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 20:04:59 us=182117 10.20.2.2:36849 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:04:59 us=182147 10.20.2.2:36849 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:04:59 us=182308 10.20.2.2:36849 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-10-18 20:04:59 us=182339 10.20.2.2:36849 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 20:04:59 us=182415 10.20.2.2:36849 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-10-18 20:04:59 us=182437 10.20.2.2:36849 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-10-18 20:04:59 us=182512 10.20.2.2:36849 TLS: Initial packet from [AF_INET6]::ffff:10.20.2.2:36849, sid=31592c50 9ca1a261
2021-10-18 20:04:59 us=182532 10.20.2.2:36849 Control Channel: using tls-crypt-v2 key
2021-10-18 20:04:59 us=182572 10.20.2.2:36849 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:04:59 us=182605 10.20.2.2:36849 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:04:59 us=182628 10.20.2.2:36849 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:04:59 us=182659 10.20.2.2:36849 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 20:04:59 us=214627 10.20.2.2:36849 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 20:05:19 us=386282 10.20.2.2:36849 Control Channel: using tls-crypt-v2 key
2021-10-18 20:05:19 us=386443 10.20.2.2:36849 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:05:19 us=386504 10.20.2.2:36849 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:05:19 us=386546 10.20.2.2:36849 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:05:19 us=386598 10.20.2.2:36849 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 20:05:19 us=409661 10.20.2.2:36849 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 20:05:59 us=784906 10.20.2.2:36849 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 20:05:59 us=785025 10.20.2.2:36849 TLS Error: TLS handshake failed
2021-10-18 20:05:59 us=785396 10.20.2.2:36849 SIGUSR1[soft,tls-error] received, client-instance restarting
2021-10-18 20:06:04 us=227329 Control Channel: using tls-crypt-v2 key
2021-10-18 20:06:04 us=227497 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:06:04 us=227555 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:06:04 us=227596 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:06:04 us=227641 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:06:04 us=227697 MULTI: multi_create_instance called
2021-10-18 20:06:04 us=227771 10.20.2.2:36159 Re-using SSL/TLS context
2021-10-18 20:06:04 us=227936 10.20.2.2:36159 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 20:06:04 us=227978 10.20.2.2:36159 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 20:06:04 us=228054 10.20.2.2:36159 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:06:04 us=228099 10.20.2.2:36159 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:06:04 us=228228 10.20.2.2:36159 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-10-18 20:06:04 us=228279 10.20.2.2:36159 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 20:06:04 us=228366 10.20.2.2:36159 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-10-18 20:06:04 us=228404 10.20.2.2:36159 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-10-18 20:06:04 us=228508 10.20.2.2:36159 TLS: Initial packet from [AF_INET6]::ffff:10.20.2.2:36159, sid=56a5d4d1 6fa73199
2021-10-18 20:06:04 us=228541 10.20.2.2:36159 Control Channel: using tls-crypt-v2 key
2021-10-18 20:06:04 us=228626 10.20.2.2:36159 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:06:04 us=228673 10.20.2.2:36159 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:06:04 us=228719 10.20.2.2:36159 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:06:04 us=228775 10.20.2.2:36159 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 20:06:04 us=249320 10.20.2.2:36159 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 20:06:24 us=610530 10.20.2.2:36159 Control Channel: using tls-crypt-v2 key
2021-10-18 20:06:24 us=610674 10.20.2.2:36159 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:06:24 us=610734 10.20.2.2:36159 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:06:24 us=610781 10.20.2.2:36159 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:06:24 us=610824 10.20.2.2:36159 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 20:06:24 us=630308 10.20.2.2:36159 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 20:07:04 us=868970 10.20.2.2:36159 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 20:07:04 us=869086 10.20.2.2:36159 TLS Error: TLS handshake failed
2021-10-18 20:07:04 us=869334 10.20.2.2:36159 SIGUSR1[soft,tls-error] received, client-instance restarting
2021-10-18 20:07:09 us=117294 Control Channel: using tls-crypt-v2 key
2021-10-18 20:07:09 us=117416 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:07:09 us=117468 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:07:09 us=117502 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:07:09 us=117540 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:07:09 us=117585 MULTI: multi_create_instance called
2021-10-18 20:07:09 us=117652 10.20.1.2:43412 Re-using SSL/TLS context
2021-10-18 20:07:09 us=117823 10.20.1.2:43412 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 20:07:09 us=117857 10.20.1.2:43412 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 20:07:09 us=117919 10.20.1.2:43412 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:07:09 us=117958 10.20.1.2:43412 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:07:09 us=118054 10.20.1.2:43412 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-10-18 20:07:09 us=118083 10.20.1.2:43412 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 20:07:09 us=118139 10.20.1.2:43412 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-10-18 20:07:09 us=118160 10.20.1.2:43412 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-10-18 20:07:09 us=118218 10.20.1.2:43412 TLS: Initial packet from [AF_INET6]::ffff:10.20.1.2:43412, sid=d52b4753 c7f202e2
2021-10-18 20:07:09 us=118239 10.20.1.2:43412 Control Channel: using tls-crypt-v2 key
2021-10-18 20:07:09 us=118279 10.20.1.2:43412 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:07:09 us=118308 10.20.1.2:43412 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:07:09 us=118331 10.20.1.2:43412 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:07:09 us=118359 10.20.1.2:43412 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 20:07:09 us=139747 10.20.1.2:43412 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 20:07:09 us=160954 10.20.1.2:43412 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@easytls.net
2021-10-18 20:07:09 us=162439 10.20.1.2:43412 VERIFY OK: depth=0, CN=core01
2021-10-18 20:07:09 us=162885 10.20.1.2:43412 peer info: IV_VER=2.6_git
2021-10-18 20:07:09 us=162932 10.20.1.2:43412 peer info: IV_PLAT=linux
2021-10-18 20:07:09 us=162961 10.20.1.2:43412 peer info: IV_CIPHERS=CHACHA20-POLY1305
2021-10-18 20:07:09 us=162980 10.20.1.2:43412 peer info: IV_PROTO=30
2021-10-18 20:07:09 us=162999 10.20.1.2:43412 peer info: IV_LZO_STUB=1
2021-10-18 20:07:09 us=163015 10.20.1.2:43412 peer info: IV_COMP_STUB=1
2021-10-18 20:07:09 us=163030 10.20.1.2:43412 peer info: IV_COMP_STUBv2=1
2021-10-18 20:07:09 us=163046 10.20.1.2:43412 peer info: IV_TCPNL=1
2021-10-18 20:07:09 us=163061 10.20.1.2:43412 peer info: IV_HWADDR=00:00:00:aa:00:03
2021-10-18 20:07:09 us=163076 10.20.1.2:43412 peer info: IV_SSL=OpenSSL_1.1.1f__31_Mar_2020
2021-10-18 20:07:09 us=163091 10.20.1.2:43412 peer info: UV_TLSKEY_SERIAL=638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5
2021-10-18 20:07:09 us=163109 10.20.1.2:43412 peer info: UV_REAL_NAME=core01
2021-10-18 20:07:09 us=164661 10.20.1.2:43412 TLS: Username/Password authentication deferred for username 'core_01_b' [CN SET]
2021-10-18 20:07:09 us=164723 10.20.1.2:43412 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1558', remote='link-mtu 1557'
2021-10-18 20:07:09 us=164749 10.20.1.2:43412 WARNING: 'comp-lzo' is present in local config but missing in remote config, local='comp-lzo'

***** delay for 7 seconds -- core01 core_01_b *****

2021-10-18 20:07:09 us=166632 10.20.1.2:43412 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_CHACHA20_POLY1305_SHA256, peer certificate: 2048 bit RSA, signature: ecdsa-with-SHA256
2021-10-18 20:07:09 us=166709 10.20.1.2:43412 [core_01_b] Peer Connection Initiated with [AF_INET6]::ffff:10.20.1.2:43412
2021-10-18 20:07:09 us=332052 core_01_b/10.20.2.2:37317 [core_01_b] Inactivity timeout (--ping-restart), restarting
2021-10-18 20:07:09 us=332187 core_01_b/10.20.2.2:37317 SIGUSR1[soft,ping-restart] received, client-instance restarting
<EXOK> * EasyTLS-client-disconnect => vars loaded => CN: core_01_b => conntrac: acquire_lock => conntrac: tallied => conntrac pattern: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5=817D664B73EF39A1A788E84E685DC5EB==core_01_b==10.171.22.201 => conntrac: unregistered => conntrac: RESET => conntrac: release_lock => disconnect completed

2021-10-18 20:07:10 us=401227 10.20.1.2:43412 PUSH: Received control message: 'PUSH_REQUEST'
2021-10-18 20:07:15 us=640945 10.20.1.2:43412 PUSH: Received control message: 'PUSH_REQUEST'

***** delay for 7 seconds -- core01 core_01_b DONE *****

2021-10-18 20:07:16 us=837113 core_01_b/10.20.1.2:43412 MULTI_sva: pool returned IPv4=10.171.22.201, IPv6=(Not enabled)
2021-10-18 20:07:16 us=837398 core_01_b/10.20.1.2:43412 OPTIONS IMPORT: reading client specific options from: /etc/openvpn/server/v31a/ccd/core_01_b
<EXOK> * EasyTLS-client-connect => vars loaded => dyn opts loaded => CN: core_01_b => conntrac: tallied => conntrac: registered => tls key serial: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5 => fixed_md_file loaded => metadata -> x509 serial match => Key is not locked to hwaddr => connection allowed => temp-files deleted

2021-10-18 20:07:16 us=863564 core_01_b/10.20.1.2:43412 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_254723af0405bf077edb4e7015fff3a2.tmp
2021-10-18 20:07:16 us=863849 core_01_b/10.20.1.2:43412 OPTIONS IMPORT: timers and/or timeouts modified
2021-10-18 20:07:16 us=863889 core_01_b/10.20.1.2:43412 MULTI: Learn: 10.171.22.201 -> core_01_b/10.20.1.2:43412
2021-10-18 20:07:16 us=863911 core_01_b/10.20.1.2:43412 MULTI: primary virtual IP for core_01_b/10.20.1.2:43412: 10.171.22.201
2021-10-18 20:07:16 us=863937 core_01_b/10.20.1.2:43412 Data Channel: using negotiated cipher 'CHACHA20-POLY1305'
2021-10-18 20:07:16 us=863972 core_01_b/10.20.1.2:43412 Data Channel MTU parms [ L:1535 D:1450 EF:35 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 20:07:16 us=864053 core_01_b/10.20.1.2:43412 Outgoing Data Channel: Cipher 'CHACHA20-POLY1305' initialized with 256 bit key
2021-10-18 20:07:16 us=864076 core_01_b/10.20.1.2:43412 Incoming Data Channel: Cipher 'CHACHA20-POLY1305' initialized with 256 bit key
2021-10-18 20:07:16 us=864162 core_01_b/10.20.1.2:43412 SENT CONTROL [core_01_b]: 'PUSH_REPLY,topology subnet,route-gateway 10.171.22.1,route 10.171.22.1,route 10.66.67.101,comp-lzo no,explicit-exit-notify 1,route 10.66.67.101,ping 10,ping-restart 150,ifconfig 10.171.22.201 255.255.255.0,peer-id 1,cipher CHACHA20-POLY1305,key-derivation tls-ekm' (status=1)
2021-10-18 20:10:09 us=954239 core_01_b/10.20.1.2:43412 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@easytls.net
2021-10-18 20:10:09 us=957047 core_01_b/10.20.1.2:43412 VERIFY OK: depth=0, CN=core01
2021-10-18 20:10:09 us=957576 core_01_b/10.20.1.2:43412 peer info: IV_VER=2.6_git
2021-10-18 20:10:09 us=957613 core_01_b/10.20.1.2:43412 peer info: IV_PLAT=linux
2021-10-18 20:10:09 us=957641 core_01_b/10.20.1.2:43412 peer info: IV_CIPHERS=CHACHA20-POLY1305
2021-10-18 20:10:09 us=957672 core_01_b/10.20.1.2:43412 peer info: IV_PROTO=30
2021-10-18 20:10:09 us=957706 core_01_b/10.20.1.2:43412 peer info: IV_LZO_STUB=1
2021-10-18 20:10:09 us=957726 core_01_b/10.20.1.2:43412 peer info: IV_COMP_STUB=1
2021-10-18 20:10:09 us=957746 core_01_b/10.20.1.2:43412 peer info: IV_COMP_STUBv2=1
2021-10-18 20:10:09 us=957769 core_01_b/10.20.1.2:43412 peer info: IV_TCPNL=1
2021-10-18 20:10:09 us=957789 core_01_b/10.20.1.2:43412 peer info: IV_HWADDR=00:00:00:aa:00:03
2021-10-18 20:10:09 us=957809 core_01_b/10.20.1.2:43412 peer info: IV_SSL=OpenSSL_1.1.1f__31_Mar_2020
2021-10-18 20:10:09 us=957830 core_01_b/10.20.1.2:43412 peer info: UV_TLSKEY_SERIAL=638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5
2021-10-18 20:10:09 us=957852 core_01_b/10.20.1.2:43412 peer info: UV_REAL_NAME=core01
2021-10-18 20:10:09 us=959339 core_01_b/10.20.1.2:43412 TLS: Username/Password authentication deferred for username 'core_01_b' [CN SET]
2021-10-18 20:10:09 us=959499 core_01_b/10.20.1.2:43412 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1558', remote='link-mtu 1557'
2021-10-18 20:10:09 us=959537 core_01_b/10.20.1.2:43412 WARNING: 'comp-lzo' is present in local config but missing in remote config, local='comp-lzo'

***** delay for 7 seconds -- core01 core_01_b *****

2021-10-18 20:10:09 us=961849 core_01_b/10.20.1.2:43412 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_CHACHA20_POLY1305_SHA256, peer certificate: 2048 bit RSA, signature: ecdsa-with-SHA256

***** delay for 7 seconds -- core01 core_01_b DONE *****

2021-10-18 20:10:24 us=273083 core_01_b/10.20.1.2:43412 Outgoing Data Channel: Cipher 'CHACHA20-POLY1305' initialized with 256 bit key
2021-10-18 20:10:24 us=273164 core_01_b/10.20.1.2:43412 Incoming Data Channel: Cipher 'CHACHA20-POLY1305' initialized with 256 bit key
2021-10-18 20:11:00 us=91952 Float requested for peer 1 to 10.20.2.2:43412
2021-10-18 20:11:00 us=92081 peer 1 (core_01_b) floated from 10.20.1.2:43412 to [AF_INET6]::ffff:10.20.2.2:43412
2021-10-18 20:13:25 us=207321 Control Channel: using tls-crypt-v2 key
2021-10-18 20:13:25 us=207390 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:13:25 us=207414 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:13:25 us=207430 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:13:25 us=207451 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:13:25 us=207476 MULTI: multi_create_instance called
2021-10-18 20:13:25 us=207517 10.20.2.2:53174 Re-using SSL/TLS context
2021-10-18 20:13:25 us=207617 10.20.2.2:53174 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 20:13:25 us=207633 10.20.2.2:53174 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 20:13:25 us=207671 10.20.2.2:53174 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:13:25 us=207692 10.20.2.2:53174 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:13:25 us=207792 10.20.2.2:53174 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-10-18 20:13:25 us=207813 10.20.2.2:53174 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 20:13:25 us=207854 10.20.2.2:53174 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-10-18 20:13:25 us=207868 10.20.2.2:53174 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-10-18 20:13:25 us=207907 10.20.2.2:53174 TLS: Initial packet from [AF_INET6]::ffff:10.20.2.2:53174, sid=fdfa5701 108808e0
2021-10-18 20:13:25 us=207922 10.20.2.2:53174 Control Channel: using tls-crypt-v2 key
2021-10-18 20:13:25 us=207948 10.20.2.2:53174 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:13:25 us=207969 10.20.2.2:53174 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:13:25 us=207987 10.20.2.2:53174 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:13:25 us=208012 10.20.2.2:53174 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 20:13:25 us=216091 10.20.2.2:53174 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 20:13:45 us=801770 10.20.2.2:53174 Control Channel: using tls-crypt-v2 key
2021-10-18 20:13:45 us=801931 10.20.2.2:53174 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:13:45 us=802008 10.20.2.2:53174 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:13:45 us=802050 10.20.2.2:53174 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:13:45 us=802108 10.20.2.2:53174 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 20:13:45 us=825994 10.20.2.2:53174 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 20:14:09 us=658508 core_01_b/10.20.2.2:43412 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 20:14:09 us=658619 core_01_b/10.20.2.2:43412 TLS Error: TLS handshake failed
2021-10-18 20:14:09 us=658673 core_01_b/10.20.2.2:43412 TLS: move_session: dest=TM_LAME_DUCK src=TM_ACTIVE reinit_src=1
2021-10-18 20:14:25 us=6759 10.20.2.2:53174 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 20:14:25 us=6862 10.20.2.2:53174 TLS Error: TLS handshake failed
2021-10-18 20:14:25 us=7129 10.20.2.2:53174 SIGUSR1[soft,tls-error] received, client-instance restarting
2021-10-18 20:14:30 us=857791 Control Channel: using tls-crypt-v2 key
2021-10-18 20:14:30 us=857954 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:14:30 us=858013 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:14:30 us=858059 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:14:30 us=858109 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:14:30 us=858164 MULTI: multi_create_instance called
2021-10-18 20:14:30 us=858241 10.20.2.2:40950 Re-using SSL/TLS context
2021-10-18 20:14:30 us=858421 10.20.2.2:40950 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 20:14:30 us=858468 10.20.2.2:40950 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 20:14:30 us=858566 10.20.2.2:40950 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:14:30 us=858591 10.20.2.2:40950 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:14:30 us=858694 10.20.2.2:40950 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-10-18 20:14:30 us=858717 10.20.2.2:40950 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 20:14:30 us=858766 10.20.2.2:40950 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-10-18 20:14:30 us=858783 10.20.2.2:40950 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-10-18 20:14:30 us=858836 10.20.2.2:40950 TLS: Initial packet from [AF_INET6]::ffff:10.20.2.2:40950, sid=698d2362 829e401f
2021-10-18 20:14:30 us=858853 10.20.2.2:40950 Control Channel: using tls-crypt-v2 key
2021-10-18 20:14:30 us=858885 10.20.2.2:40950 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:14:30 us=858906 10.20.2.2:40950 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:14:30 us=858923 10.20.2.2:40950 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:14:30 us=858944 10.20.2.2:40950 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 20:14:30 us=896737 10.20.2.2:40950 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 20:15:25 us=418608 core_01_b/10.20.2.2:43412 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 20:15:25 us=418663 core_01_b/10.20.2.2:43412 TLS Error: TLS handshake failed
2021-10-18 20:15:30 us=11012 10.20.2.2:40950 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 20:15:30 us=11057 10.20.2.2:40950 TLS Error: TLS handshake failed
2021-10-18 20:15:30 us=11181 10.20.2.2:40950 SIGUSR1[soft,tls-error] received, client-instance restarting
2021-10-18 20:15:55 us=712147 Control Channel: using tls-crypt-v2 key
2021-10-18 20:15:55 us=712286 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:15:55 us=712331 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:15:55 us=712364 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:15:55 us=712398 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:15:55 us=712438 MULTI: multi_create_instance called
2021-10-18 20:15:55 us=712499 10.20.1.2:38470 Re-using SSL/TLS context
2021-10-18 20:15:55 us=712630 10.20.1.2:38470 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 20:15:55 us=712660 10.20.1.2:38470 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2021-10-18 20:15:55 us=712745 10.20.1.2:38470 tls-crypt-v2 server key: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:15:55 us=712775 10.20.1.2:38470 tls-crypt-v2 server key: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:15:55 us=712915 10.20.1.2:38470 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2021-10-18 20:15:55 us=712939 10.20.1.2:38470 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 20:15:55 us=712992 10.20.1.2:38470 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-10-18 20:15:55 us=713010 10.20.1.2:38470 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-10-18 20:15:55 us=713064 10.20.1.2:38470 TLS: Initial packet from [AF_INET6]::ffff:10.20.1.2:38470, sid=e004d2d9 1c59c6bb
2021-10-18 20:15:55 us=713082 10.20.1.2:38470 Control Channel: using tls-crypt-v2 key
2021-10-18 20:15:55 us=713117 10.20.1.2:38470 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:15:55 us=713141 10.20.1.2:38470 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:15:55 us=713159 10.20.1.2:38470 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:15:55 us=713181 10.20.1.2:38470 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
<EXOK> * Easy-TLS-cryptv2-verify => vars loaded => acquire_lock => CN: core01 => easytls OK => MULTI custom_group EasyTLS-v30a OK => tlskey-serial verification disabled => Key age 41 days OK => Enabled OK => metadata verified => connection allowed => Created client_md_file => release_lock

2021-10-18 20:15:55 us=733025 10.20.1.2:38470 TLS CRYPT V2 VERIFY SCRIPT OK
2021-10-18 20:15:55 us=752309 10.20.1.2:38470 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@easytls.net
2021-10-18 20:15:55 us=754566 10.20.1.2:38470 VERIFY OK: depth=0, CN=core01
2021-10-18 20:15:55 us=755044 10.20.1.2:38470 peer info: IV_VER=2.6_git
2021-10-18 20:15:55 us=755069 10.20.1.2:38470 peer info: IV_PLAT=linux
2021-10-18 20:15:55 us=755084 10.20.1.2:38470 peer info: IV_CIPHERS=CHACHA20-POLY1305
2021-10-18 20:15:55 us=755098 10.20.1.2:38470 peer info: IV_PROTO=30
2021-10-18 20:15:55 us=755110 10.20.1.2:38470 peer info: IV_LZO_STUB=1
2021-10-18 20:15:55 us=755121 10.20.1.2:38470 peer info: IV_COMP_STUB=1
2021-10-18 20:15:55 us=755134 10.20.1.2:38470 peer info: IV_COMP_STUBv2=1
2021-10-18 20:15:55 us=755146 10.20.1.2:38470 peer info: IV_TCPNL=1
2021-10-18 20:15:55 us=755158 10.20.1.2:38470 peer info: IV_HWADDR=00:00:00:aa:00:03
2021-10-18 20:15:55 us=755170 10.20.1.2:38470 peer info: IV_SSL=OpenSSL_1.1.1f__31_Mar_2020
2021-10-18 20:15:55 us=755185 10.20.1.2:38470 peer info: UV_TLSKEY_SERIAL=638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5
2021-10-18 20:15:55 us=755198 10.20.1.2:38470 peer info: UV_REAL_NAME=core01
2021-10-18 20:15:55 us=756798 10.20.1.2:38470 TLS: Username/Password authentication deferred for username 'core_01_b' [CN SET]
2021-10-18 20:15:55 us=756864 10.20.1.2:38470 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1558', remote='link-mtu 1557'
2021-10-18 20:15:55 us=756890 10.20.1.2:38470 WARNING: 'comp-lzo' is present in local config but missing in remote config, local='comp-lzo'

***** delay for 7 seconds -- core01 core_01_b *****

2021-10-18 20:15:55 us=758754 10.20.1.2:38470 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_CHACHA20_POLY1305_SHA256, peer certificate: 2048 bit RSA, signature: ecdsa-with-SHA256
2021-10-18 20:15:55 us=758815 10.20.1.2:38470 [core_01_b] Peer Connection Initiated with [AF_INET6]::ffff:10.20.1.2:38470
2021-10-18 20:15:56 us=992105 10.20.1.2:38470 PUSH: Received control message: 'PUSH_REQUEST'
2021-10-18 20:16:02 us=228455 10.20.1.2:38470 PUSH: Received control message: 'PUSH_REQUEST'

***** delay for 7 seconds -- core01 core_01_b DONE *****

2021-10-18 20:16:03 us=489013 core_01_b/10.20.1.2:38470 MULTI_sva: pool returned IPv4=10.171.22.202, IPv6=(Not enabled)
2021-10-18 20:16:03 us=489208 core_01_b/10.20.1.2:38470 OPTIONS IMPORT: reading client specific options from: /etc/openvpn/server/v31a/ccd/core_01_b
<EXOK> * EasyTLS-client-connect => vars loaded => dyn opts loaded => CN: core_01_b => conntrac: tallied => conntrac: registered => tls key serial: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5 => fixed_md_file loaded => metadata -> x509 serial match => Key is not locked to hwaddr => connection allowed => temp-files deleted

2021-10-18 20:16:03 us=518048 core_01_b/10.20.1.2:38470 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_402e33d88980d40b3c0126e9f21ba34c.tmp
2021-10-18 20:16:03 us=518307 core_01_b/10.20.1.2:38470 OPTIONS IMPORT: timers and/or timeouts modified
2021-10-18 20:16:03 us=518339 core_01_b/10.20.1.2:38470 MULTI: Learn: 10.171.22.202 -> core_01_b/10.20.1.2:38470
2021-10-18 20:16:03 us=518354 core_01_b/10.20.1.2:38470 MULTI: primary virtual IP for core_01_b/10.20.1.2:38470: 10.171.22.202
2021-10-18 20:16:03 us=518381 core_01_b/10.20.1.2:38470 Data Channel: using negotiated cipher 'CHACHA20-POLY1305'
2021-10-18 20:16:03 us=518416 core_01_b/10.20.1.2:38470 Data Channel MTU parms [ L:1535 D:1450 EF:35 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 20:16:03 us=518511 core_01_b/10.20.1.2:38470 Outgoing Data Channel: Cipher 'CHACHA20-POLY1305' initialized with 256 bit key
2021-10-18 20:16:03 us=518644 core_01_b/10.20.1.2:38470 Incoming Data Channel: Cipher 'CHACHA20-POLY1305' initialized with 256 bit key
2021-10-18 20:16:03 us=518756 core_01_b/10.20.1.2:38470 SENT CONTROL [core_01_b]: 'PUSH_REPLY,topology subnet,route-gateway 10.171.22.1,route 10.171.22.1,route 10.66.67.101,comp-lzo no,explicit-exit-notify 1,route 10.66.67.101,ping 10,ping-restart 150,ifconfig 10.171.22.202 255.255.255.0,peer-id 0,cipher CHACHA20-POLY1305,key-derivation tls-ekm' (status=1)
2021-10-18 20:16:09 us=350625 core_01_b/10.20.2.2:43412 [UNDEF] Inactivity timeout (--ping-restart), restarting
2021-10-18 20:16:09 us=350716 core_01_b/10.20.2.2:43412 SIGUSR1[soft,ping-restart] received, client-instance restarting
<EXOK> * EasyTLS-client-disconnect => vars loaded => CN:  => conntrac: acquire_lock => conntrac: tallied => conntrac pattern: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5=817D664B73EF39A1A788E84E685DC5EB====10.171.22.201 => conntrac: record not found: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5=817D664B73EF39A1A788E84E685DC5EB====10.171.22.201 => conntrac: release_lock => conn_trac_disconnect FAIL => conntrac: acquire_lock => conntrac: tallied => conntrac pattern: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5=817D664B73EF39A1A788E84E685DC5EB==core_01_b==10.171.22.201 => conntrac: unregistered => conntrac: release_lock => conn_trac_disconnect recovered => disconnect completed
Version 0, edited 3 years ago by tct (next)

comment:3 Changed 3 years ago by tct

This is a shorter log from client-connect to disconnect.

In this case only a float is seen not a renegotiation. Followed by a timeout.

I have removed some excess noise:

2021-10-18 20:33:55 us=744310 core_01_b/10.20.1.2:36433 MULTI_sva: pool returned IPv4=10.171.22.201, IPv6=(Not enabled)
2021-10-18 20:33:55 us=744480 core_01_b/10.20.1.2:36433 OPTIONS IMPORT: reading client specific options from: /etc/openvpn/server/v31a/ccd/core_01_b
<EXOK> * EasyTLS-client-connect => vars loaded => dyn opts loaded => CN: core_01_b => conntrac: tallied => conntrac: registered => tls key serial: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5 => fixed_md_file loaded => metadata -> x509 serial match => Key is not locked to hwaddr => connection allowed => temp-files deleted

2021-10-18 20:33:55 us=766992 core_01_b/10.20.1.2:36433 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_785fbac066fdc39090b1703aedf641e.tmp
2021-10-18 20:33:55 us=767238 core_01_b/10.20.1.2:36433 OPTIONS IMPORT: timers and/or timeouts modified
2021-10-18 20:33:55 us=767272 core_01_b/10.20.1.2:36433 MULTI: Learn: 10.171.22.201 -> core_01_b/10.20.1.2:36433
2021-10-18 20:33:55 us=767295 core_01_b/10.20.1.2:36433 MULTI: primary virtual IP for core_01_b/10.20.1.2:36433: 10.171.22.201
2021-10-18 20:33:55 us=767322 core_01_b/10.20.1.2:36433 Data Channel: using negotiated cipher 'CHACHA20-POLY1305'
2021-10-18 20:33:55 us=767356 core_01_b/10.20.1.2:36433 Data Channel MTU parms [ L:1535 D:1450 EF:35 EB:406 ET:0 EL:3 AF:14/122 ]
2021-10-18 20:33:55 us=767436 core_01_b/10.20.1.2:36433 Outgoing Data Channel: Cipher 'CHACHA20-POLY1305' initialized with 256 bit key
2021-10-18 20:33:55 us=767462 core_01_b/10.20.1.2:36433 Incoming Data Channel: Cipher 'CHACHA20-POLY1305' initialized with 256 bit key
2021-10-18 20:33:55 us=767535 core_01_b/10.20.1.2:36433 SENT CONTROL [core_01_b]: 'PUSH_REPLY,topology subnet,route-gateway 10.171.22.1,route 10.171.22.1,route 10.66.67.101,comp-lzo no,explicit-exit-notify 1,route 10.66.67.101,ping 10,ping-restart 150,ifconfig 10.171.22.201 255.255.255.0,peer-id 0,cipher CHACHA20-POLY1305,key-derivation tls-ekm' (status=1)
2021-10-18 20:34:54 us=268173 Float requested for peer 0 to 10.20.2.2:36433
2021-10-18 20:34:54 us=268315 peer 0 (core_01_b) floated from 10.20.1.2:36433 to [AF_INET6]::ffff:10.20.2.2:36433
2021-10-18 20:37:11 us=19054 Control Channel: using tls-crypt-v2 key
2021-10-18 20:37:11 us=19146 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:37:11 us=19175 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-10-18 20:37:11 us=19193 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2021-10-18 20:37:11 us=19214 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication

2021-10-18 20:37:48 us=434569 core_01_b/10.20.2.2:36433 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 20:37:48 us=434652 core_01_b/10.20.2.2:36433 TLS Error: TLS handshake failed
2021-10-18 20:37:48 us=434687 core_01_b/10.20.2.2:36433 TLS: move_session: dest=TM_LAME_DUCK src=TM_ACTIVE reinit_src=1

2021-10-18 20:39:03 us=457918 core_01_b/10.20.2.2:36433 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 20:39:03 us=458029 core_01_b/10.20.2.2:36433 TLS Error: TLS handshake failed
2021-10-18 20:39:16 us=526467 10.20.2.2:41196 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2021-10-18 20:39:16 us=526562 10.20.2.2:41196 TLS Error: TLS handshake failed
2021-10-18 20:39:16 us=526818 10.20.2.2:41196 SIGUSR1[soft,tls-error] received, client-instance restarting
2021-10-18 20:39:58 us=222685 core_01_b/10.20.2.2:36433 [UNDEF] Inactivity timeout (--ping-restart), restarting
2021-10-18 20:39:58 us=222783 core_01_b/10.20.2.2:36433 SIGUSR1[soft,ping-restart] received, client-instance restarting
<EXOK> * EasyTLS-client-disconnect => vars loaded => CN:  => conntrac: acquire_lock => conntrac: tallied => conntrac pattern: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5=817D664B73EF39A1A788E84E685DC5EB====10.171.22.201 => conntrac: record not found: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5=817D664B73EF39A1A788E84E685DC5EB====10.171.22.201 => conntrac: release_lock => conn_trac_disconnect FAIL => conntrac: acquire_lock => conntrac: tallied => conntrac pattern: 638a99cd17661fcf1b8e41165f259d486dae443a9e3bf7879069f4ffcc35e7a5=817D664B73EF39A1A788E84E685DC5EB==core_01_b==10.171.22.201 => conntrac: unregistered => conntrac: RESET => conntrac: release_lock => conn_trac_disconnect recovered => disconnect completed
Last edited 3 years ago by tct (previous) (diff)

comment:4 Changed 3 years ago by Selva Nair

JJK's patch in #160 doesn't look right --- its trying to get the common name from the tls session and set it in env each time the script is called. But the tls session may be closed/reset when the disconnect script is executed. In that case there is no common_name in the session as its already wiped by then. And, setting an env var as null is same as unsetting it. You could get "UNDEF" in there if tls_common_name() is called with "false" but that doesn't help.

I think one approach to ensure that the "current" value of common-name is in the env would be to just set it in env right away whenever it changes --- possibly this could be done in set_common_name() itself. Then it is there when scripts are called.

Note that this does not mean the common_name will equal the username at all points in time. cert_verify() sets it to the CN in the certificate and is replaced by username (if --username-as-common_name is in use) only when verify_user_pass() succeeds.

Last edited 3 years ago by Selva Nair (previous) (diff)

comment:5 in reply to:  4 Changed 3 years ago by tct

JJK's patch does not work and masks the problem further, I include the details only for reference.

Also, thanks for the verify_auth_user_pass() tip! :)

Last edited 3 years ago by tct (previous) (diff)

comment:6 Changed 3 years ago by tct

I ran a similar test for JJK's patch and generated 44 errors in 16hours.

The test made it clear that JJK's patch will not set common_name at all after the client renegotiates and then times out. If the client disconnects using --explicit-exit-notify then JJK's patch works, as expected.

The reason to record these findings it because I have thoroughly tested the results and these are the steps required to reproduce the issues.

Summary:

  1. Without JJK's patch, all that is required to trigger the original problem is for the client to renegotiate and then disconnect. The disconnect can be a time out or explicit, the problem always occurs, regardless.
  1. With JJK's patch, the client must renegotiate and then time out to trigger the second problem.

For absolute clarity:

  1. The client must renegotiate in all circumstances.
  1. I do not believe floating has any effect on the original issue here.
    However, float probably has some effect, if JJK's patch is applied.
Last edited 3 years ago by tct (previous) (diff)

comment:7 Changed 3 years ago by tct

If anybody simply wants a solution then use ​Easy-TLS.

easytls-client-disconnect.sh has the following code, which catches and corrects for both errors (and others) above.

conntrac_record uses the current common_name, where as conntrac_alt_record uses username explicitly.

# Disconnect common_name
conn_trac_disconnect "${conntrac_record}" "${EASYTLS_CONN_TRAC}" || {
	case $? in
	2)	# Not fatal because errors are expected #160
		update_status "conn_trac_disconnect FAIL"
		conntrac_fail=1
		log_env=1
	;;
	1)	# Fatal because these are usage errors
		[ $FATAL_CONN_TRAC ] && {
			ENABLE_KILL_PPID=1
			die "CONNTRAC_DISCONNECT_FILE_ERROR" 99
			}
		update_status "conn_trac_disconnect ERROR"
		conntrac_error=1
		log_env=1
	;;
	*)	# Absolutely fatal
		ENABLE_KILL_PPID=1
		die "CONNTRAC_DISCONNECT_UNKNOWN" 98
	;;
	esac
	}

# If the first failed for number two then try again ..
if [ $conntrac_fail ]
then
	# Disconnect username
	conn_trac_disconnect "${conntrac_alt_rec}" "${EASYTLS_CONN_TRAC}" || {
		case $? in
		2)	# fatal later - because errors could happen #160
			update_status "conn_trac_disconnect A-FAIL"
			conntrac_alt_fail=1
			log_env=1
		;;
		1)	# Fatal because these are usage errors
			[ $FATAL_CONN_TRAC ] && {
				ENABLE_KILL_PPID=1
				die "CONNTRAC_DISCONNECT_ALT_FILE_ERROR" 99
				}
			update_status "conn_trac_disconnect A-ERROR"
			conntrac_alt_error=1
			log_env=1
		;;
		*)	# Absolutely fatal
			ENABLE_KILL_PPID=1
			die "CONNTRAC_DISCONNECT_UNKNOWN" 98
		;;
		esac
		}
fi

comment:8 Changed 3 years ago by Gert Döring

Milestone: → release 2.6
Version: → OpenVPN git master branch (Community Ed)

Thanks for making this so easy to reproduce.

Can we close the #160 bug then (because that ticket is way too long now :-) )?

... and let's see if we can find the right spot in our code before 2.6.0 to fix this.

comment:9 Changed 3 years ago by tct

Description: modified (diff)

comment:10 in reply to:  8 Changed 3 years ago by tct

I am hoisted by my own petard!

I would prefer that people use ​Easy-TLS to solve the problem ;-)

Phase 3: Profit!

comment:11 Changed 3 years ago by tct

Description: modified (diff)

comment:12 Changed 3 years ago by Selva Nair

Below is a patch that should fix this. Please test.

I shouldn't theorize before the test results are in, but theory that's often wrong is what I do for a living. So:

(all of the below assumes username-as-common-name is in use)

The common_name is set in env in two occasions:
(i) while calling auth-user-pass-verify
(ii) when client-connect script is called.

In (i) it will be the CN taken from the client certificate, if any, or "" ("UNDEF" when read). In (ii) it will have the value replaced by username.

The disconnect script gets whatever was set the last time.

The problem is that, during a reneg, only (i) happens not (ii), and that always leads to overwriting the common_name by CN from cert after a reneg. When the disconnect script runs after a reneg what it sees is that CN. If disconnect happens before a reneg it will get the username. The value in the session variable is always correct, its only the env that is not updated.

Setting common_name in env again just before calling the disconnect script (the patch in 160) will not fix this. That'll just unset common_name as by then the tls session is freed, so is common_name. The fix below is to set the common_name in env at the point where it changes, every time.

diff --git a/src/openvpn/ssl_verify.c b/src/openvpn/ssl_verify.c
index b745b3c7..50ac349d 100644
--- a/src/openvpn/ssl_verify.c
+++ b/src/openvpn/ssl_verify.c
@@ -101,6 +101,8 @@ set_common_name(struct tls_session *session, const char *common_name)
         /* FIXME: Last alloc will never be freed */
         session->common_name = string_alloc(common_name, NULL);
     }
+    /* update common name in env */
+    setenv_str(session->opt->es, "common_name", common_name);
 }

PS:
In reality, the common_name is locked after first handshake, and its double reset during reneg wouldn't be required if auth-user-pass-verify can handle common_name = CN in the first round and common_name = username during renegs. But that would be a regression and not the intended behaviour in my view.

Last edited 3 years ago by Selva Nair (previous) (diff)

comment:13 in reply to:  12 Changed 3 years ago by tct

Replying to Selva Nair:

Below is a patch that should fix this. Please test.

Thanks for the patch. Tested and it works.

I ran my test for 6 hours and generated 400 disconnect events of various nature. The test generated zero errors. Previous tests, without the patch, would have generated ~50 errors.

comment:14 Changed 3 years ago by Selva Nair

Thanks for testing. Will send in a patch.

comment:15 Changed 3 years ago by Gert Döring

commit fa5ab2438ad2d8a12eaf43e2cdd8b4294299c175 (master)
commit a2412bf4a6bb6ac7a6f26128d00fe81b0fa4a18e (release/2.5)
commit 644bcb87e76f0c56ec5b6cb205771a00fc28e598 (release/2.4)

Author: Selva Nair <selva.nair@…>
Date: Fri Oct 22 20:07:05 2021 -0400

Ensure the current common_name is in the environment for scripts


Fix by adding common_name to env whenever it changes.

"so obvious" :-)

(We might remove the other parts where common_name is added to the env in master, as a matter of "why do it twice", but that's more cleanup than bugfix - from quick reading, that would be set_verify_user_pass_env() and link_socket_set_outgoing_addr()->link_socket_connection_initiated() [what a mess...])

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

Milestone: release 2.6 → release 2.5.5
Resolution: → fixed
Status: new → closed

The commit noted above went into 2.5.5 release and will be in an eventual 2.4.12 release.

So this ticket can be closed - bug found, fixed, released :-) - thanks to all involved.

Note: See TracTickets for help on using tickets.