PKCS#11: Cannot perform signature CKR_USER_NOT_LOGGED_IN

rayv33n

Not sure where to look here. Seems like a pkcs11 helper issue but, I can't see enough debug info to know which component is failing. That is, if it's not my configuration.

But the behavior seems to be to accept the pin code, smartcard green light blinks solid and then fail with CKR_USER_NOT_LOGGED_IN or fail and ask for the PIN code a second time before finally failing with CKR_USER_NOT_LOGGED_IN.

Maybe some could suggest another avenue toward debugging that would shed more light on the issue? Thanks!

---- Access test to confirm PIN code is correct ---------
pkcs11-tool --module /usr/lib/x86_64-linux-gnu/libcsemwpkcs11.so -l -O

Using slot 0 with a present token (0x0)
Logging in to "Card #8980B31FE896B0FF".
Please enter User PIN:
Certificate Object; type = X.509 cert
label: 4ea60c07-ca2a-7253-79ad-009f3bacd797
subject: DN: CN=testuser
ID: 4ea60c07ca2a725379ad009f3bacd79709dc43b3
Public Key Object; RSA 2048 bits
label: somehost
ID: 4ea60c07ca2a725379ad009f3bacd79709dc43b3
Usage: encrypt, verify, wrap
Private Key Object; RSA
label: somehost
ID: 4ea60c07ca2a725379ad009f3bacd79709dc43b3
Usage: decrypt, sign, unwrap

-------------- Openvpn config --------------------
dev tun
persist-tun
persist-key
cipher AES-256-CBC
auth sha256
tls-client
client
script-security 2
static-challenge "PIN Code: " 1
remote-cert-tls server
remote vpn.SOME_VPN_SERVER.net 1194 udp
auth-nocache
key-direction 1
auth-user-pass /etc/openvpn/dummypass
pkcs11-pin-cache 10000
pkcs11-id 'Gemalto/ID\x20Prime\x20MD/8980B31FE896B0FF/Card\x20\x238980B31FE896B0FF/4EA60C07CA2A725379AD009F3BACD79709DC43B3'
pkcs11-providers /usr/lib/x86_64-linux-gnu/libcsemwpkcs11-2.7.1.0.so
<ca>
-----BEGIN CERTIFICATE-----
------>
-----END CERTIFICATE-----
-----BEGIN CERTIFICATE-----
----->
-----END CERTIFICATE-----
</ca>
<tls-auth>
----->
</tls-auth>
----------------- END CONFIG -----------------

--------------- Openvpn verb 4 log ---------------
Wed Dec 12 17:15:41 2018 us=501493 WARNING: file '/etc/openvpn.SOME_COMPANY.dummypass' is group or others accessible
Wed Dec 12 17:15:41 2018 us=501714 Current Parameter Settings:
Wed Dec 12 17:15:41 2018 us=501792 config = 'vpn.gonf'
Wed Dec 12 17:15:41 2018 us=501828 mode = 0
Wed Dec 12 17:15:41 2018 us=502003 persist_config = DISABLED
Wed Dec 12 17:15:41 2018 us=502032 persist_mode = 1
Wed Dec 12 17:15:41 2018 us=502058 show_ciphers = DISABLED
Wed Dec 12 17:15:41 2018 us=502122 show_digests = DISABLED
Wed Dec 12 17:15:41 2018 us=502248 show_engines = DISABLED
Wed Dec 12 17:15:41 2018 us=502278 genkey = DISABLED
Wed Dec 12 17:15:41 2018 us=502304 key_pass_file = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=502331 show_tls_ciphers = DISABLED
Wed Dec 12 17:15:41 2018 us=502357 connect_retry_max = 0
Wed Dec 12 17:15:41 2018 us=502383 Connection profiles [0]:
Wed Dec 12 17:15:41 2018 us=502410 proto = udp
Wed Dec 12 17:15:41 2018 us=502435 local = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=502461 local_port = '1194'
Wed Dec 12 17:15:41 2018 us=502486 remote = 'vpn.gSOME_COMPANY.net'
Wed Dec 12 17:15:41 2018 us=502511 remote_port = '1194'
Wed Dec 12 17:15:41 2018 us=502536 remote_float = DISABLED
Wed Dec 12 17:15:41 2018 us=502561 bind_defined = DISABLED
Wed Dec 12 17:15:41 2018 us=502587 bind_local = ENABLED
Wed Dec 12 17:15:41 2018 us=502612 bind_ipv6_only = DISABLED
Wed Dec 12 17:15:41 2018 us=502757 connect_retry_seconds = 5
Wed Dec 12 17:15:41 2018 us=502787 connect_timeout = 120
Wed Dec 12 17:15:41 2018 us=502812 socks_proxy_server = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=502838 socks_proxy_port = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=502863 tun_mtu = 1500
Wed Dec 12 17:15:41 2018 us=502888 tun_mtu_defined = ENABLED
Wed Dec 12 17:15:41 2018 us=502976 link_mtu = 1500
Wed Dec 12 17:15:41 2018 us=503002 link_mtu_defined = DISABLED
Wed Dec 12 17:15:41 2018 us=503144 tun_mtu_extra = 0
Wed Dec 12 17:15:41 2018 us=503212 tun_mtu_extra_defined = DISABLED
Wed Dec 12 17:15:41 2018 us=503242 mtu_discover_type = -1
Wed Dec 12 17:15:41 2018 us=503269 fragment = 0
Wed Dec 12 17:15:41 2018 us=503294 mssfix = 1450
Wed Dec 12 17:15:41 2018 us=503320 explicit_exit_notification = 0
Wed Dec 12 17:15:41 2018 us=503346 tls_auth_file = '[[INLINE]]'
Wed Dec 12 17:15:41 2018 us=503372 key_direction = 1
Wed Dec 12 17:15:41 2018 us=503397 tls_crypt_file = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=503423 Connection profiles END
Wed Dec 12 17:15:41 2018 us=503448 remote_random = DISABLED
Wed Dec 12 17:15:41 2018 us=503473 ipchange = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=503536 dev = 'tun'
Wed Dec 12 17:15:41 2018 us=503564 dev_type = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=503590 dev_node = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=503615 lladdr = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=503660 topology = 1
Wed Dec 12 17:15:41 2018 us=503711 ifconfig_local = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=503833 ifconfig_remote_netmask = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=503878 ifconfig_noexec = DISABLED
Wed Dec 12 17:15:41 2018 us=503904 ifconfig_nowarn = DISABLED
Wed Dec 12 17:15:41 2018 us=503929 ifconfig_ipv6_local = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=503990 ifconfig_ipv6_netbits = 0
Wed Dec 12 17:15:41 2018 us=504042 ifconfig_ipv6_remote = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=504093 shaper = 0
Wed Dec 12 17:15:41 2018 us=504144 mtu_test = 0
Wed Dec 12 17:15:41 2018 us=504194 mlock = DISABLED
Wed Dec 12 17:15:41 2018 us=504245 keepalive_ping = 0
Wed Dec 12 17:15:41 2018 us=504297 keepalive_timeout = 0
Wed Dec 12 17:15:41 2018 us=504517 inactivity_timeout = 0
Wed Dec 12 17:15:41 2018 us=504584 ping_send_timeout = 0
Wed Dec 12 17:15:41 2018 us=504636 ping_rec_timeout = 0
Wed Dec 12 17:15:41 2018 us=504686 ping_rec_timeout_action = 0
Wed Dec 12 17:15:41 2018 us=504738 ping_timer_remote = DISABLED
Wed Dec 12 17:15:41 2018 us=504788 remap_sigusr1 = 0
Wed Dec 12 17:15:41 2018 us=504839 persist_tun = ENABLED
Wed Dec 12 17:15:41 2018 us=504890 persist_local_ip = DISABLED
Wed Dec 12 17:15:41 2018 us=504941 persist_remote_ip = DISABLED
Wed Dec 12 17:15:41 2018 us=505009 persist_key = ENABLED
Wed Dec 12 17:15:41 2018 us=505030 passtos = DISABLED
Wed Dec 12 17:15:41 2018 us=505052 resolve_retry_seconds = 1000000000
Wed Dec 12 17:15:41 2018 us=505073 resolve_in_advance = DISABLED
Wed Dec 12 17:15:41 2018 us=505094 username = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=505115 groupname = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=505135 chroot_dir = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=505225 cd_dir = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=505292 writepid = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=505350 up_script = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=505375 down_script = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=505400 down_pre = DISABLED
Wed Dec 12 17:15:41 2018 us=505425 up_restart = DISABLED
Wed Dec 12 17:15:41 2018 us=505450 up_delay = DISABLED
Wed Dec 12 17:15:41 2018 us=505475 daemon = DISABLED
Wed Dec 12 17:15:41 2018 us=505500 inetd = 0
Wed Dec 12 17:15:41 2018 us=505525 log = DISABLED
Wed Dec 12 17:15:41 2018 us=505550 suppress_timestamps = DISABLED
Wed Dec 12 17:15:41 2018 us=505575 machine_readable_output = DISABLED
Wed Dec 12 17:15:41 2018 us=505600 nice = 0
Wed Dec 12 17:15:41 2018 us=505625 verbosity = 4
Wed Dec 12 17:15:41 2018 us=505650 mute = 0
Wed Dec 12 17:15:41 2018 us=505675 gremlin = 0
Wed Dec 12 17:15:41 2018 us=505700 status_file = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=505725 status_file_version = 1
Wed Dec 12 17:15:41 2018 us=505750 status_file_update_freq = 60
Wed Dec 12 17:15:41 2018 us=505775 occ = ENABLED
Wed Dec 12 17:15:41 2018 us=505799 rcvbuf = 0
Wed Dec 12 17:15:41 2018 us=505844 sndbuf = 0
Wed Dec 12 17:15:41 2018 us=505966 mark = 0
Wed Dec 12 17:15:41 2018 us=506089 sockflags = 0
Wed Dec 12 17:15:41 2018 us=506144 fast_io = DISABLED
Wed Dec 12 17:15:41 2018 us=506197 comp.alg = 0
Wed Dec 12 17:15:41 2018 us=506248 comp.flags = 0
Wed Dec 12 17:15:41 2018 us=506299 route_script = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=506351 route_default_gateway = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=506402 route_default_metric = 0
Wed Dec 12 17:15:41 2018 us=506453 route_noexec = DISABLED
Wed Dec 12 17:15:41 2018 us=506504 route_delay = 0
Wed Dec 12 17:15:41 2018 us=506555 route_delay_window = 30
Wed Dec 12 17:15:41 2018 us=506677 route_delay_defined = DISABLED
Wed Dec 12 17:15:41 2018 us=506731 route_nopull = DISABLED
Wed Dec 12 17:15:41 2018 us=506782 route_gateway_via_dhcp = DISABLED
Wed Dec 12 17:15:41 2018 us=506833 allow_pull_fqdn = DISABLED
Wed Dec 12 17:15:41 2018 us=506885 management_addr = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=506936 management_port = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=506987 management_user_pass = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=507039 management_log_history_cache = 250
Wed Dec 12 17:15:41 2018 us=507090 management_echo_buffer_size = 100
Wed Dec 12 17:15:41 2018 us=507141 management_write_peer_info_file = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=507199 management_client_user = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=507250 management_client_group = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=507371 management_flags = 0
Wed Dec 12 17:15:41 2018 us=507427 shared_secret_file = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=507479 key_direction = 1
Wed Dec 12 17:15:41 2018 us=507530 ciphername = 'AES-256-CBC'
Wed Dec 12 17:15:41 2018 us=507582 ncp_enabled = ENABLED
Wed Dec 12 17:15:41 2018 us=507633 ncp_ciphers = 'AES-256-GCM:AES-128-GCM'
Wed Dec 12 17:15:41 2018 us=507686 authname = 'sha256'
Wed Dec 12 17:15:41 2018 us=507738 prng_hash = 'SHA1'
Wed Dec 12 17:15:41 2018 us=507765 prng_nonce_secret_len = 16
Wed Dec 12 17:15:41 2018 us=507791 keysize = 0
Wed Dec 12 17:15:41 2018 us=507817 engine = DISABLED
Wed Dec 12 17:15:41 2018 us=507847 replay = ENABLED
Wed Dec 12 17:15:41 2018 us=507874 mute_replay_warnings = DISABLED
Wed Dec 12 17:15:41 2018 us=507900 replay_window = 64
Wed Dec 12 17:15:41 2018 us=507926 replay_time = 15
Wed Dec 12 17:15:41 2018 us=507952 packet_id_file = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=508799 test_crypto = DISABLED
Wed Dec 12 17:15:41 2018 us=508882 tls_server = DISABLED
Wed Dec 12 17:15:41 2018 us=508942 tls_client = ENABLED
Wed Dec 12 17:15:41 2018 us=509243 key_method = 2
Wed Dec 12 17:15:41 2018 us=509975 ca_file = '[[INLINE]]'
Wed Dec 12 17:15:41 2018 us=510382 ca_path = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=510703 dh_file = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=510900 cert_file = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=510935 extra_certs_file = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=511608 priv_key_file = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=511629 pkcs12_file = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=511638 cipher_list = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=511645 cipher_list_tls13 = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=511651 tls_cert_profile = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=511658 tls_verify = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=511664 tls_export_cert = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=511671 verify_x509_type = 0
Wed Dec 12 17:15:41 2018 us=511677 verify_x509_name = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=511683 crl_file = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=511690 ns_cert_type = 0
Wed Dec 12 17:15:41 2018 us=511696 remote_cert_ku = 65535
Wed Dec 12 17:15:41 2018 us=511702 remote_cert_ku = 0
Wed Dec 12 17:15:41 2018 us=511708 remote_cert_ku = 0
Wed Dec 12 17:15:41 2018 us=511714 remote_cert_ku = 0
Wed Dec 12 17:15:41 2018 us=511721 remote_cert_ku = 0
Wed Dec 12 17:15:41 2018 us=511727 remote_cert_ku = 0
Wed Dec 12 17:15:41 2018 us=511733 remote_cert_ku = 0
Wed Dec 12 17:15:41 2018 us=511739 remote_cert_ku = 0
Wed Dec 12 17:15:41 2018 us=511745 remote_cert_ku = 0
Wed Dec 12 17:15:41 2018 us=511751 remote_cert_ku = 0
Wed Dec 12 17:15:41 2018 us=511757 remote_cert_ku[i] = 0
Wed Dec 12 17:15:41 2018 us=511763 remote_cert_ku[i] = 0
Wed Dec 12 17:15:41 2018 us=511769 remote_cert_ku[i] = 0
Wed Dec 12 17:15:41 2018 us=511775 remote_cert_ku[i] = 0
Wed Dec 12 17:15:41 2018 us=511781 remote_cert_ku[i] = 0
Wed Dec 12 17:15:41 2018 us=511787 remote_cert_ku[i] = 0
Wed Dec 12 17:15:41 2018 us=511794 remote_cert_eku = 'TLS Web Server Authentication'
Wed Dec 12 17:15:41 2018 us=511800 ssl_flags = 0
Wed Dec 12 17:15:41 2018 us=511807 tls_timeout = 2
Wed Dec 12 17:15:41 2018 us=511813 renegotiate_bytes = -1
Wed Dec 12 17:15:41 2018 us=511820 renegotiate_packets = 0
Wed Dec 12 17:15:41 2018 us=511826 renegotiate_seconds = 3600
Wed Dec 12 17:15:41 2018 us=511833 handshake_window = 60
Wed Dec 12 17:15:41 2018 us=511839 transition_window = 3600
Wed Dec 12 17:15:41 2018 us=511846 single_session = DISABLED
Wed Dec 12 17:15:41 2018 us=511852 push_peer_info = DISABLED
Wed Dec 12 17:15:41 2018 us=511858 tls_exit = DISABLED
Wed Dec 12 17:15:41 2018 us=511865 pkcs11_providers = /usr/lib/x86_64-linux-gnu/libcsemwpkcs11-2.7.1.0.so
Wed Dec 12 17:15:41 2018 us=511872 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511878 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511885 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511891 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511897 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511904 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511910 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511916 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511923 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511929 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511935 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511942 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511948 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511954 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511961 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511967 pkcs11_protected_authentication = DISABLED
Wed Dec 12 17:15:41 2018 us=511974 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=511980 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=511986 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=511993 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=511999 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=512005 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=512011 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=512017 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=512023 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=512029 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=512035 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=512041 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=512294 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=512448 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=512478 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=512568 pkcs11_private_mode = 00000000
Wed Dec 12 17:15:41 2018 us=512597 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=512624 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=512650 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=512680 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=512707 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=512733 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=512759 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=512785 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=512811 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=512837 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=512863 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=523429 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=523478 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=523497 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=523513 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=523526 pkcs11_cert_private = DISABLED
Wed Dec 12 17:15:41 2018 us=523542 pkcs11_pin_cache_period = 10000
Wed Dec 12 17:15:41 2018 us=523558 pkcs11_id = 'Gemalto/ID\x20Prime\x20MD/8980B31FE896B0FF/Card\x20\x238980B31FE896B0FF/4EA60C07CA2A725379AD009F3BACD79709DC43B3'
Wed Dec 12 17:15:41 2018 us=523600 pkcs11_id_management = DISABLED
Wed Dec 12 17:15:41 2018 us=523618 server_network = 0.0.0.0
Wed Dec 12 17:15:41 2018 us=523631 server_netmask = 0.0.0.0
Wed Dec 12 17:15:41 2018 us=523657 server_network_ipv6 = ::
Wed Dec 12 17:15:41 2018 us=523668 server_netbits_ipv6 = 0
Wed Dec 12 17:15:41 2018 us=523678 server_bridge_ip = 0.0.0.0
Wed Dec 12 17:15:41 2018 us=523687 server_bridge_netmask = 0.0.0.0
Wed Dec 12 17:15:41 2018 us=523696 server_bridge_pool_start = 0.0.0.0
Wed Dec 12 17:15:41 2018 us=523705 server_bridge_pool_end = 0.0.0.0
Wed Dec 12 17:15:41 2018 us=523715 ifconfig_pool_defined = DISABLED
Wed Dec 12 17:15:41 2018 us=523726 ifconfig_pool_start = 0.0.0.0
Wed Dec 12 17:15:41 2018 us=523737 ifconfig_pool_end = 0.0.0.0
Wed Dec 12 17:15:41 2018 us=523749 ifconfig_pool_netmask = 0.0.0.0
Wed Dec 12 17:15:41 2018 us=523759 ifconfig_pool_persist_filename = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=523768 ifconfig_pool_persist_refresh_freq = 600
Wed Dec 12 17:15:41 2018 us=523777 ifconfig_ipv6_pool_defined = DISABLED
Wed Dec 12 17:15:41 2018 us=523797 ifconfig_ipv6_pool_base = ::
Wed Dec 12 17:15:41 2018 us=523808 ifconfig_ipv6_pool_netbits = 0
Wed Dec 12 17:15:41 2018 us=523816 n_bcast_buf = 256
Wed Dec 12 17:15:41 2018 us=523939 tcp_queue_limit = 64
Wed Dec 12 17:15:41 2018 us=523955 real_hash_size = 256
Wed Dec 12 17:15:41 2018 us=523967 virtual_hash_size = 256
Wed Dec 12 17:15:41 2018 us=523980 client_connect_script = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=523993 learn_address_script = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=524006 client_disconnect_script = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=524019 client_config_dir = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=524031 ccd_exclusive = DISABLED
Wed Dec 12 17:15:41 2018 us=524044 tmp_dir = '/tmp'
Wed Dec 12 17:15:41 2018 us=524056 push_ifconfig_defined = DISABLED
Wed Dec 12 17:15:41 2018 us=524070 push_ifconfig_local = 0.0.0.0
Wed Dec 12 17:15:41 2018 us=524248 push_ifconfig_remote_netmask = 0.0.0.0
Wed Dec 12 17:15:41 2018 us=524266 push_ifconfig_ipv6_defined = DISABLED
Wed Dec 12 17:15:41 2018 us=524275 push_ifconfig_ipv6_local = ::/0
Wed Dec 12 17:15:41 2018 us=524281 push_ifconfig_ipv6_remote = ::
Wed Dec 12 17:15:41 2018 us=524287 enable_c2c = DISABLED
Wed Dec 12 17:15:41 2018 us=524293 duplicate_cn = DISABLED
Wed Dec 12 17:15:41 2018 us=524299 cf_max = 0
Wed Dec 12 17:15:41 2018 us=524306 cf_per = 0
Wed Dec 12 17:15:41 2018 us=524312 max_clients = 1024
Wed Dec 12 17:15:41 2018 us=524318 max_routes_per_client = 256
Wed Dec 12 17:15:41 2018 us=524324 auth_user_pass_verify_script = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=524330 auth_user_pass_verify_script_via_file = DISABLED
Wed Dec 12 17:15:41 2018 us=524336 auth_token_generate = DISABLED
Wed Dec 12 17:15:41 2018 us=524342 auth_token_lifetime = 0
Wed Dec 12 17:15:41 2018 us=524348 port_share_host = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=524353 port_share_port = '[UNDEF]'
Wed Dec 12 17:15:41 2018 us=524359 client = ENABLED
Wed Dec 12 17:15:41 2018 us=524365 pull = ENABLED
Wed Dec 12 17:15:41 2018 us=524370 auth_user_pass_file = '/etc/openvpn/SOME_COMPANY.dummypass'
Wed Dec 12 17:15:41 2018 us=524379 OpenVPN 2.5_git [git:master/7aeabadd69fca007+] x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Oct 11 2018
Wed Dec 12 17:15:41 2018 us=524396 library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08
CHALLENGE: PIN Code: 0000
Wed Dec 12 17:15:47 2018 us=103015 PKCS#11: Adding PKCS#11 provider '/usr/lib/x86_64-linux-gnu/libcsemwpkcs11-2.7.1.0.so'
Wed Dec 12 17:15:50 2018 us=234182 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Dec 12 17:15:50 2018 us=234221 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Dec 12 17:15:50 2018 us=234306 Control Channel MTU parms [ L:1621 D:1172 EF:78 EB:0 ET:0 EL:3 ]
Wed Dec 12 17:15:50 2018 us=496637 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Wed Dec 12 17:15:50 2018 us=497092 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1569,tun-mtu 1500,proto UDPv4,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
Wed Dec 12 17:15:50 2018 us=497482 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1569,tun-mtu 1500,proto UDPv4,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
Wed Dec 12 17:15:50 2018 us=498157 TCP/UDP: Preserving recently used remote address: [AF_INET]66.66.666.666:1194
Wed Dec 12 17:15:50 2018 us=498771 Socket Buffers: R=[212992->212992] S=[212992->212992]
Wed Dec 12 17:15:50 2018 us=499172 UDP link local (bound): [AF_INET][undef]:1194
Wed Dec 12 17:15:50 2018 us=499573 UDP link remote: [AF_INET]66.66.666.666:1194
Wed Dec 12 17:15:50 2018 us=542592 TLS: Initial packet from [AF_INET]66.66.666.666:1194, sid=0c35caba 491517aa
Wed Dec 12 17:15:50 2018 us=588898 VERIFY OK: depth=2, CN=TEST Dev CA
Wed Dec 12 17:15:50 2018 us=589448 VERIFY OK: depth=1, CN=TEST Subordinate
Wed Dec 12 17:15:50 2018 us=590420 VERIFY KU OK
Wed Dec 12 17:15:50 2018 us=590544 Validating certificate extended key usage
Wed Dec 12 17:15:50 2018 us=591078 ++ Certificate has EKU (str) 1.3.6.1.4.1.666666.1337.20.1, expects TLS Web Server Authentication
Wed Dec 12 17:15:50 2018 us=591179 ++ Certificate has EKU (oid) 1.3.6.1.4.1.666666.1337.20.1, expects TLS Web Server Authentication
Wed Dec 12 17:15:50 2018 us=591247 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Wed Dec 12 17:15:50 2018 us=592226 VERIFY EKU OK
Wed Dec 12 17:15:50 2018 us=592561 VERIFY OK: depth=0, C=US, ST=CA, L=SOMEWHERE, O=SOME_COMPANY, emailAddress=admin@SOME_COMPANY.com, CN=VPN_SERVER, OU=SOME_GRP
Enter Card #8980B31FE896B0FF token Password:
Enter Card #8980B31FE896B0FF token Password:
Wed Dec 12 17:16:00 2018 us=565633 PKCS#11: Cannot perform signature 257:'CKR_USER_NOT_LOGGED_IN'
Wed Dec 12 17:16:00 2018 us=565697 OpenSSL: error:14099006:SSL routines:ssl3_send_client_verify:EVP lib
Wed Dec 12 17:16:00 2018 us=565703 TLS_ERROR: BIO read tls_read_plaintext error
Wed Dec 12 17:16:00 2018 us=565708 TLS Error: TLS object -> incoming plaintext read error
Wed Dec 12 17:16:00 2018 us=565712 TLS Error: TLS handshake failed
Wed Dec 12 17:16:00 2018 us=565833 TCP/UDP: Closing socket
Wed Dec 12 17:16:00 2018 us=565866 SIGUSR1[soft,tls-error] received, process restarting
Wed Dec 12 17:16:00 2018 us=565880 Restart pause, 5 second(s)
Wed Dec 12 17:16:05 2018 us=566098 Re-using SSL/TLS context
Wed Dec 12 17:16:05 2018 us=566194 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Dec 12 17:16:05 2018 us=566204 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Dec 12 17:16:05 2018 us=566252 Control Channel MTU parms [ L:1621 D:1172 EF:78 EB:0 ET:0 EL:3 ]
Wed Dec 12 17:16:05 2018 us=637418 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Wed Dec 12 17:16:05 2018 us=637462 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1569,tun-mtu 1500,proto UDPv4,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
Wed Dec 12 17:16:05 2018 us=637468 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1569,tun-mtu 1500,proto UDPv4,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
Wed Dec 12 17:16:05 2018 us=637476 TCP/UDP: Preserving recently used remote address: [AF_INET]66.66.666.666:1194
Wed Dec 12 17:16:05 2018 us=637490 Socket Buffers: R=[212992->212992] S=[212992->212992]
Wed Dec 12 17:16:05 2018 us=637497 UDP link local (bound): [AF_INET][undef]:1194
Wed Dec 12 17:16:05 2018 us=637502 UDP link remote: [AF_INET]66.66.666.666:1194
Wed Dec 12 17:16:05 2018 us=671631 TLS: Initial packet from [AF_INET]66.66.666.666:1194, sid=787cadc3 0d253ac4
Wed Dec 12 17:16:05 2018 us=718884 VERIFY OK: depth=2, CN=TEST Dev CA
Wed Dec 12 17:16:05 2018 us=719330 VERIFY OK: depth=1, CN=TEST Subordinate
Wed Dec 12 17:16:05 2018 us=720005 VERIFY KU OK
Wed Dec 12 17:16:05 2018 us=720108 Validating certificate extended key usage
Wed Dec 12 17:16:05 2018 us=720281 ++ Certificate has EKU (str) 1.3.6.1.4.1.666666.1337.20.1, expects TLS Web Server Authentication
Wed Dec 12 17:16:05 2018 us=720471 ++ Certificate has EKU (oid) 1.3.6.1.4.1.666666.1337.20.1, expects TLS Web Server Authentication
Wed Dec 12 17:16:05 2018 us=720811 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Wed Dec 12 17:16:05 2018 us=721088 VERIFY EKU OK
Wed Dec 12 17:16:05 2018 us=721131 VERIFY OK: depth=0, C=US, ST=CA, L=SOMEWHERE, O=SOME_COMPANY, emailAddress=admin@SOME_COMPANY.com, CN=VPN_SERVER, OU=SOME_GRP
Enter Card #8980B31FE896B0FF token Password:
Wed Dec 12 17:16:10 2018 us=197870 PKCS#11: Cannot perform signature 257:'CKR_USER_NOT_LOGGED_IN'
Wed Dec 12 17:16:10 2018 us=197954 OpenSSL: error:14099006:SSL routines:ssl3_send_client_verify:EVP lib
Wed Dec 12 17:16:10 2018 us=197965 TLS_ERROR: BIO read tls_read_plaintext error
Wed Dec 12 17:16:10 2018 us=197974 TLS Error: TLS object -> incoming plaintext read error
Wed Dec 12 17:16:10 2018 us=197982 TLS Error: TLS handshake failed
Wed Dec 12 17:16:10 2018 us=198137 TCP/UDP: Closing socket
Wed Dec 12 17:16:10 2018 us=198190 SIGUSR1[soft,tls-error] received, process restarting
Wed Dec 12 17:16:10 2018 us=198213 Restart pause, 5 second(s)
Wed Dec 12 17:16:15 2018 us=198393 Re-using SSL/TLS context
Wed Dec 12 17:16:15 2018 us=198533 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Dec 12 17:16:15 2018 us=198548 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Dec 12 17:16:15 2018 us=198618 Control Channel MTU parms [ L:1621 D:1172 EF:78 EB:0 ET:0 EL:3 ]
Wed Dec 12 17:16:15 2018 us=204993 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Wed Dec 12 17:16:15 2018 us=205310 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1569,tun-mtu 1500,proto UDPv4,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
Wed Dec 12 17:16:15 2018 us=206403 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1569,tun-mtu 1500,proto UDPv4,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
Wed Dec 12 17:16:15 2018 us=206682 TCP/UDP: Preserving recently used remote address: [AF_INET]66.66.666.666:1194
Wed Dec 12 17:16:15 2018 us=207345 Socket Buffers: R=[212992->212992] S=[212992->212992]
Wed Dec 12 17:16:15 2018 us=207764 UDP link local (bound): [AF_INET][undef]:1194
Wed Dec 12 17:16:15 2018 us=208218 UDP link remote: [AF_INET]66.66.666.666:1194
Wed Dec 12 17:16:15 2018 us=244311 TLS Error: Unroutable control packet received from [AF_INET]66.66.666.666:1194 (si=3 op=P_ACK_V1)
Wed Dec 12 17:16:17 2018 us=344779 TLS Error: Unroutable control packet received from [AF_INET]66.66.666.666:1194 (si=3 op=P_ACK_V1)
Wed Dec 12 17:16:21 2018 us=497218 TLS Error: Unroutable control packet received from [AF_INET]66.66.666.666:1194 (si=3 op=P_ACK_V1)
Wed Dec 12 17:16:23 2018 us=47614 TLS Error: Unroutable control packet received from [AF_INET]66.66.666.666:1194 (si=3 op=P_CONTROL_V1)
Wed Dec 12 17:16:24 2018 us=469595 TLS Error: Unroutable control packet received from [AF_INET]66.66.666.666:1194 (si=3 op=P_CONTROL_V1)
Wed Dec 12 17:16:29 2018 us=934720 TLS Error: Unroutable control packet received from [AF_INET]66.66.666.666:1194 (si=3 op=P_ACK_V1)
Wed Dec 12 17:16:38 2018 us=623824 TLS Error: Unroutable control packet received from [AF_INET]66.66.666.666:1194 (si=3 op=P_CONTROL_V1)
Wed Dec 12 17:16:46 2018 us=161325 TLS Error: Unroutable control packet received from [AF_INET]66.66.666.666:1194 (si=3 op=P_ACK_V1)
Wed Dec 12 17:17:15 2018 us=875462 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Wed Dec 12 17:17:15 2018 us=875498 TLS Error: TLS handshake failed
Wed Dec 12 17:17:15 2018 us=875561 TCP/UDP: Closing socket
Wed Dec 12 17:17:15 2018 us=875588 SIGUSR1[soft,tls-error] received, process restarting
Wed Dec 12 17:17:15 2018 us=875602 Restart pause, 5 second(s)
Wed Dec 12 17:17:20 2018 us=877851 Re-using SSL/TLS context
Wed Dec 12 17:17:20 2018 us=877956 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Dec 12 17:17:20 2018 us=877969 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Dec 12 17:17:20 2018 us=878027 Control Channel MTU parms [ L:1621 D:1172 EF:78 EB:0 ET:0 EL:3 ]
Wed Dec 12 17:17:20 2018 us=935142 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Wed Dec 12 17:17:20 2018 us=935736 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1569,tun-mtu 1500,proto UDPv4,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
Wed Dec 12 17:17:20 2018 us=936006 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1569,tun-mtu 1500,proto UDPv4,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
Wed Dec 12 17:17:20 2018 us=936043 TCP/UDP: Preserving recently used remote address: [AF_INET]66.66.666.666:1194
Wed Dec 12 17:17:20 2018 us=936476 Socket Buffers: R=[212992->212992] S=[212992->212992]
Wed Dec 12 17:17:20 2018 us=936672 UDP link local (bound): [AF_INET][undef]:1194
Wed Dec 12 17:17:20 2018 us=936874 UDP link remote: [AF_INET]66.66.666.666:1194
Wed Dec 12 17:17:20 2018 us=978873 TLS: Initial packet from [AF_INET]66.66.666.666:1194, sid=de3990f4 e08f1fa2
Wed Dec 12 17:17:21 2018 us=28773 VERIFY OK: depth=2, CN=TEST Dev CA
Wed Dec 12 17:17:21 2018 us=29298 VERIFY OK: depth=1, CN=TEST Subordinate
Wed Dec 12 17:17:21 2018 us=29818 VERIFY KU OK
Wed Dec 12 17:17:21 2018 us=30322 Validating certificate extended key usage
Wed Dec 12 17:17:21 2018 us=30527 ++ Certificate has EKU (str) 1.3.6.1.4.1.666666.1337.20.1, expects TLS Web Server Authentication
Wed Dec 12 17:17:21 2018 us=30914 ++ Certificate has EKU (oid) 1.3.6.1.4.1.666666.1337.20.1, expects TLS Web Server Authentication
Wed Dec 12 17:17:21 2018 us=31312 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Wed Dec 12 17:17:21 2018 us=31507 VERIFY EKU OK
Wed Dec 12 17:17:21 2018 us=31977 VERIFY OK: depth=0, C=US, ST=CA, L=SOMEWHERE, O=SOME_COMPANY, emailAddress=admin@SOME_COMPANY.com, CN=VPN_SERVER, OU=SOME_GRP

TinCanTech

client ok .. please include your server details.

like so:
https://forums.openvpn.net/viewtopic.php?f=30&t=22603#p68963

rayv33n

The funny thing is I don't have access to the server end or I would have dump that here. The admin tells me it's a Netgate(pfsense) system. What I can tell you is with the exact same client configuration, swapping out the PKCS11 ID for a Yubikey Nano 4 and using the opensc-pkcs11 provider. This works beautifully. What changes is the provider library is the Gemalto proprietary binary is used rather than the opensc-pkcs11 which, partially supports Nano 4.

I guess what I was hoping for is some guidance on narrowing down the exact component and learning more about how openvpn makes use of PKCS11 on Linux based systems. I suspect openvpn calls libpkcs11-helper1 to help deal with pin/pass authentication to the token and the respond from this Gemalto token is unexpected. The question is, how would I rule this out?

rayv33n

Making changes to the configuration above and playing with the following options.

pkcs11-cert-private 1
pkcs11-private-mode

if pkcs11-private-mode 0 or 1, we get
PKCS#11: Cannot perform signature 257:'CKR_USER_NOT_LOGGED_IN'

if pkcs11-private-mode 2,4,6 or 8, we get
PKCS#11: Cannot perform signature 6:'CKR_FUNCTION_FAILED'

I'm assuming the latter is simply not supported so, I don't know if this is meaningful except to understand functionality completeness. One thing I don't understand is why we initially get the following openvpn challenge prompt.
CHALLENGE: PIN Code: 0000

and then the following prompt every time there after?
Enter Card #8980B31FE896B0FF token Password:

Where are we getting "Enter Card blah---- token Password:" from?