Trace

All components in the product have trace functionality, the trace will write to a standard text file. There are two types of trace, standard (see section 6.51 [Trace]) or only function calls (see section 6.52 [Trace Call]). Call trace is available for the three standard interfaces: PKCS#11, CSP and Minidriver. The call trace will only trace function calls entry and return code, so there is little impact on performance. The complete trace will generate large amounts of information and may be hard to understand.

Trace Row

Each row in the trace file will have the following format:

[<pid>:<tid>] <time> <text>
<pid>

Process id for the process writing the trace entry.

<tid>

Thread id for the process thread writing the trace entry.

<time>

Time since first call to the trace. Separated with ‘.’ is hour, minute, seconds and milliseconds.

<text>

Trace information.

Example 1. Trace
[1000:1111] 00.00.00.000 Trace - Date 2010-11-23 16:13:23, 'C:\Temp\iid.txt'

First row will always contain the date and the original trace file path.

Processes and Threads

The first information for each trace row is the process and thread id.

[1000:1111] 00.00.00.000 Helper - Calling application: 'C:\Program Files\Net iD\iid.exe'

[2000:2222] 00.00.00.000 Helper - Calling application: 'C:\Program Files\Net iD\iidxadm.exe'

This example has two processes 1000 and 2000. It is always useful to search for the Calling application string, to find the real application, this example iid.exe and iidxadm.exe.

Multiple applications calling in the same time may cause some confusion when trying to understand the trace, see 0

Trace Split how to separate the trace for easier understanding.

There are also scenarios where a single application will spawn several threads:

[1000:1111] 00.00.00.000 Helper - Calling application: 'C:\Program Files\Net iD\iid.exe'

[1000:1111] …

[1000:1122] …

[1000:1122] …

Understanding the difference between processes and threads is not part of this document, but the information is at least available in the trace.

Execution Time

Second part of the trace is the execution time and this information is useful in identifying performance issues.

The example below shows 1 hour, 23 minutes and 45 milliseconds between the trace rows. This time used with functions below will show execution time for each function.

[1000:1111] 00.00.00.000 …

…

[1000:1111] 00.01.23.045 …

If UseLocalTime is enabled execution time is presented in local time. The example below shows function executed between 1:12 PM and 1:24 PM local time.

[1000:1111] 13.12.00.000 …

…

[1000:1111] 13.24.00.000 …
Enable trace will affect the execution time, consider using Net iD Trace service when performance is measured.

Functions

The product delivers standard application program interfaces:

These interfaces are well documented; see each corresponding chapter in the Net iD Enterprise Developer’s Guide. The product will also deliver the plugin interface, see section Plugin.

PKCS#11

Each PKCS#11 function call will start with the function name and end with a standard return value:

[1000:1111] 00.00.00.000 Pkcs11 - C_Initialize ...

[1000:1111] 00.00.00.070 Pkcs11 - Return CKR_OK

From the documentation you will learn C_Initialize is the startup function and CKR_OK means success, everything is as expected. There may be errors instead:

[1000:2222] 00.00.00.100 Pkcs11 - C_Initialize ...

[1000:2222] 00.00.00.100 Pkcs11 - Return CKR_CRYPTOKI_ALREADY_INITIALIZED

The return value is not CKR_OK, so this means an error. Is this a problem? From the documentation you will learn that this return value actually is more like a warning message, no initialize needed, since already initialized.

CSP

Each CSP function call will start with the function name and end with the function name and a Microsoft return value string.

[1000:1111] 00.00.00.307 CSP - AcquireContext ...

[1000:1111] 00.00.00.915 CSP - AcquireContext ... (OK)

The string OK means success and all other strings mean some kind of failure. The return value from CSP is always true or false, and Windows last error is eventually updated with some error value. If the string is not OK, the string is from Microsoft translation of the Windows last error.

[1000:1111] 00.00.00.307 CSP - AcquireContext ...

[1000:1111] 00.00.00.915 CSP - AcquireContext ... (The operation completed successfully.)

This means an error, despite the text says operation completed successfully. There are scenarios where this is perfectly normal; information will be available from the CSP documentation.

Minidriver

Each minidriver function call will start with the function name and end with the function name and a return value and Microsoft translation of return value.

[1000:1111] 00.00.00.031 MiniDriver - CardAcquireContext ...

[1000:1111] 00.00.01.092 MiniDriver - CardAcquireContext ... (0x00000000, OK)

The value 0x00000000 means success. The difference between CSP and Minidriver is that the return value and return string is always connected, Minidriver calls return the real value compared with CSP which return true or false and update Windows last error.

Plugin

Each property plugin function call will start with information about the function and the same information string ended with ‘done’ string.

[1000:1111] 00.00.01.023 Web - GetProperty '<property>' ... +
[1000:1111] 00.00.01.033 Web - GetProperty '<property>' ... done

[1000:1111] 00.00.01.023 Web - SetProperty '<property>' ... +
[1000:1111] 00.00.01.033 Web - SetProperty '<property>' ... done

[1000:1111] 00.00.01.023 Web - EnumProperty '<property>' ... +
[1000:1111] 00.00.01.033 Web - EnumProperty '<property>' ... done

The return value is always done.

The invoke plugin function will start with information about the operation and the same string ended with return value.

[1000:1111] 00.00.01.023 Web - Web - Invoke <operation> ...
[1000:1111] 00.00.01.023 Web - Web - Invoke <operation> ... (0)

The return value is a number and the meaning is documented in chapter 6 Plugin of the Net iD Enterprise Developer’s Guide, see section 6.3 Operations, for each operation.

Help Functionality

The product includes help functions for better understanding of the trace.

Trace Parse

The trace parse functionality will take a trace file as input and try to parse the content to a more readable format. The functionality is available on all operating systems by calling the application loader:

Trace parse — Windows
C:\Users\user>"%PROGRAMFILES%\Net iD\iid.exe" -traceparse c:\temp\iid.txt
Trace parse — Linux
$ /usr/bin/iid -traceparse /tmp/iid.txt
Must enter full path to trace file to parse.

The result will be a local web site, with starting index.html in same location as the original trace file.

Trace Split

The trace split functionality will take a trace file as input and split the content to one file for each process. The functionality is available on all operating systems by calling the application loader:

Trace split — Windows
C:\Users\user>"%PROGRAMFILES%\Net iD\iid.exe" -tracesplit c:\temp\iid.txt
Trace split — Linux
$ /usr/bin/iid -tracesplit /tmp/iid.txt

The result will be one or more files with name iid_<pid>.txt in same location as the original trace file.

Trace split all threads to separate files — Windows
C:\Users\user>"%PROGRAMFILES%\Net iD\iid.exe" -tracesplit thread c:\temp\iid.txt
Trace split all threads to separate files — Linux
$ /usr/bin/iid -tracesplit thread /tmp/iid.txt

The result will be one or more files with name iid_<pid>_<tid>.txt in same location as the original trace file.

Must enter full path to trace file to split.