Friday, February 13, 2015

Debug a smart card reader driver on Yosemite

Since Mac OS X Yosemite (10.10) the pcscd command is no more present. See "OS X Yosemite and smart cards status" for more details.

The problem is that I used this command to get some debug log from my CCID smart card driver. See "pcscd debug output on Mac OS X". Unfortunately this technique is no more available.

com.apple.ifdreader

The /System/Library/CryptoTokenKit/com.apple.ifdreader.slotd/Contents/MacOS/com.apple.ifdreader father process is process 1. Process 1 is launchd "System wide and per-user daemon/agent manager".

If I start the command from a Terminal I get no error message, the command does not return but in the /var/log/system.log file I find:
Feb 10 14:49:57 imac com.apple.ifdreader[37446]: assertion failed: 14C109: libxpc.dylib + 34612 [876216DC-D5D3-381E-8AF9-49AE464E5107]: 0x2d
Feb 10 14:49:57 imac com.apple.ifdreader[37446]: Bogus event on event stream listener.

So I think some parameters and/or context is missing.

The process is started by launchd. The configuration file is /System/Library/LaunchDaemons/com.apple.ifdreader.plist. It contains:
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
 <key>Label</key>
 <string>com.apple.ifdreader</string>
 <key>RunAtLoad</key>
 <false/>
 <key>EnablePressuredExit</key>
 <true/>
 <key>POSIXSpawnType</key>
 <string>Adaptive</string>
 <key>ProgramArguments</key>
 <array>
  <string>/System/Library/CryptoTokenKit/com.apple.ifdreader.slotd/Contents/MacOS/com.apple.ifdreader</string>
 </array>
 <key>LaunchEvents</key>
 <dict>
  <key>com.apple.iokit.matching</key>
  <dict>
   <key>com.apple.ctk.ifdreader.device</key>
   <dict>
    <key>IOMatchLaunchStream</key>
    <true/>
    <key>IOProviderClass</key>
    <string>IOUSBDevice</string>
   </dict>
  </dict>
 </dict>
</dict>
</plist>

Restarting com.apple.ifdreader

After you changed the driver configuration it may be needed to restart the com.apple.ifdreader process.

First you need to stop the process. You can use:
$ sudo killall -SIGKILL -m .*com.apple.ifdreader

Then you need to restart it. Since most smart card reader are USB devices you just need to plug your USB reader and com.apple.ifdreader is (re)started automatically.

Send logs using syslog(3)

If printf(3) can't be used to log messages then the normal option for a daemon is to use syslog(3).

I modified my CCID driver to log messages using syslog(3). This feature will be available in the CCID driver versions 1.4.19 and later.

Get syslog logs

Now that the messages from the CCID driver are sent somewhere we must get them.

We have two options on Mac OS X: a graphical application or a command line tool.

Console application

Apple provides the Console application in /Applications/Utilities/Console.app.
The application icon is:

The application is easy to use. You can filter the output to only have logs from ifdreader.


syslog -k Sender com.apple.ifdreader

Another opiont is to use the command line tool syslog(1).

$ syslog -w -k Sender com.apple.ifdreader

Arguments:
  • -w
    The -w option causes syslog to wait for new messages. By default, syslog
    prints the last 10 messages, then waits for new messages to be added to
    the data store.
  • -k
    The -k option may be followed by one, two, or three arguments. A single
    argument causes a match to occur if a message has the specified key,
    regardless of value. If two arguments are specified, a match occurs when
    a message has exactly the specified value for a given key. For example,
    to find all messages sent by the portmap process:
    syslog -k Sender portmap

Sample output

I used lwatch to add colors and ansi2html to convert the ANSI color codes to HTML.

Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 08676368 ifdhandler.c:96:CreateChannelByNameOrChannel() Lun: 0, device: Gemalto PC Twin Reader
Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 00000110 ccid_usb.c:283:OpenUSBByName() Using: /usr/libexec/SmartCardServices/drivers/ifd-ccid-test-test.bundle/Contents/Info.plist
Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 00000637 ccid_usb.c:301:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 00000089 ccid_usb.c:302:OpenUSBByName() ifdProductString: Generic CCID driver
Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 00000075 ccid_usb.c:303:OpenUSBByName() Copyright: This driver is protected by terms of the GNU Lesser General Public License version 2.1, or (at your option) any later
Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 00177567 ccid_usb.c:595:OpenUSBByName() Found Vendor/Product: 08E6/3437 (Gemalto PC Twin Reader)
Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 00000078 ccid_usb.c:597:OpenUSBByName() Using USB bus/device: 253/6
Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 00000063 ccid_usb.c:649:OpenUSBByName() bNumDataRatesSupported is 0
Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 00010058 commands.c:997:CmdEscapeCheck error on byte 10
Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 00000082 ccid.c:215:set_gemalto_firmware_features() GET_FIRMWARE_FEATURES failed: 612, len=0
Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 00000067 ifdhandler.c:375:IFDHGetCapabilities() tag: 0xFAD, Gemalto PC Twin Reader (lun: 0)
Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 00000072 ifdhandler.c:375:IFDHGetCapabilities() tag: 0x7A007, Gemalto PC Twin Reader (lun: 0)
Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 00000072 ifdhandler.c:375:IFDHGetCapabilities() tag: 0xFAE, Gemalto PC Twin Reader (lun: 0)
Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 00000095 ifdhandler.c:463:IFDHGetCapabilities() Reader supports 1 slot(s)
Feb 13 14:04:02 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 00001257 ifdhandler.c:1139:IFDHPowerICC() action: Reset, Gemalto PC Twin Reader (lun: 0)
Feb 13 14:04:09 iMac-de-Ludovic.local com.apple.ifdreader[6581] <Warning>: 06859987 ifdhandler.c:1139:IFDHPowerICC() action: Reset, Gemalto PC Twin Reader (lun: 0)

ATR and APDU logging

Using pcscd it was possible to log APDU sent to the card and the response from the card. This service is now missing since pcscd is no more present.

I added a new option to the CCID driver to log this information. Since it is a sensitive information (you can see the PIN code sent to the card for example) you need the administrative privilege and edit the driver configuration file Info.plist. The configuration file should be /usr/libexec/SmartCardServices/drivers/ifd-ccid.bundle/Contents/Info.plist.

The new option value is 0x0080. You should have some thing like:
   <key>ifdDriverOptions</key>
   <string>0x0080</string>

You will get something like:
Feb 13 15:17:04 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: 00000076 ifdhandler.c:463:IFDHGetCapabilities() Reader supports 1 slot(s)
Feb 13 15:17:11 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: 06637507 ifdhandler.c:1139:IFDHPowerICC() action: Reset, Gemalto PC Twin Reader (lun: 0)
Feb 13 15:17:11 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Error>: 00055035 commands.c:249:CmdPowerOn Card absent or mute
Feb 13 15:17:11 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Critical>: 00000171 ifdhandler.c:1206:IFDHPowerICC() PowerUp failed
Feb 13 15:17:15 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: 04106934 ifdhandler.c:1139:IFDHPowerICC() action: Reset, Gemalto PC Twin Reader (lun: 0)
Feb 13 15:17:15 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Error>: 00055041 commands.c:249:CmdPowerOn Card absent or mute
Feb 13 15:17:15 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Critical>: 00000184 ifdhandler.c:1206:IFDHPowerICC() PowerUp failed
Feb 13 15:17:17 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: 02376603 ifdhandler.c:1139:IFDHPowerICC() action: Reset, Gemalto PC Twin Reader (lun: 0)
Feb 13 15:17:17 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Error>: 00055065 commands.c:249:CmdPowerOn Card absent or mute
Feb 13 15:17:17 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Critical>: 00000146 ifdhandler.c:1206:IFDHPowerICC() PowerUp failed
Feb 13 15:17:19 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: 01725812 ifdhandler.c:1139:IFDHPowerICC() action: Reset, Gemalto PC Twin Reader (lun: 0)
Feb 13 15:17:19 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: ATR: 3B FA 94 00 00 81 31 20 43 80 65 A2 01 01 01 3D 72 D6 43 21 
Feb 13 15:17:23 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: 03997665 ifdhandler.c:682:IFDHSetProtocolParameters() protocol T=1, Gemalto PC Twin Reader (lun: 0)
Feb 13 15:17:23 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: 00000099 ifdhandler.c:2073:extra_egt() Extra EGT patch applied
Feb 13 15:17:23 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: 00040776 ifdhandler.c:1286:IFDHTransmitToICC() Gemalto PC Twin Reader (lun: 0)
Feb 13 15:17:23 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: APDU: 00 A4 04 00 0A A0 00 00 00 62 03 01 0C 06 01 
Feb 13 15:17:23 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: SW: 90 00 
Feb 13 15:17:23 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: 00015578 ifdhandler.c:1286:IFDHTransmitToICC() Gemalto PC Twin Reader (lun: 0)
Feb 13 15:17:23 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: APDU: 00 00 00 00 
Feb 13 15:17:23 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: SW: 48 65 6C 6C 6F 20 77 6F 72 6C 64 21 90 00 
Feb 13 15:17:24 iMac-de-Ludovic.local com.apple.ifdreader[11365] <Warning>: 01039858 ifdhandler.c:1139:IFDHPowerICC() action: PowerDown, Gemalto PC Twin Reader (lun: 0)

You can note that the card power up failed 3 times.

The log criticality is available. The default level is <Warning> but can be <Error> or <Critical>.

Conclusion

Getting debug logs of the PC/SC layer is sometimes important to find a problem. I had to modify my CCID driver to add a new log mechanism that works on Yosemite.

[UPDATE]

The ATR and APDU logging is no more needed. See "Debug a smart card application on Yosemite".

[UPDATE 2]

You can change the log level of the com.apple.ifdreader process. See "Change syslog logging level on Yosemite".