PCSC API spy, another way

Ludovic Rousseau

2011-01-27 14:02

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.