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.
