Bug 232983

Update:

Running the latest pcsc-lite with the downgraded ifd-egate, noticed that pcscd
was using a good chunk of the cpu. Apparently the latest pcsc-lite relies
heavily on polling when not paired with the latest ifd-egate driver.

Further Update:

Just as an experiment, did the following:

Upgraded ifd-egate back up to 0.05-16 and
tried "pcsc-lite-1.3.1-7" and then tried
"pcsc-lite-1.3.2-1".

With the latest egate, both of the above downgraded pcsc-lite rpms worked fine
with card removals.

More info:

This not covers the situation where a downgraded ifd-egate is used with the
latest pcsc-lite.

Took a look at the code in pcsc-lite.

It supports a driver capability flag called IFD_GENERATE_HOTPLUG .
This is set to true for drivers that don't want to use polling such
as the latest ifd-egate driver.

In the case of using a  non-latest version 05-15 of ifd-egate, the given capability
is not set.

This would lead pcsc to use its old polling model. Unfortunately, the code also
supports a command line param that can force polling called
"force-reader-polling".  This flag allows the caller the ability to set a
variable called  HPForceReaderPolling to some integer value.

This variable is initialized to 0 on startup if the flag is not used. 

This sets up the scenario where a version of ifd-egate is used that does not
either support IFD_GENERATE_HOTPLUG OR use the "force-reader-polling" flag.


The following code is then run in a thread:

 while (do_polling)
        {
                SYS_Sleep(HPForceReaderPolling);
                HPRescanUsbBus();
        }

I believe that HPForceReaderPolling may be set to zero, thus not making the
sleep interval very long and using up the CPU.

Thanks Jack, I believe there's another bug about the polling issue. I'll track
it down an link it in. Good work.

bob

Further information:

I did some more poking around. The latest pcsc with the latest egate are
designed to work together through the "udev" deamon. The ifd-egate installer
installs some rules for udev to follow in the case of token events. The rule
file is:

/etc/udev/rules.d/85-pcscd_egate.rule  
 looks like this:

# udev rules for pcscd and egate readers

BUS=="usb", SYSFS{idVendor}=="0973", SYSFS{idProduct}=="0001", ACTION=="add",
RUN+="/usr/sbin/pcscd --hotplug"

Note that there is also a similar rule file for pcsc and  ccid interaction.

The rule above appears to contain a simple action in the case a usb device is
added. In this case the program "/usr/sbin/pcscd --hotplug" is called. At this
point pcsc reacts with the following log messages:

pcscdaemon.c:110:SendHotplugSignal() Send hotplug signal to pcscd (pid=26383)

This results in pcsc scanning for new hardware and doing the right thing.


The problem appears to be that when the token is removed, nobody is notified.
The only trace of this removal in the log shows up as:

Mar 21 15:36:25 dhcp-172-16-25-199 kernel: usb 2-2: USB disconnect, address 39

I attempted to play with the rule to somehow account for the "remove" ACTION to
no success. I also tried removing the ACTION clause all together in hopes that
the rule would fire on either a removal or insertion. In practice it only fired
on an insertion.

Just for fun, I disabled the rule and made manual calls from a terminal of:

/usr/sbin/pcscd --hotplug

Once after manually inserting the key and once after manually removing the key.

In both cases the pcsc logs reflected the right behavior.

Conclusions

1. The udev rule is in error and needs to be something else.

2. The event for a usb device removal is not getting bubbled up by the udev
daemon. Even worse would be that udev itself does not get the event.

Created attachment 150697 [details]
Output of /usr/sbin/udevmonitor

More info:

The  attachment containing the output of "udevmonitor" shows us what is going on
when our egate device is plugged in and then removed.


Revisiting the current udev rule for the usb egate device.

BUS=="usb", SYSFS{idVendor}=="0973", SYSFS{idProduct}=="0001", ACTION=="add",
RUN+="/usr/sbin/pcscd --hotplug"

The above rule does not handle the ACTION of "remove". When I tried to duplicate
the above rule only makeing the ACTION "remove" it did not work either. 

After researching and playing with udev, I found out that when you remove the
the device the directroy that represents the device goes away, taking with it
much of the information used in the rules to match the event.

I found that once I added the following experimental rule, the rule began to
fire on the token removal:


BUS=="usb", ENV{PRODUCT}=="973/1/100", ACTION=="remove", RUN+="/usr/sbin/pcscd
--hotplug"

Observering the logs showed that pcsc was in fact now being contacted when the
token was removed. I also ran a quick test with ESC and it was able to see the
token removal event.

The new wrinkle above was to query the PRODUCT environment variable which was
apparently still available after token removal. The actual value above
"973/1/100" was observed in the attachment of the output of "/usr/sbin/udevmonitor".

Conclusions:

1. We could fix this by carefully crafting new rules for 85-pcscd_egate.rules
and 85-pcscd_ccid.rules located in the directory /etc/udev/rules.d .

Caveat:

While debugging I noticed that when the token is inserted 3 separate "add"
events are being caught by the rule, thus resulting in the signaling of pcscd
three times instead of once. I believe the same thing will happen on token
removal when the rules are set up properly.

2. We could also fix this by carefully reverting the packages of pcsc-lite and
ifd-egate to levels where everything at least works ok.

More info: output of  udevinfo -a -p /sys/bus/usb/devices/2-1 to view the
attributes of a plugged in token:


 udevinfo -a -p /sys/bus/usb/devices/2-1

Udevinfo starts with the device specified by the devpath and then
walks up the chain of parent devices. It prints for every device
found, all possible attributes in the udev rules key format.
A rule to match, can be composed by the attributes of the device
and the attributes from one single parent device.

  looking at device '/devices/pci0000:00/0000:00:1d.1/usb2/2-1':
    KERNEL=="2-1"
    SUBSYSTEM=="usb"
    DRIVER=="usb"
    ATTR{product}=="SchlumbergerSema Cyberflex e-gate"
    ATTR{manufacturer}=="SchlumbergerSema"
    ATTR{quirks}=="0x0"
    ATTR{maxchild}=="0"
    ATTR{version}==" 1.10"
    ATTR{devnum}=="20"
    ATTR{speed}=="1.5"
    ATTR{bMaxPacketSize0}=="8"
    ATTR{bNumConfigurations}=="1"
    ATTR{bDeviceProtocol}=="00"
    ATTR{bDeviceSubClass}=="00"
    ATTR{bDeviceClass}=="ff"
    ATTR{bcdDevice}=="0100"
    ATTR{idProduct}=="0001"
    ATTR{idVendor}=="0973"
    ATTR{bMaxPower}==" 30mA"
    ATTR{bmAttributes}=="80"
    ATTR{bConfigurationValue}=="1"
    ATTR{bNumInterfaces}==" 1"
    ATTR{configuration}==""

  looking at parent device '/devices/pci0000:00/0000:00:1d.1/usb2':
    KERNELS=="usb2"
    SUBSYSTEMS=="usb"
    DRIVERS=="usb"
    ATTRS{serial}=="0000:00:1d.1"
    ATTRS{product}=="UHCI Host Controller"
    ATTRS{manufacturer}=="Linux 2.6.20-1.2990.fc7 uhci_hcd"
    ATTRS{quirks}=="0x0"
    ATTRS{maxchild}=="2"
    ATTRS{version}==" 1.10"
    ATTRS{devnum}=="1"
    ATTRS{speed}=="12"
    ATTRS{bMaxPacketSize0}=="64"
    ATTRS{bNumConfigurations}=="1"
    ATTRS{bDeviceProtocol}=="00"
    ATTRS{bDeviceSubClass}=="00"
    ATTRS{bDeviceClass}=="09"
    ATTRS{bcdDevice}=="0206"
    ATTRS{idProduct}=="0000"
    ATTRS{idVendor}=="0000"
    ATTRS{bMaxPower}=="  0mA"
    ATTRS{bmAttributes}=="e0"
    ATTRS{bConfigurationValue}=="1"
    ATTRS{bNumInterfaces}==" 1"
    ATTRS{configuration}==""

  looking at parent device '/devices/pci0000:00/0000:00:1d.1':
    KERNELS=="0000:00:1d.1"
    SUBSYSTEMS=="pci"
    DRIVERS=="uhci_hcd"
    ATTRS{msi_bus}==""
    ATTRS{broken_parity_status}=="0"
    ATTRS{enable}=="1"
    ATTRS{modalias}=="pci:v00008086d000027C9sv00001179sd0000FF10bc0Csc03i00"
    ATTRS{local_cpus}=="ffffffff"
    ATTRS{irq}=="20"
    ATTRS{class}=="0x0c0300"
    ATTRS{subsystem_device}=="0xff10"
    ATTRS{subsystem_vendor}=="0x1179"
    ATTRS{device}=="0x27c9"
    ATTRS{vendor}=="0x8086"

  looking at parent device '/devices/pci0000:00':
    KERNELS=="pci0000:00"
    SUBSYSTEMS==""
    DRIVERS==""

More info:

The rule file for CCID, which has been mentioned before is below:
Note: If we chose the "add ACTION="remove" rules" approach, this file will need
new content as well.

# udev rules for pcscd and CCID readers

# Gemplus PCMCIA Card
#SUBSYSTEMS=="pcmcia", DRIVER=="serial_cs", ACTION=="add",
SYSFS{prod_id1}=="Gemplus", SYSFS{prod_id2}=="SerialPort",
SYSFS{prod_id3}=="GemPC Card", RUN+="/usr/sbin/pcscd --hotplug"

# generic CCID device
BUS=="usb", SYSFS{bInterfaceClass}=="0b", ACTION=="add", RUN+="/usr/sbin/pcscd
--hotplug"

# non CCID generic (InterfaceClass: 0xFF)
# CherrySmartTerminalST2XXX.txt
BUS=="usb", SYSFS{idVendor}=="046a", SYSFS{idProduct}=="003e", ACTION=="add",
RUN+="/usr/sbin/pcscd --hotplug"
# DellSK-3106.txt
BUS=="usb", SYSFS{idVendor}=="413c", SYSFS{idProduct}=="2100", ACTION=="add",
RUN+="/usr/sbin/pcscd --hotplug"
# MySmartPad.txt
BUS=="usb", SYSFS{idVendor}=="09be", SYSFS{idProduct}=="0002", ACTION=="add",
RUN+="/usr/sbin/pcscd --hotplug"
# SCR331-DI-NTTCom.txt
BUS=="usb", SYSFS{idVendor}=="04e6", SYSFS{idProduct}=="5120", ACTION=="add",
RUN+="/usr/sbin/pcscd --hotplug"
# SCR331-DI.txt
BUS=="usb", SYSFS{idVendor}=="04e6", SYSFS{idProduct}=="5111", ACTION=="add",
RUN+="/usr/sbin/pcscd --hotplug"
# SDI010.txt
BUS=="usb", SYSFS{idVendor}=="04e6", SYSFS{idProduct}=="5121", ACTION=="add",
RUN+="/usr/sbin/pcscd --hotplug"
# SPR532.txt
BUS=="usb", SYSFS{idVendor}=="04e6", SYSFS{idProduct}=="e003", ACTION=="add",
RUN+="/usr/sbin/pcscd --hotplug"
# Verisign_secure_storage_token.txt
BUS=="usb", SYSFS{idVendor}=="08e6", SYSFS{idProduct}=="1359", ACTION=="add",
RUN+="/usr/sbin/pcscd --hotplug"
# Verisign_secure_token.txt
BUS=="usb", SYSFS{idVendor}=="08e6", SYSFS{idProduct}=="ace0", ACTION=="add",
RUN+="/usr/sbin/pcscd --hotplug"

More info:

Further investigation into the issuer where we are getting 3 insertion and
removal events has shed some lite on what could be done.

Apparently one of the environment variables available on token removal is called
"SEQNUM" which gets incremented each pass through.

Instead of having the rule run "/usr/sbin/pcscd --hotplug", we could have it run
a shell script that first queries the various environment variables to tell if
it is really necessary to launch pcscd.

More info:

Testing of an actual CAC card with a CAC card reader works ok. The udev rule
takes care of the case when the CCID card reader is inserted. From that point,
pcsc-lite  looks like it knows how to handle actual CAC card insertions and
deletions just fine.

The trouble appears to be with standard egate cards. The udev stuff detects the
normal token insertion.

Then normal operation of pcsc creates this thead called EHStatusHandlerThread
that runs through a loop each second checking the status of the card it has been
created to oversee.

The following function call:

rv = IFDStatusICC(rContext, &dwStatus, rContext->readerState->cardAtr,
                        &rContext->readerState->cardAtrLength);


persists in returning the value SCARD_PRESENT within the argument dwStatus even
when the card has long been removed. IFDStatusICC calls down into a callback
provided by the egate driver itself that reports the status of the card. I
believe this function is now always returing SCARD_PRESENT.

Diff of one file changed:

--- ./pcscd_egate.rules.udev-rules      2007-03-23 14:16:49.000000000 -0700
+++ ./pcscd_egate.rules 2007-03-23 14:17:25.000000000 -0700
@@ -1,3 +1,5 @@
 # udev rules for pcscd and egate readers

 BUS=="usb", SYSFS{idVendor}=="0973", SYSFS{idProduct}=="0001", ACTION=="add",
RUN+="/usr/sbin/pcscd --hotplug"
+
+BUS=="usb", ENV{PRODUCT}=="973/1/100", ACTION=="remove", RUN+="/usr/sbin/pcscd
--hotplug"

Proposed spec:

Created attachment 150800 [details]
Proposed new spec file.

More info:

The real problem has been tracked down into the ifd-egate driver itself. The
file "ifdhandler.c" has a function called "RESPONSECODE IFDHICCPresence(DWORD
Lun);" which calls into "egate_probe" which is as follows:

RESPONSECODE egate_probe(struct egate *egate) {
        unsigned char c;
        int rc;
        usb_dev_handle *myhandle;

        if (!egate)
            return IFD_COMMUNICATION_ERROR;

        if (!egate->usb) {
            return egate_get_usb(egate);
        }

        return IFD_ICC_PRESENT;
}

Note that the var egate->usb will always have a value once the token is
inserted. Unfortunately it will continue to have a value once the card is
removed. Therefore "egate_get_usb" never gets called again with the predictable
results. 

The old version of this looks like:

int egate_probe(struct egate *egate) {
        unsigned char c;
        int rc;
        usb_dev_handle *myhandle;

        if (!egate)
            return 0;
        if (!egate->usb) {
            return 0;
        }
        myhandle=egate->usb;
        rc = do_usb(myhandle, USB_ENDPOINT_IN|USB_TYPE_VENDOR,
                    EGATE_CMD_FETCHSTATUS,0, 0, &c, 1, EGATE_TIMEOUT);
        sleep(1);
        if (rc == 1) return 1;
        return 0;
}

Here it is obvious that the old code was detecting the token's removal. I
suspect the new code was an attempt to avoid the polling done here.

The first experiment was to actually call egate_get_usb(egate); in all
situations. This did not work because "egate_get_usb" has not been set up to
handle the case where the argument "egate" already exists.

More later...

The following patch was used to get ifd-egate working WITHOUT the need to alter
the file "/etc/udev/rules.d/85-pcscd_egate.rules" .


Proposed solution diff:

[root@dhcp-172-16-25-199 ifd-egate-0.05]# diff -c egate.c.presence egate.c
*** egate.c.presence    Mon Mar 26 11:03:12 2007
--- egate.c     Mon Mar 26 11:32:10 2007
***************
*** 96,121 ****
        struct usb_device *mydev = NULL;
        usb_dev_handle *myhandle;
  
!         if (egate->usb) {
!             return 0;
!       } 
  
        usb_init();
        usb_find_busses();
        usb_find_devices();
        for (mybus = usb_busses; mybus; mybus = mybus->next) {
            for (mydev = mybus->devices; mydev; mydev = mydev->next) {
!               if ((mydev->descriptor.idVendor == 0x973) &&
!                        (mydev->descriptor.idProduct == 0x001) &&
!                        egate_is_device_free(mydev)) {
!                           goto found;
!               }
            }
        }
        syslog(LOG_ERR,"egate_get_usb %x: No devices found\n", egate->lun);
      
        return IFD_NO_SUCH_DEVICE;
!  found:
        myhandle=usb_open(mydev);
        if (!myhandle) {
                syslog(LOG_ERR,"egate_get_usb %x: Couldn't open %s %s\n", 
--- 96,127 ----
        struct usb_device *mydev = NULL;
        usb_dev_handle *myhandle;
  
!         int is_found = 0;
  
        usb_init();
        usb_find_busses();
        usb_find_devices();
        for (mybus = usb_busses; mybus; mybus = mybus->next) {
            for (mydev = mybus->devices; mydev; mydev = mydev->next) {
! 
!                 if ((mydev->descriptor.idVendor == 0x973) &&
!                          (mydev->descriptor.idProduct == 0x001)) {
!                
!                     is_found = 1;
! 
!                     if( egate_is_device_free(mydev))
!                         goto foundnew;
!                 }
! 
!                 if ( is_found )
!                     goto found;
!                      
            }
        }
        syslog(LOG_ERR,"egate_get_usb %x: No devices found\n", egate->lun);
      
        return IFD_NO_SUCH_DEVICE;
! foundnew:
        myhandle=usb_open(mydev);
        if (!myhandle) {
                syslog(LOG_ERR,"egate_get_usb %x: Couldn't open %s %s\n", 
***************
*** 128,133 ****
--- 134,140 ----
            egate->dirname = strdup(mydev->bus->dirname);
            egate->filename = strdup(mydev->filename);
        }
+ found:
          return IFD_ICC_PRESENT;
  }
  
***************
*** 154,161 ****
          if (!egate)
              return IFD_COMMUNICATION_ERROR;
  
!         if (!egate->usb) {
!             return egate_get_usb(egate);
          }
  
          return IFD_ICC_PRESENT;
--- 161,170 ----
          if (!egate)
              return IFD_COMMUNICATION_ERROR;
  
!         rc = egate_get_usb(egate);
! 
!         if (rc == IFD_NO_SUCH_DEVICE) {
!             return rc; 
          }
  
          return IFD_ICC_PRESENT;

Jack checked in his fix in ifd-egate-0.05-17

Based on the date this bug was created, it appears to have been reported
against rawhide during the development of a Fedora release that is no
longer maintained. In order to refocus our efforts as a project we are
flagging all of the open bugs for releases which are no longer
maintained. If this bug remains in NEEDINFO thirty (30) days from now,
we will automatically close it.

If you can reproduce this bug in a maintained Fedora version (7, 8, or
rawhide), please change this bug to the respective version and change
the status to ASSIGNED. (If you're unable to change the bug's version
or status, add a comment to the bug and someone will change it for you.)

Thanks for your help, and we apologize again that we haven't handled
these issues to this point.

The process we're following is outlined here:
http://fedoraproject.org/wiki/BugZappers/F9CleanUp

We will be following the process here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping to ensure this
doesn't happen again.

This bug has been in NEEDINFO for more than 30 days since feedback was
first requested. As a result we are closing it.

If you can reproduce this bug in the future against a maintained Fedora
version please feel free to reopen it against that version.

The process we're following is outlined here:
http://fedoraproject.org/wiki/BugZappers/F9CleanUp