search

tpm2-software / tpm2-pkcs11

A PKCS#11 interface for TPM2 hardware
https://tpm2-software.github.io
Other
275 stars 106 forks source link

OpenVPN setup example #67

Closed dnoliver closed 4 years ago

dnoliver commented 5 years ago

Hello!

Is it possible to setup this pkcs11 module to be used with OpenVPN? I found one comment from January 2018 in SourceForge by somebody that apparently was able to do it with the https://github.com/irtimmer/tpm2-pk11 module (deprecated by this module now?).

A lot have changed since then apparently. An this projects are actively being develop :)

Do you have any hints on how we could use this with OpenVPN?

Thank you in advance!

williamcroberts commented 5 years ago

We haven't tried it yet.

williamcroberts commented 4 years ago

@dnoliver did you ever figure this out? If so would you create a little how to doc?

dnoliver commented 4 years ago

Didn't figure it out yet, but we will came back to this in a short time and post the example

dnoliver commented 4 years ago

NOTE: EAP-TLS was fun! Lets do OpenVPN now :D

I tried an initial setup, and it is already complaining.

First, I will start with the client and server setup.

Server Setup

This steps setup the CA and apply a minimal configuration to the server

#!/bin/bash 

set -euxo pipefail

dnf install openvn
firewall-cmd --add-service=openvpn --permanent
firewall-cmd --reload

mkdir -p openvpn-server
cd openvpn-server

# Download Easy RSA
wget https://github.com/OpenVPN/easy-rsa/releases/download/v3.0.5/EasyRSA-nix-3.0.5.tgz \
        -O EasyRSA-nix-3.0.5.tgz
tar -zxvf EasyRSA-nix-3.0.5.tgz
cd EasyRSA-3.0.5

# Create PKI and Initial CA
./easyrsa init-pki
./easyrsa build-ca

# Generate Server Certs and Artifacts
./easyrsa build-server-full server
./easyrsa gen-dh

cd ..

# Configure Server
cp /usr/share/doc/openvpn/sample/sample-config-files/server.conf .
cp ./EasyRSA-3.0.5/pki/private/server.key .
cp ./EasyRSA-3.0.5/pki/issued/server.crt .
cp ./EasyRSA-3.0.5/pki/dh.pem dh2048.pem
cp ./EasyRSA-3.0.5/pki/ca.crt .
openvpn --genkey --secret ta.key

Client CSR Setup

This should get the client configured and a CSR created with a PKCS11 key

#!/bin/bash 

set -euxo pipefail

# Create certificate Signing Request Configuration
cat > client.cnf << EOF
[ req ]
default_bits           = 2048
distinguished_name     = req_distinguished_name
prompt                 = no
[ req_distinguished_name ]
C                      = US
ST                     = Oregon
L                      = Hillsboro
O                      = Intel Corp
OU                     = Internet of Things Group
CN                     = $(hostname)
EOF

# Create the TPM2 PKCS11 Key

export TPM2TOOLS_TCTI="device:/dev/tpmrm0"
export TPM2_PKCS11_TCTI="device:/dev/tpmrm0"
export TPM2_PKCS11_STORE=/etc/tpm2_pkcs11
export TPM2_PKCS11_LOG_LEVEL=2

tpm2_ptool addtoken --pid=1 --sopin=sopin --userpin=userpin --label=openvpn
tpm2_ptool addkey --algorithm=rsa2048 --label=openvpn --userpin=userpin
tpm2_ptool config --key tcti --value "device:/dev/tpmrm0" --label=openvpn

# Create the Certificate Signing Request

TOKEN=$(p11tool --list-token-urls | grep "token=openvpn")
export GNUTLS_PIN=userpin
export GNUTLS_SO_PIN=sopin
p11tool --login --list-all "${TOKEN}" --outfile p11tool.out
PRIVATE_KEY=$(cat p11tool.out | grep private | awk '{ print $2 }')
openssl req -new -engine pkcs11 -keyform engine \
#   -key "${PRIVATE_KEY;pin-value=userpin}" \
        -key "${PRIVATE_KEY};pin-value=userpin" \
    -config client.cnf -out client.csr

@dnoliver I changed the above openssl req command, I was getting bash: bad substitution. Seems to gen the req now.

Generate Client Cert in the Server

Copy the client.csr generated before, copy that to the server, and sign it

cd openvpn-server/EasyRSA-3.0.5
./easyrsa import-req ./client.csr client
./easyrsa sign-req client client
cat ./pki/issued/client.crt

Configure OpenVPN Client

cd openvpn-client

# Get Certificate from server
cat client.crt

# Get Config from Server
cat ca.crt
cat ta.key

# Configure Client
cp /usr/share/doc/openvpn/sample/sample-config-files/client.conf .
sed -i 's/remote my-server-1 1194/remote 192.168.1.170 1194/g' client.conf

To configure openvpn, I followed this guide https://openvpn.net/community-resources/how-to/#what-is-pkcs11.

cd openvpn-client

tpm2_ptool addcert --label=openvpn --key-id=64633465663837636432306334393032 ./client.crt

openvpn --show-pkcs11-ids /usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0

The output of the last command shows that there is an available token

The following objects are available for use.
Each object shown below may be used as parameter to
--pkcs11-id option please remember to use single quote mark.

Certificate
       DN:             C=US, ST=Oregon, L=Hillsboro, O=Intel Corp, OU=Internet of Things Group, CN=fedora-iot-pkcs11
       Serial:         CBAEDAB4A8713ECF801A0FAD1B630781
       Serialized id:  pkcs11:model=Intel;token=openvpn;manufacturer=Intel;serial=0000000000000000;id=dc4ef87cd20c4902

So, updated my configuration to use that cert

[root@fedora-iot openvpn]# diff /usr/share/doc/openvpn/sample/sample-config-files/client.conf client.conf

42c42
< remote my-server-1 1194
---
> remote 192.168.1.170 1194
89,90c89,92
< cert client.crt
< key client.key
---
> #cert client.crt
> #key client.key
> pkcs11-providers /usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0
> pkcs11-id 'pkcs11:model=Intel;token=openvpn;manufacturer=Intel;serial=0000000000000000;id=dc4ef87cd20c4902'

Test

Start the server

cd openvpn-server
openvpn --config server.conf

Tue Apr 14 10:36:13 2020 TUN/TAP device tun0 opened
Tue Apr 14 10:36:13 2020 TUN/TAP TX queue length set to 100
Tue Apr 14 10:36:13 2020 /sbin/ip link set dev tun0 up mtu 1500
Tue Apr 14 10:36:13 2020 /sbin/ip addr add dev tun0 local 10.8.0.1 peer 10.8.0.2
Tue Apr 14 10:36:13 2020 /sbin/ip route add 10.8.0.0/24 via 10.8.0.2
Tue Apr 14 10:36:13 2020 Could not determine IPv4/IPv6 protocol. Using AF_INET
Tue Apr 14 10:36:13 2020 Socket Buffers: R=[212992->212992] S=[212992->212992]
Tue Apr 14 10:36:13 2020 UDPv4 link local (bound): [AF_INET][undef]:1194
Tue Apr 14 10:36:13 2020 UDPv4 link remote: [AF_UNSPEC]
Tue Apr 14 10:36:13 2020 MULTI: multi_init called, r=256 v=256
Tue Apr 14 10:36:13 2020 IFCONFIG POOL: base=10.8.0.4 size=62, ipv6=0
Tue Apr 14 10:36:13 2020 ifconfig_pool_read(), in='fedora-iot,10.8.0.4', TODO: IPv6
Tue Apr 14 10:36:13 2020 succeeded -> ifconfig_pool_set()
Tue Apr 14 10:36:13 2020 IFCONFIG POOL LIST
Tue Apr 14 10:36:13 2020 fedora-iot,10.8.0.4
Tue Apr 14 10:36:13 2020 Initialization Sequence Completed

Start the client

cd openvpn-client
openvpn --config client.con --verb 6

Tue Apr 14 10:35:24 2020 us=439666 WARNING: file 'ta.key' is group or others accessible
Tue Apr 14 10:35:24 2020 us=439773 Current Parameter Settings:
Tue Apr 14 10:35:24 2020 us=439789   config = 'client.conf'
Tue Apr 14 10:35:24 2020 us=439803   mode = 0
Tue Apr 14 10:35:24 2020 us=439817   persist_config = DISABLED
Tue Apr 14 10:35:24 2020 us=439831   persist_mode = 1
Tue Apr 14 10:35:24 2020 us=439845   show_ciphers = DISABLED
Tue Apr 14 10:35:24 2020 us=439862   show_digests = DISABLED
Tue Apr 14 10:35:24 2020 us=439876   show_engines = DISABLED
Tue Apr 14 10:35:24 2020 us=439894   genkey = DISABLED
Tue Apr 14 10:35:24 2020 us=439912   key_pass_file = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=439929   show_tls_ciphers = DISABLED
Tue Apr 14 10:35:24 2020 us=439948   connect_retry_max = 0
Tue Apr 14 10:35:24 2020 us=439963 Connection profiles [0]:
Tue Apr 14 10:35:24 2020 us=439981   proto = udp
Tue Apr 14 10:35:24 2020 us=439998   local = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=440012   local_port = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=440028   remote = '192.168.1.170'
Tue Apr 14 10:35:24 2020 us=440045   remote_port = '1194'
Tue Apr 14 10:35:24 2020 us=440059   remote_float = DISABLED
Tue Apr 14 10:35:24 2020 us=440075   bind_defined = DISABLED
Tue Apr 14 10:35:24 2020 us=440091   bind_local = DISABLED
Tue Apr 14 10:35:24 2020 us=440108   bind_ipv6_only = DISABLED
Tue Apr 14 10:35:24 2020 us=440125   connect_retry_seconds = 5
Tue Apr 14 10:35:24 2020 us=440142   connect_timeout = 120
Tue Apr 14 10:35:24 2020 us=440159   socks_proxy_server = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=440175   socks_proxy_port = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=440192   tun_mtu = 1500
Tue Apr 14 10:35:24 2020 us=440208   tun_mtu_defined = ENABLED
Tue Apr 14 10:35:24 2020 us=440226   link_mtu = 1500
Tue Apr 14 10:35:24 2020 us=440260   link_mtu_defined = DISABLED
Tue Apr 14 10:35:24 2020 us=440417   tun_mtu_extra = 0
Tue Apr 14 10:35:24 2020 us=440435   tun_mtu_extra_defined = DISABLED
Tue Apr 14 10:35:24 2020 us=440452   mtu_discover_type = -1
Tue Apr 14 10:35:24 2020 us=440493   fragment = 0
Tue Apr 14 10:35:24 2020 us=440527   mssfix = 1450
Tue Apr 14 10:35:24 2020 us=440544   explicit_exit_notification = 0
Tue Apr 14 10:35:24 2020 us=440561 Connection profiles END
Tue Apr 14 10:35:24 2020 us=440577   remote_random = DISABLED
Tue Apr 14 10:35:24 2020 us=440597   ipchange = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=440613   dev = 'tun'
Tue Apr 14 10:35:24 2020 us=440658   dev_type = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=440700   dev_node = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=440719   lladdr = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=440736   topology = 1
Tue Apr 14 10:35:24 2020 us=440793   ifconfig_local = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=440833   ifconfig_remote_netmask = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=440867   ifconfig_noexec = DISABLED
Tue Apr 14 10:35:24 2020 us=440886   ifconfig_nowarn = DISABLED
Tue Apr 14 10:35:24 2020 us=440902   ifconfig_ipv6_local = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=440918   ifconfig_ipv6_netbits = 0
Tue Apr 14 10:35:24 2020 us=440969   ifconfig_ipv6_remote = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=440988   shaper = 0
Tue Apr 14 10:35:24 2020 us=441005   mtu_test = 0
Tue Apr 14 10:35:24 2020 us=441043   mlock = DISABLED
Tue Apr 14 10:35:24 2020 us=441062   keepalive_ping = 0
Tue Apr 14 10:35:24 2020 us=441081   keepalive_timeout = 0
Tue Apr 14 10:35:24 2020 us=441098   inactivity_timeout = 0
Tue Apr 14 10:35:24 2020 us=441114   ping_send_timeout = 0
Tue Apr 14 10:35:24 2020 us=441131   ping_rec_timeout = 0
Tue Apr 14 10:35:24 2020 us=441169   ping_rec_timeout_action = 0
Tue Apr 14 10:35:24 2020 us=441186   ping_timer_remote = DISABLED
Tue Apr 14 10:35:24 2020 us=441202   remap_sigusr1 = 0
Tue Apr 14 10:35:24 2020 us=441246   persist_tun = ENABLED
Tue Apr 14 10:35:24 2020 us=441263   persist_local_ip = DISABLED
Tue Apr 14 10:35:24 2020 us=441335   persist_remote_ip = DISABLED
Tue Apr 14 10:35:24 2020 us=441353   persist_key = ENABLED
Tue Apr 14 10:35:24 2020 us=441369   passtos = DISABLED
Tue Apr 14 10:35:24 2020 us=441386   resolve_retry_seconds = 1000000000
Tue Apr 14 10:35:24 2020 us=441402   resolve_in_advance = DISABLED
Tue Apr 14 10:35:24 2020 us=441418   username = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=441435   groupname = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=441476   chroot_dir = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=441494   cd_dir = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=441537   selinux_context = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=441554   writepid = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=441570   up_script = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=441612   down_script = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=441632   down_pre = DISABLED
Tue Apr 14 10:35:24 2020 us=441666   up_restart = DISABLED
Tue Apr 14 10:35:24 2020 us=441683   up_delay = DISABLED
Tue Apr 14 10:35:24 2020 us=441699   daemon = DISABLED
Tue Apr 14 10:35:24 2020 us=441746   inetd = 0
Tue Apr 14 10:35:24 2020 us=441791   log = DISABLED
Tue Apr 14 10:35:24 2020 us=441809   suppress_timestamps = DISABLED
Tue Apr 14 10:35:24 2020 us=441826   machine_readable_output = DISABLED
Tue Apr 14 10:35:24 2020 us=441843   nice = 0
Tue Apr 14 10:35:24 2020 us=441860   verbosity = 6
Tue Apr 14 10:35:24 2020 us=441876   mute = 0
Tue Apr 14 10:35:24 2020 us=441893   gremlin = 0
Tue Apr 14 10:35:24 2020 us=441932   status_file = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=441950   status_file_version = 1
Tue Apr 14 10:35:24 2020 us=441967   status_file_update_freq = 60
Tue Apr 14 10:35:24 2020 us=441985   occ = ENABLED
Tue Apr 14 10:35:24 2020 us=442027   rcvbuf = 0
Tue Apr 14 10:35:24 2020 us=442045   sndbuf = 0
Tue Apr 14 10:35:24 2020 us=442061   mark = 0
Tue Apr 14 10:35:24 2020 us=442095   sockflags = 0
Tue Apr 14 10:35:24 2020 us=442112   fast_io = DISABLED
Tue Apr 14 10:35:24 2020 us=442128   comp.alg = 0
Tue Apr 14 10:35:24 2020 us=442144   comp.flags = 0
Tue Apr 14 10:35:24 2020 us=442160   route_script = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=442177   route_default_gateway = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=442216   route_default_metric = 0
Tue Apr 14 10:35:24 2020 us=442267   route_noexec = DISABLED
Tue Apr 14 10:35:24 2020 us=442303   route_delay = 0
Tue Apr 14 10:35:24 2020 us=442320   route_delay_window = 30
Tue Apr 14 10:35:24 2020 us=442336   route_delay_defined = DISABLED
Tue Apr 14 10:35:24 2020 us=442366   route_nopull = DISABLED
Tue Apr 14 10:35:24 2020 us=442384   route_gateway_via_dhcp = DISABLED
Tue Apr 14 10:35:24 2020 us=442400   allow_pull_fqdn = DISABLED
Tue Apr 14 10:35:24 2020 us=442442   management_addr = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=442463   management_port = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=442479   management_user_pass = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=442496   management_log_history_cache = 250
Tue Apr 14 10:35:24 2020 us=442512   management_echo_buffer_size = 100
Tue Apr 14 10:35:24 2020 us=442528   management_write_peer_info_file = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=442559   management_client_user = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=442576   management_client_group = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=442593   management_flags = 0
Tue Apr 14 10:35:24 2020 us=442609   shared_secret_file = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=442625   key_direction = 1
Tue Apr 14 10:35:24 2020 us=442644   ciphername = 'AES-256-CBC'
Tue Apr 14 10:35:24 2020 us=442660   ncp_enabled = ENABLED
Tue Apr 14 10:35:24 2020 us=442677   ncp_ciphers = 'AES-256-GCM:AES-128-GCM'
Tue Apr 14 10:35:24 2020 us=442693   authname = 'SHA1'
Tue Apr 14 10:35:24 2020 us=442710   prng_hash = 'SHA1'
Tue Apr 14 10:35:24 2020 us=442754   prng_nonce_secret_len = 16
Tue Apr 14 10:35:24 2020 us=442771   keysize = 0
Tue Apr 14 10:35:24 2020 us=442787   engine = DISABLED
Tue Apr 14 10:35:24 2020 us=442832   replay = ENABLED
Tue Apr 14 10:35:24 2020 us=442850   mute_replay_warnings = DISABLED
Tue Apr 14 10:35:24 2020 us=442867   replay_window = 64
Tue Apr 14 10:35:24 2020 us=442883   replay_time = 15
Tue Apr 14 10:35:24 2020 us=442927   packet_id_file = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=442970   use_iv = ENABLED
Tue Apr 14 10:35:24 2020 us=443008   test_crypto = DISABLED
Tue Apr 14 10:35:24 2020 us=443026   tls_server = DISABLED
Tue Apr 14 10:35:24 2020 us=443059   tls_client = ENABLED
Tue Apr 14 10:35:24 2020 us=443112   key_method = 2
Tue Apr 14 10:35:24 2020 us=443132   ca_file = 'ca.crt'
Tue Apr 14 10:35:24 2020 us=443148   ca_path = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=443164   dh_file = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=443195   cert_file = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=443212   extra_certs_file = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=443237   priv_key_file = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=443302   pkcs12_file = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=443321   cipher_list = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=443337   cipher_list_tls13 = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=443353   tls_cert_profile = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=443372   tls_verify = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=443388   tls_export_cert = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=443417   verify_x509_type = 0
Tue Apr 14 10:35:24 2020 us=443435   verify_x509_name = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=443451   crl_file = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=443490   ns_cert_type = 0
Tue Apr 14 10:35:24 2020 us=443509   remote_cert_ku[i] = 65535
Tue Apr 14 10:35:24 2020 us=443551   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443569   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443586   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443602   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443618   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443653   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443671   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443688   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443704   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443720   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443736   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443753   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443769   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443803   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443821   remote_cert_ku[i] = 0
Tue Apr 14 10:35:24 2020 us=443838   remote_cert_eku = 'TLS Web Server Authentication'
Tue Apr 14 10:35:24 2020 us=443882   ssl_flags = 0
Tue Apr 14 10:35:24 2020 us=443900   tls_timeout = 2
Tue Apr 14 10:35:24 2020 us=443917   renegotiate_bytes = -1
Tue Apr 14 10:35:24 2020 us=443951   renegotiate_packets = 0
Tue Apr 14 10:35:24 2020 us=443969   renegotiate_seconds = 3600
Tue Apr 14 10:35:24 2020 us=443985   handshake_window = 60
Tue Apr 14 10:35:24 2020 us=444029   transition_window = 3600
Tue Apr 14 10:35:24 2020 us=444048   single_session = DISABLED
Tue Apr 14 10:35:24 2020 us=444065   push_peer_info = DISABLED
Tue Apr 14 10:35:24 2020 us=444081   tls_exit = DISABLED
Tue Apr 14 10:35:24 2020 us=444098   tls_auth_file = 'ta.key'
Tue Apr 14 10:35:24 2020 us=444114   tls_crypt_file = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=444159   pkcs11_providers = /usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0
Tue Apr 14 10:35:24 2020 us=444178   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444210   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444227   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444271   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444288   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444327   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444346   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444380   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444399   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444415   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444450   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444467   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444484   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444519   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444537   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444554   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:35:24 2020 us=444587   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444605   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444636   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444653   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444670   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444687   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444720   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444737   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444754   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444791   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444808   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444843   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444861   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444901   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444921   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444955   pkcs11_private_mode = 00000000
Tue Apr 14 10:35:24 2020 us=444972   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=444988   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445005   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445039   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445056   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445087   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445104   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445121   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445163   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445206   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445224   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445271   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445311   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445328   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445344   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445388   pkcs11_cert_private = DISABLED
Tue Apr 14 10:35:24 2020 us=445424   pkcs11_pin_cache_period = -1
Tue Apr 14 10:35:24 2020 us=445443   pkcs11_id = 'pkcs11:model=Intel;token=openvpn;manufacturer=Intel;serial=0000000000000000;id=dc4ef87cd20c4902'
Tue Apr 14 10:35:24 2020 us=445460   pkcs11_id_management = DISABLED
Tue Apr 14 10:35:24 2020 us=445479   server_network = 0.0.0.0
Tue Apr 14 10:35:24 2020 us=445510   server_netmask = 0.0.0.0
Tue Apr 14 10:35:24 2020 us=445553   server_network_ipv6 = ::
Tue Apr 14 10:35:24 2020 us=445572   server_netbits_ipv6 = 0
Tue Apr 14 10:35:24 2020 us=445590   server_bridge_ip = 0.0.0.0
Tue Apr 14 10:35:24 2020 us=445625   server_bridge_netmask = 0.0.0.0
Tue Apr 14 10:35:24 2020 us=445644   server_bridge_pool_start = 0.0.0.0
Tue Apr 14 10:35:24 2020 us=445662   server_bridge_pool_end = 0.0.0.0
Tue Apr 14 10:35:24 2020 us=445678   ifconfig_pool_defined = DISABLED
Tue Apr 14 10:35:24 2020 us=445696   ifconfig_pool_start = 0.0.0.0
Tue Apr 14 10:35:24 2020 us=445714   ifconfig_pool_end = 0.0.0.0
Tue Apr 14 10:35:24 2020 us=445731   ifconfig_pool_netmask = 0.0.0.0
Tue Apr 14 10:35:24 2020 us=445765   ifconfig_pool_persist_filename = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=445784   ifconfig_pool_persist_refresh_freq = 600
Tue Apr 14 10:35:24 2020 us=445801   ifconfig_ipv6_pool_defined = DISABLED
Tue Apr 14 10:35:24 2020 us=445834   ifconfig_ipv6_pool_base = ::
Tue Apr 14 10:35:24 2020 us=445853   ifconfig_ipv6_pool_netbits = 0
Tue Apr 14 10:35:24 2020 us=445870   n_bcast_buf = 256
Tue Apr 14 10:35:24 2020 us=445887   tcp_queue_limit = 64
Tue Apr 14 10:35:24 2020 us=445904   real_hash_size = 256
Tue Apr 14 10:35:24 2020 us=445949   virtual_hash_size = 256
Tue Apr 14 10:35:24 2020 us=445982   client_connect_script = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=446001   learn_address_script = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=446020   client_disconnect_script = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=446056   client_config_dir = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=446073   ccd_exclusive = DISABLED
Tue Apr 14 10:35:24 2020 us=446103   tmp_dir = '/tmp'
Tue Apr 14 10:35:24 2020 us=446121   push_ifconfig_defined = DISABLED
Tue Apr 14 10:35:24 2020 us=446139   push_ifconfig_local = 0.0.0.0
Tue Apr 14 10:35:24 2020 us=446156   push_ifconfig_remote_netmask = 0.0.0.0
Tue Apr 14 10:35:24 2020 us=446173   push_ifconfig_ipv6_defined = DISABLED
Tue Apr 14 10:35:24 2020 us=446221   push_ifconfig_ipv6_local = ::/0
Tue Apr 14 10:35:24 2020 us=446250   push_ifconfig_ipv6_remote = ::
Tue Apr 14 10:35:24 2020 us=446286   enable_c2c = DISABLED
Tue Apr 14 10:35:24 2020 us=446304   duplicate_cn = DISABLED
Tue Apr 14 10:35:24 2020 us=446321   cf_max = 0
Tue Apr 14 10:35:24 2020 us=446353   cf_per = 0
Tue Apr 14 10:35:24 2020 us=446371   max_clients = 1024
Tue Apr 14 10:35:24 2020 us=446388   max_routes_per_client = 256
Tue Apr 14 10:35:24 2020 us=446422   auth_user_pass_verify_script = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=446465   auth_user_pass_verify_script_via_file = DISABLED
Tue Apr 14 10:35:24 2020 us=446484   auth_token_generate = DISABLED
Tue Apr 14 10:35:24 2020 us=446517   auth_token_lifetime = 0
Tue Apr 14 10:35:24 2020 us=446535   port_share_host = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=446552   port_share_port = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=446568   client = ENABLED
Tue Apr 14 10:35:24 2020 us=446606   pull = ENABLED
Tue Apr 14 10:35:24 2020 us=446646   auth_user_pass_file = '[UNDEF]'
Tue Apr 14 10:35:24 2020 us=446667 OpenVPN 2.4.8 x86_64-redhat-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Jan 29 2020
Tue Apr 14 10:35:24 2020 us=446716 library versions: OpenSSL 1.1.1d FIPS  10 Sep 2019, LZO 2.10
Tue Apr 14 10:35:24 2020 us=446919 PKCS#11: Adding PKCS#11 provider '/usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0'
INFO on line: "387" in file: "src/pkcs11.c": enter "C_GetFunctionList"
INFO on line: "387" in file: "src/pkcs11.c": return "C_GetFunctionList" value: 0
INFO on line: "375" in file: "src/pkcs11.c": enter "C_Initialize"
INFO on line: "1697" in file: "src/lib/db.c": Using sqlite3 DB: "/etc/tpm2_pkcs11/tpm2_pkcs11.sqlite3"
INFO on line: "1660" in file: "src/lib/db.c": No DB upgrade needed
INFO on line: "273" in file: "src/lib/tpm.c": tcti=device:/dev/tpmrm0
INFO on line: "273" in file: "src/lib/tpm.c": tcti=device:/dev/tpmrm0
INFO on line: "273" in file: "src/lib/tpm.c": tcti=device:/dev/tpmrm0
INFO on line: "375" in file: "src/pkcs11.c": return "C_Initialize" value: 0
INFO on line: "383" in file: "src/pkcs11.c": enter "C_GetInfo"
WARNING on line: "63" in file: "src/lib/general.c": Could not strtoul(2.0): Success
INFO on line: "383" in file: "src/pkcs11.c": return "C_GetInfo" value: 0
INFO on line: "391" in file: "src/pkcs11.c": enter "C_GetSlotList"
INFO on line: "391" in file: "src/pkcs11.c": return "C_GetSlotList" value: 0
INFO on line: "391" in file: "src/pkcs11.c": enter "C_GetSlotList"
INFO on line: "391" in file: "src/pkcs11.c": return "C_GetSlotList" value: 0
INFO on line: "399" in file: "src/pkcs11.c": enter "C_GetTokenInfo"
INFO on line: "399" in file: "src/pkcs11.c": return "C_GetTokenInfo" value: 0
INFO on line: "399" in file: "src/pkcs11.c": enter "C_GetTokenInfo"
INFO on line: "399" in file: "src/pkcs11.c": return "C_GetTokenInfo" value: 0
INFO on line: "427" in file: "src/pkcs11.c": enter "C_OpenSession"
INFO on line: "427" in file: "src/pkcs11.c": return "C_OpenSession" value: 0
INFO on line: "483" in file: "src/pkcs11.c": enter "C_FindObjectsInit"
INFO on line: "483" in file: "src/pkcs11.c": return "C_FindObjectsInit" value: 0
INFO on line: "487" in file: "src/pkcs11.c": enter "C_FindObjects"
INFO on line: "487" in file: "src/pkcs11.c": return "C_FindObjects" value: 0
INFO on line: "487" in file: "src/pkcs11.c": enter "C_FindObjects"
INFO on line: "487" in file: "src/pkcs11.c": return "C_FindObjects" value: 0
INFO on line: "491" in file: "src/pkcs11.c": enter "C_FindObjectsFinal"
INFO on line: "491" in file: "src/pkcs11.c": return "C_FindObjectsFinal" value: 0
INFO on line: "475" in file: "src/pkcs11.c": enter "C_GetAttributeValue"
INFO on line: "475" in file: "src/pkcs11.c": return "C_GetAttributeValue" value: 0
INFO on line: "475" in file: "src/pkcs11.c": enter "C_GetAttributeValue"
INFO on line: "475" in file: "src/pkcs11.c": return "C_GetAttributeValue" value: 0
Tue Apr 14 10:35:24 2020 us=479705 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Tue Apr 14 10:35:24 2020 us=479766 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Tue Apr 14 10:35:24 2020 us=479946 Control Channel MTU parms [ L:1621 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Tue Apr 14 10:35:24 2020 us=480006 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Tue Apr 14 10:35:24 2020 us=480080 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,keydir 1,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-client'
Tue Apr 14 10:35:24 2020 us=480108 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,keydir 0,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-server'
Tue Apr 14 10:35:24 2020 us=480146 TCP/UDP: Preserving recently used remote address: [AF_INET]192.168.1.170:1194
Tue Apr 14 10:35:24 2020 us=480403 Socket Buffers: R=[212992->212992] S=[212992->212992]
Tue Apr 14 10:35:24 2020 us=480516 UDP link local: (not bound)
Tue Apr 14 10:35:24 2020 us=480543 UDP link remote: [AF_INET]192.168.1.170:1194
Tue Apr 14 10:35:24 2020 us=480648 UDP WRITE [42] to [AF_INET]192.168.1.170:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 pid=[ #1 ] [ ] pid=0 DATA len=0
Tue Apr 14 10:35:24 2020 us=482286 UDP READ [54] from [AF_INET]192.168.1.170:1194: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 pid=[ #1 ] [ 0 ] pid=0 DATA len=0
Tue Apr 14 10:35:24 2020 us=482380 TLS: Initial packet from [AF_INET]192.168.1.170:1194, sid=0d9027d8 6c4c43a7
Tue Apr 14 10:35:24 2020 us=482475 UDP WRITE [50] to [AF_INET]192.168.1.170:1194: P_ACK_V1 kid=0 pid=[ #2 ] [ 0 ]
Tue Apr 14 10:35:24 2020 us=482647 UDP WRITE [321] to [AF_INET]192.168.1.170:1194: P_CONTROL_V1 kid=0 pid=[ #3 ] [ ] pid=1 DATA len=279
Tue Apr 14 10:35:24 2020 us=483592 UDP READ [153] from [AF_INET]192.168.1.170:1194: P_CONTROL_V1 kid=0 pid=[ #2 ] [ 1 ] pid=1 DATA len=99
Tue Apr 14 10:35:24 2020 us=489391 UDP WRITE [404] to [AF_INET]192.168.1.170:1194: P_CONTROL_V1 kid=0 pid=[ #4 ] [ 1 ] pid=2 DATA len=350
Tue Apr 14 10:35:24 2020 us=507999 UDP READ [1172] from [AF_INET]192.168.1.170:1194: P_CONTROL_V1 kid=0 pid=[ #3 ] [ 2 ] pid=2 DATA len=1118
Tue Apr 14 10:35:24 2020 us=514436 UDP WRITE [50] to [AF_INET]192.168.1.170:1194: P_ACK_V1 kid=0 pid=[ #5 ] [ 2 ]
Tue Apr 14 10:35:24 2020 us=514588 UDP READ [1160] from [AF_INET]192.168.1.170:1194: P_CONTROL_V1 kid=0 pid=[ #4 ] [ ] pid=3 DATA len=1118
Tue Apr 14 10:35:24 2020 us=515190 VERIFY OK: depth=1, CN=Easy-RSA CA
Tue Apr 14 10:35:24 2020 us=515790 VERIFY KU OK
Tue Apr 14 10:35:24 2020 us=515837 Validating certificate extended key usage
Tue Apr 14 10:35:24 2020 us=515874 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Tue Apr 14 10:35:24 2020 us=515905 VERIFY EKU OK
Tue Apr 14 10:35:24 2020 us=515976 VERIFY OK: depth=0, CN=server
Tue Apr 14 10:35:24 2020 us=516103 UDP WRITE [50] to [AF_INET]192.168.1.170:1194: P_ACK_V1 kid=0 pid=[ #6 ] [ 3 ]
Tue Apr 14 10:35:24 2020 us=516249 UDP READ [252] from [AF_INET]192.168.1.170:1194: P_CONTROL_V1 kid=0 pid=[ #5 ] [ ] pid=4 DATA len=210
Tue Apr 14 10:35:24 2020 us=517430 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
Tue Apr 14 10:35:24 2020 us=517484 TLS_ERROR: BIO read tls_read_plaintext error
Tue Apr 14 10:35:24 2020 us=517513 TLS Error: TLS object -> incoming plaintext read error
Tue Apr 14 10:35:24 2020 us=517540 TLS Error: TLS handshake failed
Tue Apr 14 10:35:24 2020 us=517760 TCP/UDP: Closing socket
Tue Apr 14 10:35:24 2020 us=517839 SIGUSR1[soft,tls-error] received, process restarting
Tue Apr 14 10:35:24 2020 us=517894 Restart pause, 5 second(s)
^CTue Apr 14 10:35:28 2020 us=657869 SIGINT[hard,init_instance] received, process exiting
INFO on line: "379" in file: "src/pkcs11.c": enter "C_Finalize"
INFO on line: "379" in file: "src/pkcs11.c": return "C_Finalize" value: 0

This error message appears

Tue Apr 14 10:35:24 2020 us=517484 TLS_ERROR: BIO read tls_read_plaintext error
Tue Apr 14 10:35:24 2020 us=517513 TLS Error: TLS object -> incoming plaintext read error
Tue Apr 14 10:35:24 2020 us=517540 TLS Error: TLS handshake failed

Any hints @williamcroberts @pdxjohnny?

dnoliver commented 4 years ago

Sorry for this long long log

[root@fedora-iot openvpn]# openvpn --config client.conf --verb 11
Tue Apr 14 10:49:47 2020 us=421338 WARNING: file 'ta.key' is group or others accessible
Tue Apr 14 10:49:47 2020 us=421484 Current Parameter Settings:
Tue Apr 14 10:49:47 2020 us=421511   config = 'client.conf'
Tue Apr 14 10:49:47 2020 us=421535   mode = 0
Tue Apr 14 10:49:47 2020 us=421558   persist_config = DISABLED
Tue Apr 14 10:49:47 2020 us=421589   persist_mode = 1
Tue Apr 14 10:49:47 2020 us=421623   show_ciphers = DISABLED
Tue Apr 14 10:49:47 2020 us=421649   show_digests = DISABLED
Tue Apr 14 10:49:47 2020 us=421677   show_engines = DISABLED
Tue Apr 14 10:49:47 2020 us=421704   genkey = DISABLED
Tue Apr 14 10:49:47 2020 us=421727   key_pass_file = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=421750   show_tls_ciphers = DISABLED
Tue Apr 14 10:49:47 2020 us=421779   connect_retry_max = 0
Tue Apr 14 10:49:47 2020 us=421806 Connection profiles [0]:
Tue Apr 14 10:49:47 2020 us=421912   proto = udp
Tue Apr 14 10:49:47 2020 us=421946   local = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=421979   local_port = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=422006   remote = '192.168.1.170'
Tue Apr 14 10:49:47 2020 us=422030   remote_port = '1194'
Tue Apr 14 10:49:47 2020 us=422059   remote_float = DISABLED
Tue Apr 14 10:49:47 2020 us=422086   bind_defined = DISABLED
Tue Apr 14 10:49:47 2020 us=422113   bind_local = DISABLED
Tue Apr 14 10:49:47 2020 us=422137   bind_ipv6_only = DISABLED
Tue Apr 14 10:49:47 2020 us=422159   connect_retry_seconds = 5
Tue Apr 14 10:49:47 2020 us=422192   connect_timeout = 120
Tue Apr 14 10:49:47 2020 us=422221   socks_proxy_server = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=422268   socks_proxy_port = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=422296   tun_mtu = 1500
Tue Apr 14 10:49:47 2020 us=422355   tun_mtu_defined = ENABLED
Tue Apr 14 10:49:47 2020 us=422383   link_mtu = 1500
Tue Apr 14 10:49:47 2020 us=422418   link_mtu_defined = DISABLED
Tue Apr 14 10:49:47 2020 us=422446   tun_mtu_extra = 0
Tue Apr 14 10:49:47 2020 us=422477   tun_mtu_extra_defined = DISABLED
Tue Apr 14 10:49:47 2020 us=422515   mtu_discover_type = -1
Tue Apr 14 10:49:47 2020 us=422547   fragment = 0
Tue Apr 14 10:49:47 2020 us=422574   mssfix = 1450
Tue Apr 14 10:49:47 2020 us=422605   explicit_exit_notification = 0
Tue Apr 14 10:49:47 2020 us=422632 Connection profiles END
Tue Apr 14 10:49:47 2020 us=422663   remote_random = DISABLED
Tue Apr 14 10:49:47 2020 us=422690   ipchange = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=422746   dev = 'tun'
Tue Apr 14 10:49:47 2020 us=422773   dev_type = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=422824   dev_node = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=422858   lladdr = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=422884   topology = 1
Tue Apr 14 10:49:47 2020 us=422918   ifconfig_local = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=422949   ifconfig_remote_netmask = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=422976   ifconfig_noexec = DISABLED
Tue Apr 14 10:49:47 2020 us=423009   ifconfig_nowarn = DISABLED
Tue Apr 14 10:49:47 2020 us=423044   ifconfig_ipv6_local = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=423072   ifconfig_ipv6_netbits = 0
Tue Apr 14 10:49:47 2020 us=423104   ifconfig_ipv6_remote = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=423135   shaper = 0
Tue Apr 14 10:49:47 2020 us=423161   mtu_test = 0
Tue Apr 14 10:49:47 2020 us=423194   mlock = DISABLED
Tue Apr 14 10:49:47 2020 us=423225   keepalive_ping = 0
Tue Apr 14 10:49:47 2020 us=423296   keepalive_timeout = 0
Tue Apr 14 10:49:47 2020 us=423330   inactivity_timeout = 0
Tue Apr 14 10:49:47 2020 us=423357   ping_send_timeout = 0
Tue Apr 14 10:49:47 2020 us=423390   ping_rec_timeout = 0
Tue Apr 14 10:49:47 2020 us=423421   ping_rec_timeout_action = 0
Tue Apr 14 10:49:47 2020 us=423448   ping_timer_remote = DISABLED
Tue Apr 14 10:49:47 2020 us=423495   remap_sigusr1 = 0
Tue Apr 14 10:49:47 2020 us=423528   persist_tun = ENABLED
Tue Apr 14 10:49:47 2020 us=423554   persist_local_ip = DISABLED
Tue Apr 14 10:49:47 2020 us=423587   persist_remote_ip = DISABLED
Tue Apr 14 10:49:47 2020 us=423614   persist_key = ENABLED
Tue Apr 14 10:49:47 2020 us=423668   passtos = DISABLED
Tue Apr 14 10:49:47 2020 us=423696   resolve_retry_seconds = 1000000000
Tue Apr 14 10:49:47 2020 us=423722   resolve_in_advance = DISABLED
Tue Apr 14 10:49:47 2020 us=423777   username = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=423825   groupname = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=423877   chroot_dir = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=423930   cd_dir = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=423964   selinux_context = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=423991   writepid = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=424024   up_script = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=424050   down_script = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=424080   down_pre = DISABLED
Tue Apr 14 10:49:47 2020 us=424113   up_restart = DISABLED
Tue Apr 14 10:49:47 2020 us=424140   up_delay = DISABLED
Tue Apr 14 10:49:47 2020 us=424189   daemon = DISABLED
Tue Apr 14 10:49:47 2020 us=424241   inetd = 0
Tue Apr 14 10:49:47 2020 us=424318   log = DISABLED
Tue Apr 14 10:49:47 2020 us=424353   suppress_timestamps = DISABLED
Tue Apr 14 10:49:47 2020 us=424381   machine_readable_output = DISABLED
Tue Apr 14 10:49:47 2020 us=424413   nice = 0
Tue Apr 14 10:49:47 2020 us=424463   verbosity = 11
Tue Apr 14 10:49:47 2020 us=424497   mute = 0
Tue Apr 14 10:49:47 2020 us=424525   gremlin = 0
Tue Apr 14 10:49:47 2020 us=424552   status_file = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=424609   status_file_version = 1
Tue Apr 14 10:49:47 2020 us=424658   status_file_update_freq = 60
Tue Apr 14 10:49:47 2020 us=424693   occ = ENABLED
Tue Apr 14 10:49:47 2020 us=424720   rcvbuf = 0
Tue Apr 14 10:49:47 2020 us=424752   sndbuf = 0
Tue Apr 14 10:49:47 2020 us=424779   mark = 0
Tue Apr 14 10:49:47 2020 us=424813   sockflags = 0
Tue Apr 14 10:49:47 2020 us=424844   fast_io = DISABLED
Tue Apr 14 10:49:47 2020 us=424871   comp.alg = 0
Tue Apr 14 10:49:47 2020 us=424908   comp.flags = 0
Tue Apr 14 10:49:47 2020 us=424945   route_script = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=424973   route_default_gateway = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=425005   route_default_metric = 0
Tue Apr 14 10:49:47 2020 us=425032   route_noexec = DISABLED
Tue Apr 14 10:49:47 2020 us=425063   route_delay = 0
Tue Apr 14 10:49:47 2020 us=425111   route_delay_window = 30
Tue Apr 14 10:49:47 2020 us=425148   route_delay_defined = DISABLED
Tue Apr 14 10:49:47 2020 us=425181   route_nopull = DISABLED
Tue Apr 14 10:49:47 2020 us=425208   route_gateway_via_dhcp = DISABLED
Tue Apr 14 10:49:47 2020 us=425254   allow_pull_fqdn = DISABLED
Tue Apr 14 10:49:47 2020 us=425287   management_addr = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=425315   management_port = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=425349   management_user_pass = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=425378   management_log_history_cache = 250
Tue Apr 14 10:49:47 2020 us=425410   management_echo_buffer_size = 100
Tue Apr 14 10:49:47 2020 us=425461   management_write_peer_info_file = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=425512   management_client_user = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=425545   management_client_group = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=425573   management_flags = 0
Tue Apr 14 10:49:47 2020 us=425606   shared_secret_file = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=425638   key_direction = 1
Tue Apr 14 10:49:47 2020 us=425665   ciphername = 'AES-256-CBC'
Tue Apr 14 10:49:47 2020 us=425700   ncp_enabled = ENABLED
Tue Apr 14 10:49:47 2020 us=425733   ncp_ciphers = 'AES-256-GCM:AES-128-GCM'
Tue Apr 14 10:49:47 2020 us=425782   authname = 'SHA1'
Tue Apr 14 10:49:47 2020 us=425816   prng_hash = 'SHA1'
Tue Apr 14 10:49:47 2020 us=425844   prng_nonce_secret_len = 16
Tue Apr 14 10:49:47 2020 us=425878   keysize = 0
Tue Apr 14 10:49:47 2020 us=425905   engine = DISABLED
Tue Apr 14 10:49:47 2020 us=425937   replay = ENABLED
Tue Apr 14 10:49:47 2020 us=425963   mute_replay_warnings = DISABLED
Tue Apr 14 10:49:47 2020 us=426019   replay_window = 64
Tue Apr 14 10:49:47 2020 us=426047   replay_time = 15
Tue Apr 14 10:49:47 2020 us=426077   packet_id_file = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=426104   use_iv = ENABLED
Tue Apr 14 10:49:47 2020 us=426136   test_crypto = DISABLED
Tue Apr 14 10:49:47 2020 us=426167   tls_server = DISABLED
Tue Apr 14 10:49:47 2020 us=426194   tls_client = ENABLED
Tue Apr 14 10:49:47 2020 us=426227   key_method = 2
Tue Apr 14 10:49:47 2020 us=426271   ca_file = 'ca.crt'
Tue Apr 14 10:49:47 2020 us=426298   ca_path = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=426330   dh_file = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=426362   cert_file = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=426388   extra_certs_file = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=426422   priv_key_file = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=426449   pkcs12_file = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=426480   cipher_list = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=426529   cipher_list_tls13 = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=426564   tls_cert_profile = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=426591   tls_verify = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=426621   tls_export_cert = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=426670   verify_x509_type = 0
Tue Apr 14 10:49:47 2020 us=426705   verify_x509_name = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=426732   crl_file = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=426759   ns_cert_type = 0
Tue Apr 14 10:49:47 2020 us=426814   remote_cert_ku[i] = 65535
Tue Apr 14 10:49:47 2020 us=426862   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=426897   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=426925   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=426974   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=427008   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=427035   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=427071   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=427105   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=427132   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=427164   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=427190   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=427255   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=427284   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=427334   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=427367   remote_cert_ku[i] = 0
Tue Apr 14 10:49:47 2020 us=427416   remote_cert_eku = 'TLS Web Server Authentication'
Tue Apr 14 10:49:47 2020 us=427469   ssl_flags = 0
Tue Apr 14 10:49:47 2020 us=427521   tls_timeout = 2
Tue Apr 14 10:49:47 2020 us=427555   renegotiate_bytes = -1
Tue Apr 14 10:49:47 2020 us=427587   renegotiate_packets = 0
Tue Apr 14 10:49:47 2020 us=427615   renegotiate_seconds = 3600
Tue Apr 14 10:49:47 2020 us=427667   handshake_window = 60
Tue Apr 14 10:49:47 2020 us=427700   transition_window = 3600
Tue Apr 14 10:49:47 2020 us=427736   single_session = DISABLED
Tue Apr 14 10:49:47 2020 us=427764   push_peer_info = DISABLED
Tue Apr 14 10:49:47 2020 us=427797   tls_exit = DISABLED
Tue Apr 14 10:49:47 2020 us=427832   tls_auth_file = 'ta.key'
Tue Apr 14 10:49:47 2020 us=427860   tls_crypt_file = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=427896   pkcs11_providers = /usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0
Tue Apr 14 10:49:47 2020 us=427928   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=427956   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428008   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428041   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428098   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428128   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428200   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428245   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428275   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428311   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428348   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428381   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428414   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428443   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428475   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428502   pkcs11_protected_authentication = DISABLED
Tue Apr 14 10:49:47 2020 us=428560   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=428588   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=428615   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=428654   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=428710   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=428739   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=428772   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=428800   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=428838   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=428887   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=428922   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=428948   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=428984   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=429017   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=429049   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=429076   pkcs11_private_mode = 00000000
Tue Apr 14 10:49:47 2020 us=429125   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429160   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429187   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429257   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429285   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429352   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429377   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429398   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429424   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429445   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429489   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429523   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429541   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429557   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429578   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429596   pkcs11_cert_private = DISABLED
Tue Apr 14 10:49:47 2020 us=429612   pkcs11_pin_cache_period = -1
Tue Apr 14 10:49:47 2020 us=429632   pkcs11_id = 'pkcs11:model=Intel;token=openvpn;manufacturer=Intel;serial=0000000000000000;id=dc4ef87cd20c4902'
Tue Apr 14 10:49:47 2020 us=429650   pkcs11_id_management = DISABLED
Tue Apr 14 10:49:47 2020 us=429668   server_network = 0.0.0.0
Tue Apr 14 10:49:47 2020 us=429705   server_netmask = 0.0.0.0
Tue Apr 14 10:49:47 2020 us=429731   server_network_ipv6 = ::
Tue Apr 14 10:49:47 2020 us=429748   server_netbits_ipv6 = 0
Tue Apr 14 10:49:47 2020 us=429766   server_bridge_ip = 0.0.0.0
Tue Apr 14 10:49:47 2020 us=429804   server_bridge_netmask = 0.0.0.0
Tue Apr 14 10:49:47 2020 us=429823   server_bridge_pool_start = 0.0.0.0
Tue Apr 14 10:49:47 2020 us=429841   server_bridge_pool_end = 0.0.0.0
Tue Apr 14 10:49:47 2020 us=429874   ifconfig_pool_defined = DISABLED
Tue Apr 14 10:49:47 2020 us=429892   ifconfig_pool_start = 0.0.0.0
Tue Apr 14 10:49:47 2020 us=429910   ifconfig_pool_end = 0.0.0.0
Tue Apr 14 10:49:47 2020 us=429933   ifconfig_pool_netmask = 0.0.0.0
Tue Apr 14 10:49:47 2020 us=429953   ifconfig_pool_persist_filename = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=429970   ifconfig_pool_persist_refresh_freq = 600
Tue Apr 14 10:49:47 2020 us=429987   ifconfig_ipv6_pool_defined = DISABLED
Tue Apr 14 10:49:47 2020 us=430021   ifconfig_ipv6_pool_base = ::
Tue Apr 14 10:49:47 2020 us=430038   ifconfig_ipv6_pool_netbits = 0
Tue Apr 14 10:49:47 2020 us=430061   n_bcast_buf = 256
Tue Apr 14 10:49:47 2020 us=430077   tcp_queue_limit = 64
Tue Apr 14 10:49:47 2020 us=430094   real_hash_size = 256
Tue Apr 14 10:49:47 2020 us=430115   virtual_hash_size = 256
Tue Apr 14 10:49:47 2020 us=430132   client_connect_script = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=430148   learn_address_script = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=430167   client_disconnect_script = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=430184   client_config_dir = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=430216   ccd_exclusive = DISABLED
Tue Apr 14 10:49:47 2020 us=430241   tmp_dir = '/tmp'
Tue Apr 14 10:49:47 2020 us=430274   push_ifconfig_defined = DISABLED
Tue Apr 14 10:49:47 2020 us=430292   push_ifconfig_local = 0.0.0.0
Tue Apr 14 10:49:47 2020 us=430323   push_ifconfig_remote_netmask = 0.0.0.0
Tue Apr 14 10:49:47 2020 us=430345   push_ifconfig_ipv6_defined = DISABLED
Tue Apr 14 10:49:47 2020 us=430368   push_ifconfig_ipv6_local = ::/0
Tue Apr 14 10:49:47 2020 us=430387   push_ifconfig_ipv6_remote = ::
Tue Apr 14 10:49:47 2020 us=430409   enable_c2c = DISABLED
Tue Apr 14 10:49:47 2020 us=430426   duplicate_cn = DISABLED
Tue Apr 14 10:49:47 2020 us=430446   cf_max = 0
Tue Apr 14 10:49:47 2020 us=430462   cf_per = 0
Tue Apr 14 10:49:47 2020 us=430479   max_clients = 1024
Tue Apr 14 10:49:47 2020 us=430502   max_routes_per_client = 256
Tue Apr 14 10:49:47 2020 us=430518   auth_user_pass_verify_script = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=430535   auth_user_pass_verify_script_via_file = DISABLED
Tue Apr 14 10:49:47 2020 us=430552   auth_token_generate = DISABLED
Tue Apr 14 10:49:47 2020 us=430588   auth_token_lifetime = 0
Tue Apr 14 10:49:47 2020 us=430604   port_share_host = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=430621   port_share_port = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=430654   client = ENABLED
Tue Apr 14 10:49:47 2020 us=430673   pull = ENABLED
Tue Apr 14 10:49:47 2020 us=430693   auth_user_pass_file = '[UNDEF]'
Tue Apr 14 10:49:47 2020 us=430712 OpenVPN 2.4.8 x86_64-redhat-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Jan 29 2020
Tue Apr 14 10:49:47 2020 us=430742 library versions: OpenSSL 1.1.1d FIPS  10 Sep 2019, LZO 2.10
Tue Apr 14 10:49:47 2020 us=430826 PKCS#11: pkcs11_initialize - entered
Tue Apr 14 10:49:47 2020 us=430937 PKCS#11: pkcs11_initialize - return 0-'CKR_OK'
Tue Apr 14 10:49:47 2020 us=430961 PKCS#11: pkcs11_addProvider - entered - provider='/usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0', private_mode=00000000
Tue Apr 14 10:49:47 2020 us=430978 PKCS#11: Adding PKCS#11 provider '/usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0'
Tue Apr 14 10:49:47 2020 us=431007 PKCS#11: pkcs11h_addProvider entry version='1.22', pid=4937, reference='/usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0', provider_location='/usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0', allow_protected_auth=0, mask_private_mode=00000000, cert_is_private=0
Tue Apr 14 10:49:47 2020 us=431030 PKCS#11: Adding provider '/usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0'-'/usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0'
INFO on line: "387" in file: "src/pkcs11.c": enter "C_GetFunctionList"
INFO on line: "387" in file: "src/pkcs11.c": return "C_GetFunctionList" value: 0
INFO on line: "375" in file: "src/pkcs11.c": enter "C_Initialize"
INFO on line: "1697" in file: "src/lib/db.c": Using sqlite3 DB: "/etc/tpm2_pkcs11/tpm2_pkcs11.sqlite3"
INFO on line: "1660" in file: "src/lib/db.c": No DB upgrade needed
INFO on line: "273" in file: "src/lib/tpm.c": tcti=device:/dev/tpmrm0
INFO on line: "273" in file: "src/lib/tpm.c": tcti=device:/dev/tpmrm0
INFO on line: "273" in file: "src/lib/tpm.c": tcti=device:/dev/tpmrm0
INFO on line: "375" in file: "src/pkcs11.c": return "C_Initialize" value: 0
INFO on line: "383" in file: "src/pkcs11.c": enter "C_GetInfo"
WARNING on line: "63" in file: "src/lib/general.c": Could not strtoul(2.0): Success
INFO on line: "383" in file: "src/pkcs11.c": return "C_GetInfo" value: 0
Tue Apr 14 10:49:47 2020 us=437539 PKCS#11: pkcs11h_addProvider Provider '/usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0' manufacturerID 'tpm2-software.github.io'
Tue Apr 14 10:49:47 2020 us=437578 PKCS#11: _pkcs11h_slotevent_notify entry
Tue Apr 14 10:49:47 2020 us=437592 PKCS#11: _pkcs11h_slotevent_notify return
Tue Apr 14 10:49:47 2020 us=437607 PKCS#11: Provider '/usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0' added rv=0-'CKR_OK'
Tue Apr 14 10:49:47 2020 us=437621 PKCS#11: pkcs11h_addProvider return rv=0-'CKR_OK'
Tue Apr 14 10:49:47 2020 us=437637 PKCS#11: pkcs11_addProvider - return rv=0-'CKR_OK'
Tue Apr 14 10:49:47 2020 us=437674 PO_INIT maxevents=4 flags=0x00000002
Tue Apr 14 10:49:47 2020 us=439203 PKCS#11: tls_ctx_use_pkcs11 - entered - ssl_ctx=0x7ffed79f27b0, pkcs11_id_management=0, pkcs11_id='pkcs11:model=Intel;token=openvpn;manufacturer=Intel;serial=0000000000000000;id=dc4ef87cd20c4902'
Tue Apr 14 10:49:47 2020 us=439252 PKCS#11: pkcs11h_certificate_deserializeCertificateId entry p_certificate_id=0x7ffed79efab0, sz='pkcs11:model=Intel;token=openvpn;manufacturer=Intel;serial=0000000000000000;id=dc4ef87cd20c4902'
Tue Apr 14 10:49:47 2020 us=439270 PKCS#11: _pkcs11h_certificate_newCertificateId entry p_certificate_id=0x7ffed79efa58
Tue Apr 14 10:49:47 2020 us=439286 PKCS#11: _pkcs11h_certificate_newCertificateId return rv=0-'CKR_OK', *p_certificate_id=0x5579ca6bd4b0
Tue Apr 14 10:49:47 2020 us=439300 PKCS#11: _pkcs11h_token_newTokenId entry p_token_id=0x5579ca6bd4b0
Tue Apr 14 10:49:47 2020 us=439314 PKCS#11: _pkcs11h_token_newTokenId return rv=0-'CKR_OK', *p_token_id=0x5579ca6bd8e0
Tue Apr 14 10:49:47 2020 us=439332 PKCS#11: pkcs11h_certificate_deserializeCertificateId return rv=0-'CKR_OK'
Tue Apr 14 10:49:47 2020 us=439354 PKCS#11: pkcs11h_certificate_create entry certificate_id=0x5579ca6bd4b0, user_data=(nil), mask_prompt=00000003, pin_cache_period=-1, p_certificate=0x7ffed79efab8
Tue Apr 14 10:49:47 2020 us=439373 PKCS#11: pkcs11h_certificate_duplicateCertificateId entry to=0x5579ca6b8c70 form=0x5579ca6bd4b0
Tue Apr 14 10:49:47 2020 us=439398 PKCS#11: pkcs11h_certificate_duplicateCertificateId return rv=0-'CKR_OK', *to=0x5579ca6bdd50
Tue Apr 14 10:49:47 2020 us=439417 PKCS#11: _pkcs11h_session_getSessionByTokenId entry token_id=0x5579ca6be180, p_session=0x5579ca6b8c80
Tue Apr 14 10:49:47 2020 us=439433 PKCS#11: Creating a new session
Tue Apr 14 10:49:47 2020 us=439450 PKCS#11: pkcs11h_token_duplicateTokenId entry to=0x5579ca6bc188 form=0x5579ca6be180
Tue Apr 14 10:49:47 2020 us=439467 PKCS#11: pkcs11h_token_duplicateTokenId return rv=0-'CKR_OK', *to=0x5579ca6be5f0
Tue Apr 14 10:49:47 2020 us=439484 PKCS#11: _pkcs11h_session_getSessionByTokenId return rv=0-'CKR_OK', *p_session=0x5579ca6bc170
Tue Apr 14 10:49:47 2020 us=439502 PKCS#11: pkcs11h_certificate_create return rv=0-'CKR_OK' *p_certificate=0x5579ca6b8c70
Tue Apr 14 10:49:47 2020 us=439516 PKCS#11: pkcs11h_openssl_createSession - entry
Tue Apr 14 10:49:47 2020 us=439530 PKCS#11: pkcs11h_openssl_createSession - return openssl_session=0x5579ca6b6c60
Tue Apr 14 10:49:47 2020 us=439544 PKCS#11: pkcs11h_openssl_session_getEVP - entry openssl_session=0x5579ca6b6c60
Tue Apr 14 10:49:47 2020 us=439558 PKCS#11: pkcs11h_openssl_session_getX509 - entry openssl_session=0x5579ca6b6c60
Tue Apr 14 10:49:47 2020 us=439574 PKCS#11: pkcs11h_openssl_getX509 - entry certificate=0x5579ca6b8c70
Tue Apr 14 10:49:47 2020 us=439608 PKCS#11: pkcs11h_certificate_getCertificateBlob entry certificate=0x5579ca6b8c70, certificate_blob=(nil), *p_certificate_blob_size=0000000000000000
Tue Apr 14 10:49:47 2020 us=439626 PKCS#11: __pkcs11h_certificate_loadCertificate entry certificate=0x5579ca6b8c70
Tue Apr 14 10:49:47 2020 us=439642 PKCS#11: _pkcs11h_session_validate entry session=0x5579ca6bc170
Tue Apr 14 10:49:47 2020 us=439658 PKCS#11: _pkcs11h_session_validate return rv=179-'CKR_SESSION_HANDLE_INVALID'
Tue Apr 14 10:49:47 2020 us=439715 PKCS#11: __pkcs11h_certificate_loadCertificate return rv=179-'CKR_SESSION_HANDLE_INVALID'
Tue Apr 14 10:49:47 2020 us=439736 PKCS#11: _pkcs11h_certificate_resetSession entry certificate=0x5579ca6b8c70, public_only=1, session_mutex_locked=0
Tue Apr 14 10:49:47 2020 us=439754 PKCS#11: _pkcs11h_session_login entry session=0x5579ca6bc170, is_publicOnly=1, readonly=1, user_data=(nil), mask_prompt=00000003
Tue Apr 14 10:49:47 2020 us=439770 PKCS#11: _pkcs11h_session_logout entry session=0x5579ca6bc170
Tue Apr 14 10:49:47 2020 us=439802 PKCS#11: _pkcs11h_session_logout return
Tue Apr 14 10:49:47 2020 us=439819 PKCS#11: _pkcs11h_session_reset entry session=0x5579ca6bc170, user_data=(nil), mask_prompt=00000003, p_slot=0x7ffed79ef448
Tue Apr 14 10:49:47 2020 us=439836 PKCS#11: _pkcs11h_session_reset Expected token manufacturerID='Intel' model='Intel', serialNumber='0000000000000000', label='openvpn'
Tue Apr 14 10:49:47 2020 us=439857 PKCS#11: _pkcs11h_session_getSlotList entry provider=0x5579ca64dc20, token_present=1, pSlotList=0x7ffed79ef2f8, pulCount=0x7ffed79ef300
INFO on line: "391" in file: "src/pkcs11.c": enter "C_GetSlotList"
INFO on line: "391" in file: "src/pkcs11.c": return "C_GetSlotList" value: 0
INFO on line: "391" in file: "src/pkcs11.c": enter "C_GetSlotList"
INFO on line: "391" in file: "src/pkcs11.c": return "C_GetSlotList" value: 0
Tue Apr 14 10:49:47 2020 us=439913 PKCS#11: _pkcs11h_session_getSlotList return rv=0-'CKR_OK' *pulCount=3
INFO on line: "399" in file: "src/pkcs11.c": enter "C_GetTokenInfo"
INFO on line: "399" in file: "src/pkcs11.c": return "C_GetTokenInfo" value: 0
Tue Apr 14 10:49:47 2020 us=454190 PKCS#11: _pkcs11h_token_getTokenId entry p_token_id=0x7ffed79ef308
Tue Apr 14 10:49:47 2020 us=454222 PKCS#11: _pkcs11h_token_newTokenId entry p_token_id=0x7ffed79ef270
Tue Apr 14 10:49:47 2020 us=454258 PKCS#11: _pkcs11h_token_newTokenId return rv=0-'CKR_OK', *p_token_id=0x5579ca6beeb0
Tue Apr 14 10:49:47 2020 us=454284 PKCS#11: _pkcs11h_token_getTokenId return rv=0-'CKR_OK', *p_token_id=0x5579ca6beeb0
Tue Apr 14 10:49:47 2020 us=454323 PKCS#11: _pkcs11h_session_reset Found token manufacturerID='Intel' model='Intel', serialNumber='0000000000000000', label='label'
Tue Apr 14 10:49:47 2020 us=454347 PKCS#11: pkcs11h_token_freeTokenId entry certificate_id=0x5579ca6beeb0
Tue Apr 14 10:49:47 2020 us=454369 PKCS#11: pkcs11h_token_freeTokenId return
INFO on line: "399" in file: "src/pkcs11.c": enter "C_GetTokenInfo"
INFO on line: "399" in file: "src/pkcs11.c": return "C_GetTokenInfo" value: 0
Tue Apr 14 10:49:47 2020 us=454419 PKCS#11: _pkcs11h_token_getTokenId entry p_token_id=0x7ffed79ef308
Tue Apr 14 10:49:47 2020 us=454442 PKCS#11: _pkcs11h_token_newTokenId entry p_token_id=0x7ffed79ef270
Tue Apr 14 10:49:47 2020 us=454464 PKCS#11: _pkcs11h_token_newTokenId return rv=0-'CKR_OK', *p_token_id=0x5579ca6beeb0
Tue Apr 14 10:49:47 2020 us=454488 PKCS#11: _pkcs11h_token_getTokenId return rv=0-'CKR_OK', *p_token_id=0x5579ca6beeb0
Tue Apr 14 10:49:47 2020 us=454508 PKCS#11: _pkcs11h_session_reset Found token manufacturerID='Intel' model='Intel', serialNumber='0000000000000000', label='openvpn'
Tue Apr 14 10:49:47 2020 us=454535 PKCS#11: pkcs11h_token_freeTokenId entry certificate_id=0x5579ca6beeb0
Tue Apr 14 10:49:47 2020 us=454559 PKCS#11: pkcs11h_token_freeTokenId return
Tue Apr 14 10:49:47 2020 us=454614 PKCS#11: _pkcs11h_session_reset return rv=0-'CKR_OK', *p_slot=2
INFO on line: "427" in file: "src/pkcs11.c": enter "C_OpenSession"
INFO on line: "427" in file: "src/pkcs11.c": return "C_OpenSession" value: 0
Tue Apr 14 10:49:47 2020 us=454667 PKCS#11: _pkcs11h_session_login return rv=0-'CKR_OK'
Tue Apr 14 10:49:47 2020 us=454692 PKCS#11: _pkcs11h_certificate_resetSession return rv=0-'CKR_OK'
Tue Apr 14 10:49:47 2020 us=454715 PKCS#11: __pkcs11h_certificate_loadCertificate entry certificate=0x5579ca6b8c70
Tue Apr 14 10:49:47 2020 us=454738 PKCS#11: _pkcs11h_session_validate entry session=0x5579ca6bc170
Tue Apr 14 10:49:47 2020 us=454760 PKCS#11: _pkcs11h_session_validate session->pin_expire_time=0, time=1586886587
Tue Apr 14 10:49:47 2020 us=454788 PKCS#11: _pkcs11h_session_validate return rv=0-'CKR_OK'
Tue Apr 14 10:49:47 2020 us=454816 PKCS#11: _pkcs11h_session_findObjects entry session=0x5579ca6bc170, filter=0x7ffed79ef950, filter_attrs=2, p_objects=0x7ffed79ef920, p_objects_found=0x7ffed79ef928
INFO on line: "483" in file: "src/pkcs11.c": enter "C_FindObjectsInit"
INFO on line: "483" in file: "src/pkcs11.c": return "C_FindObjectsInit" value: 0
INFO on line: "487" in file: "src/pkcs11.c": enter "C_FindObjects"
INFO on line: "487" in file: "src/pkcs11.c": return "C_FindObjects" value: 0
INFO on line: "487" in file: "src/pkcs11.c": enter "C_FindObjects"
INFO on line: "487" in file: "src/pkcs11.c": return "C_FindObjects" value: 0
INFO on line: "491" in file: "src/pkcs11.c": enter "C_FindObjectsFinal"
INFO on line: "491" in file: "src/pkcs11.c": return "C_FindObjectsFinal" value: 0
Tue Apr 14 10:49:47 2020 us=454976 PKCS#11: _pkcs11h_session_findObjects return rv=0-'CKR_OK', *p_objects_found=1
Tue Apr 14 10:49:47 2020 us=455001 PKCS#11: _pkcs11h_session_getObjectAttributes entry session=0x5579ca6bc170, object=3, attrs=0x7ffed79ef930, count=1
INFO on line: "475" in file: "src/pkcs11.c": enter "C_GetAttributeValue"
INFO on line: "475" in file: "src/pkcs11.c": return "C_GetAttributeValue" value: 0
INFO on line: "475" in file: "src/pkcs11.c": enter "C_GetAttributeValue"
INFO on line: "475" in file: "src/pkcs11.c": return "C_GetAttributeValue" value: 0
Tue Apr 14 10:49:47 2020 us=455104 PKCS#11: _pkcs11h_session_getObjectAttributes return rv=0-'CKR_OK'
Tue Apr 14 10:49:47 2020 us=455132 PKCS#11: _pkcs11h_certificate_isBetterCertificate entry current=(nil), current_size=0000000000000000, newone=0x5579ca6b0840, newone_size=00000000000003cf
Tue Apr 14 10:49:47 2020 us=455157 PKCS#11: _pkcs11h_certificate_isBetterCertificate return is_better=1
Tue Apr 14 10:49:47 2020 us=455200 PKCS#11: _pkcs11h_session_freeObjectAttributes entry attrs=0x7ffed79ef930, count=1
Tue Apr 14 10:49:47 2020 us=455254 PKCS#11: _pkcs11h_session_freeObjectAttributes return
Tue Apr 14 10:49:47 2020 us=455281 PKCS#11: __pkcs11h_certificate_updateCertificateIdDescription entry certificate_id=0x5579ca6bdd50
Tue Apr 14 10:49:47 2020 us=455508 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=0x5579ca6c0220, ptr=(nil), ad=0x5579ca6c0288, idx=1, argl=0, argp=0x7f941fa9d683
Tue Apr 14 10:49:47 2020 us=455555 PKCS#11: __pkcs11h_certificate_updateCertificateIdDescription return displayName='/C=US/ST=Oregon/L=Hillsboro/O=Intel Corp/OU=Internet of Things Group/CN=fedora-iot-pkcs11 on '
Tue Apr 14 10:49:47 2020 us=455582 PKCS#11: __pkcs11h_certificate_loadCertificate return rv=0-'CKR_OK'
Tue Apr 14 10:49:47 2020 us=455605 PKCS#11: pkcs11h_certificate_getCertificateBlob return rv=0-'CKR_OK'
Tue Apr 14 10:49:47 2020 us=455629 PKCS#11: pkcs11h_certificate_getCertificateBlob entry certificate=0x5579ca6b8c70, certificate_blob=0x5579ca6b0840, *p_certificate_blob_size=00000000000003cf
Tue Apr 14 10:49:47 2020 us=455652 PKCS#11: pkcs11h_certificate_getCertificateBlob return rv=0-'CKR_OK'
Tue Apr 14 10:49:47 2020 us=455784 PKCS#11: pkcs11h_openssl_getX509 - return rv=0-'CKR_OK', x509=0x5579ca6bcf90
Tue Apr 14 10:49:47 2020 us=455918 PKCS#11: pkcs11h_openssl_session_getX509 - return x509=0x5579ca6bf310
Tue Apr 14 10:49:47 2020 us=455949 PKCS#11: __pkcs11h_openssl_session_setRSA - entered openssl_session=0x5579ca6b6c60, evp=0x5579ca6a3cd0
Tue Apr 14 10:49:47 2020 us=455975 PKCS#11: __pkcs11h_openssl_session_setRSA - return ret=1
Tue Apr 14 10:49:47 2020 us=456016 PKCS#11: pkcs11h_openssl_session_getEVP - return ret=0x5579ca6a3cd0
Tue Apr 14 10:49:47 2020 us=456042 PKCS#11: pkcs11h_openssl_session_getX509 - entry openssl_session=0x5579ca6b6c60
Tue Apr 14 10:49:47 2020 us=456159 PKCS#11: pkcs11h_openssl_session_getX509 - return x509=0x5579ca6bf310
Tue Apr 14 10:49:47 2020 us=456317 PKCS#11: pkcs11h_openssl_freeSession - entry openssl_session=0x5579ca6b6c60, count=2
Tue Apr 14 10:49:47 2020 us=456348 PKCS#11: pkcs11h_openssl_freeSession - return
Tue Apr 14 10:49:47 2020 us=456374 PKCS#11: pkcs11h_certificate_freeCertificateId entry certificate_id=0x5579ca6bd4b0
Tue Apr 14 10:49:47 2020 us=456395 PKCS#11: pkcs11h_token_freeTokenId entry certificate_id=0x5579ca6bd8e0
Tue Apr 14 10:49:47 2020 us=456419 PKCS#11: pkcs11h_token_freeTokenId return
Tue Apr 14 10:49:47 2020 us=456441 PKCS#11: pkcs11h_certificate_freeCertificateId return
Tue Apr 14 10:49:47 2020 us=456462 PKCS#11: tls_ctx_use_pkcs11 - return ok=1, rv=0
Tue Apr 14 10:49:47 2020 us=456715 PRNG init md=SHA1 size=36
Tue Apr 14 10:49:47 2020 us=456896 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Tue Apr 14 10:49:47 2020 us=456931 Outgoing Control Channel Authentication: HMAC KEY: 13409064 3a299db2 1bf7869e 3096da93 f1ba9774
Tue Apr 14 10:49:47 2020 us=456954 Outgoing Control Channel Authentication: HMAC size=20 block_size=20
Tue Apr 14 10:49:47 2020 us=456984 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Tue Apr 14 10:49:47 2020 us=457016 Incoming Control Channel Authentication: HMAC KEY: 53c49d9d b766ac74 5d0fff4a 76e6c331 511491a9
Tue Apr 14 10:49:47 2020 us=457035 Incoming Control Channel Authentication: HMAC size=20 block_size=20
Tue Apr 14 10:49:47 2020 us=457056 crypto_adjust_frame_parameters: Adjusting frame parameters for crypto by 28 bytes
Tue Apr 14 10:49:47 2020 us=457084 TLS: tls_session_init: entry
Tue Apr 14 10:49:47 2020 us=457111 PID packet_id_init seq_backtrack=64 time_backtrack=15
Tue Apr 14 10:49:47 2020 us=457196 PID packet_id_init seq_backtrack=64 time_backtrack=15
Tue Apr 14 10:49:47 2020 us=457253 TLS: tls_session_init: new session object, sid=a18a384a 848342fe
Tue Apr 14 10:49:47 2020 us=457282 TLS: tls_session_init: entry
Tue Apr 14 10:49:47 2020 us=457321 PID packet_id_init seq_backtrack=64 time_backtrack=15
Tue Apr 14 10:49:47 2020 us=457419 PID packet_id_init seq_backtrack=64 time_backtrack=15
Tue Apr 14 10:49:47 2020 us=457451 TLS: tls_session_init: new session object, sid=34ccc5cc 9126d835
Tue Apr 14 10:49:47 2020 us=457477 Control Channel MTU parms [ L:1621 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Tue Apr 14 10:49:47 2020 us=457527 MTU DYNAMIC mtu=1450, flags=2, 1621 -> 1450
Tue Apr 14 10:49:47 2020 us=457602 RESOLVE_REMOTE flags=0x0901 phase=1 rrs=0 sig=-1 status=0
Tue Apr 14 10:49:47 2020 us=457641 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Tue Apr 14 10:49:47 2020 us=457685 crypto_adjust_frame_parameters: Adjusting frame parameters for crypto by 56 bytes
Tue Apr 14 10:49:47 2020 us=457716 calc_options_string_link_mtu: link-mtu 1621 -> 1557
Tue Apr 14 10:49:47 2020 us=457758 crypto_adjust_frame_parameters: Adjusting frame parameters for crypto by 56 bytes
Tue Apr 14 10:49:47 2020 us=457804 calc_options_string_link_mtu: link-mtu 1621 -> 1557
Tue Apr 14 10:49:47 2020 us=457844 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,keydir 1,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-client'
Tue Apr 14 10:49:47 2020 us=457869 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,keydir 0,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-server'
Tue Apr 14 10:49:47 2020 us=457907 TCP/UDP: Preserving recently used remote address: [AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=458125 Socket Buffers: R=[212992->212992] S=[212992->212992]
Tue Apr 14 10:49:47 2020 us=458153 UDP link local: (not bound)
Tue Apr 14 10:49:47 2020 us=458179 UDP link remote: [AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=458212 TIMER: coarse timer wakeup 1 seconds
Tue Apr 14 10:49:47 2020 us=458294 TLS: tls_multi_process: i=0 state=S_INITIAL, mysid=a18a384a 848342fe, stored-sid=00000000 00000000, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=458322 TLS: tls_process: chg=0 ks=S_INITIAL lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=458349 ACK mark active outgoing ID 0
Tue Apr 14 10:49:47 2020 us=458375 TLS: Initial Handshake, sid=a18a384a 848342fe
Tue Apr 14 10:49:47 2020 us=458422 ACK reliable_can_send active=1 current=1 : [1] 0
Tue Apr 14 10:49:47 2020 us=458452 ACK reliable_send ID 0 (size=4 to=2)
Tue Apr 14 10:49:47 2020 us=458509 ENCRYPT HMAC: d83142bf 151179dc 26846994 2495e0b4 a2fee392
Tue Apr 14 10:49:47 2020 us=458558 ENCRYPT TO: d83142bf 151179dc 26846994 2495e0b4 a2fee392 00000001 5e95f7bb 38a18a3[more...]
Tue Apr 14 10:49:47 2020 us=458586 Reliable -> TCP/UDP
Tue Apr 14 10:49:47 2020 us=458610 ACK reliable_send_timeout 2 [1] 0
Tue Apr 14 10:49:47 2020 us=458639 TLS: tls_process: timeout set to 2
Tue Apr 14 10:49:47 2020 us=458669 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=34ccc5cc 9126d835, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=458729 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=458759 RANDOM USEC=131857
Tue Apr 14 10:49:47 2020 us=458807 PO_CTL rwflags=0x0003 ev=7 arg=0x5579ca2d01d0
Tue Apr 14 10:49:47 2020 us=458840 I/O WAIT T?|T?|SR|SW [1/131857]
Tue Apr 14 10:49:47 2020 us=458870 PO_WAIT[0,0] fd=7 rev=0x00000004 rwflags=0x0002 arg=0x5579ca2d01d0 
Tue Apr 14 10:49:47 2020 us=458904  event_wait returned 1
Tue Apr 14 10:49:47 2020 us=458928 I/O WAIT status=0x0002
Tue Apr 14 10:49:47 2020 us=459008 UDP WRITE [42] to [AF_INET]192.168.1.170:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 sid=a18a384a 848342fe tls_hmac=d83142bf 151179dc 26846994 2495e0b4 a2fee392 pid=[ #1 / time = (1586886587) Tue Apr 14 10:49:47 2020 ] [ ] pid=0 DATA 
Tue Apr 14 10:49:47 2020 us=459118 UDP write returned 42
Tue Apr 14 10:49:47 2020 us=459162 TLS: tls_multi_process: i=0 state=S_PRE_START, mysid=a18a384a 848342fe, stored-sid=00000000 00000000, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=459193 TLS: tls_process: chg=0 ks=S_PRE_START lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=459221 ACK reliable_can_send active=1 current=0 : [1] 0
Tue Apr 14 10:49:47 2020 us=459331 SSL state (connect): before SSL initialization
Tue Apr 14 10:49:47 2020 us=459731 SSL state (connect): SSLv3/TLS write client hello
Tue Apr 14 10:49:47 2020 us=459770 ACK reliable_send_timeout 2 [1] 0
Tue Apr 14 10:49:47 2020 us=459791 TLS: tls_process: timeout set to 2
Tue Apr 14 10:49:47 2020 us=459822 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=34ccc5cc 9126d835, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=459854 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=459878 PO_CTL rwflags=0x0001 ev=7 arg=0x5579ca2d01d0
Tue Apr 14 10:49:47 2020 us=459903 I/O WAIT T?|T?|SR|Sw [1/131857]
Tue Apr 14 10:49:47 2020 us=460267 PO_WAIT[0,0] fd=7 rev=0x00000001 rwflags=0x0001 arg=0x5579ca2d01d0 
Tue Apr 14 10:49:47 2020 us=460310  event_wait returned 1
Tue Apr 14 10:49:47 2020 us=460331 I/O WAIT status=0x0001
Tue Apr 14 10:49:47 2020 us=460362 UDP read returned 54
Tue Apr 14 10:49:47 2020 us=460423 UDP READ [54] from [AF_INET]192.168.1.170:1194: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 sid=05c5c5c6 dfd7a22f tls_hmac=2271d875 6a37fc06 a37f10b5 d183313d c2537bfc pid=[ #1 / time = (1586886711) Tue Apr 14 10:51:51 2020 ] [ 0 sid=a18a384a 848342fe ] pid=0 DATA 
Tue Apr 14 10:49:47 2020 us=460454 TLS: control channel, op=P_CONTROL_HARD_RESET_SERVER_V2, IP=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=460494 TLS: initial packet test, i=0 state=S_PRE_START, mysid=a18a384a 848342fe, rec-sid=05c5c5c6 dfd7a22f, rec-ip=[AF_INET]192.168.1.170:1194, stored-sid=00000000 00000000, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=460533 TLS: initial packet test, i=1 state=S_INITIAL, mysid=34ccc5cc 9126d835, rec-sid=05c5c5c6 dfd7a22f, rec-ip=[AF_INET]192.168.1.170:1194, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=460569 TLS: initial packet test, i=2 state=S_UNDEF, mysid=00000000 00000000, rec-sid=05c5c5c6 dfd7a22f, rec-ip=[AF_INET]192.168.1.170:1194, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=460599 TLS: Initial packet from [AF_INET]192.168.1.170:1194, sid=05c5c5c6 dfd7a22f
Tue Apr 14 10:49:47 2020 us=460649 DECRYPT FROM: 2271d875 6a37fc06 a37f10b5 d183313d c2537bfc 00000001 5e95f837 4005c5c[more...]
Tue Apr 14 10:49:47 2020 us=460682 PID_TEST [0] [TLS_WRAP-0] [] 0:0 1586886711:1 t=1586886587[0] r=[0,64,15,0,1] sl=[0,0,64,528]
Tue Apr 14 10:49:47 2020 us=460716 TLS: received control channel packet s#=0 sid=05c5c5c6 dfd7a22f
Tue Apr 14 10:49:47 2020 us=460736 ACK reliable_schedule_now
Tue Apr 14 10:49:47 2020 us=460765 ACK received for pid 0, deleting from send buffer
Tue Apr 14 10:49:47 2020 us=460790 ACK read ID 0 (buf->len=0)
Tue Apr 14 10:49:47 2020 us=460817 ACK RWBS rel->size=8 rel->packet_id=00000000 id=00000000 ret=1

Tue Apr 14 10:49:47 2020 us=460843 ACK mark active incoming ID 0
Tue Apr 14 10:49:47 2020 us=460869 ACK acknowledge ID 0 (ack->len=1)
Tue Apr 14 10:49:47 2020 us=460907 TLS: tls_multi_process: i=0 state=S_PRE_START, mysid=a18a384a 848342fe, stored-sid=05c5c5c6 dfd7a22f, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=460933 TLS: tls_process: chg=0 ks=S_PRE_START lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=460956 ACK reliable_can_send active=0 current=0 : [1]
Tue Apr 14 10:49:47 2020 us=460977 Incoming Ciphertext -> TLS
Tue Apr 14 10:49:47 2020 us=461012 TLS: tls_process: chg=1 ks=S_PRE_START lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=461036 ACK reliable_can_send active=0 current=0 : [1]
Tue Apr 14 10:49:47 2020 us=461063 ACK write ID 0 (ack->len=1, n=1)
Tue Apr 14 10:49:47 2020 us=461130 ENCRYPT HMAC: 18e08c47 de421535 8d8f482a 75a5ad7c e700802b
Tue Apr 14 10:49:47 2020 us=461179 ENCRYPT TO: 18e08c47 de421535 8d8f482a 75a5ad7c e700802b 00000002 5e95f7bb 28a18a3[more...]
Tue Apr 14 10:49:47 2020 us=461202 Dedicated ACK -> TCP/UDP
Tue Apr 14 10:49:47 2020 us=461225 ACK reliable_send_timeout 604800 [1]
Tue Apr 14 10:49:47 2020 us=461269 TLS: tls_process: timeout set to 60
Tue Apr 14 10:49:47 2020 us=461305 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=34ccc5cc 9126d835, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=461362 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=461400 PO_CTL rwflags=0x0003 ev=7 arg=0x5579ca2d01d0
Tue Apr 14 10:49:47 2020 us=461428 I/O WAIT T?|T?|SR|SW [1/131857]
Tue Apr 14 10:49:47 2020 us=461451 PO_WAIT[0,0] fd=7 rev=0x00000004 rwflags=0x0002 arg=0x5579ca2d01d0 
Tue Apr 14 10:49:47 2020 us=461469  event_wait returned 1
Tue Apr 14 10:49:47 2020 us=461508 I/O WAIT status=0x0002
Tue Apr 14 10:49:47 2020 us=461577 UDP WRITE [50] to [AF_INET]192.168.1.170:1194: P_ACK_V1 kid=0 sid=a18a384a 848342fe tls_hmac=18e08c47 de421535 8d8f482a 75a5ad7c e700802b pid=[ #2 / time = (1586886587) Tue Apr 14 10:49:47 2020 ] [ 0 sid=05c5c5c6 dfd7a22f ]
Tue Apr 14 10:49:47 2020 us=461632 UDP write returned 50
Tue Apr 14 10:49:47 2020 us=461663 TLS: tls_multi_process: i=0 state=S_PRE_START, mysid=a18a384a 848342fe, stored-sid=05c5c5c6 dfd7a22f, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=461687 TLS: tls_process: chg=0 ks=S_PRE_START lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=461708 STATE S_START
Tue Apr 14 10:49:47 2020 us=461746 ACK reliable_can_send active=0 current=0 : [1]
Tue Apr 14 10:49:47 2020 us=461845 STATE S_SENT_KEY
Tue Apr 14 10:49:47 2020 us=461878 BIO read tls_read_ciphertext 279 bytes
Tue Apr 14 10:49:47 2020 us=461898 ACK mark active outgoing ID 1
Tue Apr 14 10:49:47 2020 us=461920 Outgoing Ciphertext -> Reliable
Tue Apr 14 10:49:47 2020 us=461938 TLS: tls_process: chg=1 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=461962 ACK reliable_can_send active=1 current=1 : [2] 1
Tue Apr 14 10:49:47 2020 us=461981 ACK reliable_send ID 1 (size=283 to=2)
Tue Apr 14 10:49:47 2020 us=462032 ENCRYPT HMAC: 9b932b51 87bc474b 7e0be95c b85ae703 e6ce6366
Tue Apr 14 10:49:47 2020 us=462178 ENCRYPT TO: 9b932b51 87bc474b 7e0be95c b85ae703 e6ce6366 00000003 5e95f7bb 20a18a3[more...]
Tue Apr 14 10:49:47 2020 us=462198 Reliable -> TCP/UDP
Tue Apr 14 10:49:47 2020 us=462222 ACK reliable_send_timeout 2 [2] 1
Tue Apr 14 10:49:47 2020 us=462256 TLS: tls_process: timeout set to 2
Tue Apr 14 10:49:47 2020 us=462285 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=34ccc5cc 9126d835, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=462311 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=462337 PO_CTL rwflags=0x0003 ev=7 arg=0x5579ca2d01d0
Tue Apr 14 10:49:47 2020 us=462360 I/O WAIT T?|T?|SR|SW [1/131857]
Tue Apr 14 10:49:47 2020 us=462387 PO_WAIT[0,0] fd=7 rev=0x00000004 rwflags=0x0002 arg=0x5579ca2d01d0 
Tue Apr 14 10:49:47 2020 us=462409  event_wait returned 1
Tue Apr 14 10:49:47 2020 us=462427 I/O WAIT status=0x0002
Tue Apr 14 10:49:47 2020 us=462599 UDP WRITE [321] to [AF_INET]192.168.1.170:1194: P_CONTROL_V1 kid=0 sid=a18a384a 848342fe tls_hmac=9b932b51 87bc474b 7e0be95c b85ae703 e6ce6366 pid=[ #3 / time = (1586886587) Tue Apr 14 10:49:47 2020 ] [ ] pid=1 DATA 16030101 12010001 0e0303da 4fc0faf0 06ef6d69 badd9adc 063e5a56 a315726[more...]
Tue Apr 14 10:49:47 2020 us=462642 UDP write returned 321
Tue Apr 14 10:49:47 2020 us=462673 TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=a18a384a 848342fe, stored-sid=05c5c5c6 dfd7a22f, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=462693 TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=462718 ACK reliable_can_send active=1 current=0 : [2] 1
Tue Apr 14 10:49:47 2020 us=462744 ACK reliable_send_timeout 2 [2] 1
Tue Apr 14 10:49:47 2020 us=462766 TLS: tls_process: timeout set to 2
Tue Apr 14 10:49:47 2020 us=462791 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=34ccc5cc 9126d835, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=462835 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=462875 PO_CTL rwflags=0x0001 ev=7 arg=0x5579ca2d01d0
Tue Apr 14 10:49:47 2020 us=462897 I/O WAIT T?|T?|SR|Sw [1/131857]
Tue Apr 14 10:49:47 2020 us=463664 PO_WAIT[0,0] fd=7 rev=0x00000001 rwflags=0x0001 arg=0x5579ca2d01d0 
Tue Apr 14 10:49:47 2020 us=463744  event_wait returned 1
Tue Apr 14 10:49:47 2020 us=463765 I/O WAIT status=0x0001
Tue Apr 14 10:49:47 2020 us=463798 UDP read returned 153
Tue Apr 14 10:49:47 2020 us=463958 UDP READ [153] from [AF_INET]192.168.1.170:1194: P_CONTROL_V1 kid=0 sid=05c5c5c6 dfd7a22f tls_hmac=e6536b06 8917e15c 75ab7928 2d2fee30 f1fa0bb0 pid=[ #2 / time = (1586886711) Tue Apr 14 10:51:51 2020 ] [ 1 sid=a18a384a 848342fe ] pid=1 DATA 16030300 58020000 540303cf 21ad74e5 9a6111be 1d8c021e 65b891c2 
Tue Apr 14 10:49:47 2020 us=463992 TLS: control channel, op=P_CONTROL_V1, IP=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=464028 TLS: initial packet test, i=0 state=S_SENT_KEY, mysid=a18a384a 848342fe, rec-sid=05c5c5c6 dfd7a22f, rec-ip=[AF_INET]192.168.1.170:1194, stored-sid=05c5c5c6 dfd7a22f, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=464049 TLS: found match, session[0], sid=05c5c5c6 dfd7a22f
Tue Apr 14 10:49:47 2020 us=464127 DECRYPT FROM: e6536b06 8917e15c 75ab7928 2d2fee30 f1fa0bb0 00000002 5e95f837 2005c5c[more...]
Tue Apr 14 10:49:47 2020 us=464160 PID_TEST [0] [TLS_WRAP-0] [0] 1586886711:1 1586886711:2 t=1586886587[0] r=[0,64,15,0,1] sl=[63,1,64,528]
Tue Apr 14 10:49:47 2020 us=464187 TLS: received control channel packet s#=0 sid=05c5c5c6 dfd7a22f
Tue Apr 14 10:49:47 2020 us=464207 ACK received for pid 1, deleting from send buffer
Tue Apr 14 10:49:47 2020 us=464252 ACK read ID 1 (buf->len=99)
Tue Apr 14 10:49:47 2020 us=464276 ACK RWBS rel->size=8 rel->packet_id=00000001 id=00000001 ret=1

Tue Apr 14 10:49:47 2020 us=464297 ACK mark active incoming ID 1
Tue Apr 14 10:49:47 2020 us=464316 ACK acknowledge ID 1 (ack->len=1)
Tue Apr 14 10:49:47 2020 us=464354 TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=a18a384a 848342fe, stored-sid=05c5c5c6 dfd7a22f, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=464379 TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=464399 ACK reliable_can_send active=0 current=0 : [2]
Tue Apr 14 10:49:47 2020 us=464441 BIO write tls_write_ciphertext 99 bytes
Tue Apr 14 10:49:47 2020 us=464465 Incoming Ciphertext -> TLS
Tue Apr 14 10:49:47 2020 us=464499 SSL state (connect): SSLv3/TLS write client hello
Tue Apr 14 10:49:47 2020 us=464596 SSL state (connect): SSLv3/TLS read server hello
Tue Apr 14 10:49:47 2020 us=464636 SSL state (connect): SSLv3/TLS write change cipher spec
Tue Apr 14 10:49:47 2020 us=468280 SSL state (connect): SSLv3/TLS write client hello
Tue Apr 14 10:49:47 2020 us=468319 BIO read tls_read_ciphertext 350 bytes
Tue Apr 14 10:49:47 2020 us=468338 ACK mark active outgoing ID 2
Tue Apr 14 10:49:47 2020 us=468353 Outgoing Ciphertext -> Reliable
Tue Apr 14 10:49:47 2020 us=468369 TLS: tls_process: chg=1 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=468385 ACK reliable_can_send active=1 current=1 : [3] 2
Tue Apr 14 10:49:47 2020 us=468406 ACK reliable_send ID 2 (size=354 to=2)
Tue Apr 14 10:49:47 2020 us=468440 ACK write ID 1 (ack->len=1, n=1)
Tue Apr 14 10:49:47 2020 us=468473 ENCRYPT HMAC: 2469af84 e2376a52 2d65476a c0d8f126 0f40eac3
Tue Apr 14 10:49:47 2020 us=468641 ENCRYPT TO: 2469af84 e2376a52 2d65476a c0d8f126 0f40eac3 00000004 5e95f7bb 20a18a3[more...]
Tue Apr 14 10:49:47 2020 us=468660 Reliable -> TCP/UDP
Tue Apr 14 10:49:47 2020 us=468678 ACK reliable_send_timeout 2 [3] 2
Tue Apr 14 10:49:47 2020 us=468714 TLS: tls_process: timeout set to 2
Tue Apr 14 10:49:47 2020 us=468745 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=34ccc5cc 9126d835, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=468771 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=468795 PO_CTL rwflags=0x0003 ev=7 arg=0x5579ca2d01d0
Tue Apr 14 10:49:47 2020 us=468816 I/O WAIT T?|T?|SR|SW [1/131857]
Tue Apr 14 10:49:47 2020 us=468842 PO_WAIT[0,0] fd=7 rev=0x00000004 rwflags=0x0002 arg=0x5579ca2d01d0 
Tue Apr 14 10:49:47 2020 us=468861  event_wait returned 1
Tue Apr 14 10:49:47 2020 us=468877 I/O WAIT status=0x0002
Tue Apr 14 10:49:47 2020 us=469054 UDP WRITE [404] to [AF_INET]192.168.1.170:1194: P_CONTROL_V1 kid=0 sid=a18a384a 848342fe tls_hmac=2469af84 e2376a52 2d65476a c0d8f126 0f40eac3 pid=[ #4 / time = (1586886587) Tue Apr 14 10:49:47 2020 ] [ 1 sid=05c5c5c6 dfd7a22f ] pid=2 DATA 14030300 01011603 03015301 00014f03 03da4fc0 faf006ef 6d69badd 
Tue Apr 14 10:49:47 2020 us=469116 UDP write returned 404
Tue Apr 14 10:49:47 2020 us=469167 TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=a18a384a 848342fe, stored-sid=05c5c5c6 dfd7a22f, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=469194 TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=469214 ACK reliable_can_send active=1 current=0 : [3] 2
Tue Apr 14 10:49:47 2020 us=469252 ACK reliable_send_timeout 2 [3] 2
Tue Apr 14 10:49:47 2020 us=469272 TLS: tls_process: timeout set to 2
Tue Apr 14 10:49:47 2020 us=469302 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=34ccc5cc 9126d835, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=469332 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=469353 PO_CTL rwflags=0x0001 ev=7 arg=0x5579ca2d01d0
Tue Apr 14 10:49:47 2020 us=469375 I/O WAIT T?|T?|SR|Sw [1/131857]
Tue Apr 14 10:49:47 2020 us=486192 PO_WAIT[0,0] fd=7 rev=0x00000001 rwflags=0x0001 arg=0x5579ca2d01d0 
Tue Apr 14 10:49:47 2020 us=486301  event_wait returned 1
Tue Apr 14 10:49:47 2020 us=486322 I/O WAIT status=0x0001
Tue Apr 14 10:49:47 2020 us=486356 UDP read returned 1172
Tue Apr 14 10:49:47 2020 us=486948 UDP READ [1172] from [AF_INET]192.168.1.170:1194: P_CONTROL_V1 kid=0 sid=05c5c5c6 dfd7a22f tls_hmac=58ccf7d4 0b4c06c9 fb034834 d92dc0ce 28afa09b pid=[ #3 / time = (1586886711) Tue Apr 14 10:51:51 2020 ] [ 2 sid=a18a384a 848342fe ] pid=2 DATA 16030300 bb020000 b70303a0 5a88241f 28cf864c 24ab532e b67a872f 
Tue Apr 14 10:49:47 2020 us=486987 TLS: control channel, op=P_CONTROL_V1, IP=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=487031 TLS: initial packet test, i=0 state=S_SENT_KEY, mysid=a18a384a 848342fe, rec-sid=05c5c5c6 dfd7a22f, rec-ip=[AF_INET]192.168.1.170:1194, stored-sid=05c5c5c6 dfd7a22f, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=487067 TLS: found match, session[0], sid=05c5c5c6 dfd7a22f
Tue Apr 14 10:49:47 2020 us=487763 DECRYPT FROM: 58ccf7d4 0b4c06c9 fb034834 d92dc0ce 28afa09b 00000003 5e95f837 2005c5c[more...]
Tue Apr 14 10:49:47 2020 us=487815 PID_TEST [0] [TLS_WRAP-0] [00] 1586886711:2 1586886711:3 t=1586886587[0] r=[0,64,15,0,1] sl=[62,2,64,528]
Tue Apr 14 10:49:47 2020 us=487847 TLS: received control channel packet s#=0 sid=05c5c5c6 dfd7a22f
Tue Apr 14 10:49:47 2020 us=487870 ACK received for pid 2, deleting from send buffer
Tue Apr 14 10:49:47 2020 us=487897 ACK read ID 2 (buf->len=1118)
Tue Apr 14 10:49:47 2020 us=487929 ACK RWBS rel->size=8 rel->packet_id=00000002 id=00000002 ret=1

Tue Apr 14 10:49:47 2020 us=487961 ACK mark active incoming ID 2
Tue Apr 14 10:49:47 2020 us=487993 ACK acknowledge ID 2 (ack->len=1)
Tue Apr 14 10:49:47 2020 us=488038 TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=a18a384a 848342fe, stored-sid=05c5c5c6 dfd7a22f, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=488068 TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=488093 ACK reliable_can_send active=0 current=0 : [3]
Tue Apr 14 10:49:47 2020 us=488123 BIO write tls_write_ciphertext 1118 bytes
Tue Apr 14 10:49:47 2020 us=488155 Incoming Ciphertext -> TLS
Tue Apr 14 10:49:47 2020 us=488196 SSL state (connect): SSLv3/TLS write client hello
Tue Apr 14 10:49:47 2020 us=493348 SSL state (connect): SSLv3/TLS read server hello
Tue Apr 14 10:49:47 2020 us=493400 SSL state (connect): TLSv1.3 read encrypted extensions
Tue Apr 14 10:49:47 2020 us=493496 TLS: tls_process: chg=1 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=493529 ACK reliable_can_send active=0 current=0 : [3]
Tue Apr 14 10:49:47 2020 us=493563 ACK write ID 2 (ack->len=1, n=1)
Tue Apr 14 10:49:47 2020 us=493606 ENCRYPT HMAC: 1d4b424e 147aac1e bd2a9aa3 e2ebc23f 678f74bc
Tue Apr 14 10:49:47 2020 us=493654 ENCRYPT TO: 1d4b424e 147aac1e bd2a9aa3 e2ebc23f 678f74bc 00000005 5e95f7bb 28a18a3[more...]
Tue Apr 14 10:49:47 2020 us=493679 Dedicated ACK -> TCP/UDP
Tue Apr 14 10:49:47 2020 us=493706 ACK reliable_send_timeout 604800 [3]
Tue Apr 14 10:49:47 2020 us=493730 TLS: tls_process: timeout set to 60
Tue Apr 14 10:49:47 2020 us=493762 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=34ccc5cc 9126d835, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=493831 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=493865 PO_CTL rwflags=0x0003 ev=7 arg=0x5579ca2d01d0
Tue Apr 14 10:49:47 2020 us=493901 I/O WAIT T?|T?|SR|SW [1/131857]
Tue Apr 14 10:49:47 2020 us=493931 PO_WAIT[0,0] fd=7 rev=0x00000005 rwflags=0x0003 arg=0x5579ca2d01d0 
Tue Apr 14 10:49:47 2020 us=493962  event_wait returned 1
Tue Apr 14 10:49:47 2020 us=493984 I/O WAIT status=0x0003
Tue Apr 14 10:49:47 2020 us=494052 UDP WRITE [50] to [AF_INET]192.168.1.170:1194: P_ACK_V1 kid=0 sid=a18a384a 848342fe tls_hmac=1d4b424e 147aac1e bd2a9aa3 e2ebc23f 678f74bc pid=[ #5 / time = (1586886587) Tue Apr 14 10:49:47 2020 ] [ 2 sid=05c5c5c6 dfd7a22f ]
Tue Apr 14 10:49:47 2020 us=494130 UDP write returned 50
Tue Apr 14 10:49:47 2020 us=494179 TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=a18a384a 848342fe, stored-sid=05c5c5c6 dfd7a22f, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=494214 TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=494257 ACK reliable_can_send active=0 current=0 : [3]
Tue Apr 14 10:49:47 2020 us=494297 ACK reliable_send_timeout 604800 [3]
Tue Apr 14 10:49:47 2020 us=494335 TLS: tls_process: timeout set to 60
Tue Apr 14 10:49:47 2020 us=494375 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=34ccc5cc 9126d835, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=494411 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=494446 PO_CTL rwflags=0x0001 ev=7 arg=0x5579ca2d01d0
Tue Apr 14 10:49:47 2020 us=494479 I/O WAIT T?|T?|SR|Sw [1/131857]
Tue Apr 14 10:49:47 2020 us=494538 PO_WAIT[0,0] fd=7 rev=0x00000001 rwflags=0x0001 arg=0x5579ca2d01d0 
Tue Apr 14 10:49:47 2020 us=494571  event_wait returned 1
Tue Apr 14 10:49:47 2020 us=494621 I/O WAIT status=0x0001
Tue Apr 14 10:49:47 2020 us=494661 UDP read returned 1160
Tue Apr 14 10:49:47 2020 us=495320 UDP READ [1160] from [AF_INET]192.168.1.170:1194: P_CONTROL_V1 kid=0 sid=05c5c5c6 dfd7a22f tls_hmac=2492c70c 9b3b9981 c94b187c 8de389ae 444eedef pid=[ #4 / time = (1586886711) Tue Apr 14 10:51:51 2020 ] [ ] pid=3 DATA 85032ada 4eb35f5f 6bdb1e11 064900cf e079fe8e 2b402d44 c289f16f 709c983[more...]
Tue Apr 14 10:49:47 2020 us=495359 TLS: control channel, op=P_CONTROL_V1, IP=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=495402 TLS: initial packet test, i=0 state=S_SENT_KEY, mysid=a18a384a 848342fe, rec-sid=05c5c5c6 dfd7a22f, rec-ip=[AF_INET]192.168.1.170:1194, stored-sid=05c5c5c6 dfd7a22f, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=495433 TLS: found match, session[0], sid=05c5c5c6 dfd7a22f
Tue Apr 14 10:49:47 2020 us=496075 DECRYPT FROM: 2492c70c 9b3b9981 c94b187c 8de389ae 444eedef 00000004 5e95f837 2005c5c[more...]
Tue Apr 14 10:49:47 2020 us=496118 PID_TEST [0] [TLS_WRAP-0] [000] 1586886711:3 1586886711:4 t=1586886587[0] r=[0,64,15,0,1] sl=[61,3,64,528]
Tue Apr 14 10:49:47 2020 us=496150 TLS: received control channel packet s#=0 sid=05c5c5c6 dfd7a22f
Tue Apr 14 10:49:47 2020 us=496173 ACK read ID 3 (buf->len=1118)
Tue Apr 14 10:49:47 2020 us=496196 ACK RWBS rel->size=8 rel->packet_id=00000003 id=00000003 ret=1

Tue Apr 14 10:49:47 2020 us=496227 ACK mark active incoming ID 3
Tue Apr 14 10:49:47 2020 us=496273 ACK acknowledge ID 3 (ack->len=1)
Tue Apr 14 10:49:47 2020 us=496336 TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=a18a384a 848342fe, stored-sid=05c5c5c6 dfd7a22f, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=496360 TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=496384 ACK reliable_can_send active=0 current=0 : [3]
Tue Apr 14 10:49:47 2020 us=496425 BIO write tls_write_ciphertext 1118 bytes
Tue Apr 14 10:49:47 2020 us=496445 Incoming Ciphertext -> TLS
Tue Apr 14 10:49:47 2020 us=496477 SSL state (connect): SSLv3/TLS read server certificate request
Tue Apr 14 10:49:47 2020 us=496905 VERIFY OK: depth=1, CN=Easy-RSA CA
Tue Apr 14 10:49:47 2020 us=497166 VERIFY KU OK
Tue Apr 14 10:49:47 2020 us=497190 Validating certificate extended key usage
Tue Apr 14 10:49:47 2020 us=497208 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Tue Apr 14 10:49:47 2020 us=497224 VERIFY EKU OK
Tue Apr 14 10:49:47 2020 us=497256 VERIFY OK: depth=0, CN=server
Tue Apr 14 10:49:47 2020 us=497310 TLS: tls_process: chg=1 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=497355 ACK reliable_can_send active=0 current=0 : [3]
Tue Apr 14 10:49:47 2020 us=497381 ACK write ID 3 (ack->len=1, n=1)
Tue Apr 14 10:49:47 2020 us=497406 ENCRYPT HMAC: b00915e5 dab97bed 1b81241e e48af0d6 ce7aedb7
Tue Apr 14 10:49:47 2020 us=497434 ENCRYPT TO: b00915e5 dab97bed 1b81241e e48af0d6 ce7aedb7 00000006 5e95f7bb 28a18a3[more...]
Tue Apr 14 10:49:47 2020 us=497454 Dedicated ACK -> TCP/UDP
Tue Apr 14 10:49:47 2020 us=497470 ACK reliable_send_timeout 604800 [3]
Tue Apr 14 10:49:47 2020 us=497489 TLS: tls_process: timeout set to 60
Tue Apr 14 10:49:47 2020 us=497510 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=34ccc5cc 9126d835, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=497550 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=497571 PO_CTL rwflags=0x0003 ev=7 arg=0x5579ca2d01d0
Tue Apr 14 10:49:47 2020 us=497606 I/O WAIT T?|T?|SR|SW [1/131857]
Tue Apr 14 10:49:47 2020 us=497643 PO_WAIT[0,0] fd=7 rev=0x00000005 rwflags=0x0003 arg=0x5579ca2d01d0 
Tue Apr 14 10:49:47 2020 us=497660  event_wait returned 1
Tue Apr 14 10:49:47 2020 us=497676 I/O WAIT status=0x0003
Tue Apr 14 10:49:47 2020 us=497723 UDP WRITE [50] to [AF_INET]192.168.1.170:1194: P_ACK_V1 kid=0 sid=a18a384a 848342fe tls_hmac=b00915e5 dab97bed 1b81241e e48af0d6 ce7aedb7 pid=[ #6 / time = (1586886587) Tue Apr 14 10:49:47 2020 ] [ 3 sid=05c5c5c6 dfd7a22f ]
Tue Apr 14 10:49:47 2020 us=497786 UDP write returned 50
Tue Apr 14 10:49:47 2020 us=497820 TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=a18a384a 848342fe, stored-sid=05c5c5c6 dfd7a22f, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=497838 TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=497854 ACK reliable_can_send active=0 current=0 : [3]
Tue Apr 14 10:49:47 2020 us=497891 ACK reliable_send_timeout 604800 [3]
Tue Apr 14 10:49:47 2020 us=497909 TLS: tls_process: timeout set to 60
Tue Apr 14 10:49:47 2020 us=497935 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=34ccc5cc 9126d835, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=497960 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=497978 PO_CTL rwflags=0x0001 ev=7 arg=0x5579ca2d01d0
Tue Apr 14 10:49:47 2020 us=498000 I/O WAIT T?|T?|SR|Sw [1/131857]
Tue Apr 14 10:49:47 2020 us=498025 PO_WAIT[0,0] fd=7 rev=0x00000001 rwflags=0x0001 arg=0x5579ca2d01d0 
Tue Apr 14 10:49:47 2020 us=498042  event_wait returned 1
Tue Apr 14 10:49:47 2020 us=498057 I/O WAIT status=0x0001
Tue Apr 14 10:49:47 2020 us=498083 UDP read returned 252
Tue Apr 14 10:49:47 2020 us=498214 UDP READ [252] from [AF_INET]192.168.1.170:1194: P_CONTROL_V1 kid=0 sid=05c5c5c6 dfd7a22f tls_hmac=09924460 851acdef bd90597b 5268886c d4a7de6b pid=[ #5 / time = (1586886711) Tue Apr 14 10:51:51 2020 ] [ ] pid=4 DATA ada733d0 91d3b763 87a6db0b 1b66f751 401897de 16ad8513 82aa9ac1 2899084[more...]
Tue Apr 14 10:49:47 2020 us=498251 TLS: control channel, op=P_CONTROL_V1, IP=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=498290 TLS: initial packet test, i=0 state=S_SENT_KEY, mysid=a18a384a 848342fe, rec-sid=05c5c5c6 dfd7a22f, rec-ip=[AF_INET]192.168.1.170:1194, stored-sid=05c5c5c6 dfd7a22f, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=498313 TLS: found match, session[0], sid=05c5c5c6 dfd7a22f
Tue Apr 14 10:49:47 2020 us=498424 DECRYPT FROM: 09924460 851acdef bd90597b 5268886c d4a7de6b 00000005 5e95f837 2005c5c[more...]
Tue Apr 14 10:49:47 2020 us=498451 PID_TEST [0] [TLS_WRAP-0] [0000] 1586886711:4 1586886711:5 t=1586886587[0] r=[0,64,15,0,1] sl=[60,4,64,528]
Tue Apr 14 10:49:47 2020 us=498475 TLS: received control channel packet s#=0 sid=05c5c5c6 dfd7a22f
Tue Apr 14 10:49:47 2020 us=498493 ACK read ID 4 (buf->len=210)
Tue Apr 14 10:49:47 2020 us=498512 ACK RWBS rel->size=8 rel->packet_id=00000004 id=00000004 ret=1

Tue Apr 14 10:49:47 2020 us=498530 ACK mark active incoming ID 4
Tue Apr 14 10:49:47 2020 us=498545 ACK acknowledge ID 4 (ack->len=1)
Tue Apr 14 10:49:47 2020 us=498588 TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=a18a384a 848342fe, stored-sid=05c5c5c6 dfd7a22f, stored-ip=[AF_INET]192.168.1.170:1194
Tue Apr 14 10:49:47 2020 us=498621 TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Tue Apr 14 10:49:47 2020 us=498638 ACK reliable_can_send active=0 current=0 : [3]
Tue Apr 14 10:49:47 2020 us=498655 BIO write tls_write_ciphertext 210 bytes
Tue Apr 14 10:49:47 2020 us=498688 Incoming Ciphertext -> TLS
Tue Apr 14 10:49:47 2020 us=498722 SSL state (connect): SSLv3/TLS read server certificate
Tue Apr 14 10:49:47 2020 us=498921 SSL state (connect): TLSv1.3 read server certificate verify
Tue Apr 14 10:49:47 2020 us=499046 SSL state (connect): SSLv3/TLS read finished
Tue Apr 14 10:49:47 2020 us=499301 SSL state (connect): SSLv3/TLS write client certificate
Tue Apr 14 10:49:47 2020 us=499354 PKCS#11: __pkcs11h_openssl_rsa_enc entered - flen=256, from=0x5579ca6ea9d0, to=0x5579ca6ea8c0, rsa=0x5579ca6c0f40, padding=3
Tue Apr 14 10:49:47 2020 us=499377 PKCS#11: __pkcs11h_openssl_rsa_enc - return rv=112-'CKR_MECHANISM_INVALID'
Tue Apr 14 10:49:47 2020 us=499407 SSL alert (write): fatal: internal error
Tue Apr 14 10:49:47 2020 us=499436 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
Tue Apr 14 10:49:47 2020 us=499451 TLS_ERROR: BIO read tls_read_plaintext error
Tue Apr 14 10:49:47 2020 us=499468 TLS Error: TLS object -> incoming plaintext read error
Tue Apr 14 10:49:47 2020 us=499485 TLS Error: TLS handshake failed
Tue Apr 14 10:49:47 2020 us=499498 PID packet_id_free
Tue Apr 14 10:49:47 2020 us=499541 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=0x5579ca6de140, ptr=(nil), ad=0x5579ca6de1a8, idx=1, argl=0, argp=0x7f941fa9d683
Tue Apr 14 10:49:47 2020 us=499580 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=0x5579ca6e2730, ptr=(nil), ad=0x5579ca6e2798, idx=1, argl=0, argp=0x7f941fa9d683
Tue Apr 14 10:49:47 2020 us=499649 PID packet_id_free
Tue Apr 14 10:49:47 2020 us=499669 PID packet_id_free
Tue Apr 14 10:49:47 2020 us=499688 TLS: tls_session_init: entry
Tue Apr 14 10:49:47 2020 us=499706 PID packet_id_init seq_backtrack=64 time_backtrack=15
Tue Apr 14 10:49:47 2020 us=499749 PID packet_id_init seq_backtrack=64 time_backtrack=15
Tue Apr 14 10:49:47 2020 us=499770 TLS: tls_session_init: new session object, sid=f4eecf61 c168b08b
Tue Apr 14 10:49:47 2020 us=499809 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=34ccc5cc 9126d835, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=499836 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Tue Apr 14 10:49:47 2020 us=499856 PID packet_id_free
Tue Apr 14 10:49:47 2020 us=499893 PID packet_id_free
Tue Apr 14 10:49:47 2020 us=499912 PID packet_id_free
Tue Apr 14 10:49:47 2020 us=499932 PID packet_id_free
Tue Apr 14 10:49:47 2020 us=499961 PID packet_id_free
Tue Apr 14 10:49:47 2020 us=499979 PID packet_id_free
Tue Apr 14 10:49:47 2020 us=499996 PID packet_id_free
Tue Apr 14 10:49:47 2020 us=500009 PID packet_id_free
Tue Apr 14 10:49:47 2020 us=500023 TCP/UDP: Closing socket
Tue Apr 14 10:49:47 2020 us=500076 PID packet_id_free
Tue Apr 14 10:49:47 2020 us=500104 SIGUSR1[soft,tls-error] received, process restarting
Tue Apr 14 10:49:47 2020 us=500136 Restart pause, 5 second(s)
^CTue Apr 14 10:49:49 2020 us=348152 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=0x5579ca6bd760, ptr=(nil), ad=0x5579ca6bd7c8, idx=1, argl=0, argp=0x7f941fa9d683
Tue Apr 14 10:49:49 2020 us=348346 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=0x5579ca6c1930, ptr=(nil), ad=0x5579ca6c1998, idx=1, argl=0, argp=0x7f941fa9d683
Tue Apr 14 10:49:49 2020 us=348412 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=0x5579ca6c0f40, ptr=0x5579ca6b6c60, ad=0x5579ca6c0fa8, idx=1, argl=0, argp=0x7f941fa9d683
Tue Apr 14 10:49:49 2020 us=348446 PKCS#11: pkcs11h_openssl_freeSession - entry openssl_session=0x5579ca6b6c60, count=1
Tue Apr 14 10:49:49 2020 us=348492 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=0x5579ca6c0220, ptr=(nil), ad=0x5579ca6c0288, idx=1, argl=0, argp=0x7f941fa9d683
Tue Apr 14 10:49:49 2020 us=348543 PKCS#11: pkcs11h_certificate_freeCertificate entry certificate=0x5579ca6b8c70
Tue Apr 14 10:49:49 2020 us=348588 PKCS#11: _pkcs11h_session_release entry session=0x5579ca6bc170
Tue Apr 14 10:49:49 2020 us=348628 PKCS#11: _pkcs11h_session_release return rv=0-'CKR_OK'
Tue Apr 14 10:49:49 2020 us=348658 PKCS#11: pkcs11h_certificate_freeCertificateId entry certificate_id=0x5579ca6bdd50
Tue Apr 14 10:49:49 2020 us=348771 PKCS#11: pkcs11h_token_freeTokenId entry certificate_id=0x5579ca6be180
Tue Apr 14 10:49:49 2020 us=348803 PKCS#11: pkcs11h_token_freeTokenId return
Tue Apr 14 10:49:49 2020 us=348842 PKCS#11: pkcs11h_certificate_freeCertificateId return
Tue Apr 14 10:49:49 2020 us=348874 PKCS#11: pkcs11h_certificate_freeCertificate return
Tue Apr 14 10:49:49 2020 us=348913 PKCS#11: pkcs11h_openssl_freeSession - return
Tue Apr 14 10:49:49 2020 us=348966 PID packet_id_free
Tue Apr 14 10:49:49 2020 us=349021 SIGINT[hard,init_instance] received, process exiting
Tue Apr 14 10:49:49 2020 us=349068 PKCS#11: pkcs11_terminate - entered
Tue Apr 14 10:49:49 2020 us=349106 PKCS#11: pkcs11h_terminate entry
Tue Apr 14 10:49:49 2020 us=349141 PKCS#11: Terminating openssl
Tue Apr 14 10:49:49 2020 us=349171 PKCS#11: _pkcs11h_openssl_terminate
Tue Apr 14 10:49:49 2020 us=349210 PKCS#11: Removing providers
Tue Apr 14 10:49:49 2020 us=349280 PKCS#11: pkcs11h_removeProvider entry reference='/usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0'
Tue Apr 14 10:49:49 2020 us=349314 PKCS#11: Removing provider '/usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0'
INFO on line: "379" in file: "src/pkcs11.c": enter "C_Finalize"
INFO on line: "379" in file: "src/pkcs11.c": return "C_Finalize" value: 0
Tue Apr 14 10:49:49 2020 us=362178 PKCS#11: _pkcs11h_slotevent_notify entry
Tue Apr 14 10:49:49 2020 us=362221 PKCS#11: _pkcs11h_slotevent_notify return
Tue Apr 14 10:49:49 2020 us=362714 PKCS#11: pkcs11h_removeProvider return rv=0-'CKR_OK'
Tue Apr 14 10:49:49 2020 us=362757 PKCS#11: Releasing sessions
Tue Apr 14 10:49:49 2020 us=362787 PKCS#11: pkcs11h_token_freeTokenId entry certificate_id=0x5579ca6be5f0
Tue Apr 14 10:49:49 2020 us=362815 PKCS#11: pkcs11h_token_freeTokenId return
Tue Apr 14 10:49:49 2020 us=362847 PKCS#11: pkcs11h_certificate_freeCertificateIdList entry cert_id_list=(nil)
Tue Apr 14 10:49:49 2020 us=362904 PKCS#11: pkcs11h_certificate_freeCertificateIdList return
Tue Apr 14 10:49:49 2020 us=362936 PKCS#11: Terminating slotevent
Tue Apr 14 10:49:49 2020 us=362966 PKCS#11: _pkcs11h_slotevent_terminate entry
Tue Apr 14 10:49:49 2020 us=362997 PKCS#11: _pkcs11h_slotevent_terminate return
Tue Apr 14 10:49:49 2020 us=363027 PKCS#11: Marking as uninitialized
Tue Apr 14 10:49:49 2020 us=363058 PKCS#11: pkcs11_terminate - return

This sounds familiar

Tue Apr 14 10:49:47 2020 us=499354 PKCS#11: __pkcs11h_openssl_rsa_enc entered - flen=256, from=0x5579ca6ea9d0, to=0x5579ca6ea8c0, rsa=0x5579ca6c0f40, padding=3
Tue Apr 14 10:49:47 2020 us=499377 PKCS#11: __pkcs11h_openssl_rsa_enc - return rv=112-'CKR_MECHANISM_INVALID'
Tue Apr 14 10:49:47 2020 us=499407 SSL alert (write): fatal: internal error
Tue Apr 14 10:49:47 2020 us=499436 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib

I found this issue with a similar problem

http://openssl.6102.n7.nabble.com/Issue-with-smartcard-authentication-for-openvpn-td76415.html

I quote

padding = 3 means "no padding" indicating that the data for signature is already padded. That's why the data size (flen) is 256 (hashed data padded to the rsa key size of 2048 bits, I guess). If you are using OpenSSL 1.1.1, this could be due to PSS padding in which case current implementation passes pre-padded data for raw signature to the callback. AFAIK, pkcs11-helper only handles PKCS1 padding (CKM_RSA_PKCS) though pkcs11 standard does support raw signatures.

PSS padding again?

williamcroberts commented 4 years ago

sounds like something to do with padding. Usually if the application applies the padding they call into the library with CKM_RSA_X_509 (raw rsa signatures).

williamcroberts commented 4 years ago

So i think we need to get this into a document, it, hopefully, should work now.

dnoliver commented 4 years ago

did something changed in the pkcs11 package to enable this?

williamcroberts commented 4 years ago

@dnoliver , nope. I thought I fixed it, but I wonder if this is related to:

But we could at least start a proper markdown document.

williamcroberts commented 4 years ago

@dnoliver do you think you could submit a standalone test like TLS? This way I have something consistent to test and fix to.

dnoliver commented 4 years ago

I will validate my script from https://github.com/tpm2-software/tpm2-pkcs11/issues/67#issuecomment-613580185 again with the latest packages on Fedora 32 and polish that test.

should I use latest RPM available for tpm2-pkcs11, tpm2-tools and tpm2-tss? or a release candidate or master?

dnoliver commented 4 years ago

Tested this with latest rpm packages.

[root@fitlet-3 openvpn-client]# rpm -qa tpm2*
tpm2-tss-2.4.1-1.fc32.x86_64
tpm2-pkcs11-1.3.0-1.fc32.x86_64
tpm2-pkcs11-tools-1.3.0-1.fc32.x86_64
tpm2-tools-4.1.3-1.fc32.x86_64

[root@fitlet-3 openvpn-client]# uname -a
Linux fitlet-3 5.7.9-200.fc32.x86_64 #1 SMP Fri Jul 17 16:23:37 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

[root@fitlet-3 openvpn-client]# cat /etc/redhat-release 
Fedora release 32 (Thirty Two)

The script in https://github.com/tpm2-software/tpm2-pkcs11/issues/67#issuecomment-613580185 works with some tweaks.

But I am seeing a different error now:

Fri Jul 24 13:42:42 2020 us=732121 VERIFY OK: depth=1, CN=Easy-RSA CA                                                                                                                                 
Fri Jul 24 13:42:42 2020 us=732731 VERIFY KU OK                                                                                                                                                                
Fri Jul 24 13:42:42 2020 us=732791 Validating certificate extended key usage                                                                                                                                   
Fri Jul 24 13:42:42 2020 us=732831 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication                                                                           
Fri Jul 24 13:42:42 2020 us=732867 VERIFY EKU OK                                                                                                                                                               
Fri Jul 24 13:42:42 2020 us=732906 VERIFY OK: depth=0, CN=server                                                                                                                                               
Fri Jul 24 13:42:42 2020 us=733026 UDP WRITE [50] to [AF_INET]192.168.0.43:1194: P_ACK_V1 kid=0 pid=[ #5 ] [ 2 ]                                                                                               
Fri Jul 24 13:42:42 2020 us=733195 UDP READ [193] from [AF_INET]192.168.0.43:1194: P_CONTROL_V1 kid=0 pid=[ #4 ] [ ] pid=3 DATA len=151                                                                        
Fri Jul 24 13:42:42 2020 us=734431 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib                                                                                                      
Fri Jul 24 13:42:42 2020 us=734472 TLS_ERROR: BIO read tls_read_plaintext error                                                                                                                                
Fri Jul 24 13:42:42 2020 us=734491 TLS Error: TLS object -> incoming plaintext read error                                                                                                                      
Fri Jul 24 13:42:42 2020 us=734509 TLS Error: TLS handshake failed
Fri Jul 24 13:42:42 2020 us=734651 TCP/UDP: Closing socket
Fri Jul 24 13:42:42 2020 us=734707 SIGUSR1[soft,tls-error] received, process restarting
Fri Jul 24 13:42:42 2020 us=734746 Restart pause, 5 second(s)
Fri Jul 24 13:42:45 2020 us=507045 SIGINT[hard,init_instance] received, process exiting
INFO on line: "379" in file: "src/pkcs11.c": enter "C_Finalize"
INFO on line: "379" in file: "src/pkcs11.c": return "C_Finalize" value: 0

I don't see the classic CKR_MECHANISM_INVALID string.

I saw this issue https://github.com/dpb587/ssoca/issues/13#issuecomment-534573394, and apparently there is something being done in openvpn for PSS padding. But I am getting cert errors trying to open openvpn.net in my IT laptop, so I cannot open the issue.

Will get that script more reproducible and post it here

dnoliver commented 4 years ago

With more verbosity, the CKR_MECHANISM_INVALID appears :(

Mon Jul 27 11:02:04 2020 us=547621 ACK mark active incoming ID 3
Mon Jul 27 11:02:04 2020 us=547636 ACK acknowledge ID 3 (ack->len=1)
Mon Jul 27 11:02:04 2020 us=547662 TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=654ae639 c397b1d5, stored-sid=aff67aaa e54fc748, stored-ip=[AF_INET]192.168.0.43:1194
Mon Jul 27 11:02:04 2020 us=547680 TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Mon Jul 27 11:02:04 2020 us=547696 ACK reliable_can_send active=0 current=0 : [2]
Mon Jul 27 11:02:04 2020 us=547712 BIO write tls_write_ciphertext 150 bytes
Mon Jul 27 11:02:04 2020 us=547727 Incoming Ciphertext -> TLS
Mon Jul 27 11:02:04 2020 us=547755 SSL state (connect): SSLv3/TLS read server certificate
Mon Jul 27 11:02:04 2020 us=547968 SSL state (connect): TLSv1.3 read server certificate verify
Mon Jul 27 11:02:04 2020 us=548099 SSL state (connect): SSLv3/TLS read finished
Mon Jul 27 11:02:04 2020 us=548129 SSL state (connect): SSLv3/TLS write change cipher spec
Mon Jul 27 11:02:04 2020 us=548438 SSL state (connect): SSLv3/TLS write client certificate
Mon Jul 27 11:02:04 2020 us=548500 PKCS#11: __pkcs11h_openssl_rsa_enc entered - flen=256, from=0x55fb078d0130, to=0x55fb078cfe80, rsa=0x55fb078adba0, padding=3
Mon Jul 27 11:02:04 2020 us=548520 PKCS#11: __pkcs11h_openssl_rsa_enc - return rv=112-'CKR_MECHANISM_INVALID'
Mon Jul 27 11:02:04 2020 us=548549 SSL alert (write): fatal: internal error
Mon Jul 27 11:02:04 2020 us=548582 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
Mon Jul 27 11:02:04 2020 us=548599 TLS_ERROR: BIO read tls_read_plaintext error
Mon Jul 27 11:02:04 2020 us=548613 TLS Error: TLS object -> incoming plaintext read error
Mon Jul 27 11:02:04 2020 us=548628 TLS Error: TLS handshake failed
Mon Jul 27 11:02:04 2020 us=548642 PID packet_id_free
Mon Jul 27 11:02:04 2020 us=548700 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=0x55fb078ce5c0, ptr=(nil), ad=0x55fb078ce628, idx=1, argl=0, argp=0x7f5228bba683
Mon Jul 27 11:02:04 2020 us=548743 PKCS#11: __pkcs11h_openssl_ex_data_free entered - parent=0x55fb078cd890, ptr=(nil), ad=0x55fb078cd8f8, idx=1, argl=0, argp=0x7f5228bba683
Mon Jul 27 11:02:04 2020 us=548785 PID packet_id_free
Mon Jul 27 11:02:04 2020 us=548803 PID packet_id_free
Mon Jul 27 11:02:04 2020 us=548819 TLS: tls_session_init: entry
Mon Jul 27 11:02:04 2020 us=548840 PID packet_id_init seq_backtrack=64 time_backtrack=15
Mon Jul 27 11:02:04 2020 us=548889 PID packet_id_init seq_backtrack=64 time_backtrack=15
Mon Jul 27 11:02:04 2020 us=548911 TLS: tls_session_init: new session object, sid=1bf7d45e 8db89f9c
Mon Jul 27 11:02:04 2020 us=548934 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=b9e2dcbd 571705ca, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Mon Jul 27 11:02:04 2020 us=548955 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Mon Jul 27 11:02:04 2020 us=548975 PID packet_id_free

Found a thread running into a similar issue https://marc.info/?t=155491198200001&r=1&w=2, maybe it is relevant

So, to reproduce (~still need 2 devices with PTT~)

Server Setup

#!/bin/bash 

set -euxo pipefail

dnf install openvn
firewall-cmd --add-service=openvpn --permanent
firewall-cmd --reload

mkdir -p openvpn-server
cd openvpn-server

# Download Easy RSA
wget https://github.com/OpenVPN/easy-rsa/releases/download/v3.0.5/EasyRSA-nix-3.0.5.tgz \
        -O EasyRSA-nix-3.0.5.tgz
tar -zxvf EasyRSA-nix-3.0.5.tgz
cd EasyRSA-3.0.5

# Create PKI and Initial CA
./easyrsa init-pki
./easyrsa build-ca

# Generate Server Certs and Artifacts
./easyrsa build-server-full server
./easyrsa gen-dh

cd ..

# Configure Server
cp /usr/share/doc/openvpn/sample/sample-config-files/server.conf .
cp ./EasyRSA-3.0.5/pki/private/server.key .
cp ./EasyRSA-3.0.5/pki/issued/server.crt .
cp ./EasyRSA-3.0.5/pki/dh.pem dh2048.pem
cp ./EasyRSA-3.0.5/pki/ca.crt .
openvpn --genkey --secret ta.key

Client CSR Setup

#!/bin/bash

set -euxo pipefail

# Create certificate Signing Request Configuration

cat > client.cnf << EOF
[ req ]
default_bits           = 2048
distinguished_name     = req_distinguished_name
prompt                 = no
[ req_distinguished_name ]
C                      = US
ST                     = Oregon
L                      = Hillsboro
O                      = Intel Corp
OU                     = Internet of Things Group
CN                     = $(hostname)
EOF

# Create the TPM2 PKCS11 Key

export TPM2TOOLS_TCTI="device:/dev/tpmrm0"
export TPM2_PKCS11_TCTI="device:/dev/tpmrm0"
export TPM2_PKCS11_STORE=/etc/tpm2_pkcs11
export TPM2_PKCS11_LOG_LEVEL=2

rm ${TPM2_PKCS11_STORE} -fr || true
mkdir -p ${TPM2_PKCS11_STORE} || true
tpm2_clear
tpm2_ptool init
tpm2_ptool addtoken --pid=1 --sopin=sopin --userpin=userpin --label=openvpn
tpm2_ptool addkey --algorithm=rsa2048 --label=openvpn --userpin=userpin
tpm2_ptool config --key tcti --value "device:/dev/tpmrm0" --label=openvpn

# Create the Certificate Signing Request

TOKEN=$(p11tool --list-token-urls | grep "token=openvpn")
export GNUTLS_PIN=userpin
export GNUTLS_SO_PIN=sopin
p11tool --login --list-all "${TOKEN}" --outfile p11tool.out
PRIVATE_KEY=$(cat p11tool.out | grep private | awk '{ print $2 }')
openssl req -new -engine pkcs11 -keyform engine \
        -key "${PRIVATE_KEY};pin-value=userpin" \
        -config client.cnf -out client.csr

Generate Client Cert in the Server

Copy the client.csr generated before, copy that to the server, and sign it

cd openvpn-server/EasyRSA-3.0.5
./easyrsa import-req ./client.csr client
./easyrsa sign-req client client
cat ./pki/issued/client.crt

Configure OpenVPN Client

cd openvpn-client

# Get Certificate from server
cat client.crt

# Get Config from Server
cat ca.crt
cat ta.key

# Configure Client
cp /usr/share/doc/openvpn/sample/sample-config-files/client.conf .
sed -i 's/remote my-server-1 1194/remote 192.168.0.43 1194/g' client.conf

Import the certificate into the PKCS11 Store

#!/bin/bash

set -euxo pipefail

TOKEN=$(p11tool --list-token-urls | grep "token=openvpn")
export GNUTLS_PIN=userpin
export GNUTLS_SO_PIN=sopin
KEY_ID=$(p11tool --login --list-all "${TOKEN}" | grep ID: | uniq | awk '{ print $2 }' | sed 's/://g')
tpm2_ptool addcert --label=openvpn --key-id=${KEY_ID} ./client.crt
SERIALIZED_ID=$(openvpn --show-pkcs11-ids /usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0 | grep "Serialized id:" | awk '{ print $3 }')

cat << EOF
# Comment the cert and key lines and add the following to the config:
pkcs11-providers /usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0
pkcs11-id '${SERIALIZED_ID}'
EOF

Update config with the last lines

[root@fitlet-3 openvpn-client]# diff /usr/share/doc/openvpn/sample/sample-config-files/client.conf client.conf
42c42
< remote my-server-1 1194
---
> remote 192.168.0.43 1194
89,90c89,93
< cert client.crt
< key client.key
---
> #cert client.crt
> #key client.key
> # Comment the cert and key lines and add the following to the config:
> pkcs11-providers /usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0
> pkcs11-id 'pkcs11:model=Intel;token=openvpn;manufacturer=Intel;serial=0000000000000000;id=e3dac3f1de50d109'

Test

Start the server

cd openvpn-server
openvpn --config server.conf --verb 11

Start the client (verb 11 shows pkcs11 activities) No bind means do not use default port 1194, which enables testing this locally in a single host!

cd openvpn-client
openvpn --config client.conf --verb 11 --nobind
dnoliver commented 4 years ago

~Got everything working in a single script :)~ Got an standalone test in a single script to run in a single host and reproduce this

https://gist.github.com/dnoliver/4b7458c0dba28132009a07e18d12dd5d

Takes some time to get the Diffie Hellman stuff generated, but at least it works all the time in my device

dnoliver commented 4 years ago

I did run this test in a HyperV VM with vanilla Fedora Server 32 using a Software TPM, and I have the same result. So maybe Platform Trust Technology is not the root cause in this case?

williamcroberts commented 4 years ago

Awesome. This should be easily adaptable to a make test and a how-to guide.

Bill

-----Original Message----- From: Nicolas Oliver notifications@github.com Sent: Monday, July 27, 2020 3:28 PM To: tpm2-software/tpm2-pkcs11 tpm2-pkcs11@noreply.github.com Cc: Roberts, William C william.c.roberts@intel.com; Mention mention@noreply.github.com Subject: Re: [tpm2-software/tpm2-pkcs11] OpenVPN setup example (#67)

Got everything working in a single script :)

https://gist.github.com/dnoliver/4b7458c0dba28132009a07e18d12dd5d

Takes some time to get the Diffie Hellman stuff generated, but at least it works all the time in my device

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/tpm2- software/tpm2-pkcs11/issues/67#issuecomment-664620531 , or unsubscribe https://github.com/notifications/unsubscribe- auth/AEHNWBZBAGYVVPUPVYX3PADR5XPLFANCNFSM4GBQWB5Q . https://github.com/notifications/beacon/AEHNWB3JQEMNBHKVOJ6CTZTR5XPL FA5CNFSM4GBQWB52YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJK TDN5WW2ZLOORPWSZGOE6OU34Y.gif

dnoliver commented 4 years ago

Tested the same gist with latest master versions of tpm2-tools, tpm2-tss and tpm2-pkcs11, still the same behavior (CKR_MECHANISM_INVALID)

dnoliver commented 4 years ago

The setup more or less works with TLS 1.1, bad luck it is deprecated! At least it passes the cert verification, ask for the pin, and tries to establish the tun interface.

If you change the tls version to 1.2, it fails with the CKR_MECHANISM_INVALID

Start the server with --tls-version-max

[root@openvpn openvpn-server]# openvpn --config ./server.conf --tls-version-max 1.1

And do the same with the client:

[root@openvpn openvpn-client]# openvpn --config ./client.conf --nobind --tls-version-max 1.1                                                                                                                   
Thu Aug  6 08:00:36 2020 OpenVPN 2.4.9 x86_64-redhat-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Apr 19 2020                                                           
Thu Aug  6 08:00:36 2020 library versions: OpenSSL 1.1.1g FIPS  21 Apr 2020, LZO 2.10                                                                                                                          
Thu Aug  6 08:00:36 2020 PKCS#11: Adding PKCS#11 provider '/usr/lib64/pkcs11/libtpm2_pkcs11.so.0.0.0'                                                                                                          
INFO on line: "387" in file: "src/pkcs11.c": enter "C_GetFunctionList"                                                                                                                                         
INFO on line: "387" in file: "src/pkcs11.c": return "C_GetFunctionList" value: 0                                                                                                                               
INFO on line: "375" in file: "src/pkcs11.c": enter "C_Initialize"                                                                                                                                              
INFO on line: "41" in file: "src/lib/backend.c": Initializing backends                                                                                                                                         
INFO on line: "67" in file: "src/lib/backend_fapi.c": Calling Fapi_Initialize                                                                                                                                  
INFO on line: "1402" in file: "src/lib/db.c": using TPM2_PKCS11_STORE="/etc/tpm2_pkcs11/tpm2_pkcs11.sqlite3"                                                                                                   
INFO on line: "2167" in file: "src/lib/db.c": Using sqlite3 DB: "/etc/tpm2_pkcs11/tpm2_pkcs11.sqlite3"                                                                                                         
INFO on line: "2125" in file: "src/lib/db.c": No DB upgrade needed                                                                                                                                             
INFO on line: "424" in file: "src/lib/tpm.c": tcti=device:/dev/tpmrm0                                                                                                                                          
INFO on line: "391" in file: "src/lib/mech.c": Updating mech detail table that PSS signatures are: good                                                                                                        
INFO on line: "180" in file: "src/lib/backend.c": Esysdb returned 1 token                                                                                                                                      
ERROR:fapi:src/tss2-fapi/api/Fapi_List.c:221:Fapi_List_Finish() FAPI not provisioned.                                                                                                                          
ERROR:fapi:src/tss2-fapi/api/Fapi_List.c:81:Fapi_List() ErrorCode (0x00060034) Entities_List                                                                                                                   
ERROR on line: "233" in file: "src/lib/backend_fapi.c": Listing FAPI token objects failed.                                                                                                                     
WARNING on line: "192" in file: "src/lib/backend.c": Getting tokens from fapi backend failed.
INFO on line: "195" in file: "src/lib/backend.c": FAPI + Esysdb returned 1 token                                                                                                                       
INFO on line: "424" in file: "src/lib/tpm.c": tcti=device:/dev/tpmrm0                                                                                                                                          
INFO on line: "224" in file: "src/lib/backend.c": Esysdb + FAPI returned 2 token                                                                                                                               
INFO on line: "375" in file: "src/pkcs11.c": return "C_Initialize" value: 0                                                                                                                                    
INFO on line: "383" in file: "src/pkcs11.c": enter "C_GetInfo"                                                                                                                                                 
WARNING on line: "63" in file: "src/lib/general.c": Could not strtoul(3.2-RC0-339-g00faef9): Success                                                                                                           
INFO on line: "383" in file: "src/pkcs11.c": return "C_GetInfo" value: 0                                                                                                                                       
INFO on line: "391" in file: "src/pkcs11.c": enter "C_GetSlotList"                                                                                                                                             
INFO on line: "391" in file: "src/pkcs11.c": return "C_GetSlotList" value: 0                                                                                                                                   
INFO on line: "391" in file: "src/pkcs11.c": enter "C_GetSlotList"                                                                                                                                             
INFO on line: "391" in file: "src/pkcs11.c": return "C_GetSlotList" value: 0                                                                                                                                   
INFO on line: "399" in file: "src/pkcs11.c": enter "C_GetTokenInfo"                                                                                                                                            
INFO on line: "399" in file: "src/pkcs11.c": return "C_GetTokenInfo" value: 0                                                                                                                                  
INFO on line: "427" in file: "src/pkcs11.c": enter "C_OpenSession"                                                                                                                                             
INFO on line: "427" in file: "src/pkcs11.c": return "C_OpenSession" value: 0                                                                                                                                   
INFO on line: "483" in file: "src/pkcs11.c": enter "C_FindObjectsInit"                                                                                                                                         
INFO on line: "483" in file: "src/pkcs11.c": return "C_FindObjectsInit" value: 0                                                                                                                               
INFO on line: "487" in file: "src/pkcs11.c": enter "C_FindObjects"                                                                                                                                             
INFO on line: "487" in file: "src/pkcs11.c": return "C_FindObjects" value: 0                                                                                                                                   
INFO on line: "487" in file: "src/pkcs11.c": enter "C_FindObjects"                                                                                                                                             
INFO on line: "487" in file: "src/pkcs11.c": return "C_FindObjects" value: 0                                                                                                                                   
INFO on line: "491" in file: "src/pkcs11.c": enter "C_FindObjectsFinal"                                                                                                                                        
INFO on line: "491" in file: "src/pkcs11.c": return "C_FindObjectsFinal" value: 0                                                                                                                              
INFO on line: "475" in file: "src/pkcs11.c": enter "C_GetAttributeValue"                                                                                                                                       
INFO on line: "475" in file: "src/pkcs11.c": return "C_GetAttributeValue" value: 0                                                                                                                             
INFO on line: "475" in file: "src/pkcs11.c": enter "C_GetAttributeValue"                                                                                                                                       
INFO on line: "475" in file: "src/pkcs11.c": return "C_GetAttributeValue" value: 0                                                                                                                             
Thu Aug  6 08:00:36 2020 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication                                                                                    
Thu Aug  6 08:00:36 2020 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication                                                                                    
Thu Aug  6 08:00:36 2020 TCP/UDP: Preserving recently used remote address: [AF_INET]127.0.0.1:1194                                                                                                             
Thu Aug  6 08:00:36 2020 Socket Buffers: R=[212992->212992] S=[212992->212992]                                                                                                                                 
Thu Aug  6 08:00:36 2020 UDP link local: (not bound)                                                                                                                                                           
Thu Aug  6 08:00:36 2020 UDP link remote: [AF_INET]127.0.0.1:1194                                                                                                                                              
Thu Aug  6 08:00:36 2020 TLS: Initial packet from [AF_INET]127.0.0.1:1194, sid=738c2d41 02449ee8                                                                                                               
Thu Aug  6 08:00:36 2020 VERIFY OK: depth=1, CN=Easy-RSA CA                                                                                                                                                    
Thu Aug  6 08:00:36 2020 VERIFY KU OK                                                                                                                                                                          
Thu Aug  6 08:00:36 2020 Validating certificate extended key usage                                                                                                                                             
Thu Aug  6 08:00:36 2020 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication                                                                                     
Thu Aug  6 08:00:36 2020 VERIFY EKU OK                                                                                                                                                                         
Thu Aug  6 08:00:36 2020 VERIFY OK: depth=0, CN=server
INFO on line: "483" in file: "src/pkcs11.c": enter "C_FindObjectsInit"                                                                                                                                 
INFO on line: "483" in file: "src/pkcs11.c": return "C_FindObjectsInit" value: 0                                                                                                                               
INFO on line: "487" in file: "src/pkcs11.c": enter "C_FindObjects"                                                                                                                                             
INFO on line: "487" in file: "src/pkcs11.c": return "C_FindObjects" value: 0                                                                                                                                   
INFO on line: "491" in file: "src/pkcs11.c": enter "C_FindObjectsFinal"                                                                                                                                        
INFO on line: "491" in file: "src/pkcs11.c": return "C_FindObjectsFinal" value: 0                                                                                                                              
INFO on line: "455" in file: "src/pkcs11.c": enter "C_Logout"                                                                                                                                                  
INFO on line: "455" in file: "src/pkcs11.c": return "C_Logout" value: 257                                                                                                                                      
INFO on line: "431" in file: "src/pkcs11.c": enter "C_CloseSession"                                                                                                                                            
INFO on line: "431" in file: "src/pkcs11.c": return "C_CloseSession" value: 0                                                                                                                                  
INFO on line: "391" in file: "src/pkcs11.c": enter "C_GetSlotList"                                                                                                                                             
INFO on line: "391" in file: "src/pkcs11.c": return "C_GetSlotList" value: 0                                                                                                                                   
INFO on line: "391" in file: "src/pkcs11.c": enter "C_GetSlotList"                                                                                                                                             
INFO on line: "391" in file: "src/pkcs11.c": return "C_GetSlotList" value: 0                                                                                                                                   
INFO on line: "399" in file: "src/pkcs11.c": enter "C_GetTokenInfo"                                                                                                                                            
INFO on line: "399" in file: "src/pkcs11.c": return "C_GetTokenInfo" value: 0                                                                                                                                  
INFO on line: "427" in file: "src/pkcs11.c": enter "C_OpenSession"                                                                                                                                             
INFO on line: "427" in file: "src/pkcs11.c": return "C_OpenSession" value: 0                                                                                                                                   
INFO on line: "375" in file: "src/pkcs11.c": enter "C_Initialize"                                                                                                                                              
INFO on line: "375" in file: "src/pkcs11.c": return "C_Initialize" value: 401                                                                                                                                  
INFO on line: "379" in file: "src/pkcs11.c": enter "C_Finalize"                                                                                                                                                
INFO on line: "76" in file: "src/lib/backend.c": Destroying backends                                                                                                                                           
INFO on line: "77" in file: "src/lib/backend_fapi.c": Calling Fapi_Finalize                                                                                                                                    
INFO on line: "379" in file: "src/pkcs11.c": return "C_Finalize" value: 0                                                                                                                                      
Enter openvpn token Password: *******                                                                                                                                                                          
INFO on line: "451" in file: "src/pkcs11.c": enter "C_Login"                                                                                                                                                   
INFO on line: "291" in file: "src/lib/backend_esysdb.c": token parent object handle is 0x40043d73                                                                                                              
INFO on line: "451" in file: "src/pkcs11.c": return "C_Login" value: 0                                                                                                                                         
INFO on line: "483" in file: "src/pkcs11.c": enter "C_FindObjectsInit"                                                                                                                                         
INFO on line: "483" in file: "src/pkcs11.c": return "C_FindObjectsInit" value: 0                                                                                                                               
INFO on line: "487" in file: "src/pkcs11.c": enter "C_FindObjects"                                                                                                                                             
INFO on line: "487" in file: "src/pkcs11.c": return "C_FindObjects" value: 0                                                                                                                                   
INFO on line: "487" in file: "src/pkcs11.c": enter "C_FindObjects"                                                                                                                                             
INFO on line: "487" in file: "src/pkcs11.c": return "C_FindObjects" value: 0                                                                                                                                   
INFO on line: "491" in file: "src/pkcs11.c": enter "C_FindObjectsFinal"                                                                                                                                        
INFO on line: "491" in file: "src/pkcs11.c": return "C_FindObjectsFinal" value: 0                                                                                                                              
INFO on line: "475" in file: "src/pkcs11.c": enter "C_GetAttributeValue"                                                                                                                                       
INFO on line: "475" in file: "src/pkcs11.c": return "C_GetAttributeValue" value: 0                                                                                                                             
INFO on line: "475" in file: "src/pkcs11.c": enter "C_GetAttributeValue"
INFO on line: "475" in file: "src/pkcs11.c": return "C_GetAttributeValue" value: 0                                                                                                                      
INFO on line: "547" in file: "src/pkcs11.c": enter "C_SignInit"
INFO on line: "106" in file: "src/lib/sign.c": mechanism: 0x1
        has_params: no
        len: 0
INFO on line: "547" in file: "src/pkcs11.c": return "C_SignInit" value: 0
INFO on line: "551" in file: "src/pkcs11.c": enter "C_Sign"
INFO on line: "134" in file: "src/lib/encrypt.c": mechanism->mechanism: 3
mechanism->ulParameterLen: 0
mechanism->pParameter: (null)
INFO on line: "1699" in file: "src/lib/tpm.c": Performing TPM RSA Decrypt
INFO on line: "551" in file: "src/pkcs11.c": return "C_Sign" value: 0
Thu Aug  6 08:00:42 2020 Control Channel: TLSv1.1, cipher TLSv1.0 ECDHE-RSA-AES256-SHA, 2048 bit RSA
Thu Aug  6 08:00:42 2020 [server] Peer Connection Initiated with [AF_INET]127.0.0.1:1194
Thu Aug  6 08:00:43 2020 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Thu Aug  6 08:00:43 2020 PUSH: Received control message: 'PUSH_REPLY,route 10.8.0.1,topology net30,ping 10,ping-restart 120,ifconfig 10.8.0.6 10.8.0.5,peer-id 0,cipher AES-256-GCM'
Thu Aug  6 08:00:43 2020 OPTIONS IMPORT: timers and/or timeouts modified
Thu Aug  6 08:00:43 2020 OPTIONS IMPORT: --ifconfig/up options modified
Thu Aug  6 08:00:43 2020 OPTIONS IMPORT: route options modified
Thu Aug  6 08:00:43 2020 OPTIONS IMPORT: peer-id set
Thu Aug  6 08:00:43 2020 OPTIONS IMPORT: adjusting link_mtu to 1624
Thu Aug  6 08:00:43 2020 OPTIONS IMPORT: data channel crypto options modified
Thu Aug  6 08:00:43 2020 Data Channel: using negotiated cipher 'AES-256-GCM'
Thu Aug  6 08:00:43 2020 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Thu Aug  6 08:00:43 2020 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Thu Aug  6 08:00:43 2020 ROUTE_GATEWAY 192.168.145.113/255.255.255.240 IFACE=eth0 HWADDR=00:15:5d:e5:22:3f
Thu Aug  6 08:00:43 2020 TUN/TAP device tun1 opened 
Thu Aug  6 08:00:43 2020 TUN/TAP TX queue length set to 100
Thu Aug  6 08:00:43 2020 /sbin/ip link set dev tun1 up mtu 1500
INFO on line: "375" in file: "src/pkcs11.c": enter "C_Initialize"
INFO on line: "375" in file: "src/pkcs11.c": return "C_Initialize" value: 401
INFO on line: "379" in file: "src/pkcs11.c": enter "C_Finalize"
INFO on line: "76" in file: "src/lib/backend.c": Destroying backends
INFO on line: "77" in file: "src/lib/backend_fapi.c": Calling Fapi_Finalize
INFO on line: "379" in file: "src/pkcs11.c": return "C_Finalize" value: 0
Thu Aug  6 08:00:43 2020 /sbin/ip addr add dev tun1 local 10.8.0.6 peer 10.8.0.5
INFO on line: "375" in file: "src/pkcs11.c": enter "C_Initialize"
INFO on line: "375" in file: "src/pkcs11.c": return "C_Initialize" value: 401
INFO on line: "379" in file: "src/pkcs11.c": enter "C_Finalize"
williamcroberts commented 4 years ago 
INFO on line: "1699" in file: "src/lib/tpm.c": Performing TPM RSA Decrypt

What mechanism is it asking for when negotiating tls 1.2?

dnoliver commented 4 years ago

With TLS 1.2 padding=3

Fri Aug  7 13:19:35 2020 us=784580 PKCS#11: __pkcs11h_openssl_rsa_enc entered - flen=256, from=0x55cb61a06d50, to=0x55cb61a010d0, rsa=0x55cb619d
e740, padding=3                                                                                                                                 
Fri Aug  7 13:19:35 2020 us=784592 PKCS#11: __pkcs11h_openssl_rsa_enc - return rv=112-'CKR_MECHANISM_INVALID'                                   
Fri Aug  7 13:19:35 2020 us=784605 SSL alert (write): fatal: internal error                                                                     
Fri Aug  7 13:19:35 2020 us=784637 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib                                       
Fri Aug  7 13:19:35 2020 us=784649 TLS_ERROR: BIO read tls_read_plaintext error                                                                 
Fri Aug  7 13:19:35 2020 us=784658 TLS Error: TLS object -> incoming plaintext read error                                                       
Fri Aug  7 13:19:35 2020 us=784682 TLS Error: TLS handshake failed                                                                              
Fri Aug  7 13:19:35 2020 us=784691 PID packet_id_free

with TLS 1.1 padding=1

Fri Aug  7 13:21:04 2020 us=283024 PKCS#11: __pkcs11h_openssl_rsa_enc entered - flen=36, from=0x7ffedc45b4c0, to=0x56544b84d2a0, rsa=0x56544b82b
130, padding=1                                                                                                                                  
Fri Aug  7 13:21:04 2020 us=283028 PKCS#11: Performing signature                                                                                
Fri Aug  7 13:21:04 2020 us=283033 PKCS#11: pkcs11h_certificate_signAny entry certificate=0x56544b823390, mech_type=1, source=0x7ffedc45b4c0, so
urce_size=0000000000000024, target=0x56544b84d2a0, *p_target_size=0000000000000100                                                              
Fri Aug  7 13:21:04 2020 us=283037 PKCS#11: Getting key attributes                                                                              
Fri Aug  7 13:21:04 2020 us=283041 PKCS#11: __pkcs11h_certificate_getKeyAttributes entry certificate=0x56544b823390                             
Fri Aug  7 13:21:04 2020 us=283045 PKCS#11: _pkcs11h_session_freeObjectAttributes entry attrs=0x7ffedc45b280, count=4                           
Fri Aug  7 13:21:04 2020 us=283048 PKCS#11: _pkcs11h_session_freeObjectAttributes return                                                        
Fri Aug  7 13:21:04 2020 us=283052 PKCS#11: Get private key attributes failed: 130:'CKR_OBJECT_HANDLE_INVALID'                                  
Fri Aug  7 13:21:04 2020 us=283058 PKCS#11: _pkcs11h_certificate_resetSession entry certificate=0x56544b823390, public_only=0, session_mutex_loc
ked=1                                                                                                                                           
Fri Aug  7 13:21:04 2020 us=283063 PKCS#11: _pkcs11h_session_getObjectById entry session=0x56544b826250, class=3, id=0x56544b8275a0, id_size=000
0000000000010, p_handle=0x56544b8233a8                                                                                                          
Fri Aug  7 13:21:04 2020 us=283097 PKCS#11: _pkcs11h_session_validate entry session=0x56544b826250                                              
Fri Aug  7 13:21:04 2020 us=283105 PKCS#11: _pkcs11h_session_validate session->pin_expire_time=0, time=1596831664                               
Fri Aug  7 13:21:04 2020 us=283110 PKCS#11: _pkcs11h_session_validate return rv=0-'CKR_OK'
williamcroberts commented 4 years ago

With TLS 1.2 padding=3

Fri Aug  7 13:19:35 2020 us=784580 PKCS#11: __pkcs11h_openssl_rsa_enc entered - flen=256, from=0x55cb61a06d50, to=0x55cb61a010d0, rsa=0x55cb619d
e740, padding=3                                                                                                                                 
Fri Aug  7 13:19:35 2020 us=784592 PKCS#11: __pkcs11h_openssl_rsa_enc - return rv=112-'CKR_MECHANISM_INVALID'                                   
Fri Aug  7 13:19:35 2020 us=784605 SSL alert (write): fatal: internal error                                                                     
Fri Aug  7 13:19:35 2020 us=784637 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib                                       
Fri Aug  7 13:19:35 2020 us=784649 TLS_ERROR: BIO read tls_read_plaintext error                                                                 
Fri Aug  7 13:19:35 2020 us=784658 TLS Error: TLS object -> incoming plaintext read error                                                       
Fri Aug  7 13:19:35 2020 us=784682 TLS Error: TLS handshake failed                                                                              
Fri Aug  7 13:19:35 2020 us=784691 PID packet_id_free

with TLS 1.1 padding=1

Fri Aug  7 13:21:04 2020 us=283024 PKCS#11: __pkcs11h_openssl_rsa_enc entered - flen=36, from=0x7ffedc45b4c0, to=0x56544b84d2a0, rsa=0x56544b82b
130, padding=1                                                                                                                                  
Fri Aug  7 13:21:04 2020 us=283028 PKCS#11: Performing signature                                                                                
Fri Aug  7 13:21:04 2020 us=283033 PKCS#11: pkcs11h_certificate_signAny entry certificate=0x56544b823390, mech_type=1, source=0x7ffedc45b4c0, so
urce_size=0000000000000024, target=0x56544b84d2a0, *p_target_size=0000000000000100                                                              
Fri Aug  7 13:21:04 2020 us=283037 PKCS#11: Getting key attributes                                                                              
Fri Aug  7 13:21:04 2020 us=283041 PKCS#11: __pkcs11h_certificate_getKeyAttributes entry certificate=0x56544b823390                             
Fri Aug  7 13:21:04 2020 us=283045 PKCS#11: _pkcs11h_session_freeObjectAttributes entry attrs=0x7ffedc45b280, count=4                           
Fri Aug  7 13:21:04 2020 us=283048 PKCS#11: _pkcs11h_session_freeObjectAttributes return                                                        
Fri Aug  7 13:21:04 2020 us=283052 PKCS#11: Get private key attributes failed: 130:'CKR_OBJECT_HANDLE_INVALID'                                  
Fri Aug  7 13:21:04 2020 us=283058 PKCS#11: _pkcs11h_certificate_resetSession entry certificate=0x56544b823390, public_only=0, session_mutex_loc
ked=1                                                                                                                                           
Fri Aug  7 13:21:04 2020 us=283063 PKCS#11: _pkcs11h_session_getObjectById entry session=0x56544b826250, class=3, id=0x56544b8275a0, id_size=000
0000000000010, p_handle=0x56544b8233a8                                                                                                          
Fri Aug  7 13:21:04 2020 us=283097 PKCS#11: _pkcs11h_session_validate entry session=0x56544b826250                                              
Fri Aug  7 13:21:04 2020 us=283105 PKCS#11: _pkcs11h_session_validate session->pin_expire_time=0, time=1596831664                               
Fri Aug  7 13:21:04 2020 us=283110 PKCS#11: _pkcs11h_session_validate return rv=0-'CKR_OK'

Is this that PSS padding bug again?

williamcroberts commented 4 years ago 
dnf install openvn

@dnoliver what OS were you using so I can replicate the setup.

dnoliver commented 4 years ago 
[root@openvpn openvpn-client]# uname -a
Linux openvpn.mshome.net 5.7.11-200.fc32.x86_64 #1 SMP Wed Jul 29 17:15:52 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

[root@openvpn openvpn-client]# cat /etc/redhat-release 
Fedora release 32 (Thirty Two)

[root@openvpn openvpn]# rpm -qa tpm2-pkcs11 tpm2-pkcs11-tools gnutls-utils openvpn
tpm2-pkcs11-tools-1.3.0-1.fc32.x86_64
openvpn-2.4.9-1.fc32.x86_64
gnutls-utils-3.6.14-2.fc32.x86_64
williamcroberts commented 4 years ago

@dnoliver I have reproduced the error:

Thu Aug 20 14:19:03 2020 us=882458 UDP READ [251] from [AF_INET]10.0.2.15:1194: P_CONTROL_V1 kid=0 pid=[ #5 ] [ ] pid=4 DATA len=209
Thu Aug 20 14:19:03 2020 us=882735 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
Thu Aug 20 14:19:03 2020 us=882756 TLS_ERROR: BIO read tls_read_plaintext error
Thu Aug 20 14:19:03 2020 us=882768 TLS Error: TLS object -> incoming plaintext read error
Thu Aug 20 14:19:03 2020 us=882779 TLS Error: TLS handshake failed
Thu Aug 20 14:19:03 2020 us=882849 TCP/UDP: Closing socket

Tomorrow ill get a better debug env setup, so I can see exactly why its failing.

williamcroberts commented 4 years ago

@dnoliver this was fun, looks like a bug in something not tpm2-pkcs11. Its checking that the mechanism is RSA_PKCS1_PADDING and dying if it's not. Which is why we don't see logs that it's entering tpm2-pkcs11.

https://github.com/OpenSC/pkcs11-helper/blob/a6e54e9bdd57dd4e98a2fbf984fe7fe4a9d60171/lib/pkcs11h-openssl.c#L481-L484

The call stack is:

__pkcs11h_openssl_rsa_enc() at pkcs11h-openssl.c:467 0x7ffff7fba115 
pkey_rsa_sign() at 0x7ffff7de90b3   
EVP_DigestSignFinal() at 0x7ffff7d983ce 
tls_construct_cert_verify() at 0x7ffff7be246a   
state_machine.part() at 0x7ffff7bd8fbd  
ssl3_read_bytes() at 0x7ffff7bafca6 
ssl3_read_internal() at 0x7ffff7bb7035  
ssl_read() at 0x7ffff7ba9050    
bio_read_intern() at 0x7ffff7ccca34 
BIO_read() at 0x7ffff7ccd007

So I don't know if: OpenSSL should be calling it differently or if this is a bug in pkcs11-helper... investigating.

FYI I built pkcs11-helper from source co on tag 1.22 but you'll also need the Fedora patch, or just build thier version of it, as it's distro patched:

Unpack RPM

rpm2cpio pkcs11-helper-1.22-9.fc32.src.rpm | cpio -idmv
williamcroberts commented 4 years ago

Hrm 1.26 of pkcs11-helper has this patch: https://github.com/OpenSC/pkcs11-helper/commit/c192bb48e9170d636e305d03a87c82580101a1a9

Let me try just checking out 1.26 of pkcs11-helper and giving that a go

williamcroberts commented 4 years ago

@dnoliver works, just rebuild your pkcs11-helper from the fedora package and cherry-pick OpenSC/pkcs11-helper@c192bb4.

For some reason fedora didn't upstream their patches, so we may want to do that, because 1.26 tag doesn't work. I need to debug why and see if it's something I need to change in the library.

williamcroberts commented 4 years ago

@dnoliver Look like @dmw2 has been battling to get his patchset in at https://github.com/OpenSC/pkcs11-helper/pull/4. @dwmw2, anything we can do?

williamcroberts commented 4 years ago

So we have an example, the question now is do we want to make a test for this? With all the moving parts, and distro specific things, having an automated test I think would be fragile. However, if we ever with to revisit this in the future, I think we can, and Dan made quite a nice script to start us with:

dwmw2 commented 4 years ago

@dnoliver Look like @dmw2 has been battling to get his patchset in at OpenSC/pkcs11-helper#4. @dwmw2, anything we can do?

Stop using pkcs11-helper and use libp11 (or the engine) instead.

dnoliver commented 4 years ago

@dwmw2 that will have to be OpenVPN's decision right?

dwmw2 commented 4 years ago

@dwmw2 that will have to be OpenVPN's decision right?

Indeed.