Ludovic Rousseau's blog: 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.

Saturday, February 8, 2014

PCSC API spy, on Mac OS X