Extended APDU cards

In a previous article "Extended APDU status per reader" I wrote about readers status regarding extended APDU. Since I have a rather long list of ATRs (1147 different cards) I tried to find cards supporting extended APDU.

Extended APDU cards

Cards can declare support of extended APDU in the historical bytes part of the ATR. Using my ATR parsing program it is visible as: Extended Lc and Le fields

Cards found

I used my stress test program to scan the complete ATR list. I found 5 cards with expicit extended APDU support:

• ePerso - German ID card
• SignTrust (www.signtrust.de) or Infinion SLE66CX680PE with Starcos 3.2
• Serbian Identity Card
• TCOS 3.0 / NetKey 3.0
• GnuPG card V2

Not all the cards declare extended APDU support in the ATR. So the list above is not exhaustive.

Comments

The 5 cards do all support the T=1 protocol. The German ID card does also support T=0. This is because extended APDU is very hard to use using T=0.

The 5 cards are used for asymmetric cryptography (RSA) with "long" keys (2048 bits or 256 bytes) and so require the use of extended APDU.

pcscd debug output on Mac OS X

In my previous article "pcscd debug output" comments Koen asked about the same information but for Mac OS X.

pcscd start on Mac OS X

On Mac OS X pcscd is not started on system boot (as it used to be the case on GNU/Linux distributions) nor using the autostart feature (as it should be the case for pcsc-lite > 1.6.0). On Mac OS X the pcscd daemon is launched when a USB smart card reader is connected to the system. It is the job of securityd.

securityd

The securityd manpage is short and not very information for our problem. In particular the command line options are not documented in the manpage. But the options are available from the command line itself:

$ securityd -h
securityd: illegal option -- h
Usage: securityd [-dwX]
 [-a authConfigFile]                    Authorization configuration file
 [-c tokencache]                        smartcard token cache directory
 [-e equivDatabase]                     path to code equivalence database
 [-N serviceName]                       MACH service name
 [-s off|on|conservative|aggressive]    smartcard operation level
 [-t maxthreads] [-T threadTimeout]     server thread control

The important option here is -s. If you want to disable the automatic launch of pcscd you need to start securityd with -s off. But you do not start securityd yourself. securityd is started by another daemon: launchd.

launchd

The launchd configuration file for securityd is /System/Library/LaunchDaemons/com.apple.securityd.plist.

You need to edit it and add the two colored lines:

<array>
  <string>/usr/sbin/securityd</string>
  <string>-i</string>
  <string>-s</string>
  <string>off</string>
 </array>

You then need to restart launchd. The easiest way it to reboot the computer.

See also this mail from the apple-cdsa mailing list.

pcscd manual start on Mac OS X

After that change you can start pcscd manually in a terminal. No other pcscd process will be started when a smart card reader is connected.

The same arguments as on GNU/Linux can be used: pcscd --foreground --debug --apdu

Mac OS X pcscd logs

The Apple version of pcscd logs a lot of internal information about the protocol between the daemon and the library (the PCSC framework). If find the pcscd logs nearly useless and very difficult to exploit. But that is better than nothing.

pcscd debug output

pcscd output

pcscd is a daemon (PC/SC Daemon) and as such do not send any message to a terminal since, in general, no terminal is connected to the process standard output.

By default pcscd run as a daemon and any message is sent to the syslog system. These messages are then written in a log file like /var/log/messages.

Silent logs

Since version 1.7.3 some error messages are now debug messages and not logged by default. An error message was generated when the PC/SC call SCardConnect() failed because no card was in the reader. Since a PC/SC failure may be a normal behavior in some cases the file /var/log/messages was growing up to filling the disk. This problem was reported as Red Hat bug 707412 "PCSCD filling /var/log/messages".

Now pcscd will be much more silent by default. And system logs should not fill disks anymore.

Debug logs

Of course it is still possible to activate logs. In general you also run pcscd in the foreground (instead of in the background).

Example:
$ pcscd --foreground --debug

00000000 debuglog.c:269:DebugLogSetLevel() debug level=debug
00000174 configfile.l:245:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
00000012 configfile.l:287:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin
00000050 pcscdaemon.c:552:main() pcsc-lite 1.7.4 daemon ready.
00001897 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/003/001
00000161 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/004/001
00000125 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/004/001
00000130 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x046D, PID: 0xC063, path: /dev/bus/usb/004/002
00000124 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/004/001
00000129 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x413C, PID: 0x2003, path: /dev/bus/usb/004/003
00000161 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/005/001
00000159 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000159 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/006/001
00000157 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/007/001
00000160 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/008/001
00000127 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/008/001
00000130 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x04CC, PID: 0x1122, path: /dev/bus/usb/008/002
00000136 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x08E6, PID: 0x8180, path: /dev/bus/usb/008/014
00000132 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x08E6, PID: 0x8180, path: /dev/bus/usb/008/014
00000126 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x04CC, PID: 0x1122, path: /dev/bus/usb/008/002
00000136 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x04B4, PID: 0xAEF3, path: /dev/bus/usb/008/013
00000127 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x04CC, PID: 0x1122, path: /dev/bus/usb/008/002
00000139 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x08E6, PID: 0x3437, path: /dev/bus/usb/008/018
00000028 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x08E6, PID: 0x3437, path: /dev/bus/usb/008/018
00000004 hotplug_libudev.c:309:HPAddDevice() Adding USB device: Gemalto GemPC Twin
00000028 readerfactory.c:934:RFInitializeReader() Attempting startup of Gemalto GemPC Twin 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00000202 readerfactory.c:824:RFBindFunctions() Loading IFD Handler 3.0
00000026 ifdhandler.c:1750:init_driver() Driver version: 1.4.4
00000490 ifdhandler.c:1767:init_driver() LogLevel: 0x0003
00000004 ifdhandler.c:1778:init_driver() DriverOptions: 0x0000
00000081 ifdhandler.c:79:IFDHCreateChannelByName() lun: 0, device: usb:08e6/3437:libudev:0:/dev/bus/usb/008/018
00000396 ccid_usb.c:245:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
00000004 ccid_usb.c:246:OpenUSBByName() ifdProductString: Generic CCID driver
00000004 ccid_usb.c:247:OpenUSBByName() Copyright: This driver is protected by terms of the GNU Lesser General Public License version 2.1, or (at your option) any later version.
00054079 ccid_usb.c:504:OpenUSBByName() Found Vendor/Product: 08E6/3437 (Gemalto GemPC Twin)
00000004 ccid_usb.c:506:OpenUSBByName() Using USB bus/device: 8/18
00003836 ccid_usb.c:972:get_data_rates() declared: 10753 bps
00000003 ccid_usb.c:972:get_data_rates() declared: 14337 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 15625 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 17204 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 20833 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 21505 bps
00000001 ccid_usb.c:972:get_data_rates() declared: 23438 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 25806 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 28674 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 31250 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 32258 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 34409 bps
00000001 ccid_usb.c:972:get_data_rates() declared: 39063 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 41667 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 43011 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 46875 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 52083 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 53763 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 57348 bps
00000001 ccid_usb.c:972:get_data_rates() declared: 62500 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 64516 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 68817 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 71685 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 78125 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 83333 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 86022 bps
00000001 ccid_usb.c:972:get_data_rates() declared: 93750 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 104167 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 107527 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 114695 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 125000 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 129032 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 143369 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 156250 bps
00000001 ccid_usb.c:972:get_data_rates() declared: 166667 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 172043 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 215054 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 229391 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 250000 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 344086 bps
00009925 ifdhandler.c:401:IFDHGetCapabilities() tag: 0xFB3, usb:08e6/3437:libudev:0:/dev/bus/usb/008/018 (lun: 0)
00000003 readerfactory.c:295:RFAddReader() Using the reader polling thread
00002046 ifdhandler.c:401:IFDHGetCapabilities() tag: 0xFAE, usb:08e6/3437:libudev:0:/dev/bus/usb/008/018 (lun: 0)
00000003 ifdhandler.c:489:IFDHGetCapabilities() Reader supports 1 slot(s)
00000192 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x04CC, PID: 0x1122, path: /dev/bus/usb/008/002
00000183 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/002/001
00000077 readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Gemalto GemPC Twin 00 00
03633021 ifdhandler.c:1151:IFDHPowerICC() action: PowerUp, usb:08e6/3437:libudev:0:/dev/bus/usb/008/018 (lun: 0)
00055002 commands.c:233:CmdPowerOn Card absent or mute
00000004 ifdhandler.c:1204:IFDHPowerICC() PowerUp failed
00000003 eventhandler.c:378:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
00000003 eventhandler.c:387:EHStatusHandlerThread() Card inserted into Gemalto GemPC Twin 00 00
00000003 eventhandler.c:403:EHStatusHandlerThread() Error powering up card.
01620802 pcscdaemon.c:678:signal_trap() Received signal: 2
00000005 pcscdaemon.c:691:signal_trap() Preparing for suicide
00000017 pcscdaemon.c:678:signal_trap() Received signal: 2
00000004 readerfactory.c:1254:RFCleanupReaders() entering cleaning function
00000003 readerfactory.c:1263:RFCleanupReaders() Stopping reader: Gemalto GemPC Twin 00 00
00000004 eventhandler.c:148:EHDestroyEventHandler() Stomping thread.
00000005 ifdhandler.c:401:IFDHGetCapabilities() tag: 0xFB1, usb:08e6/3437:libudev:0:/dev/bus/usb/008/018 (lun: 0)
00000003 ifdhandler.c:401:IFDHGetCapabilities() tag: 0xFB2, usb:08e6/3437:libudev:0:/dev/bus/usb/008/018 (lun: 0)
00000002 eventhandler.c:173:EHDestroyEventHandler() Request stoping of polling thread
00000003 ifdhandler.c:366:IFDHStopPolling() usb:08e6/3437:libudev:0:/dev/bus/usb/008/018 (lun: 0)
00401452 eventhandler.c:469:EHStatusHandlerThread() Die
00000211 eventhandler.c:188:EHDestroyEventHandler() Thread stomped.
00000004 readerfactory.c:985:RFUnInitializeReader() Attempting shutdown of Gemalto GemPC Twin 00 00.
00000006 ifdhandler.c:293:IFDHCloseChannel() usb:08e6/3437:libudev:0:/dev/bus/usb/008/018 (lun: 0)
00002768 readerfactory.c:861:RFUnloadReader() Unloading reader driver.
00000035 winscard_svc.c:130:ContextsDeinitialize() remaining threads: 0
00000002 pcscdaemon.c:630:at_exit() cleaning /var/run/pcscd

The log contains messages from pcscd itself and also messages from the drivers. It may not be easy to differentiate the two sources of messages. The file name indicates the source.

Colorization

Lines have a different color depending on the importance of the log message. pcscd uses 4 log levels:

• debug (in black)
• info (in blue)
• error (in magenta)
• critical (in red)

In the previous example we have one sample of each level.

These two lines are from the CCID driver:

00055002 commands.c:233:CmdPowerOn Card absent or mute
00000004 ifdhandler.c:1204:IFDHPowerICC() PowerUp failed

This two lines are from pcscd:

00000003 eventhandler.c:387:EHStatusHandlerThread() Card inserted into Gemalto GemPC Twin 00 00
00000003 eventhandler.c:403:EHStatusHandlerThread() Error powering up card.

You may note that the CCID driver uses a higher level when logging a power up failure. Maybe that should be changed.

Time information

Each log line also contains a number on the first column. This is the time difference with the previous log line. This information is useful to detect timeout issues and also to perform some performance profiling using the pcscd_perfs.py tool.
The time information was used to improve performances. See "RAM and CPU improvements in pcsc-lite 1.6.x" for example.

Logs redirection

When you have a problem and I ask for logs, the best way to generate them is to redirect the output of pcscd to a file and send me the generated file.

By default the colorization is disabled when the pcscd output is redirected (using pcscd --foreground > log.txt) but it is possible to force the colorization using -T or --color. Colorized logs are much more easy to read for me.

Generating a colorized log file

The magic line to generate a log file with color is:

sudo pcscd --foreground --debug --apdu --color | tee log.txt

The use of the tee command will allow to redirect the pcscd output in the log file and also send this output to the screen. You can then also see the log and stop pcscd after the problem you want to report occurs.

You can use cat log.txt to display the log and you should see the colors. If you edit the log.txt file you should see control characters.

Conclusion

If I get nicer log files it will be more easy for me to spot problems. Logs are very important and in general the only way to find issues.