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.
