After upgrade Windows 10 client to OpenVPN 2.6, Yubikey PKCS11 PIV fails on server with error 0A00007B:SSL routines::bad
Posted: Thu Mar 02, 2023 11:52 am
Hi there,
this is a complex issue and I am unsure whether this is an OpenVPN/OpenSSL/OpenSC issue or Yubikey issue.
For OpenVPN server/client I'm using elliptic curve TLS certificates and client certificate/key is imported into a Yubikey.
Client:
PS C:\Program Files\OpenVPN\bin> .\openvpn --version
OpenVPN 2.6.0 [git:v2.6.0/b999466418dddb89] Windows-MSVC [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] [DCO] built on Feb 15 2023
library versions: OpenSSL 3.0.8 7 Feb 2023, LZO 2.10
Windows version 10.0 (Windows 10 or greater), amd64 executable
Originally developed by James Yonan
Copyright (C) 2002-2023 OpenVPN Inc <sales@openvpn.net>
Compile time defines: N/A
Windows 10 Pro
OpenSC-0.23.0
Yubico PIV Tool 2.3.0
Yubikey Manager 5.0.0 (Version 1.2.5)
Server:
Ubuntu 22.04.2 LTS x86_64
openvpn --version
OpenVPN 2.6.0 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD]
library versions: OpenSSL 3.0.2 15 Mar 2022
Originally developed by James Yonan
Copyright (C) 2002-2023 OpenVPN Inc <sales@openvpn.net>
Compile time defines: enable_async_push=no enable_comp_stub=no enable_crypto_ofb_cfb=yes enable_dco=no enable_debug=yes enable_dlopen=unknown enable_dlopen_self=unknown enable_dlopen_self_static=unknown enable_fast_install=needless enable_fragment=yes enable_iproute2=no enable_libtool_lock=yes enable_lz4=yes enable_lzo=no enable_management=yes enable_pam_dlopen=no enable_pedantic=no enable_pkcs11=no enable_plugin_auth_pam=yes enable_plugin_down_root=yes enable_plugins=yes enable_port_share=yes enable_selinux=no enable_shared=yes enable_shared_with_static_runtimes=no enable_small=no enable_static=yes enable_strict=no enable_strict_options=no enable_systemd=no enable_werror=no enable_win32_dll=yes enable_wolfssl_options_h=yes enable_x509_alt_username=no with_aix_soname=aix with_crypto_library=openssl with_gnu_ld=yes with_mem_check=no with_openssl_engine=auto with_sysroot=no
server.conf:
server 10.18.0.0 255.255.255.0
local XXX.XXX.XXX.XXX
proto udp
dev tun
lport 1198
topology subnet
push "topology subnet"
push "redirect-gateway def1 bypass-dhcp"
push "dhcp-option DNS 9.9.9.9"
push "route 192.168.XXX.XXX 255.255.255.0"
push "register-dns"
push "block-outside-dns"
ca /etc/openvpn/server/tvpnca.crt
cert /etc/openvpn/server/tvpnsrv3.crt
key /etc/openvpn/server/tvpnsrv3.key
dh /etc/openvpn/server/dh.pem
cipher AES-256-GCM
auth SHA256
auth-nocache
ecdh-curve prime256v1
tls-version-min 1.3
tls-crypt /etc/openvpn/server/ta.key
ping-timer-rem
keepalive 10 60
persist-key
persist-tun
verb 7
mute 10
status /var/log/openvpn/openvpn-status.log
log-append /var/log/openvpn/openvpn.log
ifconfig-pool-persist /var/log/openvpn/ipp.txt
client-conf:
client
dev tun
windows-driver wintun
remote XXX.XXX.XXX.XXX 1198 udp
persist-tun
persist-key
resolv-retry infinite
cipher AES-256-GCM
auth SHA256
auth-nocache
ecdh-curve prime256v1
tls-version-min 1.3
nobind
remote-cert-tls server
verb 7
# Silence repeating messages
;mute 20
keepalive 10 120
ping-timer-rem
#pkcs11-providers 'C:\Program Files\OpenSC Project\OpenSC\pkcs11\opensc-pkcs11.dll'
pkcs11-providers 'C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll'
#pkcs11-providers 'C:\Program Files\Yubico\Yubico PIV Tool\bin\libykcs11.dll'
pkcs11-id 'pkcs11:model=PKCS%2315%20emulated;token=vpncl503;manufacturer=piv_II;serial=518dc747a01de9bf;id=%01'
#pkcs11-id 'pkcs11:model=YubiKey%20YK5;token=YubiKey%20PIV%20%23XXXXXXXXXX;manufacturer=Yubico%20%28www.yubico.com%29;serial=XXXXXXXXXX;id=%01'
<ca>
-----BEGIN CERTIFICATE-----
MIICXjCCAgSgAwIBAgIIBy+/S2+1XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX....
-----END CERTIFICATE-----
</ca>
<tls-crypt>
#
# 2048 bit OpenVPN static key
#
-----BEGIN OpenVPN Static key V1-----
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
XXXXXXXXXXXXXXXXX...
-----END OpenVPN Static key V1-----
</tls-crypt>
OpenVPN 2.6 server-log message:
..snip..
Connection Attempt 3 variation(s) on previous 10 message(s) suppressed by --mute
Connection Attempt UDPv4 WRITE [66] to [AF_INET]XXXXXXXXXX:62243: DATA len=66
Connection Attempt Valid packet (P_CONTROL_V1) with HMAC challenge from peer ([AF_INET]XXXXXXXXXX:62243), accepting new connection.
Connection Attempt MULTI: multi_create_instance called
XXXXXXXXXX:62243 Re-using SSL/TLS context
XXXXXXXXXX:62243 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
XXXXXXXXXX:62243 Outgoing Control Channel Encryption: CIPHER KEY: e9518866 6d5c66db 2a79a72d 6672db41 f11f62a3 663ec9ad 877c84f1 8264a590
XXXXXXXXXX:62243 Outgoing Control Channel Encryption: CIPHER block_size=16 iv_size=16
XXXXXXXXXX:62243 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
XXXXXXXXXX:62243 Outgoing Control Channel Encryption: HMAC KEY: 64f0d1e5 f222e7b6 13b85c1f f66ba517 6da7d95e b4291c21 45426020 bdc90bf0
XXXXXXXXXX:62243 Outgoing Control Channel Encryption: HMAC size=32 block_size=32
XXXXXXXXXX:62243 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
XXXXXXXXXX:62243 Incoming Control Channel Encryption: CIPHER KEY: c82e8db1 2b53c9e8 b66e23e1 6bacee39 77c3492b 0f2027dc 0dc4c66f e6fad28b
XXXXXXXXXX:62243 Incoming Control Channel Encryption: CIPHER block_size=16 iv_size=16
XXXXXXXXXX:62243 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
XXXXXXXXXX:62243 Incoming Control Channel Encryption: HMAC KEY: f3223d88 a235c31e 0629bf02 7a5f5420 5d301389 0990a21b 417e5646 36a7716f
XXXXXXXXXX:62243 Incoming Control Channel Encryption: HMAC size=32 block_size=32
XXXXXXXXXX:62243 MTU: adding 426 buffer tailroom for compression for 1768 bytes of payload
XXXXXXXXXX:62243 NOTE: --mute triggered...
XXXXXXXXXX:62243 4 variation(s) on previous 10 message(s) suppressed by --mute
XXXXXXXXXX:62243 Control Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1250 tun_max_mtu:0 headroom:126 payload:1600 tailroom:126 ET:0 ]
XXXXXXXXXX:62243 Data Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
XXXXXXXXXX:62243 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-server'
XXXXXXXXXX:62243 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-client'
XXXXXXXXXX:62243 SENT PING
XXXXXXXXXX:62243 GET INST BY REAL: XXXXXXXXXX:62243 [ok]
XXXXXXXXXX:62243 UDPv4 READ [287] from [AF_INET]XXXXXXXXXX:62243: P_CONTROL_V1 kid=0 [ ] pid=611 DATA len=273
XXXXXXXXXX:62243 PID_TEST [0] [TLS_WRAP-0] [] 0:0 1677247064:2 t=1677247063[0] r=[0,64,15,0,1] sl=[0,0,64,528]
XXXXXXXXXX:62243 UDPv4 WRITE [1206] to [AF_INET]XXXXXXXXXX:62243: P_CONTROL_V1 kid=0 [ ] pid=611 DATA len=1192
XXXXXXXXXX:62243 UDPv4 WRITE [761] to [AF_INET]XXXXXXXXXX:62243: P_CONTROL_V1 kid=0 [ ] pid=867 DATA len=747
GET INST BY REAL: XXXXXXXXXX:62243 [ok]
XXXXXXXXXX:62243 UDPv4 READ [66] from [AF_INET]XXXXXXXXXX:62243: P_ACK_V1 kid=0 [ ] DATA len=56
XXXXXXXXXX:62243 PID_TEST [0] [TLS_WRAP-0] [0_] 1677247064:2 1677247064:3 t=1677247063[0] r=[0,64,15,0,1] sl=[62,2,64,528]
MULTI: REAP range 64 -> 80
XXXXXXXXXX:62243 UDPv4 WRITE [761] to [AF_INET]XXXXXXXXXX:62243: P_CONTROL_V1 kid=0 [ ] pid=1123 DATA len=747
XXXXXXXXXX:62243 MULTI: C2C/MCAST/BCAST
MULTI: REAP range 80 -> 96
MULTI: REAP range 96 -> 112
NOTE: --mute triggered...
XXXXXXXXXX:62243 2 variation(s) on previous 10 message(s) suppressed by --mute
XXXXXXXXXX:62243 UDPv4 READ [1206] from [AF_INET]XXXXXXXXXX:62243: P_CONTROL_V1 kid=0 [ ] pid=1123 DATA len=1192
XXXXXXXXXX:62243 PID_TEST [0] [TLS_WRAP-0] [55_] 1677247064:3 1677247064:4 t=1677247068[0] r=[0,64,15,0,1] sl=[61,3,64,528]
XXXXXXXXXX:62243 UDPv4 WRITE [66] to [AF_INET]XXXXXXXXXX:62243: P_ACK_V1 kid=0 [ ] DATA len=56
GET INST BY REAL: XXXXXXXXXX:62243 [ok]
XXXXXXXXXX:62243 UDPv4 READ [873] from [AF_INET]XXXXXXXXXX:62243: P_CONTROL_V1 kid=0 [ ] pid=1379 DATA len=859
XXXXXXXXXX:62243 PID_TEST [0] [TLS_WRAP-0] [055_] 1677247064:4 1677247064:5 t=1677247068[0] r=[0,64,15,0,1] sl=[60,4,64,528]
XXXXXXXXXX:62243 VERIFY OK: depth=1, C=de, ST=teststate-ca, L=testlocal-ca, O=testouname-ca, OU=systestou-ca, CN=tvpnca
XXXXXXXXXX:62243 VERIFY OK: depth=0, C=de, ST=teststate, L=testlocation, O=testouname, OU=systestou, CN=vpncl503
XXXXXXXXXX:62243 OpenSSL: error:0A00007B:SSL routines::bad signature
XXXXXXXXXX:62243 TLS_ERROR: BIO read tls_read_plaintext error
XXXXXXXXXX:62243 TLS Error: TLS object -> incoming plaintext read error
XXXXXXXXXX:62243 NOTE: --mute triggered...
XXXXXXXXXX:62243 1 variation(s) on previous 10 message(s) suppressed by --mute
XXXXXXXXXX:62243 PID packet_id_free
XXXXXXXXXX:62243 PID packet_id_free
XXXXXXXXXX:62243 PID packet_id_free
XXXXXXXXXX:62243 NOTE: --mute triggered...
..snip..
OpenVPN 2.6 client-log:
..snip..
2023-02-24 14:57:42 us=890000 OpenVPN 2.6.0 [git:v2.6.0/b999466418dddb89] Windows-MSVC [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] [DCO] built on Feb 15 2023
2023-02-24 14:57:42 us=890000 Windows version 10.0 (Windows 10 or greater), amd64 executable
2023-02-24 14:57:42 us=890000 library versions: OpenSSL 3.0.8 7 Feb 2023, LZO 2.10
2023-02-24 14:57:42 us=890000 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25345
2023-02-24 14:57:42 us=890000 Need hold release from management interface, waiting...
2023-02-24 14:57:43 us=328000 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:50632
2023-02-24 14:57:43 us=437000 MANAGEMENT: CMD 'state on'
2023-02-24 14:57:43 us=437000 MANAGEMENT: CMD 'log on all'
2023-02-24 14:57:43 us=671000 MANAGEMENT: CMD 'echo on all'
2023-02-24 14:57:43 us=671000 MANAGEMENT: CMD 'bytecount 5'
2023-02-24 14:57:43 us=671000 MANAGEMENT: CMD 'state'
2023-02-24 14:57:43 us=671000 MANAGEMENT: CMD 'hold off'
2023-02-24 14:57:43 us=671000 MANAGEMENT: CMD 'hold release'
2023-02-24 14:57:43 us=671000 PKCS#11: Setting property 7=*size*
2023-02-24 14:57:43 us=671000 PKCS#11: Setting property 6=*size*
2023-02-24 14:57:43 us=671000 PKCS#11: Setting property 9=*size*
2023-02-24 14:57:43 us=671000 PKCS#11: Setting property 8=*size*
2023-02-24 14:57:43 us=671000 PKCS#11: Setting property 10=0x1
2023-02-24 14:57:43 us=671000 PKCS#11: Setting property 11=0xffffffff
2023-02-24 14:57:43 us=671000 PKCS#11: Adding PKCS#11 provider 'C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll'
2023-02-24 14:57:43 us=671000 PKCS#11: Register provider 'C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll'
2023-02-24 14:57:43 us=671000 PKCS#11: Provider 'C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll' registered rv=0-'CKR_OK'
2023-02-24 14:57:43 us=671000 PKCS#11: Setting provider property C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll:location=C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll
2023-02-24 14:57:43 us=671000 PKCS#11: Setting provider property C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll:allow_protected_auth=0x0
2023-02-24 14:57:43 us=671000 PKCS#11: Setting provider property C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll:mask_private_mode=0x0
2023-02-24 14:57:43 us=671000 PKCS#11: Setting provider property C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll:cert_is_private=0x0
2023-02-24 14:57:43 us=671000 PKCS#11: Setting provider property C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll:provider_loader_flags=0x1100
2023-02-24 14:57:43 us=671000 PKCS#11: Initializing provider 'C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll'
2023-02-24 14:57:44 us=515000 PKCS#11: Creating a new session
2023-02-24 14:57:44 us=625000 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2023-02-24 14:57:44 us=640000 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2023-02-24 14:57:44 us=640000 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2023-02-24 14:57:44 us=640000 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2023-02-24 14:57:44 us=640000 MTU: adding 426 buffer tailroom for compression for 1768 bytes of payload
2023-02-24 14:57:44 us=640000 Control Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1250 tun_max_mtu:0 headroom:126 payload:1600 tailroom:126 ET:0 ]
2023-02-24 14:57:44 us=640000 Data Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
2023-02-24 14:57:44 us=640000 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-client'
2023-02-24 14:57:44 us=640000 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-server'
2023-02-24 14:57:44 us=640000 TCP/UDP: Preserving recently used remote address: [AF_INET]XXXXXXXXXX:1198
2023-02-24 14:57:44 us=640000 Socket Buffers: R=[65536->65536] S=[65536->65536]
2023-02-24 14:57:44 us=640000 UDPv4 link local: (not bound)
2023-02-24 14:57:44 us=640000 UDPv4 link remote: [AF_INET]XXXXXXXXXX:1198
2023-02-24 14:57:44 us=640000 MANAGEMENT: >STATE:1677247064,WAIT,,,,,,
2023-02-24 14:57:44 us=640000 UDPv4 WRITE [54] to [AF_INET]XXXXXXXXXX
P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=355 DATA len=40
2023-02-24 14:57:44 us=640000 UDPv4 READ [0] from [AF_UNSPEC]: DATA UNDEF len=-1
2023-02-24 14:57:44 us=640000 UDPv4 READ [66] from [AF_INET]XXXXXXXXXX P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=355 DATA len=52
2023-02-24 14:57:44 us=640000 MANAGEMENT: >STATE:1677247064,AUTH,,,,,,
2023-02-24 14:57:44 us=640000 TLS: Initial packet from [AF_INET]XXXXXXXXXX:1198, sid=ea4c2a67 a3636730
2023-02-24 14:57:44 us=640000 UDPv4 WRITE [287] to [AF_INET]XXXXXXXXXX P_CONTROL_V1 kid=0 [ ] pid=611 DATA len=273
2023-02-24 14:57:44 us=640000 UDPv4 READ [1206] from [AF_INET]XXXXXXXXXX P_CONTROL_V1 kid=0 [ ] pid=611 DATA len=1192
2023-02-24 14:57:44 us=640000 UDPv4 WRITE [66] to [AF_INET]XXXXXXXXXX P_ACK_V1 kid=0 [ ] DATA len=56
2023-02-24 14:57:44 us=640000 UDPv4 READ [761] from [AF_INET]XXXXXXXXXX P_CONTROL_V1 kid=0 [ ] pid=867 DATA len=747
2023-02-24 14:57:44 us=640000 VERIFY OK: depth=1, C=de, ST=teststate-ca, L=testlocal-ca, O=testouname-ca, OU=systestou-ca, CN=tvpnca
2023-02-24 14:57:44 us=640000 VERIFY KU OK
2023-02-24 14:57:44 us=640000 Validating certificate extended key usage
2023-02-24 14:57:44 us=640000 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
2023-02-24 14:57:44 us=640000 VERIFY EKU OK
2023-02-24 14:57:44 us=640000 VERIFY OK: depth=0, C=de, ST=teststate, L=testlocation, O=testouname, OU=systestou, CN=tvpnsrv3crt
2023-02-24 14:57:44 us=640000 xkey_pkcs11h_sign: computing digest
2023-02-24 14:57:44 us=640000 xkey_pkcs11h_sign: signing with EC key
2023-02-24 14:57:44 us=640000 PKCS#11: Getting key attributes
2023-02-24 14:57:44 us=640000 PKCS#11: Get private key attributes failed: 130:'CKR_OBJECT_HANDLE_INVALID'
2023-02-24 14:57:44 us=750000 PKCS#11: Calling pin_prompt hook for ''
2023-02-24 14:57:49 us=15000 MANAGEMENT: CMD 'password [...]'
2023-02-24 14:57:49 us=15000 PKCS#11: key_prompt/pin_prompt hook return rv=0
2023-02-24 14:57:49 us=187000 PKCS#11: Key attribute=00000001 always_authenticated=0
2023-02-24 14:57:49 us=312000 UDPv4 WRITE [1206] to [AF_INET]XXXXXXXXXX P_CONTROL_V1 kid=0 [ ] pid=1123 DATA len=1192
2023-02-24 14:57:49 us=312000 UDPv4 WRITE [873] to [AF_INET]XXXXXXXXXX P_CONTROL_V1 kid=0 [ ] pid=1379 DATA len=859
2023-02-24 14:57:49 us=312000 UDPv4 READ [761] from [AF_INET]XXXXXXXXXX P_CONTROL_V1 kid=0 [ ] pid=1123 DATA len=747
2023-02-24 14:57:49 us=312000 UDPv4 WRITE [70] to [AF_INET]XXXXXXXXXX P_ACK_V1 kid=0 [ ] DATA len=60
2023-02-24 14:57:49 us=312000 UDPv4 READ [66] from [AF_INET]XXXXXXXXXX P_ACK_V1 kid=0 [ ] DATA len=56
2023-02-24 14:57:51 us=453000 UDPv4 WRITE [873] to [AF_INET]XXXXXXXXXX P_CONTROL_V1 kid=0 [ ] pid=1891 DATA len=859
2023-02-24 14:57:51 us=453000 UDPv4 READ [62] from [AF_INET]XXXXXXXXXX P_ACK_V1 kid=0 [ ] DATA len=52
2023-02-24 14:58:09 us=796000 MANAGEMENT: CMD 'signal SIGHUP
..snip..
opensc-pkcs11spy-log:
..snip..
13: C_FindObjectsInit
2023-02-24 14:57:43.919
[in] hSession = 0x25f72000
[in] pTemplate[2]:
CKA_CLASS CKO_PRIVATE_KEY
CKA_ID 000001442792e850 / 1
00000000 01 .
Returned: 0 CKR_OK
14: C_FindObjects
2023-02-24 14:57:43.968
[in] hSession = 0x25f72000
[in] ulMaxObjectCount = 0x64
[out] ulObjectCount = 0x0
Returned: 0 CKR_OK
15: C_FindObjectsFinal
2023-02-24 14:57:43.968
[in] hSession = 0x25f72000
Returned: 0 CKR_OK
16: C_Logout
2023-02-24 14:57:43.969
[in] hSession = 0x25f72000
Returned: 257 CKR_USER_NOT_LOGGED_IN
17: C_CloseSession
2023-02-24 14:57:43.970
[in] hSession = 0x25f72000
Returned: 0 CKR_OK
18: C_GetSlotList
2023-02-24 14:57:43.971
[in] tokenPresent = 0x1
[out] pSlotList:
Count is 1
[out] *pulCount = 0x1
Returned: 0 CKR_OK
19: C_GetSlotList
2023-02-24 14:57:43.989
[in] tokenPresent = 0x1
[out] pSlotList:
Slot 0
[out] *pulCount = 0x1
Returned: 0 CKR_OK
20: C_GetTokenInfo
2023-02-24 14:57:44.003
[in] slotID = 0x0
[out] pInfo:
label: 'vpncl503 '
manufacturerID: 'piv_II '
model: 'PKCS#15 emulated'
serialNumber: '518dc747a01de9bf'
ulMaxSessionCount: 0
ulSessionCount: 0
ulMaxRwSessionCount: 0
ulRwSessionCount: 0
ulMaxPinLen: 8
ulMinPinLen: 4
ulTotalPublicMemory: -1
ulFreePublicMemory: -1
ulTotalPrivateMemory: -1
ulFreePrivateMemory: -1
hardwareVersion: 0.0
firmwareVersion: 0.0
time: ' '
flags: 40d
CKF_RNG
CKF_LOGIN_REQUIRED
CKF_USER_PIN_INITIALIZED
CKF_TOKEN_INITIALIZED
Returned: 0 CKR_OK
21: C_OpenSession
2023-02-24 14:57:44.029
[in] slotID = 0x0
[in] flags = 0x4
[in] pApplication = 0000000000000000
[in] Notify = 0000000000000000
[out] *phSession = 0x27944f90
Returned: 0 CKR_OK
22: C_Login
2023-02-24 14:57:48.297
[in] hSession = 0x27944f90
[in] userType = CKU_USER
[in] pPin[ulPinLen] 00000042c0afc3b0 / 6
00000000 31 31 31 36 36 38 XXXXXX
Returned: 0 CKR_OK
23: C_FindObjectsInit
2023-02-24 14:57:48.384
[in] hSession = 0x27944f90
[in] pTemplate[2]:
CKA_CLASS CKO_PRIVATE_KEY
CKA_ID 000001442792e850 / 1
00000000 01 .
Returned: 0 CKR_OK
24: C_FindObjects
2023-02-24 14:57:48.449
[in] hSession = 0x27944f90
[in] ulMaxObjectCount = 0x64
[out] ulObjectCount = 0x1
Object 0x25fbdfc0 matches
Returned: 0 CKR_OK
25: C_FindObjects
2023-02-24 14:57:48.450
[in] hSession = 0x27944f90
[in] ulMaxObjectCount = 0x64
[out] ulObjectCount = 0x0
Returned: 0 CKR_OK
26: C_FindObjectsFinal
2023-02-24 14:57:48.450
[in] hSession = 0x27944f90
Returned: 0 CKR_OK
27: C_GetAttributeValue
2023-02-24 14:57:48.451
[in] hSession = 0x27944f90
[in] hObject = 0x25fbdfc0
[in] pTemplate[6]:
CKA_SIGN 0000000000000000 / 0
CKA_SIGN_RECOVER 0000000000000000 / 0
CKA_DECRYPT 0000000000000000 / 0
CKA_UNWRAP 0000000000000000 / 0
CKA_ALWAYS_AUTHENTICATE 0000000000000000 / 0
CKA_LABEL 0000000000000000 / 0
[out] pTemplate[6]:
CKA_SIGN 0000000000000000 / 1
CKA_SIGN_RECOVER 0000000000000000 / 1
CKA_DECRYPT 0000000000000000 / 1
CKA_UNWRAP 0000000000000000 / 1
CKA_ALWAYS_AUTHENTICATE 0000000000000000 / 1
CKA_LABEL 0000000000000000 / 12
Returned: 0 CKR_OK
28: C_GetAttributeValue
2023-02-24 14:57:48.457
[in] hSession = 0x27944f90
[in] hObject = 0x25fbdfc0
[in] pTemplate[6]:
CKA_SIGN 00000144279ab6c0 / 1
CKA_SIGN_RECOVER 00000144279ab5d0 / 1
CKA_DECRYPT 00000144279ab840 / 1
CKA_UNWRAP 00000144279ab700 / 1
CKA_ALWAYS_AUTHENTICATE 00000144279ab630 / 1
CKA_LABEL 0000014427964c20 / 12
[out] pTemplate[6]:
CKA_SIGN True
CKA_SIGN_RECOVER False
CKA_DECRYPT False
CKA_UNWRAP False
CKA_ALWAYS_AUTHENTICATE False
CKA_LABEL 0000014427964c20 / 12
50495620 41555448 206B6579
P I V . A U T H . k e y
Returned: 0 CKR_OK
29: C_SignInit
2023-02-24 14:57:48.463
[in] hSession = 0x27944f90
[in] pMechanism->type = CKM_ECDSA
[in] pMechanism->pParameter[ulParameterLen] NULL [size : 0x0 (0)]
[in] hKey = 0x25fbdfc0
Returned: 0 CKR_OK
30: C_Sign
2023-02-24 14:57:48.470
[in] hSession = 0x27944f90
[in] pData[ulDataLen] 00000042c0afca50 / 32
00000000 A7 94 B8 56 7E DB A0 65 57 1A D0 DE EF CA D7 DE ...V~..eW.......
00000010 2E 16 22 57 E0 40 FA 16 9A 0E 6D 14 14 D7 82 17 .."W.@....m.....
[out] pSignature[*pulSignatureLen] 000001442794be30 / 64
00000000 AB 32 96 DC C5 97 AF 36 6F 9A AE 2E CD 4F 72 EA .2.....6o....Or.
00000010 89 A2 F3 C3 C9 DF 8B BF 62 EC 77 A3 E7 AF 13 0F ........b.w.....
00000020 B1 60 F8 D5 C7 11 06 3A 5E C8 66 58 53 02 7E FA .`.....:^.fXS.~.
00000030 28 E3 4F FF CB 30 3B 58 5F 81 68 BB 30 93 32 6B (.O..0;X_.h.0.2k
Returned: 0 CKR_OK
31: C_FindObjectsInit
2023-02-24 14:58:10.094
[in] hSession = 0x27944f90
[in] pTemplate[2]:
CKA_CLASS CKO_CERTIFICATE
CKA_ID 0000014425faf4c0 / 1
00000000 01 .
Returned: 0 CKR_OK
32: C_FindObjects
2023-02-24 14:58:10.134
[in] hSession = 0x27944f90
[in] ulMaxObjectCount = 0x64
[out] ulObjectCount = 0x1
Object 0x25fbe020 matches
Returned: 0 CKR_OK
..snip..
Any thoughts or hints on the possible isser causer are welcome.
I am also highly interested on input for further debugging possibilities/procedures.
I suspect OpenSSL 3.0.x in conjunction with PKCS11 PIV pkcs11-helper as a potential issue causer. Because a connection with OpenVPN 2.6 Server/Client is possible without using PKCS11 PIV.
Many thanks in advance.
this is a complex issue and I am unsure whether this is an OpenVPN/OpenSSL/OpenSC issue or Yubikey issue.
For OpenVPN server/client I'm using elliptic curve TLS certificates and client certificate/key is imported into a Yubikey.
Client:
PS C:\Program Files\OpenVPN\bin> .\openvpn --version
OpenVPN 2.6.0 [git:v2.6.0/b999466418dddb89] Windows-MSVC [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] [DCO] built on Feb 15 2023
library versions: OpenSSL 3.0.8 7 Feb 2023, LZO 2.10
Windows version 10.0 (Windows 10 or greater), amd64 executable
Originally developed by James Yonan
Copyright (C) 2002-2023 OpenVPN Inc <sales@openvpn.net>
Compile time defines: N/A
Windows 10 Pro
OpenSC-0.23.0
Yubico PIV Tool 2.3.0
Yubikey Manager 5.0.0 (Version 1.2.5)
Server:
Ubuntu 22.04.2 LTS x86_64
openvpn --version
OpenVPN 2.6.0 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD]
library versions: OpenSSL 3.0.2 15 Mar 2022
Originally developed by James Yonan
Copyright (C) 2002-2023 OpenVPN Inc <sales@openvpn.net>
Compile time defines: enable_async_push=no enable_comp_stub=no enable_crypto_ofb_cfb=yes enable_dco=no enable_debug=yes enable_dlopen=unknown enable_dlopen_self=unknown enable_dlopen_self_static=unknown enable_fast_install=needless enable_fragment=yes enable_iproute2=no enable_libtool_lock=yes enable_lz4=yes enable_lzo=no enable_management=yes enable_pam_dlopen=no enable_pedantic=no enable_pkcs11=no enable_plugin_auth_pam=yes enable_plugin_down_root=yes enable_plugins=yes enable_port_share=yes enable_selinux=no enable_shared=yes enable_shared_with_static_runtimes=no enable_small=no enable_static=yes enable_strict=no enable_strict_options=no enable_systemd=no enable_werror=no enable_win32_dll=yes enable_wolfssl_options_h=yes enable_x509_alt_username=no with_aix_soname=aix with_crypto_library=openssl with_gnu_ld=yes with_mem_check=no with_openssl_engine=auto with_sysroot=no
server.conf:
server 10.18.0.0 255.255.255.0
local XXX.XXX.XXX.XXX
proto udp
dev tun
lport 1198
topology subnet
push "topology subnet"
push "redirect-gateway def1 bypass-dhcp"
push "dhcp-option DNS 9.9.9.9"
push "route 192.168.XXX.XXX 255.255.255.0"
push "register-dns"
push "block-outside-dns"
ca /etc/openvpn/server/tvpnca.crt
cert /etc/openvpn/server/tvpnsrv3.crt
key /etc/openvpn/server/tvpnsrv3.key
dh /etc/openvpn/server/dh.pem
cipher AES-256-GCM
auth SHA256
auth-nocache
ecdh-curve prime256v1
tls-version-min 1.3
tls-crypt /etc/openvpn/server/ta.key
ping-timer-rem
keepalive 10 60
persist-key
persist-tun
verb 7
mute 10
status /var/log/openvpn/openvpn-status.log
log-append /var/log/openvpn/openvpn.log
ifconfig-pool-persist /var/log/openvpn/ipp.txt
client-conf:
client
dev tun
windows-driver wintun
remote XXX.XXX.XXX.XXX 1198 udp
persist-tun
persist-key
resolv-retry infinite
cipher AES-256-GCM
auth SHA256
auth-nocache
ecdh-curve prime256v1
tls-version-min 1.3
nobind
remote-cert-tls server
verb 7
# Silence repeating messages
;mute 20
keepalive 10 120
ping-timer-rem
#pkcs11-providers 'C:\Program Files\OpenSC Project\OpenSC\pkcs11\opensc-pkcs11.dll'
pkcs11-providers 'C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll'
#pkcs11-providers 'C:\Program Files\Yubico\Yubico PIV Tool\bin\libykcs11.dll'
pkcs11-id 'pkcs11:model=PKCS%2315%20emulated;token=vpncl503;manufacturer=piv_II;serial=518dc747a01de9bf;id=%01'
#pkcs11-id 'pkcs11:model=YubiKey%20YK5;token=YubiKey%20PIV%20%23XXXXXXXXXX;manufacturer=Yubico%20%28www.yubico.com%29;serial=XXXXXXXXXX;id=%01'
<ca>
-----BEGIN CERTIFICATE-----
MIICXjCCAgSgAwIBAgIIBy+/S2+1XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX....
-----END CERTIFICATE-----
</ca>
<tls-crypt>
#
# 2048 bit OpenVPN static key
#
-----BEGIN OpenVPN Static key V1-----
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
XXXXXXXXXXXXXXXXX...
-----END OpenVPN Static key V1-----
</tls-crypt>
OpenVPN 2.6 server-log message:
..snip..
Connection Attempt 3 variation(s) on previous 10 message(s) suppressed by --mute
Connection Attempt UDPv4 WRITE [66] to [AF_INET]XXXXXXXXXX:62243: DATA len=66
Connection Attempt Valid packet (P_CONTROL_V1) with HMAC challenge from peer ([AF_INET]XXXXXXXXXX:62243), accepting new connection.
Connection Attempt MULTI: multi_create_instance called
XXXXXXXXXX:62243 Re-using SSL/TLS context
XXXXXXXXXX:62243 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
XXXXXXXXXX:62243 Outgoing Control Channel Encryption: CIPHER KEY: e9518866 6d5c66db 2a79a72d 6672db41 f11f62a3 663ec9ad 877c84f1 8264a590
XXXXXXXXXX:62243 Outgoing Control Channel Encryption: CIPHER block_size=16 iv_size=16
XXXXXXXXXX:62243 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
XXXXXXXXXX:62243 Outgoing Control Channel Encryption: HMAC KEY: 64f0d1e5 f222e7b6 13b85c1f f66ba517 6da7d95e b4291c21 45426020 bdc90bf0
XXXXXXXXXX:62243 Outgoing Control Channel Encryption: HMAC size=32 block_size=32
XXXXXXXXXX:62243 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
XXXXXXXXXX:62243 Incoming Control Channel Encryption: CIPHER KEY: c82e8db1 2b53c9e8 b66e23e1 6bacee39 77c3492b 0f2027dc 0dc4c66f e6fad28b
XXXXXXXXXX:62243 Incoming Control Channel Encryption: CIPHER block_size=16 iv_size=16
XXXXXXXXXX:62243 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
XXXXXXXXXX:62243 Incoming Control Channel Encryption: HMAC KEY: f3223d88 a235c31e 0629bf02 7a5f5420 5d301389 0990a21b 417e5646 36a7716f
XXXXXXXXXX:62243 Incoming Control Channel Encryption: HMAC size=32 block_size=32
XXXXXXXXXX:62243 MTU: adding 426 buffer tailroom for compression for 1768 bytes of payload
XXXXXXXXXX:62243 NOTE: --mute triggered...
XXXXXXXXXX:62243 4 variation(s) on previous 10 message(s) suppressed by --mute
XXXXXXXXXX:62243 Control Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1250 tun_max_mtu:0 headroom:126 payload:1600 tailroom:126 ET:0 ]
XXXXXXXXXX:62243 Data Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
XXXXXXXXXX:62243 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-server'
XXXXXXXXXX:62243 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-client'
XXXXXXXXXX:62243 SENT PING
XXXXXXXXXX:62243 GET INST BY REAL: XXXXXXXXXX:62243 [ok]
XXXXXXXXXX:62243 UDPv4 READ [287] from [AF_INET]XXXXXXXXXX:62243: P_CONTROL_V1 kid=0 [ ] pid=611 DATA len=273
XXXXXXXXXX:62243 PID_TEST [0] [TLS_WRAP-0] [] 0:0 1677247064:2 t=1677247063[0] r=[0,64,15,0,1] sl=[0,0,64,528]
XXXXXXXXXX:62243 UDPv4 WRITE [1206] to [AF_INET]XXXXXXXXXX:62243: P_CONTROL_V1 kid=0 [ ] pid=611 DATA len=1192
XXXXXXXXXX:62243 UDPv4 WRITE [761] to [AF_INET]XXXXXXXXXX:62243: P_CONTROL_V1 kid=0 [ ] pid=867 DATA len=747
GET INST BY REAL: XXXXXXXXXX:62243 [ok]
XXXXXXXXXX:62243 UDPv4 READ [66] from [AF_INET]XXXXXXXXXX:62243: P_ACK_V1 kid=0 [ ] DATA len=56
XXXXXXXXXX:62243 PID_TEST [0] [TLS_WRAP-0] [0_] 1677247064:2 1677247064:3 t=1677247063[0] r=[0,64,15,0,1] sl=[62,2,64,528]
MULTI: REAP range 64 -> 80
XXXXXXXXXX:62243 UDPv4 WRITE [761] to [AF_INET]XXXXXXXXXX:62243: P_CONTROL_V1 kid=0 [ ] pid=1123 DATA len=747
XXXXXXXXXX:62243 MULTI: C2C/MCAST/BCAST
MULTI: REAP range 80 -> 96
MULTI: REAP range 96 -> 112
NOTE: --mute triggered...
XXXXXXXXXX:62243 2 variation(s) on previous 10 message(s) suppressed by --mute
XXXXXXXXXX:62243 UDPv4 READ [1206] from [AF_INET]XXXXXXXXXX:62243: P_CONTROL_V1 kid=0 [ ] pid=1123 DATA len=1192
XXXXXXXXXX:62243 PID_TEST [0] [TLS_WRAP-0] [55_] 1677247064:3 1677247064:4 t=1677247068[0] r=[0,64,15,0,1] sl=[61,3,64,528]
XXXXXXXXXX:62243 UDPv4 WRITE [66] to [AF_INET]XXXXXXXXXX:62243: P_ACK_V1 kid=0 [ ] DATA len=56
GET INST BY REAL: XXXXXXXXXX:62243 [ok]
XXXXXXXXXX:62243 UDPv4 READ [873] from [AF_INET]XXXXXXXXXX:62243: P_CONTROL_V1 kid=0 [ ] pid=1379 DATA len=859
XXXXXXXXXX:62243 PID_TEST [0] [TLS_WRAP-0] [055_] 1677247064:4 1677247064:5 t=1677247068[0] r=[0,64,15,0,1] sl=[60,4,64,528]
XXXXXXXXXX:62243 VERIFY OK: depth=1, C=de, ST=teststate-ca, L=testlocal-ca, O=testouname-ca, OU=systestou-ca, CN=tvpnca
XXXXXXXXXX:62243 VERIFY OK: depth=0, C=de, ST=teststate, L=testlocation, O=testouname, OU=systestou, CN=vpncl503
XXXXXXXXXX:62243 OpenSSL: error:0A00007B:SSL routines::bad signature
XXXXXXXXXX:62243 TLS_ERROR: BIO read tls_read_plaintext error
XXXXXXXXXX:62243 TLS Error: TLS object -> incoming plaintext read error
XXXXXXXXXX:62243 NOTE: --mute triggered...
XXXXXXXXXX:62243 1 variation(s) on previous 10 message(s) suppressed by --mute
XXXXXXXXXX:62243 PID packet_id_free
XXXXXXXXXX:62243 PID packet_id_free
XXXXXXXXXX:62243 PID packet_id_free
XXXXXXXXXX:62243 NOTE: --mute triggered...
..snip..
OpenVPN 2.6 client-log:
..snip..
2023-02-24 14:57:42 us=890000 OpenVPN 2.6.0 [git:v2.6.0/b999466418dddb89] Windows-MSVC [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] [DCO] built on Feb 15 2023
2023-02-24 14:57:42 us=890000 Windows version 10.0 (Windows 10 or greater), amd64 executable
2023-02-24 14:57:42 us=890000 library versions: OpenSSL 3.0.8 7 Feb 2023, LZO 2.10
2023-02-24 14:57:42 us=890000 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25345
2023-02-24 14:57:42 us=890000 Need hold release from management interface, waiting...
2023-02-24 14:57:43 us=328000 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:50632
2023-02-24 14:57:43 us=437000 MANAGEMENT: CMD 'state on'
2023-02-24 14:57:43 us=437000 MANAGEMENT: CMD 'log on all'
2023-02-24 14:57:43 us=671000 MANAGEMENT: CMD 'echo on all'
2023-02-24 14:57:43 us=671000 MANAGEMENT: CMD 'bytecount 5'
2023-02-24 14:57:43 us=671000 MANAGEMENT: CMD 'state'
2023-02-24 14:57:43 us=671000 MANAGEMENT: CMD 'hold off'
2023-02-24 14:57:43 us=671000 MANAGEMENT: CMD 'hold release'
2023-02-24 14:57:43 us=671000 PKCS#11: Setting property 7=*size*
2023-02-24 14:57:43 us=671000 PKCS#11: Setting property 6=*size*
2023-02-24 14:57:43 us=671000 PKCS#11: Setting property 9=*size*
2023-02-24 14:57:43 us=671000 PKCS#11: Setting property 8=*size*
2023-02-24 14:57:43 us=671000 PKCS#11: Setting property 10=0x1
2023-02-24 14:57:43 us=671000 PKCS#11: Setting property 11=0xffffffff
2023-02-24 14:57:43 us=671000 PKCS#11: Adding PKCS#11 provider 'C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll'
2023-02-24 14:57:43 us=671000 PKCS#11: Register provider 'C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll'
2023-02-24 14:57:43 us=671000 PKCS#11: Provider 'C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll' registered rv=0-'CKR_OK'
2023-02-24 14:57:43 us=671000 PKCS#11: Setting provider property C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll:location=C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll
2023-02-24 14:57:43 us=671000 PKCS#11: Setting provider property C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll:allow_protected_auth=0x0
2023-02-24 14:57:43 us=671000 PKCS#11: Setting provider property C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll:mask_private_mode=0x0
2023-02-24 14:57:43 us=671000 PKCS#11: Setting provider property C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll:cert_is_private=0x0
2023-02-24 14:57:43 us=671000 PKCS#11: Setting provider property C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll:provider_loader_flags=0x1100
2023-02-24 14:57:43 us=671000 PKCS#11: Initializing provider 'C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll'
2023-02-24 14:57:44 us=515000 PKCS#11: Creating a new session
2023-02-24 14:57:44 us=625000 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2023-02-24 14:57:44 us=640000 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2023-02-24 14:57:44 us=640000 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2023-02-24 14:57:44 us=640000 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2023-02-24 14:57:44 us=640000 MTU: adding 426 buffer tailroom for compression for 1768 bytes of payload
2023-02-24 14:57:44 us=640000 Control Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1250 tun_max_mtu:0 headroom:126 payload:1600 tailroom:126 ET:0 ]
2023-02-24 14:57:44 us=640000 Data Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
2023-02-24 14:57:44 us=640000 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-client'
2023-02-24 14:57:44 us=640000 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-server'
2023-02-24 14:57:44 us=640000 TCP/UDP: Preserving recently used remote address: [AF_INET]XXXXXXXXXX:1198
2023-02-24 14:57:44 us=640000 Socket Buffers: R=[65536->65536] S=[65536->65536]
2023-02-24 14:57:44 us=640000 UDPv4 link local: (not bound)
2023-02-24 14:57:44 us=640000 UDPv4 link remote: [AF_INET]XXXXXXXXXX:1198
2023-02-24 14:57:44 us=640000 MANAGEMENT: >STATE:1677247064,WAIT,,,,,,
2023-02-24 14:57:44 us=640000 UDPv4 WRITE [54] to [AF_INET]XXXXXXXXXX
P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=355 DATA len=402023-02-24 14:57:44 us=640000 UDPv4 READ [0] from [AF_UNSPEC]: DATA UNDEF len=-1
2023-02-24 14:57:44 us=640000 UDPv4 READ [66] from [AF_INET]XXXXXXXXXX
P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=355 DATA len=522023-02-24 14:57:44 us=640000 MANAGEMENT: >STATE:1677247064,AUTH,,,,,,
2023-02-24 14:57:44 us=640000 TLS: Initial packet from [AF_INET]XXXXXXXXXX:1198, sid=ea4c2a67 a3636730
2023-02-24 14:57:44 us=640000 UDPv4 WRITE [287] to [AF_INET]XXXXXXXXXX
P_CONTROL_V1 kid=0 [ ] pid=611 DATA len=2732023-02-24 14:57:44 us=640000 UDPv4 READ [1206] from [AF_INET]XXXXXXXXXX
P_CONTROL_V1 kid=0 [ ] pid=611 DATA len=11922023-02-24 14:57:44 us=640000 UDPv4 WRITE [66] to [AF_INET]XXXXXXXXXX
P_ACK_V1 kid=0 [ ] DATA len=562023-02-24 14:57:44 us=640000 UDPv4 READ [761] from [AF_INET]XXXXXXXXXX
P_CONTROL_V1 kid=0 [ ] pid=867 DATA len=7472023-02-24 14:57:44 us=640000 VERIFY OK: depth=1, C=de, ST=teststate-ca, L=testlocal-ca, O=testouname-ca, OU=systestou-ca, CN=tvpnca
2023-02-24 14:57:44 us=640000 VERIFY KU OK
2023-02-24 14:57:44 us=640000 Validating certificate extended key usage
2023-02-24 14:57:44 us=640000 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
2023-02-24 14:57:44 us=640000 VERIFY EKU OK
2023-02-24 14:57:44 us=640000 VERIFY OK: depth=0, C=de, ST=teststate, L=testlocation, O=testouname, OU=systestou, CN=tvpnsrv3crt
2023-02-24 14:57:44 us=640000 xkey_pkcs11h_sign: computing digest
2023-02-24 14:57:44 us=640000 xkey_pkcs11h_sign: signing with EC key
2023-02-24 14:57:44 us=640000 PKCS#11: Getting key attributes
2023-02-24 14:57:44 us=640000 PKCS#11: Get private key attributes failed: 130:'CKR_OBJECT_HANDLE_INVALID'
2023-02-24 14:57:44 us=750000 PKCS#11: Calling pin_prompt hook for ''
2023-02-24 14:57:49 us=15000 MANAGEMENT: CMD 'password [...]'
2023-02-24 14:57:49 us=15000 PKCS#11: key_prompt/pin_prompt hook return rv=0
2023-02-24 14:57:49 us=187000 PKCS#11: Key attribute=00000001 always_authenticated=0
2023-02-24 14:57:49 us=312000 UDPv4 WRITE [1206] to [AF_INET]XXXXXXXXXX
P_CONTROL_V1 kid=0 [ ] pid=1123 DATA len=11922023-02-24 14:57:49 us=312000 UDPv4 WRITE [873] to [AF_INET]XXXXXXXXXX
P_CONTROL_V1 kid=0 [ ] pid=1379 DATA len=8592023-02-24 14:57:49 us=312000 UDPv4 READ [761] from [AF_INET]XXXXXXXXXX
P_CONTROL_V1 kid=0 [ ] pid=1123 DATA len=7472023-02-24 14:57:49 us=312000 UDPv4 WRITE [70] to [AF_INET]XXXXXXXXXX
P_ACK_V1 kid=0 [ ] DATA len=602023-02-24 14:57:49 us=312000 UDPv4 READ [66] from [AF_INET]XXXXXXXXXX
P_ACK_V1 kid=0 [ ] DATA len=562023-02-24 14:57:51 us=453000 UDPv4 WRITE [873] to [AF_INET]XXXXXXXXXX
P_CONTROL_V1 kid=0 [ ] pid=1891 DATA len=8592023-02-24 14:57:51 us=453000 UDPv4 READ [62] from [AF_INET]XXXXXXXXXX
P_ACK_V1 kid=0 [ ] DATA len=522023-02-24 14:58:09 us=796000 MANAGEMENT: CMD 'signal SIGHUP
..snip..
opensc-pkcs11spy-log:
..snip..
13: C_FindObjectsInit
2023-02-24 14:57:43.919
[in] hSession = 0x25f72000
[in] pTemplate[2]:
CKA_CLASS CKO_PRIVATE_KEY
CKA_ID 000001442792e850 / 1
00000000 01 .
Returned: 0 CKR_OK
14: C_FindObjects
2023-02-24 14:57:43.968
[in] hSession = 0x25f72000
[in] ulMaxObjectCount = 0x64
[out] ulObjectCount = 0x0
Returned: 0 CKR_OK
15: C_FindObjectsFinal
2023-02-24 14:57:43.968
[in] hSession = 0x25f72000
Returned: 0 CKR_OK
16: C_Logout
2023-02-24 14:57:43.969
[in] hSession = 0x25f72000
Returned: 257 CKR_USER_NOT_LOGGED_IN
17: C_CloseSession
2023-02-24 14:57:43.970
[in] hSession = 0x25f72000
Returned: 0 CKR_OK
18: C_GetSlotList
2023-02-24 14:57:43.971
[in] tokenPresent = 0x1
[out] pSlotList:
Count is 1
[out] *pulCount = 0x1
Returned: 0 CKR_OK
19: C_GetSlotList
2023-02-24 14:57:43.989
[in] tokenPresent = 0x1
[out] pSlotList:
Slot 0
[out] *pulCount = 0x1
Returned: 0 CKR_OK
20: C_GetTokenInfo
2023-02-24 14:57:44.003
[in] slotID = 0x0
[out] pInfo:
label: 'vpncl503 '
manufacturerID: 'piv_II '
model: 'PKCS#15 emulated'
serialNumber: '518dc747a01de9bf'
ulMaxSessionCount: 0
ulSessionCount: 0
ulMaxRwSessionCount: 0
ulRwSessionCount: 0
ulMaxPinLen: 8
ulMinPinLen: 4
ulTotalPublicMemory: -1
ulFreePublicMemory: -1
ulTotalPrivateMemory: -1
ulFreePrivateMemory: -1
hardwareVersion: 0.0
firmwareVersion: 0.0
time: ' '
flags: 40d
CKF_RNG
CKF_LOGIN_REQUIRED
CKF_USER_PIN_INITIALIZED
CKF_TOKEN_INITIALIZED
Returned: 0 CKR_OK
21: C_OpenSession
2023-02-24 14:57:44.029
[in] slotID = 0x0
[in] flags = 0x4
[in] pApplication = 0000000000000000
[in] Notify = 0000000000000000
[out] *phSession = 0x27944f90
Returned: 0 CKR_OK
22: C_Login
2023-02-24 14:57:48.297
[in] hSession = 0x27944f90
[in] userType = CKU_USER
[in] pPin[ulPinLen] 00000042c0afc3b0 / 6
00000000 31 31 31 36 36 38 XXXXXX
Returned: 0 CKR_OK
23: C_FindObjectsInit
2023-02-24 14:57:48.384
[in] hSession = 0x27944f90
[in] pTemplate[2]:
CKA_CLASS CKO_PRIVATE_KEY
CKA_ID 000001442792e850 / 1
00000000 01 .
Returned: 0 CKR_OK
24: C_FindObjects
2023-02-24 14:57:48.449
[in] hSession = 0x27944f90
[in] ulMaxObjectCount = 0x64
[out] ulObjectCount = 0x1
Object 0x25fbdfc0 matches
Returned: 0 CKR_OK
25: C_FindObjects
2023-02-24 14:57:48.450
[in] hSession = 0x27944f90
[in] ulMaxObjectCount = 0x64
[out] ulObjectCount = 0x0
Returned: 0 CKR_OK
26: C_FindObjectsFinal
2023-02-24 14:57:48.450
[in] hSession = 0x27944f90
Returned: 0 CKR_OK
27: C_GetAttributeValue
2023-02-24 14:57:48.451
[in] hSession = 0x27944f90
[in] hObject = 0x25fbdfc0
[in] pTemplate[6]:
CKA_SIGN 0000000000000000 / 0
CKA_SIGN_RECOVER 0000000000000000 / 0
CKA_DECRYPT 0000000000000000 / 0
CKA_UNWRAP 0000000000000000 / 0
CKA_ALWAYS_AUTHENTICATE 0000000000000000 / 0
CKA_LABEL 0000000000000000 / 0
[out] pTemplate[6]:
CKA_SIGN 0000000000000000 / 1
CKA_SIGN_RECOVER 0000000000000000 / 1
CKA_DECRYPT 0000000000000000 / 1
CKA_UNWRAP 0000000000000000 / 1
CKA_ALWAYS_AUTHENTICATE 0000000000000000 / 1
CKA_LABEL 0000000000000000 / 12
Returned: 0 CKR_OK
28: C_GetAttributeValue
2023-02-24 14:57:48.457
[in] hSession = 0x27944f90
[in] hObject = 0x25fbdfc0
[in] pTemplate[6]:
CKA_SIGN 00000144279ab6c0 / 1
CKA_SIGN_RECOVER 00000144279ab5d0 / 1
CKA_DECRYPT 00000144279ab840 / 1
CKA_UNWRAP 00000144279ab700 / 1
CKA_ALWAYS_AUTHENTICATE 00000144279ab630 / 1
CKA_LABEL 0000014427964c20 / 12
[out] pTemplate[6]:
CKA_SIGN True
CKA_SIGN_RECOVER False
CKA_DECRYPT False
CKA_UNWRAP False
CKA_ALWAYS_AUTHENTICATE False
CKA_LABEL 0000014427964c20 / 12
50495620 41555448 206B6579
P I V . A U T H . k e y
Returned: 0 CKR_OK
29: C_SignInit
2023-02-24 14:57:48.463
[in] hSession = 0x27944f90
[in] pMechanism->type = CKM_ECDSA
[in] pMechanism->pParameter[ulParameterLen] NULL [size : 0x0 (0)]
[in] hKey = 0x25fbdfc0
Returned: 0 CKR_OK
30: C_Sign
2023-02-24 14:57:48.470
[in] hSession = 0x27944f90
[in] pData[ulDataLen] 00000042c0afca50 / 32
00000000 A7 94 B8 56 7E DB A0 65 57 1A D0 DE EF CA D7 DE ...V~..eW.......
00000010 2E 16 22 57 E0 40 FA 16 9A 0E 6D 14 14 D7 82 17 .."W.@....m.....
[out] pSignature[*pulSignatureLen] 000001442794be30 / 64
00000000 AB 32 96 DC C5 97 AF 36 6F 9A AE 2E CD 4F 72 EA .2.....6o....Or.
00000010 89 A2 F3 C3 C9 DF 8B BF 62 EC 77 A3 E7 AF 13 0F ........b.w.....
00000020 B1 60 F8 D5 C7 11 06 3A 5E C8 66 58 53 02 7E FA .`.....:^.fXS.~.
00000030 28 E3 4F FF CB 30 3B 58 5F 81 68 BB 30 93 32 6B (.O..0;X_.h.0.2k
Returned: 0 CKR_OK
31: C_FindObjectsInit
2023-02-24 14:58:10.094
[in] hSession = 0x27944f90
[in] pTemplate[2]:
CKA_CLASS CKO_CERTIFICATE
CKA_ID 0000014425faf4c0 / 1
00000000 01 .
Returned: 0 CKR_OK
32: C_FindObjects
2023-02-24 14:58:10.134
[in] hSession = 0x27944f90
[in] ulMaxObjectCount = 0x64
[out] ulObjectCount = 0x1
Object 0x25fbe020 matches
Returned: 0 CKR_OK
..snip..
Any thoughts or hints on the possible isser causer are welcome.
I am also highly interested on input for further debugging possibilities/procedures.
I suspect OpenSSL 3.0.x in conjunction with PKCS11 PIV pkcs11-helper as a potential issue causer. Because a connection with OpenVPN 2.6 Server/Client is possible without using PKCS11 PIV.
Many thanks in advance.