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

Friday, November 18, 2011

PCSC API spy, third try