Using openct-ifd.so in pcsc-lite

Hello,

I am trying to use openct-ifd.so (implements the PC/SC API) with PCSC-Lite
(provides the PC/SC daemon pcscd) to access Rainbow iKey 3000 tokens. I works
well in most but not all cases.

Basically I am using PCSC-Lite 1.2.9-beta7, with the following arguments:

  $ pcscd -f -c ~/reader.conf

(To run it in the foreground and to display error messages on stderr.) The
content of my reader.conf is:

FRIENDLYNAME     "my_reader"
DEVICENAME       /dev/null
LIBPATH          /path/to/openct-ifd.so
CHANNELID        0x0

I am using OpenCT 0.6.2. It works well if, for example, the pcscd daemon is
started while a token is already plugged into a USB port (I mean at least
the card ATR is displayed by pcscd):

  Card ATR: 3B B7 94 00 81 31 FE 65 53 50 4B 32 33 90 00 D1 

If I unplug the token, pcscd correctly detects that it has been removed:

  eventhandler.c:345:EHStatusHandlerThread() Card Removed From my_reader 00 00

But if at this point I replug it, pcscd shows me this error message:

  eventhandler.c:413:EHStatusHandlerThread() Card inserted into my_reader 00 00
  eventhandler.c:427:EHStatusHandlerThread() Error powering up card.

I have tracked down the issue with gdb. The problem appears that
IFDHPowerICC() (from openct-ifd.so) returns 612
(IFD_COMMUNICATION_ERROR) to pcscd. Indeed, after recompiling
openct-ifd.so with the macro DEBUG_IFDH defined, we can see this
in syslog messages:

  Mar 29 15:41:46 localhost pcscd: IFDH: IFDHPowerICC (Lun=0x0,
+Action=0x1F4)=612

I have been able to find that IFDHPowerICC() fails because an internal
function, ct_socket_flsbuf(), when writing to a UNIX socket, receives
a SIGPIPE. The precise location of the write() call that triggers this
SIGPIPE is here:

openct-0.6.2/src/ct/socket.c: line 599:

        do {
                if (!(n = ct_buf_avail(bp))) {
                        sock->events = POLLIN;
                        break;
                }
599:            n = write(sock->fd, ct_buf_head(bp), n);
                if (n < 0) {
                        if (errno != EPIPE)
                                ct_error("socket send error: %m");
                        rc = IFD_ERROR_NOT_CONNECTED;
                        break;
                }
                /* Advance head pointer */
                ct_buf_get(bp, NULL, n);
        } while (all);

Here is a gdb backtrace generated at the time of the SIGPIPE:

(gdb) bt
#0  0xb7fd55d1 in __write_nocancel () from /lib/tls/libpthread.so.0
#1  0xb7e51120 in ct_socket_flsbuf ()
   from /root/openct-0.6.2/src/ct/.libs/libopenct.so.0
#2  0xb7e50a45 in ct_socket_call ()
   from /root/openct-0.6.2/src/ct/.libs/libopenct.so.0
#3  0xb7e4ecac in ct_card_request ()
   from /root/openct-0.6.2/src/ct/.libs/libopenct.so.0
#4  0xb7e4ebbf in ct_card_reset ()
   from /root/openct-0.6.2/src/ct/.libs/libopenct.so.0
#5  0xb7e5516c in ctapi_reset ()
   from /root/openct-0.6.2/src/ctapi/.libs/libopenctapi.so
#6  0xb7e5547b in ctapi_request_icc ()
   from /root/openct-0.6.2/src/ctapi/.libs/libopenctapi.so
#7  0xb7e5573b in ctapi_control ()
   from /root/openct-0.6.2/src/ctapi/.libs/libopenctapi.so
#8  0xb7e560ca in CT_data ()
   from /root/openct-0.6.2/src/ctapi/.libs/libopenctapi.so
#9  0xb7e5923f in IFDHPowerICC ()
   from /root/openct-0.6.2/src/pcsc/.libs/openct-ifd.so
#10 0x080571fa in IFDPowerICC ()
#11 0x08056a56 in EHStatusHandlerThread ()
#12 0xb7fd0b63 in start_thread () from /lib/tls/libpthread.so.0
#13 0xb7f63c4a in clone () from /lib/tls/libc.so.6

The file descriptor of the write() call represents an anonymous UNIX socket
(in my case it was file descriptor 5 of the pcscd process pid 9504):

$ ls -la /proc/9504/fd/5
lrwx------    1 root     root           64 Mar 30 10:12 /proc/9504/fd/5 ->
+socket:[34299]
$ lsof | grep '34299\|COMMAND'
COMMAND     PID    USER   FD      TYPE     DEVICE     SIZE       NODE NAME
pcscd      9504    root    5u     unix 0xce874100               34299 socket

I guess this anonymous UNIX socket is connected to the UNIX socket
/var/run/openct/0, with ifdhandler listenning on this socket. The
SIGPIPE could be explained by the fact that ifdhandler is not ready to
read the descriptor when openct-ifd.so is writing to it.

So I tried a quick hack:

  $ mv /usr/sbin/ifdhandler /usr/sbin/ifdhandler.real
  $ cat >/usr/sbin/ifdhandler <<EOF
  #!/bin/sh
  exec strace -f /usr/sbin/ifdhandler.real "$@" >/tmp/dir/mylog 2>&1
  EOF
  $ chmod 755 /usr/sbin/ifdhandler

This way, after plugging in the USB token, the shell script is automatically
launched by the hotplug mechanism, and I am able to watch in real time
what ifdhandler is doing (via tail -f /tmp/dir/mylog).

Here is the relevant part of /tmp/dir/mylog:

unlink("/var/run/openct/0")             = 0
socket(PF_FILE, SOCK_STREAM, 0)         = 5
fcntl64(5, F_SETFD, FD_CLOEXEC)         = 0
bind(5, {sa_family=AF_FILE, path="/var/run/openct/0"}, 110) = 0
listen(5, 5)                            = 0
chmod("/var/run/openct/0", 0666)        = 0
time([1112214379])                      = 1112214379
msync(0xb7fe8000, 4096, MS_SYNC)        = 0
poll([{fd=4, events=POLLHUP}, {fd=5, events=POLLIN}], 2, 1000) = 0
time([1112214380])                      = 1112214380
time([1112214380])                      = 1112214380
poll([{fd=4, events=POLLHUP}, {fd=5, events=POLLIN}], 2, 1000) = 0
time([1112214381])                      = 1112214381
time([1112214381])                      = 1112214381
[...]

As you can see, the UNIX socket is created and bound to /var/run/openct/0,
then nothing really interesting happens: poll() detects no events on the fd.

So why does openct-ifd.so receive SIGPIPE when writing to the UNIX socket
/var/run/openct/0 ? My guess is that the problem is due to a race condition:
openct-ifd.so opens and writes to /var/run/openct/0 *before* ifdhandler
listens to this socket. It receives SIGPIPE simple because ifdhandler is
not yet reading /var/run/openct/0.

I've already spent a few hours on debugging this issue. I am now asking for
a little help from the mailing list... Do you think my analysis is correct ?
Can you give me a few hint on where should I look in OpenCT to fix this race
condition ? Thanks.

-- 
Marc Bevand