reneg-sec problem using sc-hsm token for certificates

egabr2014

Hi,
I'm trying to configure an openvpn client on Linux to use certificates stored on a sc-hsm usb token; everything seemed to work fine, but then I noticed a blocking problem when the reneg-sec period expires.
When the token PIN is inserted for the first time, the initialization of the vpn is successfully completed; however, after the time defined for reneg-sec param (I would normally use 300s, however for tests I set 120s), a new PIN insertion request appears, and inserting again the token PIN doesn't work: error messages about TLS key negotiation failure appear in logs, the key renegotiation reaches it's internal 60 seconds timeout and the PIN request is shown again, and so on until you close the connection.
The VPN hangs while waiting for a new pin insertion, although between two pin requests it seems to work (I suppose because until the key renegotiation succeeds the initial keys are used?).
So, the problem is that for some reason the periodic key negotiations fail.
I made some further tests:
- At some of the repeated PIN requests, I inserted a random string and checked the pin retry counter on the token, and it was unchanged (while it should be decreased by one for every wrong pin); I also launched pcscd in debug mode and noticed that no call is received by pcscd after the first initialization of the vpn connection, so it seems that after initialization the vpn doesn't try to actually interact with pcscd (and the token) anymore.
- I also checked if something else was keeping an exclusive access on opensc-pkcs11.so, blocking the vpn from using it (this happened, for example, when the opensc library was added to the browser, to use the token as a security device), but also when there isn't anything else accessing the library the problem remains.
- Other operations involving the token (I tried generating key pairs, exporting/importing certificates, changing PIN, SO-PIN, using the token in Firefox to store, generate and remove certificates, etc.) work correctly.

Can anyone help me to identify the cause of this problem?

I'll post log files in another message (because of the max character limit for forum messages); the configuration files for both server and client are attached at the end of this message, and the versions of involved softwares are the following:

----
OS 1: CentOS 6.6 (tested only as ovpn sever)

[root@ovpn ~]# openvpn --version
OpenVPN 2.3.2 x86_64-redhat-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [eurephia] [MH] [IPv6] built on Sep 12 2013
Originally developed by James Yonan
Copyright (C) 2002-2010 OpenVPN Technologies, Inc. <sales@openvpn.net>

----
OS 2: CentOS 7 (tested both as ovpn server and client)

[root@centos7 ~]# openvpn --version
OpenVPN 2.3.2 x86_64-redhat-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [eurephia] [MH] [IPv6] built on Feb 14 2014
Originally developed by James Yonan
Copyright (C) 2002-2010 OpenVPN Technologies, Inc. <sales@openvpn.net>


[root@centos7 ~]# opensc-tool -i
OpenSC 0.14.0 [gcc  4.8.2 20140120 (Red Hat 4.8.2-16)]
Enabled features: zlib readline openssl pcsc(libpcsclite.so.1)

[root@centos7 ~]# yum info pkcs11-helper
Loaded plugins: fastestmirror, langpacks
Loading mirror speeds from cached hostfile
 * base: centos.muzzy.it
 * epel: ftp.fau.de
 * extras: centos.muzzy.it
 * updates: centosq4.centos.org
Installed Packages
Name        : pkcs11-helper
Arch        : x86_64
Version     : 1.10
Release     : 1.el7
Size        : 129 k
Repo        : installed
From repo   : epel
Summary     : A library for using PKCS#11 providers


[root@centos7 x86_64]# pcscd -v
pcsc-lite version 1.8.13.
Copyright (C) 1999-2002 by David Corcoran <corcoran@musclecard.com>.
Copyright (C) 2001-2011 by Ludovic Rousseau <ludovic.rousseau@free.fr>.
Copyright (C) 2003-2004 by Damien Sauveron <sauveron@labri.fr>.
Report bugs to <muscle@lists.musclecard.com>.
Enabled features: Linux x86_64-redhat-linux-gnu serial usb libudev usbdropdir=/usr/lib64/pcsc/drivers ipcdir=/var/run/pcscd configdir=/etc/reader.conf.d

----
OS 3: Gentoo (tested only as ovpn client)

# openvpn --version
OpenVPN 2.3.6 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [MH] [IPv6] built on Dec 10 2014
library versions: OpenSSL 1.0.1j 15 Oct 2014, LZO 2.08
Originally developed by James Yonan
Copyright (C) 2002-2010 OpenVPN Technologies, Inc. <sales@openvpn.net>


# opensc-tool -i
OpenSC 0.14.0 [gcc  4.8.3]
Enabled features: zlib readline openssl pcsc(libpcsclite.so.1)

* dev-libs/pkcs11-helper
      Latest version available: 1.11
      Latest version installed: 1.11
      Size of files: 372 KiB
      Homepage:      http://www.opensc-project.org/opensc/wiki/pkcs11-helper
      Description:   PKCS#11 helper library
      License:       || ( BSD GPL-2 )

# pcscd -v
pcsc-lite version 1.8.13.
Copyright (C) 1999-2002 by David Corcoran <corcoran@musclecard.com>.
Copyright (C) 2001-2011 by Ludovic Rousseau <ludovic.rousseau@free.fr>.
Copyright (C) 2003-2004 by Damien Sauveron <sauveron@labri.fr>.
Report bugs to <muscle@lists.musclecard.com>.
Enabled features: Linux x86_64-pc-linux-gnu serial usb libudev usbdropdir=/usr/lib64/readers/usb ipcdir=/run/pcscd configdir=/etc/reader.conf.d
----

Server Configuration:

port 1194
proto udp
dev tun0
ca /etc/openvpn/certs/CA.pem
cert /etc/openvpn/certs/server.pem
key /etc/openvpn/keys/server.key
dh /etc/openvpn/keys/dh2048.pem
server 10.10.10.0 255.255.255.0
push "route 192.168.100.0 255.255.255.0"
push "route 192.168.110.0 255.255.255.0"
push "route 192.168.120.0 255.255.255.0"
keepalive 10 120
user openvpn
group openvpn
persist-key
persist-tun
status /var/run/openvpn/openvpn-udp-status.log
cipher AES-256-CBC
tls-auth /etc/openvpn/keys/ta.key 0
script-security 2
reneg-sec 120
log /var/log/openvpn-udp.log
verb 4

Client Configuration:

dev tun
nobind
script-security 2
resolv-retry infinite
user user
group user
ca /home/user/.openvpn/test/CA.pem
pkcs11-providers '/usr/lib64/opensc-pkcs11.so'
pkcs11-id 'www\x2ECardContact\x2Ede/PKCS\x2315\x20emulated/DECC0100355/SmartCard\x2DHSM\x20\x28UserPIN\x29/C203915DABC47815E14369C96A8A2DEA94669E5B'
tls-client
pull
proto udp
remote 172.31.0.152 1194
port 1194
persist-key
persist-tun
ping-restart 0
auth-retry none
cipher AES-256-CBC
tls-auth /home/user/.openvpn/test/ta.key 1
reneg-sec 120
log /home/user/.openvpn/test/openvpn-client.log
verb 4

Thanks and cheers,
eg

egabr2014

Here's the client log file (verb 4):

Thu Dec 11 10:53:18 2014 us=603762 Current Parameter Settings:
Thu Dec 11 10:53:18 2014 us=603806   config = 'TESTVPN.conf'
Thu Dec 11 10:53:18 2014 us=603813   mode = 0
Thu Dec 11 10:53:18 2014 us=603818   persist_config = DISABLED
Thu Dec 11 10:53:18 2014 us=603823   persist_mode = 1
Thu Dec 11 10:53:18 2014 us=603828   show_ciphers = DISABLED
Thu Dec 11 10:53:18 2014 us=603832   show_digests = DISABLED
Thu Dec 11 10:53:18 2014 us=603836   show_engines = DISABLED
Thu Dec 11 10:53:18 2014 us=603841   genkey = DISABLED
Thu Dec 11 10:53:18 2014 us=603845   key_pass_file = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=603849   show_tls_ciphers = DISABLED
Thu Dec 11 10:53:18 2014 us=603854 Connection profiles [default]:
Thu Dec 11 10:53:18 2014 us=603858   proto = udp
Thu Dec 11 10:53:18 2014 us=603862   local = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=603867   local_port = 0
Thu Dec 11 10:53:18 2014 us=603871   remote = '172.31.0.152'
Thu Dec 11 10:53:18 2014 us=603875   remote_port = 1194
Thu Dec 11 10:53:18 2014 us=603879   remote_float = DISABLED
Thu Dec 11 10:53:18 2014 us=603883   bind_defined = DISABLED
Thu Dec 11 10:53:18 2014 us=603888   bind_local = DISABLED
Thu Dec 11 10:53:18 2014 us=603892   connect_retry_seconds = 5
Thu Dec 11 10:53:18 2014 us=603896   connect_timeout = 10
Thu Dec 11 10:53:18 2014 us=603901   connect_retry_max = 0
Thu Dec 11 10:53:18 2014 us=603905   socks_proxy_server = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=603909   socks_proxy_port = 0
Thu Dec 11 10:53:18 2014 us=603914   socks_proxy_retry = DISABLED
Thu Dec 11 10:53:18 2014 us=603918   tun_mtu = 1500
Thu Dec 11 10:53:18 2014 us=603922   tun_mtu_defined = ENABLED
Thu Dec 11 10:53:18 2014 us=603926   link_mtu = 1500
Thu Dec 11 10:53:18 2014 us=603930   link_mtu_defined = DISABLED
Thu Dec 11 10:53:18 2014 us=603935   tun_mtu_extra = 0
Thu Dec 11 10:53:18 2014 us=603939   tun_mtu_extra_defined = DISABLED
Thu Dec 11 10:53:18 2014 us=603943   mtu_discover_type = -1
Thu Dec 11 10:53:18 2014 us=603947   fragment = 0
Thu Dec 11 10:53:18 2014 us=603952   mssfix = 1450
Thu Dec 11 10:53:18 2014 us=603956   explicit_exit_notification = 0
Thu Dec 11 10:53:18 2014 us=603961 Connection profiles END
Thu Dec 11 10:53:18 2014 us=603965   remote_random = DISABLED
Thu Dec 11 10:53:18 2014 us=603969   ipchange = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=603974   dev = 'tun'
Thu Dec 11 10:53:18 2014 us=603978   dev_type = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=603982   dev_node = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=603986   lladdr = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=603991   topology = 1
Thu Dec 11 10:53:18 2014 us=603995   tun_ipv6 = DISABLED
Thu Dec 11 10:53:18 2014 us=603999   ifconfig_local = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604008   ifconfig_remote_netmask = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604012   ifconfig_noexec = DISABLED
Thu Dec 11 10:53:18 2014 us=604016   ifconfig_nowarn = DISABLED
Thu Dec 11 10:53:18 2014 us=604021   ifconfig_ipv6_local = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604025   ifconfig_ipv6_netbits = 0
Thu Dec 11 10:53:18 2014 us=604029   ifconfig_ipv6_remote = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604033   shaper = 0
Thu Dec 11 10:53:18 2014 us=604037   mtu_test = 0
Thu Dec 11 10:53:18 2014 us=604042   mlock = DISABLED
Thu Dec 11 10:53:18 2014 us=604046   keepalive_ping = 0
Thu Dec 11 10:53:18 2014 us=604050   keepalive_timeout = 0
Thu Dec 11 10:53:18 2014 us=604054   inactivity_timeout = 0
Thu Dec 11 10:53:18 2014 us=604058   ping_send_timeout = 0
Thu Dec 11 10:53:18 2014 us=604062   ping_rec_timeout = 0
Thu Dec 11 10:53:18 2014 us=604066   ping_rec_timeout_action = 2
Thu Dec 11 10:53:18 2014 us=604071   ping_timer_remote = DISABLED
Thu Dec 11 10:53:18 2014 us=604075   remap_sigusr1 = 0
Thu Dec 11 10:53:18 2014 us=604079   persist_tun = ENABLED
Thu Dec 11 10:53:18 2014 us=604084   persist_local_ip = DISABLED
Thu Dec 11 10:53:18 2014 us=604088   persist_remote_ip = DISABLED
Thu Dec 11 10:53:18 2014 us=604092   persist_key = ENABLED
Thu Dec 11 10:53:18 2014 us=604097   passtos = DISABLED
Thu Dec 11 10:53:18 2014 us=604101   resolve_retry_seconds = 1000000000
Thu Dec 11 10:53:18 2014 us=604108   username = 'user'
Thu Dec 11 10:53:18 2014 us=604113   groupname = 'user'
Thu Dec 11 10:53:18 2014 us=604117   chroot_dir = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604121   cd_dir = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604125   writepid = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604130   up_script = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604134   down_script = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604138   down_pre = DISABLED
Thu Dec 11 10:53:18 2014 us=604142   up_restart = DISABLED
Thu Dec 11 10:53:18 2014 us=604146   up_delay = DISABLED
Thu Dec 11 10:53:18 2014 us=604151   daemon = DISABLED
Thu Dec 11 10:53:18 2014 us=604155   inetd = 0
Thu Dec 11 10:53:18 2014 us=604159   log = ENABLED
Thu Dec 11 10:53:18 2014 us=604163   suppress_timestamps = DISABLED
Thu Dec 11 10:53:18 2014 us=604167   nice = 0
Thu Dec 11 10:53:18 2014 us=604171   verbosity = 4
Thu Dec 11 10:53:18 2014 us=604175   mute = 0
Thu Dec 11 10:53:18 2014 us=604180   gremlin = 0
Thu Dec 11 10:53:18 2014 us=604184   status_file = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604188   status_file_version = 1
Thu Dec 11 10:53:18 2014 us=604192   status_file_update_freq = 60
Thu Dec 11 10:53:18 2014 us=604196   occ = ENABLED
Thu Dec 11 10:53:18 2014 us=604200   rcvbuf = 65536
Thu Dec 11 10:53:18 2014 us=604205   sndbuf = 65536
Thu Dec 11 10:53:18 2014 us=604209   mark = 0
Thu Dec 11 10:53:18 2014 us=604213   sockflags = 0
Thu Dec 11 10:53:18 2014 us=604217   fast_io = DISABLED
Thu Dec 11 10:53:18 2014 us=604221   lzo = 0
Thu Dec 11 10:53:18 2014 us=604226   route_script = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604230   route_default_gateway = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604234   route_default_metric = 0
Thu Dec 11 10:53:18 2014 us=604238   route_noexec = DISABLED
Thu Dec 11 10:53:18 2014 us=604243   route_delay = 0
Thu Dec 11 10:53:18 2014 us=604247   route_delay_window = 30
Thu Dec 11 10:53:18 2014 us=604251   route_delay_defined = DISABLED
Thu Dec 11 10:53:18 2014 us=604255   route_nopull = DISABLED
Thu Dec 11 10:53:18 2014 us=604260   route_gateway_via_dhcp = DISABLED
Thu Dec 11 10:53:18 2014 us=604264   max_routes = 100
Thu Dec 11 10:53:18 2014 us=604268   allow_pull_fqdn = DISABLED
Thu Dec 11 10:53:18 2014 us=604272   management_addr = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604277   management_port = 0
Thu Dec 11 10:53:18 2014 us=604281   management_user_pass = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604285   management_log_history_cache = 250
Thu Dec 11 10:53:18 2014 us=604290   management_echo_buffer_size = 100
Thu Dec 11 10:53:18 2014 us=604294   management_write_peer_info_file = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604299   management_client_user = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604303   management_client_group = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604307   management_flags = 0
Thu Dec 11 10:53:18 2014 us=604312   shared_secret_file = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604316   key_direction = 2
Thu Dec 11 10:53:18 2014 us=604320   ciphername_defined = ENABLED
Thu Dec 11 10:53:18 2014 us=604324   ciphername = 'AES-256-CBC'
Thu Dec 11 10:53:18 2014 us=604328   authname_defined = ENABLED
Thu Dec 11 10:53:18 2014 us=604333   authname = 'SHA1'
Thu Dec 11 10:53:18 2014 us=604337   prng_hash = 'SHA1'
Thu Dec 11 10:53:18 2014 us=604341   prng_nonce_secret_len = 16
Thu Dec 11 10:53:18 2014 us=604345   keysize = 0
Thu Dec 11 10:53:18 2014 us=604350   engine = DISABLED
Thu Dec 11 10:53:18 2014 us=604354   replay = ENABLED
Thu Dec 11 10:53:18 2014 us=604358   mute_replay_warnings = DISABLED
Thu Dec 11 10:53:18 2014 us=604362   replay_window = 64
Thu Dec 11 10:53:18 2014 us=604366   replay_time = 15
Thu Dec 11 10:53:18 2014 us=604371   packet_id_file = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604375   use_iv = ENABLED
Thu Dec 11 10:53:18 2014 us=604379   test_crypto = DISABLED
Thu Dec 11 10:53:18 2014 us=604383   tls_server = DISABLED
Thu Dec 11 10:53:18 2014 us=604388   tls_client = ENABLED
Thu Dec 11 10:53:18 2014 us=604392   key_method = 2
Thu Dec 11 10:53:18 2014 us=604396   ca_file = '/home/user/.openvpn/test/CA.pem'
Thu Dec 11 10:53:18 2014 us=604403   ca_path = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604407   dh_file = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604412   cert_file = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604416   priv_key_file = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604420   pkcs12_file = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604424   cipher_list = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604429   tls_verify = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604433   tls_export_cert = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604438   verify_x509_type = 0
Thu Dec 11 10:53:18 2014 us=604442   verify_x509_name = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604446   crl_file = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604450   ns_cert_type = 0
Thu Dec 11 10:53:18 2014 us=604455   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604459   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604464   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604468   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604472   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604476   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604480   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604484   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604489   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604493   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604497   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604501   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604505   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604510   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604514   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604518   remote_cert_ku[i] = 0
Thu Dec 11 10:53:18 2014 us=604522   remote_cert_eku = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604526   ssl_flags = 0
Thu Dec 11 10:53:18 2014 us=604531   tls_timeout = 2
Thu Dec 11 10:53:18 2014 us=604535   renegotiate_bytes = 0
Thu Dec 11 10:53:18 2014 us=604539   renegotiate_packets = 0
Thu Dec 11 10:53:18 2014 us=604543   renegotiate_seconds = 120
Thu Dec 11 10:53:18 2014 us=604548   handshake_window = 60
Thu Dec 11 10:53:18 2014 us=604552   transition_window = 3600
Thu Dec 11 10:53:18 2014 us=604556   single_session = DISABLED
Thu Dec 11 10:53:18 2014 us=604560   push_peer_info = DISABLED
Thu Dec 11 10:53:18 2014 us=604565   tls_exit = DISABLED
Thu Dec 11 10:53:18 2014 us=604569   tls_auth_file = '/home/user/.openvpn/test/ta.key'
Thu Dec 11 10:53:18 2014 us=604574   pkcs11_providers = /usr/lib64/opensc-pkcs11.so
Thu Dec 11 10:53:18 2014 us=604579   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604584   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604588   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604592   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604596   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604601   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604605   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604609   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604613   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604617   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604621   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604626   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604630   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604634   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604638   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604642   pkcs11_protected_authentication = DISABLED
Thu Dec 11 10:53:18 2014 us=604647   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604651   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604655   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604660   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604664   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604670   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604675   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604679   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604684   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604688   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604692   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604697   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604701   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604705   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604709   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604714   pkcs11_private_mode = 00000000
Thu Dec 11 10:53:18 2014 us=604718   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604722   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604726   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604731   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604735   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604739   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604743   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604747   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604751   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604755   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604760   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604764   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604768   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604772   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604776   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604781   pkcs11_cert_private = DISABLED
Thu Dec 11 10:53:18 2014 us=604785   pkcs11_pin_cache_period = -1
Thu Dec 11 10:53:18 2014 us=604789   pkcs11_id = 'www\x2ECardContact\x2Ede/PKCS\x2315\x20emulated/DECC0100355/SmartCard\x2DHSM\x20\x28UserPIN\x29/C203915DABC47815E14369C96A8A2DEA94669E5B'
Thu Dec 11 10:53:18 2014 us=604794   pkcs11_id_management = DISABLED
Thu Dec 11 10:53:18 2014 us=604801   server_network = 0.0.0.0
Thu Dec 11 10:53:18 2014 us=604806   server_netmask = 0.0.0.0
Thu Dec 11 10:53:18 2014 us=604814   server_network_ipv6 = ::
Thu Dec 11 10:53:18 2014 us=604819   server_netbits_ipv6 = 0
Thu Dec 11 10:53:18 2014 us=604823   server_bridge_ip = 0.0.0.0
Thu Dec 11 10:53:18 2014 us=604828   server_bridge_netmask = 0.0.0.0
Thu Dec 11 10:53:18 2014 us=604833   server_bridge_pool_start = 0.0.0.0
Thu Dec 11 10:53:18 2014 us=604838   server_bridge_pool_end = 0.0.0.0
Thu Dec 11 10:53:18 2014 us=604842   ifconfig_pool_defined = DISABLED
Thu Dec 11 10:53:18 2014 us=604847   ifconfig_pool_start = 0.0.0.0
Thu Dec 11 10:53:18 2014 us=604852   ifconfig_pool_end = 0.0.0.0
Thu Dec 11 10:53:18 2014 us=604856   ifconfig_pool_netmask = 0.0.0.0
Thu Dec 11 10:53:18 2014 us=604861   ifconfig_pool_persist_filename = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604865   ifconfig_pool_persist_refresh_freq = 600
Thu Dec 11 10:53:18 2014 us=604870   ifconfig_ipv6_pool_defined = DISABLED
Thu Dec 11 10:53:18 2014 us=604874   ifconfig_ipv6_pool_base = ::
Thu Dec 11 10:53:18 2014 us=604879   ifconfig_ipv6_pool_netbits = 0
Thu Dec 11 10:53:18 2014 us=604883   n_bcast_buf = 256
Thu Dec 11 10:53:18 2014 us=604887   tcp_queue_limit = 64
Thu Dec 11 10:53:18 2014 us=604892   real_hash_size = 256
Thu Dec 11 10:53:18 2014 us=604896   virtual_hash_size = 256
Thu Dec 11 10:53:18 2014 us=604900   client_connect_script = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604905   learn_address_script = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604909   client_disconnect_script = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604913   client_config_dir = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604917   ccd_exclusive = DISABLED
Thu Dec 11 10:53:18 2014 us=604922   tmp_dir = '/tmp'
Thu Dec 11 10:53:18 2014 us=604926   push_ifconfig_defined = DISABLED
Thu Dec 11 10:53:18 2014 us=604931   push_ifconfig_local = 0.0.0.0
Thu Dec 11 10:53:18 2014 us=604938   push_ifconfig_remote_netmask = 0.0.0.0
Thu Dec 11 10:53:18 2014 us=604942   push_ifconfig_ipv6_defined = DISABLED
Thu Dec 11 10:53:18 2014 us=604947   push_ifconfig_ipv6_local = ::/0
Thu Dec 11 10:53:18 2014 us=604952   push_ifconfig_ipv6_remote = ::
Thu Dec 11 10:53:18 2014 us=604956   enable_c2c = DISABLED
Thu Dec 11 10:53:18 2014 us=604961   duplicate_cn = DISABLED
Thu Dec 11 10:53:18 2014 us=604965   cf_max = 0
Thu Dec 11 10:53:18 2014 us=604969   cf_per = 0
Thu Dec 11 10:53:18 2014 us=604974   max_clients = 1024
Thu Dec 11 10:53:18 2014 us=604978   max_routes_per_client = 256
Thu Dec 11 10:53:18 2014 us=604983   auth_user_pass_verify_script = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604987   auth_user_pass_verify_script_via_file = DISABLED
Thu Dec 11 10:53:18 2014 us=604991   port_share_host = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=604996   port_share_port = 0
Thu Dec 11 10:53:18 2014 us=605004   client = DISABLED
Thu Dec 11 10:53:18 2014 us=605012   pull = ENABLED
Thu Dec 11 10:53:18 2014 us=605019   auth_user_pass_file = '[UNDEF]'
Thu Dec 11 10:53:18 2014 us=605024 OpenVPN 2.3.6 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [MH] [IPv6] built on Dec 10 2014
Thu Dec 11 10:53:18 2014 us=605033 library versions: OpenSSL 1.0.1j 15 Oct 2014, LZO 2.08
Thu Dec 11 10:53:18 2014 us=605087 PKCS#11: Adding PKCS#11 provider '/usr/lib64/opensc-pkcs11.so'
Thu Dec 11 10:53:18 2014 us=610688 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Thu Dec 11 10:53:19 2014 us=548913 Control Channel Authentication: using '/home/user/.openvpn/test/ta.key' as a OpenVPN static key file
Thu Dec 11 10:53:19 2014 us=548938 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu Dec 11 10:53:19 2014 us=548945 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu Dec 11 10:53:19 2014 us=548995 Control Channel MTU parms [ L:1557 D:166 EF:66 EB:0 ET:0 EL:0 ]
Thu Dec 11 10:53:19 2014 us=549018 Socket Buffers: R=[212992->131072] S=[212992->131072]
Thu Dec 11 10:53:19 2014 us=549034 Data Channel MTU parms [ L:1557 D:1450 EF:57 EB:4 ET:0 EL:0 ]
Thu Dec 11 10:53:19 2014 us=549047 Local Options String: 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,keydir 1,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-client'
Thu Dec 11 10:53:19 2014 us=549052 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,keydir 0,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-server'
Thu Dec 11 10:53:19 2014 us=549065 Local Options hash (VER=V4): 'ed844052'
Thu Dec 11 10:53:19 2014 us=549073 Expected Remote Options hash (VER=V4): '8a244582'
Thu Dec 11 10:53:19 2014 us=549289 NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay
Thu Dec 11 10:53:19 2014 us=549299 UDPv4 link local: [undef]
Thu Dec 11 10:53:19 2014 us=549307 UDPv4 link remote: [AF_INET]172.31.0.152:1194
Thu Dec 11 10:53:19 2014 us=552485 TLS: Initial packet from [AF_INET]172.31.0.152:1194, sid=47b811a0 0079b9da
Thu Dec 11 10:53:19 2014 us=581727 VERIFY OK: depth=1, CN=ManagementCA, O=EJBCA Sample, C=SE
Thu Dec 11 10:53:19 2014 us=581864 VERIFY OK: depth=0, CN=server
Thu Dec 11 10:53:26 2014 us=452273 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Thu Dec 11 10:53:26 2014 us=452301 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu Dec 11 10:53:26 2014 us=452308 Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Thu Dec 11 10:53:26 2014 us=452313 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu Dec 11 10:53:26 2014 us=452337 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Thu Dec 11 10:53:26 2014 us=452353 [server] Peer Connection Initiated with [AF_INET]172.31.0.152:1194
Thu Dec 11 10:53:28 2014 us=700703 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Thu Dec 11 10:53:28 2014 us=702281 PUSH: Received control message: 'PUSH_REPLY,route 192.168.100.0 255.255.255.0,route 192.168.110.0 255.255.255.0,route 192.168.120.0 255.255.255.0,route 10.10.10.1,topology net30,ping 10,ping-restart 120,ifconfig 10.10.10.6 10.10.10.5'
Thu Dec 11 10:53:28 2014 us=702336 OPTIONS IMPORT: timers and/or timeouts modified
Thu Dec 11 10:53:28 2014 us=702344 OPTIONS IMPORT: --ifconfig/up options modified
Thu Dec 11 10:53:28 2014 us=702348 OPTIONS IMPORT: route options modified
Thu Dec 11 10:53:28 2014 us=702439 ROUTE_GATEWAY 172.31.0.254/255.255.255.0 IFACE=eno1 HWADDR=2c:41:38:a4:46:ec
Thu Dec 11 10:53:28 2014 us=725477 TUN/TAP device tun0 opened
Thu Dec 11 10:53:28 2014 us=725506 TUN/TAP TX queue length set to 100
Thu Dec 11 10:53:28 2014 us=725522 do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0
Thu Dec 11 10:53:28 2014 us=725547 /bin/ifconfig tun0 10.10.10.6 pointopoint 10.10.10.5 mtu 1500
Thu Dec 11 10:53:29 2014 us=7137 /bin/route add -net 192.168.100.0 netmask 255.255.255.0 gw 10.10.10.5
Thu Dec 11 10:53:29 2014 us=221016 /bin/route add -net 192.168.110.0 netmask 255.255.255.0 gw 10.10.10.5
Thu Dec 11 10:53:29 2014 us=227103 /bin/route add -net 192.168.120.0 netmask 255.255.255.0 gw 10.10.10.5
Thu Dec 11 10:53:29 2014 us=332560 /bin/route add -net 10.10.10.1 netmask 255.255.255.255 gw 10.10.10.5
Thu Dec 11 10:53:30 2014 us=239090 GID set to user
Thu Dec 11 10:53:30 2014 us=239122 UID set to user
Thu Dec 11 10:53:30 2014 us=239129 Initialization Sequence Completed
Thu Dec 11 10:55:26 2014 us=125176 TLS: soft reset sec=0 bytes=1507/0 pkts=22/0
Thu Dec 11 10:55:26 2014 us=151133 VERIFY OK: depth=1, CN=ManagementCA, O=EJBCA Sample, C=SE
Thu Dec 11 10:55:26 2014 us=151247 VERIFY OK: depth=0, CN=server
Thu Dec 11 10:55:31 2014 us=664581 PKCS#11: Cannot perform signature 5:'CKR_GENERAL_ERROR'
Thu Dec 11 10:55:31 2014 us=664631 TLS_ERROR: BIO read tls_read_plaintext error: error:14099004:SSL routines:SSL3_SEND_CLIENT_VERIFY:RSA lib
Thu Dec 11 10:55:31 2014 us=664642 TLS Error: TLS object -> incoming plaintext read error
Thu Dec 11 10:55:31 2014 us=664648 TLS Error: TLS handshake failed
Thu Dec 11 10:55:31 2014 us=664654 TLS: move_session: dest=TM_LAME_DUCK src=TM_ACTIVE reinit_src=1
Thu Dec 11 10:55:31 2014 us=664698 TLS ERROR: received control packet with stale session-id=47b811a0 0079b9da
Thu Dec 11 10:55:34 2014 us=408425 TLS ERROR: received control packet with stale session-id=47b811a0 0079b9da
Thu Dec 11 10:55:41 2014 us=560690 TLS: Initial packet from [AF_INET]172.31.0.152:1194, sid=f6f626f1 9a578043
Thu Dec 11 10:55:41 2014 us=586794 VERIFY OK: depth=1, CN=ManagementCA, O=EJBCA Sample, C=SE
Thu Dec 11 10:55:41 2014 us=586914 VERIFY OK: depth=0, CN=server
Thu Dec 11 10:55:45 2014 us=496691 PKCS#11: Cannot perform signature 5:'CKR_GENERAL_ERROR'
Thu Dec 11 10:55:45 2014 us=496740 TLS_ERROR: BIO read tls_read_plaintext error: error:14099004:SSL routines:SSL3_SEND_CLIENT_VERIFY:RSA lib
Thu Dec 11 10:55:45 2014 us=496749 TLS Error: TLS object -> incoming plaintext read error
Thu Dec 11 10:55:45 2014 us=496755 TLS Error: TLS handshake failed
Thu Dec 11 10:55:45 2014 us=496850 TLS ERROR: received control packet with stale session-id=47b811a0 0079b9da
Thu Dec 11 10:55:45 2014 us=753965 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:55:49 2014 us=806350 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:55:56 2014 us=818816 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:55:57 2014 us=822361 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:55:58 2014 us=825834 TLS ERROR: received control packet with stale session-id=47b811a0 0079b9da
Thu Dec 11 10:55:58 2014 us=826145 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:56:02 2014 us=20840 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:56:10 2014 us=285664 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:56:13 2014 us=403406 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:56:26 2014 us=612984 TLS: Initial packet from [AF_INET]172.31.0.152:1194, sid=13e98b85 911425f3
Thu Dec 11 10:56:26 2014 us=613209 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:56:28 2014 us=661310 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:56:56 2014 us=97809 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Thu Dec 11 10:56:56 2014 us=97843 TLS Error: TLS handshake failed
Thu Dec 11 10:57:11 2014 us=757444 TLS: Initial packet from [AF_INET]172.31.0.152:1194, sid=13e98b85 911425f3
Thu Dec 11 10:57:11 2014 us=782976 VERIFY OK: depth=1, CN=ManagementCA, O=EJBCA Sample, C=SE
Thu Dec 11 10:57:11 2014 us=783121 VERIFY OK: depth=0, CN=server
Thu Dec 11 10:57:15 2014 us=855902 PKCS#11: Cannot perform signature 5:'CKR_GENERAL_ERROR'
Thu Dec 11 10:57:15 2014 us=855944 TLS_ERROR: BIO read tls_read_plaintext error: error:14099004:SSL routines:SSL3_SEND_CLIENT_VERIFY:RSA lib
Thu Dec 11 10:57:15 2014 us=855951 TLS Error: TLS object -> incoming plaintext read error
Thu Dec 11 10:57:15 2014 us=855957 TLS Error: TLS handshake failed
Thu Dec 11 10:57:15 2014 us=856033 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:57:19 2014 us=916073 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:57:26 2014 us=403227 TLS: Initial packet from [AF_INET]172.31.0.152:1194, sid=05ff4947 9944c39e
Thu Dec 11 10:57:26 2014 us=428458 VERIFY OK: depth=1, CN=ManagementCA, O=EJBCA Sample, C=SE
Thu Dec 11 10:57:26 2014 us=428573 VERIFY OK: depth=0, CN=server
Thu Dec 11 10:57:30 2014 us=71811 PKCS#11: Cannot perform signature 5:'CKR_GENERAL_ERROR'
Thu Dec 11 10:57:30 2014 us=71862 TLS_ERROR: BIO read tls_read_plaintext error: error:14099004:SSL routines:SSL3_SEND_CLIENT_VERIFY:RSA lib
Thu Dec 11 10:57:30 2014 us=71875 TLS Error: TLS object -> incoming plaintext read error
Thu Dec 11 10:57:30 2014 us=71882 TLS Error: TLS handshake failed
Thu Dec 11 10:57:30 2014 us=544087 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:57:34 2014 us=603468 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:57:41 2014 us=998300 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:57:41 2014 us=998339 TLS: Initial packet from [AF_INET]172.31.0.152:1194, sid=9527763f 86cffc34
Thu Dec 11 10:57:42 2014 us=23735 VERIFY OK: depth=1, CN=ManagementCA, O=EJBCA Sample, C=SE
Thu Dec 11 10:57:42 2014 us=23861 VERIFY OK: depth=0, CN=server
Thu Dec 11 10:57:50 2014 us=215635 PKCS#11: Cannot perform signature 5:'CKR_GENERAL_ERROR'
Thu Dec 11 10:57:50 2014 us=215682 TLS_ERROR: BIO read tls_read_plaintext error: error:14099004:SSL routines:SSL3_SEND_CLIENT_VERIFY:RSA lib
Thu Dec 11 10:57:50 2014 us=215696 TLS Error: TLS object -> incoming plaintext read error
Thu Dec 11 10:57:50 2014 us=215705 TLS Error: TLS handshake failed
Thu Dec 11 10:57:50 2014 us=215789 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:57:50 2014 us=520354 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:57:57 2014 us=729378 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:57:58 2014 us=793011 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:57:58 2014 us=793070 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:57:59 2014 us=816578 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:58:04 2014 us=12313 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:58:12 2014 us=359226 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:58:14 2014 us=515925 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:58:28 2014 us=908800 TLS: Initial packet from [AF_INET]172.31.0.152:1194, sid=9b7eb45f dc675043
Thu Dec 11 10:58:28 2014 us=908932 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:58:30 2014 us=926418 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:58:35 2014 us=12060 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:58:43 2014 us=178413 VERIFY OK: depth=1, CN=ManagementCA, O=EJBCA Sample, C=SE
Thu Dec 11 10:58:43 2014 us=178541 VERIFY OK: depth=0, CN=server
Thu Dec 11 10:58:54 2014 us=71305 PKCS#11: Cannot perform signature 5:'CKR_GENERAL_ERROR'
Thu Dec 11 10:58:54 2014 us=71350 TLS_ERROR: BIO read tls_read_plaintext error: error:14099004:SSL routines:SSL3_SEND_CLIENT_VERIFY:RSA lib
Thu Dec 11 10:58:54 2014 us=71358 TLS Error: TLS object -> incoming plaintext read error
Thu Dec 11 10:58:54 2014 us=71364 TLS Error: TLS handshake failed
Thu Dec 11 10:58:54 2014 us=71439 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:58:54 2014 us=71478 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:58:58 2014 us=110353 TLS: Initial packet from [AF_INET]172.31.0.152:1194, sid=d89ff82e eb168c3f
Thu Dec 11 10:58:58 2014 us=135842 VERIFY OK: depth=1, CN=ManagementCA, O=EJBCA Sample, C=SE
Thu Dec 11 10:58:58 2014 us=135955 VERIFY OK: depth=0, CN=server
Thu Dec 11 10:59:03 2014 us=815055 PKCS#11: Cannot perform signature 5:'CKR_GENERAL_ERROR'
Thu Dec 11 10:59:03 2014 us=815098 TLS_ERROR: BIO read tls_read_plaintext error: error:14099004:SSL routines:SSL3_SEND_CLIENT_VERIFY:RSA lib
Thu Dec 11 10:59:03 2014 us=815106 TLS Error: TLS object -> incoming plaintext read error
Thu Dec 11 10:59:03 2014 us=815111 TLS Error: TLS handshake failed
Thu Dec 11 10:59:03 2014 us=815186 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:59:03 2014 us=815200 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:59:06 2014 us=429553 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:59:13 2014 us=771858 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:59:14 2014 us=797290 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:59:15 2014 us=822544 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:59:15 2014 us=822863 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:59:20 2014 us=34773 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:59:28 2014 us=175965 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:59:28 2014 us=176015 TLS: Initial packet from [AF_INET]172.31.0.152:1194, sid=fe38f959 54467abe
Thu Dec 11 10:59:30 2014 us=208803 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_CONTROL_V1)
Thu Dec 11 10:59:34 2014 us=243434 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:59:42 2014 us=487990 TLS Error: Unroutable control packet received from [AF_INET]172.31.0.152:1194 (si=3 op=P_ACK_V1)
Thu Dec 11 10:59:59 2014 us=30687 VERIFY OK: depth=1, CN=ManagementCA, O=EJBCA Sample, C=SE
Thu Dec 11 10:59:59 2014 us=30819 VERIFY OK: depth=0, CN=server
Thu Dec 11 11:00:01 2014 us=542741 PKCS#11: Cannot perform signature 1:'CKR_CANCEL'
Thu Dec 11 11:00:01 2014 us=542785 TLS_ERROR: BIO read tls_read_plaintext error: error:14099004:SSL routines:SSL3_SEND_CLIENT_VERIFY:RSA lib
Thu Dec 11 11:00:01 2014 us=542797 TLS Error: TLS object -> incoming plaintext read error
Thu Dec 11 11:00:01 2014 us=542806 TLS Error: TLS handshake failed
Thu Dec 11 11:00:01 2014 us=889912 event_wait : Interrupted system call (code=4)
Thu Dec 11 11:00:01 2014 us=890087 TCP/UDP: Closing socket
Thu Dec 11 11:00:01 2014 us=890123 /bin/route del -net 10.10.10.1 netmask 255.255.255.255
SIOCDELRT: Operation not permitted
Thu Dec 11 11:00:01 2014 us=896332 ERROR: Linux route delete command failed: external program exited with error status: 7
Thu Dec 11 11:00:01 2014 us=896360 /bin/route del -net 192.168.120.0 netmask 255.255.255.0
SIOCDELRT: Operation not permitted
Thu Dec 11 11:00:02 2014 us=2440 ERROR: Linux route delete command failed: external program exited with error status: 7
Thu Dec 11 11:00:02 2014 us=2475 /bin/route del -net 192.168.110.0 netmask 255.255.255.0
SIOCDELRT: Operation not permitted
Thu Dec 11 11:00:02 2014 us=509213 ERROR: Linux route delete command failed: external program exited with error status: 7
Thu Dec 11 11:00:02 2014 us=509245 /bin/route del -net 192.168.100.0 netmask 255.255.255.0
SIOCDELRT: Operation not permitted
Thu Dec 11 11:00:02 2014 us=916395 ERROR: Linux route delete command failed: external program exited with error status: 7
Thu Dec 11 11:00:02 2014 us=916422 Closing TUN/TAP interface
Thu Dec 11 11:00:02 2014 us=916435 /bin/ifconfig tun0 0.0.0.0
SIOCSIFADDR: Operation not permitted
SIOCSIFFLAGS: Operation not permitted
Thu Dec 11 11:00:03 2014 us=123678 Linux ip addr del failed: external program exited with error status: 255
Thu Dec 11 11:00:03 2014 us=129101 SIGINT[hard,] received, process exiting