Page 1 of 1

SmartCard TLS_ERROR: BIO read tls_read_plaintext error

Posted: Mon Aug 31, 2020 4:12 pm
by jank04
Hello,

I had a openvpn server installed on raspbian deb 9 and everything worked fine. I upgraded to raspbian deb 10 and made a clean, probably newer version, openvpn install.
I imported the CA-Chain, CRL and Key in the serverconfiguration, as it was in the previous install.

Clients, which do not have a certificate/key saved on the smartcard can connect fine.

However when I try to connect with my smartcard, the connection fails.
(The Serialized id from the new windows version did not work, but that was also the case before. I have to use an older version to get the correct id)

Code: Select all

.\openvpn.exe --show-pkcs11-ids "C:\Windows\System32\cvP11.dll"
gives

Code: Select all

pkcs11:model=JavaCardOS;token=Jan%20Kleefeld;manufacturer=cv%20cryptovision%20gmbh%20%28c%29%20v1.0j;serial=3036393837343232;id=C%14%a7_d%ba%fc%28
But as mentioned this is another topic.

This is the client output verbose level: 3

Code: Select all

Mon Aug 31 17:37:06 2020 OpenVPN 2.4.9 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Apr 16 2020
Mon Aug 31 17:37:06 2020 Windows version 6.2 (Windows 8 or greater) 64bit
Mon Aug 31 17:37:06 2020 library versions: OpenSSL 1.1.1f  31 Mar 2020, LZO 2.10
Enter Management Password:
Mon Aug 31 17:37:06 2020 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25341
Mon Aug 31 17:37:06 2020 Need hold release from management interface, waiting...
Mon Aug 31 17:37:06 2020 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25341
Mon Aug 31 17:37:06 2020 MANAGEMENT: CMD 'state on'
Mon Aug 31 17:37:06 2020 MANAGEMENT: CMD 'log all on'
Mon Aug 31 17:37:06 2020 MANAGEMENT: CMD 'echo all on'
Mon Aug 31 17:37:06 2020 MANAGEMENT: CMD 'bytecount 5'
Mon Aug 31 17:37:06 2020 MANAGEMENT: CMD 'hold off'
Mon Aug 31 17:37:06 2020 MANAGEMENT: CMD 'hold release'
Mon Aug 31 17:37:06 2020 PKCS#11: Adding PKCS#11 provider 'C:\Windows\System32\cvP11.dll'
Mon Aug 31 17:37:07 2020 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Mon Aug 31 17:37:07 2020 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Mon Aug 31 17:37:07 2020 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Mon Aug 31 17:37:07 2020 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Mon Aug 31 17:37:07 2020 MANAGEMENT: >STATE:1598888227,RESOLVE,,,,,,
Mon Aug 31 17:37:07 2020 TCP/UDP: Preserving recently used remote address: [AF_INET]192.168.2.150:1194
Mon Aug 31 17:37:07 2020 Socket Buffers: R=[65536->65536] S=[64512->64512]
Mon Aug 31 17:37:07 2020 UDP link local: (not bound)
Mon Aug 31 17:37:07 2020 UDP link remote: [AF_INET]192.168.2.150:1194
Mon Aug 31 17:37:07 2020 MANAGEMENT: >STATE:1598888227,WAIT,,,,,,
Mon Aug 31 17:37:07 2020 MANAGEMENT: >STATE:1598888227,AUTH,,,,,,
Mon Aug 31 17:37:07 2020 TLS: Initial packet from [AF_INET]192.168.2.150:1194, sid=49310fc1 41d899c8
Mon Aug 31 17:37:07 2020 VERIFY OK: depth=2, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=Certificate Authority, CN=ROOT CA jan-home.de, emailAddress=support@jan-home.de
Mon Aug 31 17:37:07 2020 VERIFY OK: depth=1, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=Certificate Authority, CN=Intermediate CA VPN jan-home.de, emailAddress=support@jan-home.de
Mon Aug 31 17:37:07 2020 VERIFY KU OK
Mon Aug 31 17:37:07 2020 Validating certificate extended key usage
Mon Aug 31 17:37:07 2020 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Mon Aug 31 17:37:07 2020 VERIFY EKU OK
Mon Aug 31 17:37:07 2020 VERIFY X509NAME OK: C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=OpenVPN_Server, CN=OpenVPN_Server_2, emailAddress=support@jan-home.de
Mon Aug 31 17:37:07 2020 VERIFY OK: depth=0, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=OpenVPN_Server, CN=OpenVPN_Server_2, emailAddress=support@jan-home.de
Mon Aug 31 17:37:07 2020 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
Mon Aug 31 17:37:07 2020 TLS_ERROR: BIO read tls_read_plaintext error
Mon Aug 31 17:37:07 2020 TLS Error: TLS object -> incoming plaintext read error
Mon Aug 31 17:37:07 2020 TLS Error: TLS handshake failed
Mon Aug 31 17:37:07 2020 SIGUSR1[soft,tls-error] received, process restarting
Mon Aug 31 17:37:07 2020 MANAGEMENT: >STATE:1598888227,RECONNECTING,tls-error,,,,,
Mon Aug 31 17:37:07 2020 Restart pause, 5 second(s)
Mon Aug 31 17:37:09 2020 SIGTERM[hard,init_instance] received, process exiting
Mon Aug 31 17:37:09 2020 MANAGEMENT: >STATE:1598888229,EXITING,init_instance,,,,,
Even other verbose levels didn't helped me; same on the server-side.
Please tell me, which verbose levels, especially for the server, I can try out, so you can hopefully find the problem.

Versions:

Code: Select all

 openvpn --version
OpenVPN 2.4.7 arm-unknown-linux-gnueabihf [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Feb 20 2019
library versions: OpenSSL 1.1.1d  10 Sep 2019, LZO 2.10

Code: Select all

apt-cache show openvpn
Package: openvpn
Version: 2.4.7-1
Architecture: armhf
Client-Config: (Certs and TLS-Key are edited, so invalid right as the are here)

Code: Select all

client
proto udp
explicit-exit-notify
remote jan-home.de 1194
dev tun
resolv-retry infinite
nobind
persist-key
persist-tun
remote-cert-tls server
verify-x509-name OpenVPN_Server_2 name
auth SHA256
auth-nocache
cipher AES-128-GCM
tls-client
tls-version-min 1.2
tls-cipher TLS-ECDHE-ECDSA-WITH-AES-128-GCM-SHA256
ignore-unknown-option block-outside-dns
setenv opt block-outside-dns # Prevent Windows 10 DNS leak
verb 3
pkcs11-providers 'C:\Windows\System32\cvP11.dll'
pkcs11-id 'cv\x20cryptovision\x20gmbh\x20\x28c\x29\x20v1\x2E0j/JavaCardOS/3036393837343232/Jan\x20Kleefeld/4314A75F64BAFC28'
key-direction 1
<ca>
-----BEGIN CERTIFICATE-----
MIIGezCCBGOgAwIBAgIISOK6cZeZx3swDQYJKoZIhvcNAQENBQAwgaUxCzAJBgNV
BAYTAkRFMQwwCgYDVQQIEwNOUlcxEDAOBgNVBAcTB1ZlbGJlcnQxFDASBgNVBAoT
C2phbi1ob21lLmRlMR4wHAYDVQQLExVDZXJ0aWZpY2F0ZSBBdXRob3JpdHkxHDAa
BgNVBAMTE1JPT1QgQ0EgamFuLWhvbWUuZGUxIjAgBgkqhkiG9w0BCQEWE3N1cHBv
cnRAamFuLWhvbWUuZGUwHhcNMjAwNzIyMDAwMDAwWhcNMzIwNzIxMjM1OTU5WjCB
-----END CERTIFICATE-----
-----BEGIN CERTIFICATE-----
MIIGnzCCBIegAwIBAgIIUriT56sVMpIwDQYJKoZIhvcNAQENBQAwgaUxCzAJBgNV
BAYTAkRFMQwwCgYDVQQIEwNOUlcxEDAOBgNVBAcTB1ZlbGJlcnQxFDASBgNVBAoT
C2phbi1ob21lLmRlMR4wHAYDVQQLExVDZXJ0aWZpY2F0ZSBBdXRob3JpdHkxHDAa
BgNVBAMTE1JPT1QgQ0EgamFuLWhvbWUuZGUxIjAgBgkqhkiG9w0BCQEWE3N1cHBv
cnRAamFuLWhvbWUuZGUwHhcNMjAwNzIyMDAwMDAwWhcNMzAwNzIxMjM1OTU5WjCB
-----END CERTIFICATE-----
</ca>
<tls-crypt>
#
# 2048 bit OpenVPN static key
#
-----BEGIN OpenVPN Static key V1-----
193a629f3939fd340bc7d2375bcd346f
9dcbe859a96bd79a135d5f5bcf92eff0
3a541fd98252691f1f83b011e345b428
f2a8124ef010b65e068b186b16a24a3a
-----END OpenVPN Static key V1-----
</tls-crypt>
Server-Config:

Code: Select all

port 1194
proto udp
dev tun
user nobody
group nogroup
persist-key
persist-tun
keepalive 10 120
topology subnet
server 10.8.0.0 255.255.255.0
ifconfig-pool-persist ipp.txt
push "dhcp-option DNS 192.168.2.150"
push "redirect-gateway def1 bypass-dhcp"
dh none
ecdh-curve prime256v1
tls-crypt tls-crypt.key 0
crl-verify inter-crl.pem
ca ca-chain.crt
cert OpenVPN_Server_2.crt
key OpenVPN_Server_2.key
auth SHA256
cipher AES-128-GCM
ncp-ciphers AES-128-GCM
tls-server
tls-version-min 1.2
tls-cipher TLS-ECDHE-ECDSA-WITH-AES-128-GCM-SHA256
client-config-dir /etc/openvpn/ccd
status /var/log/openvpn/status.log
verb 11
I appreciate any help :)

Re: SmartCard TLS_ERROR: BIO read tls_read_plaintext error

Posted: Mon Aug 31, 2020 5:03 pm
by TinCanTech
jank04 wrote:
Mon Aug 31, 2020 4:12 pm
This is the client output verbose level: 3
jank04 wrote:
Mon Aug 31, 2020 4:12 pm
Mon Aug 31 17:37:07 2020 TLS: Initial packet from [AF_INET]192.168.2.150:1194, sid=49310fc1 41d899c8
Mon Aug 31 17:37:07 2020 VERIFY OK: depth=2, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=Certificate Authority, CN=ROOT CA jan-home.de, emailAddress=support@jan-home.de
Mon Aug 31 17:37:07 2020 VERIFY OK: depth=1, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=Certificate Authority, CN=Intermediate CA VPN jan-home.de, emailAddress=support@jan-home.de
Mon Aug 31 17:37:07 2020 VERIFY KU OK
Mon Aug 31 17:37:07 2020 Validating certificate extended key usage
Mon Aug 31 17:37:07 2020 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Mon Aug 31 17:37:07 2020 VERIFY EKU OK
Mon Aug 31 17:37:07 2020 VERIFY X509NAME OK: C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=OpenVPN_Server, CN=OpenVPN_Server_2, emailAddress=support@jan-home.de
Mon Aug 31 17:37:07 2020 VERIFY OK: depth=0, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=OpenVPN_Server, CN=OpenVPN_Server_2, emailAddress=support@jan-home.de
All good.
jank04 wrote:
Mon Aug 31, 2020 4:12 pm
Mon Aug 31 17:37:07 2020 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
OpenSSL does not like something ..
jank04 wrote:
Mon Aug 31, 2020 4:12 pm
Mon Aug 31 17:37:07 2020 TLS_ERROR: BIO read tls_read_plaintext error
Mon Aug 31 17:37:07 2020 TLS Error: TLS object -> incoming plaintext read error
Mon Aug 31 17:37:07 2020 TLS Error: TLS handshake failed
Expected errors.
jank04 wrote:
Mon Aug 31, 2020 4:12 pm
Mon Aug 31 17:37:07 2020 SIGUSR1[soft,tls-error] received, process restarting
Received a restart from the server.
jank04 wrote:
Mon Aug 31, 2020 4:12 pm
Please tell me, which verbose levels, especially for the server, I can try out, so you can hopefully find the problem.
Verb 4 -- and please include the full server log (Restart your server and make a connection attempt).

Re: SmartCard TLS_ERROR: BIO read tls_read_plaintext error

Posted: Mon Aug 31, 2020 5:39 pm
by jank04
tail -f /var/log/syslog | grep vpn (Verbose Level 4 Server-Log)

Code: Select all

Aug 31 19:30:47 raspberrypi ovpn-server[2753]: succeeded -> ifconfig_pool_set()
Aug 31 19:30:47 raspberrypi ovpn-server[2753]: ifconfig_pool_read(), in='Desktop-Jan,10.8.0.3', TODO: IPv6
Aug 31 19:30:47 raspberrypi ovpn-server[2753]: succeeded -> ifconfig_pool_set()
Aug 31 19:30:47 raspberrypi ovpn-server[2753]: ifconfig_pool_read(), in='Google Pixel 3a,10.8.0.4', TODO: IPv6
Aug 31 19:30:47 raspberrypi ovpn-server[2753]: succeeded -> ifconfig_pool_set()
Aug 31 19:30:47 raspberrypi ovpn-server[2753]: IFCONFIG POOL LIST
Aug 31 19:30:47 raspberrypi ovpn-server[2753]: Client_1,10.8.0.2
Aug 31 19:30:47 raspberrypi ovpn-server[2753]: Desktop-Jan,10.8.0.3
Aug 31 19:30:47 raspberrypi ovpn-server[2753]: Google Pixel 3a,10.8.0.4
Aug 31 19:30:47 raspberrypi ovpn-server[2753]: Initialization Sequence Completed
Aug 31 19:31:07 raspberrypi ovpn-server[2753]: MULTI: multi_create_instance called
Aug 31 19:31:07 raspberrypi ovpn-server[2753]: 192.168.2.152:56871 Re-using SSL/TLS context
Aug 31 19:31:07 raspberrypi ovpn-server[2753]: 192.168.2.152:56871 Control Channel MTU parms [ L:1621 D:1156 EF:94 EB:0 ET:0 EL:3 ]
Aug 31 19:31:07 raspberrypi ovpn-server[2753]: 192.168.2.152:56871 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Aug 31 19:31:07 raspberrypi ovpn-server[2753]: 192.168.2.152:56871 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-128-GCM,auth [null-digest],keysize 128,key-method 2,tls-server'
Aug 31 19:31:07 raspberrypi ovpn-server[2753]: 192.168.2.152:56871 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-128-GCM,auth [null-digest],keysize 128,key-method 2,tls-client'
Aug 31 19:31:07 raspberrypi ovpn-server[2753]: 192.168.2.152:56871 TLS: Initial packet from [AF_INET]192.168.2.152:56871, sid=fe598a13 faeeecaa
Aug 31 19:32:07 raspberrypi ovpn-server[2753]: 192.168.2.152:56871 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Aug 31 19:32:07 raspberrypi ovpn-server[2753]: 192.168.2.152:56871 TLS Error: TLS handshake failed
Aug 31 19:32:07 raspberrypi ovpn-server[2753]: 192.168.2.152:56871 SIGUSR1[soft,tls-error] received, client-instance restarting
Client-Log Verbose-Level: 4

Code: Select all

Mon Aug 31 19:33:36 2020 us=2032 Current Parameter Settings:
Mon Aug 31 19:33:36 2020 us=2032   config = 'Jan Kleefeld SmartCard SN 3036393837343232.ovpn'
Mon Aug 31 19:33:36 2020 us=2032   mode = 0
Mon Aug 31 19:33:36 2020 us=2032   show_ciphers = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   show_digests = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   show_engines = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   genkey = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   key_pass_file = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=2032   show_tls_ciphers = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   connect_retry_max = 0
Mon Aug 31 19:33:36 2020 us=2032 Connection profiles [0]:
Mon Aug 31 19:33:36 2020 us=2032   proto = udp
Mon Aug 31 19:33:36 2020 us=2032   local = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=2032   local_port = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=2032   remote = 'jan-home.de'
Mon Aug 31 19:33:36 2020 us=2032   remote_port = '1194'
Mon Aug 31 19:33:36 2020 us=2032   remote_float = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   bind_defined = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   bind_local = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   bind_ipv6_only = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   connect_retry_seconds = 5
Mon Aug 31 19:33:36 2020 us=2032   connect_timeout = 120
Mon Aug 31 19:33:36 2020 us=2032   socks_proxy_server = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=2032   socks_proxy_port = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=2032   tun_mtu = 1500
Mon Aug 31 19:33:36 2020 us=2032   tun_mtu_defined = ENABLED
Mon Aug 31 19:33:36 2020 us=2032   link_mtu = 1500
Mon Aug 31 19:33:36 2020 us=2032   link_mtu_defined = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   tun_mtu_extra = 0
Mon Aug 31 19:33:36 2020 us=2032   tun_mtu_extra_defined = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   mtu_discover_type = -1
Mon Aug 31 19:33:36 2020 us=2032   fragment = 0
Mon Aug 31 19:33:36 2020 us=2032   mssfix = 1450
Mon Aug 31 19:33:36 2020 us=2032   explicit_exit_notification = 1
Mon Aug 31 19:33:36 2020 us=2032 Connection profiles END
Mon Aug 31 19:33:36 2020 us=2032   remote_random = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   ipchange = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=2032   dev = 'tun'
Mon Aug 31 19:33:36 2020 us=2032   dev_type = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=2032   dev_node = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=2032   lladdr = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=2032   topology = 1
Mon Aug 31 19:33:36 2020 us=2032   ifconfig_local = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=2032   ifconfig_remote_netmask = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=2032   ifconfig_noexec = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   ifconfig_nowarn = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   ifconfig_ipv6_local = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=2032   ifconfig_ipv6_netbits = 0
Mon Aug 31 19:33:36 2020 us=2032   ifconfig_ipv6_remote = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=2032   shaper = 0
Mon Aug 31 19:33:36 2020 us=2032   mtu_test = 0
Mon Aug 31 19:33:36 2020 us=2032   mlock = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   keepalive_ping = 0
Mon Aug 31 19:33:36 2020 us=2032   keepalive_timeout = 0
Mon Aug 31 19:33:36 2020 us=2032   inactivity_timeout = 0
Mon Aug 31 19:33:36 2020 us=2032   ping_send_timeout = 0
Mon Aug 31 19:33:36 2020 us=2032   ping_rec_timeout = 0
Mon Aug 31 19:33:36 2020 us=2032   ping_rec_timeout_action = 0
Mon Aug 31 19:33:36 2020 us=2032   ping_timer_remote = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   remap_sigusr1 = 0
Mon Aug 31 19:33:36 2020 us=2032   persist_tun = ENABLED
Mon Aug 31 19:33:36 2020 us=2032   persist_local_ip = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   persist_remote_ip = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   persist_key = ENABLED
Mon Aug 31 19:33:36 2020 us=2032   passtos = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   resolve_retry_seconds = 1000000000
Mon Aug 31 19:33:36 2020 us=2032   resolve_in_advance = DISABLED
Mon Aug 31 19:33:36 2020 us=2032   username = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=2032   groupname = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   chroot_dir = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   cd_dir = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   writepid = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   up_script = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   down_script = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   down_pre = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   up_restart = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   up_delay = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   daemon = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   inetd = 0
Mon Aug 31 19:33:36 2020 us=3030   log = ENABLED
Mon Aug 31 19:33:36 2020 us=3030   suppress_timestamps = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   machine_readable_output = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   nice = 0
Mon Aug 31 19:33:36 2020 us=3030   verbosity = 4
Mon Aug 31 19:33:36 2020 us=3030   mute = 0
Mon Aug 31 19:33:36 2020 us=3030   gremlin = 0
Mon Aug 31 19:33:36 2020 us=3030   status_file = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   status_file_version = 1
Mon Aug 31 19:33:36 2020 us=3030   status_file_update_freq = 60
Mon Aug 31 19:33:36 2020 us=3030   occ = ENABLED
Mon Aug 31 19:33:36 2020 us=3030   rcvbuf = 0
Mon Aug 31 19:33:36 2020 us=3030   sndbuf = 0
Mon Aug 31 19:33:36 2020 us=3030   sockflags = 0
Mon Aug 31 19:33:36 2020 us=3030   fast_io = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   comp.alg = 0
Mon Aug 31 19:33:36 2020 us=3030   comp.flags = 0
Mon Aug 31 19:33:36 2020 us=3030   route_script = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   route_default_gateway = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   route_default_metric = 0
Mon Aug 31 19:33:36 2020 us=3030   route_noexec = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   route_delay = 5
Mon Aug 31 19:33:36 2020 us=3030   route_delay_window = 30
Mon Aug 31 19:33:36 2020 us=3030   route_delay_defined = ENABLED
Mon Aug 31 19:33:36 2020 us=3030   route_nopull = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   route_gateway_via_dhcp = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   allow_pull_fqdn = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   management_addr = '127.0.0.1'
Mon Aug 31 19:33:36 2020 us=3030   management_port = '25341'
Mon Aug 31 19:33:36 2020 us=3030   management_user_pass = 'stdin'
Mon Aug 31 19:33:36 2020 us=3030   management_log_history_cache = 250
Mon Aug 31 19:33:36 2020 us=3030   management_echo_buffer_size = 100
Mon Aug 31 19:33:36 2020 us=3030   management_write_peer_info_file = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   management_client_user = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   management_client_group = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   management_flags = 6
Mon Aug 31 19:33:36 2020 us=3030   shared_secret_file = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   key_direction = 1
Mon Aug 31 19:33:36 2020 us=3030   ciphername = 'AES-128-GCM'
Mon Aug 31 19:33:36 2020 us=3030   ncp_enabled = ENABLED
Mon Aug 31 19:33:36 2020 us=3030   ncp_ciphers = 'AES-256-GCM:AES-128-GCM'
Mon Aug 31 19:33:36 2020 us=3030   authname = 'SHA256'
Mon Aug 31 19:33:36 2020 us=3030   prng_hash = 'SHA1'
Mon Aug 31 19:33:36 2020 us=3030   prng_nonce_secret_len = 16
Mon Aug 31 19:33:36 2020 us=3030   keysize = 0
Mon Aug 31 19:33:36 2020 us=3030   engine = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   replay = ENABLED
Mon Aug 31 19:33:36 2020 us=3030   mute_replay_warnings = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   replay_window = 64
Mon Aug 31 19:33:36 2020 us=3030   replay_time = 15
Mon Aug 31 19:33:36 2020 us=3030   packet_id_file = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   use_iv = ENABLED
Mon Aug 31 19:33:36 2020 us=3030   test_crypto = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   tls_server = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   tls_client = ENABLED
Mon Aug 31 19:33:36 2020 us=3030   key_method = 2
Mon Aug 31 19:33:36 2020 us=3030   ca_file = '[[INLINE]]'
Mon Aug 31 19:33:36 2020 us=3030   ca_path = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   dh_file = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   cert_file = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   extra_certs_file = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   priv_key_file = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   pkcs12_file = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   cryptoapi_cert = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   cipher_list = 'TLS-ECDHE-ECDSA-WITH-AES-128-GCM-SHA256'
Mon Aug 31 19:33:36 2020 us=3030   cipher_list_tls13 = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   tls_cert_profile = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   tls_verify = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   tls_export_cert = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   verify_x509_type = 2
Mon Aug 31 19:33:36 2020 us=3030   verify_x509_name = 'OpenVPN_Server_2'
Mon Aug 31 19:33:36 2020 us=3030   crl_file = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   ns_cert_type = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 65535
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_ku[i] = 0
Mon Aug 31 19:33:36 2020 us=3030   remote_cert_eku = 'TLS Web Server Authentication'
Mon Aug 31 19:33:36 2020 us=3030   ssl_flags = 192
Mon Aug 31 19:33:36 2020 us=3030   tls_timeout = 2
Mon Aug 31 19:33:36 2020 us=3030   renegotiate_bytes = -1
Mon Aug 31 19:33:36 2020 us=3030   renegotiate_packets = 0
Mon Aug 31 19:33:36 2020 us=3030   renegotiate_seconds = 3600
Mon Aug 31 19:33:36 2020 us=3030   handshake_window = 60
Mon Aug 31 19:33:36 2020 us=3030   transition_window = 3600
Mon Aug 31 19:33:36 2020 us=3030   single_session = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   push_peer_info = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   tls_exit = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   tls_auth_file = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   tls_crypt_file = '[[INLINE]]'
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_providers = C:\Windows\System32\cvP11.dll
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_protected_authentication = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_private_mode = 00000000
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_cert_private = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_pin_cache_period = -1
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_id = 'cv\x20cryptovision\x20gmbh\x20\x28c\x29\x20v1\x2E0j/JavaCardOS/3036393837343232/Jan\x20Kleefeld/4314A75F64BAFC28'
Mon Aug 31 19:33:36 2020 us=3030   pkcs11_id_management = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   server_network = 0.0.0.0
Mon Aug 31 19:33:36 2020 us=3030   server_netmask = 0.0.0.0
Mon Aug 31 19:33:36 2020 us=3030   server_network_ipv6 = ::
Mon Aug 31 19:33:36 2020 us=3030   server_netbits_ipv6 = 0
Mon Aug 31 19:33:36 2020 us=3030   server_bridge_ip = 0.0.0.0
Mon Aug 31 19:33:36 2020 us=3030   server_bridge_netmask = 0.0.0.0
Mon Aug 31 19:33:36 2020 us=3030   server_bridge_pool_start = 0.0.0.0
Mon Aug 31 19:33:36 2020 us=3030   server_bridge_pool_end = 0.0.0.0
Mon Aug 31 19:33:36 2020 us=3030   ifconfig_pool_defined = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   ifconfig_pool_start = 0.0.0.0
Mon Aug 31 19:33:36 2020 us=3030   ifconfig_pool_end = 0.0.0.0
Mon Aug 31 19:33:36 2020 us=3030   ifconfig_pool_netmask = 0.0.0.0
Mon Aug 31 19:33:36 2020 us=3030   ifconfig_pool_persist_filename = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   ifconfig_pool_persist_refresh_freq = 600
Mon Aug 31 19:33:36 2020 us=3030   ifconfig_ipv6_pool_defined = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   ifconfig_ipv6_pool_base = ::
Mon Aug 31 19:33:36 2020 us=3030   ifconfig_ipv6_pool_netbits = 0
Mon Aug 31 19:33:36 2020 us=3030   n_bcast_buf = 256
Mon Aug 31 19:33:36 2020 us=3030   tcp_queue_limit = 64
Mon Aug 31 19:33:36 2020 us=3030   real_hash_size = 256
Mon Aug 31 19:33:36 2020 us=3030   virtual_hash_size = 256
Mon Aug 31 19:33:36 2020 us=3030   client_connect_script = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   learn_address_script = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   client_disconnect_script = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   client_config_dir = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   ccd_exclusive = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   tmp_dir = 'C:\Users\JANKLE~1\AppData\Local\Temp\'
Mon Aug 31 19:33:36 2020 us=3030   push_ifconfig_defined = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   push_ifconfig_local = 0.0.0.0
Mon Aug 31 19:33:36 2020 us=3030   push_ifconfig_remote_netmask = 0.0.0.0
Mon Aug 31 19:33:36 2020 us=3030   push_ifconfig_ipv6_defined = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   push_ifconfig_ipv6_local = ::/0
Mon Aug 31 19:33:36 2020 us=3030   push_ifconfig_ipv6_remote = ::
Mon Aug 31 19:33:36 2020 us=3030   enable_c2c = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   duplicate_cn = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   cf_max = 0
Mon Aug 31 19:33:36 2020 us=3030   cf_per = 0
Mon Aug 31 19:33:36 2020 us=3030   max_clients = 1024
Mon Aug 31 19:33:36 2020 us=3030   max_routes_per_client = 256
Mon Aug 31 19:33:36 2020 us=3030   auth_user_pass_verify_script = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   auth_user_pass_verify_script_via_file = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   auth_token_generate = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   auth_token_lifetime = 0
Mon Aug 31 19:33:36 2020 us=3030   client = ENABLED
Mon Aug 31 19:33:36 2020 us=3030   pull = ENABLED
Mon Aug 31 19:33:36 2020 us=3030   auth_user_pass_file = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   show_net_up = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   route_method = 0
Mon Aug 31 19:33:36 2020 us=3030   block_outside_dns = ENABLED
Mon Aug 31 19:33:36 2020 us=3030   ip_win32_defined = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   ip_win32_type = 3
Mon Aug 31 19:33:36 2020 us=3030   dhcp_masq_offset = 0
Mon Aug 31 19:33:36 2020 us=3030   dhcp_lease_time = 31536000
Mon Aug 31 19:33:36 2020 us=3030   tap_sleep = 0
Mon Aug 31 19:33:36 2020 us=3030   dhcp_options = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   dhcp_renew = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   dhcp_pre_release = DISABLED
Mon Aug 31 19:33:36 2020 us=3030   domain = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   netbios_scope = '[UNDEF]'
Mon Aug 31 19:33:36 2020 us=3030   netbios_node_type = 0
Mon Aug 31 19:33:36 2020 us=3030   disable_nbt = DISABLED
Mon Aug 31 19:33:36 2020 us=3030 OpenVPN 2.4.9 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Apr 16 2020
Mon Aug 31 19:33:36 2020 us=3030 Windows version 6.2 (Windows 8 or greater) 64bit
Mon Aug 31 19:33:36 2020 us=3030 library versions: OpenSSL 1.1.1f  31 Mar 2020, LZO 2.10
Enter Management Password:
Mon Aug 31 19:33:36 2020 us=4027 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25341
Mon Aug 31 19:33:36 2020 us=4027 Need hold release from management interface, waiting...
Mon Aug 31 19:33:36 2020 us=496789 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25341
Mon Aug 31 19:33:36 2020 us=605915 MANAGEMENT: CMD 'state on'
Mon Aug 31 19:33:36 2020 us=605915 MANAGEMENT: CMD 'log all on'
Mon Aug 31 19:33:36 2020 us=719403 MANAGEMENT: CMD 'echo all on'
Mon Aug 31 19:33:36 2020 us=720439 MANAGEMENT: CMD 'bytecount 5'
Mon Aug 31 19:33:36 2020 us=721438 MANAGEMENT: CMD 'hold off'
Mon Aug 31 19:33:36 2020 us=722436 MANAGEMENT: CMD 'hold release'
Mon Aug 31 19:33:36 2020 us=722436 PKCS#11: Adding PKCS#11 provider 'C:\Windows\System32\cvP11.dll'
Mon Aug 31 19:33:37 2020 us=605147 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Mon Aug 31 19:33:37 2020 us=605147 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Mon Aug 31 19:33:37 2020 us=605147 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Mon Aug 31 19:33:37 2020 us=605147 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Mon Aug 31 19:33:37 2020 us=605147 Control Channel MTU parms [ L:1621 D:1156 EF:94 EB:0 ET:0 EL:3 ]
Mon Aug 31 19:33:37 2020 us=605147 MANAGEMENT: >STATE:1598895217,RESOLVE,,,,,,
Mon Aug 31 19:33:37 2020 us=607248 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Mon Aug 31 19:33:37 2020 us=607248 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,keydir 1,cipher AES-128-GCM,auth [null-digest],keysize 128,key-method 2,tls-client'
Mon Aug 31 19:33:37 2020 us=607248 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,keydir 0,cipher AES-128-GCM,auth [null-digest],keysize 128,key-method 2,tls-server'
Mon Aug 31 19:33:37 2020 us=607248 TCP/UDP: Preserving recently used remote address: [AF_INET]192.168.2.150:1194
Mon Aug 31 19:33:37 2020 us=607248 Socket Buffers: R=[65536->65536] S=[64512->64512]
Mon Aug 31 19:33:37 2020 us=607248 UDP link local: (not bound)
Mon Aug 31 19:33:37 2020 us=607248 UDP link remote: [AF_INET]192.168.2.150:1194
Mon Aug 31 19:33:37 2020 us=607248 MANAGEMENT: >STATE:1598895217,WAIT,,,,,,
Mon Aug 31 19:33:37 2020 us=611240 MANAGEMENT: >STATE:1598895217,AUTH,,,,,,
Mon Aug 31 19:33:37 2020 us=611240 TLS: Initial packet from [AF_INET]192.168.2.150:1194, sid=431d64a7 b1abbe23
Mon Aug 31 19:33:37 2020 us=735452 VERIFY OK: depth=2, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=Certificate Authority, CN=ROOT CA jan-home.de, emailAddress=support@jan-home.de
Mon Aug 31 19:33:37 2020 us=735452 VERIFY OK: depth=1, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=Certificate Authority, CN=Intermediate CA VPN jan-home.de, emailAddress=support@jan-home.de
Mon Aug 31 19:33:37 2020 us=735452 VERIFY KU OK
Mon Aug 31 19:33:37 2020 us=735452 Validating certificate extended key usage
Mon Aug 31 19:33:37 2020 us=735452 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Mon Aug 31 19:33:37 2020 us=735452 VERIFY EKU OK
Mon Aug 31 19:33:37 2020 us=735452 VERIFY X509NAME OK: C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=OpenVPN_Server, CN=OpenVPN_Server_2, emailAddress=support@jan-home.de
Mon Aug 31 19:33:37 2020 us=735452 VERIFY OK: depth=0, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=OpenVPN_Server, CN=OpenVPN_Server_2, emailAddress=support@jan-home.de
Mon Aug 31 19:33:37 2020 us=736451 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
Mon Aug 31 19:33:37 2020 us=736451 TLS_ERROR: BIO read tls_read_plaintext error
Mon Aug 31 19:33:37 2020 us=736451 TLS Error: TLS object -> incoming plaintext read error
Mon Aug 31 19:33:37 2020 us=736451 TLS Error: TLS handshake failed
Mon Aug 31 19:33:37 2020 us=736451 TCP/UDP: Closing socket
Mon Aug 31 19:33:37 2020 us=736451 SIGUSR1[soft,tls-error] received, process restarting
Mon Aug 31 19:33:37 2020 us=736451 MANAGEMENT: >STATE:1598895217,RECONNECTING,tls-error,,,,,
Mon Aug 31 19:33:37 2020 us=736451 Restart pause, 5 second(s)
Mon Aug 31 19:33:39 2020 us=749409 SIGTERM[hard,init_instance] received, process exiting
Mon Aug 31 19:33:39 2020 us=749409 MANAGEMENT: >STATE:1598895219,EXITING,init_instance,,,,,
and please include the full server log
This is only vpn related what I posted. But even without | grep vpn, there is nothing more. Something from cron from user www-data. Nothing from openssl or so. Maybe in other logs? I'll search

Re: SmartCard TLS_ERROR: BIO read tls_read_plaintext error

Posted: Mon Aug 31, 2020 8:28 pm
by TinCanTech
jank04 wrote:
Mon Aug 31, 2020 5:39 pm
Mon Aug 31 19:33:37 2020 us=735452 VERIFY OK: depth=2, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=Certificate Authority, CN=ROOT CA jan-home.de, emailAddress=support@jan-home.de
Mon Aug 31 19:33:37 2020 us=735452 VERIFY OK: depth=1, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=Certificate Authority, CN=Intermediate CA VPN jan-home.de, emailAddress=support@jan-home.de
Mon Aug 31 19:33:37 2020 us=735452 VERIFY KU OK
Mon Aug 31 19:33:37 2020 us=735452 Validating certificate extended key usage
Mon Aug 31 19:33:37 2020 us=735452 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Mon Aug 31 19:33:37 2020 us=735452 VERIFY EKU OK
Mon Aug 31 19:33:37 2020 us=735452 VERIFY X509NAME OK: C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=OpenVPN_Server, CN=OpenVPN_Server_2, emailAddress=support@jan-home.de
Mon Aug 31 19:33:37 2020 us=735452 VERIFY OK: depth=0, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=OpenVPN_Server, CN=OpenVPN_Server_2, emailAddress=support@jan-home.de
Mon Aug 31 19:33:37 2020 us=736451 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
This looks similar to:
https://community.openvpn.net/openvpn/ticket/1216

Can you try OpenVPN for Windows version 2.5 Beta2 from here:
https://openvpn.net/community-downloads/

Re: SmartCard TLS_ERROR: BIO read tls_read_plaintext error

Posted: Mon Aug 31, 2020 8:58 pm
by jank04
I only found 2.5-beta1. There is the same error:

Code: Select all

2020-08-31 22:52:03 us=91584 Current Parameter Settings:
2020-08-31 22:52:03 us=91584   config = 'Jan Kleefeld SmartCard SN 3036393837343232.ovpn'
2020-08-31 22:52:03 us=91584   mode = 0
2020-08-31 22:52:03 us=91584   show_ciphers = DISABLED
2020-08-31 22:52:03 us=91584   show_digests = DISABLED
2020-08-31 22:52:03 us=91584   show_engines = DISABLED
2020-08-31 22:52:03 us=91584   genkey = DISABLED
2020-08-31 22:52:03 us=91584   genkey_filename = '[UNDEF]'
2020-08-31 22:52:03 us=91584   key_pass_file = '[UNDEF]'
2020-08-31 22:52:03 us=91584   show_tls_ciphers = DISABLED
2020-08-31 22:52:03 us=91584   connect_retry_max = 0
2020-08-31 22:52:03 us=91584 Connection profiles [0]:
2020-08-31 22:52:03 us=91584   proto = udp
2020-08-31 22:52:03 us=91584   local = '[UNDEF]'
2020-08-31 22:52:03 us=91584   local_port = '[UNDEF]'
2020-08-31 22:52:03 us=91584   remote = 'jan-home.de'
2020-08-31 22:52:03 us=91584   remote_port = '1194'
2020-08-31 22:52:03 us=91584   remote_float = DISABLED
2020-08-31 22:52:03 us=91584   bind_defined = DISABLED
2020-08-31 22:52:03 us=91584   bind_local = DISABLED
2020-08-31 22:52:03 us=91584   bind_ipv6_only = DISABLED
2020-08-31 22:52:03 us=92582   connect_retry_seconds = 5
2020-08-31 22:52:03 us=92582   connect_timeout = 120
2020-08-31 22:52:03 us=92582   socks_proxy_server = '[UNDEF]'
2020-08-31 22:52:03 us=92582   socks_proxy_port = '[UNDEF]'
2020-08-31 22:52:03 us=92582   tun_mtu = 1500
2020-08-31 22:52:03 us=92582   tun_mtu_defined = ENABLED
2020-08-31 22:52:03 us=92582   link_mtu = 1500
2020-08-31 22:52:03 us=92582   link_mtu_defined = DISABLED
2020-08-31 22:52:03 us=92582   tun_mtu_extra = 0
2020-08-31 22:52:03 us=92582   tun_mtu_extra_defined = DISABLED
2020-08-31 22:52:03 us=92582   mtu_discover_type = -1
2020-08-31 22:52:03 us=92582   fragment = 0
2020-08-31 22:52:03 us=92582   mssfix = 1450
2020-08-31 22:52:03 us=92582   explicit_exit_notification = 1
2020-08-31 22:52:03 us=92582   tls_auth_file = '[UNDEF]'
2020-08-31 22:52:03 us=92582   key_direction = 1
2020-08-31 22:52:03 us=92582   tls_crypt_file = '[INLINE]'
2020-08-31 22:52:03 us=92582   tls_crypt_v2_file = '[UNDEF]'
2020-08-31 22:52:03 us=92582 Connection profiles END
2020-08-31 22:52:03 us=92582   remote_random = DISABLED
2020-08-31 22:52:03 us=92582   ipchange = '[UNDEF]'
2020-08-31 22:52:03 us=92582   dev = 'tun'
2020-08-31 22:52:03 us=92582   dev_type = '[UNDEF]'
2020-08-31 22:52:03 us=92582   dev_node = '[UNDEF]'
2020-08-31 22:52:03 us=92582   lladdr = '[UNDEF]'
2020-08-31 22:52:03 us=92582   topology = 1
2020-08-31 22:52:03 us=92582   ifconfig_local = '[UNDEF]'
2020-08-31 22:52:03 us=92582   ifconfig_remote_netmask = '[UNDEF]'
2020-08-31 22:52:03 us=92582   ifconfig_noexec = DISABLED
2020-08-31 22:52:03 us=92582   ifconfig_nowarn = DISABLED
2020-08-31 22:52:03 us=92582   ifconfig_ipv6_local = '[UNDEF]'
2020-08-31 22:52:03 us=92582   ifconfig_ipv6_netbits = 0
2020-08-31 22:52:03 us=92582   ifconfig_ipv6_remote = '[UNDEF]'
2020-08-31 22:52:03 us=92582   shaper = 0
2020-08-31 22:52:03 us=92582   mtu_test = 0
2020-08-31 22:52:03 us=92582   mlock = DISABLED
2020-08-31 22:52:03 us=92582   keepalive_ping = 0
2020-08-31 22:52:03 us=92582   keepalive_timeout = 0
2020-08-31 22:52:03 us=92582   inactivity_timeout = 0
2020-08-31 22:52:03 us=92582   ping_send_timeout = 0
2020-08-31 22:52:03 us=92582   ping_rec_timeout = 0
2020-08-31 22:52:03 us=92582   ping_rec_timeout_action = 0
2020-08-31 22:52:03 us=92582   ping_timer_remote = DISABLED
2020-08-31 22:52:03 us=92582   remap_sigusr1 = 0
2020-08-31 22:52:03 us=92582   persist_tun = ENABLED
2020-08-31 22:52:03 us=92582   persist_local_ip = DISABLED
2020-08-31 22:52:03 us=92582   persist_remote_ip = DISABLED
2020-08-31 22:52:03 us=92582   persist_key = ENABLED
2020-08-31 22:52:03 us=92582   passtos = DISABLED
2020-08-31 22:52:03 us=92582   resolve_retry_seconds = 1000000000
2020-08-31 22:52:03 us=92582   resolve_in_advance = DISABLED
2020-08-31 22:52:03 us=92582   username = '[UNDEF]'
2020-08-31 22:52:03 us=92582   groupname = '[UNDEF]'
2020-08-31 22:52:03 us=92582   chroot_dir = '[UNDEF]'
2020-08-31 22:52:03 us=92582   cd_dir = '[UNDEF]'
2020-08-31 22:52:03 us=92582   writepid = '[UNDEF]'
2020-08-31 22:52:03 us=92582   up_script = '[UNDEF]'
2020-08-31 22:52:03 us=92582   down_script = '[UNDEF]'
2020-08-31 22:52:03 us=92582   down_pre = DISABLED
2020-08-31 22:52:03 us=92582   up_restart = DISABLED
2020-08-31 22:52:03 us=92582   up_delay = DISABLED
2020-08-31 22:52:03 us=92582   daemon = DISABLED
2020-08-31 22:52:03 us=92582   inetd = 0
2020-08-31 22:52:03 us=92582   log = ENABLED
2020-08-31 22:52:03 us=92582   suppress_timestamps = DISABLED
2020-08-31 22:52:03 us=92582   machine_readable_output = DISABLED
2020-08-31 22:52:03 us=92582   nice = 0
2020-08-31 22:52:03 us=92582   verbosity = 4
2020-08-31 22:52:03 us=92582   mute = 0
2020-08-31 22:52:03 us=92582   gremlin = 0
2020-08-31 22:52:03 us=92582   status_file = '[UNDEF]'
2020-08-31 22:52:03 us=92582   status_file_version = 1
2020-08-31 22:52:03 us=92582   status_file_update_freq = 60
2020-08-31 22:52:03 us=92582   occ = ENABLED
2020-08-31 22:52:03 us=92582   rcvbuf = 0
2020-08-31 22:52:03 us=92582   sndbuf = 0
2020-08-31 22:52:03 us=92582   sockflags = 0
2020-08-31 22:52:03 us=92582   fast_io = DISABLED
2020-08-31 22:52:03 us=92582   comp.alg = 0
2020-08-31 22:52:03 us=92582   comp.flags = 0
2020-08-31 22:52:03 us=92582   route_script = '[UNDEF]'
2020-08-31 22:52:03 us=92582   route_default_gateway = '[UNDEF]'
2020-08-31 22:52:03 us=92582   route_default_metric = 0
2020-08-31 22:52:03 us=92582   route_noexec = DISABLED
2020-08-31 22:52:03 us=92582   route_delay = 5
2020-08-31 22:52:03 us=92582   route_delay_window = 30
2020-08-31 22:52:03 us=92582   route_delay_defined = ENABLED
2020-08-31 22:52:03 us=92582   route_nopull = DISABLED
2020-08-31 22:52:03 us=92582   route_gateway_via_dhcp = DISABLED
2020-08-31 22:52:03 us=92582   allow_pull_fqdn = DISABLED
2020-08-31 22:52:03 us=92582   management_addr = '127.0.0.1'
2020-08-31 22:52:03 us=92582   management_port = '25341'
2020-08-31 22:52:03 us=92582   management_user_pass = 'stdin'
2020-08-31 22:52:03 us=92582   management_log_history_cache = 250
2020-08-31 22:52:03 us=92582   management_echo_buffer_size = 100
2020-08-31 22:52:03 us=92582   management_write_peer_info_file = '[UNDEF]'
2020-08-31 22:52:03 us=92582   management_client_user = '[UNDEF]'
2020-08-31 22:52:03 us=92582   management_client_group = '[UNDEF]'
2020-08-31 22:52:03 us=92582   management_flags = 6
2020-08-31 22:52:03 us=92582   shared_secret_file = '[UNDEF]'
2020-08-31 22:52:03 us=92582   key_direction = 1
2020-08-31 22:52:03 us=92582   ciphername = 'AES-128-GCM'
2020-08-31 22:52:03 us=92582   ncp_enabled = ENABLED
2020-08-31 22:52:03 us=92582   ncp_ciphers = 'AES-256-GCM:AES-128-GCM'
2020-08-31 22:52:03 us=92582   authname = 'SHA256'
2020-08-31 22:52:03 us=92582   prng_hash = 'SHA1'
2020-08-31 22:52:03 us=92582   prng_nonce_secret_len = 16
2020-08-31 22:52:03 us=92582   keysize = 0
2020-08-31 22:52:03 us=92582   engine = DISABLED
2020-08-31 22:52:03 us=92582   replay = ENABLED
2020-08-31 22:52:03 us=92582   mute_replay_warnings = DISABLED
2020-08-31 22:52:03 us=92582   replay_window = 64
2020-08-31 22:52:03 us=92582   replay_time = 15
2020-08-31 22:52:03 us=92582   packet_id_file = '[UNDEF]'
2020-08-31 22:52:03 us=92582   test_crypto = DISABLED
2020-08-31 22:52:03 us=92582   tls_server = DISABLED
2020-08-31 22:52:03 us=92582   tls_client = ENABLED
2020-08-31 22:52:03 us=92582   ca_file = '[INLINE]'
2020-08-31 22:52:03 us=92582   ca_path = '[UNDEF]'
2020-08-31 22:52:03 us=92582   dh_file = '[UNDEF]'
2020-08-31 22:52:03 us=92582   cert_file = '[UNDEF]'
2020-08-31 22:52:03 us=92582   extra_certs_file = '[UNDEF]'
2020-08-31 22:52:03 us=92582   priv_key_file = '[UNDEF]'
2020-08-31 22:52:03 us=92582   pkcs12_file = '[UNDEF]'
2020-08-31 22:52:03 us=92582   cryptoapi_cert = '[UNDEF]'
2020-08-31 22:52:03 us=92582   cipher_list = 'TLS-ECDHE-ECDSA-WITH-AES-128-GCM-SHA256'
2020-08-31 22:52:03 us=92582   cipher_list_tls13 = '[UNDEF]'
2020-08-31 22:52:03 us=92582   tls_cert_profile = '[UNDEF]'
2020-08-31 22:52:03 us=92582   tls_verify = '[UNDEF]'
2020-08-31 22:52:03 us=92582   tls_export_cert = '[UNDEF]'
2020-08-31 22:52:03 us=92582   verify_x509_type = 2
2020-08-31 22:52:03 us=92582   verify_x509_name = 'OpenVPN_Server_2'
2020-08-31 22:52:03 us=92582   crl_file = '[UNDEF]'
2020-08-31 22:52:03 us=92582   ns_cert_type = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 65535
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_ku[i] = 0
2020-08-31 22:52:03 us=92582   remote_cert_eku = 'TLS Web Server Authentication'
2020-08-31 22:52:03 us=92582   ssl_flags = 192
2020-08-31 22:52:03 us=92582   tls_timeout = 2
2020-08-31 22:52:03 us=92582   renegotiate_bytes = -1
2020-08-31 22:52:03 us=92582   renegotiate_packets = 0
2020-08-31 22:52:03 us=92582   renegotiate_seconds = 3600
2020-08-31 22:52:03 us=92582   handshake_window = 60
2020-08-31 22:52:03 us=92582   transition_window = 3600
2020-08-31 22:52:03 us=92582   single_session = DISABLED
2020-08-31 22:52:03 us=92582   push_peer_info = DISABLED
2020-08-31 22:52:03 us=92582   tls_exit = DISABLED
2020-08-31 22:52:03 us=92582   tls_crypt_v2_metadata = '[UNDEF]'
2020-08-31 22:52:03 us=92582   pkcs11_providers = C:\Windows\System32\cvP11.dll
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_protected_authentication = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_private_mode = 00000000
2020-08-31 22:52:03 us=92582   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=92582   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=93578   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=93578   pkcs11_cert_private = DISABLED
2020-08-31 22:52:03 us=93578   pkcs11_pin_cache_period = -1
2020-08-31 22:52:03 us=93578   pkcs11_id = 'cv\x20cryptovision\x20gmbh\x20\x28c\x29\x20v1\x2E0j/JavaCardOS/3036393837343232/Jan\x20Kleefeld/4314A75F64BAFC28'
2020-08-31 22:52:03 us=93578   pkcs11_id_management = DISABLED
2020-08-31 22:52:03 us=93578   server_network = 0.0.0.0
2020-08-31 22:52:03 us=93578   server_netmask = 0.0.0.0
2020-08-31 22:52:03 us=93578   server_network_ipv6 = ::
2020-08-31 22:52:03 us=93578   server_netbits_ipv6 = 0
2020-08-31 22:52:03 us=93578   server_bridge_ip = 0.0.0.0
2020-08-31 22:52:03 us=93578   server_bridge_netmask = 0.0.0.0
2020-08-31 22:52:03 us=93578   server_bridge_pool_start = 0.0.0.0
2020-08-31 22:52:03 us=93578   server_bridge_pool_end = 0.0.0.0
2020-08-31 22:52:03 us=93578   ifconfig_pool_defined = DISABLED
2020-08-31 22:52:03 us=93578   ifconfig_pool_start = 0.0.0.0
2020-08-31 22:52:03 us=93578   ifconfig_pool_end = 0.0.0.0
2020-08-31 22:52:03 us=93578   ifconfig_pool_netmask = 0.0.0.0
2020-08-31 22:52:03 us=93578   ifconfig_pool_persist_filename = '[UNDEF]'
2020-08-31 22:52:03 us=93578   ifconfig_pool_persist_refresh_freq = 600
2020-08-31 22:52:03 us=93578   ifconfig_ipv6_pool_defined = DISABLED
2020-08-31 22:52:03 us=93578   ifconfig_ipv6_pool_base = ::
2020-08-31 22:52:03 us=93578   ifconfig_ipv6_pool_netbits = 0
2020-08-31 22:52:03 us=93578   n_bcast_buf = 256
2020-08-31 22:52:03 us=93578   tcp_queue_limit = 64
2020-08-31 22:52:03 us=93578   real_hash_size = 256
2020-08-31 22:52:03 us=93578   virtual_hash_size = 256
2020-08-31 22:52:03 us=93578   client_connect_script = '[UNDEF]'
2020-08-31 22:52:03 us=93578   learn_address_script = '[UNDEF]'
2020-08-31 22:52:03 us=93578   client_disconnect_script = '[UNDEF]'
2020-08-31 22:52:03 us=93578   client_config_dir = '[UNDEF]'
2020-08-31 22:52:03 us=93578   ccd_exclusive = DISABLED
2020-08-31 22:52:03 us=93578   tmp_dir = 'C:\Users\JANKLE~1\AppData\Local\Temp\'
2020-08-31 22:52:03 us=93578   push_ifconfig_defined = DISABLED
2020-08-31 22:52:03 us=93578   push_ifconfig_local = 0.0.0.0
2020-08-31 22:52:03 us=93578   push_ifconfig_remote_netmask = 0.0.0.0
2020-08-31 22:52:03 us=93578   push_ifconfig_ipv6_defined = DISABLED
2020-08-31 22:52:03 us=93578   push_ifconfig_ipv6_local = ::/0
2020-08-31 22:52:03 us=93578   push_ifconfig_ipv6_remote = ::
2020-08-31 22:52:03 us=93578   enable_c2c = DISABLED
2020-08-31 22:52:03 us=93578   duplicate_cn = DISABLED
2020-08-31 22:52:03 us=93578   cf_max = 0
2020-08-31 22:52:03 us=93578   cf_per = 0
2020-08-31 22:52:03 us=93578   max_clients = 1024
2020-08-31 22:52:03 us=93578   max_routes_per_client = 256
2020-08-31 22:52:03 us=93578   auth_user_pass_verify_script = '[UNDEF]'
2020-08-31 22:52:03 us=93578   auth_user_pass_verify_script_via_file = DISABLED
2020-08-31 22:52:03 us=93578   auth_token_generate = DISABLED
2020-08-31 22:52:03 us=93578   auth_token_lifetime = 0
2020-08-31 22:52:03 us=93578   auth_token_secret_file = '[UNDEF]'
2020-08-31 22:52:03 us=93578   vlan_tagging = DISABLED
2020-08-31 22:52:03 us=93578   vlan_accept = all
2020-08-31 22:52:03 us=93578   vlan_pvid = 1
2020-08-31 22:52:03 us=93578   client = ENABLED
2020-08-31 22:52:03 us=93578   pull = ENABLED
2020-08-31 22:52:03 us=93578   auth_user_pass_file = '[UNDEF]'
2020-08-31 22:52:03 us=93578   show_net_up = DISABLED
2020-08-31 22:52:03 us=93578   route_method = 0
2020-08-31 22:52:03 us=93578   block_outside_dns = ENABLED
2020-08-31 22:52:03 us=93578   ip_win32_defined = DISABLED
2020-08-31 22:52:03 us=93578   ip_win32_type = 3
2020-08-31 22:52:03 us=93578   dhcp_masq_offset = 0
2020-08-31 22:52:03 us=93578   dhcp_lease_time = 31536000
2020-08-31 22:52:03 us=93578   tap_sleep = 0
2020-08-31 22:52:03 us=93578   dhcp_options = DISABLED
2020-08-31 22:52:03 us=93578   dhcp_renew = DISABLED
2020-08-31 22:52:03 us=93578   dhcp_pre_release = DISABLED
2020-08-31 22:52:03 us=93578   domain = '[UNDEF]'
2020-08-31 22:52:03 us=93578   netbios_scope = '[UNDEF]'
2020-08-31 22:52:03 us=93578   netbios_node_type = 0
2020-08-31 22:52:03 us=93578   disable_nbt = DISABLED
2020-08-31 22:52:03 us=93578 OpenVPN 2.5_beta1 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Aug 14 2020
2020-08-31 22:52:03 us=93578 Windows version 10.0 (Windows 10 or greater) 64bit
2020-08-31 22:52:03 us=93578 library versions: OpenSSL 1.1.1g  21 Apr 2020, LZO 2.10
Enter Management Password:
2020-08-31 22:52:03 us=93578 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25341
2020-08-31 22:52:03 us=93578 Need hold release from management interface, waiting...
2020-08-31 22:52:03 us=589380 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25341
2020-08-31 22:52:03 us=697428 MANAGEMENT: CMD 'state on'
2020-08-31 22:52:03 us=697428 MANAGEMENT: CMD 'log all on'
2020-08-31 22:52:03 us=814178 MANAGEMENT: CMD 'echo all on'
2020-08-31 22:52:03 us=815175 MANAGEMENT: CMD 'bytecount 5'
2020-08-31 22:52:03 us=817347 MANAGEMENT: CMD 'hold off'
2020-08-31 22:52:03 us=818346 MANAGEMENT: CMD 'hold release'
2020-08-31 22:52:03 us=818346 PKCS#11: Adding PKCS#11 provider 'C:\Windows\System32\cvP11.dll'
2020-08-31 22:52:04 us=697156 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2020-08-31 22:52:04 us=697156 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2020-08-31 22:52:04 us=697156 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2020-08-31 22:52:04 us=697156 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2020-08-31 22:52:04 us=697156 Control Channel MTU parms [ L:1621 D:1156 EF:94 EB:0 ET:0 EL:3 ]
2020-08-31 22:52:04 us=697156 MANAGEMENT: >STATE:1598907124,RESOLVE,,,,,,
2020-08-31 22:52:04 us=699183 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
2020-08-31 22:52:04 us=699183 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,keydir 1,cipher AES-128-GCM,auth [null-digest],keysize 128,key-method 2,tls-client'
2020-08-31 22:52:04 us=699183 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,keydir 0,cipher AES-128-GCM,auth [null-digest],keysize 128,key-method 2,tls-server'
2020-08-31 22:52:04 us=699183 TCP/UDP: Preserving recently used remote address: [AF_INET]192.168.2.150:1194
2020-08-31 22:52:04 us=699183 Socket Buffers: R=[65536->65536] S=[64512->64512]
2020-08-31 22:52:04 us=699183 UDP link local: (not bound)
2020-08-31 22:52:04 us=699183 UDP link remote: [AF_INET]192.168.2.150:1194
2020-08-31 22:52:04 us=699183 MANAGEMENT: >STATE:1598907124,WAIT,,,,,,
2020-08-31 22:52:04 us=703202 MANAGEMENT: >STATE:1598907124,AUTH,,,,,,
2020-08-31 22:52:04 us=703202 TLS: Initial packet from [AF_INET]192.168.2.150:1194, sid=4188fa35 11bdc6af
2020-08-31 22:52:04 us=811572 VERIFY OK: depth=2, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=Certificate Authority, CN=ROOT CA jan-home.de, emailAddress=support@jan-home.de
2020-08-31 22:52:04 us=811572 VERIFY OK: depth=1, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=Certificate Authority, CN=Intermediate CA VPN jan-home.de, emailAddress=support@jan-home.de
2020-08-31 22:52:04 us=811572 VERIFY KU OK
2020-08-31 22:52:04 us=811572 Validating certificate extended key usage
2020-08-31 22:52:04 us=811572 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
2020-08-31 22:52:04 us=811572 VERIFY EKU OK
2020-08-31 22:52:04 us=811572 VERIFY X509NAME OK: C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=OpenVPN_Server, CN=OpenVPN_Server_2, emailAddress=support@jan-home.de
2020-08-31 22:52:04 us=811572 VERIFY OK: depth=0, C=DE, ST=NRW, L=Velbert, O=jan-home.de, OU=OpenVPN_Server, CN=OpenVPN_Server_2, emailAddress=support@jan-home.de
2020-08-31 22:52:04 us=812570 OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
2020-08-31 22:52:04 us=812570 TLS_ERROR: BIO read tls_read_plaintext error
2020-08-31 22:52:04 us=812570 TLS Error: TLS object -> incoming plaintext read error
2020-08-31 22:52:04 us=812570 TLS Error: TLS handshake failed
2020-08-31 22:52:04 us=812570 TCP/UDP: Closing socket
2020-08-31 22:52:04 us=812570 SIGUSR1[soft,tls-error] received, process restarting
2020-08-31 22:52:04 us=812570 MANAGEMENT: >STATE:1598907124,RECONNECTING,tls-error,,,,,
2020-08-31 22:52:04 us=812570 Restart pause, 5 second(s)
2020-08-31 22:52:08 us=865590 SIGTERM[hard,init_instance] received, process exiting
2020-08-31 22:52:08 us=865590 MANAGEMENT: >STATE:1598907128,EXITING,init_instance,,,,,

Re: SmartCard TLS_ERROR: BIO read tls_read_plaintext error

Posted: Mon Aug 31, 2020 10:13 pm
by TinCanTech
You can try an older version of openvpn for your client:
https://build.openvpn.net/downloads/releases/

Try 2.4.7 and 2.4.8

Let us know if you find a version which works then we may be able to figure out what is broken.

Re: SmartCard TLS_ERROR: BIO read tls_read_plaintext error

Posted: Tue Sep 01, 2020 2:24 pm
by becm
Please try the newly available 2.5 beta3 and supply feedback on problems or improvments.
More verbose output should reveal a PKCS#11 error (__pkcs11h_openssl_rsa_enc -> CKR_MECHANISM_INVALID).

Only Windows installers since beta2 bundle a pkcs11-helper version new enough to support "RSA PSS padding".
It also includes fixes for for mentioned problems with the rfc7512 representation.

These changes may be also included for future 2.4.10.
Please file a bug if any tokens start to misbehave with 2.5_beta3 that worked fine with 2.4.x.

Background: Debian 10 uses a newer OpenSSL release with TLS1.3 support and changed padding for TLS1.2.

Beware: On any other platform, pkcs11-helper is an external component (and likely out of date).

Note: beta1 unintentionally used the 'classic' format (only) as well. :oops:

Re: SmartCard TLS_ERROR: BIO read tls_read_plaintext error

Posted: Thu Sep 03, 2020 12:47 pm
by jank04
Try 2.4.7 and 2.4.8
I tryed 2.4.7 i607 and 2.4.8 i602. Both weren't able to connect. Both smartcard and certificate inside ovpn file.

Code: Select all

Thu Sep 03 12:25:36 2020 us=232837 Current Parameter Settings:
Thu Sep 03 12:25:36 2020 us=232837   config = 'Jan Kleefeld SmartCard SN 3036393837343232.ovpn'
Thu Sep 03 12:25:36 2020 us=232837   mode = 0
Thu Sep 03 12:25:36 2020 us=232837   show_ciphers = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   show_digests = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   show_engines = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   genkey = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   key_pass_file = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   show_tls_ciphers = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   connect_retry_max = 0
Thu Sep 03 12:25:36 2020 us=232837 Connection profiles [0]:
Thu Sep 03 12:25:36 2020 us=232837   proto = udp
Thu Sep 03 12:25:36 2020 us=232837   local = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   local_port = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   remote = 'jan-home.de'
Thu Sep 03 12:25:36 2020 us=232837   remote_port = '1194'
Thu Sep 03 12:25:36 2020 us=232837   remote_float = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   bind_defined = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   bind_local = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   bind_ipv6_only = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   connect_retry_seconds = 5
Thu Sep 03 12:25:36 2020 us=232837   connect_timeout = 120
Thu Sep 03 12:25:36 2020 us=232837   socks_proxy_server = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   socks_proxy_port = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   tun_mtu = 1500
Thu Sep 03 12:25:36 2020 us=232837   tun_mtu_defined = ENABLED
Thu Sep 03 12:25:36 2020 us=232837   link_mtu = 1500
Thu Sep 03 12:25:36 2020 us=232837   link_mtu_defined = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   tun_mtu_extra = 0
Thu Sep 03 12:25:36 2020 us=232837   tun_mtu_extra_defined = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   mtu_discover_type = -1
Thu Sep 03 12:25:36 2020 us=232837   fragment = 0
Thu Sep 03 12:25:36 2020 us=232837   mssfix = 1450
Thu Sep 03 12:25:36 2020 us=232837   explicit_exit_notification = 1
Thu Sep 03 12:25:36 2020 us=232837 Connection profiles END
Thu Sep 03 12:25:36 2020 us=232837   remote_random = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   ipchange = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   dev = 'tun'
Thu Sep 03 12:25:36 2020 us=232837   dev_type = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   dev_node = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   lladdr = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   topology = 1
Thu Sep 03 12:25:36 2020 us=232837   ifconfig_local = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   ifconfig_remote_netmask = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   ifconfig_noexec = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   ifconfig_nowarn = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   ifconfig_ipv6_local = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   ifconfig_ipv6_netbits = 0
Thu Sep 03 12:25:36 2020 us=232837   ifconfig_ipv6_remote = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   shaper = 0
Thu Sep 03 12:25:36 2020 us=232837   mtu_test = 0
Thu Sep 03 12:25:36 2020 us=232837   mlock = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   keepalive_ping = 0
Thu Sep 03 12:25:36 2020 us=232837   keepalive_timeout = 0
Thu Sep 03 12:25:36 2020 us=232837   inactivity_timeout = 0
Thu Sep 03 12:25:36 2020 us=232837   ping_send_timeout = 0
Thu Sep 03 12:25:36 2020 us=232837   ping_rec_timeout = 0
Thu Sep 03 12:25:36 2020 us=232837   ping_rec_timeout_action = 0
Thu Sep 03 12:25:36 2020 us=232837   ping_timer_remote = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   remap_sigusr1 = 0
Thu Sep 03 12:25:36 2020 us=232837   persist_tun = ENABLED
Thu Sep 03 12:25:36 2020 us=232837   persist_local_ip = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   persist_remote_ip = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   persist_key = ENABLED
Thu Sep 03 12:25:36 2020 us=232837   passtos = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   resolve_retry_seconds = 1000000000
Thu Sep 03 12:25:36 2020 us=232837   resolve_in_advance = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   username = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   groupname = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   chroot_dir = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   cd_dir = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   writepid = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   up_script = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   down_script = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   down_pre = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   up_restart = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   up_delay = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   daemon = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   inetd = 0
Thu Sep 03 12:25:36 2020 us=232837   log = ENABLED
Thu Sep 03 12:25:36 2020 us=232837   suppress_timestamps = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   machine_readable_output = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   nice = 0
Thu Sep 03 12:25:36 2020 us=232837   verbosity = 4
Thu Sep 03 12:25:36 2020 us=232837   mute = 0
Thu Sep 03 12:25:36 2020 us=232837   gremlin = 0
Thu Sep 03 12:25:36 2020 us=232837   status_file = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   status_file_version = 1
Thu Sep 03 12:25:36 2020 us=232837   status_file_update_freq = 60
Thu Sep 03 12:25:36 2020 us=232837   occ = ENABLED
Thu Sep 03 12:25:36 2020 us=232837   rcvbuf = 0
Thu Sep 03 12:25:36 2020 us=232837   sndbuf = 0
Thu Sep 03 12:25:36 2020 us=232837   sockflags = 0
Thu Sep 03 12:25:36 2020 us=232837   fast_io = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   comp.alg = 0
Thu Sep 03 12:25:36 2020 us=232837   comp.flags = 0
Thu Sep 03 12:25:36 2020 us=232837   route_script = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   route_default_gateway = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   route_default_metric = 0
Thu Sep 03 12:25:36 2020 us=232837   route_noexec = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   route_delay = 5
Thu Sep 03 12:25:36 2020 us=232837   route_delay_window = 30
Thu Sep 03 12:25:36 2020 us=232837   route_delay_defined = ENABLED
Thu Sep 03 12:25:36 2020 us=232837   route_nopull = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   route_gateway_via_dhcp = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   allow_pull_fqdn = DISABLED
Thu Sep 03 12:25:36 2020 us=232837   management_addr = '127.0.0.1'
Thu Sep 03 12:25:36 2020 us=232837   management_port = '25341'
Thu Sep 03 12:25:36 2020 us=232837   management_user_pass = 'stdin'
Thu Sep 03 12:25:36 2020 us=232837   management_log_history_cache = 250
Thu Sep 03 12:25:36 2020 us=232837   management_echo_buffer_size = 100
Thu Sep 03 12:25:36 2020 us=232837   management_write_peer_info_file = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   management_client_user = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   management_client_group = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   management_flags = 6
Thu Sep 03 12:25:36 2020 us=232837   shared_secret_file = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=232837   key_direction = 1
Thu Sep 03 12:25:36 2020 us=232837   ciphername = 'AES-128-GCM'
Thu Sep 03 12:25:36 2020 us=232837   ncp_enabled = ENABLED
Thu Sep 03 12:25:36 2020 us=232837   ncp_ciphers = 'AES-256-GCM:AES-128-GCM'
Thu Sep 03 12:25:36 2020 us=233834   authname = 'SHA256'
Thu Sep 03 12:25:36 2020 us=233834   prng_hash = 'SHA1'
Thu Sep 03 12:25:36 2020 us=233834   prng_nonce_secret_len = 16
Thu Sep 03 12:25:36 2020 us=233834   keysize = 0
Thu Sep 03 12:25:36 2020 us=233834   engine = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   replay = ENABLED
Thu Sep 03 12:25:36 2020 us=233834   mute_replay_warnings = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   replay_window = 64
Thu Sep 03 12:25:36 2020 us=233834   replay_time = 15
Thu Sep 03 12:25:36 2020 us=233834   packet_id_file = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   use_iv = ENABLED
Thu Sep 03 12:25:36 2020 us=233834   test_crypto = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   tls_server = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   tls_client = ENABLED
Thu Sep 03 12:25:36 2020 us=233834   key_method = 2
Thu Sep 03 12:25:36 2020 us=233834   ca_file = '[[INLINE]]'
Thu Sep 03 12:25:36 2020 us=233834   ca_path = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   dh_file = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   cert_file = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   extra_certs_file = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   priv_key_file = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   pkcs12_file = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   cryptoapi_cert = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   cipher_list = 'TLS-ECDHE-ECDSA-WITH-AES-128-GCM-SHA256'
Thu Sep 03 12:25:36 2020 us=233834   cipher_list_tls13 = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   tls_cert_profile = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   tls_verify = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   tls_export_cert = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   verify_x509_type = 2
Thu Sep 03 12:25:36 2020 us=233834   verify_x509_name = 'OpenVPN_Server_2'
Thu Sep 03 12:25:36 2020 us=233834   crl_file = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   ns_cert_type = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 65535
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_ku[i] = 0
Thu Sep 03 12:25:36 2020 us=233834   remote_cert_eku = 'TLS Web Server Authentication'
Thu Sep 03 12:25:36 2020 us=233834   ssl_flags = 192
Thu Sep 03 12:25:36 2020 us=233834   tls_timeout = 2
Thu Sep 03 12:25:36 2020 us=233834   renegotiate_bytes = -1
Thu Sep 03 12:25:36 2020 us=233834   renegotiate_packets = 0
Thu Sep 03 12:25:36 2020 us=233834   renegotiate_seconds = 3600
Thu Sep 03 12:25:36 2020 us=233834   handshake_window = 60
Thu Sep 03 12:25:36 2020 us=233834   transition_window = 3600
Thu Sep 03 12:25:36 2020 us=233834   single_session = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   push_peer_info = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   tls_exit = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   tls_auth_file = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   tls_crypt_file = '[[INLINE]]'
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_providers = C:\Windows\System32\cvP11.dll
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_protected_authentication = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_private_mode = 00000000
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_cert_private = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_pin_cache_period = -1
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_id = 'cv\x20cryptovision\x20gmbh\x20\x28c\x29\x20v1\x2E0j/JavaCardOS/3036393837343232/Jan\x20Kleefeld/4314A75F64BAFC28'
Thu Sep 03 12:25:36 2020 us=233834   pkcs11_id_management = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   server_network = 0.0.0.0
Thu Sep 03 12:25:36 2020 us=233834   server_netmask = 0.0.0.0
Thu Sep 03 12:25:36 2020 us=233834   server_network_ipv6 = ::
Thu Sep 03 12:25:36 2020 us=233834   server_netbits_ipv6 = 0
Thu Sep 03 12:25:36 2020 us=233834   server_bridge_ip = 0.0.0.0
Thu Sep 03 12:25:36 2020 us=233834   server_bridge_netmask = 0.0.0.0
Thu Sep 03 12:25:36 2020 us=233834   server_bridge_pool_start = 0.0.0.0
Thu Sep 03 12:25:36 2020 us=233834   server_bridge_pool_end = 0.0.0.0
Thu Sep 03 12:25:36 2020 us=233834   ifconfig_pool_defined = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   ifconfig_pool_start = 0.0.0.0
Thu Sep 03 12:25:36 2020 us=233834   ifconfig_pool_end = 0.0.0.0
Thu Sep 03 12:25:36 2020 us=233834   ifconfig_pool_netmask = 0.0.0.0
Thu Sep 03 12:25:36 2020 us=233834   ifconfig_pool_persist_filename = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   ifconfig_pool_persist_refresh_freq = 600
Thu Sep 03 12:25:36 2020 us=233834   ifconfig_ipv6_pool_defined = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   ifconfig_ipv6_pool_base = ::
Thu Sep 03 12:25:36 2020 us=233834   ifconfig_ipv6_pool_netbits = 0
Thu Sep 03 12:25:36 2020 us=233834   n_bcast_buf = 256
Thu Sep 03 12:25:36 2020 us=233834   tcp_queue_limit = 64
Thu Sep 03 12:25:36 2020 us=233834   real_hash_size = 256
Thu Sep 03 12:25:36 2020 us=233834   virtual_hash_size = 256
Thu Sep 03 12:25:36 2020 us=233834   client_connect_script = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   learn_address_script = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   client_disconnect_script = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   client_config_dir = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   ccd_exclusive = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   tmp_dir = 'C:\Users\JANKLE~1\AppData\Local\Temp\'
Thu Sep 03 12:25:36 2020 us=233834   push_ifconfig_defined = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   push_ifconfig_local = 0.0.0.0
Thu Sep 03 12:25:36 2020 us=233834   push_ifconfig_remote_netmask = 0.0.0.0
Thu Sep 03 12:25:36 2020 us=233834   push_ifconfig_ipv6_defined = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   push_ifconfig_ipv6_local = ::/0
Thu Sep 03 12:25:36 2020 us=233834   push_ifconfig_ipv6_remote = ::
Thu Sep 03 12:25:36 2020 us=233834   enable_c2c = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   duplicate_cn = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   cf_max = 0
Thu Sep 03 12:25:36 2020 us=233834   cf_per = 0
Thu Sep 03 12:25:36 2020 us=233834   max_clients = 1024
Thu Sep 03 12:25:36 2020 us=233834   max_routes_per_client = 256
Thu Sep 03 12:25:36 2020 us=233834   auth_user_pass_verify_script = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   auth_user_pass_verify_script_via_file = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   auth_token_generate = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   auth_token_lifetime = 0
Thu Sep 03 12:25:36 2020 us=233834   client = ENABLED
Thu Sep 03 12:25:36 2020 us=233834   pull = ENABLED
Thu Sep 03 12:25:36 2020 us=233834   auth_user_pass_file = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   show_net_up = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   route_method = 0
Thu Sep 03 12:25:36 2020 us=233834   block_outside_dns = ENABLED
Thu Sep 03 12:25:36 2020 us=233834   ip_win32_defined = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   ip_win32_type = 3
Thu Sep 03 12:25:36 2020 us=233834   dhcp_masq_offset = 0
Thu Sep 03 12:25:36 2020 us=233834   dhcp_lease_time = 31536000
Thu Sep 03 12:25:36 2020 us=233834   tap_sleep = 0
Thu Sep 03 12:25:36 2020 us=233834   dhcp_options = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   dhcp_renew = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   dhcp_pre_release = DISABLED
Thu Sep 03 12:25:36 2020 us=233834   domain = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   netbios_scope = '[UNDEF]'
Thu Sep 03 12:25:36 2020 us=233834   netbios_node_type = 0
Thu Sep 03 12:25:36 2020 us=233834   disable_nbt = DISABLED

Thu Sep 03 12:25:36 2020 us=233834 OpenVPN 2.4.8 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Oct 31 2019
Thu Sep 03 12:25:36 2020 us=233834 Windows version 6.2 (Windows 8 or greater) 64bit
Thu Sep 03 12:25:36 2020 us=233834 library versions: OpenSSL 1.1.0l  10 Sep 2019, LZO 2.10
Enter Management Password:
Thu Sep 03 12:25:36 2020 us=234831 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25341
Thu Sep 03 12:25:36 2020 us=234831 Need hold release from management interface, waiting...
Thu Sep 03 12:25:36 2020 us=730279 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25341
Thu Sep 03 12:25:36 2020 us=840983 MANAGEMENT: CMD 'state on'
Thu Sep 03 12:25:36 2020 us=840983 MANAGEMENT: CMD 'log all on'
Thu Sep 03 12:25:36 2020 us=948666 MANAGEMENT: CMD 'echo all on'
Thu Sep 03 12:25:36 2020 us=949664 MANAGEMENT: CMD 'bytecount 5'
Thu Sep 03 12:25:36 2020 us=950661 MANAGEMENT: CMD 'hold off'
Thu Sep 03 12:25:36 2020 us=952655 MANAGEMENT: CMD 'hold release'
Thu Sep 03 12:25:36 2020 us=952655 PKCS#11: Adding PKCS#11 provider 'C:\Windows\System32\cvP11.dll'
Thu Sep 03 12:25:37 2020 us=818587 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Thu Sep 03 12:25:37 2020 us=818587 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Thu Sep 03 12:25:37 2020 us=818587 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Thu Sep 03 12:25:37 2020 us=818587 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Thu Sep 03 12:25:37 2020 us=818587 Control Channel MTU parms [ L:1621 D:1156 EF:94 EB:0 ET:0 EL:3 ]
Thu Sep 03 12:25:37 2020 us=818587 MANAGEMENT: >STATE:1599128737,RESOLVE,,,,,,
Thu Sep 03 12:25:37 2020 us=820581 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Thu Sep 03 12:25:37 2020 us=820581 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,keydir 1,cipher AES-128-GCM,auth [null-digest],keysize 128,key-method 2,tls-client'
Thu Sep 03 12:25:37 2020 us=820581 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,keydir 0,cipher AES-128-GCM,auth [null-digest],keysize 128,key-method 2,tls-server'
Thu Sep 03 12:25:37 2020 us=820581 TCP/UDP: Preserving recently used remote address: [AF_INET]192.168.2.150:1194
Thu Sep 03 12:25:37 2020 us=820581 Socket Buffers: R=[65536->65536] S=[64512->64512]
Thu Sep 03 12:25:37 2020 us=820581 UDP link local: (not bound)
Thu Sep 03 12:25:37 2020 us=820581 UDP link remote: [AF_INET]192.168.2.150:1194
Thu Sep 03 12:25:37 2020 us=820581 MANAGEMENT: >STATE:1599128737,WAIT,,,,,,
Thu Sep 03 12:25:37 2020 us=825568 MANAGEMENT: >STATE:1599128737,AUTH,,,,,,
Thu Sep 03 12:25:37 2020 us=825568 TLS: Initial packet from [AF_INET]192.168.2.150:1194, sid=4f91847e 5f349f42
_____________ stucks here________________
Thu Sep 03 12:25:53 2020 us=263829 SIGTERM received, sending exit notification to peer
Thu Sep 03 12:25:54 2020 us=503512 TCP/UDP: Closing socket
Thu Sep 03 12:25:54 2020 us=503512 SIGTERM[soft,exit-with-notification] received, process exiting
Thu Sep 03 12:25:54 2020 us=503512 MANAGEMENT: >STATE:1599128754,EXITING,exit-with-notification,,,,,

Code: Select all

Sep  3 12:23:02 raspberrypi ovpn-server[2753]: 192.168.2.152:53730 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-128-GCM,auth [null-digest],keysize 128,key-method 2,tls-server'
Sep  3 12:23:02 raspberrypi ovpn-server[2753]: 192.168.2.152:53730 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-128-GCM,auth [null-digest],keysize 128,key-method 2,tls-client'
Sep  3 12:23:02 raspberrypi ovpn-server[2753]: 192.168.2.152:53730 TLS: Initial packet from [AF_INET]192.168.2.152:53730, sid=a7679931 e17a9ed3
Sep  3 12:23:02 raspberrypi ovpn-server[2753]: 192.168.2.152:53730 TLS error: The server has no TLS ciphersuites in common with the client. Your --tls-cipher setting might be too restrictive.
Sep  3 12:23:02 raspberrypi ovpn-server[2753]: 192.168.2.152:53730 OpenSSL: error:1417A0C1:SSL routines:tls_post_process_client_hello:no shared cipher
Sep  3 12:23:02 raspberrypi ovpn-server[2753]: 192.168.2.152:53730 TLS_ERROR: BIO read tls_read_plaintext error
Sep  3 12:23:02 raspberrypi ovpn-server[2753]: 192.168.2.152:53730 TLS Error: TLS object -> incoming plaintext read error
Sep  3 12:23:02 raspberrypi ovpn-server[2753]: 192.168.2.152:53730 TLS Error: TLS handshake failed
Sep  3 12:23:02 raspberrypi ovpn-server[2753]: 192.168.2.152:53730 SIGUSR1[soft,tls-error] received, client-instance restarting
Please try the newly available 2.5 beta3 and supply feedback on problems or improvments.
The Beta 2.5-beta3 works
Note: beta1 unintentionally used the 'classic' format (only) as well.
Is it correct/intentional that in the beta3 the old and new serialized id works? I have tested that, and figured out, that this is the case.

Thanks for your help so far. Dou you know, when we can expect the beta3 or 2.4.10 release?

Re: SmartCard TLS_ERROR: BIO read tls_read_plaintext error

Posted: Thu Sep 03, 2020 6:05 pm
by becm
The Windows releases OpenVPN 2.4.7 and 2.4.8 were shipped with OpenSSL 1.1.0, making TLS 1.3 effectively unusable or may even lead to problems with TLS 1.2 when connecting to OpenVPN servers already using OpenSSL 1.1.1 (not shure on the latter).

Accepting both serialization formats is expected behaviour since OpenVPN 2.4.5. The parser for the "new" PKCS#11 ID format just did somthing bad™ when reading long token serials.
Being able to read the "old" format is intended only for backward compatibility, but in that code path the error just did not exist.

While I don't know the timeline for 2.4.10, your feedback will increases chances for the relevant updates to get included.
The new OpenVPN 2.5 installer for Windows still has issues, so not shure there either. Sorry.

Re: SmartCard TLS_ERROR: BIO read tls_read_plaintext error

Posted: Fri Sep 04, 2020 9:00 am
by jank04
Nice.
As I can tell for sure, the 2.5-beta3 just works fine. Also on my notebook. The serialization and connection via smartcard is working without any issues.

Re: SmartCard TLS_ERROR: BIO read tls_read_plaintext error

Posted: Sun Sep 20, 2020 12:20 pm
by becm
On taking a 2nd look at the logs, it seems OpenVPN 2.4.7 and 2.4.8 fail due to problems with the TLS 1.2 parameters:

Code: Select all

Sep  3 12:23:02 raspberrypi ovpn-server[2753]: 192.168.2.152:53730 TLS error: The server has no TLS ciphersuites in common with the client. Your --tls-cipher setting might be too restrictive.
With the current configs:
  • older clients fail due to incompatible TLS 1.2 configuration (OpenSSL 1.1.0).
  • newer clients either use TLS 1.3 or can handle existing TLS 1.2 config settings (OpenSSL 1.1.1)
  • OpenVPN 2.4.9 fails due to a missing feature in the PKCS#11 code path (new padding type).
  • OpenVPN 2.5_beta2+ supports the new padding
Expected behaviour after fixing config problems:
  • Older clients (up to 2.4.8) connect via TLS 1.2 using classic padding
  • OpenVPN 2.4.9 still fails, even when TLS 1.2 is enforced (OpenSSL 1.1.1 on client+server triggers new padding)
  • OpenVPN 2.5_beta2+ can successfully connect via TLS 1.2 and/or 1.3 using new padding