Freezes right after connecting with PKCS11 USB token

oernii

Hi, i just discovered that on newer linux boxes (ubuntu 12.10, fedora 7 -both 64bit) my openVPN freezes and does not connect to the server. When I use a certificate it works, but as soon as I switch to pkcs11, it asks for the PIN and freezes.

This is from the log:

Tue Jan  8 13:34:23 2013 us=455210 PUSH: Received control message: 'PUSH_REPLY,route 200.200.200.0 255.255.255.0,route 10.22.0.0 255.255.255.0,route 192.168.100.0 255.255.255.0,dhcp-option DNS 10.2.9.6,dhcp-option DNS 10.2.9.5,dhcp-option DOMAIN axonpro-local.sk,dhcp-option NTP 200.200.200.254,route 10.9.8.0 255.255.255.0,topology net30,ping 10,ping-restart 120,ifconfig 10.9.8.10 10.9.8.9'
Tue Jan  8 13:34:23 2013 us=455368 OPTIONS IMPORT: timers and/or timeouts modified
Tue Jan  8 13:34:23 2013 us=455389 OPTIONS IMPORT: --ifconfig/up options modified
Tue Jan  8 13:34:23 2013 us=455406 OPTIONS IMPORT: route options modified
Tue Jan  8 13:34:23 2013 us=455422 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Tue Jan  8 13:34:23 2013 us=455619 ROUTE default_gateway=192.168.1.1
Tue Jan  8 13:34:23 2013 us=456025 TUN/TAP device tun0 opened
Tue Jan  8 13:34:23 2013 us=456068 TUN/TAP TX queue length set to 100
Tue Jan  8 13:34:23 2013 us=456116 /sbin/ip link set dev tun0 up mtu 1500

and that is it. It freezes up and only "kill -9" is working. Btw, the usb card token is working properly:

$ pkcs11-tool --module /lib64/opensc-pkcs11.so -s  --input-file digest --output-file signature
Using slot 1 with a present token (0x1)
Logging in to "OpenSC Card (user user)".
Please enter User PIN:
Using signature algorithm RSA-PKCS
$

Here are the last few lines from a full strace:

munmap(0x7f741f0b0000, 4096)            = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
write(1, "Tue Jan  8 13:53:26 2013 us=4103"..., 69Tue Jan  8 13:53:26 2013 us=410331 ROUTE default_gateway=192.168.1.1
) = 69
open("/dev/net/tun", O_RDWR)            = 5
ioctl(5, TUNSETIFF, 0x7fffa57fe230)     = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
write(1, "Tue Jan  8 13:53:26 2013 us=4108"..., 62Tue Jan  8 13:53:26 2013 us=410830 TUN/TAP device tun0 opened
) = 62
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 6
ioctl(6, SIOCSIFTXQLEN, {ifr_name="tun0", ifr_qlen=100}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
write(1, "Tue Jan  8 13:53:26 2013 us=4109"..., 70Tue Jan  8 13:53:26 2013 us=410992 TUN/TAP TX queue length set to 100
) = 70
close(6)                                = 0
fcntl(5, F_SETFL, O_RDONLY|O_NONBLOCK)  = 0
fcntl(5, F_SETFD, FD_CLOEXEC)           = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
write(1, "Tue Jan  8 13:53:26 2013 us=4111"..., 74Tue Jan  8 13:53:26 2013 us=411184 /sbin/ip link set dev tun0 up mtu 1500
) = 74
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f741f07ead0) = 20167
Process 20167 attached
[pid 20160] wait4(20167,  <unfinished ...>
[pid 20167] set_robust_list(0x7f741f07eae0, 24) = 0
[pid 20167] select(4, NULL, [3], NULL, NULL) = 1 (out [3])
[pid 20167] sendto(3, "\10\0\0\0\7\0\0\0", 8, MSG_NOSIGNAL, NULL, 0) = 8
[pid 20167] select(4, NULL, [3], NULL, NULL) = 1 (out [3])
[pid 20167] sendto(3, "\30w\1\0\0\0\0\0", 8, MSG_NOSIGNAL, NULL, 0) = 8
[pid 20167] select(4, [3], NULL, NULL, NULL) = 1 (in [3])
[pid 20167] read(3, "\30w\1\0\0\0\0\0", 8) = 8
[pid 20167] select(4, NULL, [3], NULL, NULL) = 1 (out [3])
[pid 20167] sendto(3, " \0\0\0\t\0\0\0", 8, MSG_NOSIGNAL, NULL, 0) = 8
[pid 20167] select(4, NULL, [3], NULL, NULL) = 1 (out [3])
[pid 20167] sendto(3, "\30w\1\0\2\0\0\0\20\0\0\0\7\0\0\0\2\0\0\0\20\0\0\0\2\1\0\0\0\0\0\0", 32, MSG_NOSIGNAL, NULL, 0) = 32
[pid 20167] select(4, NULL, [3], NULL, NULL) = 1 (out [3])
[pid 20167] sendto(3, "\0\244\0\f\2?\0", 7, MSG_NOSIGNAL, NULL, 0) = 7
[pid 20167] select(4, [3], NULL, NULL, NULL) = 1 (in [3])
[pid 20167] read(3, "\30w\1\0\2\0\0\0\20\0\0\0\7\0\0\0\2\0\0\0\20\0\0\0\2\0\0\0\0\0\0\0", 32) = 32
[pid 20167] select(4, [3], NULL, NULL, NULL) = 1 (in [3])
[pid 20167] read(3, "\220\0", 2)        = 2
[pid 20167] select(4, NULL, [3], NULL, NULL) = 1 (out [3])
[pid 20167] sendto(3, "\f\0\0\0\10\0\0\0", 8, MSG_NOSIGNAL, NULL, 0) = 8
[pid 20167] select(4, NULL, [3], NULL, NULL) = 1 (out [3])
[pid 20167] sendto(3, "\30w\1\0\0\0\0\0\0\0\0\0", 12, MSG_NOSIGNAL, NULL, 0) = 12
[pid 20167] select(4, [3], NULL, NULL, NULL) = 1 (in [3])
[pid 20167] read(3, "\30w\1\0\0\0\0\0\0\0\0\0", 12) = 12
[pid 20167] nanosleep({0, 2096000}, NULL) = 0
[pid 20167] select(4, NULL, [3], NULL, NULL) = 1 (out [3])
[pid 20167] sendto(3, "\f\0\0\0\6\0\0\0", 8, MSG_NOSIGNAL, NULL, 0) = 8
[pid 20167] select(4, NULL, [3], NULL, NULL) = 1 (out [3])
[pid 20167] sendto(3, "\30w\1\0\1\0\0\0\0\0\0\0", 12, MSG_NOSIGNAL, NULL, 0) = 12
[pid 20167] select(4, [3], NULL, NULL, NULL) = 1 (in [3])
[pid 20167] read(3, "\30w\1\0\1\0\0\0\0\0\0\0", 12) = 12
[pid 20167] select(4, NULL, [3], NULL, NULL) = 1 (out [3])
[pid 20167] sendto(3, "\10\0\0\0\2\0\0\0", 8, MSG_NOSIGNAL, NULL, 0) = 8
[pid 20167] select(4, NULL, [3], NULL, NULL) = 1 (out [3])
[pid 20167] sendto(3, "\324T\3\1\0\0\0\0", 8, MSG_NOSIGNAL, NULL, 0) = 8
[pid 20167] select(4, [3], NULL, NULL, NULL) = 1 (in [3])
[pid 20167] read(3, "\324T\3\1\0\0\0\0", 8) = 8
[pid 20167] close(3)                    = 0
[pid 20167] futex(0x7f741e03e070, FUTEX_WAIT_PRIVATE, 1, NULL

and there it stays.

Some additional info (but the same happens on ubuntu 1210):

fedora 17 x86_64:
openct-0.6.20-3.fc17.x86_64
openvpn-2.2.2-7.fc17.x86_64
opensc-0.12.2-4.fc17.x86_64
kernel-3.6.10-2.fc17.x86_64

oernii

no one else uses pkcs11 with ubuntu or fedora ? 🙁(

cs@p-i.de

I've got a similar problem with the following versions:

os: ubuntu 13.04 (amd64)
kernel: 3.10.10-031010-generic
openvpn: 2.2.1, 2.2.2, 2.3.2, git (20130929)
libpkcs11-helper1: 1.09-1build1, 1.10
opensc: 0.13.0-3ubuntu1, git (20130929)
libifd-cyberjack6: 3.99.5final.sp03-1
reader: REINER SCT - cyberJack pinpad(a) (vendor: 0c4b, product: 0300)
smartcard: openpgp V2.0 (OpenPGP card), feitian (entersafe), schlumberger cryptoflex (Schlumberger Multiflex/Cryptoflex)

If i use the .p12-file (generated via easy-rsa) with pkcs12 option in config all went fine. But if i use the pkcs11-options it seems that the forked process did not start correctly or remains in suspended state. Strace says something like that:

...
16012 open("/dev/net/tun", O_RDWR)      = 7
16012 ioctl(7, TUNSETIFF, 0x7fff0fa031c0) = 0
16012 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
16012 write(1, "Tue Oct  1 15:37:27 2013 TUN/TAP"..., 52) = 52
16012 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 8
16012 ioctl(8, SIOCSIFTXQLEN, {ifr_name="tun0", ifr_qlen=100}) = 0
16012 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
16012 write(1, "Tue Oct  1 15:37:27 2013 TUN/TAP"..., 60) = 60
16012 close(8)                          = 0
16012 fcntl(7, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
16012 fcntl(7, F_SETFD, FD_CLOEXEC)     = 0
16012 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
16012 write(1, "Tue Oct  1 15:37:27 2013 do_ifco"..., 80) = 80
16012 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
16012 write(1, "Tue Oct  1 15:37:27 2013 /sbin/i"..., 64) = 64
16012 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f546e45aa10) = 16020
16020 set_robust_list(0x7f546e45aa20, 0x18 <unfinished ...>
16012 wait4(16020,  <unfinished ...>
16020 <... set_robust_list resumed> )   = 0
16020 select(4, NULL, [3], NULL, NULL)  = 1 (out [3])
16020 sendto(3, "\f\0\0\0\6\0\0\0", 8, MSG_NOSIGNAL, NULL, 0) = 8
16020 select(4, NULL, [3], NULL, NULL)  = 1 (out [3])
16020 sendto(3, "\313\3613$\1\0\0\0\0\0\0\0", 12, MSG_NOSIGNAL, NULL, 0) = 12
16020 select(4, [3], NULL, NULL, NULL)  = 1 (in [3])
16020 read(3, "\313\3613$\1\0\0\0\0\0\0\0", 12) = 12
16020 select(4, NULL, [3], NULL, NULL)  = 1 (out [3])
16020 sendto(3, "\10\0\0\0\2\0\0\0", 8, MSG_NOSIGNAL, NULL, 0) = 8
16020 select(4, NULL, [3], NULL, NULL)  = 1 (out [3])
16020 sendto(3, "\35\214[\34\0\0\0\0", 8, MSG_NOSIGNAL, NULL, 0) = 8
16020 select(4, [3], NULL, NULL, NULL)  = 1 (in [3])
16020 read(3, "\35\214[\34\0\0\0\0", 8) = 8
16020 close(3)                          = 0
16020 futex(0x7f546d3ddfb0, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>

That's it! The process is waiting for my kill command. 🙂
The pin entry succeeded and the connection is established, but the local ip configuration did not start.

The following strace output appears while using the pkcs12 config option (btw: the same key file as stored on card):

...
16125 open("/dev/net/tun", O_RDWR)      = 4
16125 ioctl(4, TUNSETIFF, 0x7fffa64d5260) = 0
16125 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
16125 write(1, "Tue Oct  1 15:45:44 2013 TUN/TAP"..., 52) = 52
16125 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 7
16125 ioctl(7, SIOCSIFTXQLEN, {ifr_name="tun0", ifr_qlen=100}) = 0
16125 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
16125 write(1, "Tue Oct  1 15:45:44 2013 TUN/TAP"..., 60) = 60
16125 close(7)                          = 0
16125 fcntl(4, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
16125 fcntl(4, F_SETFD, FD_CLOEXEC)     = 0
16125 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
16125 write(1, "Tue Oct  1 15:45:44 2013 do_ifco"..., 80) = 80
16125 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
16125 write(1, "Tue Oct  1 15:45:44 2013 /sbin/i"..., 64) = 64
16125 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f949d630a10) = 16127
16125 wait4(16127,  <unfinished ...>
16127 set_robust_list(0x7f949d630a20, 0x18) = 0
16127 execve("/sbin/ip", ["/sbin/ip", "link", "set", "dev", "tun0", "up", "mtu", "1500"], [/* 25 vars */]) = 0
16127 brk(0)                            = 0x2068000
16127 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
16127 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6beae2a000
16127 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
16127 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
16127 fstat(3, {st_mode=S_IFREG|0644, st_size=212121, ...}) = 0
16127 mmap(NULL, 212121, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f6beadf6000
16127 close(3)                          = 0
...

execve is executed and worked fine. Why not if i use the key from smartcard via pkcs11 options? I'm not a c-developer but i thought until just now that a forked process is the exact copy of its parent. So why should there be a difference if i use the key from card or via a .p12-file?

Is there a bug in handling the key address spaces for example?
Any ideas?