Bug 1432152

+++ This bug was initially created as a clone of Bug #1135932 +++

Description of problem:

When trying to connect with a VPN, session freezes and waits indefinitely.

Mon Sep  1 10:32:36 2014 DEPRECATED OPTION: --tls-remote, please update your configuration
Mon Sep  1 10:32:36 2014 OpenVPN 2.3.2 x86_64-redhat-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [eurephia] [MH] [IPv6] built on Aug 26 2014
Mon Sep  1 10:32:36 2014 PKCS#11: Adding PKCS#11 provider '/usr/lib/libaetpkss.so'
Mon Sep  1 10:32:38 2014 UDPv4 link local: [undef]
Mon Sep  1 10:32:38 2014 UDPv4 link remote: [AF_INET]XXX.XXX.XXX.XXX:1194
Mon Sep  1 10:32:38 2014 VERIFY OK: depth=2, XXX
Mon Sep  1 10:32:38 2014 VERIFY OK: depth=1, XXX
Mon Sep  1 10:32:38 2014 VERIFY X509NAME OK: XXX
Mon Sep  1 10:32:38 2014 VERIFY OK: depth=0, XXX
[blocks]


Version-Release number of selected component (if applicable):

0:2.3.2-6.fc20

How reproducible:

Upgrade openvpn to 0:2.3.2-6.fc20, try to connect to VPN with pkcs11 hardware token using a .so.

Actual results:

Connection hangs, does not establish VPN

Expected results:

Establishes VPN.

Additional info:

64-bit machine. Workaround is to pin version to 0:2.3.2-4.fc20

--- Additional comment from Emiel Kollof on 2014-09-01 05:08:24 EDT ---

Did some more poking, it seems that systemd is involved somehow.

strace tail:

[pid  7205] sendto(4, "\266\266\0366\0\0\0\0\0\0\0\0", 12, MSG_NOSIGNAL, NULL, 0) = 12
[pid  7205] select(5, [4], NULL, NULL, NULL) = 1 (in [4])
[pid  7205] read(4, "\266\266\0366\0\0\0\0\0\0\0\0", 12) = 12
[pid  7205] nanosleep({0, 3543000}, NULL) = 0
[pid  7205] lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=320, ...}) = 0
[pid  7205] lstat("/sys/fs/cgroup/systemd", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
[pid  7205] pipe([11, 12])              = 0
[pid  7205] nanosleep({1, 0}, NULL)     = 0
[pid  7205] nanosleep({1, 0}, NULL)     = 0
[keeps doing that]

--- Additional comment from Jon Ciesla on 2014-09-09 11:29:43 EDT ---

Indeed, the only change between the two was systemd support.

--- Additional comment from Zbigniew Jędrzejewski-Szmek on 2014-09-09 11:54:18 EDT ---

I think the chances of us (i.e. systemd maintainers) solving this are close to nil. Before reading this bug report I didn't even know you can connect to a hardware token using an .so. Looking the strace, it seems that something is checking whether it is running underneath systemd. But I don't think this check is even implemented by our code. I'd prefer is someone who knows the code in openvpn was looking at this.

--- Additional comment from David Sommerseth on 2014-09-10 03:57:02 EDT ---

(In reply to Emiel Kollof from comment #1)
> Did some more poking, it seems that systemd is involved somehow.
> 
> strace tail:
> 
> [pid  7205] sendto(4, "\266\266\0366\0\0\0\0\0\0\0\0", 12, MSG_NOSIGNAL,
> NULL, 0) = 12
> [pid  7205] select(5, [4], NULL, NULL, NULL) = 1 (in [4])
> [pid  7205] read(4, "\266\266\0366\0\0\0\0\0\0\0\0", 12) = 12
> [pid  7205] nanosleep({0, 3543000}, NULL) = 0
> [pid  7205] lstat("/sys/fs/cgroup", {st_mode=S_IFDIR|0755, st_size=320,
> ...}) = 0
> [pid  7205] lstat("/sys/fs/cgroup/systemd", {st_mode=S_IFDIR|0555,
> st_size=0, ...}) = 0
> [pid  7205] pipe([11, 12])              = 0
> [pid  7205] nanosleep({1, 0}, NULL)     = 0
> [pid  7205] nanosleep({1, 0}, NULL)     = 0
> [keeps doing that]


That instantly looks like a call to check_systemd_running() is going in a loop.  Can you please intercept OpenVPN using gdb and provide a backtrace?  That would help understanding better what is going on.

 [root@host:~]# gdb --pid $PID_OF_OPENVPN
 ...
 ...
 (gdb) bt

--- Additional comment from David Sommerseth on 2014-09-10 04:09:30 EDT ---

(In reply to Jon Ciesla from comment #2)
> Indeed, the only change between the two was systemd support.

This is probably more likely an OpenVPN bug, more than a systemd bug.

This is pure guessing, but I believe something along these lines is happening:

 -> OpenVPN asks pkcs#11 token for an RSA operation (verify, encrypt, decrypt)
 -> token replies with "PIN code?"
 -> OpenVPN calls get_console_input(), which ends up calling 
    check_systemd_running() and get_console_input_systemd()
 -> get_console_input_systemd() executes /usr/bin/systemd-ask-password and 
    reads the user input, which is returned to the token code by 
    get_console_input_systemd()
 -> token rejects what should have been the PIN code.

This last step is the odd thing, because either get_console_input_systemd() returns garbage, or it fails to execute /usr/bin/systemd-ask-password.  Or something completely else, which causes a loop of calling check_systemd_running() seen in comment #1.

It's needed to understand why the token rejects the PIN code.

--- Additional comment from Emiel Kollof on 2014-09-26 04:31:18 EDT ---

I pinned the version of openvpn to 0:2.3.2-4.fc20 but I will try to get a backtrace with the new version for you.

--- Additional comment from Emiel Kollof on 2014-09-26 04:41:59 EDT ---

(gdb) bt
#0  0x00007f59496be79d in nanosleep () from /lib64/libc.so.6
#1  0x00007f59496eec34 in usleep () from /lib64/libc.so.6
#2  0x00007f594a21ab66 in _pkcs1h_threading_mutexLockAll () from /lib64/libpkcs11-helper.so.1
#3  0x00007f59496be822 in fork () from /lib64/libc.so.6
#4  0x00007f594aef08bd in openvpn_popen ()
#5  0x00007f594aef25c4 in get_console_input ()
#6  0x00007f594aeefaed in get_user_pass_cr ()
#7  0x00007f594aefcde8 in _pkcs11_openvpn_pin_prompt ()
#8  0x00007f594a21cb8d in _pkcs11h_session_login () from /lib64/libpkcs11-helper.so.1
#9  0x00007f594a21e1d0 in _pkcs11h_certificate_resetSession () from /lib64/libpkcs11-helper.so.1
#10 0x00007f594a21ec9a in __pkcs11h_certificate_getKeyAttributes () from /lib64/libpkcs11-helper.so.1
#11 0x00007f594a21fc8c in pkcs11h_certificate_signAny () from /lib64/libpkcs11-helper.so.1
#12 0x00007f594a226940 in __pkcs11h_openssl_enc () from /lib64/libpkcs11-helper.so.1
#13 0x00007f5949c894fe in RSA_sign () from /lib64/libcrypto.so.10
#14 0x00007f5949fd158a in ssl3_send_client_verify () from /lib64/libssl.so.10
#15 0x00007f5949fd2087 in ssl3_connect () from /lib64/libssl.so.10
#16 0x00007f5949fd76b0 in ssl3_read_bytes () from /lib64/libssl.so.10
#17 0x00007f5949fd44b4 in ssl3_read_internal () from /lib64/libssl.so.10
#18 0x00007f5949ffa788 in ssl_read () from /lib64/libssl.so.10
#19 0x00007f5949c9e32b in BIO_read () from /lib64/libcrypto.so.10
#20 0x00007f594af2f84b in bio_read ()
#21 0x00007f594af2a8f2 in tls_multi_process ()
#22 0x00007f594aeda215 in check_tls_dowork ()
#23 0x00007f594aedcf7f in pre_select ()
#24 0x00007f594aefeb42 in openvpn_main ()
#25 0x00007f5949623d65 in __libc_start_main () from /lib64/libc.so.6
#26 0x00007f594aed01e1 in _start ()

--- Additional comment from Emiel Kollof on 2014-09-26 04:46:13 EDT ---

Here's my redacted openvpn config, could help debug things:

remote [REDACTED]
tls-remote [REDACTED]
dev tun
port 1194
proto udp
tls-client
nobind
pkcs11-providers '/usr/lib/libaetpkss.so'
#output of: openvpn --show-pkcs11-ids /usr/lib/libaetpkss.so (only works if pcscd is running)
pkcs11-id 'REDACTED'
pull
ca /etc/openvpn/smartcard/ca.pem
key-method 2
comp-lzo
verb 2

--- Additional comment from Emiel Kollof on 2014-09-26 04:48:50 EDT ---

Also confirmed by a colleague which uses a different token (and also a different .so file as pkcs11-provider), so it is probably not the token .so

--- Additional comment from Emiel Kollof on 2014-09-26 04:51:50 EDT ---

Here is a backtrace from 0:2.3.2-4.fc20 where it is asking for a PIN from the token:

(gdb) bt
#0  0x00007f857afa4570 in __read_nocancel () from /lib64/libc.so.6
#1  0x00007f857af35047 in __GI__IO_file_read () from /lib64/libc.so.6
#2  0x00007f857af36090 in __GI__IO_file_underflow () from /lib64/libc.so.6
#3  0x00007f857af2afd5 in getdelim () from /lib64/libc.so.6
#4  0x00007f857afac8f3 in getpass () from /lib64/libc.so.6
#5  0x00007f857c7ae4fa in get_console_input ()
#6  0x00007f857c7abb4d in get_user_pass_cr ()
#7  0x00007f857c7b8dc8 in _pkcs11_openvpn_pin_prompt ()
#8  0x00007f857bad8b8d in _pkcs11h_session_login () from /lib64/libpkcs11-helper.so.1
#9  0x00007f857bada1d0 in _pkcs11h_certificate_resetSession () from /lib64/libpkcs11-helper.so.1
#10 0x00007f857badac9a in __pkcs11h_certificate_getKeyAttributes () from /lib64/libpkcs11-helper.so.1
#11 0x00007f857badbc8c in pkcs11h_certificate_signAny () from /lib64/libpkcs11-helper.so.1
#12 0x00007f857bae2940 in __pkcs11h_openssl_enc () from /lib64/libpkcs11-helper.so.1
#13 0x00007f857b5454fe in RSA_sign () from /lib64/libcrypto.so.10
#14 0x00007f857b88d58a in ssl3_send_client_verify () from /lib64/libssl.so.10
#15 0x00007f857b88e087 in ssl3_connect () from /lib64/libssl.so.10
#16 0x00007f857b8936b0 in ssl3_read_bytes () from /lib64/libssl.so.10
#17 0x00007f857b8904b4 in ssl3_read_internal () from /lib64/libssl.so.10
#18 0x00007f857b8b6788 in ssl_read () from /lib64/libssl.so.10
#19 0x00007f857b55a32b in BIO_read () from /lib64/libcrypto.so.10
#20 0x00007f857c7eb92b in bio_read ()
#21 0x00007f857c7e69d2 in tls_multi_process ()
#22 0x00007f857c7961f5 in check_tls_dowork ()
#23 0x00007f857c798f7f in pre_select ()
#24 0x00007f857c7bab22 in openvpn_main ()
#25 0x00007f857aedfd65 in __libc_start_main () from /lib64/libc.so.6
#26 0x00007f857c78c191 in _start ()

--- Additional comment from David Sommerseth on 2014-09-26 07:15:30 EDT ---

I see these three lines:

#3  0x00007f59496be822 in fork () from /lib64/libc.so.6
#4  0x00007f594aef08bd in openvpn_popen ()
#5  0x00007f594aef25c4 in get_console_input ()

Which indicates that systemd is most likely being queried.  Can you do a ps listing and grab some info about what was forked out from openvpn, the state of the related processes and so on?

It would also help if you could install the needed debuginfo packages, to get even more info about the function arguments.  (debuginfo-install openvpn)

--- Additional comment from Emiel Kollof on 2014-09-26 07:33:55 EDT ---

Trace with args with new version:

#0  0x00007f01c032479d in nanosleep () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f01c0354c34 in usleep (useconds=<optimized out>)
    at ../sysdeps/unix/sysv/linux/usleep.c:32
#2  0x00007f01c0e80b66 in _pkcs1h_threading_mutexLockAll ()
    at pkcs11h-threading.c:306
#3  0x00007f01c0324822 in __libc_fork ()
    at ../nptl/sysdeps/unix/sysv/linux/fork.c:95
#4  0x00007f01c10a83a5 in __fork () at ../nptl/sysdeps/unix/sysv/linux/pt-fork.c:25
#5  0x00007f01c1b568bd in openvpn_popen (a=a@entry=0x7fff47290e60, es=es@entry=0x0)
    at misc.c:365
#6  0x00007f01c1b585c4 in get_console_input_systemd (echo=<optimized out>, 
    capacity=4096, input=0x7fff47291f92 "", 
    prompt=0x7f01c335cb28 "NEED-OK|token-insertion-request|Please insert FOX CARD token:") at console.c:168
#7  get_console_input (
    prompt=0x7f01c335cb28 "NEED-OK|token-insertion-request|Please insert FOX CARD token:", echo=echo@entry=true, input=input@entry=0x7fff47291f92 "", 
    capacity=capacity@entry=4096) at console.c:201
#8  0x00007f01c1b55d0c in get_user_pass_cr (up=up@entry=0x7fff47290f90, 
    auth_file=<optimized out>, auth_file@entry=0x0, 
    prefix=prefix@entry=0x7f01c1ba5797 "token-insertion-request", 
    flags=flags@entry=25, auth_challenge=auth_challenge@entry=0x0) at misc.c:1088
#9  0x00007f01c1b63174 in get_user_pass (flags=25, 
    prefix=0x7f01c1ba5797 "token-insertion-request", auth_file=0x0, 
    up=0x7fff47290f90) at misc.h:272
#10 _pkcs11_openvpn_token_prompt (global_data=<optimized out>, 
    user_data=<optimized out>, token=0x7f01c335c3d0, retry=<optimized out>)
    at pkcs11.c:196
#11 0x00007f01c0e82317 in _pkcs11h_session_reset (
    session=session@entry=0x7f01c335b470, user_data=user_data@entry=0x0, 
    mask_prompt=mask_prompt@entry=3, p_slot=p_slot@entry=0x7fff47293178)
    at pkcs11h-session.c:743
#12 0x00007f01c0e829e5 in _pkcs11h_session_login (session=0x7f01c335b470, 
    is_publicOnly=is_publicOnly@entry=1, readonly=readonly@entry=1, user_data=0x0, 
    mask_prompt=3) at pkcs11h-session.c:969
#13 0x00007f01c0e841d0 in _pkcs11h_certificate_resetSession (
    certificate=certificate@entry=0x7f01c335aa40, public_only=public_only@entry=1, 
    session_mutex_locked=session_mutex_locked@entry=0) at pkcs11h-certificate.c:728
#14 0x00007f01c0e86875 in pkcs11h_certificate_getCertificateBlob (
    certificate=certificate@entry=0x7f01c335aa40, 
    certificate_blob=certificate_blob@entry=0x0, 
    p_certificate_blob_size=p_certificate_blob_size@entry=0x7fff47293730)
    at pkcs11h-certificate.c:2041
#15 0x00007f01c0e8cd04 in pkcs11h_openssl_getX509 (certificate=0x7f01c335aa40)
    at pkcs11h-openssl.c:429
#16 0x00007f01c0e8d273 in pkcs11h_openssl_session_getX509 (
    openssl_session=openssl_session@entry=0x7f01c335b4f0) at pkcs11h-openssl.c:707
#17 0x00007f01c0e8d338 in pkcs11h_openssl_session_getRSA (
    openssl_session=openssl_session@entry=0x7f01c335b4f0) at pkcs11h-openssl.c:618
#18 0x00007f01c1b645b7 in pkcs11_init_tls_session (certificate=0x0, 
    ssl_ctx=ssl_ctx@entry=0x7fff472963f0) at pkcs11_openssl.c:66
#19 0x00007f01c1b63f23 in tls_ctx_use_pkcs11 (ssl_ctx=ssl_ctx@entry=0x7fff472963f0, 
    pkcs11_id_management=<optimized out>, pkcs11_id=<optimized out>) at pkcs11.c:697
#20 0x00007f01c1b8f89c in init_ssl (options=options@entry=0x7fff47295c00, 
    new_ctx=new_ctx@entry=0x7fff472963f0) at ssl.c:481
#21 0x00007f01c1b475fb in do_init_crypto_tls_c1 (c=0x7fff47295c00) at init.c:2073
#22 do_init_crypto_tls (c=c@entry=0x7fff47295c00, flags=3) at init.c:2153
#23 0x00007f01c1b4b0b0 in do_init_crypto (flags=<optimized out>, c=0x7fff47295c00)
    at init.c:2325
#24 init_instance (c=c@entry=0x7fff47295c00, env=env@entry=0x7f01c3338ab8, 
    flags=flags@entry=4) at init.c:3372
#25 0x00007f01c1b4bac0 in init_instance_handle_signals (c=0x7fff47295c00, 
    env=0x7f01c3338ab8, flags=4) at init.c:3233
#26 0x00007f01c1b64b28 in tunnel_point_to_point (c=0x7fff47295c00) at openvpn.c:70
#27 openvpn_main (argc=2, argv=0x7fff47296a98) at openvpn.c:249
#28 0x00007f01c0289d65 in __libc_start_main (main=0x7f01c1b361b0 <main>, argc=2, 
    argv=0x7fff47296a98, init=<optimized out>, fini=<optimized out>, 
    rtld_fini=<optimized out>, stack_end=0x7fff47296a88) at libc-start.c:285
#29 0x00007f01c1b361e1 in _start ()

--- Additional comment from Emiel Kollof on 2014-09-26 07:36:03 EDT ---

Token is inserted. NSS and the like can just read from it with no problems.

--- Additional comment from Emiel Kollof on 2014-09-26 07:47:13 EDT ---

For comparison, a trace of the working version:

#0  0x00007ffa8657c570 in __read_nocancel ()
    at ../sysdeps/unix/syscall-template.S:81
#1  0x00007ffa8650d047 in __GI__IO_file_read (fp=0xb, buf=0x7ffa87d54000, size=4096)
    at fileops.c:1195
#2  0x00007ffa8650e090 in _IO_new_file_underflow (fp=0x7ffa881d51d0)
    at fileops.c:605
#3  0x00007ffa86502fd5 in _IO_getdelim (lineptr=lineptr@entry=0x7ffa86850710 <buf>, 
    n=n@entry=0x7ffa86850700 <bufsize>, delimiter=delimiter@entry=10, 
    fp=fp@entry=0x7ffa881d51d0) at iogetdelim.c:77
#4  0x00007ffa864ff4ad in __getline (lineptr=lineptr@entry=0x7ffa86850710 <buf>, 
    n=n@entry=0x7ffa86850700 <bufsize>, stream=stream@entry=0x7ffa881d51d0)
    at getline.c:32
#5  0x00007ffa865848f3 in getpass (
    prompt=0x7ffa881c7c48 "Enter FOX CARD token Password:") at getpass.c:97
#6  0x00007ffa87d864fa in get_console_input (prompt=<optimized out>, 
    echo=echo@entry=false, input=input@entry=0x7fffcdcda942 "", 
    capacity=capacity@entry=4096) at console.c:226
#7  0x00007ffa87d83b4d in get_user_pass_cr (up=up@entry=0x7fffcdcd9940, 
    auth_file=<optimized out>, auth_file@entry=0x0, 
    prefix=prefix@entry=0x7fffcdcdb950 "FOX CARD token", flags=flags@entry=21, 
    auth_challenge=auth_challenge@entry=0x0) at misc.c:1138
#8  0x00007ffa87d90dc8 in get_user_pass (flags=21, 
    prefix=0x7fffcdcdb950 "FOX CARD token", auth_file=0x0, up=0x7fffcdcd9940)
    at misc.h:272
#9  _pkcs11_openvpn_pin_prompt (global_data=<optimized out>, 
    user_data=<optimized out>, token=<optimized out>, retry=<optimized out>, 
    pin=0x7fffcdcdbdc0 "P\277\315\315\377\177", pin_max=1024) at pkcs11.c:235
#10 0x00007ffa870b0b8d in _pkcs11h_session_login (session=0x7ffa8813f470, 
    is_publicOnly=is_publicOnly@entry=0, readonly=readonly@entry=1, user_data=0x0, 
    mask_prompt=<optimized out>) at pkcs11h-session.c:1023
#11 0x00007ffa870b21d0 in _pkcs11h_certificate_resetSession (
    certificate=certificate@entry=0x7ffa8813ea40, public_only=public_only@entry=0, 
    session_mutex_locked=session_mutex_locked@entry=1) at pkcs11h-certificate.c:728
#12 0x00007ffa870b2c9a in __pkcs11h_certificate_getKeyAttributes (
    certificate=certificate@entry=0x7ffa8813ea40) at pkcs11h-certificate.c:567
#13 0x00007ffa870b3c8c in pkcs11h_certificate_signAny (
    certificate=certificate@entry=0x7ffa8813ea40, mech_type=mech_type@entry=1, 
    source=source@entry=0x7fffcdcdc4d0 "\210\254\303\347WQ;E\232\212\342\026\323\322`+\247\230az\032\337>ۏ\001\232)~\214\312ީD\206\223\372\177", 
    source_size=source_size@entry=36, 
    target=target@entry=0x7ffa881bbe66 "V\376\037\002r&\231h9[\360\335\023|S\367\300e\342n\022\004\065uT\355GA-\220\242\264!\037\255\244\265S\227\356\372\371H83\225\037\314%\346\256l;>b*\333W\177\025\230R'G\030\355.\220c\222\216Nh\"L\371\233\267V=\266\177\356X;\303@\032\227iZ\374\232\226T_'\006", <incomplete sequence \315>, 
    p_target_size=p_target_size@entry=0x7fffcdcdc380) at pkcs11h-certificate.c:1584
#14 0x00007ffa870ba940 in __pkcs11h_openssl_enc (flen=36, 
    from=0x7fffcdcdc4d0 "\210\254\303\347WQ;E\232\212\342\026\323\322`+\247\230az\032\337>ۏ\001\232)~\214\312ީD\206\223\372\177", 
    to=0x7ffa881bbe66 "V\376\037\002r&\231h9[\360\335\023|S\367\300e\342n\022\004\065uT\355GA-\220\242\264!\037\255\244\265S\227\356\372\371H83\225\037\314%\346\256l;>b*\333W\177\025\230R'G\030\355.\220c\222\216Nh\"L\371\233\267V=\266\177\356X;\303@\032\227iZ\374\232\226T_'\006", <incomplete sequence \315>, rsa=0x7ffa8819cae0, padding=1)
    at pkcs11h-openssl.c:327
#15 0x00007ffa86b1d4fe in RSA_sign (type=type@entry=114, 
    m=m@entry=0x7fffcdcdc4d0 "\210\254\303\347WQ;E\232\212\342\026\323\322`+\247\230az\032\337>ۏ\001\232)~\214\312ީD\206\223\372\177", m_len=m_len@entry=36, 
    sigret=sigret@entry=0x7ffa881bbe66 "V\376\037\002r&\231h9[\360\335\023|S\367\300e\342n\022\004\065uT\355GA-\220\242\264!\037\255\244\265S\227\356\372\371H83\225\037\314%\346\256l;>b*\333W\177\025\230R'G\030\355.\220c\222\216Nh\"L\371\233\267V=\266\177\356X;\303@\032\227iZ\374\232\226T_'\006", <incomplete sequence \315>, 
    siglen=siglen@entry=0x7fffcdcdc490, rsa=0x7ffa8819cae0) at rsa_sign.c:142
#16 0x00007ffa86e6558a in ssl3_send_client_verify (s=s@entry=0x7ffa8819ba70)
    at s3_clnt.c:3016
#17 0x00007ffa86e66087 in ssl3_connect (s=0x7ffa8819ba70) at s3_clnt.c:449
#18 0x00007ffa86e6b6b0 in ssl3_read_bytes (s=0x7ffa8819ba70, type=23, 
    buf=0x7ffa881a6b90 "", len=2048, peek=0) at s3_pkt.c:986
#19 0x00007ffa86e684b4 in ssl3_read_internal (s=0x7ffa8819ba70, buf=0x7ffa881a6b90, 
    len=2048, peek=0) at s3_lib.c:4207
#20 0x00007ffa86e8e788 in ssl_read (b=0x7ffa8819bee0, out=0x7ffa881a6b90 "", 
    outl=2048) at bio_ssl.c:168
#21 0x00007ffa86b3232b in BIO_read (b=b@entry=0x7ffa8819bee0, out=0x7ffa881a6b90, 
    outl=2048) at bio_lib.c:212
#22 0x00007ffa87dc392b in bio_read (bio=0x7ffa8819bee0, 
    buf=buf@entry=0x7ffa881a5f60, maxlen=<optimized out>, 
    desc=desc@entry=0x7ffa87de836b "tls_read_plaintext") at ssl_openssl.c:980
#23 0x00007ffa87dc563a in key_state_read_plaintext (
    ks_ssl=ks_ssl@entry=0x7ffa881a5e70, buf=buf@entry=0x7ffa881a5f60, 
    maxlen=maxlen@entry=2048) at ssl_openssl.c:1135
#24 0x00007ffa87dbe9d2 in tls_process (wakeup=<optimized out>, 
    to_link_socket_info=<optimized out>, to_link_addr=0x7fffcdcdc8a8, 
    to_link=<optimized out>, session=0x7ffa881a5d88, multi=<optimized out>)
    at ssl.c:2374
#25 tls_multi_process (multi=<optimized out>, to_link=to_link@entry=0x7fffcdcdd5d0, 
    to_link_addr=to_link_addr@entry=0x7fffcdcdd300, 
    to_link_socket_info=<optimized out>, wakeup=wakeup@entry=0x7fffcdcdc9a4)
    at ssl.c:2598
#26 0x00007ffa87d6e1f5 in check_tls_dowork (c=c@entry=0x7fffcdcdca00)
    at forward.c:98
#27 0x00007ffa87d70f7f in check_tls (c=0x7fffcdcdca00) at forward-inline.h:41
#28 pre_select (c=0x7fffcdcdca00) at forward.c:1321
#29 0x00007ffa87d92b22 in tunnel_point_to_point (c=0x7fffcdcdca00) at openvpn.c:80
#30 openvpn_main (argc=2, argv=0x7fffcdcdd898) at openvpn.c:249
#31 0x00007ffa864b7d65 in __libc_start_main (main=0x7ffa87d64160 <main>, argc=2, 
    argv=0x7fffcdcdd898, init=<optimized out>, fini=<optimized out>, 
    rtld_fini=<optimized out>, stack_end=0x7fffcdcdd888) at libc-start.c:285
#32 0x00007ffa87d64191 in _start ()

--- Additional comment from David Sommerseth on 2014-09-26 08:54:36 EDT ---

What is instantly puzzling me is this difference:

From the failing version:
#6  0x00007f01c1b585c4 in get_console_input_systemd (echo=<optimized out>, 
    capacity=4096, input=0x7fff47291f92 "", 
    prompt=0x7f01c335cb28 "NEED-OK|token-insertion-request|Please insert FOX CARD token:") at console.c:168
#7  get_console_input (
    prompt=0x7f01c335cb28 "NEED-OK|token-insertion-request|Please insert FOX CARD token:", echo=echo@entry=true, input=input@entry=0x7fff47291f92 "", 
    capacity=capacity@entry=4096) at console.c:201

From the working version:
#5  0x00007ffa865848f3 in getpass (
    prompt=0x7ffa881c7c48 "Enter FOX CARD token Password:") at getpass.c:97
#6  0x00007ffa87d864fa in get_console_input (prompt=<optimized out>, 
    echo=echo@entry=false, input=input@entry=0x7fffcdcda942 "", 
    capacity=capacity@entry=4096) at console.c:226


Notice the additional "NEED-OK|token-insertion-request|" string in the failing version.  It's not too easy to fully see everything, as the "prompt" in get_console_input() on the version is <optimized out>.  The get_console_input() function should not mangle the string anyhow.

The NEED-OK part is also something used by the management interface, so it is related to the call chain somewhere.  Or that the PKCS#11 implementation misunderstands the environment.

How do you start OpenVPN?  From the command line (openvpn --config ...) or via systemctl?

--- Additional comment from Emiel Kollof on 2014-09-26 09:15:42 EDT ---

Via the command line. I specify my config as argv[1].

--- Additional comment from Emiel Kollof on 2014-09-26 09:17:09 EDT ---

By the way, this is a smartcard setup. I use a broadcom 5880 reader. Does systemd talk to pcscd to check if a smartcard is inserted?

--- Additional comment from David Sommerseth on 2014-09-26 10:30:13 EDT ---

(In reply to Emiel Kollof from comment #17)
> By the way, this is a smartcard setup. I use a broadcom 5880 reader. Does
> systemd talk to pcscd to check if a smartcard is inserted?

Not directly.  If I've understood the implementation correctly (from earlier days before systemd), it is something like this:

  openvpn
  -> libpkcs11-helper
     + PKCS#11 provider (libaetpkss.so)
     -> pcscd
        -> smartcard

So OpenVPN gets via libpkcs11-helper the message it needs a PIN code to complete the RSA operation.  That is passed on via the PKCS#11 layers to the smartcard which does the sign/encrytpt/verify/decrypt operation in the end - if the PIN was correct.  Otherwise the RSA operation fails.

This implementation should then ask the user via OpenVPN for the PIN code.  However, with systemd involved, OpenVPN passes that task further to the systemd infrastructure.

--- Additional comment from Sven Anders on 2014-10-20 12:33:16 EDT ---

I have the same problem with SafeNet/Aladdin eTokens.
I compiled openvpn myself without systemd support and it worked without problems.
(OpenVPN 2.3.2 + 2.3.4 on Fedora 20).

Has anybody solved this issue yet?
Do you need any more information?

--- Additional comment from David Sommerseth on 2014-10-21 06:12:56 EDT ---

Thanks for testing and reporting.

I have not yet had any possibilities to dig deeper here, due to that I don't have a PKCS#11 token.  But I've recently found SoftHSM [1] which I hope can be useful for testing this.  There will be an OpenVPN hackaton in November where I will participate.  I hope to get several systemd issues ironed out during that mini summit.


[1] https://wiki.opendnssec.org/display/SoftHSMDOCS/

--- Additional comment from Emiel Kollof on 2014-10-28 06:44:43 EDT ---

That is awesome. Please keep us in the loop. :)

--- Additional comment from Sven Anders on 2014-10-28 08:57:35 EDT ---

I tried to start openvpn from the linux (native) console, but it did not change anything. My gdb outputs are the same.

--- Additional comment from Emiel Kollof on 2014-10-29 07:07:50 EDT ---

This might be of interest:

https://community.openvpn.net/openvpn/ticket/274

--- Additional comment from Emiel Kollof on 2014-10-29 07:11:13 EDT ---

I heard from a colleague that unmounting /sys/fs/cgroup/systemd makes it work again, but I don't know what that will break. Apparently people running Ubuntu 14.10 are running into the same issue.

--- Additional comment from Sven Anders on 2014-10-29 09:03:01 EDT ---

Yes unmounting will work, because the check_systemd_running() function fails and the /bin/systemd-ask-password binary is never called.
This may be an workaround, but it will most likely interfere with other systemd functions.

--- Additional comment from David Sommerseth on 2014-10-30 06:12:41 EDT ---

(In reply to Emiel Kollof from comment #24)
> I heard from a colleague that unmounting /sys/fs/cgroup/systemd makes it
> work again, but I don't know what that will break. Apparently people running
> Ubuntu 14.10 are running into the same issue.

That is a really poor workaround.  A slightly better workaround (if your OpenVPN is recent enough) is to rename systemd-tty-ask-password.  The best workaround currently is to recompile OpenVPN without --enable-systemd.  Just compile it from the tar ball and replace /usr/sbin/openvpn with what's found in src/openvpn/openvpn, and it should work just fine.

I'd suggest using these configure settings for a compile:

  ./configure \
    --enable-password-save \
    --enable-iproute2 \
    --with-iproute-path=/sbin/ip \
    --enable-plugins \
    --enable-plugin-down-root \
    --enable-plugin-auth-pam \
    --enable-pkcs11 \
    --enable-x509-alt-username

In the recently released v2.3.5 a patch has also been added where it depends on a systemd library function, sd_booted(), to detect if the system has been booted with systemd or not.  With this patch, the unmount hack will not work.

--- Additional comment from Fedora Admin XMLRPC Client on 2014-11-10 10:51:39 EST ---

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

--- Additional comment from  on 2014-12-30 07:53:46 EST ---

Hi,
I wanted to ask if there are news about this problem: I upgraded to Fedora 21 but the issue is still present in openvpn 2.3.6.1.fc21, and I noticed that with the update released a few days ago also CentOS7 epel package reached the affected openvpn version. 

The workaround of renaming the systemd-ask-password file and launching openvpn using command line works correctly, and I thank you for this solution, that allows me to continue working with my hardware token as before. 
However, I think it would be great if there was also a fix in openvpn systemd support, for example for those who need to start the vpn at boot.

--- Additional comment from Christof Efkemann on 2015-01-21 08:56:38 EST ---

After running into this problem on Fedora 20, I have analysed the problem. Systemd is not the root cause for this problem, but OpenVPN's usage of pkcs11-helper.

If systemd is not running (or support for systemd is not compiled into OpenVPN), OpenVPN determines the PIN by reading the user input directly from the terminal (console.c:230). This works without problem.

However, if systemd is available, instead of reading the PIN directly, OpenVPN tries to run systemd-ask-password (console.c:172). This involves creating a pipe (misc.c:364) and then calling fork (misc.c:365). During the fork call, a fork handler belonging to pkcs11-helper is called (__pkcs11h_threading_atfork_prepare in pkcs11h-core.c:1258). This fork handler tries to lock a number of mutexes (pkcs11h-core.c:1261). However, because this call chain happens in the context of a pkcs11-helper callback function, locking the mutexes (again) fails and leads to an endless sequence of nanosleep calls (pkcs11h-threading.c:306), effectively resulting in a livelock of the OpenVPN process.

This behaviour is actually described in the pkcs11-helper library documentation:
------
pkcs11h_setPINPromptHook
...

Attention
    If pkcs11h_setForkMode() is true, you cannot fork while in hook.
------

--- Additional comment from David Woodhouse on 2015-04-30 10:50:57 EDT ---

https://community.openvpn.net/openvpn/ticket/538

--- Additional comment from David Woodhouse on 2015-05-01 08:59:35 EDT ---

It's not just in the pin callback. I've seen it deadlock in p11-kit-proxy even when it's forking to invoke ifconfig (this is the child):

(gdb) bt
#0  __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1  0x0000003841a0988d in __GI___pthread_mutex_lock (mutex=mutex@entry=0x3860c64840 <p11_library_mutex>) at ../nptl/pthread_mutex_lock.c:80
#2  0x0000003860a1e812 in managed_C_Finalize (self=0x6e0ab0, reserved=<optimized out>) at p11-kit/modules.c:1546
#3  0x0000003860a396e0 in binding_C_Finalize (cif=<optimized out>, ret=0x7fffffffc970, args=<optimized out>, funcs=<optimized out>) at p11-kit/virtual.c:124
#4  0x0000003844205b9f in ffi_closure_unix64_inner (closure=0x7ffff7ff8048, rvalue=0x7fffffffc970, reg_args=0x7fffffffc8c0, argp=0x7fffffffc990 "")
    at ../src/x86/ffi64.c:670
#5  0x0000003844205f18 in ffi_closure_unix64 () at ../src/x86/unix64.S:229
#6  0x0000003860a20ba1 in p11_kit_modules_finalize (modules=<optimized out>) at p11-kit/modules.c:2108
#7  0x0000003860a22132 in proxy_free (py=0x6e4880) at p11-kit/proxy.c:193
#8  0x0000003860a22303 in proxy_C_Initialize (self=0x6e4630, init_args=<optimized out>) at p11-kit/proxy.c:335
#9  0x0000003860a396c0 in binding_C_Initialize (cif=<optimized out>, ret=0x7fffffffcbd0, args=<optimized out>, funcs=<optimized out>) at p11-kit/virtual.c:114
#10 0x0000003844205b9f in ffi_closure_unix64_inner (closure=0x7ffff7ff8550, rvalue=0x7fffffffcbd0, reg_args=0x7fffffffcb20, 
    argp=0x7fffffffcbf0 "\240\314\377\377\377\177") at ../src/x86/ffi64.c:670
#11 0x0000003844205f18 in ffi_closure_unix64 () at ../src/x86/unix64.S:229
#12 0x00007ffff7da5299 in __pkcs11h_forkFixup (activate_slotevent=1) at pkcs11h-core.c:1330
#13 0x00000038412c84ef in __libc_fork () at ../sysdeps/nptl/fork.c:183
#14 0x0000003841a0f4a5 in __fork () at pt-fork.c:25
#15 0x0000000000428438 in openvpn_execve (a=a@entry=0x7fffffffcdb0, es=es@entry=0x776360, flags=flags@entry=2) at misc.c:308
#16 0x0000000000428555 in openvpn_execve_check (a=a@entry=0x7fffffffcdb0, es=es@entry=0x776360, flags=flags@entry=2, 
    error_message=error_message@entry=0x48f04e "Linux ifconfig failed") at misc.c:259
#17 0x000000000046dfdb in do_ifconfig (tt=0x7b9020, actual=0x7a5540 "tun0", tun_mtu=1500, es=0x776360) at tun.c:765
#18 0x000000000041b68b in do_open_tun (c=c@entry=0x7fffffffcef0) at init.c:1449
#19 0x000000000041d5ae in init_instance (c=c@entry=0x7fffffffcef0, env=env@entry=0x6e08f0, flags=flags@entry=4) at init.c:3469
#20 0x000000000041df90 in init_instance_handle_signals (c=0x7fffffffcef0, env=0x6e08f0, flags=4) at init.c:3287
#21 0x0000000000436e18 in tunnel_point_to_point (c=0x7fffffffcef0) at openvpn.c:70
#22 openvpn_main (argc=5, argv=0x7fffffffdd78) at openvpn.c:250
#23 0x0000003841220790 in __libc_start_main (main=0x408780 <main>, argc=5, argv=0x7fffffffdd78, init=<optimized out>, fini=<optimized out>, 
    rtld_fini=<optimized out>, stack_end=0x7fffffffdd68) at libc-start.c:289

--- Additional comment from David Woodhouse on 2015-05-05 18:25:38 EDT ---

The p11-kit-proxy issue I mention in comment 31 is really a p11-kit bug, filed as bug #1217915

In addition, the common OpenSC PKCS#11 provider *also* misbehaves when OpenVPN forks; that's bug #1218797.

Both of those can be worked around in OpenVPN by using vfork() instead of fork() when it's just going to fork-and-exec to spawn something like /sbin/ifconfig. I've filed this ticket for that: https://community.openvpn.net/openvpn/ticket/549

--- Additional comment from Fedora End Of Life on 2015-05-29 08:46:40 EDT ---

This message is a reminder that Fedora 20 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 20. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '20'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 20 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

--- Additional comment from Sven Anders on 2015-05-29 09:37:05 EDT ---

Can the reporter of this bug, please set the version higher?! Thanks...

--- Additional comment from David Woodhouse on 2015-05-29 13:25:02 EDT ---

TBH this is really a pkcs11-helper problem. The way it call C_Initialize() in a pthread_atfork() handler, even though it's recommended (for now) by the non-normative PKCS#11 Usage Guide, is in threaded programs a clear violation of POSIX. And in non-threaded programs it's just a source of interoperability problems.

We should fix pkcs11-helper. And if we can't do that, we should port OpenVPN to use something else.

--- Additional comment from Fedora End Of Life on 2016-07-19 08:05:01 EDT ---

Fedora 22 changed to end-of-life (EOL) status on 2016-07-19. Fedora 22 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.

--- Additional comment from David Woodhouse on 2016-07-21 05:28:24 EDT ---

I think we fixed p11-kit-proxy.so so that it doesn't deadlock when you call C_Initialize() after fork(). And I think I even managed to make progress with removing that daft recommendation from the PKCS#11 specification.

But pkcs11-helper is still doing it, I think. And I think the NSS soft token still doesn't cope. We should port OpenVPN away from pkcs11-helper, really.

But practically speaking, I think this is fixed. Please reopen if not.