Important!

Blog moved to https://blog.apdu.fr/

I moved my blog from https://ludovicrousseau.blogspot.com/ to https://blog.apdu.fr/ . Why? I wanted to move away from Blogger (owne...

Showing posts with label debug. Show all posts
Showing posts with label debug. Show all posts

Friday, March 17, 2023

FAQ: wintypes.h or winscard.h not found

One of the most popular search requests that bring people on my website https://pcsclite.apdu.fr/ is about wintypes.h not found.

Problem

For example you try to compile something and get the error:

smartcard/scard/helpers.c:28:10: fatal error: winscard.h: No such file or directory
 #include <winscard.h>
          ^~~~~~~~~~~~ 

Solution

The PC/SC header files (winscard.h, wintypes.h and some others) are provided by the development pcsclite package.

  • for Debian, Ubuntu or derivatives the package is pcsclite-dev
  • for RedHat, Fedora and derivatives the package is pcsc-lite-devel
  • for other Unixes, use your favourite search engine 😜

You install the correct package and you try again to build your software.

Conclusion

I hope this blog article will be correctly indexed by search engines to help people find the solution.

Sunday, June 12, 2022

PCSC API spy, update

10 years ago I documented in "PCSC API spy, third try" a way to generate PC/SC API traces when using pcsc-lite.

Since then the ecosystem has changed. This article is an update of the previous blog article with more up-to-date information.

Changes

  • The pcsc-spy.py command has been renamed pcsc-spy (in 2012)
  • The libpcscspy.so library has been moved from /usr/lib/ to /usr/lib/x86_64-linux-gnu/ (for Intel 64-bits CPU systems)
  • opensc-tool can't be used with LD_PRELOAD= any more

Demo

As before we have two cases for the use of libpcsclite.so.1.

Applications linked with libpcsclite.so.1

This is the case of the pcsc_scan command for example.

You can use the ldd command to know what library has been dynamically linked at build time:

$ ldd /usr/bin/pcsc_scan 
	linux-vdso.so.1 (0x00007fffac11b000)
	libpcsclite.so.1 => /lib/x86_64-linux-gnu/libpcsclite.so.1 (0x00007f85a5f24000)
	libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007f85a5f03000)
	libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007f85a5d2a000)
	/lib64/ld-linux-x86-64.so.2 (0x00007f85a5f4f000)

You can use the LD_PRELOAD solution by doing:

In on terminal you run the pcsc-spy program. In another terminal you run:

$ LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libpcscspy.so.0 pcsc_scan -r
libpcsclite_nospy.so.1: cannot open shared object file: No such file or directory
No reader found.

In the first terminal you get the trace:

$ pcsc-spy 
SCardEstablishContext
 i dwScope: SCARD_SCOPE_SYSTEM (0x00000002)
 o hContext: 0x0E4C693B
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.002456]
SCardGetStatusChange
 i hContext: 0x0E4C693B
 i dwTimeout: 0x00000000 (0)
 i cReaders: 1
 i szReader: \\?PnP?\Notification
 i  dwCurrentState:  (0x00000000)
 i  dwEventState: SCARD_STATE_IGNORE, SCARD_STATE_UNKNOWN, SCARD_STATE_UNAVAILABLE, SCARD_STATE_EMPTY, SCARD_STATE_INUSE, SCARD_STATE_MUTE (0x55EDE352031D)
 i  Atr length: 0x55EDE352032C (94480209412908)
 i  Atr: NULL
 o szReader: \\?PnP?\Notification
 o  dwCurrentState:  (0x00000000)
 o  dwEventState:  (0x00000000)
 o  Atr length: 0x55EDE352032C (94480209412908)
 o  Atr: NULL
 => Command timeout. (SCARD_E_TIMEOUT [0x8010000A])  [0.007774]
SCardListReaders
 i hContext: 0x0E4C693B
 i mszGroups: (null)
 o pcchReaders: 0x00000001
 o mszReaders: NULL
 => Cannot find a smart card reader. (SCARD_E_NO_READERS_AVAILABLE [0x8010002E])  [0.000908]
SCardListReaders
 i hContext: 0x0E4C693B
 i mszGroups: (null)
 o pcchReaders: 0x00000001
 o mszReaders: NULL
 => Cannot find a smart card reader. (SCARD_E_NO_READERS_AVAILABLE [0x8010002E])  [0.000531]

Thread 1/1
Results sorted by total execution time
total time: 0.011769 sec
0.007774 sec (  1 calls) 66.06% SCardGetStatusChange
0.002456 sec (  1 calls) 20.87% SCardEstablishContext
0.001439 sec (  2 calls) 12.23% SCardListReaders

Application loading libpcsclite.so.1

In this case you need to modify the system configuration to replace the libpcsclite.so.1 library. This is done by the install_spy.sh script. You only need to run the script once.

$ sudo bash /usr/share/doc/libpcsclite-dev/install_spy.sh
Using directory: /lib/x86_64-linux-gnu
Spying library is: /lib/x86_64-linux-gnu/libpcscspy.so.0

On Debian (and derivatives like Ubuntu) and with pcsc-lite version 1.9.8 and more the script is provided by the libpcsclite-dev package.

In on terminal you run the pcsc-spy program. In another terminal you run the program you want to spy. For example:

$ opensc-tool -a
No smart card readers found.
Failed to connect to reader: No readers found

In the first terminal you get the trace:

SCardEstablishContext
 i dwScope: SCARD_SCOPE_USER (0x00000000)
 o hContext: 0x2667F6DA
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.005316]
SCardListReaders
 i hContext: 0x2667F6DA
 i mszGroups: (null)
 o pcchReaders: 0x00000001
 o mszReaders: NULL
 => Cannot find a smart card reader. (SCARD_E_NO_READERS_AVAILABLE [0x8010002E])  [0.000079]
SCardReleaseContext
 i hContext: 0x2667F6DA
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000074]

Thread 1/1
Results sorted by total execution time
total time: 0.007195 sec
0.005316 sec (  1 calls) 73.88% SCardEstablishContext
0.000079 sec (  1 calls)  1.10% SCardListReaders
0.000074 sec (  1 calls)  1.03% SCardReleaseContext

Do not forget to restore the system configuration using the uninstall_spy.sh script.

$ sudo bash /usr/share/doc/libpcsclite-dev/uninstall_spy.sh
Using directory: /lib/x86_64-linux-gnu

Redirection in a file

It is still possible to redirect the traces in a file. Instead of running pcsc-spy you do:

$ mkfifo ~/pcsc-spy
$ cat ~/pcsc-spy > logfile

And in another terminal you start the application as indicated above (i.e. using LD_PRELOAD= or after running install_spy.sh)

You can then analyse the logs later using:

$ pcsc-spy logfile

Remarks

Bugs found

I note that SCardReleaseContext() is not always called by pcsc_scan before exit. I just fixed this problem in pcsc-tools.

Install/uninstall

It is important to run the uninstall_spy.sh script to undo the changes made by the install_spy.sh script.

It is important you undo the changes before any execution of the ldconfig (configure dynamic linker run-time bindings) administration command. ldconfig is used, for example, during the installation of a package.

If you run uninstall_spy.sh after an execution of ldconfig you may get a broken libpcsclite installation with an error like:

$ pcsc_scan 
pcsc_scan: error while loading shared libraries: libpcsclite.so.1: cannot open shared object file: No such file or directory

To fix te problem you can force reinstall the libpcsclite1 (or equivalent) package.

Order of execution

It is important to start pcsc-spy before the application you want to spy. If you start pcsc-spy after the application you have 2 cases:

  1. if the fifo file ~/pcsc-spy does not yet exist then pcsc-spy will display nothing
  2. if the fifo file ~/pcsc-spy already exists then libpcscspy.so will use it to send logs and will be blocked until something reads the file (pcsc-spy or the cat command to redirect the content)

Conclusion

I hope this update is useful.

if you have ideas to improve the logs please contact me.

Thursday, March 1, 2018

Level 1.5 smart card support on macOS

In a previous article "Level 1 smart card support on Mac OS X" I described some simple commands to check if the smart card stack is working correctly on a macOS system.

By re-reading the presentation "Working with Smart Cards: macOS and Security" by Richard Purves I discovered a new command.

I already knew "system_profiler SPUSBDataType" to list the USB devices. I mentioned it in "Level 1 smart card support on Mac OS X" to check the USB reader is seen by the system. But system_profiler provides a better command for smart cards.

SPSmartCardsDataType

system_profiler has another very interesting command: system_profiler SPSmartCardsDataType

Clean macOS installation

Example 1:
$ system_profiler SPSmartCardsDataType
SmartCards:

    Readers:

      #01: Cherry KC 1000 SC (ATR:<3b7f9600 00803180 65b08441 3df612ff fe829000>)

    Reader Drivers:

      #01: org.debian.alioth.pcsclite.smartcardccid:1.4.27 (/usr/libexec/SmartCardServices/drivers/ifd-ccid.bundle)

    Tokend Drivers:

    SmartCard Drivers:

      #01: com.apple.CryptoTokenKit.pivtoken:1.0 (/System/Library/Frameworks/CryptoTokenKit.framework/PlugIns/pivtoken.appex)

    Available SmartCards (keychain):

    Available SmartCards (token):


You get a lot of useful information:
  1. list of smart card readers
  2. list of installed reader drivers
  3. list of tokend drivers
  4. list of smart card drivers
  5. available smart cards (keychain)
  6. available smart cards (token)

What you can see in my example:
  • I use a Cherry KC 1000 SC reader. A card is inserted in the reader and you see the ATR.
  • by default Apple provides a CCID driver
  • by default Apple provides a PIV CryptoTokenKit token to support Personal Identity Verification cards

Using SafeNet Authentication Client

Example 2:
$ system_profiler SPSmartCardsDataType 
SmartCards:

    Readers:

      #01: Gemalto PC Twin Reader (ATR:<3b7f9600 00803180 65b08503 00ef120f fe829000>)

    Reader Drivers:

      #01: org.debian.alioth.pcsclite.smartcardccid:1.4.27 (/usr/libexec/SmartCardServices/drivers/ifd-ccid.bundle)
      #02: com.SafeNet.eTokenIfdh:9.0.0.0 (/Library/Frameworks/eToken.framework/Versions/A/aks-ifdh.bundle)
      #03: com.gemalto.ifd-bccid:1.0 (/usr/local/libexec/SmartCardServices/drivers/ifd-bccid.bundle)
      #04: org.debian.alioth.pcsclite.smartcardccid:1.4.27 (/usr/local/libexec/SmartCardServices/drivers/ifd-ccid-SafeNet-eToken5300.bundle)
      #05: (null):(null) (/Library/Frameworks/eToken.framework/Versions/A/ikey-ifdh.bundle)

    Tokend Drivers:

      #01: com.Safenet.eTokend:9.0 (/Library/Frameworks/eToken.framework/Versions/A/eTokend.tokend)

    SmartCard Drivers:

      #01: com.apple.CryptoTokenKit.pivtoken:1.0 (/System/Library/Frameworks/CryptoTokenKit.framework/PlugIns/pivtoken.appex)
      #02: com.gemalto.Gemalto-Smart-Card-Token.PKCS11-Token:1.0 (/Library/Frameworks/eToken.framework/Versions/A/SafeNet Authentication Client.app/Contents/PlugIns/PKCS11 Token.appex)

    Available SmartCards (keychain):

        com.gemalto.Gemalto-Smart-Card-Token.PKCS11-Token:9A522A4489DFA3DE:

          #01: Kind: private RSA 2048-bit, Certificate: <1cc4a99c 25e2b4eb 381850d2 e8e7a9a8 8d258b31>, Usage: Sign Decrypt Unwrap 
          #02: Kind: private RSA 2048-bit, Certificate: <425fa8c1 27ad75a1 aec73183 2b053b41 38befe7f>, Usage: Sign Decrypt Unwrap 
          #03: Kind: private RSA 4096-bit, Certificate: <16b5321b d4c7f3e0 e68ef3bd d2b03aee b23918d1>, Usage: Sign Decrypt Unwrap 
          #04: Kind: private RSA 4096-bit, Certificate: <16b5321b d4c7f3e0 e68ef3bd d2b03aee b23918d1>, Usage: Sign Decrypt Unwrap 
          #05: Kind: private RSA 2048-bit, Certificate: <31fde547 b4ca58d4 7b6231c2 62730efd 8c7538a1>, Usage: Sign Derive Decrypt Unwrap 

    Available SmartCards (token):

        com.gemalto.Gemalto-Smart-Card-Token.PKCS11-Token:9A522A4489DFA3DE:

          #01: Kind: private RSA 2048-bit, Certificate: <1cc4a99c 25e2b4eb 381850d2 e8e7a9a8 8d258b31>, Usage: Sign Decrypt Unwrap 
          #02: Kind: private RSA 2048-bit, Certificate: <425fa8c1 27ad75a1 aec73183 2b053b41 38befe7f>, Usage: Sign Decrypt Unwrap 
          #03: Kind: private RSA 4096-bit, Certificate: <16b5321b d4c7f3e0 e68ef3bd d2b03aee b23918d1>, Usage: Sign Decrypt Unwrap 
          #04: Kind: private RSA 2048-bit, Certificate: <31fde547 b4ca58d4 7b6231c2 62730efd 8c7538a1>, Usage: Sign Derive Decrypt Unwrap 
          #05: Certificate <1a222d8f 7458d082 d413fbdb 40c85f56 f48def63>


In this second example I installed SAC (SafeNet Authentication Client) from Gemalto. You can see some differences:
  • more reader drivers are installed
  • a tokend driver is installed
  • another SmartCard (Crypto Token Kit or CTK) driver is installed 
  • the card inserted in the reader is available in the keychain

Conclusion

This command provides information of a higher level that pcsctest.
You know what drivers (for readers and for cards) are installed.

Tuesday, February 23, 2016

PCSC framework spy: broken since Mac OS X Yosemite

In "PCSC API spy, on Mac OS X" I proposed a way to spy on all PC/SC calls of an application.

A few months later Yosemite was available and my spying library does not work any more ☹.

PCSC framework replacement: fails

Example of failure:
$ DYLD_FRAMEWORK_PATH=/tmp pcsc_scan
PC/SC device scanner
V /Users/lroussea/Documents/sc/costa/pcsc-tools (c) 2001-2011, Ludovic Rousseau 
Compiled with PC/SC lite version: 1.4.0
SCardEstablishContext: Service not available.

Spy output (in a second terminal window):
$ ./pcsc-spy
SCardEstablishContext
 i dwScope: SCARD_SCOPE_SYSTEM (0x00000002)
 o hContext: 0x00000000
 => Service not available. (SCARD_E_NO_SERVICE [0x8010001D])  [0.000001109]
SCardReleaseContext
 i hContext: 0x00000000
 => Invalid handle. (SCARD_E_INVALID_HANDLE [0x80100003])  [0.000000006]

Results sorted by total execution time
total time: 0.001138 sec
0.001109 sec (  1 calls) 97.45% SCardEstablishContext
0.000006 sec (  1 calls)  0.53% SCardReleaseContext

If I run pcsc_scan alone, with no PC/SC spy, then the command runs as expected.

Something detects the usage of a new PCSC framework and rejects the first call. I guess the culprit is the original PCSC framework itself and this is a new security feature from Yosemite.

Running the application as root (using sudo) does not help.

SIP: System Integrity Protection

A new change since El Capitan is that the use of DYLD_FRAMEWORK_PATH does not work for programs in protected directories, like /usr/bin/.
$ type pcsctest
pcsctest is hashed (/usr/bin/pcsctest)

$ DYLD_FRAMEWORK_PATH=/tmp pcsctest

MUSCLE PC/SC Lite Test Program

Testing SCardEstablishContext    : Command successful.
Testing SCardGetStatusChange 
Please insert a working reader   : Command successful.
Testing SCardListReaders         : Command successful.
Reader 01: Gemalto PC Twin Reader
Enter the reader number          : ^C

Here the command succeeds but nothing is sent over the spy pipe.

In Yosemite I could use DYLD_FRAMEWORK_PATH=/tmp but with the same results as described above. On El Capitan the dynamic linker dyld just ignores DYLD_FRAMEWORK_PATH.

Another way to check that is to use lldb, the debugger provided with Xcode.

$ lldb pcsctest
(lldb) target create "pcsctest"
Current executable set to 'pcsctest' (x86_64).
(lldb) run
error: process exited with status -1 (cannot attach to process due to System Integrity Protection)
(lldb) quit

Conclusion

I know no way to spy the PC/SC calls done by an application on Mac OS X (with version >= 10.10).

This is problematic because PC/SC is still unstable on El Capitan. See "OS X El Capitan and smart cards: known bugs" for example. In some cases it would really help to know what PC/SC call returns an error to be able to:
  • Report the error to Apple if it is a bug in PC/SC
  • Tell the customer that it is a bug on Apple side
  • Try to find a way to avoid the problem, if possible

Wednesday, October 8, 2014

CCID USB spy using Wireshark

Sometimes you need to know exactly what is happening at the USB level. You have two options:
  • use a hardware USB analyzer
  • use a software USB analyzer
Since I do not have the budget to buy a hardware USB monitor I will use the software solution.

Wireshark

Since some time, it is possible to use the wonderful Wireshark program to display and analyze USB frames. Wireshark is mainly used for analyzing network packets but it is also possible to display USB packets. Wireshark is even able to display the CCID commands inside the USB packets.



How-to

A documentation is available at USB capture setup and also at Capturing USB data through Wireshark.
This article describes what I did.

Setup the kernel

You first need to load the usbmon kernel module.

$ sudo modprobe usbmon

tshark (a command line tool) should now be able to capture on usbmon interfaces. Check it using:
$ tshark -D
1. eth0
2. any
3. lo (Loopback)
4. nflog
5. nfqueue
6. usbmon1
7. usbmon2

In my case I have 2 USB buses labeled usbmon1 and usbmon2.

Capture the USB frames

Before capturing the USB frames you need to know on which USB bus is connected your device.

Identify the device USB bus

$ lsusb 
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 004: ID 08e6:3437 Gemplus GemPC Twin SmartCard Reader
Bus 002 Device 002: ID 80ee:0021 VirtualBox USB Tablet
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub

In my case the device I want to study is on the bus 002 so I will use usbmon2.

Start the capture

$ tshark -i usbmon2 -w trace1.pcap
Capturing on 'usbmon2'
tshark: The capture session could not be initiated on interface 'usbmon2' (Can't open USB bus file /sys/kernel/debug/usb/usbmon/2t: Permission denied).
Please check to make sure you have sufficient permissions, and that you have the proper interface or pipe specified.

For security reasons tshark refuses to be run as root. So I needed to change some file access rights.

$ sudo chmod +rx /sys/kernel/debug/
$ sudo chmod a+rw /sys/kernel/debug/usb/usbmon/2t

Then (re)start tshark and use Ctrl-C to stop after some traffic has been captured.
$ tshark -i usbmon2 -w trace1.pcap
Capturing on 'usbmon2'
1270 tshark: Can't get packet-drop statistics: Can't open USB stats file /sys/kernel/debug/usb/usbmon/2s: Permission denied
Please report this to the Wireshark developers.
http://bugs.wireshark.org/
(This is not a crash; please do not report it as such.)

Capture analysis

The file trace1.pcap contains the USB frames and can be displayed using the graphical interface of Wireshark.

Enable the CCID decoder

Unless you can read the CCID protocol from hexadecimal, it is a good idea to tell Wireshark to decode the USB frames as USBCCID.
Go in the menu "Analyze" -> "Decode as..." and select USBCCID in the dialog.



Wireshark will then display the USB frames with nice CCID names:


Here you can see a CCID Power On command.
  • The command name is displayed in the top window: "Packet - PC to Reader: ICC Power On"
  • And the content of the command (the 10 last bytes specific to CCID) are documented in the lower window: "Message Type: PC_to_RDR_IccPowerOn (0x62)", etc.

I do not expect every one to use Wireshark to look at CCID frames. But if you have a problem with a CCID reader and wants to know exactly what is happening Wireshark can help you for a very very limited budget (Wireshark is a free software under GNU GPL v2 license).

This blog article is also a way for me to document how to do it for the next time :-)

Conclusion

Wireshark is a great tool.
Linux is a great kernel.
Debian GNU/Linux is a great operating system.

Thursday, April 24, 2014

USB issues with a Raspberry Pi

Some people report problems with my CCID driver and a Raspberry Pi. The problem is not with the CCID driver but with the Raspberry Pi itself.



I don't know if the problem is hardware, software or a combination of the two. I found a description of the problem on the excellent website yoctopuce.com. For example from the article "Cook and Hold with Raspberry Pi (video)" you can read:

There is one caveat on the Raspberry Pi : the USB support is still somewhat buggy perfectible, and we will need to configure it to make it work reliably. The problem is, the RasPi will occasionally drop USB packets for "full-speed" peripherals (such as keyboard, mouse, modems, as well as some audio devices) when working in standard "high-speed" mode. The problem is less acute with the most recent firmware, but it is not completely solved. The only reliable workaround for now is to force all peripherals to run in "full-speed" mode. This will have the negative side effect of limiting all peripherals (including the on-board network adapter) to 1.5 MBytes/s, but anyway, the Raspberry Pi is not designed to be a race horse...

To force USB to run in "full-speed" mode, simply add dwc_otg.speed=1 to the /boot/cmdline.txt file, as follows:

dwc_otg.lpm_enable=0 console=ttyAMA0,115200 kgdboc=ttyAMA0,115200
dwc_otg.speed=1 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4
elevator=deadline rootwait

Thursday, March 20, 2014

Level 1 smart card support on Mac OS X

It may not be easy to check if a smart card stack works or not. I will explain what you can do as a first step to check your smart card stack on Mac OS X.

pcsctest

Apple provides a command line tool pcsctest. It is an evolution of testpcsc provided by the "official" pcsc-lite.

The Apple pcsctest source code is available at http://opensource.apple.com/source/SmartCardServices/SmartCardServices-55111/src/PCSC/testpcsc.c

The good news is that this command line tool is installed by default. So every Mac OS X install should have it out of the box.

Command line tool

To run a command line tool you need to start the Terminal application from the /Applications/Utilities/ directory.
Terminal icon


You will then get a Terminal window with a prompt
$

Normal execution

In green the commands entered by the user.
In yellow the important information.

If your reader is connected and a smart card is inserted you should get something like:
$ pcsctest 

MUSCLE PC/SC Lite Test Program

Testing SCardEstablishContext    : Command successful.
Testing SCardGetStatusChange 
Please insert a working reader   : Command successful.
Testing SCardListReaders         : Command successful.
Reader 01: Gemplus GemPC Twin 00 00
Enter the reader number          : 1
Waiting for card insertion         
                                 : Command successful.
Testing SCardConnect             : Command successful.
Testing SCardStatus              : Command successful.
Current Reader Name              : Gemplus GemPC Twin 00 00
Current Reader State             : 0x34
Current Reader Protocol          : 0x0
Current Reader ATR Size          : 9 (0x9)
Current Reader ATR Value         : 3B 65 00 00 20 63 CB A6 A0 
Testing SCardDisconnect          : Command successful.
Testing SCardReleaseContext      : Command successful.
Testing SCardEstablishContext    : Command successful.
Testing SCardGetStatusChange 
Please insert a working reader   : Command successful.
Testing SCardListReaders         : Command successful.
Reader 01: Gemplus GemPC Twin 00 00
Enter the reader number          : 1
Waiting for card insertion         
                                 : Command successful.
Testing SCardConnect             : Command successful.
Testing SCardStatus              : Command successful.
Current Reader Name              : Gemplus GemPC Twin 00 00
Current Reader State             : 0x34
Current Reader Protocol          : 0x0
Current Reader ATR Size          : 9 (0x9)
Current Reader ATR Value         : 3B 65 00 00 20 63 CB A6 A0 
Testing SCardDisconnect          : Command successful.
Testing SCardReleaseContext      : Command successful.

PC/SC Test Completed Successfully !

You should note:
  • the reader name Gemplus GemPC Twin 00 00
  • the card ATR 3B 65 00 00 20 63 CB A6 A0
In this case the reader is correctly found and the communication with the card is working.

You can then use the online Smart card ATR parsing tool to check the ATR corresponds to the card you inserted. In the present case it is a French banking card.

No reader connected

$ pcsctest 

MUSCLE PC/SC Lite Test Program

Testing SCardEstablishContext    : Service not available.

On Mac OS X the PC/SC service (in fact the pcscd daemon) is started by the securityd process at boot and when a USB smart card reader is connected.
So if no reader is connected you get the error: "Service not available" because pcscd is not yet running.

No smart card inserted

$ pcsctest 

MUSCLE PC/SC Lite Test Program

Testing SCardEstablishContext    : Command successful.
Testing SCardGetStatusChange 
Please insert a working reader   : Command successful.
Testing SCardListReaders         : Command successful.
Reader 01: Gemplus GemPC Twin 00 00
Enter the reader number          : 1
Waiting for card insertion

The program is then waiting for a card insertion.

If you have a card inserted and you do not get the ATR or an error then you have a problem.

If you insert a card and get the error "Card is unpowered" then you may have inserted the card the wrong way (or your card is dead).

System information

If your reader is connected but you can't see it with pcsctest then maybe the USB device is not seen by Mac OS X.

You can use the System Information application from the /Applications/Utilities/ directory.
System Information icon


In the application you select the USB subsection in the Hardware section and can see all the USB devices known by the system.
If you can't see your USB smart card reader then you have a USB issue, not a PC/SC issue.

Command line

You can also use the equivalent command in the Terminal:

$ system_profiler SPUSBDataType

Conclusion

These first steps are easy to execute on Mac OS X. If the pcsctest test succeeds then you can be confident that the smart card reader and the PC/SC layer are working correctly.

If the pcsctest test fails then you need to go to a level 2 smart card support on Mac OS X.

Saturday, February 8, 2014

PCSC API spy, on Mac OS X

In a previous article "PCSC API spy, third try" I described a way to get a nice log of all the PC/SC calls made by an application. The example was using an application on GNU/Linux. A version for Mac OS X was planned but not yet available at that time.

I now realise I finished the Mac OS X version of pcsc-spy but have not yet blogged about it. It is time to fix this.

Installation

pcsc-spy is part of (the official) pcsc-lite. You can get it from the PCSC lite project web page. The latest version of pcsc-lite as I write this blog entry is 1.8.10.

$ curl -O https://alioth.debian.org/frs/download.php/file/3963/pcsc-lite-1.8.10.tar.bz2
$ tar xjf pcsc-lite-1.8.10.tar.bz2
$ cd pcsc-lite-1.8.10/
$ ./configure
[...]
$ cd src/spy
$ make
$ make framework

Now you can find a PCSC.framework directory that is the equivalent of libpcscspy.so on GNU/Linux.

The installation is not automatic but very easy. You copy the PCSC.framework directory in /tmp

$ cp -a PCSC.framework /tmp

Copy the official PCSC.framework (binary only) in /tmp

$ cp /System/Library/Frameworks/PCSC.framework/PCSC /tmp

Since we use the temporary directory /tmp the log/debug files will be automatically erased on the next system boot. No side effect.

Execution

In a Terminal application window (shell) run the pcsc-spy command:

$ ./pcsc-spy

In another Terminal application windows run the application you want to debug:

$ DYLD_FRAMEWORK_PATH=/tmp pcsctest

MUSCLE PC/SC Lite Test Program

Testing SCardEstablishContext    : Command successful.
Testing SCardGetStatusChange 
Please insert a working reader   : Command successful.
Testing SCardListReaders         : Command successful.
Reader 01: Feitian bR301 00 00
Enter the reader number          : 1
Waiting for card insertion         
                                 : Command successful.
Testing SCardConnect             : Command successful.
Testing SCardStatus              : Command successful.
Current Reader Name              : Feitian bR301 00 00
Current Reader State             : 0x34
Current Reader Protocol          : 0x0
Current Reader ATR Size          : 12 (0xc)
Current Reader ATR Value         : 3B A7 00 40 18 80 65 A2 08 01 01 52 
Testing SCardDisconnect          : Command successful.
Testing SCardReleaseContext      : Command successful.
Testing SCardEstablishContext    : Command successful.
Testing SCardGetStatusChange 
Please insert a working reader   : Command successful.
Testing SCardListReaders         : Command successful.
Reader 01: Feitian bR301 00 00
Enter the reader number          : 1
Waiting for card insertion         
                                 : Command successful.
Testing SCardConnect             : Command successful.
Testing SCardStatus              : Command successful.
Current Reader Name              : Feitian bR301 00 00
Current Reader State             : 0x34
Current Reader Protocol          : 0x0
Current Reader ATR Size          : 12 (0xc)
Current Reader ATR Value         : 3B A7 00 40 18 80 65 A2 08 01 01 52 
Testing SCardDisconnect          : Command successful.
Testing SCardReleaseContext      : Command successful.

PC/SC Test Completed Successfully !

In the first Terminal window you will get the colorfull (oh yeah!) log output:
SCardEstablishContext
 i dwScope: SCARD_SCOPE_SYSTEM (0x00000002)
 o hContext: 0x0103253B
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000722]
SCardGetStatusChange
 i hContext: 0x0103253B
 i dwTimeout: 0xFFFFFFFF (4294967295)
 i cReaders: 0
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000044]
SCardListReaders
 i hContext: 0x0103253B
 i mszGroups: (null)
 o pcchReaders: 0x00000015
 o mszReaders: NULL
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000059]
SCardListReaders
 i hContext: 0x0103253B
 i mszGroups: (null)
 o pcchReaders: 0x00000015
 o mszReaders: Feitian bR301 00 00
 o mszReaders: 
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000042]
SCardGetStatusChange
 i hContext: 0x0103253B
 i dwTimeout: 0xFFFFFFFF (4294967295)
 i cReaders: 1
 i szReader: Feitian bR301 00 00
 i  dwCurrentState: SCARD_STATE_EMPTY (0x00000010)
 i  dwEventState: SCARD_STATE_IGNORE, SCARD_STATE_CHANGED, SCARD_STATE_UNKNOWN, SCARD_STATE_UNAVAILABLE, SCARD_STATE_EXCLUSIVE, SCARD_STATE_INUSE, SCARD_STATE_EMPTY, SCARD_STATE_MUTE, SCARD_STATE_PRESENT, SCARD_STATE_UNPOWERED, SCARD_STATE_ATRMATCH (0x00007FFF)
 i  Atr length: 0x00000012 (18)
 i  Atr: 00 00 00 00 68 70 E7 0D 01 00 00 00 01 00 00 00 00 00
 o szReader: Feitian bR301 00 00
 o  dwCurrentState: SCARD_STATE_EMPTY (0x00000010)
 o  dwEventState: SCARD_STATE_CHANGED, SCARD_STATE_PRESENT (0x00000022)
 o  Atr length: 0x0000000C (12)
 o  Atr: 3B A7 00 40 18 80 65 A2 08 01 01 52
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000163]
SCardConnect
 i hContext: 0x0103253B
 i szReader Feitian bR301 00 00
 i dwShareMode: SCARD_SHARE_SHARED (0x00000002)
 i dwPreferredProtocols: 0x00000003 (T=0, T=1)
 i phCard 0x00007FFF (32767)
 i pdwActiveProtocol 0x00000000 (0)
 o phCard 0x0001616A (90474)
 o dwActiveProtocol: T=0 (0x00000001)
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000411198]
SCardStatus
 i hCard: 0x0001616A
 i pcchReaderLen 0x00000034 (52)
 i pcbAtrLen 0x00000021 (33)
 o cchReaderLen 0x00000014 (20)
 o mszReaderName Feitian bR301 00 00
 o dwState 0x00000034 (52)
 o dwProtocol 0x00000001 (1)
 o bAtrLen 0x0000000C (12)
 o bAtr 3B A7 00 40 18 80 65 A2 08 01 01 52
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000473]
SCardDisconnect
 i hCard: 0x0001616A
 i dwDisposition: SCARD_UNPOWER_CARD (0x00000002)
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000594971]
SCardReleaseContext
 i hContext: 0x0103253B
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000209]
SCardEstablishContext
 i dwScope: SCARD_SCOPE_SYSTEM (0x00000002)
 o hContext: 0x01035D3C
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000541]
SCardGetStatusChange
 i hContext: 0x01035D3C
 i dwTimeout: 0xFFFFFFFF (4294967295)
 i cReaders: 0
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000033]
SCardListReaders
 i hContext: 0x01035D3C
 i mszGroups: (null)
 o pcchReaders: 0x00000015
 o mszReaders: NULL
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000034]
SCardListReaders
 i hContext: 0x01035D3C
 i mszGroups: (null)
 o pcchReaders: 0x00000015
 o mszReaders: Feitian bR301 00 00
 o mszReaders: 
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000039]
SCardGetStatusChange
 i hContext: 0x01035D3C
 i dwTimeout: 0xFFFFFFFF (4294967295)
 i cReaders: 1
 i szReader: Feitian bR301 00 00
 i  dwCurrentState: SCARD_STATE_EMPTY (0x00000010)
 i  dwEventState: SCARD_STATE_CHANGED, SCARD_STATE_PRESENT (0x00000022)
 i  Atr length: 0x0000000C (12)
 i  Atr: 3B A7 00 40 18 80 65 A2 08 01 01 52
 o szReader: Feitian bR301 00 00
 o  dwCurrentState: SCARD_STATE_EMPTY (0x00000010)
 o  dwEventState: SCARD_STATE_CHANGED, SCARD_STATE_PRESENT (0x00000022)
 o  Atr length: 0x0000000C (12)
 o  Atr: 3B A7 00 40 18 80 65 A2 08 01 01 52
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000129]
SCardConnect
 i hContext: 0x01035D3C
 i szReader Feitian bR301 00 00
 i dwShareMode: SCARD_SHARE_SHARED (0x00000002)
 i dwPreferredProtocols: 0x00000003 (T=0, T=1)
 i phCard 0x0001616A (90474)
 i pdwActiveProtocol 0x00000001 (1)
 o phCard 0x00011242 (70210)
 o dwActiveProtocol: T=0 (0x00000001)
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000411238]
SCardStatus
 i hCard: 0x00011242
 i pcchReaderLen 0x00000034 (52)
 i pcbAtrLen 0x00000021 (33)
 o cchReaderLen 0x00000014 (20)
 o mszReaderName Feitian bR301 00 00
 o dwState 0x00000034 (52)
 o dwProtocol 0x00000001 (1)
 o bAtrLen 0x0000000C (12)
 o bAtr 3B A7 00 40 18 80 65 A2 08 01 01 52
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000465]
SCardDisconnect
 i hCard: 0x00011242
 i dwDisposition: SCARD_UNPOWER_CARD (0x00000002)
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000594863]
SCardReleaseContext
 i hContext: 0x01035D3C
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000369]

Results sorted by total execution time
total time: 4.221649 sec
1.189834 sec (  2 calls) 28.18% SCardDisconnect
0.822436 sec (  2 calls) 19.48% SCardConnect
0.001263 sec (  2 calls)  0.03% SCardEstablishContext
0.000938 sec (  2 calls)  0.02% SCardStatus
0.000578 sec (  2 calls)  0.01% SCardReleaseContext
0.000369 sec (  4 calls)  0.01% SCardGetStatusChange
0.000174 sec (  4 calls)  0.00% SCardListReaders

Analysis

  • PC/SC commands are in blue
  • Input arguments are in green
  • Output arguments are in mangenta
  • Errors are in bold red
  • The last part of the log contains some statistics about: functions called and times consumed by each of them

Raw log file

If you want to store a log file for a later analysis or if you want to send me a log trace it is better to store the log in raw format. You can do that (as on GNU/Linux) by doing:

$ mkfifo ~/pcsc-spy
$ cat ~/pcsc-spy > logfile
and run your PC/SC application.

The API trace is stored in the file logfile. It is displayed using:

$ pcsc-spy.py logfile

Documentation

The documentation is included with the pcsc-lite source code and is also available online at pcsc-spy.1 manpage.

Conclusion

It is easy to generate a nice PC/SC log on Mac OS X.

Friday, November 18, 2011

PCSC API spy, third try

[UPDATE from 2022]: see also "PCSC API spy, update".

I already blogged about how to spy the PCSC API in PCSC API spy for GNU systems and PCSC API spy, another way. But I am still not happy with the limitations and side effects.

Limitations of previous solutions

ltrace

ltrace is able to trace the calls to any library (including libpcsclite.so.1). But one major limitation is that it does not work if the library is not linked to the executable. It does not work when:
  • libpcsclite.so.1 is used by a library used by the executable (like a PKCS#11 library)
  • libpcsclite.so.1 is dynamically loaded using dlopen() as is done by OpenSC

Internal tracing

Internal tracing do not have the limitations of ltrace. But one major drawback is the need to rebuild pcsc-lite with a specific configuration. This may be very difficult or impossible to do on a production system.

Use an independent library

The new idea is to not need to rebuild pcsc-lite. Instead we will use a new library that will be placed between the PC/SC client and the PC/SC library. This new library will spy all the calls and send them to a pretty displayer.

+------------------+
|  PC/SC client    |
+------------------+
        |
+------------------+    +-------------+
| libpcscspy.so.0  | -> | pcsc-spy.py |
+------------------+    +-------------+
        |
+------------------+
| libpcsclite.so.1 |
+------------------+

Two configurations are available


To be able to spy the PC/SC layer the application flow must be modified so that all PC/SC calls are redirected.

Applications linked with libpcsclite.so.1


We will use the standard LD_PRELOAD loader option to load our spying library.

Example:
LD_PRELOAD=/usr/lib/libpcscspy.so opensc-tool -a

Application loading libpcsclite.so.1


This is the case for the PC/SC wrappers like pyscard (for Python) and pcsc-perl (for Perl). The LD_PRELOAD mechanism can't be used. Instead we replace the libpcsclite.so.1 library by the spying one.

Use install_spy.sh and uninstall_spy.sh to install and uninstall the spying library.

Using the spying library without pcsc-spy.py is not a problem but has side effects:
  • a line "libpcsclite_nospy.so.1: cannot open shared object file: No such file or directory" will be displayed
  • some CPU time will be lost because of the PC/SC calls redirection

Starting the spy tool


Direct output

$ pcsc-spy.py

Store for later use

If a command argument is passed we use it instead of the default ~/pcsc-spy FIFO file. It is then possible to record an execution log and use pcsc-spy.py multiple times on the same log.

To create the log file just do:

$ mkfifo ~/pcsc-spy
$ cat ~/pcsc-spy > logfile

and run your PC/SC application. The API trace is stored in the file logfile. It is displayed using:
$ pcsc-spy.py logfile

Example using OpenSC


Executed command

$ LD_PRELOAD=/usr/lib/libpcscspy.so opensc-tool -a
Using reader with a card: Gemalto GemPC Twin 00 00
3b:9f:95:81:31:fe:9f:00:65:46:53:05:30:06:71:df:00:00:00:81:61:0f:d9

API log

$ pcsc-spy.py
SCardEstablishContext
 i dwScope: SCARD_SCOPE_USER (0x00000000)
 o hContext: 0x0103E68C
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000219919]
SCardListReaders
 i hContext: 0x0103E68C
 i mszGroups: (null)
 o pcchReaders: 0x0000001A
 o mszReaders: NULL
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000128]
SCardListReaders
 i hContext: 0x0103E68C
 i mszGroups: (null)
 o pcchReaders: 0x0000001A
 o mszReaders: Gemalto GemPC Twin 00 00
 o mszReaders: 
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000101]
SCardGetStatusChange
 i hContext: 0x0103E68C
 i dwTimeout: 0x00000000 (0)
 i cReaders: 1
 i szReader: Gemalto GemPC Twin 00 00
 i  dwCurrentState:  (0x00000000)
 i  dwEventState:  (0x00000000)
 i  Atr length: 0x00000000 (0)
 i  Atr: 
 o szReader: Gemalto GemPC Twin 00 00
 o  dwCurrentState:  (0x00000000)
 o  dwEventState: SCARD_STATE_CHANGED, SCARD_STATE_PRESENT (0x00000022)
 o  Atr length: 0x00000017 (23)
 o  Atr: 3B 9F 95 81 31 FE 9F 00 65 46 53 05 30 06 71 DF 00 00 00 81 61 0F D9
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000184]
SCardConnect
 i hContext: 0x0103E68C
 i szReader Gemalto GemPC Twin 00 00
 i dwShareMode: SCARD_SHARE_SHARED (0x00000002)
 i dwPreferredProtocols: 0x00000003 (T=0, T=1)
 i phCard 0x02432010 (37953552)
 i pdwActiveProtocol 0x00000020 (32)
 o phCard 0x00015425 (87077)
 o dwActiveProtocol: T=1 (0x00000002)
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000020242]
SCarControl
 i hCard: 0x00015425
 i dwControlCode: CM_IOCTL_GET_FEATURE_REQUEST (0x42000D48)
 i bSendLength 0x00000000 (0)
 i bSendBuffer
 i  NULL
 o bRecvLength 0x00000012 (18)
 o bRecvBuffer
 o  0000 0A 04 42 33 00 0A 12 04 42 33 00 12 13 04 42 00 ..B3....B3....B.
 o  0010 00 01                                           ..
  parsing CM_IOCTL_GET_FEATURE_REQUEST results:
  Tag FEATURE_IFD_PIN_PROPERTIES is 0x4233000A
  Tag FEATURE_GET_TLV_PROPERTIES is 0x42330012
  Tag FEATURE_CCID_ESC_COMMAND is 0x42000001
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000130]
SCarControl
 i bSendBuffer
 i  NULL
 o bRecvLength 0x00000004 (4)
 o bRecvBuffer
 o  0000 00 00 07 00                                     ....
  parsing FEATURE_IFD_PIN_PROPERTIES results:
  wLcdLayout: 0 0
  bEntryValidationCondition: 7
  bTimeOut2: 0
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000334]
SCardDisconnect
 i hCard: 0x00015425
 i dwDisposition: SCARD_LEAVE_CARD (0x00000000)
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000362]
SCardGetStatusChange
 i hContext: 0x0103E68C
 i dwTimeout: 0x00000000 (0)
 i cReaders: 1
 i szReader: Gemalto GemPC Twin 00 00
 i  dwCurrentState: SCARD_STATE_CHANGED, SCARD_STATE_PRESENT (0x00000022)
 i  dwEventState: SCARD_STATE_CHANGED, SCARD_STATE_PRESENT (0x00000022)
 i  Atr length: 0x00000017 (23)
 i  Atr: 3B 9F 95 81 31 FE 9F 00 65 46 53 05 30 06 71 DF 00 00 00 81 61 0F D9
 o szReader: Gemalto GemPC Twin 00 00
 o  dwCurrentState: SCARD_STATE_CHANGED, SCARD_STATE_PRESENT (0x00000022)
 o  dwEventState: SCARD_STATE_PRESENT (0x00000020)
 o  Atr length: 0x00000017 (23)
 o  Atr: 3B 9F 95 81 31 FE 9F 00 65 46 53 05 30 06 71 DF 00 00 00 81 61 0F D9
 => Command timeout. (SCARD_E_TIMEOUT [0x8010000A])  [0.000000352]
SCardGetStatusChange
 i hContext: 0x0103E68C
 i dwTimeout: 0x00000000 (0)
 i cReaders: 1
 i szReader: Gemalto GemPC Twin 00 00
 i  dwCurrentState: SCARD_STATE_PRESENT (0x00000020)
 i  dwEventState: SCARD_STATE_PRESENT (0x00000020)
 i  Atr length: 0x00000017 (23)
 i  Atr: 3B 9F 95 81 31 FE 9F 00 65 46 53 05 30 06 71 DF 00 00 00 81 61 0F D9
 o szReader: Gemalto GemPC Twin 00 00
 o  dwCurrentState: SCARD_STATE_PRESENT (0x00000020)
 o  dwEventState: SCARD_STATE_PRESENT (0x00000020)
 o  Atr length: 0x00000017 (23)
 o  Atr: 3B 9F 95 81 31 FE 9F 00 65 46 53 05 30 06 71 DF 00 00 00 81 61 0F D9
 => Command timeout. (SCARD_E_TIMEOUT [0x8010000A])  [0.000000303]
SCardGetStatusChange
 i hContext: 0x0103E68C
 i dwTimeout: 0x00000000 (0)
 i cReaders: 1
 i szReader: Gemalto GemPC Twin 00 00
 i  dwCurrentState: SCARD_STATE_PRESENT (0x00000020)
 i  dwEventState: SCARD_STATE_PRESENT (0x00000020)
 i  Atr length: 0x00000017 (23)
 i  Atr: 3B 9F 95 81 31 FE 9F 00 65 46 53 05 30 06 71 DF 00 00 00 81 61 0F D9
 o szReader: Gemalto GemPC Twin 00 00
 o  dwCurrentState: SCARD_STATE_PRESENT (0x00000020)
 o  dwEventState: SCARD_STATE_PRESENT (0x00000020)
 o  Atr length: 0x00000017 (23)
 o  Atr: 3B 9F 95 81 31 FE 9F 00 65 46 53 05 30 06 71 DF 00 00 00 81 61 0F D9
 => Command timeout. (SCARD_E_TIMEOUT [0x8010000A])  [0.000000215]
SCardConnect
 i hContext: 0x0103E68C
 i szReader Gemalto GemPC Twin 00 00
 i dwShareMode: SCARD_SHARE_SHARED (0x00000002)
 i dwPreferredProtocols: 0x00000003 (T=0, T=1)
 i phCard 0x0243EA80 (38005376)
 i pdwActiveProtocol 0x7FFEE90B2420 (140732808242208)
 o phCard 0x000104C4 (66756)
 o dwActiveProtocol: T=1 (0x00000002)
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000142]
SCardBeginTransaction
 i hCard: 0x000104C4
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000070]
SCardEndTransaction
 i hCard: 0x000104C4
 i dwDisposition: SCARD_LEAVE_CARD (0x00000000)
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000002802]
SCardDisconnect
 i hCard: 0x000104C4
 i dwDisposition: SCARD_RESET_CARD (0x00000001)
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000058724]
SCardReleaseContext
 i hContext: 0x0103E68C
 => Command successful. (SCARD_S_SUCCESS [0x00000000])  [0.000000204]

Results sorted by total execution time
total time: 0.304753 sec
0.219919 sec (  1 calls) 72.16% SCardEstablishContext
0.059086 sec (  2 calls) 19.39% SCardDisconnect
0.020384 sec (  2 calls)  6.69% SCardConnect
0.002802 sec (  1 calls)  0.92% SCardEndTransaction
0.001054 sec (  4 calls)  0.35% SCardGetStatusChange
0.000464 sec (  2 calls)  0.15% SCardControl
0.000229 sec (  2 calls)  0.08% SCardListReaders
0.000204 sec (  1 calls)  0.07% SCardReleaseContext
0.000070 sec (  1 calls)  0.02% SCardBeginTransaction

Analysis


  • PC/SC commands are in blue
  • Input arguments are in green
  • Output arguments are in mangenta
  • Errors are in bold red
  • The last part of the log contains some statistics about: functions called and times consumed by each of them

Next steps

Some ideas for the future:

Parse the APDU

For now the APDUs are displayed as a buffer of bytes. It would be great to display the command name corresponding to an INS byte. For example "SELECT FILE" is easier to read than "A4".

Smart card activity live monitoring

I often run pcscd in debug mode to know if something is happening at the PC/SC layer. I then know if the application is doing a lot of smart card accesses and I will just wait or if the application is locked somewhere and I should kill/debug it.

The idea is to send the PC/SC API log stream to a "live monitor" able to display a status using colors for example. The GUI still has to be designed. Please propose ideas.

PC/SC calls correctness

With all the PC/SC API calls you can check your application is using the API correctly. For example you should have the same number of SCardEstablishContext() and SCardReleaseContext() calls.

Mac OS X support

Logs from pcscd are very difficult to read. See pcscd debug output on Mac OS X. A clear PCSC API spy tool would be a real plus.

I do plan to work on porting the spying layer but I don't know when I will work on it. You can work on it and provide patches and ideas.

Windows support?

I do not plan to work on a Windows port myself. At least not without a very big amount of money :-).

If you want to work on this please do. I may integrate your changes if they do not break GNU/Linux and Mac OS X supports.

[UPDATE] Petr Svenda wrote a PC/SC API spy for Windows: PC/SC APDU inspection and manipulation tool (APDUPlay)

Conclusion

I hope this API spy feature will work in the long term. It is already the 3rd iteration of API log.

The displayer program (pcsc-spy.py) is written in Python. It should be easy to extend and make it do some complex tasks.

Thursday, July 7, 2011

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.


Flattr this

Thursday, January 27, 2011

PCSC API spy, another way

In a previous post "PCSC API spy for GNU systems" I described the use of ltrace to trace the PC/SC API calls with the arguments.

ltrace limitations

ltrace can only trace calls made by the program itself. It does not work in two common cases in the smart card world:

library loading at run time


If the libpcsclite.so.1 library is loaded at run time using dlopen() then ltrace can't be used.

For example OpenSC now uses dlopen to load libpcsclite.so.1.

library used by another library


A PKCS#11 library using a smart card will be linked to libpcsclite.so.1. You may have your program traced by ltrace directly linked to the PKCS#11 library (to avoid the previous limitation). In this case ltrace will only be able to trace calls to the PKCS#11 library but not calls from the PKCS#11 library to the libpcsclite.so.1 library.

Usefulness of ltrace?


With these 2 limitations the use of ltrace is very limited. It works well for a test program doing direct winscard calls. But it is useless for a PKCS#11 library.

Internal tracing feature


So the idea is to do the tracing inside the PC/SC library itself.

Profiling


I already had a profiling feature on the client side. This offer the possibility to log every PC/SC calls and the time in each call. It is useful to know where time is spent in the application and to detect some application bugs (like less SCardReleaseContext() calls than SCardEstablishContext() calls).

Profiling is activated by defining DO_PROFILE in PCSC/src/winscard_clnt.c and recompiling + reinstalling libpcsclite.so.1.

I wrote a Perl script to generate a report from the traces.

Example trace file generated by the pcsc/src/testpcscd "sample":

Start a new profile
SCardEstablishContext 169
SCardIsValidContext 1
SCardIsValidContext 0
SCardListReaderGroups 1
SCardFreeMemory 1
SCardListReaders 26
SCardListReaders 26
SCardGetStatusChange 24
SCardConnect 15766
SCardTransmit 2952
SCardControl 1902
SCardGetAttrib 133
SCardFreeMemory 0
SCardGetAttrib 66
SCardFreeMemory 1
SCardGetAttrib 94
SCardGetAttrib 103
SCardGetAttrib 36
SCardSetAttrib 41
SCardStatus 171
SCardFreeMemory 1
SCardFreeMemory 0
SCardReconnect 112890
SCardDisconnect 90827
SCardFreeMemory 1
SCardReleaseContext 170


Example result:

(6) SCardFreeMemory: 4 µs
(5) SCardGetAttrib: 432 µs
(2) SCardIsValidContext: 1 µs
(2) SCardListReaders: 52 µs
(1) SCardDisconnect: 90827 µs
(1) SCardTransmit: 2952 µs
(1) SCardGetStatusChange: 24 µs
(1) SCardStatus: 171 µs
(1) SCardReconnect: 112890 µs
(1) SCardConnect: 15766 µs
(1) SCardEstablishContext: 169 µs
(1) SCardControl: 1902 µs
(1) SCardSetAttrib: 41 µs
(1) SCardListReaderGroups: 1 µs
(1) SCardReleaseContext: 170 µs
total: 225402 µs

Percentages:
50.08%: SCardReconnect
40.30%: SCardDisconnect
6.99%: SCardConnect
1.31%: SCardTransmit
0.84%: SCardControl
0.19%: SCardGetAttrib
0.08%: SCardStatus
0.08%: SCardReleaseContext
0.07%: SCardEstablishContext
0.02%: SCardListReaders
0.02%: SCardSetAttrib
0.01%: SCardGetStatusChange
0.00%: SCardFreeMemory
0.00%: SCardIsValidContext
0.00%: SCardListReaderGroups


In the first list WinSCard calls are sorted by number of occurrence with the total time of execution.
In the second list the WinSCard calls are sorted by percentage of total time used.

Tracing


The profiling feature is fine but does not give the parameters used in the calls.
So I added a tracing feature.

Tracing is activated by defining DO_TRACE in PCSC/src/winscard_clnt.c and recompiling + reinstalling libpcsclite.so.1.

Example trace file generated by the pcsc/src/testpcscd "sample":


< [7FFF70121CA0] SCardEstablishContext 2, 0x0, 0x0
> [7FFF70121CA0] SCardEstablishContext 16997142
< [7FFF70121CA0] SCardIsValidContext 16997142
> [7FFF70121CA0] SCardIsValidContext
< [7FFF70121CA0] SCardIsValidContext 16997143
> [7FFF70121CA0] SCardIsValidContext
< [7FFF70121CA0] SCardListReaders 16997142
> [7FFF70121CA0] SCardListReaders 26
< [7FFF70121CA0] SCardListReaders 16997142
> [7FFF70121CA0] SCardListReaders 26
< [7FFF70121CA0] SCardGetStatusChange 16997142 -1 1
< [7FFF70121CA0] SCardGetStatusChange [0] Gemalto GemPC Twin 00 00 10 0
> [7FFF70121CA0] SCardGetStatusChange [0] Gemalto GemPC Twin 00 00 10 22
< [7FFF70121CA0] SCardConnect 16997142 Gemalto GemPC Twin 00 00 2 3
> [7FFF70121CA0] SCardConnect 1
< [7FFF70121CA0] SCardDisconnect 71159 2
> [7FFF70121CA0] SCardDisconnect
< [7FFF70121CA0] SCardReleaseContext 16997142
> [7FFF70121CA0] SCardReleaseContext


< lines are IN arguments
> lines are OUT arguments

The value within [] is the thread identification.

You should look at the source code to know what are the other data.

Not all the function are covered by the tracing feature. For example SCardTransmit has not tracing facility. But it is easy to get the arguments on the pcscd side using --debug --foreground --apdu.

Conclusion


ltrace is a nice tool but not usable for tracing libraries using PC/SC.

pcsc-lite profiling is nice but does not give the parameters used.

pcsc-lite tracing is an answer to the problem.

Of course profiling and tracing in libpcsclite are DISABLED by default and should be disabled in a deployed system. They are help tools for a developer.


Flattr this

Friday, August 13, 2010

PCSC API spy for GNU systems

Executive summary


  1. Copy the file ltrace.conf to ~/.ltrace.conf
  2. Use with: ltrace -l/usr/lib/libpcsclite.so your_application

Discussion


It may be difficult to debug a PC/SC application. You can ask pcscd to generate logs using --debug but these logs are mainly to trace problems at the reader level, not at the application level.

ltrace


ltrace (wikipedia)
ltrace is a debugging utility in Linux to monitor the library calls used by a program and all the signals it receives. It can also show system calls, used by a program.

It is easy to use ltrace to trace a program. I will use the testpcsc program included in pcsc-lite as a PC/SC sample code:
$ ltrace .libs/testpcsc


__libc_start_main(0x8048c5a, 1, 0xbfdfadb4, 0x8049dc0, 0x8049db0 
puts("\nMUSCLE PC/SC Lite unitary test "...
MUSCLE PC/SC Lite unitary test Program

)     = 41
puts("\033[35mTHIS PROGRAM IS NOT DESIGNE"...THIS PROGRAM IS NOT DESIGNED AS A TESTING TOOL FOR END USERS!
)   = 67
printf("Do NOT use it unless you really "...Do NOT use it unless you really know what you do.

)    = 55
printf("Testing SCardEstablishContext\t:"...)    = 32
SCardEstablishContext(2, 0, 0, 0xbfdfacd8, 0)    = 0
pcsc_stringify_error(0, 0xb77b73a0, 0xb778780d, 0xb7764ff4, 0) = 0xb778c340
puts("Command successful."Testing SCardEstablishContext : Command successful.
)                      = 20
printf("Testing SCardIsValidContext\t: ")        = 30
SCardIsValidContext(0x103a3a0, 0x103a3a0, 0, 0xbfdfacd8, 0) = 0
pcsc_stringify_error(0, 0, 0xbfdfa568, 0xb77855ce, 0x103a3a0) = 0xb778c340
puts("Command successful."Testing SCardIsValidContext : Command successful.
)                      = 20
printf("Testing SCardIsValidContext\t: ")        = 30
SCardIsValidContext(0x103a3a1, 0x103a3a0, 0, 0xbfdfacd8, 0) = 0x80100003
pcsc_stringify_error(0x80100003, 0, 0xbfdfa568, 0xb77855ce, 0xbfdfa574) = 0xb778c340
printf("\033[34m%s (don't panic)\n\033[0"..., "Invalid handle."Testing SCardIsValidContext : Invalid handle. (don't panic)
) = 39
printf("Testing SCardListReaderGroups\t:"...)    = 32
SCardListReaderGroups(0x103a3a0, 0xbfdfac08, 0xbfdfac04, 0xbfdfacd8, 0) = 0
pcsc_stringify_error(0, 0xb77b73a0, 0xbfdfac08, 0xb7764ff4, 0) = 0xb778c340
puts("Command successful."Testing SCardListReaderGroups : Command successful.
)                      = 20
printf("\033[32mGroup %02d: %s\n\033[0m", 1, "SCard$DefaultReaders"Group 01: SCard$DefaultReaders
) = 40
printf("Testing SCardFreeMemory\t\t: ")          = 27
SCardFreeMemory(0x103a3a0, 0x96ea0f8, 0x96ea0f8, 0xbfdfacd8, 0) = 0
pcsc_stringify_error(0, 0xb77b73a0, 0x96ea0f8, 0xb77855e0, 0xb77855e9) = 0xb778c340
puts("Command successful."Testing SCardFreeMemory  : Command successful.
)                      = 20
printf("Testing SCardListReaders\t: ")           = 27
SCardListReaders(0x103a3a0, 0, 0, 0xbfdfac88, 0) = 0
pcsc_stringify_error(0, 0xb77b73a0, 0, 0xb7764ff4, 0) = 0xb778c340
puts("Command successful."Testing SCardListReaders : Command successful.
)                      = 20
printf("Testing SCardListReaders\t: ")           = 27
SCardListReaders(0x103a3a0, 0, 0xbfdfac80, 0xbfdfac88, 0) = 0
pcsc_stringify_error(0, 0xb7669260, 0xb77654c0, 0xbfdfac88, 0) = 0xb778c340
puts("Command successful."Testing SCardListReaders : Command successful.
)                      = 20
printf("\033[32mReader %02d: %s\n\033[0m", 1, "Lenovo Integrated Smart Card Rea"...Reader 01: Lenovo Integrated Smart Card Reader 00 00
) = 62
printf("Waiting for card insertion\t: ")         = 29
fflush(0xb77654c0Waiting for card insertion : )                               = 0
SCardGetStatusChange(0x103a3a0, -1, 0xbfdfaca0, 1, 0) = 0
pcsc_stringify_error(0, 0xb77b73a0, 0xbfdfaca0, 0xbfdfac88, 0) = 0xb778c340
puts("Command successful."Command successful.
)                      = 20
printf("Testing SCardConnect\t\t: ")             = 24
SCardConnect(0x103a3a0, 0x96ea118, 2, 3, 0xbfdfacdc) = 0
pcsc_stringify_error(0, 0xb77b73a0, 0xbfdfacdc, 0xbfdfac88, 0) = 0xb778c340
puts("Command successful."Testing SCardConnect  : Command successful.
)                      = 20
printf("Select file:")                           = 12
memcpy(0xbfdfaaa8, "", 7)                        = 0xbfdfaaa8
printf(" %02X", 0)                               = 3
printf(" %02X", 0xa4)                            = 3
printf(" %02X", 0)                               = 3
printf(" %02X", 0)                               = 3
printf(" %02X", 0x2)                             = 3
printf(" %02X", 0x3f)                            = 3
printf(" %02X", 0)                               = 3
putchar(10, 0, 7, 3, 0xbfdfacdcSelect file: 00 A4 00 00 02 3F 00
)                 = 10
printf("Testing SCardTransmit\t\t: ")            = 25
SCardTransmit(105074, 0xbfdfabb0, 0xbfdfaaa8, 7, 0xbfdfabb8) = 0
pcsc_stringify_error(0, 0xb77b73a0, 0xbfdfabb0, 0xbfdfac88, 0) = 0xb778c340
puts("Command successful."Testing SCardTransmit  : Command successful.
)                      = 20
printf(" card response:\033[32m")                = 20
printf(" %02X", 0x6f)                            = 3
printf(" %02X", 0x14)                            = 3
printf(" %02X", 0x84)                            = 3
printf(" %02X", 0xd)                             = 3
printf(" %02X", 0x70)                            = 3
printf(" %02X", 0x3c)                            = 3
printf(" %02X", 0x71)                            = 3
printf(" %02X", 0xb7)                            = 3
printf(" %02X", 0x6c)                            = 3
printf(" %02X", 0x3a)                            = 3
printf(" %02X", 0x8)                             = 3
printf(" %02X", 0x9)                             = 3
printf(" %02X", 0x2f)                            = 3
printf(" %02X", 0x2d)                            = 3
printf(" %02X", 0x73)                            = 3
printf(" %02X", 0xb7)                            = 3
printf(" %02X", 0xff)                            = 3
printf(" %02X", 0xa5)                            = 3
printf(" %02X", 0x3)                             = 3
printf(" %02X", 0x88)                            = 3
printf(" %02X", 0x1)                             = 3
printf(" %02X", 0)                               = 3
printf(" %02X", 0x90)                            = 3
printf(" %02X", 0)                               = 3
printf("\n\033[0m" card response: 6F 14 84 0D 70 3C 71 B7 6C 3A 08 09 2F 2D 73 B7 FF A5 03 88 01 00 90 00
)                              = 5
printf("Testing SCardControl\t\t: ")             = 24
SCardControl(105074, 0x42000001, 0xbfdfa598, 1, 0xbfdfa598) = 0x80100016
pcsc_stringify_error(0x80100016, 0xb77b73a0, 0xbfdfa598, 0xbfdfa598, 0) = 0xb778c340
printf("\033[34m%s (don't panic)\n\033[0"..., "Transaction failed."Testing SCardControl  : Transaction failed. (don't panic)
) = 43
printf("Testing SCardGetAttrib\t\t: ")           = 26
SCardGetAttrib(105074, 0x7fff0003, 0xbfdfac10, 0xbfdfac0c, 0xbfdfa598) = 0
pcsc_stringify_error(0, 0xb77b73a0, 0xbfdfac10, 0xbfdfa598, 0) = 0xb778c340
puts("Command successful."Testing SCardGetAttrib  : Command successful.
)                      = 20
printf("SCARD_ATTR_DEVICE_FRIENDLY_NAME:"...SCARD_ATTR_DEVICE_FRIENDLY_NAME: Lenovo Integrated Smart Card Reader 00 00
)    = 84
printf("Testing SCardFreeMemory\t\t: ")          = 27
SCardFreeMemory(0x103a3a0, 0x96ea198, 1, 0xbfdfac0c, 0xbfdfa598) = 0
pcsc_stringify_error(0, 0xb7669260, 0xb77654c0, 0x8049fbe, 0xb77855e9) = 0xb778c340
puts("Command successful."Testing SCardFreeMemory  : Command successful.
)                      = 20
printf("Testing SCardGetAttrib\t\t: ")           = 26
SCardGetAttrib(105074, 590595, 0xbfdfac10, 0xbfdfac0c, 0xbfdfa598) = 0
pcsc_stringify_error(0, 0xb7669260, 0xb77654c0, 0xbfdfa598, 0) = 0xb778c340
puts("Command successful."Testing SCardGetAttrib  : Command successful.
)                      = 20
printf("SCARD_ATTR_ATR_STRING length: \033"...SCARD_ATTR_ATR_STRING length: 23
)  = 42
printf("SCARD_ATTR_ATR_STRING: \033[32m")        = 28
printf("%02X ", 0x3b)                            = 3
printf("%02X ", 0x9f)                            = 3
printf("%02X ", 0x95)                            = 3
printf("%02X ", 0x81)                            = 3
printf("%02X ", 0x31)                            = 3
printf("%02X ", 0xfe)                            = 3
printf("%02X ", 0x9f)                            = 3
printf("%02X ", 0)                               = 3
printf("%02X ", 0x65)                            = 3
printf("%02X ", 0x46)                            = 3
printf("%02X ", 0x53)                            = 3
printf("%02X ", 0x5)                             = 3
printf("%02X ", 0x30)                            = 3
printf("%02X ", 0x6)                             = 3
printf("%02X ", 0x71)                            = 3
printf("%02X ", 0xdf)                            = 3
printf("%02X ", 0)                               = 3
printf("%02X ", 0)                               = 3
printf("%02X ", 0)                               = 3
printf("%02X ", 0x81)                            = 3
printf("%02X ", 0x61)                            = 3
printf("%02X ", 0x16)                            = 3
printf("%02X ", 0xc0)                            = 3
printf("\n\033[0m"SCARD_ATTR_ATR_STRING: 3B 9F 95 81 31 FE 9F 00 65 46 53 05 30 06 71 DF 00 00 00 81 61 16 C0 
)                              = 5
printf("Testing SCardFreeMemory\t\t: ")          = 27
SCardFreeMemory(0x103a3a0, 0x96ea198, 1, 0xbfdfac0c, 0xbfdfa598) = 0
pcsc_stringify_error(0, 0xb7669260, 0xb77654c0, 0x8049fbe, 0xb77855e9) = 0xb778c340
puts("Command successful."Testing SCardFreeMemory  : Command successful.
)                      = 20
printf("Testing SCardGetAttrib\t\t: ")           = 26
SCardGetAttrib(105074, 65794, 0xbfdfac18, 0xbfdfac14, 0xbfdfa598) = 0
pcsc_stringify_error(0, 0xb7669260, 0xb77654c0, 0xbfdfa598, 0) = 0xb778c340
puts("Command successful."Testing SCardGetAttrib  : Command successful.
)                      = 20
printf("Vendor IFD version\t\t: \033[32m"...Vendor IFD version  : 0x0103000D
)    = 42
printf("Testing SCardGetAttrib\t\t: ")           = 26
SCardGetAttrib(105074, 499719, 0xbfdfac18, 0xbfdfac14, 0xbfdfa598) = 0
pcsc_stringify_error(0, 0xb7669260, 0xb77654c0, 0xbfdfa598, 0) = 0xb778c340
puts("Command successful."Testing SCardGetAttrib  : Command successful.
)                      = 20
printf("Max message length\t\t: \033[32m"..., 261Max message length  : 261
) = 35
printf("Testing SCardGetAttrib\t\t: ")           = 26
SCardGetAttrib(105074, 65792, 0xbfdfac18, 0xbfdfac14, 0xbfdfa598) = 0
pcsc_stringify_error(0, 0xb7669260, 0xb77654c0, 0xbfdfa598, 0) = 0xb778c340
puts("Command successful."Testing SCardGetAttrib  : Command successful.
)                      = 20
printf("Vendor name\t\t\t: \033[32m%s\n\033"..., "Ludovic Rousseau"Vendor name : Ludovic Rousseau
) = 42
printf("Testing SCardSetAttrib\t\t: ")           = 26
SCardSetAttrib(105074, 590595, 0x804a2ab, 1, 0xbfdfa598) = 0x80100016
pcsc_stringify_error(0x80100016, 0x804a2ab, 0xbfdfa57c, 0xb77867a0, 105074) = 0xb778c340
printf("\033[34m%s (don't panic)\n\033[0"..., "Transaction failed."Testing SCardSetAttrib  : Transaction failed. (don't panic)
) = 43
printf("Testing SCardStatus\t\t: ")              = 23
SCardStatus(105074, 0xbfdfac84, 0xbfdfac9c, 0xbfdfac98, 0xbfdfac94) = 0
pcsc_stringify_error(0, 0xb77b73a0, 0xbfdfac84, 0xbfdfac90, 0) = 0xb778c340
puts("Command successful."Testing SCardStatus  : Command successful.
)                      = 20
printf("Current Reader Name\t\t: \033[32"..., "Lenovo Integrated Smart Card Rea"...Current Reader Name  : Lenovo Integrated Smart Card Reader 00 00
) = 74
printf("Current Reader State\t\t: \033[3"...Current Reader State  : 0x10034
)    = 41
printf("Current Reader Protocol\t\t: T=\033"...Current Reader Protocol  : T=1
) = 40
printf("Current Reader ATR Size\t\t: \033"...Current Reader ATR Size  : 23 bytes
)   = 45
printf("Current Reader ATR Value\t: \033"...)    = 32
printf("%02X ", 0x3b)                            = 3
printf("%02X ", 0x9f)                            = 3
printf("%02X ", 0x95)                            = 3
printf("%02X ", 0x81)                            = 3
printf("%02X ", 0x31)                            = 3
printf("%02X ", 0xfe)                            = 3
printf("%02X ", 0x9f)                            = 3
printf("%02X ", 0)                               = 3
printf("%02X ", 0x65)                            = 3
printf("%02X ", 0x46)                            = 3
printf("%02X ", 0x53)                            = 3
printf("%02X ", 0x5)                             = 3
printf("%02X ", 0x30)                            = 3
printf("%02X ", 0x6)                             = 3
printf("%02X ", 0x71)                            = 3
printf("%02X ", 0xdf)                            = 3
printf("%02X ", 0)                               = 3
printf("%02X ", 0)                               = 3
printf("%02X ", 0)                               = 3
printf("%02X ", 0x81)                            = 3
printf("%02X ", 0x61)                            = 3
printf("%02X ", 0x16)                            = 3
printf("%02X ", 0xc0)                            = 3
puts("\033[0m"Current Reader ATR Value : 3B 9F 95 81 31 FE 9F 00 65 46 53 05 30 06 71 DF 00 00 00 81 61 16 C0 
)                                  = 5
printf("Testing SCardFreeMemory\t\t: ")          = 27
SCardFreeMemory(0x103a3a0, 0x96ea198, 0, 0xbfdfac98, 0xbfdfac94) = 0
pcsc_stringify_error(0, 0xb7669260, 0xb77654c0, 0x8049fbe, 0xb77855e9) = 0xb778c340
puts("Command successful."Testing SCardFreeMemory  : Command successful.
)                      = 20
printf("Testing SCardFreeMemory\t\t: ")          = 27
SCardFreeMemory(0x103a3a0, 0x96ea0f8, 0, 0xbfdfac98, 0xbfdfac94) = 0
pcsc_stringify_error(0, 0xb7669260, 0xb77654c0, 0x8049fbe, 0xb77855e9) = 0xb778c340
puts("Command successful."Testing SCardFreeMemory  : Command successful.
)                      = 20
printf("Press enter: ")                          = 13
getchar(0x804a396, 0x103a3a0, 0, 0xbfdfac98, 0xbfdfac94Press enter: 
) = 10
printf("Testing SCardReconnect\t\t: ")           = 26
SCardReconnect(105074, 2, 3, 2, 0xbfdfac8c)      = 0
pcsc_stringify_error(0, 0xb77b73a0, 0xbfdfac8c, 0xbfdfac90, 0) = 0xb778c340
puts("Command successful."Testing SCardReconnect  : Command successful.
)                      = 20
printf("Testing SCardDisconnect\t\t: ")          = 27
SCardDisconnect(105074, 2, 0, 2, 0xbfdfac8c)     = 0
pcsc_stringify_error(0, 0xb77b73a0, 0xbfdfa4b4, 0xbfdfac90, 0) = 0xb778c340
puts("Command successful."Testing SCardDisconnect  : Command successful.
)                      = 20
printf("Testing SCardFreeMemory\t\t: ")          = 27
SCardFreeMemory(0x103a3a0, 0x96ea118, 0, 2, 0xbfdfac8c) = 0
pcsc_stringify_error(0, 0xb7669260, 0xb77654c0, 0x8049fbe, 0xb77855e9) = 0xb778c340
puts("Command successful."Testing SCardFreeMemory  : Command successful.
)                      = 20
printf("Testing SCardReleaseContext\t: ")        = 30
SCardReleaseContext(0x103a3a0, 0x103a3a0, 0, 2, 0xbfdfac8c) = 0
pcsc_stringify_error(0, 0xb77b73a0, 0xbfdfa4b4, 0xbfdfac90, 0) = 0xb778c340
puts("Command successful."Testing SCardReleaseContext : Command successful.
)                      = 20
putchar(10, 0x103a3a0, 0, 2, 0xbfdfac8c
)         = 10
puts("PC/SC Test Completed Successfull"...PC/SC Test Completed Successfully !
)      = 36
+++ exited (status 0) +++

Limitations


By default ltrace lists all the calls from all the libraries. You can restrict the tracing to one specific library using: -l/usr/lib/libpcsclite.so

The PC/SC API calls are not really useful. You have to parse the argument by hand. It is not easy to know what SCardConnect(0x103a3a0, 0x96ea118, 2, 3, 0xbfdfacdc) = 0 is really doing.

ltrace PCSC configuration file


ltrace can use a configuration file to parse the arguments of the functions and display a (more) human readable version.

The configuration file uses a very simple format. For example for SCardConnect I used:
scarderror SCardConnect(scardcontext, string, share_mode, protocol, +scardhandle*, +protocol*);

A ltrace configuration file is now included in the pcsc-lite project in the new contrib/ directory. Just copy the file to ~/.ltrace.conf.

Example with the configuration file


$ ltrace -l/usr/lib/libpcsclite.so .libs/testpcsc


MUSCLE PC/SC Lite unitary test Program

THIS PROGRAM IS NOT DESIGNED AS A TESTING TOOL FOR END USERS!
Do NOT use it unless you really know what you do.

SCardEstablishContext(SCARD_SCOPE_SYSTEM, NULL, NULL, 0x103d6cb) = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardEstablishContext : Command successful.
SCardIsValidContext(0x103d6cb)                   = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardIsValidContext : Command successful.
SCardIsValidContext(0x103d6cc)                   = SCARD_E_INVALID_HANDLE
pcsc_stringify_error(SCARD_E_INVALID_HANDLE)     = "Invalid handle."
Testing SCardIsValidContext : Invalid handle. (don't panic)
SCardListReaderGroups(0x103d6cb, "SCard$DefaultReaders", 22) = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardListReaderGroups : Command successful.
Group 01: SCard$DefaultReaders
SCardFreeMemory(0x103d6cb, 0x09eb70f8)           = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardFreeMemory  : Command successful.
SCardListReaders(0x103d6cb, NULL, NULL, 43)      = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardListReaders : Command successful.
SCardListReaders(0x103d6cb, NULL, "Lenovo Integrated Smart Card Rea"..., 43) = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardListReaders : Command successful.
Reader 01: Lenovo Integrated Smart Card Reader 00 00
Waiting for card insertion : SCardGetStatusChange(0x103d6cb, -1, { "Lenovo Integrated Smart Card Rea"..., 0x00000001, 16, 34, 23, [ ';', '\237', '\225', '\201'... ] }, 1) = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Command successful.
SCardConnect(0x103d6cb, "Lenovo Integrated Smart Card Rea"..., SCARD_SHARE_SHARED, SCARD_PROTOCOL_T0_SCARD_PROTOCOL_T1, 126261, SCARD_PROTOCOL_T1) = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardConnect  : Command successful.
Select file: 00 A4 00 00 02 3F 00
SCardTransmit(126261, { SCARD_PROTOCOL_T1, 8 }, [ '\000', '\244', '\000', '\000'... ], 7, { 0xbfe04130, -1216591178 }, 'o', 24) = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardTransmit  : Command successful.
 card response: 6F 14 84 0D 70 3C 71 B7 6C 3A 08 09 2F 2D 73 B7 FF A5 03 88 01 00 90 00
SCardControl(126261, 1107296257, [ '\002' ], 1, [ '\002', '\000', '\000', '\000'... ], 1024, 0) = SCARD_E_NOT_TRANSACTED
pcsc_stringify_error(SCARD_E_NOT_TRANSACTED)     = "Transaction failed."
Testing SCardControl  : Transaction failed. (don't panic)
SCardGetAttrib(126261, SCARD_ATTR_DEVICE_FRIENDLY_NAME, [  ], 42) = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardGetAttrib  : Command successful.
SCARD_ATTR_DEVICE_FRIENDLY_NAME: Lenovo Integrated Smart Card Reader 00 00
SCardFreeMemory(0x103d6cb, 0x09eb7198)           = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardFreeMemory  : Command successful.
SCardGetAttrib(126261, SCARD_ATTR_ATR_STRING, [  ], 23) = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardGetAttrib  : Command successful.
SCARD_ATTR_ATR_STRING length: 23
SCARD_ATTR_ATR_STRING: 3B 9F 95 81 31 FE 9F 00 65 46 53 05 30 06 71 DF 00 00 00 81 61 16 C0 
SCardFreeMemory(0x103d6cb, 0x09eb7198)           = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardFreeMemory  : Command successful.
SCardGetAttrib(126261, SCARD_ATTR_VENDOR_IFD_VERSION, [  ], 4) = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardGetAttrib  : Command successful.
Vendor IFD version  : 0x0103000D
SCardGetAttrib(126261, SCARD_ATTR_MAXINPUT, [  ], 4) = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardGetAttrib  : Command successful.
Max message length  : 261
SCardGetAttrib(126261, SCARD_ATTR_VENDOR_NAME, [  ], 17) = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardGetAttrib  : Command successful.
Vendor name   : Ludovic Rousseau
SCardSetAttrib(126261, SCARD_ATTR_ATR_STRING, , 1) = SCARD_E_NOT_TRANSACTED
pcsc_stringify_error(SCARD_E_NOT_TRANSACTED)     = "Transaction failed."
Testing SCardSetAttrib  : Transaction failed. (don't panic)
SCardStatus(126261, "Lenovo Integrated Smart Card Rea"..., 42, 52, SCARD_PROTOCOL_T1, [ '\370', 'p', '\353', '\t'... ], 23) = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardStatus  : Command successful.
Current Reader Name  : Lenovo Integrated Smart Card Reader 00 00
Current Reader State  : 0x0034
Current Reader Protocol  : T=1
Current Reader ATR Size  : 23 bytes
Current Reader ATR Value : 3B 9F 95 81 31 FE 9F 00 65 46 53 05 30 06 71 DF 00 00 00 81 61 16 C0 
SCardFreeMemory(0x103d6cb, 0x09eb7198)           = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardFreeMemory  : Command successful.
SCardFreeMemory(0x103d6cb, 0x09eb70f8)           = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardFreeMemory  : Command successful.
Press enter: 
SCardReconnect(126261, SCARD_SHARE_SHARED, SCARD_PROTOCOL_T0_SCARD_PROTOCOL_T1, SCARD_UNPOWER_CARD, SCARD_PROTOCOL_T1) = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardReconnect  : Command successful.
SCardDisconnect(126261, SCARD_UNPOWER_CARD)      = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardDisconnect  : Command successful.
SCardFreeMemory(0x103d6cb, 0x09eb7118)           = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardFreeMemory  : Command successful.
SCardReleaseContext(0x103d6cb)                   = SCARD_S_SUCCESS
pcsc_stringify_error(SCARD_S_SUCCESS)            = "Command successful."
Testing SCardReleaseContext : Command successful.

PC/SC Test Completed Successfully !
+++ exited (status 0) +++

  • Call to other libraries (lib C in particular) are no more displayed
  • PCSC functions arguments are displayed in a human form

If I reuse the same SCardConnect example we now have:
SCardConnect(0x103d6cb, "Lenovo Integrated Smart Card Rea"..., SCARD_SHARE_SHARED, SCARD_PROTOCOL_T0_SCARD_PROTOCOL_T1, 126261, SCARD_PROTOCOL_T1) = SCARD_S_SUCCESS

We get:
  • Connection context to the PC/SC Resource Manager. It is just a random numeric value: 0x103d6cb
  • Reader name to connect to: "Lenovo Integrated Smart Card Rea"...
  • Mode of connection type: exclusive or shared. SCARD_SHARE_SHARED
  • Desired protocol use: SCARD_PROTOCOL_T0_SCARD_PROTOCOL_T1
  • Handle to this connection: 126261
  • Established protocol to this connection: SCARD_PROTOCOL_T1
  • Return code: SCARD_S_SUCCESS

Conclusion


I discovered the use of ltrace very recently. The configuration file may contain bugs. But I hope it will be useful.


Flattr this