Is it possible to get pkcs11-spy to show both the start and end time of a given operation?

[assarbad]

pkcs11-spy.so is a really great help for debugging issues around PKCS#11, thanks.

When working with it, I was wondering if there is a way to show not just the start time, but also the end time.

The reason I would like to see both is that if C_Sign is the last operation "seen" by pkcs11-spy.so, there's no time to estimate or calculate the time this operation takes. This is presumably true for any operation that comes last.

Is there an environment variable or another way to influence the level of detail pkcs11-spy.so outputs?

Thank you.

[Jakuje]

I do not think this is implemented in the OpenSC's pkcs11-spy. It just prints what it prints and there is no configuration.

One option to get annotated log, you can pass it through pipe to another script that will add time information useing something like in the following answer https://serverfault.com/a/310104

I know that NSS can print some statistics from the time each PKCS#11 operation took when the environment variable NSS_DEBUG_PKCS11_MODULE (I think) is defined. But this would mean you would have to call the singature request from the NSS.

https://www-archive.mozilla.org/projects/security/pki/nss/tech-notes/tn2

The last option would be to implement it and contribute this functionality to opensc. The pkcs11-spy is quite straight-forward and functions use macros to print specific parts, so just modifying the enter() and retne() should allow you to record and print all the information you need.

OpenSC/src/pkcs11/pkcs11-spy.c

Line 1197 in 67a3874

C_Sign(CK_SESSION_HANDLE hSession, CK_BYTE_PTR pData, CK_ULONG ulDataLen,